Exception during message handling: error opening image volume-435e169b-52a5-4b99-a770-f7623adaea31 at snapshot None

[Alexander Nevenchannyy]

api: '1.0'
astute_sha: ed76b0cacf34a4a683b464ebd86e0beb273b5473
auth_required: true
build_id: 2015-03-12_22-54-44
build_number: '192'
feature_groups:
- mirantis
fuellib_sha: fda8128b9ca7a8ce818421040f597a50eece8078
fuelmain_sha: 3764b8a73b3a93fd7ee66937ba4c4c77da409b78
nailgun_sha: c186f71158ed27b03d8db87561ea66c19e39b452
ostf_sha: ecb8e294b0acbdc5b0300d5e39028fb26ecc9088
production: docker
python-fuelclient_sha: 59513d6b75f86060ff5059f39fdd9cca56c83f19
release: '6.1'
release_versions:
  2014.2-6.1:
    VERSION:
      api: '1.0'
      astute_sha: ed76b0cacf34a4a683b464ebd86e0beb273b5473
      build_id: 2015-03-12_22-54-44
      build_number: '192'
      feature_groups:
      - mirantis
      fuellib_sha: fda8128b9ca7a8ce818421040f597a50eece8078
      fuelmain_sha: 3764b8a73b3a93fd7ee66937ba4c4c77da409b78
      nailgun_sha: c186f71158ed27b03d8db87561ea66c19e39b452
      ostf_sha: ecb8e294b0acbdc5b0300d5e39028fb26ecc9088
      production: docker
      python-fuelclient_sha: 59513d6b75f86060ff5059f39fdd9cca56c83f19
      release: '6.1'

Deploy was following confguration:
Baremetal, Ubuntu, HA, Neutron-gre,Ceph-all, Debug, nova-quotas, 6.1-192
Controllers:3 Computes:45

Rally job was: create-from-volume-and-delete-volume

Rally logs (grepped by volume display_name):

http_log_resp /opt/stack/.venv/lib/python2.7/site-packages/cinderclient/client.py:221
2015-03-30 05:15:49.552 2800 DEBUG cinderclient.client [-]
REQ: curl -i http://172.16.45.101:8776/v1/386e7978e270447cb71bb683c9fdfbb9/volumes -X POST -H "User-Agent: python-cinderclient" -H "Content-Type: application/json" -H "Accept: application/json" -H "X-Auth-Token: d68975f51c6d4d8f8334fd62ee45a085" -d '{"volume": {"status": "creating", "availability_zone": null, "source_volid": "3a91434b-8db7-4c16-bb14-77dc6fa6d831", "display_description": null, "snapshot_id": null, "user_id": null, "size": 1, "display_name": "rally_volume_snupcwizay", "imageRef": null, "attach_status": "detached", "volume_type": null, "project_id": null, "metadata": {}}}'

http_log_resp /opt/stack/.venv/lib/python2.7/site-packages/cinderclient/client.py:221
2015-03-30 05:15:50.415 2800 DEBUG cinderclient.client [-] RESP: [200] {'content-length': '412', 'x-compute-request-id': 'req-1c9d0e80-ddba-47d2-84d6-ea6f5f9a4fbb', 'connection': 'close', 'date': 'Mon, 30 Mar 2015 05:15:50 GMT', 'content-type': 'application/json', 'x-openstack-request-id': 'req-1c9d0e80-ddba-47d2-84d6-ea6f5f9a4fbb'}
RESP BODY: {"volume": {"status": "creating", "display_name": "rally_volume_snupcwizay", "attachments": [], "availability_zone": "nova", "bootable": "false", "encrypted": false, "created_at": "2015-03-30T05:15:49.981478", "display_description": null, "volume_type": "None", "snapshot_id": null, "source_volid": "3a91434b-8db7-4c16-bb14-77dc6fa6d831", "metadata": {}, "id": "9e0e2fd1-d69d-4157-a76b-85d75de758a0", "size": 1}}

http_log_resp /opt/stack/.venv/lib/python2.7/site-packages/cinderclient/client.py:221
2015-03-30 05:24:57.727 20741 DEBUG cinderclient.client [-] RESP: [200] {'content-length': '1105', 'x-compute-request-id': 'req-73cd162c-a08b-4c0b-9a92-455278db9fe9', 'connection': 'close',
 'date': 'Mon, 30 Mar 2015 05:24:57 GMT', 'content-type': 'application/json', 'x-openstack-request-id': 'req-73cd162c-a08b-4c0b-9a92-455278db9fe9'}
RESP BODY: {"volumes": [{"status": "available", "display_name": "rally_volume_snupcwizay", "attachments": [], "availability_zone": "nova", "bootable": "false", "encrypted": false, "created_at": "2015-03-30T05:15:50.000000", "os-vol-tenant-attr:tenant_id": "386e7978e270447cb71bb683c9fdfbb9", "os-volume-replication:driver_data": null, "display_description": null, "os-volume-replication:extended_status": null, "volume_type": "None", "snapshot_id": null, "source_volid": "3a91434b-8db7-4c16-bb14-77dc6fa6d831", "metadata": {}, "id": "9e0e2fd1-d69d-4157-a76b-85d75de758a0", "size": 1}, {"status": "available", "display_name": "ctx_rally_volume_gkzwyzcyay", "attachments": [], "availability_zone": "nova", "bootable": "false", "encrypted": false, "created_at": "2015-03-30T04:58:11.000000", "os-vol-tenant-attr:tenant_id": "386e7978e270447cb71bb683c9fdfbb9", "os-volume-replication:driver_data": null, "display_description": null, "os-volume-replication:extended_status": null, "volume_type": "None", "snapshot_id": null, "source_volid": null, "metadata": {}, "id": "3a91434b-8db7-4c16-bb14-77dc6fa6d831", "size": 1}]}

http_log_req /opt/stack/.venv/lib/python2.7/site-packages/cinderclient/client.py:212
2015-03-30 05:25:00.820 20741 DEBUG cinderclient.client [-] RESP: [200] {'content-length': '570', 'x-compute-request-id': 'req-6551106d-5337-44d3-ac3b-c1fe41e7b4e8', 'connection': 'close',
'date': 'Mon, 30 Mar 2015 05:24:59 GMT', 'content-type': 'application/json', 'x-openstack-request-id': 'req-6551106d-5337-44d3-ac3b-c1fe41e7b4e8'}
RESP BODY: {"volume": {"status": "deleting", "display_name": "rally_volume_snupcwizay", "attachments": [], "availability_zone": "nova", "bootable": "false", "encrypted": false, "created_at": "2015-03-30T05:15:50.000000", "os-vol-tenant-attr:tenant_id": "386e7978e270447cb71bb683c9fdfbb9", "os-volume-replication:driver_data": null, "display_description": null, "os-volume-replication:extended_status": null, "volume_type": "None", "snapshot_id": null, "source_volid": "3a91434b-8db7-4c16-bb14-77dc6fa6d831", "metadata": {}, "id": "9e0e2fd1-d69d-4157-a76b-85d75de758a0", "size": 1}}

http_log_resp /opt/stack/.venv/lib/python2.7/site-packages/cinderclient/client.py:221
2015-03-30 05:25:02.406 20741 DEBUG cinderclient.client [-] RESP: [200] {'content-length': '576', 'x-compute-request-id': 'req-35a531a1-3e5c-4720-a231-31689f2f427c', 'connection': 'close',
'date': 'Mon, 30 Mar 2015 05:25:02 GMT', 'content-type': 'application/json', 'x-openstack-request-id': 'req-35a531a1-3e5c-4720-a231-31689f2f427c'}
RESP BODY: {"volume": {"status": "error_deleting", "display_name": "rally_volume_snupcwizay", "attachments": [], "availability_zone": "nova", "bootable": "false", "encrypted": false, "created_at": "2015-03-30T05:15:50.000000", "os-vol-tenant-attr:tenant_id": "386e7978e270447cb71bb683c9fdfbb9", "os-volume-replication:driver_data": null, "display_description": null, "os-volume-replication:extended_status": null, "volume_type": "None", "snapshot_id": null, "source_volid": "3a91434b-8db7-4c16-bb14-77dc6fa6d831", "metadata": {}, "id": "9e0e2fd1-d69d-4157-a76b-85d75de758a0", "size": 1}}

--// last message was repeated many times//--

http_log_req /opt/stack/.venv/lib/python2.7/site-packages/cinderclient/client.py:212
2015-03-30 05:34:58.681 20741 DEBUG cinderclient.client [-] RESP: [200] {'content-length': '576', 'x-compute-request-id': 'req-03cb6694-6f69-4f6a-bb54-e03f7d0d9b72', 'connection': 'close', 'date': 'Mon, 30 Mar 2015 05:34:57 GMT', 'content-type': 'application/json', 'x-openstack-request-id': 'req-03cb6694-6f69-4f6a-bb54-e03f7d0d9b72'}
RESP BODY: {"volume": {"status": "error_deleting", "display_name": "rally_volume_snupcwizay", "attachments": [], "availability_zone": "nova", "bootable": "false", "encrypted": false, "created_at": "2015-03-30T05:15:50.000000", "os-vol-tenant-attr:tenant_id": "386e7978e270447cb71bb683c9fdfbb9", "os-volume-replication:driver_data": null, "display_description": null, "os-volume-replication:extended_status": null, "volume_type": "None", "snapshot_id": null, "source_volid": "3a91434b-8db7-4c16-bb14-77dc6fa6d831", "metadata": {}, "id": "9e0e2fd1-d69d-4157-a76b-85d75de758a0", "size": 1}}

Cinder error:
2015-03-30T05:24:20.363436+00:00 err: Exception during message handling: error opening image volume-435e169b-52a5-4b99-a770-f7623adaea31 at snapshot None
2015-03-30 05:24:19.711 2344 TRACE oslo.messaging.rpc.dispatcher Traceback (most recent call last):
2015-03-30 05:24:19.711 2344 TRACE oslo.messaging.rpc.dispatcher File "/usr/lib/python2.7/dist-packages/oslo/messaging/rpc/dispatcher.py", line 137, in _dispatch_and_reply
2015-03-30 05:24:19.711 2344 TRACE oslo.messaging.rpc.dispatcher incoming.message))
2015-03-30 05:24:19.711 2344 TRACE oslo.messaging.rpc.dispatcher File "/usr/lib/python2.7/dist-packages/oslo/messaging/rpc/dispatcher.py", line 180, in _dispatch
2015-03-30 05:24:19.711 2344 TRACE oslo.messaging.rpc.dispatcher return self._do_dispatch(endpoint, method, ctxt, args)
2015-03-30 05:24:19.711 2344 TRACE oslo.messaging.rpc.dispatcher File "/usr/lib/python2.7/dist-packages/oslo/messaging/rpc/dispatcher.py", line 126, in _do_dispatch
2015-03-30 05:24:19.711 2344 TRACE oslo.messaging.rpc.dispatcher result = getattr(endpoint, method)(ctxt, **new_args)
2015-03-30 05:24:19.711 2344 TRACE oslo.messaging.rpc.dispatcher File "/usr/lib/python2.7/dist-packages/osprofiler/profiler.py", line 105, in wrapper
2015-03-30 05:24:19.711 2344 TRACE oslo.messaging.rpc.dispatcher return f(*args, **kwargs)
2015-03-30 05:24:19.711 2344 TRACE oslo.messaging.rpc.dispatcher File "/usr/lib/python2.7/dist-packages/cinder/volume/manager.py", line 127, in lvo_inner1
2015-03-30 05:24:19.711 2344 TRACE oslo.messaging.rpc.dispatcher return lvo_inner2(inst, context, volume_id, **kwargs)
2015-03-30 05:24:19.711 2344 TRACE oslo.messaging.rpc.dispatcher File "/usr/lib/python2.7/dist-packages/cinder/openstack/common/lockutils.py", line 233, in inner
2015-03-30 05:24:19.711 2344 TRACE oslo.messaging.rpc.dispatcher retval = f(*args, **kwargs)
2015-03-30 05:24:19.711 2344 TRACE oslo.messaging.rpc.dispatcher File "/usr/lib/python2.7/dist-packages/cinder/volume/manager.py", line 126, in lvo_inner2
2015-03-30 05:24:19.711 2344 TRACE oslo.messaging.rpc.dispatcher return f(*_args, **_kwargs)
2015-03-30 05:24:19.711 2344 TRACE oslo.messaging.rpc.dispatcher File "/usr/lib/python2.7/dist-packages/cinder/volume/manager.py", line 455, in delete_volume
2015-03-30 05:24:19.711 2344 TRACE oslo.messaging.rpc.dispatcher {'status': 'error_deleting'})
2015-03-30 05:24:19.711 2344 TRACE oslo.messaging.rpc.dispatcher File "/usr/lib/python2.7/dist-packages/cinder/openstack/common/excutils.py", line 82, in __exit__
2015-03-30 05:24:19.711 2344 TRACE oslo.messaging.rpc.dispatcher six.reraise(self.type_, self.value, self.tb)
2015-03-30 05:24:19.711 2344 TRACE oslo.messaging.rpc.dispatcher File "/usr/lib/python2.7/dist-packages/cinder/volume/manager.py", line 444, in delete_volume
2015-03-30 05:24:19.711 2344 TRACE oslo.messaging.rpc.dispatcher self.driver.delete_volume(volume_ref)
2015-03-30 05:24:19.711 2344 TRACE oslo.messaging.rpc.dispatcher File "/usr/lib/python2.7/dist-packages/osprofiler/profiler.py", line 105, in wrapper
2015-03-30 05:24:19.711 2344 TRACE oslo.messaging.rpc.dispatcher return f(*args, **kwargs)
2015-03-30 05:24:19.711 2344 TRACE oslo.messaging.rpc.dispatcher File "/usr/lib/python2.7/dist-packages/cinder/volume/drivers/rbd.py", line 672, in delete_volume
2015-03-30 05:24:19.711 2344 TRACE oslo.messaging.rpc.dispatcher self._delete_clone_parent_refs(client, parent, parent_snap)
2015-03-30 05:24:19.711 2344 TRACE oslo.messaging.rpc.dispatcher File "/usr/lib/python2.7/dist-packages/cinder/volume/drivers/rbd.py", line 582, in _delete_clone_parent_refs
2015-03-30 05:24:19.711 2344 TRACE oslo.messaging.rpc.dispatcher parent_rbd = self.rbd.Image(client.ioctx, parent_name)
2015-03-30 05:24:19.711 2344 TRACE oslo.messaging.rpc.dispatcher File "/usr/lib/python2.7/dist-packages/rbd.py", line 371, in __init__
2015-03-30 05:24:19.711 2344 TRACE oslo.messaging.rpc.dispatcher raise make_ex(ret, 'error opening image %s at snapshot %s' % (name, snapshot))
2015-03-30 05:24:19.711 2344 TRACE oslo.messaging.rpc.dispatcher ImageNotFound: error opening image volume-435e169b-52a5-4b99-a770-f7623adaea31 at snapshot None
2015-03-30 05:24:19.711 2344 TRACE oslo.messaging.rpc.dispatcher

Ceph cluster was fully operational, with out any errors/

[Alexander Nevenchannyy (anevenchannyy)]

Some cinder logs, before error:

2015-03-30 05:24:59.214 25491 DEBUG cinder.openstack.common.lockutils [req-f0cb264d-5135-49e0-abd3-ce50d00e0c3e c2b29eac704d4edd8b42a10bcffd89ca 386e7978e270447cb71bb683c9fdfbb9 - - -] Got semaphore "9e0e2fd1-d69d-4157-a76b-85d75de758a0-delete_volume" for method "lvo_inner2"... inner /usr/lib/python2.7/dist-packages/cinder/openstack/common/lockutils.py:191
2015-03-30 05:24:59.215 25491 DEBUG cinder.openstack.common.lockutils [req-f0cb264d-5135-49e0-abd3-ce50d00e0c3e c2b29eac704d4edd8b42a10bcffd89ca 386e7978e270447cb71bb683c9fdfbb9 - - -] Attempting to grab file lock "9e0e2fd1-d69d-4157-a76b-85d75de758a0-delete_volume" for method "lvo_inner2"... inner /usr/lib/python2.7/dist-packages/cinder/openstack/common/lockutils.py:202
2015-03-30 05:24:59.217 25491 DEBUG cinder.openstack.common.lockutils [req-f0cb264d-5135-49e0-abd3-ce50d00e0c3e c2b29eac704d4edd8b42a10bcffd89ca 386e7978e270447cb71bb683c9fdfbb9 - - -] Got file lock "9e0e2fd1-d69d-4157-a76b-85d75de758a0-delete_volume" at /var/lock/cinder/cinder-9e0e2fd1-d69d-4157-a76b-85d75de758a0-delete_volume for method "lvo_inner2"... inner /usr/lib/python2.7/dist-packages/cinder/openstack/common/lockutils.py:232
2015-03-30 05:24:59.260 25491 INFO cinder.volume.manager [req-f0cb264d-5135-49e0-abd3-ce50d00e0c3e c2b29eac704d4edd8b42a10bcffd89ca 386e7978e270447cb71bb683c9fdfbb9 - - -] volume 9e0e2fd1-d69d-4157-a76b-85d75de758a0: deleting
2015-03-30 05:24:59.261 25491 DEBUG cinder.volume.manager [req-f0cb264d-5135-49e0-abd3-ce50d00e0c3e c2b29eac704d4edd8b42a10bcffd89ca 386e7978e270447cb71bb683c9fdfbb9 - - -] volume 9e0e2fd1-d69d-4157-a76b-85d75de758a0: removing export delete_volume /usr/lib/python2.7/dist-packages/cinder/volume/manager.py:438
2015-03-30 05:24:59.262 25491 DEBUG cinder.volume.manager [req-f0cb264d-5135-49e0-abd3-ce50d00e0c3e c2b29eac704d4edd8b42a10bcffd89ca 386e7978e270447cb71bb683c9fdfbb9 - - -] volume 9e0e2fd1-d69d-4157-a76b-85d75de758a0: deleting delete_volume /usr/lib/python2.7/dist-packages/cinder/volume/manager.py:440
2015-03-30 05:24:59.262 25491 DEBUG cinder.volume.drivers.rbd [req-f0cb264d-5135-49e0-abd3-ce50d00e0c3e c2b29eac704d4edd8b42a10bcffd89ca 386e7978e270447cb71bb683c9fdfbb9 - - -] opening connection to ceph cluster (timeout=-1). _connect_to_rados /usr/lib/python2.7/dist-packages/cinder/volume/drivers/rbd.py:291
2015-03-30 05:24:59.374 25491 DEBUG cinder.volume.drivers.rbd [req-f0cb264d-5135-49e0-abd3-ce50d00e0c3e c2b29eac704d4edd8b42a10bcffd89ca 386e7978e270447cb71bb683c9fdfbb9 - - -] volume has no backup snaps _delete_backup_snaps /usr/lib/python2.7/dist-packages/cinder/volume/drivers/rbd.py:551
2015-03-30 05:24:59.394 25491 DEBUG cinder.volume.drivers.rbd [req-f0cb264d-5135-49e0-abd3-ce50d00e0c3e c2b29eac704d4edd8b42a10bcffd89ca 386e7978e270447cb71bb683c9fdfbb9 - - -] deleting rbd volume volume-9e0e2fd1-d69d-4157-a76b-85d75de758a0 delete_volume /usr/lib/python2.7/dist-packages/cinder/volume/drivers/rbd.py:649
2015-03-30 05:24:59.638 25491 DEBUG cinder.volume.drivers.rbd [req-f0cb264d-5135-49e0-abd3-ce50d00e0c3e c2b29eac704d4edd8b42a10bcffd89ca 386e7978e270447cb71bb683c9fdfbb9 - - -] volume is a clone so cleaning references delete_volume /usr...

[Anton Arefiev (aarefiev)]

Can't reproduce it on 213 build.

[Ivan Kolodyazhny (e0ne)]

Can't reproduce with ISO:
VERSION:
  feature_groups:
    - mirantis
  production: "docker"
  release: "6.1"
  api: "1.0"
  build_number: "282"
  build_id: "2015-04-06_08-49-30"
  nailgun_sha: "a2dc04af9c5838a990adeab81789d4c090943701"
  python-fuelclient_sha: "9ad42671130deb2cc81135fb453ef0793883be2c"
  astute_sha: "240bfefe0a0b5af21b79854d0c96d8a3ee0fd885"
  fuellib_sha: "601cc8e1dccbdcf328f83f071270609e824d6c5a"
  ostf_sha: "b978badb43243d3f1b85dde15b8e301a21f12254"
  fuelmain_sha: "f90d7d40ceff39ee6d7587b183c63bd00ed0743f"

[Alexander Nevenchannyy (anevenchannyy)]

Root case of problem was mysqld crash.