yahoo-eng-team team mailing list archive

Thread
Date
[Bug 1361378] Re: "MySQL server has gone away" again

To: yahoo-eng-team@xxxxxxxxxxxxxxxxxxx
From: Victor Sergeyev <vsergeyev@xxxxxxxxxxxx>
Date: Tue, 02 Sep 2014 11:52:57 -0000
Reply-to: Bug 1361378 <1361378@xxxxxxxxxxxxxxxxxx>
Sender: bounces@xxxxxxxxxxxxx
** Project changed: oslo-incubator => oslo.db

-- 
You received this bug notification because you are a member of Yahoo!
Engineering Team, which is subscribed to Keystone.
https://bugs.launchpad.net/bugs/1361378

Title:
  "MySQL server has gone away" again

Status in OpenStack Identity (Keystone):
  New
Status in Oslo Database library:
  Incomplete

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

To manage notifications about this bug go to:
https://bugs.launchpad.net/keystone/+bug/1361378/+subscriptions
References

[Bug 1361378] [NEW] "MySQL server has gone away" again
From: Dolph Mathews, 2014-08-25