yahoo-eng-team team mailing list archive

Thread
Date
[Bug 1706329] [NEW] Using CLI to attach a volume to a VM returns successful even if the operation did not work

To: yahoo-eng-team@xxxxxxxxxxxxxxxxxxx
From: Andrei Varvara <1706329@xxxxxxxxxxxxxxxxxx>
Date: Tue, 25 Jul 2017 12:19:37 -0000
Reply-to: Bug 1706329 <1706329@xxxxxxxxxxxxxxxxxx>
Sender: bounces@xxxxxxxxxxxxx
Public bug reported:

# Steps to reproduce

 os server add volume anva_uefi1 anva_vol1 --debug

# Actual result

On controll node:

GET call to volumev2 for http://10.0.2.41:8776/v2/6fdcef20a48148a7bbd1d86795390793/volumes/anva_vol1 used request id req-4138a4fb-f87f-4517-98dd-08859d57179a
REQ: curl -g -i -X GET http://10.0.2.41:8776/v2/6fdcef20a48148a7bbd1d86795390793/volumes/detail?all_tenants=1&name=anva_vol1 -H "User-Agent: python-cinderclient" -H "Accept: application/json" -H "X-Auth-Token: {SHA1}cdb953ff3c66041c65f0e212092d454a483e3720"
Resetting dropped connection: 10.0.2.41
"GET /v2/6fdcef20a48148a7bbd1d86795390793/volumes/detail?all_tenants=1&name=anva_vol1 HTTP/1.1" 200 1036
RESP: [200] X-Compute-Request-Id: req-464bf622-de2d-4ffb-b1f1-be103f1cd50b Content-Type: application/json Content-Length: 1036 X-Openstack-Request-Id: req-464bf622-de2d-4ffb-b1f1-be103f1cd50b Date: Tue, 25 Jul 2017 12:15:47 GMT Connection: close
RESP BODY: {"volumes": [{"migration_status": null, "attachments": [], "links": [{"href": "http://10.0.2.41:8776/v2/6fdcef20a48148a7bbd1d86795390793/volumes/d3d7f5db-9839-4893-866d-b006bc11f900";, "rel": "self"}, {"href": "http://10.0.2.41:8776/6fdcef20a48148a7bbd1d86795390793/volumes/d3d7f5db-9839-4893-866d-b006bc11f900";, "rel": "bookmark"}], "availability_zone": "nova", "os-vol-host-attr:host": "rbd:volumes@RBD-backend#RBD-backend", "encrypted": false, "updated_at": "2017-07-20T15:42:21.000000", "replication_status": "disabled", "snapshot_id": null, "id": "d3d7f5db-9839-4893-866d-b006bc11f900", "size": 1, "user_id": "35019cf5041448bead1626209650450c", "os-vol-tenant-attr:tenant_id": "6fdcef20a48148a7bbd1d86795390793", "os-vol-mig-status-attr:migstat": null, "metadata": {}, "status": "available", "description": "", "multiattach": false, "source_volid": null, "consistencygroup_id": null, "os-vol-mig-status-attr:name_id": null, "name": "anva_vol1", "bootable": "false", "created_at": "2017-07-20T15:34:31.000000", "volume_type": null}]}

GET call to volumev2 for http://10.0.2.41:8776/v2/6fdcef20a48148a7bbd1d86795390793/volumes/detail?all_tenants=1&name=anva_vol1 used request id req-464bf622-de2d-4ffb-b1f1-be103f1cd50b
REQ: curl -g -i -X POST http://10.0.2.41:8774/v2.1/servers/9a00359f-fb75-4d9f-866d-9d5ec3500d35/os-volume_attachments -H "User-Agent: python-novaclient" -H "Content-Type: application/json" -H "Accept: application/json" -H "X-Auth-Token: {SHA1}cdb953ff3c66041c65f0e212092d454a483e3720" -d '{"volumeAttachment": {"volumeId": "d3d7f5db-9839-4893-866d-b006bc11f900"}}'
Resetting dropped connection: 10.0.2.41
"POST /v2.1/servers/9a00359f-fb75-4d9f-866d-9d5ec3500d35/os-volume_attachments HTTP/1.1" 200 194
RESP: [200] Content-Length: 194 Content-Type: application/json Openstack-Api-Version: compute 2.1 X-Openstack-Nova-Api-Version: 2.1 Vary: OpenStack-API-Version, X-OpenStack-Nova-API-Version X-Compute-Request-Id: req-4441abb8-be74-43de-b341-fc0897f40697 Date: Tue, 25 Jul 2017 12:15:48 GMT Connection: close
RESP BODY: {"volumeAttachment": {"device": "/dev/vdd", "serverId": "9a00359f-fb75-4d9f-866d-9d5ec3500d35", "id": "d3d7f5db-9839-4893-866d-b006bc11f900", "volumeId": "d3d7f5db-9839-4893-866d-b006bc11f900"}}

POST call to compute for http://10.0.2.41:8774/v2.1/servers/9a00359f-fb75-4d9f-866d-9d5ec3500d35/os-volume_attachments used request id req-4441abb8-be74-43de-b341-fc0897f40697
clean_up AddServerVolume:
END return value: 0

On compute node:

2017-07-25 12:15:39.399 14381 WARNING stevedore.named [req-74dc60be-f607-461e-9ce0-8e4ef3f84162 - - - - -] Could not load instance_network_info
2017-07-25 12:15:48.245 14381 INFO nova.compute.manager [req-4441abb8-be74-43de-b341-fc0897f40697 35019cf5041448bead1626209650450c 6fdcef20a48148a7bbd1d86795390793 - - -] [instance: 9a00359f-fb75-4d9f-866d-9d5ec3500d35] Attaching volume d3d7f5db-9839-4893-866d-b006bc11f900 to /dev/vdd
2017-07-25 12:15:49.385 14381 ERROR nova.virt.libvirt.driver [req-4441abb8-be74-43de-b341-fc0897f40697 35019cf5041448bead1626209650450c 6fdcef20a48148a7bbd1d86795390793 - - -] [instance: 9a00359f-fb75-4d9f-866d-9d5ec3500d35] Failed to attach volume at mountpoint: /dev/vdd
2017-07-25 12:15:49.385 14381 ERROR nova.virt.libvirt.driver [instance: 9a00359f-fb75-4d9f-866d-9d5ec3500d35] Traceback (most recent call last):
2017-07-25 12:15:49.385 14381 ERROR nova.virt.libvirt.driver [instance: 9a00359f-fb75-4d9f-866d-9d5ec3500d35]   File "/usr/lib/python2.7/dist-packages/nova/virt/libvirt/driver.py", line 1175, in attach_volume
2017-07-25 12:15:49.385 14381 ERROR nova.virt.libvirt.driver [instance: 9a00359f-fb75-4d9f-866d-9d5ec3500d35]     guest.attach_device(conf, persistent=True, live=live)
2017-07-25 12:15:49.385 14381 ERROR nova.virt.libvirt.driver [instance: 9a00359f-fb75-4d9f-866d-9d5ec3500d35]   File "/usr/lib/python2.7/dist-packages/nova/virt/libvirt/guest.py", line 296, in attach_device
2017-07-25 12:15:49.385 14381 ERROR nova.virt.libvirt.driver [instance: 9a00359f-fb75-4d9f-866d-9d5ec3500d35]     self._domain.attachDeviceFlags(device_xml, flags=flags)
2017-07-25 12:15:49.385 14381 ERROR nova.virt.libvirt.driver [instance: 9a00359f-fb75-4d9f-866d-9d5ec3500d35]   File "/usr/lib/python2.7/dist-packages/eventlet/tpool.py", line 186, in doit
2017-07-25 12:15:49.385 14381 ERROR nova.virt.libvirt.driver [instance: 9a00359f-fb75-4d9f-866d-9d5ec3500d35]     result = proxy_call(self._autowrap, f, *args, **kwargs)
2017-07-25 12:15:49.385 14381 ERROR nova.virt.libvirt.driver [instance: 9a00359f-fb75-4d9f-866d-9d5ec3500d35]   File "/usr/lib/python2.7/dist-packages/eventlet/tpool.py", line 144, in proxy_call
2017-07-25 12:15:49.385 14381 ERROR nova.virt.libvirt.driver [instance: 9a00359f-fb75-4d9f-866d-9d5ec3500d35]     rv = execute(f, *args, **kwargs)
2017-07-25 12:15:49.385 14381 ERROR nova.virt.libvirt.driver [instance: 9a00359f-fb75-4d9f-866d-9d5ec3500d35]   File "/usr/lib/python2.7/dist-packages/eventlet/tpool.py", line 125, in execute
2017-07-25 12:15:49.385 14381 ERROR nova.virt.libvirt.driver [instance: 9a00359f-fb75-4d9f-866d-9d5ec3500d35]     six.reraise(c, e, tb)
2017-07-25 12:15:49.385 14381 ERROR nova.virt.libvirt.driver [instance: 9a00359f-fb75-4d9f-866d-9d5ec3500d35]   File "/usr/lib/python2.7/dist-packages/eventlet/tpool.py", line 83, in tworker
2017-07-25 12:15:49.385 14381 ERROR nova.virt.libvirt.driver [instance: 9a00359f-fb75-4d9f-866d-9d5ec3500d35]     rv = meth(*args, **kwargs)
2017-07-25 12:15:49.385 14381 ERROR nova.virt.libvirt.driver [instance: 9a00359f-fb75-4d9f-866d-9d5ec3500d35]   File "/usr/lib/python2.7/dist-packages/libvirt.py", line 560, in attachDeviceFlags
2017-07-25 12:15:49.385 14381 ERROR nova.virt.libvirt.driver [instance: 9a00359f-fb75-4d9f-866d-9d5ec3500d35]     if ret == -1: raise libvirtError ('virDomainAttachDeviceFlags() failed', dom=self)
2017-07-25 12:15:49.385 14381 ERROR nova.virt.libvirt.driver [instance: 9a00359f-fb75-4d9f-866d-9d5ec3500d35] libvirtError: internal error: unable to execute QEMU command 'device_add': Bus 'pci.2' does not support hotplugging

I look in the code and saw this:

By implementation the code for attaching a volume to a VM does not wait 
to get a respons if the attaching was succeful or not. The user of the CLI
gets the device node on which the volume was attached even if the operation
of attaching did not succeed.
/nova/compute/api.py code _attach_volume calls
self.compute_rpcapi.attach_volume(context, instance, volume_bdm) which by implementation does cctxt.cast(ctxt, 'attach_volume', instance=instance, bdm=bdm). Because of using the
cast mechanism it will not wait for a reply from the Compute node where the actual work is
done, so it will never know if the attachment was succeful, and will inform the CLI user
with the expected succeful yaml, according to the Openstack Compute API.
RESP BODY: {"volumeAttachment": {"device": "/dev/vdc", "serverId": "04ab7b2d-daf5-4ef7-9266-e90777d5a377", "id": "6589aaef-7d9d-45d5-af0a-a6cdbaca1a7a", "volumeId": "6589aaef-7d9d-45d5-af0a-a6cdbaca1a7a"}}

Proposal:

To use a call instead of a cast and return to the CLI user the right
answer, according to what actually happened on the compute node. The
downside of this would be that it blocks the console where the CLI
command was issued for the time it takes to actually attach the volume
on the compute node.

Question: 
Why a cast is prefered against a call? Did you too in account to use a call and decided that a better way is with cast,
and let the user know the device where would be attached the volume if successful?

Many thanks,
Andrei Varvara

** Affects: nova
     Importance: Undecided
         Status: New

-- 
You received this bug notification because you are a member of Yahoo!
Engineering Team, which is subscribed to OpenStack Compute (nova).
https://bugs.launchpad.net/bugs/1706329

Title:
  Using CLI to attach a volume to a VM returns successful even if the
  operation did not work

Status in OpenStack Compute (nova):
  New

Bug description:
  # Steps to reproduce

   os server add volume anva_uefi1 anva_vol1 --debug

  # Actual result

  On controll node:

  GET call to volumev2 for http://10.0.2.41:8776/v2/6fdcef20a48148a7bbd1d86795390793/volumes/anva_vol1 used request id req-4138a4fb-f87f-4517-98dd-08859d57179a
  REQ: curl -g -i -X GET http://10.0.2.41:8776/v2/6fdcef20a48148a7bbd1d86795390793/volumes/detail?all_tenants=1&name=anva_vol1 -H "User-Agent: python-cinderclient" -H "Accept: application/json" -H "X-Auth-Token: {SHA1}cdb953ff3c66041c65f0e212092d454a483e3720"
  Resetting dropped connection: 10.0.2.41
  "GET /v2/6fdcef20a48148a7bbd1d86795390793/volumes/detail?all_tenants=1&name=anva_vol1 HTTP/1.1" 200 1036
  RESP: [200] X-Compute-Request-Id: req-464bf622-de2d-4ffb-b1f1-be103f1cd50b Content-Type: application/json Content-Length: 1036 X-Openstack-Request-Id: req-464bf622-de2d-4ffb-b1f1-be103f1cd50b Date: Tue, 25 Jul 2017 12:15:47 GMT Connection: close
  RESP BODY: {"volumes": [{"migration_status": null, "attachments": [], "links": [{"href": "http://10.0.2.41:8776/v2/6fdcef20a48148a7bbd1d86795390793/volumes/d3d7f5db-9839-4893-866d-b006bc11f900";, "rel": "self"}, {"href": "http://10.0.2.41:8776/6fdcef20a48148a7bbd1d86795390793/volumes/d3d7f5db-9839-4893-866d-b006bc11f900";, "rel": "bookmark"}], "availability_zone": "nova", "os-vol-host-attr:host": "rbd:volumes@RBD-backend#RBD-backend", "encrypted": false, "updated_at": "2017-07-20T15:42:21.000000", "replication_status": "disabled", "snapshot_id": null, "id": "d3d7f5db-9839-4893-866d-b006bc11f900", "size": 1, "user_id": "35019cf5041448bead1626209650450c", "os-vol-tenant-attr:tenant_id": "6fdcef20a48148a7bbd1d86795390793", "os-vol-mig-status-attr:migstat": null, "metadata": {}, "status": "available", "description": "", "multiattach": false, "source_volid": null, "consistencygroup_id": null, "os-vol-mig-status-attr:name_id": null, "name": "anva_vol1", "bootable": "false", "created_at": "2017-07-20T15:34:31.000000", "volume_type": null}]}

  GET call to volumev2 for http://10.0.2.41:8776/v2/6fdcef20a48148a7bbd1d86795390793/volumes/detail?all_tenants=1&name=anva_vol1 used request id req-464bf622-de2d-4ffb-b1f1-be103f1cd50b
  REQ: curl -g -i -X POST http://10.0.2.41:8774/v2.1/servers/9a00359f-fb75-4d9f-866d-9d5ec3500d35/os-volume_attachments -H "User-Agent: python-novaclient" -H "Content-Type: application/json" -H "Accept: application/json" -H "X-Auth-Token: {SHA1}cdb953ff3c66041c65f0e212092d454a483e3720" -d '{"volumeAttachment": {"volumeId": "d3d7f5db-9839-4893-866d-b006bc11f900"}}'
  Resetting dropped connection: 10.0.2.41
  "POST /v2.1/servers/9a00359f-fb75-4d9f-866d-9d5ec3500d35/os-volume_attachments HTTP/1.1" 200 194
  RESP: [200] Content-Length: 194 Content-Type: application/json Openstack-Api-Version: compute 2.1 X-Openstack-Nova-Api-Version: 2.1 Vary: OpenStack-API-Version, X-OpenStack-Nova-API-Version X-Compute-Request-Id: req-4441abb8-be74-43de-b341-fc0897f40697 Date: Tue, 25 Jul 2017 12:15:48 GMT Connection: close
  RESP BODY: {"volumeAttachment": {"device": "/dev/vdd", "serverId": "9a00359f-fb75-4d9f-866d-9d5ec3500d35", "id": "d3d7f5db-9839-4893-866d-b006bc11f900", "volumeId": "d3d7f5db-9839-4893-866d-b006bc11f900"}}

  POST call to compute for http://10.0.2.41:8774/v2.1/servers/9a00359f-fb75-4d9f-866d-9d5ec3500d35/os-volume_attachments used request id req-4441abb8-be74-43de-b341-fc0897f40697
  clean_up AddServerVolume:
  END return value: 0

  On compute node:

  2017-07-25 12:15:39.399 14381 WARNING stevedore.named [req-74dc60be-f607-461e-9ce0-8e4ef3f84162 - - - - -] Could not load instance_network_info
  2017-07-25 12:15:48.245 14381 INFO nova.compute.manager [req-4441abb8-be74-43de-b341-fc0897f40697 35019cf5041448bead1626209650450c 6fdcef20a48148a7bbd1d86795390793 - - -] [instance: 9a00359f-fb75-4d9f-866d-9d5ec3500d35] Attaching volume d3d7f5db-9839-4893-866d-b006bc11f900 to /dev/vdd
  2017-07-25 12:15:49.385 14381 ERROR nova.virt.libvirt.driver [req-4441abb8-be74-43de-b341-fc0897f40697 35019cf5041448bead1626209650450c 6fdcef20a48148a7bbd1d86795390793 - - -] [instance: 9a00359f-fb75-4d9f-866d-9d5ec3500d35] Failed to attach volume at mountpoint: /dev/vdd
  2017-07-25 12:15:49.385 14381 ERROR nova.virt.libvirt.driver [instance: 9a00359f-fb75-4d9f-866d-9d5ec3500d35] Traceback (most recent call last):
  2017-07-25 12:15:49.385 14381 ERROR nova.virt.libvirt.driver [instance: 9a00359f-fb75-4d9f-866d-9d5ec3500d35]   File "/usr/lib/python2.7/dist-packages/nova/virt/libvirt/driver.py", line 1175, in attach_volume
  2017-07-25 12:15:49.385 14381 ERROR nova.virt.libvirt.driver [instance: 9a00359f-fb75-4d9f-866d-9d5ec3500d35]     guest.attach_device(conf, persistent=True, live=live)
  2017-07-25 12:15:49.385 14381 ERROR nova.virt.libvirt.driver [instance: 9a00359f-fb75-4d9f-866d-9d5ec3500d35]   File "/usr/lib/python2.7/dist-packages/nova/virt/libvirt/guest.py", line 296, in attach_device
  2017-07-25 12:15:49.385 14381 ERROR nova.virt.libvirt.driver [instance: 9a00359f-fb75-4d9f-866d-9d5ec3500d35]     self._domain.attachDeviceFlags(device_xml, flags=flags)
  2017-07-25 12:15:49.385 14381 ERROR nova.virt.libvirt.driver [instance: 9a00359f-fb75-4d9f-866d-9d5ec3500d35]   File "/usr/lib/python2.7/dist-packages/eventlet/tpool.py", line 186, in doit
  2017-07-25 12:15:49.385 14381 ERROR nova.virt.libvirt.driver [instance: 9a00359f-fb75-4d9f-866d-9d5ec3500d35]     result = proxy_call(self._autowrap, f, *args, **kwargs)
  2017-07-25 12:15:49.385 14381 ERROR nova.virt.libvirt.driver [instance: 9a00359f-fb75-4d9f-866d-9d5ec3500d35]   File "/usr/lib/python2.7/dist-packages/eventlet/tpool.py", line 144, in proxy_call
  2017-07-25 12:15:49.385 14381 ERROR nova.virt.libvirt.driver [instance: 9a00359f-fb75-4d9f-866d-9d5ec3500d35]     rv = execute(f, *args, **kwargs)
  2017-07-25 12:15:49.385 14381 ERROR nova.virt.libvirt.driver [instance: 9a00359f-fb75-4d9f-866d-9d5ec3500d35]   File "/usr/lib/python2.7/dist-packages/eventlet/tpool.py", line 125, in execute
  2017-07-25 12:15:49.385 14381 ERROR nova.virt.libvirt.driver [instance: 9a00359f-fb75-4d9f-866d-9d5ec3500d35]     six.reraise(c, e, tb)
  2017-07-25 12:15:49.385 14381 ERROR nova.virt.libvirt.driver [instance: 9a00359f-fb75-4d9f-866d-9d5ec3500d35]   File "/usr/lib/python2.7/dist-packages/eventlet/tpool.py", line 83, in tworker
  2017-07-25 12:15:49.385 14381 ERROR nova.virt.libvirt.driver [instance: 9a00359f-fb75-4d9f-866d-9d5ec3500d35]     rv = meth(*args, **kwargs)
  2017-07-25 12:15:49.385 14381 ERROR nova.virt.libvirt.driver [instance: 9a00359f-fb75-4d9f-866d-9d5ec3500d35]   File "/usr/lib/python2.7/dist-packages/libvirt.py", line 560, in attachDeviceFlags
  2017-07-25 12:15:49.385 14381 ERROR nova.virt.libvirt.driver [instance: 9a00359f-fb75-4d9f-866d-9d5ec3500d35]     if ret == -1: raise libvirtError ('virDomainAttachDeviceFlags() failed', dom=self)
  2017-07-25 12:15:49.385 14381 ERROR nova.virt.libvirt.driver [instance: 9a00359f-fb75-4d9f-866d-9d5ec3500d35] libvirtError: internal error: unable to execute QEMU command 'device_add': Bus 'pci.2' does not support hotplugging

  I look in the code and saw this:

  By implementation the code for attaching a volume to a VM does not wait 
  to get a respons if the attaching was succeful or not. The user of the CLI
  gets the device node on which the volume was attached even if the operation
  of attaching did not succeed.
  /nova/compute/api.py code _attach_volume calls
  self.compute_rpcapi.attach_volume(context, instance, volume_bdm) which by implementation does cctxt.cast(ctxt, 'attach_volume', instance=instance, bdm=bdm). Because of using the
  cast mechanism it will not wait for a reply from the Compute node where the actual work is
  done, so it will never know if the attachment was succeful, and will inform the CLI user
  with the expected succeful yaml, according to the Openstack Compute API.
  RESP BODY: {"volumeAttachment": {"device": "/dev/vdc", "serverId": "04ab7b2d-daf5-4ef7-9266-e90777d5a377", "id": "6589aaef-7d9d-45d5-af0a-a6cdbaca1a7a", "volumeId": "6589aaef-7d9d-45d5-af0a-a6cdbaca1a7a"}}

  Proposal:

  To use a call instead of a cast and return to the CLI user the right
  answer, according to what actually happened on the compute node. The
  downside of this would be that it blocks the console where the CLI
  command was issued for the time it takes to actually attach the volume
  on the compute node.

  Question: 
  Why a cast is prefered against a call? Did you too in account to use a call and decided that a better way is with cast,
  and let the user know the device where would be attached the volume if successful?

  Many thanks,
  Andrei Varvara

To manage notifications about this bug go to:
https://bugs.launchpad.net/nova/+bug/1706329/+subscriptions
Follow ups

[Bug 1706329] Re: Using CLI to attach a volume to a VM returns successful even if the operation did not work
From: Sean Dague, 2017-07-25