cinder-backup service randomly dies in ceph jobs

[Matt Riedemann]

As seen here:

http://logs.openstack.org/25/398425/3/gate/gate-tempest-dsvm-full-devstack-plugin-ceph-ubuntu-xenial/1b2e1c4/logs/screen-c-bak.txt.gz?level=TRACE

2016-11-17 12:51:38.859 ERROR cinder.service [req-68988b27-1b9a-45b3-b7d1-ce0ee22eae44 tempest-VolumesBackupsAdminV1Test-302535748] model server went away
2016-11-17 12:51:38.859 3181 ERROR cinder.service Traceback (most recent call last):
2016-11-17 12:51:38.859 3181 ERROR cinder.service File "/opt/stack/new/cinder/cinder/service.py", line 451, in report_state
2016-11-17 12:51:38.859 3181 ERROR cinder.service Service.service_id)
2016-11-17 12:51:38.859 3181 ERROR cinder.service File "/opt/stack/new/cinder/cinder/objects/base.py", line 291, in get_by_id
2016-11-17 12:51:38.859 3181 ERROR cinder.service orm_obj = db.get_by_id(context, cls.model, id, *args, **kwargs)
2016-11-17 12:51:38.859 3181 ERROR cinder.service File "/opt/stack/new/cinder/cinder/db/api.py", line 1642, in get_by_id
2016-11-17 12:51:38.859 3181 ERROR cinder.service return IMPL.get_by_id(context, model, id, *args, **kwargs)
2016-11-17 12:51:38.859 3181 ERROR cinder.service File "/opt/stack/new/cinder/cinder/db/sqlalchemy/api.py", line 196, in wrapper
2016-11-17 12:51:38.859 3181 ERROR cinder.service return f(*args, **kwargs)
2016-11-17 12:51:38.859 3181 ERROR cinder.service File "/opt/stack/new/cinder/cinder/db/sqlalchemy/api.py", line 6293, in get_by_id
2016-11-17 12:51:38.859 3181 ERROR cinder.service return _GET_METHODS[model](context, id, *args, **kwargs)
2016-11-17 12:51:38.859 3181 ERROR cinder.service File "/opt/stack/new/cinder/cinder/db/sqlalchemy/api.py", line 178, in wrapper
2016-11-17 12:51:38.859 3181 ERROR cinder.service return f(*args, **kwargs)
2016-11-17 12:51:38.859 3181 ERROR cinder.service File "/opt/stack/new/cinder/cinder/db/sqlalchemy/api.py", line 483, in service_get
2016-11-17 12:51:38.859 3181 ERROR cinder.service service = None if not query else query.first()
2016-11-17 12:51:38.859 3181 ERROR cinder.service File "/usr/local/lib/python2.7/dist-packages/sqlalchemy/orm/query.py", line 2659, in first
2016-11-17 12:51:38.859 3181 ERROR cinder.service ret = list(self[0:1])
2016-11-17 12:51:38.859 3181 ERROR cinder.service File "/usr/local/lib/python2.7/dist-packages/sqlalchemy/orm/query.py", line 2457, in __getitem__
2016-11-17 12:51:38.859 3181 ERROR cinder.service return list(res)
2016-11-17 12:51:38.859 3181 ERROR cinder.service File "/usr/local/lib/python2.7/dist-packages/sqlalchemy/orm/query.py", line 2761, in __iter__
2016-11-17 12:51:38.859 3181 ERROR cinder.service return self._execute_and_instances(context)
2016-11-17 12:51:38.859 3181 ERROR cinder.service File "/usr/local/lib/python2.7/dist-packages/sqlalchemy/orm/query.py", line 2774, in _execute_and_instances
2016-11-17 12:51:38.859 3181 ERROR cinder.service close_with_result=True)
2016-11-17 12:51:38.859 3181 ERROR cinder.service File "/usr/local/lib/python2.7/dist-packages/sqlalchemy/orm/query.py", line 2765, in _connection_from_session
2016-11-17 12:51:38.859 3181 ERROR cinder.service **kw)
2016-11-17 12:51:38.859 3181 ERROR cinder.service File "/usr/local/lib/python2.7/dist-packages/sqlalchemy/orm/session.py", line 956, in connection
2016-11-17 12:51:38.859 3181 ERROR cinder.service execution_options=execution_options)
2016-11-17 12:51:38.859 3181 ERROR cinder.service File "/usr/local/lib/python2.7/dist-packages/sqlalchemy/orm/session.py", line 963, in _connection_for_bind
2016-11-17 12:51:38.859 3181 ERROR cinder.service conn = engine.contextual_connect(**kw)
2016-11-17 12:51:38.859 3181 ERROR cinder.service File "/usr/local/lib/python2.7/dist-packages/sqlalchemy/engine/base.py", line 2039, in contextual_connect
2016-11-17 12:51:38.859 3181 ERROR cinder.service self._wrap_pool_connect(self.pool.connect, None),
2016-11-17 12:51:38.859 3181 ERROR cinder.service File "/usr/local/lib/python2.7/dist-packages/sqlalchemy/engine/base.py", line 2078, in _wrap_pool_connect
2016-11-17 12:51:38.859 3181 ERROR cinder.service e, dialect, self)
2016-11-17 12:51:38.859 3181 ERROR cinder.service File "/usr/local/lib/python2.7/dist-packages/sqlalchemy/engine/base.py", line 1401, in _handle_dbapi_exception_noconnection
2016-11-17 12:51:38.859 3181 ERROR cinder.service util.raise_from_cause(newraise, exc_info)
2016-11-17 12:51:38.859 3181 ERROR cinder.service File "/usr/local/lib/python2.7/dist-packages/sqlalchemy/util/compat.py", line 202, in raise_from_cause
2016-11-17 12:51:38.859 3181 ERROR cinder.service reraise(type(exception), exception, tb=exc_tb, cause=cause)
2016-11-17 12:51:38.859 3181 ERROR cinder.service File "/usr/local/lib/python2.7/dist-packages/sqlalchemy/engine/base.py", line 2074, in _wrap_pool_connect
2016-11-17 12:51:38.859 3181 ERROR cinder.service return fn()
2016-11-17 12:51:38.859 3181 ERROR cinder.service File "/usr/local/lib/python2.7/dist-packages/sqlalchemy/pool.py", line 376, in connect
2016-11-17 12:51:38.859 3181 ERROR cinder.service return _ConnectionFairy._checkout(self)
2016-11-17 12:51:38.859 3181 ERROR cinder.service File "/usr/local/lib/python2.7/dist-packages/sqlalchemy/pool.py", line 713, in _checkout
2016-11-17 12:51:38.859 3181 ERROR cinder.service fairy = _ConnectionRecord.checkout(pool)
2016-11-17 12:51:38.859 3181 ERROR cinder.service File "/usr/local/lib/python2.7/dist-packages/sqlalchemy/pool.py", line 480, in checkout
2016-11-17 12:51:38.859 3181 ERROR cinder.service rec = pool._do_get()
2016-11-17 12:51:38.859 3181 ERROR cinder.service File "/usr/local/lib/python2.7/dist-packages/sqlalchemy/pool.py", line 1060, in _do_get
2016-11-17 12:51:38.859 3181 ERROR cinder.service self._dec_overflow()
2016-11-17 12:51:38.859 3181 ERROR cinder.service File "/usr/local/lib/python2.7/dist-packages/sqlalchemy/util/langhelpers.py", line 60, in __exit__
2016-11-17 12:51:38.859 3181 ERROR cinder.service compat.reraise(exc_type, exc_value, exc_tb)
2016-11-17 12:51:38.859 3181 ERROR cinder.service File "/usr/local/lib/python2.7/dist-packages/sqlalchemy/pool.py", line 1057, in _do_get
2016-11-17 12:51:38.859 3181 ERROR cinder.service return self._create_connection()
2016-11-17 12:51:38.859 3181 ERROR cinder.service File "/usr/local/lib/python2.7/dist-packages/sqlalchemy/pool.py", line 323, in _create_connection
2016-11-17 12:51:38.859 3181 ERROR cinder.service return _ConnectionRecord(self)
2016-11-17 12:51:38.859 3181 ERROR cinder.service File "/usr/local/lib/python2.7/dist-packages/sqlalchemy/pool.py", line 449, in __init__
2016-11-17 12:51:38.859 3181 ERROR cinder.service self.connection = self.__connect()
2016-11-17 12:51:38.859 3181 ERROR cinder.service File "/usr/local/lib/python2.7/dist-packages/sqlalchemy/pool.py", line 607, in __connect
2016-11-17 12:51:38.859 3181 ERROR cinder.service connection = self.__pool._invoke_creator(self)
2016-11-17 12:51:38.859 3181 ERROR cinder.service File "/usr/local/lib/python2.7/dist-packages/sqlalchemy/engine/strategies.py", line 97, in connect
2016-11-17 12:51:38.859 3181 ERROR cinder.service return dialect.connect(*cargs, **cparams)
2016-11-17 12:51:38.859 3181 ERROR cinder.service File "/usr/local/lib/python2.7/dist-packages/sqlalchemy/engine/default.py", line 385, in connect
2016-11-17 12:51:38.859 3181 ERROR cinder.service return self.dbapi.connect(*cargs, **cparams)
2016-11-17 12:51:38.859 3181 ERROR cinder.service File "/usr/local/lib/python2.7/dist-packages/pymysql/__init__.py", line 90, in Connect
2016-11-17 12:51:38.859 3181 ERROR cinder.service return Connection(*args, **kwargs)
2016-11-17 12:51:38.859 3181 ERROR cinder.service File "/usr/local/lib/python2.7/dist-packages/pymysql/connections.py", line 688, in __init__
2016-11-17 12:51:38.859 3181 ERROR cinder.service self.connect()
2016-11-17 12:51:38.859 3181 ERROR cinder.service File "/usr/local/lib/python2.7/dist-packages/pymysql/connections.py", line 906, in connect
2016-11-17 12:51:38.859 3181 ERROR cinder.service self._request_authentication()
2016-11-17 12:51:38.859 3181 ERROR cinder.service File "/usr/local/lib/python2.7/dist-packages/pymysql/connections.py", line 1114, in _request_authentication
2016-11-17 12:51:38.859 3181 ERROR cinder.service auth_packet = self._read_packet()
2016-11-17 12:51:38.859 3181 ERROR cinder.service File "/usr/local/lib/python2.7/dist-packages/pymysql/connections.py", line 961, in _read_packet
2016-11-17 12:51:38.859 3181 ERROR cinder.service packet_header = self._read_bytes(4)
2016-11-17 12:51:38.859 3181 ERROR cinder.service File "/usr/local/lib/python2.7/dist-packages/pymysql/connections.py", line 998, in _read_bytes
2016-11-17 12:51:38.859 3181 ERROR cinder.service 2013, "Lost connection to MySQL server during query")
2016-11-17 12:51:38.859 3181 ERROR cinder.service DBConnectionError: (pymysql.err.OperationalError) (2013, 'Lost connection to MySQL server during query')
2016-11-17 12:51:38.859 3181 ERROR cinder.service

http://logstash.openstack.org/#dashboard/file/logstash.json?query=message%3A%5C%22DBConnectionError%3A%20(pymysql.err.OperationalError)%20(2013%2C%20'Lost%20connection%20to%20MySQL%20server%20during%20query')%5C%22%20AND%20tags%3A%5C%22screen-c-bak.txt%5C%22&from=7d

50 hits in 7 days, check and gate, all ceph jobs, but not all failures, so it must be a random timing issue when it does and if tempest is running a volume backup test at the time that it dies only then do we have a test failure.

[Matt Riedemann (mriedem)]

req-68988b27-1b9a-45b3-b7d1-ce0ee22eae44 is the request ID from the backup create POST, and that's what failed above, so that's definitely the issue for this failure.

2016-11-17 12:51:19,219 8649 INFO [tempest.lib.common.rest_client] Request (VolumesBackupsAdminV1Test:test_volume_backup_export_import): 201 POST http://127.0.0.1:8776/v1/92a8db4543864610b83b54a99645f36b/backups/import_record 0.037s
2016-11-17 13:20:28.892457 | 2016-11-17 12:51:19,219 8649 DEBUG [tempest.lib.common.rest_client] Request - Headers: {'Content-Type': 'application/json', 'Accept': 'application/json', 'X-Auth-Token': '<omitted>'}
2016-11-17 13:20:28.892863 | Body: {"backup-record": {"backup_service": "cinder.backup.drivers.ceph", "backup_url": "eyJvYmplY3RfY291bnQiOiAwLCAic25hcHNob3RfaWQiOiBudWxsLCAicGFyZW50X2lkIjogbnVsbCwgInVzZXJfaWQiOiAiM2JlMGIzZmE1NjI4NDkyZThlZjNhYzRhMjdiNTRmNjYiLCAicHJvamVjdF9pZCI6ICI5MmE4ZGI0NTQzODY0NjEwYjgzYjU0YTk5NjQ1ZjM2YiIsICJjb250YWluZXIiOiAiYmFja3VwcyIsICJ0ZW1wX3ZvbHVtZV9pZCI6IG51bGwsICJkaXNwbGF5X25hbWUiOiAidGVtcGVzdC1Wb2x1bWVzQmFja3Vwc0FkbWluVjFUZXN0LUJhY2t1cC0xMzc3NDg1OTQiLCAic2VydmljZSI6ICJjaW5kZXIuYmFja3VwLmRyaXZlcnMuY2VwaCIsICJjcmVhdGVkX2F0IjogIjIwMTYtMTEtMTdUMTI6NTA6NDdaIiwgInVwZGF0ZWRfYXQiOiAiMjAxNi0xMS0xN1QxMjo1MToxOFoiLCAiZGlzcGxheV9kZXNjcmlwdGlvbiI6IG51bGwsICJkYXRhX3RpbWVzdGFtcCI6ICIyMDE2LTExLTE3VDEyOjUwOjQ3WiIsICJzZXJ2aWNlX21ldGFkYXRhIjogbnVsbCwgImF2YWlsYWJpbGl0eV96b25lIjogIm5vdmEiLCAiaWQiOiAiYzYzNDZiYzQtMDhkYy00MmY2LWI3OTgtM2FmNmFkNzU5OTUxIiwgInJlc3RvcmVfdm9sdW1lX2lkIjogbnVsbCwgInNpemUiOiAxLCAidGVtcF9zbmFwc2hvdF9pZCI6IG51bGwsICJzdGF0dXMiOiAiYXZhaWxhYmxlIiwgInZvbHVtZV9pZCI6ICJiYzU2OGJjYy02OTZkLTRkNzUtYjEzMy0zNTZhZTM2NDJjZTIiLCAiZGVsZXRlZF9hdCI6IG51bGwsICJmYWlsX3JlYXNvbiI6IG51bGwsICJudW1fZGVwZW5kZW50X2JhY2t1cHMiOiAwLCAiaG9zdCI6ICJ1YnVudHUteGVuaWFsLWluZnJhY2xvdWQtY2hvY29sYXRlLTU0MjQzMjIiLCAiZHJpdmVyX2luZm8iOiB7fSwgImRlbGV0ZWQiOiBmYWxzZX0="}}
2016-11-17 13:20:28.893282 | Response - Headers: {'x-compute-request-id': 'req-68988b27-1b9a-45b3-b7d1-ce0ee22eae44', 'x-openstack-request-id': 'req-68988b27-1b9a-45b3-b7d1-ce0ee22eae44', 'status': '201', 'connection': 'close', 'date': 'Thu, 17 Nov 2016 12:51:19 GMT', 'content-length': '346', 'content-type': 'application/json', 'content-location': 'http://127.0.0.1:8776/v1/92a8db4543864610b83b54a99645f36b/backups/import_record'}
2016-11-17 13:20:28.893518 | Body: {"backup": {"id": "c6346bc4-08dc-42f6-b798-3af6ad759951", "links": [{"href": "http://127.0.0.1:8776/v1/92a8db4543864610b83b54a99645f36b/backups/c6346bc4-08dc-42f6-b798-3af6ad759951", "rel": "self"}, {"href": "http://127.0.0.1:8776/92a8db4543864610b83b54a99645f36b/backups/c6346bc4-08dc-42f6-b798-3af6ad759951", "rel": "bookmark"}], "name": null}}