Nova sqlalchemy mysql db connection timeout causes a 500 error

Bug #690314 reported by Ryan Lucio
14
This bug affects 3 people
Affects Status Importance Assigned to Milestone
OpenStack Compute (nova)
Fix Released
Low
Ryan Lucio

Bug Description

Version: Austin
Deployment: multi-machine, 1 controller (api/network/scheduler/objectstore/db), 3 compute/volume nodes
Detail: Tests using the ec2 api run fine all day, but then first thing the next morning we always get a 500 on the first test. The error logging is captured below. A quick search on the SQLAlchemy site shows documentation identifying one likely cause for the issue. See http://www.sqlalchemy.org/trac/wiki/FAQ#MySQLserverhasgoneawaypsycopg.InterfaceError:connectionalreadyclosed for more info.

Output of nova-api.log

nova-api(routes.middleware): DEBUG Matched GET /services/Cloud/
nova-api(routes.middleware): DEBUG Route path: 'services/{path_info:.*}', defaults: {'action': u'index', 'controller': <nova.api.ec2.API object at 0x26e2310>}
nova-api(routes.middleware): DEBUG Match dict: {'action': u'index', 'controller': <nova.api.ec2.API object at 0x26e2310>, 'sub_domain': None, 'path_info': 'Cloud/'}
nova-api(root): INFO Looking up user: 'e6e82914-4a00-4e9f-a403-8b1bb01447ad'

Stack trace (returned in the ec2 api response):

GET http://box3:8773/services/Cloud/?AWSAccessKeyId=e6e82914-4a00-4e9f-a403-8b1bb01447ad%3Adefault-project&Action=DescribeImages&SignatureMethod=HmacSHA256&SignatureVersion=2&Timestamp=2010-12-014T16%3A27%3A59Z&Version=2010-06-15&Signature=zwRn4O0susOcnxHptRRYbV3tDps9tUngJWRHtSCv7Y4%3D returned a response status of 500) Msg (Traceback (most recent call last):
  File "/usr/lib/pymodules/python2.6/eventlet/wsgi.py", line 336, in handle_one_response
    result = self.application(self.environ, start_response)
  File "/usr/lib/pymodules/python2.6/webob/dec.py", line 159, in __call__
    return resp(environ, start_response)
  File "/usr/lib/pymodules/python2.6/routes/middleware.py", line 130, in __call__
    response = self.app(environ, start_response)
  File "/usr/lib/pymodules/python2.6/webob/dec.py", line 159, in __call__
    return resp(environ, start_response)
  File "/usr/lib/pymodules/python2.6/webob/dec.py", line 159, in __call__
    return resp(environ, start_response)
  File "/usr/lib/pymodules/python2.6/webob/dec.py", line 147, in __call__
    resp = self.call_func(req, *args, **self.kwargs)
  File "/usr/lib/pymodules/python2.6/webob/dec.py", line 208, in call_func
    return self.func(req, *args, **kwargs)
  File "/usr/lib/pymodules/python2.6/nova/api/ec2/__init__.py", line 74, in __call__
    req.path)
  File "/usr/lib/pymodules/python2.6/nova/auth/manager.py", line 262, in authenticate
    user = self.get_user_from_access_key(access_key)
  File "/usr/lib/pymodules/python2.6/nova/auth/manager.py", line 569, in get_user_from_access_key
    user_dict = drv.get_user_from_access_key(access_key)
  File "/usr/lib/pymodules/python2.6/nova/auth/dbdriver.py", line 54, in get_user_from_access_key
    return self._db_user_to_auth_user(db.user_get_by_access_key(context.get_admin_context(), access))
  File "/usr/lib/pymodules/python2.6/nova/db/api.py", line 669, in user_get_by_access_key
    return IMPL.user_get_by_access_key(context, access_key)
  File "/usr/lib/pymodules/python2.6/nova/db/sqlalchemy/api.py", line 98, in wrapper
    return f(*args, **kwargs)
  File "/usr/lib/pymodules/python2.6/nova/db/sqlalchemy/api.py", line 1491, in user_get_by_access_key
    ).filter_by(deleted=can_read_deleted(context)
  File "/usr/lib/pymodules/python2.6/sqlalchemy/orm/query.py", line 1496, in first
    ret = list(self[0:1])
  File "/usr/lib/pymodules/python2.6/sqlalchemy/orm/query.py", line 1405, in __getitem__
    return list(res)
  File "/usr/lib/pymodules/python2.6/sqlalchemy/orm/query.py", line 1565, in __iter__
    return self._execute_and_instances(context)
  File "/usr/lib/pymodules/python2.6/sqlalchemy/orm/query.py", line 1570, in _execute_and_instances
    mapper=self._mapper_zero_or_none())
  File "/usr/lib/pymodules/python2.6/sqlalchemy/orm/session.py", line 735, in execute
    clause, params or {})
  File "/usr/lib/pymodules/python2.6/sqlalchemy/engine/base.py", line 1157, in execute
    params)
  File "/usr/lib/pymodules/python2.6/sqlalchemy/engine/base.py", line 1237, in _execute_clauseelement
    return self.__execute_context(context)
  File "/usr/lib/pymodules/python2.6/sqlalchemy/engine/base.py", line 1268, in __execute_context
    context.parameters[0], context=context)
  File "/usr/lib/pymodules/python2.6/sqlalchemy/engine/base.py", line 1367, in _cursor_execute
    context)
  File "/usr/lib/pymodules/python2.6/sqlalchemy/engine/base.py", line 1360, in _cursor_execute
    context)
  File "/usr/lib/pymodules/python2.6/sqlalchemy/engine/default.py", line 288, in do_execute
    cursor.execute(statement, parameters)
  File "/usr/lib/pymodules/python2.6/MySQLdb/cursors.py", line 166, in execute
    self.errorhandler(self, exc, value)
  File "/usr/lib/pymodules/python2.6/MySQLdb/connections.py", line 35, in defaulterrorhandler
    raise errorclass, errorvalue
OperationalError: (OperationalError) (2006, 'MySQL server has gone away') 'SELECT users.created_at AS users_created_at, users.updated_at AS users_updated_at, users.deleted_at AS users_deleted_at, users.deleted AS users_deleted, users.id AS users_id, users.name AS users_name, users.access_key AS users_access_key, users.secret_key AS users_secret_key, users.is_admin AS users_is_admin \nFROM users \nWHERE users.access_key = %s AND users.deleted = %s \n LIMIT 0, 1' ('e6e82914-4a00-4e9f-a403-8b1bb01447ad', False)
) returned from server}

Related branches

Ryan Lucio (rlucio)
Changed in nova:
assignee: nobody → Ryan Lucio (rlucio)
Ryan Lucio (rlucio)
tags: added: austin
Revision history for this message
Thierry Carrez (ttx) wrote :

I guess Bexar is also affected by this, given that we don't pass pool_recycle= to create_engine.

@Ryan: I see you assigned yourself, are you working on this ? If yes, please set bug to "In progress". If not, please unassign yourself to give someone else a chance to fix it.

Changed in nova:
importance: Undecided → Low
status: New → Triaged
Ryan Lucio (rlucio)
Changed in nova:
status: Triaged → In Progress
Changed in nova:
status: In Progress → Fix Committed
Revision history for this message
Antony Messerli (antonym) wrote :
Download full text (7.8 KiB)

Ran into this running trunk from yesterday. After testing the previous day, I attempted to spin up an instance and received a similar error. Attempting one more time afterwards created the instance without the error.

nova-api.log

2011-02-05 09:14:30,653 ERROR nova.api.openstack [-] Caught error: (OperationalError) (2006, 'MySQL server has gone away') 'SELECT users.created_at AS users_created_at, users.updated_at AS users_updated_a
t, users.deleted_at AS users_deleted_at, users.deleted AS users_deleted, users.id AS users_id, users.name AS users_name, users.access_key AS users_access_key, users.secret_key AS users_secret_key, users.i
s_admin AS users_is_admin \nFROM users \nWHERE users.access_key = %s AND users.deleted = %s \n LIMIT 0, 1' ('6a0a9f51-2674-40bf-a60e-6b1b2580f47b', False)
(nova.api.openstack): TRACE: Traceback (most recent call last):
(nova.api.openstack): TRACE: File "/root/openstack/nova/nova/api/openstack/__init__.py", line 52, in __call__
(nova.api.openstack): TRACE: return req.get_response(self.application)
(nova.api.openstack): TRACE: File "/usr/lib/pymodules/python2.6/webob/request.py", line 919, in get_response
(nova.api.openstack): TRACE: application, catch_exc_info=False)
(nova.api.openstack): TRACE: File "/usr/lib/pymodules/python2.6/webob/request.py", line 887, in call_application
(nova.api.openstack): TRACE: app_iter = application(self.environ, start_response)
(nova.api.openstack): TRACE: File "/usr/lib/pymodules/python2.6/webob/dec.py", line 147, in __call__
(nova.api.openstack): TRACE: resp = self.call_func(req, *args, **self.kwargs)
(nova.api.openstack): TRACE: File "/usr/lib/pymodules/python2.6/webob/dec.py", line 208, in call_func
(nova.api.openstack): TRACE: return self.func(req, *args, **kwargs)
(nova.api.openstack): TRACE: File "/root/openstack/nova/nova/api/openstack/auth.py", line 51, in __call__
(nova.api.openstack): TRACE: return self.authenticate(req)
(nova.api.openstack): TRACE: File "/root/openstack/nova/nova/api/openstack/auth.py", line 81, in authenticate
(nova.api.openstack): TRACE: token, user = self._authorize_user(username, key, req)
(nova.api.openstack): TRACE: File "/root/openstack/nova/nova/api/openstack/auth.py", line 123, in _authorize_user
(nova.api.openstack): TRACE: user = self.auth.get_user_from_access_key(key)
(nova.api.openstack): TRACE: File "/root/openstack/nova/nova/auth/manager.py", line 606, in get_user_from_access_key
(nova.api.openstack): TRACE: user_dict = drv.get_user_from_access_key(access_key)
(nova.api.openstack): TRACE: File "/root/openstack/nova/nova/auth/dbdriver.py", line 53, in get_user_from_access_key
(nova.api.openstack): TRACE: user = db.user_get_by_access_key(context.get_admin_context(), access)
(nova.api.openstack): TRACE: File "/root/openstack/nova/nova/db/api.py", line 827, in user_get_by_access_key
(nova.api.openstack): TRACE: return IMPL.user_get_by_access_key(context, access_key)
(nova.api.openstack): TRACE: File "/root/openstack/nova/nova/db/sqlalchemy/api.py", line 97, in wrapper
(nova.api.openstack): TRACE: return f(*args, **kwargs)
(nova.api.openstack): TRACE: File "/root/opensta...

Read more...

Thierry Carrez (ttx)
Changed in nova:
milestone: none → 2011.1
status: Fix Committed → Fix Released
To post a comment you must log in.
This report contains Public information  
Everyone can see this information.

Other bug subscribers

Remote bug watches

Bug watches keep track of this bug in other bug trackers.