yahoo-eng-team team mailing list archive

Thread
Date
[Bug 1515672] [NEW] Openstack cinder and XenServer attach second volume failed

To: yahoo-eng-team@xxxxxxxxxxxxxxxxxxx
From: Sergey <snasonov@xxxxxx>
Date: Thu, 12 Nov 2015 15:56:00 -0000
Reply-to: Bug 1515672 <1515672@xxxxxxxxxxxxxxxxxx>
Sender: bounces@xxxxxxxxxxxxx
Public bug reported:

1. Openstack  kilo version nova-compute 2015.1.1-1.el7

logs from nova-compute after attaching second volume to xenserver host:

2015-11-12 18:36:42.614 996 DEBUG oslo_concurrency.lockutils [req-42ee1d90-2e83-41d3-aaec-3f928170b60d cb348d90ade04049b30e2d41a985e2d4 596095f4da8b4eddbfbbe1774e762bf4 - - -] Lock "901b2692-e337-4358-80df-8408ce626352" acquired by "do_attach_volume" :: waited 0.000s inner /usr/lib/python2.7/site-packages/oslo_concurrency/lockutils.py:444
2015-11-12 18:36:42.615 996 INFO nova.compute.manager [req-42ee1d90-2e83-41d3-aaec-3f928170b60d cb348d90ade04049b30e2d41a985e2d4 596095f4da8b4eddbfbbe1774e762bf4 - - -] [instance: 901b2692-e337-4358-80df-8408ce626352] Attaching volume a7ce4570-e35b-4db8-9502-8c33e790280a to /dev/xvdc
2015-11-12 18:36:42.616 996 DEBUG keystoneclient.session [req-42ee1d90-2e83-41d3-aaec-3f928170b60d cb348d90ade04049b30e2d41a985e2d4 596095f4da8b4eddbfbbe1774e762bf4 - - -] REQ: curl -g -i -X GET http://cinder:8776/v2/596095f4da8b4eddbfbbe1774e762bf4/volumes/a7ce4570-e35b-4db8-9502-8c33e790280a -H "User-Agent: python-cinderclient" -H "Accept: application/json" -H "X-Auth-Token: {SHA1}a3783c05f22bbd142afdbf7dfdc6bef77588687a" _http_log_request /usr/lib/python2.7/site-packages/keystoneclient/session.py:195
2015-11-12 18:36:42.787 996 DEBUG keystoneclient.session [req-42ee1d90-2e83-41d3-aaec-3f928170b60d cb348d90ade04049b30e2d41a985e2d4 596095f4da8b4eddbfbbe1774e762bf4 - - -] RESP: [200] content-length: 931 x-compute-request-id: req-9cc1ca80-d8db-49fe-b99e-97a0f667bd04 connection: keep-alive date: Thu, 12 Nov 2015 15:36:42 GMT content-type: application/json x-openstack-request-id: req-9cc1ca80-d8db-49fe-b99e-97a0f667bd04 
RESP BODY: {"volume": {"attachments": [], "links": [{"href": "http://cinder:8776/v2/596095f4da8b4eddbfbbe1774e762bf4/volumes/a7ce4570-e35b-4db8-9502-8c33e790280a";, "rel": "self"}, {"href": "http://cinder:8776/596095f4da8b4eddbfbbe1774e762bf4/volumes/a7ce4570-e35b-4db8-9502-8c33e790280a";, "rel": "bookmark"}], "availability_zone": "xen-test", "encrypted": false, "os-volume-replication:extended_status": null, "volume_type": null, "snapshot_id": null, "id": "a7ce4570-e35b-4db8-9502-8c33e790280a", "size": 10, "user_id": "cb348d90ade04049b30e2d41a985e2d4", "os-vol-tenant-attr:tenant_id": "596095f4da8b4eddbfbbe1774e762bf4", "metadata": {"readonly": "False"}, "status": "attaching", "description": null, "multiattach": false, "source_volid": null, "consistencygroup_id": null, "name": "test_tyryry", "bootable": "false", "created_at": "2015-11-11T14:31:46.000000", "os-volume-replication:driver_data": null, "replication_status": "disabled"}}
 _http_log_response /usr/lib/python2.7/site-packages/keystoneclient/session.py:224
2015-11-12 18:36:42.788 996 DEBUG keystoneclient.session [req-42ee1d90-2e83-41d3-aaec-3f928170b60d cb348d90ade04049b30e2d41a985e2d4 596095f4da8b4eddbfbbe1774e762bf4 - - -] REQ: curl -g -i -X POST http://cinder:8776/v2/596095f4da8b4eddbfbbe1774e762bf4/volumes/a7ce4570-e35b-4db8-9502-8c33e790280a/action -H "User-Agent: python-cinderclient" -H "Content-Type: application/json" -H "Accept: application/json" -H "X-Auth-Token: {SHA1}a3783c05f22bbd142afdbf7dfdc6bef77588687a" -d '{"os-initialize_connection": {"connector": {"ip": "xen-r0304.openstack.local", "initiator": "iqn.2015-06.com.example:5d183874", "host": "xen-r0304.openstack.local"}}}' _http_log_request /usr/lib/python2.7/site-packages/keystoneclient/session.py:195
2015-11-12 18:36:44.312 996 DEBUG keystoneclient.session [req-42ee1d90-2e83-41d3-aaec-3f928170b60d cb348d90ade04049b30e2d41a985e2d4 596095f4da8b4eddbfbbe1774e762bf4 - - -] RESP: [200] content-length: 305 x-compute-request-id: req-88108cb4-5fdb-44fd-b681-9f9c31f46355 connection: keep-alive date: Thu, 12 Nov 2015 15:36:44 GMT content-type: application/json x-openstack-request-id: req-88108cb4-5fdb-44fd-b681-9f9c31f46355 
RESP BODY: {"connection_info": {"driver_volume_type": "iscsi", "data": {"qos_specs": null, "target_iqn": "iqn.1986-03.com.ibm:2145.storwizev7000-mh.node1", "target_discovered": false, "volume_id": "a7ce4570-e35b-4db8-9502-8c33e790280a", "target_lun": 1, "access_mode": "rw", "target_portal": "172.30.133.125:3260"}}}
 _http_log_response /usr/lib/python2.7/site-packages/keystoneclient/session.py:224
2015-11-12 18:36:44.318 996 DEBUG nova.virt.xenapi.volume_utils [req-42ee1d90-2e83-41d3-aaec-3f928170b60d cb348d90ade04049b30e2d41a985e2d4 596095f4da8b4eddbfbbe1774e762bf4 - - -] (vol_id,host,port,iqn): (a7ce4570-e35b-4db8-9502-8c33e790280a,172.30.133.125,3260,iqn.1986-03.com.ibm:2145.storwizev7000-mh.node1) _parse_volume_info /usr/lib/python2.7/site-packages/nova/virt/xenapi/volume_utils.py:80
2015-11-12 18:36:44.324 996 DEBUG nova.virt.xenapi.volume_utils [req-42ee1d90-2e83-41d3-aaec-3f928170b60d cb348d90ade04049b30e2d41a985e2d4 596095f4da8b4eddbfbbe1774e762bf4 - - -] Introducing SR tempSR-a7ce4570-e35b-4db8-9502-8c33e790280a introduce_sr /usr/lib/python2.7/site-packages/nova/virt/xenapi/volume_utils.py:119
2015-11-12 18:36:44.336 996 DEBUG nova.virt.xenapi.volume_utils [req-42ee1d90-2e83-41d3-aaec-3f928170b60d cb348d90ade04049b30e2d41a985e2d4 596095f4da8b4eddbfbbe1774e762bf4 - - -] Creating PBD for SR introduce_sr /usr/lib/python2.7/site-packages/nova/virt/xenapi/volume_utils.py:129
2015-11-12 18:36:44.359 996 DEBUG nova.virt.xenapi.volume_utils [req-42ee1d90-2e83-41d3-aaec-3f928170b60d cb348d90ade04049b30e2d41a985e2d4 596095f4da8b4eddbfbbe1774e762bf4 - - -] Plugging SR introduce_sr /usr/lib/python2.7/site-packages/nova/virt/xenapi/volume_utils.py:132
2015-11-12 18:36:50.250 996 ERROR nova.virt.block_device [req-42ee1d90-2e83-41d3-aaec-3f928170b60d cb348d90ade04049b30e2d41a985e2d4 596095f4da8b4eddbfbbe1774e762bf4 - - -] [instance: 901b2692-e337-4358-80df-8408ce626352] Driver failed to attach volume a7ce4570-e35b-4db8-9502-8c33e790280a at /dev/xvdc
2015-11-12 18:36:50.250 996 TRACE nova.virt.block_device [instance: 901b2692-e337-4358-80df-8408ce626352] Traceback (most recent call last):
2015-11-12 18:36:50.250 996 TRACE nova.virt.block_device [instance: 901b2692-e337-4358-80df-8408ce626352]   File "/usr/lib/python2.7/site-packages/nova/virt/block_device.py", line 253, in attach
2015-11-12 18:36:50.250 996 TRACE nova.virt.block_device [instance: 901b2692-e337-4358-80df-8408ce626352]     device_type=self['device_type'], encryption=encryption)
2015-11-12 18:36:50.250 996 TRACE nova.virt.block_device [instance: 901b2692-e337-4358-80df-8408ce626352]   File "/usr/lib/python2.7/site-packages/nova/virt/xenapi/driver.py", line 410, in attach_volume
2015-11-12 18:36:50.250 996 TRACE nova.virt.block_device [instance: 901b2692-e337-4358-80df-8408ce626352]     mountpoint)
2015-11-12 18:36:50.250 996 TRACE nova.virt.block_device [instance: 901b2692-e337-4358-80df-8408ce626352]   File "/usr/lib/python2.7/site-packages/nova/virt/xenapi/volumeops.py", line 46, in attach_volume
2015-11-12 18:36:50.250 996 TRACE nova.virt.block_device [instance: 901b2692-e337-4358-80df-8408ce626352]     instance_name, dev_number, hotplug)
2015-11-12 18:36:50.250 996 TRACE nova.virt.block_device [instance: 901b2692-e337-4358-80df-8408ce626352]   File "/usr/lib/python2.7/site-packages/nova/virt/xenapi/volumeops.py", line 59, in _attach_volume
2015-11-12 18:36:50.250 996 TRACE nova.virt.block_device [instance: 901b2692-e337-4358-80df-8408ce626352]     instance_name)
2015-11-12 18:36:50.250 996 TRACE nova.virt.block_device [instance: 901b2692-e337-4358-80df-8408ce626352]   File "/usr/lib/python2.7/site-packages/nova/virt/xenapi/volumeops.py", line 90, in _connect_to_volume_provider
2015-11-12 18:36:50.250 996 TRACE nova.virt.block_device [instance: 901b2692-e337-4358-80df-8408ce626352]     self._session, sr_uuid, sr_label, sr_params)
2015-11-12 18:36:50.250 996 TRACE nova.virt.block_device [instance: 901b2692-e337-4358-80df-8408ce626352]   File "/usr/lib/python2.7/site-packages/nova/virt/xenapi/volume_utils.py", line 135, in introduce_sr
2015-11-12 18:36:50.250 996 TRACE nova.virt.block_device [instance: 901b2692-e337-4358-80df-8408ce626352]     session.call_xenapi("SR.scan", sr_ref)
2015-11-12 18:36:50.250 996 TRACE nova.virt.block_device [instance: 901b2692-e337-4358-80df-8408ce626352]   File "/usr/lib/python2.7/site-packages/nova/virt/xenapi/client/session.py", line 196, in call_xenapi
2015-11-12 18:36:50.250 996 TRACE nova.virt.block_device [instance: 901b2692-e337-4358-80df-8408ce626352]     return session.xenapi_request(method, args)
2015-11-12 18:36:50.250 996 TRACE nova.virt.block_device [instance: 901b2692-e337-4358-80df-8408ce626352]   File "/usr/lib/python2.7/site-packages/XenAPI.py", line 133, in xenapi_request
2015-11-12 18:36:50.250 996 TRACE nova.virt.block_device [instance: 901b2692-e337-4358-80df-8408ce626352]     result = _parse_result(getattr(self, methodname)(*full_params))
2015-11-12 18:36:50.250 996 TRACE nova.virt.block_device [instance: 901b2692-e337-4358-80df-8408ce626352]   File "/usr/lib/python2.7/site-packages/XenAPI.py", line 203, in _parse_result
2015-11-12 18:36:50.250 996 TRACE nova.virt.block_device [instance: 901b2692-e337-4358-80df-8408ce626352]     raise Failure(result['ErrorDescription'])
2015-11-12 18:36:50.250 996 TRACE nova.virt.block_device [instance: 901b2692-e337-4358-80df-8408ce626352] Failure: ['SR_BACKEND_FAILURE_40', '', 'The SR scan failed  [opterr=[\'INTERNAL_ERROR\', \'Db_exn.Uniqueness_constraint_violation("VDI", "uuid", "70b87c59-e01a-be46-6f43-d927e3871669")\']]', '']
2015-11-12 18:36:50.250 996 TRACE nova.virt.block_device [instance: 901b2692-e337-4358-80df-8408ce626352] 
2015-11-12 18:36:50.252 996 DEBUG keystoneclient.session [req-42ee1d90-2e83-41d3-aaec-3f928170b60d cb348d90ade04049b30e2d41a985e2d4 596095f4da8b4eddbfbbe1774e762bf4 - - -] REQ: curl -g -i -X POST http://cinder:8776/v2/596095f4da8b4eddbfbbe1774e762bf4/volumes/a7ce4570-e35b-4db8-9502-8c33e790280a/action -H "User-Agent: python-cinderclient" -H "Content-Type: application/json" -H "Accept: application/json" -H "X-Auth-Token: {SHA1}a3783c05f22bbd142afdbf7dfdc6bef77588687a" -d '{"os-terminate_connection": {"connector": {"ip": "xen-r0304.openstack.local", "initiator": "iqn.2015-06.com.example:5d183874", "host": "xen-r0304.openstack.local"}}}' _http_log_request /usr/lib/python2.7/site-packages/keystoneclient/session.py:195
2015-11-12 18:36:51.783 996 DEBUG keystoneclient.session [req-42ee1d90-2e83-41d3-aaec-3f928170b60d cb348d90ade04049b30e2d41a985e2d4 596095f4da8b4eddbfbbe1774e762bf4 - - -] RESP: [202] date: Thu, 12 Nov 2015 15:36:51 GMT connection: keep-alive content-type: text/html; charset=UTF-8 content-length: 0 x-openstack-request-id: req-3b57b55c-bc10-4eee-aac7-3283ecd9bd19 _http_log_response /usr/lib/python2.7/site-packages/keystoneclient/session.py:224
2015-11-12 18:36:51.831 996 ERROR nova.compute.manager [req-42ee1d90-2e83-41d3-aaec-3f928170b60d cb348d90ade04049b30e2d41a985e2d4 596095f4da8b4eddbfbbe1774e762bf4 - - -] [instance: 901b2692-e337-4358-80df-8408ce626352] Failed to attach a7ce4570-e35b-4db8-9502-8c33e790280a at /dev/xvdc
2015-11-12 18:36:51.831 996 TRACE nova.compute.manager [instance: 901b2692-e337-4358-80df-8408ce626352] Traceback (most recent call last):
2015-11-12 18:36:51.831 996 TRACE nova.compute.manager [instance: 901b2692-e337-4358-80df-8408ce626352]   File "/usr/lib/python2.7/site-packages/nova/compute/manager.py", line 4778, in _attach_volume
2015-11-12 18:36:51.831 996 TRACE nova.compute.manager [instance: 901b2692-e337-4358-80df-8408ce626352]     do_check_attach=False, do_driver_attach=True)
2015-11-12 18:36:51.831 996 TRACE nova.compute.manager [instance: 901b2692-e337-4358-80df-8408ce626352]   File "/usr/lib/python2.7/site-packages/nova/virt/block_device.py", line 49, in wrapped
2015-11-12 18:36:51.831 996 TRACE nova.compute.manager [instance: 901b2692-e337-4358-80df-8408ce626352]     ret_val = method(obj, context, *args, **kwargs)
2015-11-12 18:36:51.831 996 TRACE nova.compute.manager [instance: 901b2692-e337-4358-80df-8408ce626352]   File "/usr/lib/python2.7/site-packages/nova/virt/block_device.py", line 262, in attach
2015-11-12 18:36:51.831 996 TRACE nova.compute.manager [instance: 901b2692-e337-4358-80df-8408ce626352]     connector)
2015-11-12 18:36:51.831 996 TRACE nova.compute.manager [instance: 901b2692-e337-4358-80df-8408ce626352]   File "/usr/lib/python2.7/site-packages/oslo_utils/excutils.py", line 85, in __exit__
2015-11-12 18:36:51.831 996 TRACE nova.compute.manager [instance: 901b2692-e337-4358-80df-8408ce626352]     six.reraise(self.type_, self.value, self.tb)
2015-11-12 18:36:51.831 996 TRACE nova.compute.manager [instance: 901b2692-e337-4358-80df-8408ce626352]   File "/usr/lib/python2.7/site-packages/nova/virt/block_device.py", line 253, in attach
2015-11-12 18:36:51.831 996 TRACE nova.compute.manager [instance: 901b2692-e337-4358-80df-8408ce626352]     device_type=self['device_type'], encryption=encryption)
2015-11-12 18:36:51.831 996 TRACE nova.compute.manager [instance: 901b2692-e337-4358-80df-8408ce626352]   File "/usr/lib/python2.7/site-packages/nova/virt/xenapi/driver.py", line 410, in attach_volume
2015-11-12 18:36:51.831 996 TRACE nova.compute.manager [instance: 901b2692-e337-4358-80df-8408ce626352]     mountpoint)
2015-11-12 18:36:51.831 996 TRACE nova.compute.manager [instance: 901b2692-e337-4358-80df-8408ce626352]   File "/usr/lib/python2.7/site-packages/nova/virt/xenapi/volumeops.py", line 46, in attach_volume
2015-11-12 18:36:51.831 996 TRACE nova.compute.manager [instance: 901b2692-e337-4358-80df-8408ce626352]     instance_name, dev_number, hotplug)
2015-11-12 18:36:51.831 996 TRACE nova.compute.manager [instance: 901b2692-e337-4358-80df-8408ce626352]   File "/usr/lib/python2.7/site-packages/nova/virt/xenapi/volumeops.py", line 59, in _attach_volume
2015-11-12 18:36:51.831 996 TRACE nova.compute.manager [instance: 901b2692-e337-4358-80df-8408ce626352]     instance_name)
2015-11-12 18:36:51.831 996 TRACE nova.compute.manager [instance: 901b2692-e337-4358-80df-8408ce626352]   File "/usr/lib/python2.7/site-packages/nova/virt/xenapi/volumeops.py", line 90, in _connect_to_volume_provider
2015-11-12 18:36:51.831 996 TRACE nova.compute.manager [instance: 901b2692-e337-4358-80df-8408ce626352]     self._session, sr_uuid, sr_label, sr_params)
2015-11-12 18:36:51.831 996 TRACE nova.compute.manager [instance: 901b2692-e337-4358-80df-8408ce626352]   File "/usr/lib/python2.7/site-packages/nova/virt/xenapi/volume_utils.py", line 135, in introduce_sr
2015-11-12 18:36:51.831 996 TRACE nova.compute.manager [instance: 901b2692-e337-4358-80df-8408ce626352]     session.call_xenapi("SR.scan", sr_ref)
2015-11-12 18:36:51.831 996 TRACE nova.compute.manager [instance: 901b2692-e337-4358-80df-8408ce626352]   File "/usr/lib/python2.7/site-packages/nova/virt/xenapi/client/session.py", line 196, in call_xenapi
2015-11-12 18:36:51.831 996 TRACE nova.compute.manager [instance: 901b2692-e337-4358-80df-8408ce626352]     return session.xenapi_request(method, args)
2015-11-12 18:36:51.831 996 TRACE nova.compute.manager [instance: 901b2692-e337-4358-80df-8408ce626352]   File "/usr/lib/python2.7/site-packages/XenAPI.py", line 133, in xenapi_request
2015-11-12 18:36:51.831 996 TRACE nova.compute.manager [instance: 901b2692-e337-4358-80df-8408ce626352]     result = _parse_result(getattr(self, methodname)(*full_params))
2015-11-12 18:36:51.831 996 TRACE nova.compute.manager [instance: 901b2692-e337-4358-80df-8408ce626352]   File "/usr/lib/python2.7/site-packages/XenAPI.py", line 203, in _parse_result
2015-11-12 18:36:51.831 996 TRACE nova.compute.manager [instance: 901b2692-e337-4358-80df-8408ce626352]     raise Failure(result['ErrorDescription'])
2015-11-12 18:36:51.831 996 TRACE nova.compute.manager [instance: 901b2692-e337-4358-80df-8408ce626352] Failure: ['SR_BACKEND_FAILURE_40', '', 'The SR scan failed  [opterr=[\'INTERNAL_ERROR\', \'Db_exn.Uniqueness_constraint_violation("VDI", "uuid", "70b87c59-e01a-be46-6f43-d927e3871669")\']]', '']
2015-11-12 18:36:51.831 996 TRACE nova.compute.manager [instance: 901b2692-e337-4358-80df-8408ce626352]

3. Reproduce step

1. create first cinder volume on storage array. (cinder create)
2. attach that volume to instance VM reside on xenserver host (first volume attached ok). (nova volume-attach)
3. create second cinder volume on storage array.
4. attach second cinder volume to instance VM on the same xenserver host as in step 2.
5. attach second volume failed 

Expected result:

Second volume attached ok and gets available to VM instance

** 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/1515672

Title:
  Openstack cinder and XenServer attach second volume failed

Status in OpenStack Compute (nova):
  New

Bug description:
  1. Openstack  kilo version nova-compute 2015.1.1-1.el7

  logs from nova-compute after attaching second volume to xenserver
  host:

  2015-11-12 18:36:42.614 996 DEBUG oslo_concurrency.lockutils [req-42ee1d90-2e83-41d3-aaec-3f928170b60d cb348d90ade04049b30e2d41a985e2d4 596095f4da8b4eddbfbbe1774e762bf4 - - -] Lock "901b2692-e337-4358-80df-8408ce626352" acquired by "do_attach_volume" :: waited 0.000s inner /usr/lib/python2.7/site-packages/oslo_concurrency/lockutils.py:444
  2015-11-12 18:36:42.615 996 INFO nova.compute.manager [req-42ee1d90-2e83-41d3-aaec-3f928170b60d cb348d90ade04049b30e2d41a985e2d4 596095f4da8b4eddbfbbe1774e762bf4 - - -] [instance: 901b2692-e337-4358-80df-8408ce626352] Attaching volume a7ce4570-e35b-4db8-9502-8c33e790280a to /dev/xvdc
  2015-11-12 18:36:42.616 996 DEBUG keystoneclient.session [req-42ee1d90-2e83-41d3-aaec-3f928170b60d cb348d90ade04049b30e2d41a985e2d4 596095f4da8b4eddbfbbe1774e762bf4 - - -] REQ: curl -g -i -X GET http://cinder:8776/v2/596095f4da8b4eddbfbbe1774e762bf4/volumes/a7ce4570-e35b-4db8-9502-8c33e790280a -H "User-Agent: python-cinderclient" -H "Accept: application/json" -H "X-Auth-Token: {SHA1}a3783c05f22bbd142afdbf7dfdc6bef77588687a" _http_log_request /usr/lib/python2.7/site-packages/keystoneclient/session.py:195
  2015-11-12 18:36:42.787 996 DEBUG keystoneclient.session [req-42ee1d90-2e83-41d3-aaec-3f928170b60d cb348d90ade04049b30e2d41a985e2d4 596095f4da8b4eddbfbbe1774e762bf4 - - -] RESP: [200] content-length: 931 x-compute-request-id: req-9cc1ca80-d8db-49fe-b99e-97a0f667bd04 connection: keep-alive date: Thu, 12 Nov 2015 15:36:42 GMT content-type: application/json x-openstack-request-id: req-9cc1ca80-d8db-49fe-b99e-97a0f667bd04 
  RESP BODY: {"volume": {"attachments": [], "links": [{"href": "http://cinder:8776/v2/596095f4da8b4eddbfbbe1774e762bf4/volumes/a7ce4570-e35b-4db8-9502-8c33e790280a";, "rel": "self"}, {"href": "http://cinder:8776/596095f4da8b4eddbfbbe1774e762bf4/volumes/a7ce4570-e35b-4db8-9502-8c33e790280a";, "rel": "bookmark"}], "availability_zone": "xen-test", "encrypted": false, "os-volume-replication:extended_status": null, "volume_type": null, "snapshot_id": null, "id": "a7ce4570-e35b-4db8-9502-8c33e790280a", "size": 10, "user_id": "cb348d90ade04049b30e2d41a985e2d4", "os-vol-tenant-attr:tenant_id": "596095f4da8b4eddbfbbe1774e762bf4", "metadata": {"readonly": "False"}, "status": "attaching", "description": null, "multiattach": false, "source_volid": null, "consistencygroup_id": null, "name": "test_tyryry", "bootable": "false", "created_at": "2015-11-11T14:31:46.000000", "os-volume-replication:driver_data": null, "replication_status": "disabled"}}
   _http_log_response /usr/lib/python2.7/site-packages/keystoneclient/session.py:224
  2015-11-12 18:36:42.788 996 DEBUG keystoneclient.session [req-42ee1d90-2e83-41d3-aaec-3f928170b60d cb348d90ade04049b30e2d41a985e2d4 596095f4da8b4eddbfbbe1774e762bf4 - - -] REQ: curl -g -i -X POST http://cinder:8776/v2/596095f4da8b4eddbfbbe1774e762bf4/volumes/a7ce4570-e35b-4db8-9502-8c33e790280a/action -H "User-Agent: python-cinderclient" -H "Content-Type: application/json" -H "Accept: application/json" -H "X-Auth-Token: {SHA1}a3783c05f22bbd142afdbf7dfdc6bef77588687a" -d '{"os-initialize_connection": {"connector": {"ip": "xen-r0304.openstack.local", "initiator": "iqn.2015-06.com.example:5d183874", "host": "xen-r0304.openstack.local"}}}' _http_log_request /usr/lib/python2.7/site-packages/keystoneclient/session.py:195
  2015-11-12 18:36:44.312 996 DEBUG keystoneclient.session [req-42ee1d90-2e83-41d3-aaec-3f928170b60d cb348d90ade04049b30e2d41a985e2d4 596095f4da8b4eddbfbbe1774e762bf4 - - -] RESP: [200] content-length: 305 x-compute-request-id: req-88108cb4-5fdb-44fd-b681-9f9c31f46355 connection: keep-alive date: Thu, 12 Nov 2015 15:36:44 GMT content-type: application/json x-openstack-request-id: req-88108cb4-5fdb-44fd-b681-9f9c31f46355 
  RESP BODY: {"connection_info": {"driver_volume_type": "iscsi", "data": {"qos_specs": null, "target_iqn": "iqn.1986-03.com.ibm:2145.storwizev7000-mh.node1", "target_discovered": false, "volume_id": "a7ce4570-e35b-4db8-9502-8c33e790280a", "target_lun": 1, "access_mode": "rw", "target_portal": "172.30.133.125:3260"}}}
   _http_log_response /usr/lib/python2.7/site-packages/keystoneclient/session.py:224
  2015-11-12 18:36:44.318 996 DEBUG nova.virt.xenapi.volume_utils [req-42ee1d90-2e83-41d3-aaec-3f928170b60d cb348d90ade04049b30e2d41a985e2d4 596095f4da8b4eddbfbbe1774e762bf4 - - -] (vol_id,host,port,iqn): (a7ce4570-e35b-4db8-9502-8c33e790280a,172.30.133.125,3260,iqn.1986-03.com.ibm:2145.storwizev7000-mh.node1) _parse_volume_info /usr/lib/python2.7/site-packages/nova/virt/xenapi/volume_utils.py:80
  2015-11-12 18:36:44.324 996 DEBUG nova.virt.xenapi.volume_utils [req-42ee1d90-2e83-41d3-aaec-3f928170b60d cb348d90ade04049b30e2d41a985e2d4 596095f4da8b4eddbfbbe1774e762bf4 - - -] Introducing SR tempSR-a7ce4570-e35b-4db8-9502-8c33e790280a introduce_sr /usr/lib/python2.7/site-packages/nova/virt/xenapi/volume_utils.py:119
  2015-11-12 18:36:44.336 996 DEBUG nova.virt.xenapi.volume_utils [req-42ee1d90-2e83-41d3-aaec-3f928170b60d cb348d90ade04049b30e2d41a985e2d4 596095f4da8b4eddbfbbe1774e762bf4 - - -] Creating PBD for SR introduce_sr /usr/lib/python2.7/site-packages/nova/virt/xenapi/volume_utils.py:129
  2015-11-12 18:36:44.359 996 DEBUG nova.virt.xenapi.volume_utils [req-42ee1d90-2e83-41d3-aaec-3f928170b60d cb348d90ade04049b30e2d41a985e2d4 596095f4da8b4eddbfbbe1774e762bf4 - - -] Plugging SR introduce_sr /usr/lib/python2.7/site-packages/nova/virt/xenapi/volume_utils.py:132
  2015-11-12 18:36:50.250 996 ERROR nova.virt.block_device [req-42ee1d90-2e83-41d3-aaec-3f928170b60d cb348d90ade04049b30e2d41a985e2d4 596095f4da8b4eddbfbbe1774e762bf4 - - -] [instance: 901b2692-e337-4358-80df-8408ce626352] Driver failed to attach volume a7ce4570-e35b-4db8-9502-8c33e790280a at /dev/xvdc
  2015-11-12 18:36:50.250 996 TRACE nova.virt.block_device [instance: 901b2692-e337-4358-80df-8408ce626352] Traceback (most recent call last):
  2015-11-12 18:36:50.250 996 TRACE nova.virt.block_device [instance: 901b2692-e337-4358-80df-8408ce626352]   File "/usr/lib/python2.7/site-packages/nova/virt/block_device.py", line 253, in attach
  2015-11-12 18:36:50.250 996 TRACE nova.virt.block_device [instance: 901b2692-e337-4358-80df-8408ce626352]     device_type=self['device_type'], encryption=encryption)
  2015-11-12 18:36:50.250 996 TRACE nova.virt.block_device [instance: 901b2692-e337-4358-80df-8408ce626352]   File "/usr/lib/python2.7/site-packages/nova/virt/xenapi/driver.py", line 410, in attach_volume
  2015-11-12 18:36:50.250 996 TRACE nova.virt.block_device [instance: 901b2692-e337-4358-80df-8408ce626352]     mountpoint)
  2015-11-12 18:36:50.250 996 TRACE nova.virt.block_device [instance: 901b2692-e337-4358-80df-8408ce626352]   File "/usr/lib/python2.7/site-packages/nova/virt/xenapi/volumeops.py", line 46, in attach_volume
  2015-11-12 18:36:50.250 996 TRACE nova.virt.block_device [instance: 901b2692-e337-4358-80df-8408ce626352]     instance_name, dev_number, hotplug)
  2015-11-12 18:36:50.250 996 TRACE nova.virt.block_device [instance: 901b2692-e337-4358-80df-8408ce626352]   File "/usr/lib/python2.7/site-packages/nova/virt/xenapi/volumeops.py", line 59, in _attach_volume
  2015-11-12 18:36:50.250 996 TRACE nova.virt.block_device [instance: 901b2692-e337-4358-80df-8408ce626352]     instance_name)
  2015-11-12 18:36:50.250 996 TRACE nova.virt.block_device [instance: 901b2692-e337-4358-80df-8408ce626352]   File "/usr/lib/python2.7/site-packages/nova/virt/xenapi/volumeops.py", line 90, in _connect_to_volume_provider
  2015-11-12 18:36:50.250 996 TRACE nova.virt.block_device [instance: 901b2692-e337-4358-80df-8408ce626352]     self._session, sr_uuid, sr_label, sr_params)
  2015-11-12 18:36:50.250 996 TRACE nova.virt.block_device [instance: 901b2692-e337-4358-80df-8408ce626352]   File "/usr/lib/python2.7/site-packages/nova/virt/xenapi/volume_utils.py", line 135, in introduce_sr
  2015-11-12 18:36:50.250 996 TRACE nova.virt.block_device [instance: 901b2692-e337-4358-80df-8408ce626352]     session.call_xenapi("SR.scan", sr_ref)
  2015-11-12 18:36:50.250 996 TRACE nova.virt.block_device [instance: 901b2692-e337-4358-80df-8408ce626352]   File "/usr/lib/python2.7/site-packages/nova/virt/xenapi/client/session.py", line 196, in call_xenapi
  2015-11-12 18:36:50.250 996 TRACE nova.virt.block_device [instance: 901b2692-e337-4358-80df-8408ce626352]     return session.xenapi_request(method, args)
  2015-11-12 18:36:50.250 996 TRACE nova.virt.block_device [instance: 901b2692-e337-4358-80df-8408ce626352]   File "/usr/lib/python2.7/site-packages/XenAPI.py", line 133, in xenapi_request
  2015-11-12 18:36:50.250 996 TRACE nova.virt.block_device [instance: 901b2692-e337-4358-80df-8408ce626352]     result = _parse_result(getattr(self, methodname)(*full_params))
  2015-11-12 18:36:50.250 996 TRACE nova.virt.block_device [instance: 901b2692-e337-4358-80df-8408ce626352]   File "/usr/lib/python2.7/site-packages/XenAPI.py", line 203, in _parse_result
  2015-11-12 18:36:50.250 996 TRACE nova.virt.block_device [instance: 901b2692-e337-4358-80df-8408ce626352]     raise Failure(result['ErrorDescription'])
  2015-11-12 18:36:50.250 996 TRACE nova.virt.block_device [instance: 901b2692-e337-4358-80df-8408ce626352] Failure: ['SR_BACKEND_FAILURE_40', '', 'The SR scan failed  [opterr=[\'INTERNAL_ERROR\', \'Db_exn.Uniqueness_constraint_violation("VDI", "uuid", "70b87c59-e01a-be46-6f43-d927e3871669")\']]', '']
  2015-11-12 18:36:50.250 996 TRACE nova.virt.block_device [instance: 901b2692-e337-4358-80df-8408ce626352] 
  2015-11-12 18:36:50.252 996 DEBUG keystoneclient.session [req-42ee1d90-2e83-41d3-aaec-3f928170b60d cb348d90ade04049b30e2d41a985e2d4 596095f4da8b4eddbfbbe1774e762bf4 - - -] REQ: curl -g -i -X POST http://cinder:8776/v2/596095f4da8b4eddbfbbe1774e762bf4/volumes/a7ce4570-e35b-4db8-9502-8c33e790280a/action -H "User-Agent: python-cinderclient" -H "Content-Type: application/json" -H "Accept: application/json" -H "X-Auth-Token: {SHA1}a3783c05f22bbd142afdbf7dfdc6bef77588687a" -d '{"os-terminate_connection": {"connector": {"ip": "xen-r0304.openstack.local", "initiator": "iqn.2015-06.com.example:5d183874", "host": "xen-r0304.openstack.local"}}}' _http_log_request /usr/lib/python2.7/site-packages/keystoneclient/session.py:195
  2015-11-12 18:36:51.783 996 DEBUG keystoneclient.session [req-42ee1d90-2e83-41d3-aaec-3f928170b60d cb348d90ade04049b30e2d41a985e2d4 596095f4da8b4eddbfbbe1774e762bf4 - - -] RESP: [202] date: Thu, 12 Nov 2015 15:36:51 GMT connection: keep-alive content-type: text/html; charset=UTF-8 content-length: 0 x-openstack-request-id: req-3b57b55c-bc10-4eee-aac7-3283ecd9bd19 _http_log_response /usr/lib/python2.7/site-packages/keystoneclient/session.py:224
  2015-11-12 18:36:51.831 996 ERROR nova.compute.manager [req-42ee1d90-2e83-41d3-aaec-3f928170b60d cb348d90ade04049b30e2d41a985e2d4 596095f4da8b4eddbfbbe1774e762bf4 - - -] [instance: 901b2692-e337-4358-80df-8408ce626352] Failed to attach a7ce4570-e35b-4db8-9502-8c33e790280a at /dev/xvdc
  2015-11-12 18:36:51.831 996 TRACE nova.compute.manager [instance: 901b2692-e337-4358-80df-8408ce626352] Traceback (most recent call last):
  2015-11-12 18:36:51.831 996 TRACE nova.compute.manager [instance: 901b2692-e337-4358-80df-8408ce626352]   File "/usr/lib/python2.7/site-packages/nova/compute/manager.py", line 4778, in _attach_volume
  2015-11-12 18:36:51.831 996 TRACE nova.compute.manager [instance: 901b2692-e337-4358-80df-8408ce626352]     do_check_attach=False, do_driver_attach=True)
  2015-11-12 18:36:51.831 996 TRACE nova.compute.manager [instance: 901b2692-e337-4358-80df-8408ce626352]   File "/usr/lib/python2.7/site-packages/nova/virt/block_device.py", line 49, in wrapped
  2015-11-12 18:36:51.831 996 TRACE nova.compute.manager [instance: 901b2692-e337-4358-80df-8408ce626352]     ret_val = method(obj, context, *args, **kwargs)
  2015-11-12 18:36:51.831 996 TRACE nova.compute.manager [instance: 901b2692-e337-4358-80df-8408ce626352]   File "/usr/lib/python2.7/site-packages/nova/virt/block_device.py", line 262, in attach
  2015-11-12 18:36:51.831 996 TRACE nova.compute.manager [instance: 901b2692-e337-4358-80df-8408ce626352]     connector)
  2015-11-12 18:36:51.831 996 TRACE nova.compute.manager [instance: 901b2692-e337-4358-80df-8408ce626352]   File "/usr/lib/python2.7/site-packages/oslo_utils/excutils.py", line 85, in __exit__
  2015-11-12 18:36:51.831 996 TRACE nova.compute.manager [instance: 901b2692-e337-4358-80df-8408ce626352]     six.reraise(self.type_, self.value, self.tb)
  2015-11-12 18:36:51.831 996 TRACE nova.compute.manager [instance: 901b2692-e337-4358-80df-8408ce626352]   File "/usr/lib/python2.7/site-packages/nova/virt/block_device.py", line 253, in attach
  2015-11-12 18:36:51.831 996 TRACE nova.compute.manager [instance: 901b2692-e337-4358-80df-8408ce626352]     device_type=self['device_type'], encryption=encryption)
  2015-11-12 18:36:51.831 996 TRACE nova.compute.manager [instance: 901b2692-e337-4358-80df-8408ce626352]   File "/usr/lib/python2.7/site-packages/nova/virt/xenapi/driver.py", line 410, in attach_volume
  2015-11-12 18:36:51.831 996 TRACE nova.compute.manager [instance: 901b2692-e337-4358-80df-8408ce626352]     mountpoint)
  2015-11-12 18:36:51.831 996 TRACE nova.compute.manager [instance: 901b2692-e337-4358-80df-8408ce626352]   File "/usr/lib/python2.7/site-packages/nova/virt/xenapi/volumeops.py", line 46, in attach_volume
  2015-11-12 18:36:51.831 996 TRACE nova.compute.manager [instance: 901b2692-e337-4358-80df-8408ce626352]     instance_name, dev_number, hotplug)
  2015-11-12 18:36:51.831 996 TRACE nova.compute.manager [instance: 901b2692-e337-4358-80df-8408ce626352]   File "/usr/lib/python2.7/site-packages/nova/virt/xenapi/volumeops.py", line 59, in _attach_volume
  2015-11-12 18:36:51.831 996 TRACE nova.compute.manager [instance: 901b2692-e337-4358-80df-8408ce626352]     instance_name)
  2015-11-12 18:36:51.831 996 TRACE nova.compute.manager [instance: 901b2692-e337-4358-80df-8408ce626352]   File "/usr/lib/python2.7/site-packages/nova/virt/xenapi/volumeops.py", line 90, in _connect_to_volume_provider
  2015-11-12 18:36:51.831 996 TRACE nova.compute.manager [instance: 901b2692-e337-4358-80df-8408ce626352]     self._session, sr_uuid, sr_label, sr_params)
  2015-11-12 18:36:51.831 996 TRACE nova.compute.manager [instance: 901b2692-e337-4358-80df-8408ce626352]   File "/usr/lib/python2.7/site-packages/nova/virt/xenapi/volume_utils.py", line 135, in introduce_sr
  2015-11-12 18:36:51.831 996 TRACE nova.compute.manager [instance: 901b2692-e337-4358-80df-8408ce626352]     session.call_xenapi("SR.scan", sr_ref)
  2015-11-12 18:36:51.831 996 TRACE nova.compute.manager [instance: 901b2692-e337-4358-80df-8408ce626352]   File "/usr/lib/python2.7/site-packages/nova/virt/xenapi/client/session.py", line 196, in call_xenapi
  2015-11-12 18:36:51.831 996 TRACE nova.compute.manager [instance: 901b2692-e337-4358-80df-8408ce626352]     return session.xenapi_request(method, args)
  2015-11-12 18:36:51.831 996 TRACE nova.compute.manager [instance: 901b2692-e337-4358-80df-8408ce626352]   File "/usr/lib/python2.7/site-packages/XenAPI.py", line 133, in xenapi_request
  2015-11-12 18:36:51.831 996 TRACE nova.compute.manager [instance: 901b2692-e337-4358-80df-8408ce626352]     result = _parse_result(getattr(self, methodname)(*full_params))
  2015-11-12 18:36:51.831 996 TRACE nova.compute.manager [instance: 901b2692-e337-4358-80df-8408ce626352]   File "/usr/lib/python2.7/site-packages/XenAPI.py", line 203, in _parse_result
  2015-11-12 18:36:51.831 996 TRACE nova.compute.manager [instance: 901b2692-e337-4358-80df-8408ce626352]     raise Failure(result['ErrorDescription'])
  2015-11-12 18:36:51.831 996 TRACE nova.compute.manager [instance: 901b2692-e337-4358-80df-8408ce626352] Failure: ['SR_BACKEND_FAILURE_40', '', 'The SR scan failed  [opterr=[\'INTERNAL_ERROR\', \'Db_exn.Uniqueness_constraint_violation("VDI", "uuid", "70b87c59-e01a-be46-6f43-d927e3871669")\']]', '']
  2015-11-12 18:36:51.831 996 TRACE nova.compute.manager [instance: 901b2692-e337-4358-80df-8408ce626352]

  3. Reproduce step

  1. create first cinder volume on storage array. (cinder create)
  2. attach that volume to instance VM reside on xenserver host (first volume attached ok). (nova volume-attach)
  3. create second cinder volume on storage array.
  4. attach second cinder volume to instance VM on the same xenserver host as in step 2.
  5. attach second volume failed 

  Expected result:

  Second volume attached ok and gets available to VM instance

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

[Bug 1515672] Re: XenServer attach second Cinder volume failed
From: Sean Dague, 2017-06-16
[Bug 1515672] Re: XenServer attach second Cinder volume failed
From: Matt Riedemann, 2016-02-15
[Bug 1515672] Re: XenServer attach second Cinder volume failed
From: OpenStack Infra, 2016-01-09