Mirantis OpenStack

Lock wait timeout exceeded; try restarting transaction in Nova logs

Bug #1394264 reported by Ilya Shakhat
6
This bug affects 1 person
Affects Status Importance Assigned to Milestone
Mirantis OpenStack
Fix Released
High
Pavel Kholkin
Mirantis OpenStack 6.0

Bug Description

After Rally test execution Nova log contain a lot of "Lock wait timeout exceeded; try restarting transaction" error messages.

VERSION:
  feature_groups:
    - mirantis
  production: "docker"
  release: "6.0"
  api: "1.0"
  build_number: "110"
  build_id: "2014-11-16_22-00-23"
  astute_sha: "8e05026cf17aeb92e2fb028b3b95ba34803508ed"
  fuellib_sha: "4c080377d5d1f4397a257e26c836055889fa3138"
  ostf_sha: "82465a94eed4eff1fc8d8e1f2fb7e9993c22f068"
  nailgun_sha: "3e98ea8a042b43be8c00b9f852e19b4c0b853404"
  fuelmain_sha: "137d944d4a658e0358349db0daa2b9bc21ae8218"

Rally results: http://networking-ci.vm.mirantis.net/test_results/build_6.0-110-LF1/jenkins-run_rally_env_10-6-ubuntu-MSK-2014-11-18-21:33:16-2014-11-19-07:46:58/

Tags: nova
Revision history for this message
Ilya Shakhat (shakhat) wrote :
Download full text (11.7 KiB)

Nova log:
2014-11-19T03:06:17.213468+00:00 debug:
REQ: curl -i http://192.168.0.2:9696/v2.0/quotas/6997646ffb644bb69c9d1ac01836ac68.json -X GET -H "X-Auth-Token: 631b39b5a31644c4a78830a8aa
8ef53b" -H "User-Agent: python-neutronclient"
2014-11-19T03:06:17.269463+00:00 debug: RESP:200 CaseInsensitiveDict({'date': 'Wed, 19 Nov 2014 03:06:17 GMT', 'content-length': '134', '
content-type': 'application/json; charset=UTF-8', 'x-openstack-request-id': 'req-b3e568e9-6d19-40e1-be93-b81eae09274e'}) {"quota": {"subne
t": 10, "network": 10, "floatingip": 50, "security_group_rule": 100, "security_group": 10, "router": 10, "port": 50}}
2014-11-19T03:06:17.290766+00:00 err: Caught error: (OperationalError) (1205, 'Lock wait timeout exceeded; try restarting transaction') '
SELECT quota_usages.deleted_at AS quota_usages_deleted_at, quota_usages.deleted AS quota_usages_deleted, quota_usages.created_at AS quota_
usages_created_at, quota_usages.updated_at AS quota_usages_updated_at, quota_usages.id AS quota_usages_id, quota_usages.project_id AS quota_usages_project_id, quota_usages.user_id AS quota_usages_user_id, quota_usages.resource AS quota_usages_resource, quota_usages.in_use AS quota_usages_in_use, quota_usages.reserved AS quota_usages_reserved, quota_usages.until_refresh AS quota_usages_until_refresh \nFROM quota_usages \nWHERE quota_usages.deleted = %s AND quota_usages.project_id = %s FOR UPDATE' (0, '638d3d20992046e0a963e33ebd61c48d')
2014-11-19 03:06:17.273 20180 TRACE nova.api.openstack Traceback (most recent call last):
2014-11-19 03:06:17.273 20180 TRACE nova.api.openstack File "/usr/lib/python2.7/dist-packages/nova/api/openstack/__init__.py", line 124, in __call__
2014-11-19 03:06:17.273 20180 TRACE nova.api.openstack return req.get_response(self.application)
2014-11-19 03:06:17.273 20180 TRACE nova.api.openstack File "/usr/lib/python2.7/dist-packages/webob/request.py", line 1320, in send
2014-11-19 03:06:17.273 20180 TRACE nova.api.openstack application, catch_exc_info=False)
2014-11-19 03:06:17.273 20180 TRACE nova.api.openstack File "/usr/lib/python2.7/dist-packages/webob/request.py", line 1284, in call_application
2014-11-19 03:06:17.273 20180 TRACE nova.api.openstack app_iter = application(self.environ, start_response)
2014-11-19 03:06:17.273 20180 TRACE nova.api.openstack File "/usr/lib/python2.7/dist-packages/webob/dec.py", line 144, in __call__
2014-11-19 03:06:17.273 20180 TRACE nova.api.openstack return resp(environ, start_response)
2014-11-19 03:06:17.273 20180 TRACE nova.api.openstack File "/usr/lib/python2.7/dist-packages/keystonemiddleware/auth_token.py", line 748, in __call__
2014-11-19 03:06:17.273 20180 TRACE nova.api.openstack return self._call_app(env, start_response)
2014-11-19 03:06:17.273 20180 TRACE nova.api.openstack File "/usr/lib/python2.7/dist-packages/keystonemiddleware/auth_token.py", line 684, in _call_app
2014-11-19 03:06:17.273 20180 TRACE nova.api.openstack return self._app(env, _fake_start_response)
2014-11-19 03:06:17.273 20180 TRACE nova.api.openstack File "/usr/lib/python2.7/dist-packages/webob/dec.py", line 144, in __call__
2014-11-19 03:06:17.273 20180 TRACE nova.api.o...

Revision history for this message
Ilya Shakhat (shakhat) wrote :

Nova log

tags: added: nova
Roman Podoliaka (rpodolyaka)
Changed in mos:
status: New → Triaged
importance: Undecided → High
assignee: nobody → Pavel Kholkin (pkholkin)
milestone: none → 6.1
Revision history for this message
Roman Podoliaka (rpodolyaka) wrote :

Upstream bug https://bugs.launchpad.net/oslo.db/+bug/1394298

Revision history for this message
Roman Podoliaka (rpodolyaka) wrote :

Should be fixed in https://review.openstack.org/#/c/135674/

Revision history for this message
OSCI Robot (oscirobot) wrote :

RPM package oslo.db has been built for project openstack/oslo.db
Package version == 1.0.1, package release == fuel6.0.mira22.git.49fc715.689417e

Changeset: https://review.fuel-infra.org/919
project: openstack/oslo.db
branch: openstack-ci/fuel-6.0/2014.2
author: Victor Sergeyev
committer: Victor Sergeyev
subject: Handle Galera deadlock on SELECT FOR UPDATE
status: patchset-created

Files placed on repository:
python-oslo-db-1.0.1-fuel6.0.mira22.git.49fc715.689417e.noarch.rpm

NOTE: Changeset is not merged, created temporary package repository.
RPM repository URL: http://osci-obs.vm.mirantis.net:82/centos-fuel-6.0-stable-919/centos

Revision history for this message
OSCI Robot (oscirobot) wrote :

DEB package oslo.db has been built for project openstack/oslo.db
Package version == 1.0.1, package release == fuel6.0~mira19+git.49fc715.689417e

Changeset: https://review.fuel-infra.org/919
project: openstack/oslo.db
branch: openstack-ci/fuel-6.0/2014.2
author: Victor Sergeyev
committer: Victor Sergeyev
subject: Handle Galera deadlock on SELECT FOR UPDATE
status: patchset-created

Files placed on repository:
python-oslo.db_1.0.1-fuel6.0~mira19+git.49fc715.689417e_all.deb

NOTE: Changeset is not merged, created temporary package repository.
DEB repository URL: http://osci-obs.vm.mirantis.net:82/ubuntu-fuel-6.0-stable-919/ubuntu

Roman Podoliaka (rpodolyaka)
Changed in mos:
status: Triaged → In Progress
Roman Podoliaka (rpodolyaka)
Changed in mos:
milestone: 6.1 → 6.0
Revision history for this message
OSCI Robot (oscirobot) wrote :

RPM package oslo.db has been built for project openstack/oslo.db
Package version == 1.0.1, package release == fuel6.0.mira22

Changeset: https://review.fuel-infra.org/919
project: openstack/oslo.db
branch: openstack-ci/fuel-6.0/2014.2
author: Victor Sergeyev
committer: Victor Sergeyev
subject: Handle Galera deadlock on SELECT FOR UPDATE
status: change-merged

Files placed on repository:
python-oslo-db-1.0.1-fuel6.0.mira22.noarch.rpm

Changeset merged. Package placed on primary repository
RPM repository URL: http://osci-obs.vm.mirantis.net:82/centos-fuel-6.0-stable/centos

Revision history for this message
OSCI Robot (oscirobot) wrote :

DEB package oslo.db has been built for project openstack/oslo.db
Package version == 1.0.1, package release == fuel6.0~mira19

Changeset: https://review.fuel-infra.org/919
project: openstack/oslo.db
branch: openstack-ci/fuel-6.0/2014.2
author: Victor Sergeyev
committer: Victor Sergeyev
subject: Handle Galera deadlock on SELECT FOR UPDATE
status: change-merged

Files placed on repository:
python-oslo.db_1.0.1-fuel6.0~mira19_all.deb

Changeset merged. Package placed on primary repository
DEB repository URL: http://osci-obs.vm.mirantis.net:82/ubuntu-fuel-6.0-stable/ubuntu

Revision history for this message
Roman Podoliaka (rpodolyaka) wrote :

For 6.0 we'll provide a work around in oslo.db - https://review.fuel-infra.org/#/c/919/

For 7.0 we are going to fix this upstream by removing usage of SELECT FOR UPDATE in quotas management.

Changed in mos:
status: In Progress → Fix Committed
Revision history for this message
Alexander Gubanov (ogubanov) wrote :

It's hard to reproduce, so I've just checked code on mos 6.0 (build 56) - fixed!
Proof:

[root@nailgun ~]# fuel --f
api: '1.0'
astute_sha: 16b252d93be6aaa73030b8100cf8c5ca6a970a91
auth_required: true
build_id: 2014-12-18_01-32-01
build_number: '56'
feature_groups:
- mirantis
fuellib_sha: 73332192a257ea02c40a39885c502ad1ebdf3eda
fuelmain_sha: 45caacadb878abfbd9d60e134d72229698b469c9
nailgun_sha: 5f91157daa6798ff522ca9f6d34e7e135f150a90
ostf_sha: a9afb68710d809570460c29d6c3293219d3624d4
production: docker
release: '6.0'
release_versions:
  2014.2-6.0:
    VERSION:
      api: '1.0'
      astute_sha: 16b252d93be6aaa73030b8100cf8c5ca6a970a91
      build_id: 2014-12-18_01-32-01
      build_number: '56'
      feature_groups:
      - mirantis
      fuellib_sha: 73332192a257ea02c40a39885c502ad1ebdf3eda
      fuelmain_sha: 45caacadb878abfbd9d60e134d72229698b469c9
      nailgun_sha: 5f91157daa6798ff522ca9f6d34e7e135f150a90
      ostf_sha: a9afb68710d809570460c29d6c3293219d3624d4
      production: docker
      release: '6.0'

root@node-7:~# grep 'Lock wait timeout exceeded' /usr/lib/python2.7/dist-packages/oslo/db/sqlalchemy/exc_filters.py
         r"^.*\b1205\b.*Lock wait timeout exceeded.*")

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

Other bug subscribers

Remote bug watches

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