spanner: occasional "google.api_core.exceptions.Aborted: 409 Transaction not found" error with PingingPool

[odeke-em]

Given spanner_v1 VERSION1.11.0, I am obtaining a transaction from a PingingPool as per

    # Create a session pool that'll periodically refresh every 3 minutes (arbitrary choice value).
    pool = spanner.PingingPool(size=10, default_timeout=5, ping_interval=180)
    background_thread = threading.Thread(target=pool.ping, name='ping-pool')
    background_thread.daemon = True
    background_thread.start()

    db = client_instance.database(database, pool=pool)
    if not db.exists():
        raise ProgrammingError("database '%s' does not exist." % database)

    sess = db.session()
    ...
    # Then later obtaining a transaction and holding it for a long-ish time
    txn = sess.transaction()
    txn.begin()
    # Do a bunch of operations with the operation
    ...
    txn.commit()

and I can confirm that pool isn't being used concurrently, but I've seen a test failure with

  File "/home/travis/virtualenv/python3.7.1/lib/python3.7/site-packages/grpc/_channel.py", line 726, in _end_unary_response_blocking
    raise _InactiveRpcError(state)
grpc._channel._InactiveRpcError: <_InactiveRpcError of RPC that terminated with:
	status = StatusCode.ABORTED
	details = "Transaction not found"
	debug_error_string = "{"created":"@1580854844.873538358","description":"Error received from peer ipv4:172.217.204.95:443","file":"src/core/lib/surface/call.cc","file_line":1056,"grpc_message":"Transaction not found","grpc_status":10}"

and in full detail

Details

Traceback (most recent call last):
  File "/home/travis/virtualenv/python3.7.1/lib/python3.7/site-packages/google/api_core/grpc_helpers.py", line 57, in error_remapped_callable
    return callable_(*args, **kwargs)
  File "/home/travis/virtualenv/python3.7.1/lib/python3.7/site-packages/grpc/_channel.py", line 824, in __call__
    return _end_unary_response_blocking(state, call, False, None)
  File "/home/travis/virtualenv/python3.7.1/lib/python3.7/site-packages/grpc/_channel.py", line 726, in _end_unary_response_blocking
    raise _InactiveRpcError(state)
grpc._channel._InactiveRpcError: <_InactiveRpcError of RPC that terminated with:
	status = StatusCode.ABORTED
	details = "Transaction not found"
	debug_error_string = "{"created":"@1580854844.873538358","description":"Error received from peer ipv4:172.217.204.95:443","file":"src/core/lib/surface/call.cc","file_line":1056,"grpc_message":"Transaction not found","grpc_status":10}"
>
The above exception was the direct cause of the following exception:
Traceback (most recent call last):
  File "runtests.py", line 507, in <module>
    options.exclude_tags,
  File "runtests.py", line 294, in django_tests
    extra_tests=extra_tests,
  File "/home/travis/build/orijtech/spanner-orm/django_tests/django/django/test/runner.py", line 629, in run_tests
    old_config = self.setup_databases(aliases=databases)
  File "/home/travis/build/orijtech/spanner-orm/django_tests/django/django/test/runner.py", line 554, in setup_databases
    self.parallel, **kwargs
  File "/home/travis/build/orijtech/spanner-orm/django_tests/django/django/test/utils.py", line 174, in setup_databases
    serialize=connection.settings_dict.get('TEST', {}).get('SERIALIZE', True),
  File "/home/travis/virtualenv/python3.7.1/lib/python3.7/site-packages/spanner/django/creation.py", line 33, in create_test_db
    super().create_test_db(*args, **kwargs)
  File "/home/travis/build/orijtech/spanner-orm/django_tests/django/django/db/backends/base/creation.py", line 72, in create_test_db
    run_syncdb=True,
  File "/home/travis/build/orijtech/spanner-orm/django_tests/django/django/core/management/__init__.py", line 148, in call_command
    return command.execute(*args, **defaults)
  File "/home/travis/build/orijtech/spanner-orm/django_tests/django/django/core/management/base.py", line 364, in execute
    output = self.handle(*args, **options)
  File "/home/travis/build/orijtech/spanner-orm/django_tests/django/django/core/management/base.py", line 83, in wrapped
    res = handle_func(*args, **kwargs)
  File "/home/travis/build/orijtech/spanner-orm/django_tests/django/django/core/management/commands/migrate.py", line 257, in handle
    self.verbosity, self.interactive, connection.alias, apps=post_migrate_apps, plan=plan,
  File "/home/travis/build/orijtech/spanner-orm/django_tests/django/django/core/management/sql.py", line 51, in emit_post_migrate_signal
    **kwargs
  File "/home/travis/build/orijtech/spanner-orm/django_tests/django/django/dispatch/dispatcher.py", line 175, in send
    for receiver in self._live_receivers(sender)
  File "/home/travis/build/orijtech/spanner-orm/django_tests/django/django/dispatch/dispatcher.py", line 175, in <listcomp>
    for receiver in self._live_receivers(sender)
  File "/home/travis/build/orijtech/spanner-orm/django_tests/django/django/contrib/auth/management/__init__.py", line 83, in create_permissions
    Permission.objects.using(using).bulk_create(perms)
  File "/home/travis/build/orijtech/spanner-orm/django_tests/django/django/db/models/query.py", line 468, in bulk_create
    self._batched_insert(objs_with_pk, fields, batch_size, ignore_conflicts=ignore_conflicts)
  File "/home/travis/build/orijtech/spanner-orm/django_tests/django/django/db/models/query.py", line 1211, in _batched_insert
    self._insert(item, fields=fields, using=self.db, ignore_conflicts=ignore_conflicts)
  File "/home/travis/build/orijtech/spanner-orm/django_tests/django/django/db/models/query.py", line 1186, in _insert
    return query.get_compiler(using=using).execute_sql(return_id)
  File "/home/travis/build/orijtech/spanner-orm/django_tests/django/django/db/models/sql/compiler.py", line 1368, in execute_sql
    cursor.execute(sql, params)
  File "/home/travis/build/orijtech/spanner-orm/django_tests/django/django/db/backends/utils.py", line 67, in execute
    return self._execute_with_wrappers(sql, params, many=False, executor=self._execute)
  File "/home/travis/build/orijtech/spanner-orm/django_tests/django/django/db/backends/utils.py", line 76, in _execute_with_wrappers
    return executor(sql, params, many, context)
  File "/home/travis/build/orijtech/spanner-orm/django_tests/django/django/db/backends/utils.py", line 84, in _execute
    return self.cursor.execute(sql, params)
  File "/home/travis/virtualenv/python3.7.1/lib/python3.7/site-packages/spanner/dbapi/cursor.py", line 87, in execute
    self.__handle_insert(self.__get_txn(), sql, args or None)
  File "/home/travis/virtualenv/python3.7.1/lib/python3.7/site-packages/spanner/dbapi/cursor.py", line 128, in __handle_insert
    res = txn.execute_update(sql, params=params, param_types=param_types)
  File "/home/travis/virtualenv/python3.7.1/lib/python3.7/site-packages/google/cloud/spanner_v1/transaction.py", line 202, in execute_update
    metadata=metadata,
  File "/home/travis/virtualenv/python3.7.1/lib/python3.7/site-packages/google/cloud/spanner_v1/gapic/spanner_client.py", line 810, in execute_sql
    request, retry=retry, timeout=timeout, metadata=metadata
  File "/home/travis/virtualenv/python3.7.1/lib/python3.7/site-packages/google/api_core/gapic_v1/method.py", line 143, in __call__
    return wrapped_func(*args, **kwargs)
  File "/home/travis/virtualenv/python3.7.1/lib/python3.7/site-packages/google/api_core/retry.py", line 286, in retry_wrapped_func
    on_error=on_error,
  File "/home/travis/virtualenv/python3.7.1/lib/python3.7/site-packages/google/api_core/retry.py", line 184, in retry_target
    return target()
  File "/home/travis/virtualenv/python3.7.1/lib/python3.7/site-packages/google/api_core/timeout.py", line 214, in func_with_timeout
    return func(*args, **kwargs)
  File "/home/travis/virtualenv/python3.7.1/lib/python3.7/site-packages/google/api_core/grpc_helpers.py", line 59, in error_remapped_callable
    six.raise_from(exceptions.from_grpc_error(exc), exc)
  File "<string>", line 3, in raise_from
google.api_core.exceptions.Aborted: 409 Transaction not found

[larkee]

I am still looking into this one.

But just as a note: sess = db.session() creates a session object which you then need to create. This is bypassing the session pool entirely. It does not return a session from the session pool. Are you aware of this?

[odeke-em]

After creating the session pool, I invoke: if not sess.exists(): sess.create() But I didn’t know that it by passed using the session pool, that’s news to me. How does one properly get a session from the prior pool that they used to create spanner_v1.Database?

…

On Tue, Feb 11, 2020 at 10:49 PM larkee ***@***.***> wrote: I am still looking into this one. But just as a note: sess = db.session() creates a session object which you then need to create. This is bypassing the session pool entirely. It does not return a session from the session pool. Are you aware of this? — You are receiving this because you authored the thread. Reply to this email directly, view it on GitHub <#10?email_source=notifications&email_token=ABFL3V6NCPKKYBNDH5WGQ53RCOLVVA5CNFSM4KP7EJVKYY3PNVWWK3TUL52HS4DFVREXG43VMVBW63LNMVXHJKTDN5WW2ZLOORPWSZGOELPUD6A#issuecomment-585056760>, or unsubscribe <https://github.com/notifications/unsubscribe-auth/ABFL3V6PKIHBRLJZWW3B5PTRCOLVVANCNFSM4KP7EJVA> .

[larkee]

Within database methods, the following is used:

with SessionCheckout(self._pool) as session:

Which can be adapted to:

with SessionCheckout(pool) as session:

This is what I would recommend since it handles taking and returning the session for you.