OpenStack Compute (nova)

No volume Block Device Mapping in assisted snapshot with Quobyte

Bug #1700583 reported by Silvan Kaiser
6
This bug affects 1 person
Affects Status Importance Assigned to Milestone
OpenStack Compute (nova)
Invalid
Undecided
Unassigned
devstack
Invalid
Undecided
Unassigned

Bug Description

*Update*: Please see comment #5 for details on how DevStack is involved in this issue.
Also more current CI runs with this issue can be found at:
- http://78.46.57.153:8081/refs-changes-95-490195-1/
- http://78.46.57.153:8081/refs-changes-21-490021-3/
*/Update*

Since roughly last friday Quobyte CIs with a Cinder / Nova setup fail with an error during assisted snapshots in four tests:
test_create_ebs_image_and_check_boot|test_snapshot_create_delete_with_volume_in_use|test_snapshot_create_offline_delete_online|test_volume_boot_pattern

The error declares that the volume to be snapshotted has no block device mapping.

I currently cannot identify if this is a Nova or Cinder issue, so please keep an open mind when looking into this.

Complete example CI test runs with all logs can be found at e.g.:

http://78.46.57.153:8081/refs-changes-26-475226-3/
http://78.46.57.153:8081/refs-changes-02-476402-2/

n-api log excerpt:
[...]
2017-06-23 14:24:18.137 10730 DEBUG nova.api.openstack.wsgi [req-484e4bd2-e091-4411-9252-38549f7c9dbd admin admin] Action: 'create', calling method: <bound method AssistedVolumeSnapshotsController.create of <nova.api.openstack.compute.assisted_volume_snapshots.AssistedVolumeSnapshotsController object at 0x7fdd470e8fd0>>, body: {"snapshot": {"create_info": {"snapshot_id": "30bd2ad6-37a0-4027-a24e-00657adb0cca", "type": "qcow2", "new_file": "volume-43245219-bd54-4b03-a371-cca5836e58e5.30bd2ad6-37a0-4027-a24e-00657adb0cca"}, "volume_id": "43245219-bd54-4b03-a371-cca5836e58e5"}} _process_stack /opt/stack/nova/nova/api/openstack/wsgi.py:609
2017-06-23 14:24:18.438 10730 INFO nova.api.openstack.wsgi [req-484e4bd2-e091-4411-9252-38549f7c9dbd admin admin] HTTP exception thrown: No volume Block Device Mapping with id 43245219-bd54-4b03-a371-cca5836e58e5.: HTTPBadRequest: No volume Block Device Mapping with id 43245219-bd54-4b03-a371-cca5836e58e5.
2017-06-23 14:24:18.440 10730 DEBUG nova.api.openstack.wsgi [req-484e4bd2-e091-4411-9252-38549f7c9dbd admin admin] Returning 400 to user: No volume Block Device Mapping with id 43245219-bd54-4b03-a371-cca5836e58e5. __call__ /opt/stack/nova/nova/api/openstack/wsgi.py:1029
2017-06-23 14:24:18.441 10730 INFO nova.osapi_compute.wsgi.server [req-484e4bd2-e091-4411-9252-38549f7c9dbd admin admin] 127.0.0.1 "POST /v2.1/os-assisted-volume-snapshots HTTP/1.1" status: 400 len: 543 time: 0.6530399
2017-06-23 14:24:18.770 10730 INFO nova.osapi_compute.wsgi.server [req-a0c161b6-12ba-4dbf-aa10-5fa34565441c tempest-TestVolumeBootPattern-1485741991 tempest-TestVolumeBootPattern-1485741991] 127.0.0.1 "GET /v2.1/servers/0fcae274-2d09-45e7-ba84-df2b53526895 HTTP/1.1" status: 200 len: 1762 time: 0.8687029
[...]

Reading the test logs I see for instance that this error is thrown right after the volume attachment
to the VM is successful. I'd expect the snapshot API call to be able to find the mapping in that case. Example snippet:

 [... attaching volume to VM]

    2017-06-26 13:13:43,182 28633 INFO [tempest.lib.common.rest_client] Request (VolumesSnapshotTestJSON:test_snapshot_create_offline_delete_online): 200 GET http://127.0.0.1:8776/v2/182a9178e3334660ad978457a2aecc9d/volumes/df77bf3f-8602-4f28-a999-f4c73a3e9097 0.223s
    2017-06-26 13:13:43,182 28633 DEBUG [tempest.lib.common.rest_client] Request - Headers: {'Content-Type': 'application/json', 'Accept': 'application/json', 'X-Auth-Token': '<omitted>'}
            Body: None
        Response - Headers: {u'content-type': 'application/json', 'content-location': 'http://127.0.0.1:8776/v2/182a9178e3334660ad978457a2aecc9d/volumes/df77bf3f-8602-4f28-a999-f4c73a3e9097', u'x-compute-request-id': 'req-fc80f9a0-dd4c-4e9d-b044-39007bbcdbae', u'connection': 'close', 'status': '200', u'content-length': '904', u'x-openstack-request-id': 'req-fc80f9a0-dd4c-4e9d-b044-39007bbcdbae', u'date': 'Mon, 26 Jun 2017
 13:13:43 GMT'}
            Body: {"volume": {"status": "attaching", "user_id": "8fa70618b61e4290908a964b6c8d11d9", "attachments": [], "links": [{"href": "http://127.0.0.1:8776/v2/182a9178e3334660ad978457a2aecc9d/volumes/df77bf3f-8602-4f28-a999-f4c73a3e9097", "rel": "self"}, {"href": "http://127.0.0.1:8776/182a9178e3334660ad978457a2aecc9d/volumes/df77bf3f-8602-4f28-a999-f4c73a3e9097", "rel": "bookmark"}], "availability_zone": "nova", "bootable": "false", "encrypted": false, "created_at": "2017-06-26T13:13:29.000000", "description": null, "os-vol-tenant-attr:tenant_id": "182a9178e3334660ad978457a2aecc9d", "updated_at": "2017-06-26T13:13:41.000000", "volume_type": "Quobyte", "name": "tempest-VolumesSnapshotTestJSON-Volume-1014042071", "replication_status": null, "consistencygroup_id": null, "source_volid": null, "snapshot_id": null, "multiattach": false, "metadata": {}, "id": "df77bf3f-8602-4f28-a999-f4c73a3e9097", "size": 1}}
    2017-06-26 13:13:44,333 28633 INFO [tempest.lib.common.rest_client] Request (VolumesSnapshotTestJSON:test_snapshot_create_offline_delete_online): 200 GET http://127.0.0.1:8776/v2/182a9178e3334660ad978457a2aecc9d/volumes/df77bf3f-8602-4f28-a999-f4c73a3e9097 0.148s
    2017-06-26 13:13:44,346 28633 DEBUG [tempest.lib.common.rest_client] Request - Headers: {'Content-Type': 'application/json', 'Accept': 'application/json', 'X-Auth-Token': '<omitted>'} Body: None Response - Headers: {u'content-type': 'application/json', 'content-location': 'http://127.0.0.1:8776/v2/182a9178e3334660ad978457a2aecc9d/volumes/df77bf3f-8602-4f28-a999-f4c73a3e9097', u'x-compute-request-id': 'req-abc6354c-5edb-488e-9c07-e53012afe6ea', u'connection': 'close', 'status': '200', u'content-length': '904', u'x-openstack-request-id': 'req-abc6354c-5edb-488e-9c07-e53012afe6ea', u'date': 'Mon, 26 Jun 2017 13:13:44 GMT'} Body: {"volume": {"status": "attaching", "user_id": "8fa70618b61e4290908a964b6c8d11d9", "attachments": [], "links": [{"href": "http://127.0.0.1:8776/v2/182a9178e3334660ad978457a2aecc9d/volumes/df77bf3f-8602-4f28-a999-f4c73a3e9097", "rel": "self"}, {"href": "http://127.0.0.1:8776/182a9178e3334660ad978457a2aecc9d/volumes/df77bf3f-8602-4f28-a999-f4c73a3e9097", "rel": "bookmark"}], "availability_zone": "nova", "bootable": "false", "encrypted": false, "created_at": "2017-06-26T13:13:29.000000", "description": null, "os-vol-tenant-attr:tenant_id": "182a9178e3334660ad978457a2aecc9d", "updated_at": "2017-06-26T13:13:41.000000", "volume_type": "Quobyte", "name": "tempest-VolumesSnapshotTestJSON-Volume-1014042071", "replication_status": null, "consistencygroup_id": null, "source_volid": null, "snapshot_id": null, "multiattach": false, "metadata": {}, "id": "df77bf3f-8602-4f28-a999-f4c73a3e9097", "size": 1}}
    2017-06-26 13:13:45,462 28633 INFO [tempest.lib.common.rest_client] Request (VolumesSnapshotTestJSON:test_snapshot_create_offline_delete_online): 200 GET http://127.0.0.1:8776/v2/182a9178e3334660ad978457a2aecc9d/volumes/df77bf3f-8602-4f28-a999-f4c73a3e9097 0.114s

[Attach done, volume ist listed as existing attachement to VM.]

    2017-06-26 13:13:45,462 28633 DEBUG [tempest.lib.common.rest_client] Request - Headers: {'Content-Type': 'application/json', 'Accept': 'application/json', 'X-Auth-Token': '<omitted>'} Body: None Response - Headers: {u'content-type': 'application/json', 'content-location': 'http://127.0.0.1:8776/v2/182a9178e3334660ad978457a2aecc9d/volumes/df77bf3f-8602-4f28-a999-f4c73a3e9097', u'x-compute-request-id': 'req-188ae214-1572-4c50-96da-4fba9797a924', u'connection': 'close', 'status': '200', u'content-length': '1238', u'x-openstack-request-id': 'req-188ae214-1572-4c50-96da-4fba9797a924', u'date': 'Mon, 26 Jun 2017 13:13:45 GMT'} Body: {"volume": {"status": "in-use", "user_id": "8fa70618b61e4290908a964b6c8d11d9", "attachments": [{"server_id": "97e84961-87c8-4672-8e72-3f8e652d5d0e", "attachment_id": "1b172300-aa07-4764-a75f-aac567695133", "attached_at": "2017-06-26T13:13:45.000000", "host_name": null, "volume_id": "df77bf3f-8602-4f28-a999-f4c73a3e9097", "device": "/dev/vdb", "id": "df77bf3f-8602-4f28-a999-f4c73a3e9097"}], "links": [{"href": "http://127.0.0.1:8776/v2/182a9178e3334660ad978457a2aecc9d/volumes/df77bf3f-8602-4f28-a999-f4c73a3e9097", "rel": "self"}, {"href": "http://127.0.0.1:8776/182a9178e3334660ad978457a2aecc9d/volumes/df77bf3f-8602-4f28-a999-f4c73a3e9097", "rel": "bookmark"}], "availability_zone": "nova", "bootable": "false", "encrypted": false, "created_at": "2017-06-26T13:13:29.000000", "description": null, "os-vol-tenant-attr:tenant_id": "182a9178e3334660ad978457a2aecc9d", "updated_at": "2017-06-26T13:13:45.000000", "volume_type": "Quobyte", "name": "tempest-VolumesSnapshotTestJSON-Volume-1014042071", "replication_status": null, "consistencygroup_id": null, "source_volid": null, "snapshot_id": null, "multiattach": false, "metadata": {"readonly": "False", "attached_mode": "rw"}, "id": "df77bf3f-8602-4f28-a999-f4c73a3e9097", "size": 1}}

[Trigger snapshot #2 from tempest test (while volume is attached to VM). At first the new snapshot is in 'creating' status.]

    2017-06-26 13:13:46,065 28633 INFO [tempest.lib.common.rest_client] Request (VolumesSnapshotTestJSON:test_snapshot_create_offline_delete_online): 202 POST http://127.0.0.1:8776/v2/182a9178e3334660ad978457a2aecc9d/snapshots 0.603s
    2017-06-26 13:13:46,066 28633 DEBUG [tempest.lib.common.rest_client] Request - Headers: {'Content-Type': 'application/json', 'Accept': 'application/json', 'X-Auth-Token': '<omitted>'}
            Body: {"snapshot": {"force": true, "name": "tempest-VolumesSnapshotTestJSON-Snapshot-661967408", "volume_id": "df77bf3f-8602-4f28-a999-f4c73a3e9097"}}
        Response - Headers: {u'content-type': 'application/json', 'content-location': 'http://127.0.0.1:8776/v2/182a9178e3334660ad978457a2aecc9d/snapshots', u'x-compute-request-id': 'req-876cadf4-170f-42c3-87f1-a2956e6452bf', u'connection': 'close', 'status': '202', u'content-length': '309', u'x-openstack-request-id': 'req-876cadf4-170f-42c3-87f1-a2956e6452bf', u'date': 'Mon, 26 Jun 2017 13:13:46 GMT'}
            Body: {"snapshot": {"status": "creating", "size": 1, "metadata": {}, "name": "tempest-VolumesSnapshotTestJSON-Snapshot-661967408", "volume_id": "df77bf3f-8602-4f28-a999-f4c73a3e9097", "created_at": "2017-06-26T13:13:45.770696", "description": null, "id": "e6b01eec-4618-49ee-af96-d3776e881bb9", "updated_at": null}}
    2017-06-26 13:13:46,146 28633 INFO [tempest.lib.common.rest_client] Request (VolumesSnapshotTestJSON:test_snapshot_create_offline_delete_online): 200 GET http://127.0.0.1:8776/v2/182a9178e3334660ad978457a2aecc9d/snapshots/e6b01eec-4618-49ee-af96-d3776e881bb9 0.079s
    2017-06-26 13:13:46,146 28633 DEBUG [tempest.lib.common.rest_client] Request - Headers: {'Content-Type': 'application/json', 'Accept': 'application/json', 'X-Auth-Token': '<omitted>'} Body: None Response - Headers: {u'content-type': 'application/json', 'content-location': 'http://127.0.0.1:8776/v2/182a9178e3334660ad978457a2aecc9d/snapshots/e6b01eec-4618-49ee-af96-d3776e881bb9', u'x-compute-request-id': 'req-9aee4d62-5344-4818-887a-f2b661b792e6', u'connection': 'close', 'status': '200', u'content-length': '441', u'x-openstack-request-id': 'req-9aee4d62-5344-4818-887a-f2b661b792e6', u'date': 'Mon, 26 Jun 2017 13:13:46 GMT'} Body: {"snapshot": {"status": "creating", "description": null, "updated_at": null, "volume_id": "df77bf3f-8602-4f28-a999-f4c73a3e9097", "id": "e6b01eec-4618-49ee-af96-d3776e881bb9", "size": 1, "os-extended-snapshot-attributes:progress": "0%", "name": "tempest-VolumesSnapshotTestJSON-Snapshot-661967408", "os-extended-snapshot-attributes:project_id": "182a9178e3334660ad978457a2aecc9d", "created_at": "2017-06-26T13:13:46.000000", "metadata": {}}}
    2017-06-26 13:13:47,199 28633 INFO [tempest.lib.common.rest_client] Request (VolumesSnapshotTestJSON:test_snapshot_create_offline_delete_online): 200 GET http://127.0.0.1:8776/v2/182a9178e3334660ad978457a2aecc9d/snapshots/e6b01eec-4618-49ee-af96-d3776e881bb9 0.052s

[Snapshot status changes from 'creating' to 'error']

    2017-06-26 13:13:47,199 28633 DEBUG [tempest.lib.common.rest_client] Request - Headers: {'Content-Type': 'application/json', 'Accept': 'application/json', 'X-Auth-Token': '<omitted>'} Body: None Response - Headers: {u'content-type': 'application/json', 'content-location': 'http://127.0.0.1:8776/v2/182a9178e3334660ad978457a2aecc9d/snapshots/e6b01eec-4618-49ee-af96-d3776e881bb9', u'x-compute-request-id': 'req-6ad9b5c9-019a-4f73-83b9-dbbd6befafa5', u'connection': 'close', 'status': '200', u'content-length': '462', u'x-openstack-request-id': 'req-6ad9b5c9-019a-4f73-83b9-dbbd6befafa5', u'date': 'Mon, 26 Jun 2017 13:13:47 GMT'} Body: {"snapshot": {"status": "error", "description": null, "updated_at": "2017-06-26T13:13:47.000000", "volume_id": "df77bf3f-8602-4f28-a999-f4c73a3e9097", "id": "e6b01eec-4618-49ee-af96-d3776e881bb9", "size": 1, "os-extended-snapshot-attributes:progress": "0%", "name": "tempest-VolumesSnapshotTestJSON-Snapshot-661967408", "os-extended-snapshot-attributes:project_id": "182a9178e3334660ad978457a2aecc9d", "created_at": "2017-06-26T13:13:46.000000", "metadata": {}}}
    2017-06-26 13:13:47,569 28633 INFO [tempest.lib.common.rest_client] Request (VolumesSnapshotTestJSON:_run_cleanups): 202 DELETE http://127.0.0.1:8774/v2.1/servers/97e84961-87c8-4672-8e72-3f8e652d5d0e/os-volume_attachments/df77bf3f-8602-4f28-a999-f4c73a3e9097 0.368s
    2017-06-26 13:13:47,570 28633 DEBUG [tempest.lib.common.rest_client] Request - Headers: {'Content-Type': 'application/json', 'Accept': 'application/json', 'X-Auth-Token': '<omitted>'} Body: None Response - Headers: {u'content-type': 'application/json', u'x-openstack-nova-api-version': '2.1', u'vary': 'X-OpenStack-Nova-API-Version', 'content-location': 'http://127.0.0.1:8774/v2.1/servers/97e84961-87c8-4672-8e72-3f8e652d5d0e/os-volume_attachments/df77bf3f-8602-4f28-a999-f4c73a3e9097', u'openstack-api-version': 'compute 2.1', u'content-length': '0', u'connection': 'close', 'status': '202', u'x-compute-request-id': 'req-bad4db4f-cc78-40ff-a792-e99fb915e54a', u'x-openstack-request-id': 'req-bad4db4f-cc78-40ff-a792-e99fb915e54a', u'date': 'Mon, 26 Jun 2017 13:13:47 GMT'}
            Body:
    2017-06-26 13:13:47,821 28633 INFO [tempest.lib.common.rest_client] Request (VolumesSnapshotTestJSON:_run_cleanups): 200 GET http://127.0.0.1:8776/v2/182a9178e3334660ad978457a2aecc9d/volumes/df77bf3f-8602-4f28-a999-f4c73a3e9097 0.248s
    2017-06-26 13:13:47,822 28633 DEBUG [tempest.lib.common.rest_client] Request - Headers: {'Content-Type': 'application/json', 'Accept': 'application/json', 'X-Auth-Token': '<omitted>'} Body: None

See original description
Revision history for this message
Silvan Kaiser (2-silvan) wrote :

Since ~14hours ago CI checks are passing again. I still haven't identified the core of this issue but possibly it's not related to Cinder/Nova but the test environment. This might point at DevStack/Tempest. I'm running more tests on older changes but with current test env in order to verify. Will report here afterwards...

Revision history for this message
Silvan Kaiser (2-silvan) wrote :

Verified builds are working again, even on old and previously failing changes. This means the issue was somewhere in the DevStack/tempest/... env and was solved yesterday by somebody. :)

Changed in nova:
status: New → Invalid
Revision history for this message
Silvan Kaiser (2-silvan) wrote :

This issue is back hitting our Cinder and Nova CIs. I'm digging for more information and will post updates here.

Changed in nova:
status: Invalid → New
Revision history for this message
Silvan Kaiser (2-silvan) wrote :

The following four tests are failing:

tempest.api.volume.test_volumes_snapshots.VolumesSnapshotTestJSON.test_snapshot_create_delete_with_volume_in_use
tempest.api.volume.test_volumes_snapshots.VolumesSnapshotTestJSON.test_snapshot_create_offline_delete_online
tempest.scenario.test_volume_boot_pattern.TestVolumeBootPattern.test_create_ebs_image_and_check_boot
tempest.scenario.test_volume_boot_pattern.TestVolumeBootPattern.test_volume_boot_pattern

Revision history for this message
Silvan Kaiser (2-silvan) wrote :

Ok, some more insights:
- i can workaround this issue by pinning the CIs DevStack version to commit 0d9c896 . Using the following commit f3d5331 shows the issues described above. So this seems to be a DevStack related issue
- So far i could not determine why this is caused but the affecting change relates to Matts Email note on openstack-dev: http://lists.openstack.org/pipermail/openstack-dev/2017-July/120120.html

So, maybe this is only a DevStack config issue with my setup or this might be a code issue in Nova. Help for debugging this is appreciated.

description: updated
Revision history for this message
Sylvain Bauza (sylvain-bauza) wrote :

Putting in Opinion as I'm not sure it's a Nova problem.
Silvan, if you need some help for debugging, just ask in our IRC channel if you want.

Changed in nova:
status: New → Opinion
Revision history for this message
Silvan Kaiser (2-silvan) wrote :

@Sylvain: Unfortunately I'm heading off for vacation right now but I'll come back to this when i'm back. For now the workaround works ok for the CI systems.

Revision history for this message
Silvan Kaiser (2-silvan) wrote :

Whatever the exact reason was it no longer occurs. I'm currently back to run our CIs with the current DevStack master and no longer hit this, therefore marking as invalid.

Changed in devstack:
status: New → Invalid
Changed in nova:
status: Opinion → Invalid
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.