Cloud Spanner: creation of new database spuriously returns ALREADY_EXISTS

[lgruen]

OS type and version: standard CircleCI docker image circleci/python:3.6.1, running on Linux 558edcd72a3d 4.15.0-1052-aws googleapis/google-cloud-python#54-Ubuntu SMP Tue Oct 1 15:43:26 UTC 2019 x86_64 Linux.

Python version: 3.6.1

Using google-cloud-spanner library 1.13.0.

This sampledb integration test creates a new database, with a name including the current time down to second resolution.

The test is not invoked in parallel, so this database creation should never fail due to an already existing database of the same name. However, this error did occur, as the log below shows -- maybe that's a bug in the retry implementation in the library?

#!/bin/bash -eo pipefail
. venv/bin/activate
pytest
============================= test session starts ==============================
platform linux -- Python 3.6.1, pytest-5.3.2, py-1.8.1, pluggy-0.13.1
rootdir: /home/circleci/repo
collected 1 item                                                               

batch_import_test.py F                                                   [100%]

=================================== FAILURES ===================================
______________________________ test_batch_import _______________________________

args = (parent: "projects/cloudspannerecosystem/instances/***************************"
create_statement: "CREATE DATABASE `sa...ore, url)"
extra_statements: "\n\nCREATE INDEX StoriesByTitleTimeScore ON stories(title) STORING (time_ts, score)\n"
,)
kwargs = {'metadata': [('google-cloud-resource-prefix', 'projects/cloudspannerecosystem/instances/***************************/d...ion-test'), ('x-goog-api-client', 'gl-python/3.6.1 grpc/1.26.0 gax/1.15.0 gapic/1.13.0 gccl/1.13.0')], 'timeout': 60.0}

    @six.wraps(callable_)
    def error_remapped_callable(*args, **kwargs):
        try:
>           return callable_(*args, **kwargs)

venv/lib/python3.6/site-packages/google/api_core/grpc_helpers.py:57: 
_ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ 

self = <grpc._channel._UnaryUnaryMultiCallable object at 0x7fbb3527c4a8>
request = parent: "projects/cloudspannerecosystem/instances/***************************"
create_statement: "CREATE DATABASE `sam...score, url)"
extra_statements: "\n\nCREATE INDEX StoriesByTitleTimeScore ON stories(title) STORING (time_ts, score)\n"

timeout = 60.0
metadata = [('google-cloud-resource-prefix', 'projects/cloudspannerecosystem/instances/***************************/databases/samp...ontinuous-integration-test'), ('x-goog-api-client', 'gl-python/3.6.1 grpc/1.26.0 gax/1.15.0 gapic/1.13.0 gccl/1.13.0')]
credentials = None, wait_for_ready = None, compression = None

    def __call__(self,
                 request,
                 timeout=None,
                 metadata=None,
                 credentials=None,
                 wait_for_ready=None,
                 compression=None):
        state, call, = self._blocking(request, timeout, metadata, credentials,
                                      wait_for_ready, compression)
>       return _end_unary_response_blocking(state, call, False, None)

venv/lib/python3.6/site-packages/grpc/_channel.py:824: 
_ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ 

state = <grpc._channel._RPCState object at 0x7fbb352144a8>
call = <grpc._cython.cygrpc.SegregatedCall object at 0x7fbb35210088>
with_call = False, deadline = None

    def _end_unary_response_blocking(state, call, with_call, deadline):
        if state.code is grpc.StatusCode.OK:
            if with_call:
                rendezvous = _MultiThreadedRendezvous(state, call, None, deadline)
                return state.response, rendezvous
            else:
                return state.response
        else:
>           raise _InactiveRpcError(state)
E           grpc._channel._InactiveRpcError: <_InactiveRpcError of RPC that terminated with:
E           	status = StatusCode.ALREADY_EXISTS
E           	details = "Database already exists: projects/cloudspannerecosystem/instances/***************************/databases/sampledb_2020-01-19_00-09-24"
E           	debug_error_string = "{"created":"@1579392565.335114093","description":"Error received from peer ipv4:172.217.13.74:443","file":"src/core/lib/surface/call.cc","file_line":1056,"grpc_message":"Database already exists: projects/cloudspannerecosystem/instances/***************************/databases/sampledb_2020-01-19_00-09-24","grpc_status":6}"
E           >

venv/lib/python3.6/site-packages/grpc/_channel.py:726: _InactiveRpcError

The above exception was the direct cause of the following exception:

    def test_batch_import():
      instance_id = os.environ['SPANNER_INSTANCE']
    
      # Append the current timestamp to the database name.
      now_str = datetime.datetime.now().strftime('%Y-%m-%d_%H-%M-%S')
      database_id = 'sampledb_%s' % now_str
>     batch_import.main(instance_id, database_id)

batch_import_test.py:29: 
_ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ 
batch_import.py:74: in main
    database.create()
venv/lib/python3.6/site-packages/google/cloud/spanner_v1/database.py:221: in create
    metadata=metadata,
venv/lib/python3.6/site-packages/google/cloud/spanner_admin_database_v1/gapic/database_admin_client.py:424: in create_database
    request, retry=retry, timeout=timeout, metadata=metadata
venv/lib/python3.6/site-packages/google/api_core/gapic_v1/method.py:143: in __call__
    return wrapped_func(*args, **kwargs)
venv/lib/python3.6/site-packages/google/api_core/retry.py:286: in retry_wrapped_func
    on_error=on_error,
venv/lib/python3.6/site-packages/google/api_core/retry.py:184: in retry_target
    return target()
venv/lib/python3.6/site-packages/google/api_core/timeout.py:214: in func_with_timeout
    return func(*args, **kwargs)
venv/lib/python3.6/site-packages/google/api_core/grpc_helpers.py:59: in error_remapped_callable
    six.raise_from(exceptions.from_grpc_error(exc), exc)
_ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ 

value = None
from_value = <_InactiveRpcError of RPC that terminated with:
	status = StatusCode.ALREADY_EXISTS
	details = "Database already exist...cloudspannerecosystem/instances/***************************/databases/sampledb_2020-01-19_00-09-24","grpc_status":6}"
>

>   ???
E   google.api_core.exceptions.AlreadyExists: 409 Database already exists: projects/cloudspannerecosystem/instances/***************************/databases/sampledb_2020-01-19_00-09-24

<string>:3: AlreadyExists
============================== 1 failed in 1.17s ===============================

Exited with code exit status 1

It might be relevant that currently the implementation doesn't wait for the future returned by the database creation, which this PR will fix. So potentially that might lead to another operation to retry the creation?

In the logs for the Cloud Spanner instance there is only a single error listed, for google.spanner.admin.database.v1.DatabaseAdmin.CreateDatabase.

[IlyaFaer]

@lgruen, does adding result() call helped in your case? If so, let's close the issue

[lgruen]

Yes, the issue never occurred again afterwards.