Note: This bug is displayed in read-only format because the product is no longer active in Red Hat Bugzilla.

Bug 1245639

Summary: KeyError after mariadb restart
Product: Red Hat OpenStack Reporter: Attila Fazekas <afazekas>
Component: python-sqlalchemyAssignee: Michael Bayer <mbayer>
Status: CLOSED ERRATA QA Contact: Leonid Natapov <lnatapov>
Severity: high Docs Contact:
Priority: high    
Version: 7.0 (Kilo)CC: apevec, dnavale, lhh, yeylon
Target Milestone: z2Keywords: Rebase, Triaged, ZStream
Target Release: 7.0 (Kilo)   
Hardware: Unspecified   
OS: Unspecified   
Whiteboard:
Fixed In Version: python-sqlalchemy-1.0.8-1.el7ost Doc Type: Rebase: Bug Fixes Only
Doc Text:
Previously, a connection-level event handler in SQLAlchemy was invoked with the wrong state when a database reconnection attempt had failed. A separate change introduced in SQLAlchemy 1.0.2 made a slight change to the scope of the connection-level datastructure (Connection.info) during the reconnection process. The oslo.db OpenStack library depends on the state, which it stores in the datastructure within the event handler, and due to these two changes together, the datastructure unexpectedly blanked out if multiple reconnection attempts failed before eventually succeeding. As a result, when OpenStack applications attempted to recover after an unexpected database disconnect, they would in some cases encounter this situation, raise a stack trace from within oslo.db and fail to continue. With this update, the rebase of SQLAlchemy to version 1.0.8 fixes the issue with the event handler so that the correct state is passed to the connection event, allowing oslo.db to correctly maintain the information in Connection.info it expects, resulting in the multiple database reconnection attempts in OpenStack applications no longer causing oslo.db to fail.
Story Points: ---
Clone Of: Environment:
Last Closed: 2015-10-08 12:21:47 UTC Type: Bug
Regression: --- Mount Type: ---
Documentation: --- CRM:
Verified Versions: Category: ---
oVirt Team: --- RHEL 7.3 requirements from Atomic Host:
Cloudforms Team: --- Target Upstream Version:
Embargoed:

Description Attila Fazekas 2015-07-22 12:48:08 UTC
Description of problem:

I have restarted the mariadb on the undercloud node,
than attempted to deploy new system.

I received the "KeyError: 'pid'" as the heat service responses several times,
at the some time the following was logged.:

2015-07-22 08:25:52.192 29919 ERROR oslo_messaging.rpc.dispatcher [req-95325bb2-8441-4ff7-b288-1e5af4bd8fe8 admin admin] Exception during message handling: 'pid'
2015-07-22 08:25:52.192 29919 TRACE oslo_messaging.rpc.dispatcher Traceback (most recent call last):
2015-07-22 08:25:52.192 29919 TRACE oslo_messaging.rpc.dispatcher   File "/usr/lib/python2.7/site-packages/oslo_messaging/rpc/dispatcher.py", line 142, in _dispatch_and_reply
2015-07-22 08:25:52.192 29919 TRACE oslo_messaging.rpc.dispatcher     executor_callback))
2015-07-22 08:25:52.192 29919 TRACE oslo_messaging.rpc.dispatcher   File "/usr/lib/python2.7/site-packages/oslo_messaging/rpc/dispatcher.py", line 186, in _dispatch
2015-07-22 08:25:52.192 29919 TRACE oslo_messaging.rpc.dispatcher     executor_callback)
2015-07-22 08:25:52.192 29919 TRACE oslo_messaging.rpc.dispatcher   File "/usr/lib/python2.7/site-packages/oslo_messaging/rpc/dispatcher.py", line 130, in _do_dispatch
2015-07-22 08:25:52.192 29919 TRACE oslo_messaging.rpc.dispatcher     result = func(ctxt, **new_args)
2015-07-22 08:25:52.192 29919 TRACE oslo_messaging.rpc.dispatcher   File "/usr/lib/python2.7/site-packages/osprofiler/profiler.py", line 105, in wrapper
2015-07-22 08:25:52.192 29919 TRACE oslo_messaging.rpc.dispatcher     return f(*args, **kwargs)
2015-07-22 08:25:52.192 29919 TRACE oslo_messaging.rpc.dispatcher   File "/usr/lib/python2.7/site-packages/heat/common/context.py", line 300, in wrapped
2015-07-22 08:25:52.192 29919 TRACE oslo_messaging.rpc.dispatcher     return func(self, ctx, *args, **kwargs)
2015-07-22 08:25:52.192 29919 TRACE oslo_messaging.rpc.dispatcher   File "/usr/lib/python2.7/site-packages/heat/engine/service.py", line 669, in create_stack
2015-07-22 08:25:52.192 29919 TRACE oslo_messaging.rpc.dispatcher     parent_resource_name)
2015-07-22 08:25:52.192 29919 TRACE oslo_messaging.rpc.dispatcher   File "/usr/lib/python2.7/site-packages/heat/engine/service.py", line 565, in _parse_template_and_validate_stack
2015-07-22 08:25:52.192 29919 TRACE oslo_messaging.rpc.dispatcher     self._validate_new_stack(cnxt, stack_name, tmpl)
2015-07-22 08:25:52.192 29919 TRACE oslo_messaging.rpc.dispatcher   File "/usr/lib/python2.7/site-packages/heat/engine/service.py", line 533, in _validate_new_stack
2015-07-22 08:25:52.192 29919 TRACE oslo_messaging.rpc.dispatcher     if stack_object.Stack.count_all(cnxt) >= tenant_limit:
2015-07-22 08:25:52.192 29919 TRACE oslo_messaging.rpc.dispatcher   File "/usr/lib/python2.7/site-packages/heat/objects/stack.py", line 140, in count_all
2015-07-22 08:25:52.192 29919 TRACE oslo_messaging.rpc.dispatcher     return db_api.stack_count_all(context, **kwargs)
2015-07-22 08:25:52.192 29919 TRACE oslo_messaging.rpc.dispatcher   File "/usr/lib/python2.7/site-packages/heat/db/api.py", line 148, in stack_count_all
2015-07-22 08:25:52.192 29919 TRACE oslo_messaging.rpc.dispatcher     show_nested=show_nested)
2015-07-22 08:25:52.192 29919 TRACE oslo_messaging.rpc.dispatcher   File "/usr/lib/python2.7/site-packages/heat/db/sqlalchemy/api.py", line 418, in stack_count_all
2015-07-22 08:25:52.192 29919 TRACE oslo_messaging.rpc.dispatcher     return query.count()
2015-07-22 08:25:52.192 29919 TRACE oslo_messaging.rpc.dispatcher   File "/usr/lib64/python2.7/site-packages/sqlalchemy/orm/query.py", line 2734, in count
2015-07-22 08:25:52.192 29919 TRACE oslo_messaging.rpc.dispatcher     return self.from_self(col).scalar()
2015-07-22 08:25:52.192 29919 TRACE oslo_messaging.rpc.dispatcher   File "/usr/lib64/python2.7/site-packages/sqlalchemy/orm/query.py", line 2503, in scalar
2015-07-22 08:25:52.192 29919 TRACE oslo_messaging.rpc.dispatcher     ret = self.one()
2015-07-22 08:25:52.192 29919 TRACE oslo_messaging.rpc.dispatcher   File "/usr/lib64/python2.7/site-packages/sqlalchemy/orm/query.py", line 2472, in one
2015-07-22 08:25:52.192 29919 TRACE oslo_messaging.rpc.dispatcher     ret = list(self)
2015-07-22 08:25:52.192 29919 TRACE oslo_messaging.rpc.dispatcher   File "/usr/lib64/python2.7/site-packages/sqlalchemy/orm/query.py", line 2515, in __iter__
2015-07-22 08:25:52.192 29919 TRACE oslo_messaging.rpc.dispatcher     return self._execute_and_instances(context)
2015-07-22 08:25:52.192 29919 TRACE oslo_messaging.rpc.dispatcher   File "/usr/lib64/python2.7/site-packages/sqlalchemy/orm/query.py", line 2528, in _execute_and_instances
2015-07-22 08:25:52.192 29919 TRACE oslo_messaging.rpc.dispatcher     close_with_result=True)
2015-07-22 08:25:52.192 29919 TRACE oslo_messaging.rpc.dispatcher   File "/usr/lib64/python2.7/site-packages/sqlalchemy/orm/query.py", line 2519, in _connection_from_session
2015-07-22 08:25:52.192 29919 TRACE oslo_messaging.rpc.dispatcher     **kw)
2015-07-22 08:25:52.192 29919 TRACE oslo_messaging.rpc.dispatcher   File "/usr/lib64/python2.7/site-packages/sqlalchemy/orm/session.py", line 882, in connection
2015-07-22 08:25:52.192 29919 TRACE oslo_messaging.rpc.dispatcher     execution_options=execution_options)
2015-07-22 08:25:52.192 29919 TRACE oslo_messaging.rpc.dispatcher   File "/usr/lib64/python2.7/site-packages/sqlalchemy/orm/session.py", line 889, in _connection_for_bind
2015-07-22 08:25:52.192 29919 TRACE oslo_messaging.rpc.dispatcher     conn = engine.contextual_connect(**kw)
2015-07-22 08:25:52.192 29919 TRACE oslo_messaging.rpc.dispatcher   File "/usr/lib64/python2.7/site-packages/sqlalchemy/engine/base.py", line 2037, in contextual_connect
2015-07-22 08:25:52.192 29919 TRACE oslo_messaging.rpc.dispatcher     self._wrap_pool_connect(self.pool.connect, None),
2015-07-22 08:25:52.192 29919 TRACE oslo_messaging.rpc.dispatcher   File "/usr/lib64/python2.7/site-packages/sqlalchemy/engine/base.py", line 2072, in _wrap_pool_connect
2015-07-22 08:25:52.192 29919 TRACE oslo_messaging.rpc.dispatcher     return fn()
2015-07-22 08:25:52.192 29919 TRACE oslo_messaging.rpc.dispatcher   File "/usr/lib64/python2.7/site-packages/sqlalchemy/pool.py", line 376, in connect
2015-07-22 08:25:52.192 29919 TRACE oslo_messaging.rpc.dispatcher     return _ConnectionFairy._checkout(self)
2015-07-22 08:25:52.192 29919 TRACE oslo_messaging.rpc.dispatcher   File "/usr/lib64/python2.7/site-packages/sqlalchemy/pool.py", line 729, in _checkout
2015-07-22 08:25:52.192 29919 TRACE oslo_messaging.rpc.dispatcher     fairy)
2015-07-22 08:25:52.192 29919 TRACE oslo_messaging.rpc.dispatcher   File "/usr/lib64/python2.7/site-packages/sqlalchemy/event/attr.py", line 258, in __call__
2015-07-22 08:25:52.192 29919 TRACE oslo_messaging.rpc.dispatcher     fn(*args, **kw)
2015-07-22 08:25:52.192 29919 TRACE oslo_messaging.rpc.dispatcher   File "/usr/lib/python2.7/site-packages/oslo_db/sqlalchemy/session.py", line 631, in checkout
2015-07-22 08:25:52.192 29919 TRACE oslo_messaging.rpc.dispatcher     if connection_record.info['pid'] != pid:
2015-07-22 08:25:52.192 29919 TRACE oslo_messaging.rpc.dispatcher KeyError: 'pid'
2015-07-22 08:25:52.192 29919 TRACE oslo_messaging.rpc.dispatcher 




Version-Release number of selected component (if applicable):
python-oslo-db-1.7.1-1.el7ost.noarch
python-sqlalchemy-1.0.5-1.el7ost.x86_64
openstack-heat-common-2015.1.0-4.el7ost.noarch


Reconnection MUST not throw KeyError to the end users face.


The broken connection handler just healed on later try.:
2015-07-22 08:25:52.199 29918 INFO heat.engine.resource [-] CREATE: TemplateResource "Networks" Stack "overcloud" [2b9906b0-761f-4b64-9b58-dc10214c6a8e]
2015-07-22 08:25:52.199 29918 TRACE heat.engine.resource Traceback (most recent call last):
2015-07-22 08:25:52.199 29918 TRACE heat.engine.resource   File "/usr/lib/python2.7/site-packages/heat/engine/resource.py", line 500, in _action_recorder
2015-07-22 08:25:52.199 29918 TRACE heat.engine.resource     yield
2015-07-22 08:25:52.199 29918 TRACE heat.engine.resource   File "/usr/lib/python2.7/site-packages/heat/engine/resource.py", line 570, in _do_action
2015-07-22 08:25:52.199 29918 TRACE heat.engine.resource     yield self.action_handler_task(action, args=handler_args)
2015-07-22 08:25:52.199 29918 TRACE heat.engine.resource   File "/usr/lib/python2.7/site-packages/heat/engine/scheduler.py", line 296, in wrapper
2015-07-22 08:25:52.199 29918 TRACE heat.engine.resource     step = next(subtask)
2015-07-22 08:25:52.199 29918 TRACE heat.engine.resource   File "/usr/lib/python2.7/site-packages/heat/engine/resource.py", line 541, in action_handler_task
2015-07-22 08:25:52.199 29918 TRACE heat.engine.resource     handler_data = handler(*args)
2015-07-22 08:25:52.199 29918 TRACE heat.engine.resource   File "/usr/lib/python2.7/site-packages/heat/engine/resources/template_resource.py", line 257, in handle_create
2015-07-22 08:25:52.199 29918 TRACE heat.engine.resource     self.child_params())
2015-07-22 08:25:52.199 29918 TRACE heat.engine.resource   File "/usr/lib/python2.7/site-packages/heat/engine/resources/stack_resource.py", line 265, in create_with_template
2015-07-22 08:25:52.199 29918 TRACE heat.engine.resource     self.raise_local_exception(ex)
2015-07-22 08:25:52.199 29918 TRACE heat.engine.resource   File "/usr/lib/python2.7/site-packages/heat/engine/resources/stack_resource.py", line 284, in raise_local_exception
2015-07-22 08:25:52.199 29918 TRACE heat.engine.resource     local_ex = copy.copy(getattr(exception, ex_type))
2015-07-22 08:25:52.199 29918 TRACE heat.engine.resource AttributeError: 'module' object has no attribute 'KeyError'
2015-07-22 08:25:52.199 29918 TRACE heat.engine.resource 
2015-07-22 08:25:52.202 29919 ERROR sqlalchemy.pool.QueuePool [req-95325bb2-8441-4ff7-b288-1e5af4bd8fe8 admin admin] Exception during reset or similar
2015-07-22 08:25:52.202 29919 TRACE sqlalchemy.pool.QueuePool Traceback (most recent call last):
2015-07-22 08:25:52.202 29919 TRACE sqlalchemy.pool.QueuePool   File "/usr/lib64/python2.7/site-packages/sqlalchemy/pool.py", line 631, in _finalize_fairy
2015-07-22 08:25:52.202 29919 TRACE sqlalchemy.pool.QueuePool     fairy._reset(pool)
2015-07-22 08:25:52.202 29919 TRACE sqlalchemy.pool.QueuePool   File "/usr/lib64/python2.7/site-packages/sqlalchemy/pool.py", line 771, in _reset
2015-07-22 08:25:52.202 29919 TRACE sqlalchemy.pool.QueuePool     pool._dialect.do_rollback(self)
2015-07-22 08:25:52.202 29919 TRACE sqlalchemy.pool.QueuePool   File "/usr/lib64/python2.7/site-packages/sqlalchemy/dialects/mysql/base.py", line 2519, in do_rollback
2015-07-22 08:25:52.202 29919 TRACE sqlalchemy.pool.QueuePool     dbapi_connection.rollback()
2015-07-22 08:25:52.202 29919 TRACE sqlalchemy.pool.QueuePool OperationalError: (2006, 'MySQL server has gone away')
2015-07-22 08:25:52.202 29919 TRACE sqlalchemy.pool.QueuePool 
2015-07-22 08:25:52.203 29919 ERROR sqlalchemy.pool.QueuePool [req-95325bb2-8441-4ff7-b288-1e5af4bd8fe8 admin admin] Exception closing connection <_mysql.connection closed at 9be65b0>
2015-07-22 08:25:52.203 29919 TRACE sqlalchemy.pool.QueuePool Traceback (most recent call last):
2015-07-22 08:25:52.203 29919 TRACE sqlalchemy.pool.QueuePool   File "/usr/lib64/python2.7/site-packages/sqlalchemy/pool.py", line 290, in _close_connection
2015-07-22 08:25:52.203 29919 TRACE sqlalchemy.pool.QueuePool     self._dialect.do_close(connection)
2015-07-22 08:25:52.203 29919 TRACE sqlalchemy.pool.QueuePool   File "/usr/lib64/python2.7/site-packages/sqlalchemy/engine/default.py", line 426, in do_close
2015-07-22 08:25:52.203 29919 TRACE sqlalchemy.pool.QueuePool     dbapi_connection.close()
2015-07-22 08:25:52.203 29919 TRACE sqlalchemy.pool.QueuePool ProgrammingError: closing a closed connection
2015-07-22 08:25:52.203 29919 TRACE sqlalchemy.pool.QueuePool

Comment 3 Michael Bayer 2015-07-22 14:37:21 UTC
this issue is local to oslo.db.   The cause is that we have a protection mechanism which ensures that a connection which is used in a certain process is only used in that same process subsequently.  This is the 'pid' key we place in .info.   What's not clear is why the key would be missing.   I thought perhaps that if the connection were recycled, maybe the 'connect' event which populates the 'pid' is not getting called, but this event is always called in the two areas where the connection is recycled and .info is cleared.

I would need to see if there's a way to reproduce this condition with oslo.db.  I'm not at the moment seeing any codepath that could produce this unless something else were affecting that .info dictionary.

Comment 4 Michael Bayer 2015-07-22 20:00:57 UTC
this issue is occurring in several OS projects and I've identified the probable upstream cause here:

https://bitbucket.org/zzzeek/sqlalchemy/issues/3497/connectionrec-recycle-can-create-situation

Comment 5 Michael Bayer 2015-07-22 20:40:45 UTC
this is an oslo.db-level reproduction case:

from oslo_db.sqlalchemy.session import create_engine


engine = create_engine("mysql://scott:tiger@localhost/test")


c1 = engine.connect()
c2 = engine.connect()

c1.scalar("select 1")
c2.scalar("select 1")
c1.close()
c2.close()

raw_input("shutdown")

try:
    conn = engine.connect()
except Exception as e:
    print "expected error: %s" % e

assert engine.pool._invalidate_time

try:
    c2 = engine.connect()
except Exception as e:
    print "expected error: %s" % e


c3 = engine.connect()

when the script pauses on "shutdown", shut off the MySQL database, then press enter to watch the failure.  The failure will occur in SQLAlchemy 1.0.3 or greater, and should not occur in 1.0.2 or earlier.  The underlying issue is still present in those versions as well as the 0.9 series however the specific case of the 'info' dictionary being involved occurs in 1.0.3, due to changes in the connection lifecycle to suit the HAAlchemy project.

Comment 9 Michael Bayer 2015-08-27 18:29:18 UTC
Looking here to rebase python-sqlalchemy-1.0.5 to python-sqlalchemy-1.0.8.  changelog is at http://docs.sqlalchemy.org/en/rel_1_0/changelog/changelog_10.html. The SQLAlchemy 1.0 series is only doing bugfixes and only a tiny amount of maximally conservative feature adds, all new feature dev is in the 1.1 series now; I've reviewed all changes between 1.0.5 and 1.0.8 and none have any backwards-incompatible implications.

Comment 12 Leonid Natapov 2015-09-24 08:59:36 UTC
python-sqlalchemy-1.0.8-1.el7ost.x86_64

No errors after restarting mariadb on undercloud and deploying new system.

Comment 14 errata-xmlrpc 2015-10-08 12:21:47 UTC
Since the problem described in this bug report should be
resolved in a recent advisory, it has been closed with a
resolution of ERRATA.

For information on the advisory, and where to find the updated
files, follow the link below.

If the solution does not work for you, open a new bug report.

https://access.redhat.com/errata/RHBA-2015:1875