KeyError: 'pid' during db pool connection

[Matt Riedemann]

Seeing this failure in neutron jobs:

http://logs.openstack.org/56/192056/10/gate/gate-tempest-dsvm-neutron-full/f22040d/logs/screen-q-svc.txt.gz?level=TRACE#_2015-07-21_11_52_02_455

2015-07-21 11:52:02.455 ERROR neutron.api.v2.resource [req-6fce31a6-b270-4cdb-adb0-b1bb0e58ebbf tempest-TestNetworkAdvancedServerOps-391040567 tempest-TestNetworkAdvancedServerOps-916491658] delete failed
2015-07-21 11:52:02.455 8090 ERROR neutron.api.v2.resource Traceback (most recent call last):
2015-07-21 11:52:02.455 8090 ERROR neutron.api.v2.resource File "/opt/stack/new/neutron/neutron/api/v2/resource.py", line 83, in resource
2015-07-21 11:52:02.455 8090 ERROR neutron.api.v2.resource result = method(request=request, **args)
2015-07-21 11:52:02.455 8090 ERROR neutron.api.v2.resource File "/usr/local/lib/python2.7/dist-packages/oslo_db/api.py", line 146, in wrapper
2015-07-21 11:52:02.455 8090 ERROR neutron.api.v2.resource ectxt.value = e.inner_exc
2015-07-21 11:52:02.455 8090 ERROR neutron.api.v2.resource File "/usr/local/lib/python2.7/dist-packages/oslo_utils/excutils.py", line 119, in __exit__
2015-07-21 11:52:02.455 8090 ERROR neutron.api.v2.resource six.reraise(self.type_, self.value, self.tb)
2015-07-21 11:52:02.455 8090 ERROR neutron.api.v2.resource File "/usr/local/lib/python2.7/dist-packages/oslo_db/api.py", line 136, in wrapper
2015-07-21 11:52:02.455 8090 ERROR neutron.api.v2.resource return f(*args, **kwargs)
2015-07-21 11:52:02.455 8090 ERROR neutron.api.v2.resource File "/opt/stack/new/neutron/neutron/api/v2/base.py", line 486, in delete
2015-07-21 11:52:02.455 8090 ERROR neutron.api.v2.resource obj = self._item(request, id, parent_id=parent_id)
2015-07-21 11:52:02.455 8090 ERROR neutron.api.v2.resource File "/opt/stack/new/neutron/neutron/api/v2/base.py", line 293, in _item
2015-07-21 11:52:02.455 8090 ERROR neutron.api.v2.resource obj = obj_getter(request.context, id, **kwargs)
2015-07-21 11:52:02.455 8090 ERROR neutron.api.v2.resource File "/opt/stack/new/neutron/neutron/db/securitygroups_db.py", line 588, in get_security_group_rule
2015-07-21 11:52:02.455 8090 ERROR neutron.api.v2.resource security_group_rule = self._get_security_group_rule(context, id)
2015-07-21 11:52:02.455 8090 ERROR neutron.api.v2.resource File "/opt/stack/new/neutron/neutron/db/securitygroups_db.py", line 594, in _get_security_group_rule
2015-07-21 11:52:02.455 8090 ERROR neutron.api.v2.resource sgr = query.filter(SecurityGroupRule.id == id).one()
2015-07-21 11:52:02.455 8090 ERROR neutron.api.v2.resource File "/usr/local/lib/python2.7/dist-packages/sqlalchemy/orm/query.py", line 2473, in one
2015-07-21 11:52:02.455 8090 ERROR neutron.api.v2.resource ret = list(self)
2015-07-21 11:52:02.455 8090 ERROR neutron.api.v2.resource File "/usr/local/lib/python2.7/dist-packages/sqlalchemy/orm/query.py", line 2516, in __iter__
2015-07-21 11:52:02.455 8090 ERROR neutron.api.v2.resource return self._execute_and_instances(context)
2015-07-21 11:52:02.455 8090 ERROR neutron.api.v2.resource File "/usr/local/lib/python2.7/dist-packages/sqlalchemy/orm/query.py", line 2529, in _execute_and_instances
2015-07-21 11:52:02.455 8090 ERROR neutron.api.v2.resource close_with_result=True)
2015-07-21 11:52:02.455 8090 ERROR neutron.api.v2.resource File "/usr/local/lib/python2.7/dist-packages/sqlalchemy/orm/query.py", line 2520, in _connection_from_session
2015-07-21 11:52:02.455 8090 ERROR neutron.api.v2.resource **kw)
2015-07-21 11:52:02.455 8090 ERROR neutron.api.v2.resource File "/usr/local/lib/python2.7/dist-packages/sqlalchemy/orm/session.py", line 882, in connection
2015-07-21 11:52:02.455 8090 ERROR neutron.api.v2.resource execution_options=execution_options)
2015-07-21 11:52:02.455 8090 ERROR neutron.api.v2.resource File "/usr/local/lib/python2.7/dist-packages/sqlalchemy/orm/session.py", line 889, in _connection_for_bind
2015-07-21 11:52:02.455 8090 ERROR neutron.api.v2.resource conn = engine.contextual_connect(**kw)
2015-07-21 11:52:02.455 8090 ERROR neutron.api.v2.resource File "/usr/local/lib/python2.7/dist-packages/sqlalchemy/engine/base.py", line 2035, in contextual_connect
2015-07-21 11:52:02.455 8090 ERROR neutron.api.v2.resource self._wrap_pool_connect(self.pool.connect, None),
2015-07-21 11:52:02.455 8090 ERROR neutron.api.v2.resource File "/usr/local/lib/python2.7/dist-packages/sqlalchemy/engine/base.py", line 2070, in _wrap_pool_connect
2015-07-21 11:52:02.455 8090 ERROR neutron.api.v2.resource return fn()
2015-07-21 11:52:02.455 8090 ERROR neutron.api.v2.resource File "/usr/local/lib/python2.7/dist-packages/sqlalchemy/pool.py", line 376, in connect
2015-07-21 11:52:02.455 8090 ERROR neutron.api.v2.resource return _ConnectionFairy._checkout(self)
2015-07-21 11:52:02.455 8090 ERROR neutron.api.v2.resource File "/usr/local/lib/python2.7/dist-packages/sqlalchemy/pool.py", line 729, in _checkout
2015-07-21 11:52:02.455 8090 ERROR neutron.api.v2.resource fairy)
2015-07-21 11:52:02.455 8090 ERROR neutron.api.v2.resource File "/usr/local/lib/python2.7/dist-packages/sqlalchemy/event/attr.py", line 258, in __call__
2015-07-21 11:52:02.455 8090 ERROR neutron.api.v2.resource fn(*args, **kw)
2015-07-21 11:52:02.455 8090 ERROR neutron.api.v2.resource File "/usr/local/lib/python2.7/dist-packages/oslo_db/sqlalchemy/engines.py", line 349, in checkout
2015-07-21 11:52:02.455 8090 ERROR neutron.api.v2.resource if connection_record.info['pid'] != pid:
2015-07-21 11:52:02.455 8090 ERROR neutron.api.v2.resource KeyError: 'pid'
2015-07-21 11:52:02.455 8090 ERROR neutron.api.v2.resource

[Mike Bayer (zzzeek)]

can this be reproduced? I'm seeing in other bug reports too.

[Matt Riedemann (mriedem)]

Yes, mostly neutron but some n-api logs: http://goo.gl/GqLwul

[Mike Bayer (zzzeek)]

this is a bug in SQLAlchemy and I've identified it.

[Mike Bayer (zzzeek)]

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

[Mike Bayer (zzzeek)]

oslo.db 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.

[Mike Bayer (zzzeek)]

see https://review.openstack.org/#/c/205201/

[Roman Podoliaka (rpodolyaka)]

Fixed in SQLAlchemy