IPv6 Distributed Cloud: System controller has dcdbsync error

[Peng Peng]

Brief Description
-----------------
After system controller and subcloud brought up, there is dcdbsync error found in /var/log/dcdbsync/dcdbsync.log like below
DBError: (psycopg2.ProgrammingError) execute cannot be used while an asynchronous query is underway

Severity
--------
Major

Steps to Reproduce
------------------
Brought up DC system

TC-name: DC regression

Expected Behavior
------------------
no such error

Actual Behavior
----------------

Reproducibility
---------------
Reproducible

System Configuration
--------------------
DC
IPv6

Lab-name: DC

Branch/Pull Time/Commit
-----------------------
19.10 master as of 2019-09-22_20-00-00"

Last Pass
---------

Timestamp/Logs
--------------
2019-09-27 05:30:18.715 122439 ERROR sqlalchemy.pool.QueuePool [req-e6b77e50-e78f-42a7-ab9d-b724d8b40949 44a8d674b021449f81c90c4001282b68 - - default default] Error closing cursor: ProgrammingError: close cannot be used while an asynchronous query is underway
2019-09-27 05:30:18.715 122439 ERROR sqlalchemy.pool.QueuePool Traceback (most recent call last):
2019-09-27 05:30:18.715 122439 ERROR sqlalchemy.pool.QueuePool File "/usr/lib64/python2.7/site-packages/sqlalchemy/engine/base.py", line 1277, in _safe_close_cursor
2019-09-27 05:30:18.715 122439 ERROR sqlalchemy.pool.QueuePool cursor.close()
2019-09-27 05:30:18.715 122439 ERROR sqlalchemy.pool.QueuePool ProgrammingError: close cannot be used while an asynchronous query is underway
2019-09-27 05:30:18.715 122439 ERROR sqlalchemy.pool.QueuePool
2019-09-27 05:30:18.716 122439 ERROR dcdbsync.api.controllers.v1.identity.identity [req-e6b77e50-e78f-42a7-ab9d-b724d8b40949 44a8d674b021449f81c90c4001282b68 - - default default] (psycopg2.ProgrammingError) execute cannot be used while an asynchronous query is underway [SQL: 'SELECT "user".id, "user".extra, "user".enabled, "user".default_project_id, "user".created_at, "user".last_active_at, "user".domain_id \nFROM "user"']: DBError: (psycopg2.ProgrammingError) execute cannot be used while an asynchronous query is underway [SQL: 'SELECT "user".id, "user".extra, "user".enabled, "user".default_project_id, "user".created_at, "user".last_active_at, "user".domain_id \nFROM "user"']
2019-09-27 05:30:18.716 122439 ERROR dcdbsync.api.controllers.v1.identity.identity Traceback (most recent call last):
2019-09-27 05:30:18.716 122439 ERROR dcdbsync.api.controllers.v1.identity.identity File "/usr/lib/python2.7/site-packages/dcdbsync/api/controllers/v1/identity/identity.py", line 64, in get
2019-09-27 05:30:18.716 122439 ERROR dcdbsync.api.controllers.v1.identity.identity return db_api.user_get_all(context)
2019-09-27 05:30:18.716 122439 ERROR dcdbsync.api.controllers.v1.identity.identity File "/usr/lib/python2.7/site-packages/dcdbsync/db/identity/api.py", line 54, in user_get_all
2019-09-27 05:30:18.716 122439 ERROR dcdbsync.api.controllers.v1.identity.identity return IMPL.user_get_all(context)
2019-09-27 05:30:18.716 122439 ERROR dcdbsync.api.controllers.v1.identity.identity File "/usr/lib/python2.7/site-packages/dcdbsync/db/identity/sqlalchemy/api.py", line 184, in wrapper
2019-09-27 05:30:18.716 122439 ERROR dcdbsync.api.controllers.v1.identity.identity return f(*args, **kwargs)
2019-09-27 05:30:18.716 122439 ERROR dcdbsync.api.controllers.v1.identity.identity File "/usr/lib/python2.7/site-packages/dcdbsync/db/identity/sqlalchemy/api.py", line 201, in user_get_all
2019-09-27 05:30:18.716 122439 ERROR dcdbsync.api.controllers.v1.identity.identity users = query(conn, 'user')
2019-09-27 05:30:18.716 122439 ERROR dcdbsync.api.controllers.v1.identity.identity File "/usr/lib/python2.7/site-packages/dcdbsync/db/identity/sqlalchemy/api.py", line 99, in query
2019-09-27 05:30:18.716 122439 ERROR dcdbsync.api.controllers.v1.identity.identity result = connection.execute(stmt)
2019-09-27 05:30:18.716 122439 ERROR dcdbsync.api.controllers.v1.identity.identity File "/usr/lib64/python2.7/site-packages/sqlalchemy/engine/base.py", line 945, in execute
2019-09-27 05:30:18.716 122439 ERROR dcdbsync.api.controllers.v1.identity.identity return meth(self, multiparams, params)
2019-09-27 05:30:18.716 122439 ERROR dcdbsync.api.controllers.v1.identity.identity File "/usr/lib64/python2.7/site-packages/sqlalchemy/sql/elements.py", line 263, in _execute_on_connection
2019-09-27 05:30:18.716 122439 ERROR dcdbsync.api.controllers.v1.identity.identity return connection._execute_clauseelement(self, multiparams, params)
2019-09-27 05:30:18.716 122439 ERROR dcdbsync.api.controllers.v1.identity.identity File "/usr/lib64/python2.7/site-packages/sqlalchemy/engine/base.py", line 1053, in _execute_clauseelement
2019-09-27 05:30:18.716 122439 ERROR dcdbsync.api.controllers.v1.identity.identity compiled_sql, distilled_params
2019-09-27 05:30:18.716 122439 ERROR dcdbsync.api.controllers.v1.identity.identity File "/usr/lib64/python2.7/site-packages/sqlalchemy/engine/base.py", line 1189, in _execute_context
2019-09-27 05:30:18.716 122439 ERROR dcdbsync.api.controllers.v1.identity.identity context)
2019-09-27 05:30:18.716 122439 ERROR dcdbsync.api.controllers.v1.identity.identity File "/usr/lib64/python2.7/site-packages/sqlalchemy/engine/base.py", line 1398, in _handle_dbapi_exception
2019-09-27 05:30:18.716 122439 ERROR dcdbsync.api.controllers.v1.identity.identity util.raise_from_cause(newraise, exc_info)
2019-09-27 05:30:18.716 122439 ERROR dcdbsync.api.controllers.v1.identity.identity File "/usr/lib64/python2.7/site-packages/sqlalchemy/util/compat.py", line 203, in raise_from_cause
2019-09-27 05:30:18.716 122439 ERROR dcdbsync.api.controllers.v1.identity.identity reraise(type(exception), exception, tb=exc_tb, cause=cause)
2019-09-27 05:30:18.716 122439 ERROR dcdbsync.api.controllers.v1.identity.identity File "/usr/lib64/python2.7/site-packages/sqlalchemy/engine/base.py", line 1182, in _execute_context
2019-09-27 05:30:18.716 122439 ERROR dcdbsync.api.controllers.v1.identity.identity context)
2019-09-27 05:30:18.716 122439 ERROR dcdbsync.api.controllers.v1.identity.identity File "/usr/lib64/python2.7/site-packages/sqlalchemy/engine/default.py", line 470, in do_execute
2019-09-27 05:30:18.716 122439 ERROR dcdbsync.api.controllers.v1.identity.identity cursor.execute(statement, parameters)
2019-09-27 05:30:18.716 122439 ERROR dcdbsync.api.controllers.v1.identity.identity DBError: (psycopg2.ProgrammingError) execute cannot be used while an asynchronous query is underway [SQL: 'SELECT "user".id, "user".extra, "user".enabled, "user".default_project_id, "user".created_at, "user".last_active_at, "user".domain_id \nFROM "user"']
2019-09-27 05:30:18.716 122439 ERROR dcdbsync.api.controllers.v1.identity.identity

Test Activity
-------------
Regression Testing

[OpenStack Infra (hudson-openstack)]

Fix proposed to branch: master
Review: https://review.opendev.org/686425

[Ghada Khalil (gkhalil)]

Marking as stx.3.0 - issue related to Distributed Cloud which is an stx.3.0 deliverable

[OpenStack Infra (hudson-openstack)]

Reviewed: https://review.opendev.org/686425
Committed: https://git.openstack.org/cgit/starlingx/distcloud/commit/?id=3e2eccea4a5146c555be8dfcbb28e4906940a72d
Submitter: Zuul
Branch: master

commit 3e2eccea4a5146c555be8dfcbb28e4906940a72d
Author: Andy Ning <email address hidden>
Date: Thu Oct 3 11:23:31 2019 -0400

    Moved eventlet monkey_patch before app is imported

    In cmd/api.py the eventlet monkey_patch has been moved to be before api
    app import. This is because if it's called too late, the api app and
    db api module will be loaded without awareness of eventlet, the
    threading local context in db api won't be eventlet compatible, causing
    DB parallel operation errors.

    Change-Id: I294657fc910c6a4696f91308d60697d005dc53b0
    Closes-Bug: 1846411
    Signed-off-by: Andy Ning <email address hidden>

[Peng Peng (ppeng)]

No seeing this issue in the new load