"MySQL server has gone away" again

Bug #1361378 reported by Dolph Mathews on 2014-08-25
28
This bug affects 6 people
Affects Status Importance Assigned to Milestone
OpenStack Identity (keystone)
High
Unassigned
oslo.db
Undecided
Unassigned

Bug Description

This is a regression of an old issue, which I thought was resolved by the "SELECT 1;" hack, but perhaps recently reintroduced with oslo.db?

[Mon Aug 25 14:30:54.403538 2014] [:error] [pid 25778:tid 139886259214080] 25778 ERROR keystone.common.wsgi [-] (OperationalError) (2003, "Can't connect to MySQL server on '127.0.0.1' (111)") None None
[Mon Aug 25 14:30:54.403562 2014] [:error] [pid 25778:tid 139886259214080] 25778 TRACE keystone.common.wsgi Traceback (most recent call last):
[Mon Aug 25 14:30:54.403570 2014] [:error] [pid 25778:tid 139886259214080] 25778 TRACE keystone.common.wsgi File "/opt/stack/new/keystone/keystone/common/wsgi.py", line 214, in __call__
[Mon Aug 25 14:30:54.403575 2014] [:error] [pid 25778:tid 139886259214080] 25778 TRACE keystone.common.wsgi result = method(context, **params)
[Mon Aug 25 14:30:54.403581 2014] [:error] [pid 25778:tid 139886259214080] 25778 TRACE keystone.common.wsgi File "/opt/stack/new/keystone/keystone/token/controllers.py", line 99, in authenticate
[Mon Aug 25 14:30:54.403589 2014] [:error] [pid 25778:tid 139886259214080] 25778 TRACE keystone.common.wsgi context, auth)
[Mon Aug 25 14:30:54.403594 2014] [:error] [pid 25778:tid 139886259214080] 25778 TRACE keystone.common.wsgi File "/opt/stack/new/keystone/keystone/token/controllers.py", line 308, in _authenticate_local
[Mon Aug 25 14:30:54.403600 2014] [:error] [pid 25778:tid 139886259214080] 25778 TRACE keystone.common.wsgi username, CONF.identity.default_domain_id)
[Mon Aug 25 14:30:54.403606 2014] [:error] [pid 25778:tid 139886259214080] 25778 TRACE keystone.common.wsgi File "/opt/stack/new/keystone/keystone/identity/core.py", line 182, in wrapper
[Mon Aug 25 14:30:54.403612 2014] [:error] [pid 25778:tid 139886259214080] 25778 TRACE keystone.common.wsgi return f(self, *args, **kwargs)
[Mon Aug 25 14:30:54.403618 2014] [:error] [pid 25778:tid 139886259214080] 25778 TRACE keystone.common.wsgi File "/opt/stack/new/keystone/keystone/identity/core.py", line 193, in wrapper
[Mon Aug 25 14:30:54.403624 2014] [:error] [pid 25778:tid 139886259214080] 25778 TRACE keystone.common.wsgi return f(self, *args, **kwargs)
[Mon Aug 25 14:30:54.403630 2014] [:error] [pid 25778:tid 139886259214080] 25778 TRACE keystone.common.wsgi File "/opt/stack/new/keystone/keystone/identity/core.py", line 579, in get_user_by_name
[Mon Aug 25 14:30:54.403637 2014] [:error] [pid 25778:tid 139886259214080] 25778 TRACE keystone.common.wsgi ref = driver.get_user_by_name(user_name, domain_id)
[Mon Aug 25 14:30:54.403644 2014] [:error] [pid 25778:tid 139886259214080] 25778 TRACE keystone.common.wsgi File "/opt/stack/new/keystone/keystone/identity/backends/sql.py", line 140, in get_user_by_name
[Mon Aug 25 14:30:54.403650 2014] [:error] [pid 25778:tid 139886259214080] 25778 TRACE keystone.common.wsgi user_ref = query.one()
[Mon Aug 25 14:30:54.403656 2014] [:error] [pid 25778:tid 139886259214080] 25778 TRACE keystone.common.wsgi File "/usr/lib/python2.7/dist-packages/sqlalchemy/orm/query.py", line 2310, in one
[Mon Aug 25 14:30:54.403662 2014] [:error] [pid 25778:tid 139886259214080] 25778 TRACE keystone.common.wsgi ret = list(self)
[Mon Aug 25 14:30:54.403667 2014] [:error] [pid 25778:tid 139886259214080] 25778 TRACE keystone.common.wsgi File "/usr/lib/python2.7/dist-packages/sqlalchemy/orm/query.py", line 2353, in __iter__
[Mon Aug 25 14:30:54.403673 2014] [:error] [pid 25778:tid 139886259214080] 25778 TRACE keystone.common.wsgi return self._execute_and_instances(context)
[Mon Aug 25 14:30:54.403680 2014] [:error] [pid 25778:tid 139886259214080] 25778 TRACE keystone.common.wsgi File "/usr/lib/python2.7/dist-packages/sqlalchemy/orm/query.py", line 2366, in _execute_and_instances
[Mon Aug 25 14:30:54.403731 2014] [:error] [pid 25778:tid 139886259214080] 25778 TRACE keystone.common.wsgi close_with_result=True)
[Mon Aug 25 14:30:54.403740 2014] [:error] [pid 25778:tid 139886259214080] 25778 TRACE keystone.common.wsgi File "/usr/lib/python2.7/dist-packages/sqlalchemy/orm/query.py", line 2357, in _connection_from_session
[Mon Aug 25 14:30:54.403746 2014] [:error] [pid 25778:tid 139886259214080] 25778 TRACE keystone.common.wsgi **kw)
[Mon Aug 25 14:30:54.403752 2014] [:error] [pid 25778:tid 139886259214080] 25778 TRACE keystone.common.wsgi File "/usr/lib/python2.7/dist-packages/sqlalchemy/orm/session.py", line 799, in connection
[Mon Aug 25 14:30:54.403757 2014] [:error] [pid 25778:tid 139886259214080] 25778 TRACE keystone.common.wsgi close_with_result=close_with_result)
[Mon Aug 25 14:30:54.403763 2014] [:error] [pid 25778:tid 139886259214080] 25778 TRACE keystone.common.wsgi File "/usr/lib/python2.7/dist-packages/sqlalchemy/orm/session.py", line 805, in _connection_for_bind
[Mon Aug 25 14:30:54.403769 2014] [:error] [pid 25778:tid 139886259214080] 25778 TRACE keystone.common.wsgi return engine.contextual_connect(**kwargs)
[Mon Aug 25 14:30:54.403775 2014] [:error] [pid 25778:tid 139886259214080] 25778 TRACE keystone.common.wsgi File "/usr/lib/python2.7/dist-packages/sqlalchemy/engine/base.py", line 1661, in contextual_connect
[Mon Aug 25 14:30:54.403782 2014] [:error] [pid 25778:tid 139886259214080] 25778 TRACE keystone.common.wsgi self.pool.connect(),
[Mon Aug 25 14:30:54.403787 2014] [:error] [pid 25778:tid 139886259214080] 25778 TRACE keystone.common.wsgi File "/usr/lib/python2.7/dist-packages/sqlalchemy/pool.py", line 272, in connect
[Mon Aug 25 14:30:54.403793 2014] [:error] [pid 25778:tid 139886259214080] 25778 TRACE keystone.common.wsgi return _ConnectionFairy(self).checkout()
[Mon Aug 25 14:30:54.403799 2014] [:error] [pid 25778:tid 139886259214080] 25778 TRACE keystone.common.wsgi File "/usr/lib/python2.7/dist-packages/sqlalchemy/pool.py", line 431, in __init__
[Mon Aug 25 14:30:54.403804 2014] [:error] [pid 25778:tid 139886259214080] 25778 TRACE keystone.common.wsgi rec = self._connection_record = pool._do_get()
[Mon Aug 25 14:30:54.403810 2014] [:error] [pid 25778:tid 139886259214080] 25778 TRACE keystone.common.wsgi File "/usr/lib/python2.7/dist-packages/sqlalchemy/pool.py", line 772, in _do_get
[Mon Aug 25 14:30:54.403815 2014] [:error] [pid 25778:tid 139886259214080] 25778 TRACE keystone.common.wsgi return self._create_connection()
[Mon Aug 25 14:30:54.403820 2014] [:error] [pid 25778:tid 139886259214080] 25778 TRACE keystone.common.wsgi File "/usr/lib/python2.7/dist-packages/sqlalchemy/pool.py", line 225, in _create_connection
[Mon Aug 25 14:30:54.403826 2014] [:error] [pid 25778:tid 139886259214080] 25778 TRACE keystone.common.wsgi return _ConnectionRecord(self)
[Mon Aug 25 14:30:54.403833 2014] [:error] [pid 25778:tid 139886259214080] 25778 TRACE keystone.common.wsgi File "/usr/lib/python2.7/dist-packages/sqlalchemy/pool.py", line 318, in __init__
[Mon Aug 25 14:30:54.403839 2014] [:error] [pid 25778:tid 139886259214080] 25778 TRACE keystone.common.wsgi self.connection = self.__connect()
[Mon Aug 25 14:30:54.403845 2014] [:error] [pid 25778:tid 139886259214080] 25778 TRACE keystone.common.wsgi File "/usr/lib/python2.7/dist-packages/sqlalchemy/pool.py", line 379, in __connect
[Mon Aug 25 14:30:54.403851 2014] [:error] [pid 25778:tid 139886259214080] 25778 TRACE keystone.common.wsgi connection = self.__pool._creator()
[Mon Aug 25 14:30:54.403857 2014] [:error] [pid 25778:tid 139886259214080] 25778 TRACE keystone.common.wsgi File "/usr/lib/python2.7/dist-packages/sqlalchemy/engine/strategies.py", line 80, in connect
[Mon Aug 25 14:30:54.403862 2014] [:error] [pid 25778:tid 139886259214080] 25778 TRACE keystone.common.wsgi return dialect.connect(*cargs, **cparams)
[Mon Aug 25 14:30:54.403868 2014] [:error] [pid 25778:tid 139886259214080] 25778 TRACE keystone.common.wsgi File "/usr/lib/python2.7/dist-packages/sqlalchemy/engine/default.py", line 283, in connect
[Mon Aug 25 14:30:54.403888 2014] [:error] [pid 25778:tid 139886259214080] 25778 TRACE keystone.common.wsgi return self.dbapi.connect(*cargs, **cparams)
[Mon Aug 25 14:30:54.403894 2014] [:error] [pid 25778:tid 139886259214080] 25778 TRACE keystone.common.wsgi File "/usr/lib/python2.7/dist-packages/MySQLdb/__init__.py", line 81, in Connect
[Mon Aug 25 14:30:54.403901 2014] [:error] [pid 25778:tid 139886259214080] 25778 TRACE keystone.common.wsgi return Connection(*args, **kwargs)
[Mon Aug 25 14:30:54.403906 2014] [:error] [pid 25778:tid 139886259214080] 25778 TRACE keystone.common.wsgi File "/usr/lib/python2.7/dist-packages/MySQLdb/connections.py", line 187, in __init__
[Mon Aug 25 14:30:54.403911 2014] [:error] [pid 25778:tid 139886259214080] 25778 TRACE keystone.common.wsgi super(Connection, self).__init__(*args, **kwargs2)
[Mon Aug 25 14:30:54.403918 2014] [:error] [pid 25778:tid 139886259214080] 25778 TRACE keystone.common.wsgi OperationalError: (OperationalError) (2003, "Can't connect to MySQL server on '127.0.0.1' (111)") None None
[Mon Aug 25 14:30:54.403924 2014] [:error] [pid 25778:tid 139886259214080] 25778 TRACE keystone.common.wsgi
[Mon Aug 25 14:30:54.425356 2014] [authz_core:debug] [pid 25788:tid 139886145304320] mod_authz_core.c(802): [client 127.0.0.1:46458] AH01626: authorization result of Require all granted: granted
[Mon Aug 25 14:30:54.425387 2014] [authz_core:debug] [pid 25788:tid 139886145304320] mod_authz_core.c(802): [client 127.0.0.1:46458] AH01626: authorization result of : granted
[Mon Aug 25 14:30:54.425432 2014] [authz_core:debug] [pid 25788:tid 139886145304320] mod_authz_core.c(802): [client 127.0.0.1:46458] AH01626: authorization result of Require all granted: granted
[Mon Aug 25 14:30:54.425446 2014] [authz_core:debug] [pid 25788:tid 139886145304320] mod_authz_core.c(802): [client 127.0.0.1:46458] AH01626: authorization result of : granted
[Mon Aug 25 14:30:54.426830 2014] [:error] [pid 25779:tid 139886259214080] 25779 DEBUG keystone.middleware.core [-] Auth token not in the request header. Will not build auth context. process_request /opt/stack/new/keystone/keystone/middleware/core.py:276
[Mon Aug 25 14:30:54.428226 2014] [:error] [pid 25779:tid 139886259214080] 25779 DEBUG keystone.common.wsgi [-] arg_dict: {} __call__ /opt/stack/new/keystone/keystone/common/wsgi.py:183
[Mon Aug 25 14:30:54.432009 2014] [:error] [pid 25779:tid 139886259214080] 25779 ERROR keystone.common.wsgi [-] (OperationalError) (2006, 'MySQL server has gone away') 'SELECT user.id AS user_id, user.name AS user_name, user.domain_id AS user_domain_id, user.password AS user_password, user.enabled AS user_enabled, user.extra AS user_extra, user.default_project_id AS user_default_project_id \\nFROM user \\nWHERE user.name = %s AND user.domain_id = %s' ('demo', 'default')
[Mon Aug 25 14:30:54.432034 2014] [:error] [pid 25779:tid 139886259214080] 25779 TRACE keystone.common.wsgi Traceback (most recent call last):
[Mon Aug 25 14:30:54.432041 2014] [:error] [pid 25779:tid 139886259214080] 25779 TRACE keystone.common.wsgi File "/opt/stack/new/keystone/keystone/common/wsgi.py", line 214, in __call__
[Mon Aug 25 14:30:54.432047 2014] [:error] [pid 25779:tid 139886259214080] 25779 TRACE keystone.common.wsgi result = method(context, **params)
[Mon Aug 25 14:30:54.432053 2014] [:error] [pid 25779:tid 139886259214080] 25779 TRACE keystone.common.wsgi File "/opt/stack/new/keystone/keystone/token/controllers.py", line 99, in authenticate
[Mon Aug 25 14:30:54.432059 2014] [:error] [pid 25779:tid 139886259214080] 25779 TRACE keystone.common.wsgi context, auth)
[Mon Aug 25 14:30:54.432065 2014] [:error] [pid 25779:tid 139886259214080] 25779 TRACE keystone.common.wsgi File "/opt/stack/new/keystone/keystone/token/controllers.py", line 308, in _authenticate_local
[Mon Aug 25 14:30:54.432071 2014] [:error] [pid 25779:tid 139886259214080] 25779 TRACE keystone.common.wsgi username, CONF.identity.default_domain_id)
[Mon Aug 25 14:30:54.432091 2014] [:error] [pid 25779:tid 139886259214080] 25779 TRACE keystone.common.wsgi File "/opt/stack/new/keystone/keystone/identity/core.py", line 182, in wrapper
[Mon Aug 25 14:30:54.432097 2014] [:error] [pid 25779:tid 139886259214080] 25779 TRACE keystone.common.wsgi return f(self, *args, **kwargs)
[Mon Aug 25 14:30:54.432103 2014] [:error] [pid 25779:tid 139886259214080] 25779 TRACE keystone.common.wsgi File "/opt/stack/new/keystone/keystone/identity/core.py", line 193, in wrapper
[Mon Aug 25 14:30:54.432108 2014] [:error] [pid 25779:tid 139886259214080] 25779 TRACE keystone.common.wsgi return f(self, *args, **kwargs)
[Mon Aug 25 14:30:54.432114 2014] [:error] [pid 25779:tid 139886259214080] 25779 TRACE keystone.common.wsgi File "/opt/stack/new/keystone/keystone/identity/core.py", line 579, in get_user_by_name
[Mon Aug 25 14:30:54.432121 2014] [:error] [pid 25779:tid 139886259214080] 25779 TRACE keystone.common.wsgi ref = driver.get_user_by_name(user_name, domain_id)
[Mon Aug 25 14:30:54.432128 2014] [:error] [pid 25779:tid 139886259214080] 25779 TRACE keystone.common.wsgi File "/opt/stack/new/keystone/keystone/identity/backends/sql.py", line 140, in get_user_by_name
[Mon Aug 25 14:30:54.432135 2014] [:error] [pid 25779:tid 139886259214080] 25779 TRACE keystone.common.wsgi user_ref = query.one()
[Mon Aug 25 14:30:54.432140 2014] [:error] [pid 25779:tid 139886259214080] 25779 TRACE keystone.common.wsgi File "/usr/lib/python2.7/dist-packages/sqlalchemy/orm/query.py", line 2310, in one
[Mon Aug 25 14:30:54.432146 2014] [:error] [pid 25779:tid 139886259214080] 25779 TRACE keystone.common.wsgi ret = list(self)
[Mon Aug 25 14:30:54.432154 2014] [:error] [pid 25779:tid 139886259214080] 25779 TRACE keystone.common.wsgi File "/usr/lib/python2.7/dist-packages/sqlalchemy/orm/query.py", line 2353, in __iter__
[Mon Aug 25 14:30:54.432160 2014] [:error] [pid 25779:tid 139886259214080] 25779 TRACE keystone.common.wsgi return self._execute_and_instances(context)
[Mon Aug 25 14:30:54.432169 2014] [:error] [pid 25779:tid 139886259214080] 25779 TRACE keystone.common.wsgi File "/usr/lib/python2.7/dist-packages/sqlalchemy/orm/query.py", line 2368, in _execute_and_instances
[Mon Aug 25 14:30:54.432174 2014] [:error] [pid 25779:tid 139886259214080] 25779 TRACE keystone.common.wsgi result = conn.execute(querycontext.statement, self._params)
[Mon Aug 25 14:30:54.432180 2014] [:error] [pid 25779:tid 139886259214080] 25779 TRACE keystone.common.wsgi File "/usr/lib/python2.7/dist-packages/sqlalchemy/engine/base.py", line 662, in execute
[Mon Aug 25 14:30:54.432186 2014] [:error] [pid 25779:tid 139886259214080] 25779 TRACE keystone.common.wsgi params)
[Mon Aug 25 14:30:54.432191 2014] [:error] [pid 25779:tid 139886259214080] 25779 TRACE keystone.common.wsgi File "/usr/lib/python2.7/dist-packages/sqlalchemy/engine/base.py", line 761, in _execute_clauseelement
[Mon Aug 25 14:30:54.432197 2014] [:error] [pid 25779:tid 139886259214080] 25779 TRACE keystone.common.wsgi compiled_sql, distilled_params
[Mon Aug 25 14:30:54.432203 2014] [:error] [pid 25779:tid 139886259214080] 25779 TRACE keystone.common.wsgi File "/usr/lib/python2.7/dist-packages/sqlalchemy/engine/base.py", line 874, in _execute_context
[Mon Aug 25 14:30:54.432209 2014] [:error] [pid 25779:tid 139886259214080] 25779 TRACE keystone.common.wsgi context)
[Mon Aug 25 14:30:54.432217 2014] [:error] [pid 25779:tid 139886259214080] 25779 TRACE keystone.common.wsgi File "/usr/local/lib/python2.7/dist-packages/oslo/db/sqlalchemy/compat/handle_error.py", line 125, in _handle_dbapi_exception
[Mon Aug 25 14:30:54.432223 2014] [:error] [pid 25779:tid 139886259214080] 25779 TRACE keystone.common.wsgi six.reraise(type(newraise), newraise, sys.exc_info()[2])
[Mon Aug 25 14:30:54.432232 2014] [:error] [pid 25779:tid 139886259214080] 25779 TRACE keystone.common.wsgi File "/usr/local/lib/python2.7/dist-packages/oslo/db/sqlalchemy/compat/handle_error.py", line 102, in _handle_dbapi_exception
[Mon Aug 25 14:30:54.432250 2014] [:error] [pid 25779:tid 139886259214080] 25779 TRACE keystone.common.wsgi per_fn = fn(ctx)
[Mon Aug 25 14:30:54.432256 2014] [:error] [pid 25779:tid 139886259214080] 25779 TRACE keystone.common.wsgi File "/usr/local/lib/python2.7/dist-packages/oslo/db/sqlalchemy/exc_filters.py", line 323, in handler
[Mon Aug 25 14:30:54.432263 2014] [:error] [pid 25779:tid 139886259214080] 25779 TRACE keystone.common.wsgi context.is_disconnect)
[Mon Aug 25 14:30:54.432270 2014] [:error] [pid 25779:tid 139886259214080] 25779 TRACE keystone.common.wsgi File "/usr/local/lib/python2.7/dist-packages/oslo/db/sqlalchemy/exc_filters.py", line 263, in _is_db_connection_error
[Mon Aug 25 14:30:54.432277 2014] [:error] [pid 25779:tid 139886259214080] 25779 TRACE keystone.common.wsgi raise exception.DBConnectionError(operational_error)
[Mon Aug 25 14:30:54.432286 2014] [:error] [pid 25779:tid 139886259214080] 25779 TRACE keystone.common.wsgi DBConnectionError: (OperationalError) (2006, 'MySQL server has gone away') 'SELECT user.id AS user_id, user.name AS user_name, user.domain_id AS user_domain_id, user.password AS user_password, user.enabled AS user_enabled, user.extra AS user_extra, user.default_project_id AS user_default_project_id \\nFROM user \\nWHERE user.name = %s AND user.domain_id = %s' ('demo', 'default')

This appeared as a transient issue in http://logs.openstack.org/74/111574/4/gate/gate-tempest-dsvm-neutron-full/a8ff79a/logs/screen-key.txt.gz

Dolph Mathews (dolph) on 2014-08-25
Changed in keystone:
importance: Undecided → High
tags: added: db
tags: added: sql
Roman Podoliaka (rpodolyaka) wrote :

oslo.db issues 'SELECT 1' unconditionally right after a new transaction begins:

https://github.com/openstack/oslo.db/blob/master/oslo/db/sqlalchemy/session.py#L382
https://github.com/openstack/oslo.db/blob/master/oslo/db/sqlalchemy/session.py#L314-L331

which allows to detect disconnects early and reconnect to RDMBs servers transparently to the application code.

At the same time, if an RDBMs server goes away in the middle of transaction, it's left up to the consuming application to retry the whole transaction again. oslo.db provides a helper decorator for this: https://github.com/openstack/oslo.db/blob/master/oslo/db/api.py#L62-L93

Changed in oslo:
status: New → Incomplete
Viktor Serhieiev (vsergeyev) wrote :

I'ts looks strange, because. afaik, "SELECT 1;" hack was not removed from oslo.db code.

I found in the tempest logs (in syslog), that MySQL process was killed, when the tests run. So `MySQL server has gone away` error looks correct in this case.

Aug 25 14:30:53 devstack-trusty-rax-dfw-1668934 kernel: [ 2571.497792] Out of memory: Kill process 9530 (mysqld) score 20 or sacrifice child
Aug 25 14:30:53 devstack-trusty-rax-dfw-1668934 kernel: [ 2571.497879] Killed process 9530 (mysqld) total-vm:4504928kB, anon-rss:163296kB, file-rss:0kB

http://logs.openstack.org/74/111574/4/gate/gate-tempest-dsvm-neutron-full/a8ff79a/logs/syslog.txt.gz

Louis Taylor (kragniz) wrote :

I'm getting this issue when using keystone with glance on devstack. If I restart sql:

    $ sudo service mysql stop
    $ sudo service mysql start

Request glance lists the images:

    $ glance --os-image-url http://localhost:9292 image-list
    Authentication failure: An unexpected error prevented the server from fulfilling your request: (OperationalError) (2006, 'MySQL server has gone away') 'SELECT user.id AS user_id, user.name AS user_name, user.domain_id AS user_domain_id, user.password AS user_password, user.enabled AS user_enabled, user.extra AS user_extra, user.default_project_id AS user_default_project_id \nFROM user \nWHERE user.name = %s AND user.domain_id = %s' ('demo', 'default') (Disable debug mode to suppress these details.) (HTTP 500)

Keystone traceback: https://gist.githubusercontent.com/kragniz/08b715fe5b703c90cce1/raw/a506f6db72b31c61935bd7e1f7c36b2073e7b9af/keystone

affects: oslo-incubator → oslo.db
Dolph Mathews (dolph) wrote :

Latest stats on this appear to only affect rackspace build nodes:

build_node
  16% devstack-trusty-rax-iad-1740349
  13% devstack-trusty-rax-iad-1718888
  11% devstack-trusty-rax-iad-1881648
  9% devstack-trusty-rax-iad-1685251
  9% devstack-trusty-rax-iad-1687403
  8% devstack-trusty-rax-iad-1708493
  7% devstack-trusty-rax-iad-1683327
  6% devstack-trusty-rax-iad-1716529
  4% devstack-trusty-rax-iad-1704847
  4% devstack-trusty-rax-iad-1683264
  3% devstack-trusty-rax-dfw-1848344
  2% devstack-trusty-rax-iad-1704962
  2% devstack-trusty-rax-iad-1703927

And there's almost no consistency about which log / tags it appears with:

tags
  24% screen-g-reg.txt screen oslofmt multiline
  18% screen-c-api.txt screen oslofmt multiline
  15% screen-n-api.txt screen oslofmt
  12% screen-n-cond.txt screen oslofmt
  8% console.html console
  5% screen-g-api.txt screen oslofmt multiline
  2% screen-c-sch.txt screen oslofmt multiline
  2% screen-n-sch.txt screen oslofmt
  1% screen-c-vol.txt screen oslofmt multiline
  1% screen-n-crt.txt screen oslofmt
  1% screen-h-api.txt screen oslofmt multiline
  1% screen-h-eng.txt screen oslofmt multiline
  1% screen-sahara.txt screen oslofmt multiline
  0% screen-h-eng.txt screen oslofmt
  0% screen-q-svc.txt screen oslofmt multiline
  0% screen-q-vpn.txt screen oslofmt multiline
  0% tempest.txt screen oslofmt multiline

Dolph Mathews (dolph) on 2014-09-04
Changed in keystone:
status: New → Invalid
Bjørnar Ness (bjornar-ness) wrote :

I am also seeing this when upgrading from icehouse to master, dont understand the invalid status!

Mike Bayer (zzzeek) wrote :

I'm still looking but the first trace here is that it couldn't connect, period. the "select 1" is not going to save you from that if you can't connect in the first place.

Mike Bayer (zzzeek) wrote :

i can confirm the "select 1" thing is working in current oslo.db. it only emits the "SELECT 1" at the start of a transaction, and will transparently recover from an immediate connection fail. not sure if keystone is failing to use the Session with a transaction though, that would skip the "select 1" part.

Dolph Mathews (dolph) wrote :
Mike Bayer (zzzeek) wrote :

confirmed in keystone master, keystone is not using transactions and is using the Session in "autocommit" mode for many calls, which is not recommended (see http://docs.sqlalchemy.org/en/rel_0_9/orm/session.html#autocommit-mode):

line 140 of keystone/identity/backends/sql.py:

    def get_user_by_name(self, user_name, domain_id):
        session = sql.get_session() # <-- no transaction
        query = session.query(User)
        query = query.filter_by(name=user_name)
        query = query.filter_by(domain_id=domain_id)
        try:
            user_ref = query.one()
        except sql.NotFound:
            raise exception.UserNotFound(user_id=user_name)
        return identity.filter_user(user_ref.to_dict())

there's no "select 1" emitted if no transaction is begun. I don't know that this was any different in earlier oslo.db versions.

Mike Bayer (zzzeek) wrote :

OK, I am mistaken., oslo.db seems like it was doing the "SELECT 1" on checkout previously. I will need to roll back and see how this got changed.

Mike Bayer (zzzeek) wrote :

okey doke added https://bugs.launchpad.net/oslo.db/+bug/1374497, we will probably hit it on our end first.

Mike Bayer (zzzeek) wrote :

the patch for oslo.db is in review if folks feel like experimenting: https://review.openstack.org/#/c/124466/

To post a comment you must log in.
This report contains Public information  Edit
Everyone can see this information.

Other bug subscribers