Race condition while creating/deleting cinder volumes (Fuel 8.0 build 284)

Bug #1525905 reported by Ivan Lozgachev on 2015-12-14
6
This bug affects 1 person
Affects Status Importance Assigned to Milestone
Mirantis OpenStack
High
MOS Cinder

Bug Description

Original test report can be found here http://mos-scale.vm.mirantis.net/test_results/build_8.0-284/jenkins-10_env_run_rally-91-ubuntu-MSK-2015-12-12-13:48:28-2015-12-13-12:58:29/rally_report.html#/CinderVolumes.create_and_delete_volume-3/failures

The error observed while running Rally tests. Traceback:

2015-12-13 07:43:34.480 26104 ERROR cinder.volume.api Traceback (most recent call last):
2015-12-13 07:43:34.480 26104 ERROR cinder.volume.api File "/usr/lib/python2.7/dist-packages/taskflow/engines/action_engine/executor.py", line 82, in _execute_task
2015-12-13 07:43:34.480 26104 ERROR cinder.volume.api result = task.execute(**arguments)
2015-12-13 07:43:34.480 26104 ERROR cinder.volume.api File "/usr/lib/python2.7/dist-packages/cinder/volume/flows/api/create_volume.py", line 551, in execute
2015-12-13 07:43:34.480 26104 ERROR cinder.volume.api reservations = QUOTAS.reserve(context, **reserve_opts)
2015-12-13 07:43:34.480 26104 ERROR cinder.volume.api File "/usr/lib/python2.7/dist-packages/cinder/quota.py", line 808, in reserve
2015-12-13 07:43:34.480 26104 ERROR cinder.volume.api project_id=project_id)
2015-12-13 07:43:34.480 26104 ERROR cinder.volume.api File "/usr/lib/python2.7/dist-packages/cinder/quota.py", line 399, in reserve
2015-12-13 07:43:34.480 26104 ERROR cinder.volume.api project_id=project_id)
2015-12-13 07:43:34.480 26104 ERROR cinder.volume.api File "/usr/lib/python2.7/dist-packages/cinder/db/api.py", line 823, in quota_reserve
2015-12-13 07:43:34.480 26104 ERROR cinder.volume.api until_refresh, max_age, project_id=project_id)
2015-12-13 07:43:34.480 26104 ERROR cinder.volume.api File "/usr/lib/python2.7/dist-packages/cinder/db/sqlalchemy/api.py", line 183, in wrapper
2015-12-13 07:43:34.480 26104 ERROR cinder.volume.api return f(*args, **kwargs)
2015-12-13 07:43:34.480 26104 ERROR cinder.volume.api File "/usr/lib/python2.7/dist-packages/cinder/db/sqlalchemy/api.py", line 221, in wrapped
2015-12-13 07:43:34.480 26104 ERROR cinder.volume.api return f(*args, **kwargs)
2015-12-13 07:43:34.480 26104 ERROR cinder.volume.api File "/usr/lib/python2.7/dist-packages/cinder/db/sqlalchemy/api.py", line 889, in quota_reserve
2015-12-13 07:43:34.480 26104 ERROR cinder.volume.api session=session)
2015-12-13 07:43:34.480 26104 ERROR cinder.volume.api File "/usr/lib/python2.7/dist-packages/cinder/db/sqlalchemy/api.py", line 756, in _reservation_create
2015-12-13 07:43:34.480 26104 ERROR cinder.volume.api reservation_ref.save(session=session)
2015-12-13 07:43:34.480 26104 ERROR cinder.volume.api File "/usr/lib/python2.7/dist-packages/oslo_db/sqlalchemy/models.py", line 48, in save
2015-12-13 07:43:34.480 26104 ERROR cinder.volume.api session.flush()
2015-12-13 07:43:34.480 26104 ERROR cinder.volume.api File "/usr/lib/python2.7/dist-packages/sqlalchemy/orm/session.py", line 2004, in flush
2015-12-13 07:43:34.480 26104 ERROR cinder.volume.api self._flush(objects)
2015-12-13 07:43:34.480 26104 ERROR cinder.volume.api File "/usr/lib/python2.7/dist-packages/sqlalchemy/orm/session.py", line 2122, in _flush
2015-12-13 07:43:34.480 26104 ERROR cinder.volume.api transaction.rollback(_capture_exception=True)
2015-12-13 07:43:34.480 26104 ERROR cinder.volume.api File "/usr/lib/python2.7/dist-packages/sqlalchemy/util/langhelpers.py", line 60, in __exit__
2015-12-13 07:43:34.480 26104 ERROR cinder.volume.api compat.reraise(exc_type, exc_value, exc_tb)
2015-12-13 07:43:34.480 26104 ERROR cinder.volume.api File "/usr/lib/python2.7/dist-packages/sqlalchemy/orm/session.py", line 2086, in _flush
2015-12-13 07:43:34.480 26104 ERROR cinder.volume.api flush_context.execute()
2015-12-13 07:43:34.480 26104 ERROR cinder.volume.api File "/usr/lib/python2.7/dist-packages/sqlalchemy/orm/unitofwork.py", line 373, in execute
2015-12-13 07:43:34.480 26104 ERROR cinder.volume.api rec.execute(self)
2015-12-13 07:43:34.480 26104 ERROR cinder.volume.api File "/usr/lib/python2.7/dist-packages/sqlalchemy/orm/unitofwork.py", line 532, in execute
2015-12-13 07:43:34.480 26104 ERROR cinder.volume.api uow
2015-12-13 07:43:34.480 26104 ERROR cinder.volume.api File "/usr/lib/python2.7/dist-packages/sqlalchemy/orm/persistence.py", line 174, in save_obj
2015-12-13 07:43:34.480 26104 ERROR cinder.volume.api mapper, table, insert)
2015-12-13 07:43:34.480 26104 ERROR cinder.volume.api File "/usr/lib/python2.7/dist-packages/sqlalchemy/orm/persistence.py", line 781, in _emit_insert_statements
2015-12-13 07:43:34.480 26104 ERROR cinder.volume.api execute(statement, params)
2015-12-13 07:43:34.480 26104 ERROR cinder.volume.api File "/usr/lib/python2.7/dist-packages/sqlalchemy/engine/base.py", line 914, in execute
2015-12-13 07:43:34.480 26104 ERROR cinder.volume.api return meth(self, multiparams, params)
2015-12-13 07:43:34.480 26104 ERROR cinder.volume.api File "/usr/lib/python2.7/dist-packages/sqlalchemy/sql/elements.py", line 323, in _execute_on_connection
2015-12-13 07:43:34.480 26104 ERROR cinder.volume.api return connection._execute_clauseelement(self, multiparams, params)
2015-12-13 07:43:34.480 26104 ERROR cinder.volume.api File "/usr/lib/python2.7/dist-packages/sqlalchemy/engine/base.py", line 1010, in _execute_clauseelement
2015-12-13 07:43:34.480 26104 ERROR cinder.volume.api compiled_sql, distilled_params
2015-12-13 07:43:34.480 26104 ERROR cinder.volume.api File "/usr/lib/python2.7/dist-packages/sqlalchemy/engine/base.py", line 1146, in _execute_context
2015-12-13 07:43:34.480 26104 ERROR cinder.volume.api context)
2015-12-13 07:43:34.480 26104 ERROR cinder.volume.api File "/usr/lib/python2.7/dist-packages/sqlalchemy/engine/base.py", line 1337, in _handle_dbapi_exception
2015-12-13 07:43:34.480 26104 ERROR cinder.volume.api util.raise_from_cause(newraise, exc_info)
2015-12-13 07:43:34.480 26104 ERROR cinder.volume.api File "/usr/lib/python2.7/dist-packages/sqlalchemy/util/compat.py", line 199, in raise_from_cause
2015-12-13 07:43:34.480 26104 ERROR cinder.volume.api reraise(type(exception), exception, tb=exc_tb)
2015-12-13 07:43:34.480 26104 ERROR cinder.volume.api File "/usr/lib/python2.7/dist-packages/sqlalchemy/engine/base.py", line 1139, in _execute_context
2015-12-13 07:43:34.480 26104 ERROR cinder.volume.api context)
2015-12-13 07:43:34.480 26104 ERROR cinder.volume.api File "/usr/lib/python2.7/dist-packages/sqlalchemy/engine/default.py", line 450, in do_execute
2015-12-13 07:43:34.480 26104 ERROR cinder.volume.api cursor.execute(statement, parameters)
2015-12-13 07:43:34.480 26104 ERROR cinder.volume.api File "/usr/lib/python2.7/dist-packages/MySQLdb/cursors.py", line 219, in execute
2015-12-13 07:43:34.480 26104 ERROR cinder.volume.api self.errorhandler(self, exc, value)
2015-12-13 07:43:34.480 26104 ERROR cinder.volume.api File "/usr/lib/python2.7/dist-packages/MySQLdb/connections.py", line 38, in defaulterrorhandler
2015-12-13 07:43:34.480 26104 ERROR cinder.volume.api raise errorvalue
2015-12-13 07:43:34.480 26104 ERROR cinder.volume.api DBDuplicateEntry: (_mysql_exceptions.IntegrityError) (1062, "Duplicate entry '74126' for key 'PRIMARY'") [SQL: u'INSERT INTO reservations (created_at, updated_at, deleted_at, deleted, uuid, usage_id, project_id, resource, delta, expire) VALUES (%s, %s, %s, %s, %s, %s, %s, %s, %s, %s)'] [parameters: (datetime.datetime(2015, 12, 13, 7, 43, 34, 403538), None, None, 0, '73bd13d5-99b6-4f7b-80b2-2bc4bd58f74b', 4220L, 'f2497e25b28f4f10ae2f14958f83e1c0', 'gigabytes', 1, datetime.datetime(2015, 12, 14, 7, 43, 34, 346873))]
2015-12-13 07:43:34.480 26104 ERROR cinder.volume.api

Original error trace from cinderclient:

Traceback (most recent call last):
  File "/opt/stack/.venv/lib/python2.7/site-packages/rally/task/runner.py", line 64, in _run_scenario_once
    method_name)(**kwargs) or scenario_output
  File "/opt/stack/.venv/lib/python2.7/site-packages/rally/plugins/openstack/scenarios/cinder/volumes.py", line 134, in create_and_delete_volume
    volume = self._create_volume(size, **kwargs)
  File "/opt/stack/.venv/lib/python2.7/site-packages/rally/task/atomic.py", line 84, in func_atomic_actions
    f = func(self, *args, **kwargs)
  File "/opt/stack/.venv/lib/python2.7/site-packages/rally/plugins/openstack/scenarios/cinder/utils.py", line 138, in _create_volume
    volume = self.clients("cinder").volumes.create(size, **kwargs)
  File "/opt/stack/.venv/lib/python2.7/site-packages/cinderclient/v1/volumes.py", line 187, in create
    return self._create('/volumes', body, 'volume')
  File "/opt/stack/.venv/lib/python2.7/site-packages/cinderclient/base.py", line 299, in _create
    resp, body = self.api.client.post(url, body=body)
  File "/opt/stack/.venv/lib/python2.7/site-packages/cinderclient/client.py", line 315, in post
    return self._cs_request(url, 'POST', **kwargs)
  File "/opt/stack/.venv/lib/python2.7/site-packages/cinderclient/client.py", line 275, in _cs_request
    **kwargs)
  File "/opt/stack/.venv/lib/python2.7/site-packages/cinderclient/client.py", line 258, in request
    raise exceptions.from_response(resp, body)
ClientException: The server has either erred or is incapable of performing the requested operation. (HTTP 500) (Request-ID: req-d55120e5-914e-4f23-95f5-56e4b1427df1)

Please see attached cinder log.

Ivan Lozgachev (ilozgachev) wrote :
Changed in fuel:
milestone: none → 8.0
assignee: nobody → MOS Cinder (mos-cinder)
Ilya Kutukov (ikutukov) on 2015-12-14
Changed in fuel:
status: New → Confirmed
importance: Undecided → Medium
importance: Medium → High
Ivan Kolodyazhny (e0ne) on 2015-12-16
affects: fuel → mos
Changed in mos:
milestone: 8.0 → none
Changed in mos:
milestone: none → 8.0
Ivan Kolodyazhny (e0ne) wrote :

FIx is already committed. We added retry-on-deadlock

Changed in mos:
status: Confirmed → Fix Committed
tags: added: cinder scale
tags: added: area-cinder
removed: cinder
Ivan Lozgachev (ilozgachev) wrote :

Verified on ENV-10 Build 482 and ENV-14 Build 496

Changed in mos:
status: Fix Committed → Fix Released
To post a comment you must log in.
This report contains Public information  Edit
Everyone can see this information.

Other bug subscribers