Volume Block Device Mapping cannot be found

[Silvan Kaiser]

In Short:
Block Device Mapping cannot be found for Tempest online snapshot test on devstack with remote file system driver.

More Detailed:
Testing Environment is plain kilo head devstack with the included Tempest testsuite and a new remotefs based cinder driver.
The test:
     tempest.api.volume.test_volumes_snapshots.VolumesV2SnapshotTestJSON.test_snapshot_create_with_volume_in_use
produces an error in Nova, stacktrace:

2014-12-10 11:14:42.329 ^[[00;32mDEBUG nova.api.openstack.wsgi [^[[01;36mreq-5a0e0e46-2455-41ee-a36a-6c14de0d1627 ^[[00;36mVolumesV1SnapshotTestJSON-2078362258 VolumesV1SnapshotTestJSON-1658640019^[[00;32m] ^[[01;35m^[[00;32mCalling method '<bound method Controller.show of <nova.api.openstack.compute.servers.Controller object at 0x7fbd794a0690>>'^[[00m ^[[00;33mfrom (pid=12485) _process_stack /opt/stack/nova/nova/api/openstack/wsgi.py:963^[[00m^M
2014-12-10 11:14:42.374 ^[[00;36mINFO nova.osapi_compute.wsgi.server [^[[01;36mreq-5a0e0e46-2455-41ee-a36a-6c14de0d1627 ^[[00;36mVolumesV1SnapshotTestJSON-2078362258 VolumesV1SnapshotTestJSON-1658640019^[[00;36m] ^[[01;35m^[[00;36m192.168.122.67 "GET /v2/e152b27ee9d641e6a57bec75ab29c924/servers/4fb9afd5-18a9-416e-b955-d161ebbc436f HTTP/1.1" status: 200 len: 1609 time: 0.0979590^[[00m^M
2014-12-10 11:14:43.381 ^[[00;32mDEBUG nova.api.openstack.wsgi [^[[01;36mreq-02efe9e9-c7cb-46bf-8ab4-0b70a9b84f6d ^[[00;36mVolumesV1SnapshotTestJSON-2078362258 VolumesV1SnapshotTestJSON-1658640019^[[00;32m] ^[[01;35m^[[00;32mCalling method '<bound method Controller.show of <nova.api.openstack.compute.servers.Controller object at 0x7fbd794a0690>>'^[[00m ^[[00;33mfrom (pid=12487) _process_stack /opt/stack/nova/nova/api/openstack/wsgi.py:963^[[00m^M
2014-12-10 11:14:43.423 ^[[00;36mINFO nova.osapi_compute.wsgi.server [^[[01;36mreq-02efe9e9-c7cb-46bf-8ab4-0b70a9b84f6d ^[[00;36mVolumesV1SnapshotTestJSON-2078362258 VolumesV1SnapshotTestJSON-1658640019^[[00;36m] ^[[01;35m^[[00;36m192.168.122.67 "GET /v2/e152b27ee9d641e6a57bec75ab29c924/servers/4fb9afd5-18a9-416e-b955-d161ebbc436f HTTP/1.1" status: 200 len: 1749 time: 0.0428371^[[00m^M
2014-12-10 11:14:43.995 ^[[00;32mDEBUG nova.api.openstack.wsgi [^[[01;36mreq-023897db-cfd9-4259-b7c4-3621722a5eec ^[[00;36mVolumesV2SnapshotTestJSON-1786381329 VolumesV2SnapshotTestJSON-2048796393^[[00;32m] ^[[01;35m^[[00;32mAction: 'create', calling method: <bound method AssistedVolumeSnapshotsController.create of <nova.api.openstack.compute.contrib.assisted_volume_snapshots.AssistedVolumeSnapshotsController object at 0x7fbd792ef490>>, body: {"snapshot": {"create_info": {"snapshot_id": "cf916b1a-e797-41e3-bde8-39c9615aa622", "type": "qcow2", "new_file": "volume-9f7ec09d-4ff2-4ef9-96dc-2bdc07471a65.cf916b1a-e797-41e3-bde8-39c9615aa622"}, "volume_id": "9f7ec09d-4ff2-4ef9-96dc-2bdc07471a65"}}^[[00m ^[[00;33mfrom (pid=12487) _process_stack /opt/stack/nova/nova/api/openstack/wsgi.py:960^[[00m^M
2014-12-10 11:14:43.995 ^[[01;36mAUDIT nova.api.openstack.compute.contrib.assisted_volume_snapshots [^[[01;36mreq-023897db-cfd9-4259-b7c4-3621722a5eec ^[[00;36mVolumesV2SnapshotTestJSON-1786381329 VolumesV2SnapshotTestJSON-2048796393^[[01;36m] ^[[01;35m^[[01;36mCreate assisted snapshot from volume 9f7ec09d-4ff2-4ef9-96dc-2bdc07471a65^[[00m^M
2014-12-10 11:14:44.007 ^[[01;31mERROR nova.api.openstack [^[[01;36mreq-023897db-cfd9-4259-b7c4-3621722a5eec ^[[00;36mVolumesV2SnapshotTestJSON-1786381329 VolumesV2SnapshotTestJSON-2048796393^[[01;31m] ^[[01;35m^[[01;31mCaught error: No volume Block Device Mapping with id 9f7ec09d-4ff2-4ef9-96dc-2bdc07471a65.^[[00m^M
^[[01;31m2014-12-10 11:14:44.007 TRACE nova.api.openstack ^[[01;35m^[[00mTraceback (most recent call last):^M
^[[01;31m2014-12-10 11:14:44.007 TRACE nova.api.openstack ^[[01;35m^[[00m File "/opt/stack/nova/nova/api/openstack/__init__.py", line 125, in __call__^M
^[[01;31m2014-12-10 11:14:44.007 TRACE nova.api.openstack ^[[01;35m^[[00m return req.get_response(self.application)^M
^[[01;31m2014-12-10 11:14:44.007 TRACE nova.api.openstack ^[[01;35m^[[00m File "/usr/lib/python2.7/dist-packages/webob/request.py", line 1320, in send^M
^[[01;31m2014-12-10 11:14:44.007 TRACE nova.api.openstack ^[[01;35m^[[00m application, catch_exc_info=False)^M
^[[01;31m2014-12-10 11:14:44.007 TRACE nova.api.openstack ^[[01;35m^[[00m File "/usr/lib/python2.7/dist-packages/webob/request.py", line 1284, in call_application^M
^[[01;31m2014-12-10 11:14:44.007 TRACE nova.api.openstack ^[[01;35m^[[00m app_iter = application(self.environ, start_response)^M
^[[01;31m2014-12-10 11:14:44.007 TRACE nova.api.openstack ^[[01;35m^[[00m File "/usr/lib/python2.7/dist-packages/webob/dec.py", line 144, in __call__^M
^[[01;31m2014-12-10 11:14:44.007 TRACE nova.api.openstack ^[[01;35m^[[00m return resp(environ, start_response)^M
^[[01;31m2014-12-10 11:14:44.007 TRACE nova.api.openstack ^[[01;35m^[[00m File "/usr/local/lib/python2.7/dist-packages/keystonemiddleware/auth_token.py", line 793, in __call__^M
^[[01;31m2014-12-10 11:14:44.007 TRACE nova.api.openstack ^[[01;35m^[[00m return self._call_app(env, start_response)^M
^[[01;31m2014-12-10 11:14:44.007 TRACE nova.api.openstack ^[[01;35m^[[00m File "/usr/local/lib/python2.7/dist-packages/keystonemiddleware/auth_token.py", line 726, in _call_app^M
^[[01;31m2014-12-10 11:14:44.007 TRACE nova.api.openstack ^[[01;35m^[[00m return self._app(env, _fake_start_response)^M
^[[01;31m2014-12-10 11:14:44.007 TRACE nova.api.openstack ^[[01;35m^[[00m File "/usr/lib/python2.7/dist-packages/webob/dec.py", line 144, in __call__^M
^[[01;31m2014-12-10 11:14:44.007 TRACE nova.api.openstack ^[[01;35m^[[00m return resp(environ, start_response)^M
^[[01;31m2014-12-10 11:14:44.007 TRACE nova.api.openstack ^[[01;35m^[[00m File "/usr/lib/python2.7/dist-packages/webob/dec.py", line 144, in __call__^M
^[[01;31m2014-12-10 11:14:44.007 TRACE nova.api.openstack ^[[01;35m^[[00m return resp(environ, start_response)^M
^[[01;31m2014-12-10 11:14:44.007 TRACE nova.api.openstack ^[[01;35m^[[00m File "/usr/local/lib/python2.7/dist-packages/routes/middleware.py", line 131, in __call__^M
^[[01;31m2014-12-10 11:14:44.007 TRACE nova.api.openstack ^[[01;35m^[[00m response = self.app(environ, start_response)^M
^[[01;31m2014-12-10 11:14:44.007 TRACE nova.api.openstack ^[[01;35m^[[00m File "/usr/lib/python2.7/dist-packages/webob/dec.py", line 144, in __call__^M
^[[01;31m2014-12-10 11:14:44.007 TRACE nova.api.openstack ^[[01;35m^[[00m return resp(environ, start_response)^M
^[[01;31m2014-12-10 11:14:44.007 TRACE nova.api.openstack ^[[01;35m^[[00m File "/usr/lib/python2.7/dist-packages/webob/dec.py", line 130, in __call__^M
^[[01;31m2014-12-10 11:14:44.007 TRACE nova.api.openstack ^[[01;35m^[[00m resp = self.call_func(req, *args, **self.kwargs)^M
^[[01;31m2014-12-10 11:14:44.007 TRACE nova.api.openstack ^[[01;35m^[[00m File "/usr/lib/python2.7/dist-packages/webob/dec.py", line 195, in call_func^M
^[[01;31m2014-12-10 11:14:44.007 TRACE nova.api.openstack ^[[01;35m^[[00m return self.func(req, *args, **kwargs)^M
^[[01;31m2014-12-10 11:14:44.007 TRACE nova.api.openstack ^[[01;35m^[[00m File "/opt/stack/nova/nova/api/openstack/wsgi.py", line 936, in __call__^M
^[[01;31m2014-12-10 11:14:44.007 TRACE nova.api.openstack ^[[01;35m^[[00m content_type, body, accept)^M
^[[01;31m2014-12-10 11:14:44.007 TRACE nova.api.openstack ^[[01;35m^[[00m File "/opt/stack/nova/nova/api/openstack/wsgi.py", line 1001, in _process_stack^M
^[[01;31m2014-12-10 11:14:44.007 TRACE nova.api.openstack ^[[01;35m^[[00m action_result = self.dispatch(meth, request, action_args)^M
^[[01;31m2014-12-10 11:14:44.007 TRACE nova.api.openstack ^[[01;35m^[[00m File "/opt/stack/nova/nova/api/openstack/wsgi.py", line 1086, in dispatch^M
^[[01;31m2014-12-10 11:14:44.007 TRACE nova.api.openstack ^[[01;35m^[[00m return method(req=request, **action_args)^M
^[[01;31m2014-12-10 11:14:44.007 TRACE nova.api.openstack ^[[01;35m^[[00m File "/opt/stack/nova/nova/api/openstack/compute/contrib/assisted_volume_snapshots.py", line 71, in create^M
^[[01;31m2014-12-10 11:14:44.007 TRACE nova.api.openstack ^[[01;35m^[[00m create_info)^M
^[[01;31m2014-12-10 11:14:44.007 TRACE nova.api.openstack ^[[01;35m^[[00m File "/opt/stack/nova/nova/compute/api.py", line 226, in wrapped^M
^[[01;31m2014-12-10 11:14:44.007 TRACE nova.api.openstack ^[[01;35m^[[00m return func(self, context, target, *args, **kwargs)^M
^[[01;31m2014-12-10 11:14:44.007 TRACE nova.api.openstack ^[[01;35m^[[00m File "/opt/stack/nova/nova/compute/api.py", line 3263, in volume_snapshot_create^M
^[[01;31m2014-12-10 11:14:44.007 TRACE nova.api.openstack ^[[01;35m^[[00m context, volume_id, expected_attrs=['instance'])^M
^[[01;31m2014-12-10 11:14:44.007 TRACE nova.api.openstack ^[[01;35m^[[00m File "/opt/stack/nova/nova/objects/base.py", line 156, in wrapper^M
^[[01;31m2014-12-10 11:14:44.007 TRACE nova.api.openstack ^[[01;35m^[[00m result = fn(cls, context, *args, **kwargs)^M
^[[01;31m2014-12-10 11:14:44.007 TRACE nova.api.openstack ^[[01;35m^[[00m File "/opt/stack/nova/nova/objects/block_device.py", line 164, in get_by_volume_id^M
^[[01;31m2014-12-10 11:14:44.007 TRACE nova.api.openstack ^[[01;35m^[[00m raise exception.VolumeBDMNotFound(volume_id=volume_id)^M
^[[01;31m2014-12-10 11:14:44.007 TRACE nova.api.openstack ^[[01;35m^[[00mVolumeBDMNotFound: No volume Block Device Mapping with id 9f7ec09d-4ff2-4ef9-96dc-2bdc07471a65.^M
^[[01;31m2014-12-10 11:14:44.007 TRACE nova.api.openstack ^[[01;35m^[[00m^M

Testing the tests individual steps via manual cli commands (create instance, attach volume, create online snapshot) works without errors in any of the involved components.
The error occurs with our Quobyte Driver (in development, see https://blueprints.launchpad.net/cinder/+spec/quobyte-usp-driver) and apparently with the existing GlusterFS driver. Both are closely related (Quobyte build on top of GlusterFS impl) and derived from the remotefs driver. I don't know if other setups are affected.

[Eric Harney (eharney)]

I just talked to mtanino about this, I think we have a basic understanding of why this happens.

It looks like the test calls os_attach to tell Cinder the volume is attached, but it doesn't actually attach it. (Need to tell Nova to attach the volume, not just send attach info to Cinder.) Then it calls create_snapshot which will try to perform an assisted snapshot for GlusterFS, Quobyte, etc.

This assisted snapshot fails in Nova because, since the volume wasn't _actually_ attached, Nova can't find it. The test needs to actually attach the volume for this to work as intended.

[Mitsuhiro Tanino (mitsuhiro-tanino)]

I also have same problem now.

I think the root cause of this problem is in tempest test steps.
In the test of test_snapshot_create_with_volume_in_use, these test steps are executed.

(1) Create a server
(2) Create a volume
(3) Attach volume using Cinder "os-attach" API ( instead of using Nova "os-volume_attachments")
(4) Create snapshot for the volume
(5) Error...

In my understanding, "os-attach" only updates some cinder DB entry related to volume attachment and this does not attach a volume to an instance.
#This API is generally called from Nova side after volume attachment is finished.

Therefore, nova does not know the volume after this API is called and there is no block_device_mapping in nova DB.
I confirmed Nova's block_device_mapping DB entry, after "os-attach" API, and there is no volume entry which is created step (2).

In test step (3), "self.volumes_client.attach_volume" is called now. This calls cinder client API.
But I think right test is calling "self.servers_client.attach_volume". This call Nova's volume attachment API.

I succeeded this test using "self.servers_client.attach_volume".
I will post a patch to tempest shortly.

[OpenStack Infra (hudson-openstack)]

Fix proposed to branch: master
Review: https://review.openstack.org/140873

[OpenStack Infra (hudson-openstack)]

Reviewed: https://review.openstack.org/140873
Committed: https://git.openstack.org/cgit/openstack/tempest/commit/?id=ab667960ef337538cf777bb0f325cb5d0e865d76
Submitter: Jenkins
Branch: master

commit ab667960ef337538cf777bb0f325cb5d0e865d76
Author: Mitsuhiro Tanino <email address hidden>
Date: Wed Dec 10 15:52:08 2014 -0500

    Actually attach a volume to an instance before taking snapshot

    In the test test_snapshot_create_with_volume_in_use, the test calls Cinder
    "os-attach" for attaching a volume. The "os-attach" to tell Cinder the
    volume is attached, but the API doesn't actually attach the volume to an
    instance.(Only update volume status in DB)

    This is not right test case for taking a snapshot with in-use volume.
    In this test, Nova "os-volume_attachment" should be called for volume
    attachment.

    Also, some Cinder drivers fails assisted snapshot due to this problem.
    In order to perform the snapshot properly, this fix is needed.

    Closes-Bug #1401110
    Change-Id: Ib31e351fe7c3d27824241cf142c213eae287483f

[Davanum Srinivas (DIMS) (dims-v)]

Looks like this was fixed in tempest