Google-cloud-php: [Spanner] "Database has been deleted" occurs while repeating the recreation of Database

[castaneai]

(Ref #1109 )

The following error occasionally occurs while repetitively recreating the database (eg unit test).

Reproduction code

<?php

require __DIR__.'/vendor/autoload.php';

use Google\Cloud\Spanner\SpannerClient;

$projectId = '...';
$instanceId = '...';
$databaseId = '...';

const DDL = <<<DDL
CREATE TABLE `SessionTestTable` (
  `ID` STRING(36) NOT NULL,
  `Name` STRING(MAX)
) PRIMARY KEY (`ID`)
DDL;

$spanner = new SpannerClient(['projectId' => $projectId]);
$db = $spanner->connect($instanceId, $databaseId);

while (true) {
    $operation = $db->create([
        'statements' => [DDL],
    ]);
    $operation->pollUntilComplete();

    $row = $db->execute('SELECT * FROM `SessionTestTable` LIMIT 1')->rows()->current();

    $db->drop();
}

Output

PHP Fatal error:  Uncaught Google\Cloud\Core\Exception\NotFoundException: {
    "message": "Database has been deleted",
    "code": 5,
    "status": "NOT_FOUND",
    "details": []
} in project/php-spanner-session-test/vendor/google/cloud-core/src/GrpcRequestWrapper.php:254
Stack trace:
#0 project/php-spanner-session-test/vendor/google/cloud-core/src/GrpcRequestWrapper.php(191): Google\Cloud\Core\GrpcRequestWrapper->convertToGoogleException(Object(Google\ApiCore\ApiException))
#1 [internal function]: Google\Cloud\Core\GrpcRequestWrapper->handleStream(Object(Google\ApiCore\ServerStream))
#2 project/php-spanner-session-test/vendor/google/cloud-spanner/src/Result.php(177): Generator->valid()
#3 [internal function]: Google\Cloud\Spanner\Result->rows()
#4 project/php-spanner-session-test/test.php(27): Generator->current()
#5 {main}
  thrown in project/php-spanner-session-test/vendor/google/cloud-core/src/GrpcRequestWrapper.php on line 254

Fatal error: Uncaught Google\Cloud\Core\Exception\NotFoundException: {
    "message": "Database has been deleted",
    "code": 5,
    "status": "NOT_FOUND",
    "details": []
} in project/php-spanner-session-test/vendor/google/cloud-core/src/GrpcRequestWrapper.php on line 254

Google\Cloud\Core\Exception\NotFoundException: {
    "message": "Database has been deleted",
    "code": 5,
    "status": "NOT_FOUND",
    "details": []
} in project/php-spanner-session-test/vendor/google/cloud-core/src/GrpcRequestWrapper.php on line 254

Call Stack:
    0.0008     420688   1. {main}() project/php-spanner-session-test/test.php:0
   45.0366    6162432   2. Generator->current() project/php-spanner-session-test/test.php:27
   45.0366    6162480   3. Google\Cloud\Spanner\Result->rows() project/php-spanner-session-test/test.php:27
   45.0396    6275736   4. Generator->valid() project/php-spanner-session-test/vendor/google/cloud-spanner/src/Result.php:177
   45.0396    6275784   5. Google\Cloud\Core\GrpcRequestWrapper->handleStream() project/php-spanner-session-test/vendor/google/cloud-spanner/src/Result.php:177

[jdpedrie]

Hi @castaneai. I see the same result. I'll do a bit of investigating to determine what the best course of action is.

/cc @snehashah16

[crwilcox]

Does this failure occur if you reinstantiate $db on each loop?

$db = $spanner->connect($instanceId, $databaseId);

There is a suspicion that a session exists on the database that is connected to a now deleted database. Once drop is called, the $db object may be unsafe to use.

[castaneai]

@crwilcox Thanks for the suggestion.
I changed code and executed it again as follows.

As a result, "Database already exists" occurred.

$spanner = new SpannerClient(['projectId' => $projectId]);
-$db = $spanner->connect($instanceId, $databaseId);

while (true) {
+    $db = $spanner->connect($instanceId, $databaseId);
    $operation = $db->create([
        'statements' => [DDL],
    ]);
    $operation->pollUntilComplete();

    $row = $db->execute('SELECT * FROM `SessionTestTable` LIMIT 1')->rows()->current();

    $db->drop();
}

Output

PHP Fatal error:  Uncaught Google\Cloud\Core\Exception\ConflictException: {
    "message": "Database already exists: projects\/<GCP_PROJECT_ID>\/instances\/<SPANNER_INSTANCE_ID>\/databases\/session-test",
    "code": 6,
    "status": "ALREADY_EXISTS",
    "details": [
        {
            "@type": "google.rpc.resourceinfo-bin",
            "resourceType": "type.googleapis.com\/google.spanner.admin.database.v1.Database",
            "resourceName": "projects\/<GCP_PROJECT_ID>\/instances\/<SPANNER_INSTANCE_ID>\/databases\/session-test",
            "owner": "",
            "description": "Database already exists."
        },
        {
            "@type": "grpc-status-details-bin",
            "data": "<Unknown Binary Data>"
        }
    ]
} in project/vendor/google/cloud-core/src/GrpcRequestWrapper.php:254
Stack trace:
#0 project/vendor/google/cloud-core/src/GrpcRequestWrapper.php(146): Google\Cloud\Core\GrpcRequestWrapper->convertToGoogle in project/vendor/google/cloud-core/src/GrpcRequestWrapper.php on line 254

Fatal error: Uncaught Google\Cloud\Core\Exception\ConflictException: {
    "message": "Database already exists: projects\/<GCP_PROJECT_ID>\/instances\/<SPANNER_INSTANCE_ID>\/databases\/session-test",
    "code": 6,
    "status": "ALREADY_EXISTS",
    "details": [
        {
            "@type": "google.rpc.resourceinfo-bin",
            "resourceType": "type.googleapis.com\/google.spanner.admin.database.v1.Database",
            "resourceName": "projects\/<GCP_PROJECT_ID>\/instances\/<SPANNER_INSTANCE_ID>\/databases\/session-test",
            "owner": "",
            "description": "Database already exists."
        },
        {
            "@type": "grpc-status-details-bin",
            "data": "<Unknown Binary Data>"
        }
    ]
} in project/vendor/google/cloud-core/src/GrpcRequestWrapper.php on line 254

Google\Cloud\Core\Exception\ConflictException: {
    "message": "Database already exists: projects\/<GCP_PROJECT_ID>\/instances\/<SPANNER_INSTANCE_ID>\/databases\/session-test",
    "code": 6,
    "status": "ALREADY_EXISTS",
    "details": [
        {
            "@type": "google.rpc.resourceinfo-bin",
            "resourceType": "type.googleapis.com\/google.spanner.admin.database.v1.Database",
            "resourceName": "projects\/<GCP_PROJECT_ID>\/instances\/<SPANNER_INSTANCE_ID>\/databases\/session-test",
            "owner": "",
            "description": "Database already exists."
        },
        {
            "@type": "grpc-status-details-bin",
            "data": "<Unknown Binary Data>"
        }
    ]
} in project/vendor/google/cloud-core/src/GrpcRequestWrapper.php on line 254

Call Stack:
    0.0009     420600   1. {main}() project/test.php:0
    0.1172    3939832   2. Google\Cloud\Spanner\Database->create() project/test.php:25
    0.1217    3992320   3. Google\Cloud\Spanner\Connection\Grpc->createDatabase() project/vendor/google/cloud-spanner/src/Database.php:318
    0.1217    3994304   4. Google\Cloud\Spanner\Connection\Grpc->send() project/vendor/google/cloud-spanner/src/Connection/Grpc.php:326
    0.1217    3994408   5. Google\Cloud\Core\GrpcRequestWrapper->send() project/vendor/google/cloud-core/src/GrpcTrait.php:82

[crwilcox]

Hi @castaneai , it seems there is a race there since at the end of the loop the database should have been deleted. A wait may need to happen after $db->drop() so the service has a chance to finish the delete. Unfortunately it doesn't seem that drop() has a way of awaiting its completion (like create does).

@jdpedrie, do we know if this will fix the issue now? I think you might already be addressing the underlying issue. I was asking @castaneai as a verification of our suspicions, but don't want them spending to much time if we already know for certain the issue was sessions held after database drop.

[jdpedrie]

@crwilcox my tests indicated that a new instance of Database, combined with a short sleep() between loop iterations resolved the error. I should have a resolution ready next week.