On 4/25/2018 3:32 AM, Sreeram Vancheeswaran wrote:
Hi team!

We are currently facing  an issue in our out-of-tree driver nova-dpm [1] with nova and cinder on master, where instance launch in devstack is failing due to communication/time-out issues in nova-cinder.   We are unable to get to the root cause of the issue and we need your help on getting some hints/directions to debug this issue further.

--> From nova-compute service: BuildAbortException: Build of instance aborted: Unable to update the attachment. (HTTP 500) from the nova-compute server (detailed logs here [2]).

--> From cinder-volume service: ERROR oslo_messaging.rpc.server VolumeAttachmentNotFound: Volume attachment could not be found with filter: attachment_id = 266ef7e1-4735-40f1-b704-509472f565cb. Apr 25 06:42:47 zos057 cinder-volume[11475]: ERROR oslo_messaging.rpc.server  (detailed logs here [3])

Debugging steps done so far:-

  * Compared the package versions between the current devstack under
    test with the **last succeeding job in our CI system** (to be exact,
    it was for the patches https://review.openstack.org/#/c/458514/ and
    https://review.openstack.org/#/c/458820/); However the package
    versions for packages such as sqlalchemy, os-brick, oslo* are
    exactly the same in both the systems.
  * We used git bisect to revert nova and cinder projects to versions
    equal to or before the date of our last succeeding CI run; but still
    we were able to reproduce the same error.
  * Our guess is that the db "Save" operation during the update of
    volume attachment is failing.  But we are unable to trace/debug to
    that point in the rpc call;  Any suggestions on how to debug this
    sceario would be really helpful.
  * We are running devstack master on Ubuntu 16.04.04


References

[1] https://github.com/openstack/nova-dpm


[2] Apr 25 06:41:57 zos057 nova-compute[6190]: ERROR nova.volume.cinder [None req-751d4586-cd97-4a8f-9423-f2bc4b1f1269 service nova] Update attachment failed for attachment 266ef7e1-4735-40f1-b704-509472f565cb. Error: Unable to update the attachment. (HTTP 500) (Request-ID: req-550f6b9c-7f22-4dce-adbe-f6843e0aa3ce) Code: 500: ClientException: Unable to update the attachment. (HTTP 500) (Request-ID: req-550f6b9c-7f22-4dce-adbe-f6843e0aa3ce) Apr 25 06:41:57 zos057 nova-compute[6190]: ERROR nova.compute.manager [None req-751d4586-cd97-4a8f-9423-f2bc4b1f1269 service nova] [instance: d761da60-7bb1-415e-b5b9-eaaed124d6d2] Instance failed block device setup: ClientException: Unable to update the attachment. (HTTP 500) (Request-ID: req-550f6b9c-7f22-4dce-adbe-f6843e0aa3ce) Apr 25 06:41:57 zos057 nova-compute[6190]: ERROR nova.compute.manager [instance: d761da60-7bb1-415e-b5b9-eaaed124d6d2] Traceback (most recent call last): Apr 25 06:41:57 zos057 nova-compute[6190]: ERROR nova.compute.manager [instance: d761da60-7bb1-415e-b5b9-eaaed124d6d2]   File "/opt/stack/nova/nova/compute/manager.py", line 1577, in _prep_block_device Apr 25 06:41:57 zos057 nova-compute[6190]: ERROR nova.compute.manager [instance: d761da60-7bb1-415e-b5b9-eaaed124d6d2] wait_func=self._await_block_device_map_created) Apr 25 06:41:57 zos057 nova-compute[6190]: ERROR nova.compute.manager [instance: d761da60-7bb1-415e-b5b9-eaaed124d6d2]   File "/opt/stack/nova/nova/virt/block_device.py", line 828, in attach_block_devices Apr 25 06:41:57 zos057 nova-compute[6190]: ERROR nova.compute.manager [instance: d761da60-7bb1-415e-b5b9-eaaed124d6d2] _log_and_attach(device) Apr 25 06:41:57 zos057 nova-compute[6190]: ERROR nova.compute.manager [instance: d761da60-7bb1-415e-b5b9-eaaed124d6d2]   File "/opt/stack/nova/nova/virt/block_device.py", line 825, in _log_and_attach Apr 25 06:41:57 zos057 nova-compute[6190]: ERROR nova.compute.manager [instance: d761da60-7bb1-415e-b5b9-eaaed124d6d2] bdm.attach(*attach_args, **attach_kwargs) Apr 25 06:41:57 zos057 nova-compute[6190]: ERROR nova.compute.manager [instance: d761da60-7bb1-415e-b5b9-eaaed124d6d2]   File "/opt/stack/nova/nova/virt/block_device.py", line 46, in wrapped Apr 25 06:41:57 zos057 nova-compute[6190]: ERROR nova.compute.manager [instance: d761da60-7bb1-415e-b5b9-eaaed124d6d2]     ret_val = method(obj, context, *args, **kwargs) Apr 25 06:41:57 zos057 nova-compute[6190]: ERROR nova.compute.manager [instance: d761da60-7bb1-415e-b5b9-eaaed124d6d2]   File "/opt/stack/nova/nova/virt/block_device.py", line 618, in attach Apr 25 06:41:57 zos057 nova-compute[6190]: ERROR nova.compute.manager [instance: d761da60-7bb1-415e-b5b9-eaaed124d6d2]     virt_driver, do_driver_attach) Apr 25 06:41:57 zos057 nova-compute[6190]: ERROR nova.compute.manager [instance: d761da60-7bb1-415e-b5b9-eaaed124d6d2]   File "/usr/local/lib/python2.7/dist-packages/oslo_concurrency/lockutils.py", line 274, in inner Apr 25 06:41:57 zos057 nova-compute[6190]: ERROR nova.compute.manager [instance: d761da60-7bb1-415e-b5b9-eaaed124d6d2]     return f(*args, **kwargs) Apr 25 06:41:57 zos057 nova-compute[6190]: ERROR nova.compute.manager [instance: d761da60-7bb1-415e-b5b9-eaaed124d6d2]   File "/opt/stack/nova/nova/virt/block_device.py", line 615, in _do_locked_attach Apr 25 06:41:57 zos057 nova-compute[6190]: ERROR nova.compute.manager [instance: d761da60-7bb1-415e-b5b9-eaaed124d6d2] self._do_attach(*args, **_kwargs) Apr 25 06:41:57 zos057 nova-compute[6190]: ERROR nova.compute.manager [instance: d761da60-7bb1-415e-b5b9-eaaed124d6d2]   File "/opt/stack/nova/nova/virt/block_device.py", line 600, in _do_attach Apr 25 06:41:57 zos057 nova-compute[6190]: ERROR nova.compute.manager [instance: d761da60-7bb1-415e-b5b9-eaaed124d6d2]     do_driver_attach) Apr 25 06:41:57 zos057 nova-compute[6190]: ERROR nova.compute.manager [instance: d761da60-7bb1-415e-b5b9-eaaed124d6d2]   File "/opt/stack/nova/nova/virt/block_device.py", line 514, in _volume_attach Apr 25 06:41:57 zos057 nova-compute[6190]: ERROR nova.compute.manager [instance: d761da60-7bb1-415e-b5b9-eaaed124d6d2] self['mount_device'])['connection_info'] Apr 25 06:41:57 zos057 nova-compute[6190]: ERROR nova.compute.manager [instance: d761da60-7bb1-415e-b5b9-eaaed124d6d2]   File "/opt/stack/nova/nova/volume/cinder.py", line 291, in wrapper Apr 25 06:41:57 zos057 nova-compute[6190]: ERROR nova.compute.manager [instance: d761da60-7bb1-415e-b5b9-eaaed124d6d2]     res = method(self, ctx, *args, **kwargs) Apr 25 06:41:57 zos057 nova-compute[6190]: ERROR nova.compute.manager [instance: d761da60-7bb1-415e-b5b9-eaaed124d6d2]   File "/opt/stack/nova/nova/volume/cinder.py", line 327, in wrapper Apr 25 06:41:57 zos057 nova-compute[6190]: ERROR nova.compute.manager [instance: d761da60-7bb1-415e-b5b9-eaaed124d6d2]     res = method(self, ctx, attachment_id, *args, **kwargs) Apr 25 06:41:57 zos057 nova-compute[6190]: ERROR nova.compute.manager [instance: d761da60-7bb1-415e-b5b9-eaaed124d6d2]   File "/opt/stack/nova/nova/volume/cinder.py", line 736, in attachment_update Apr 25 06:41:57 zos057 nova-compute[6190]: ERROR nova.compute.manager [instance: d761da60-7bb1-415e-b5b9-eaaed124d6d2]     'code': getattr(ex, 'code', None)}) Apr 25 06:41:57 zos057 nova-compute[6190]: ERROR nova.compute.manager [instance: d761da60-7bb1-415e-b5b9-eaaed124d6d2]   File "/usr/local/lib/python2.7/dist-packages/oslo_utils/excutils.py", line 220, in __exit__ Apr 25 06:41:57 zos057 nova-compute[6190]: ERROR nova.compute.manager [instance: d761da60-7bb1-415e-b5b9-eaaed124d6d2]     self.force_reraise() Apr 25 06:41:57 zos057 nova-compute[6190]: ERROR nova.compute.manager [instance: d761da60-7bb1-415e-b5b9-eaaed124d6d2]   File "/usr/local/lib/python2.7/dist-packages/oslo_utils/excutils.py", line 196, in force_reraise Apr 25 06:41:57 zos057 nova-compute[6190]: ERROR nova.compute.manager [instance: d761da60-7bb1-415e-b5b9-eaaed124d6d2] six.reraise(self.type_, self.value, self.tb) Apr 25 06:41:57 zos057 nova-compute[6190]: ERROR nova.compute.manager [instance: d761da60-7bb1-415e-b5b9-eaaed124d6d2]   File "/opt/stack/nova/nova/volume/cinder.py", line 726, in attachment_update Apr 25 06:41:57 zos057 nova-compute[6190]: ERROR nova.compute.manager [instance: d761da60-7bb1-415e-b5b9-eaaed124d6d2]     attachment_id, _connector) Apr 25 06:41:57 zos057 nova-compute[6190]: ERROR nova.compute.manager [instance: d761da60-7bb1-415e-b5b9-eaaed124d6d2]   File "/usr/local/lib/python2.7/dist-packages/cinderclient/v3/attachments.py", line 67, in update Apr 25 06:41:57 zos057 nova-compute[6190]: ERROR nova.compute.manager [instance: d761da60-7bb1-415e-b5b9-eaaed124d6d2]     resp = self._update('/attachments/%s' % id, body) Apr 25 06:41:57 zos057 nova-compute[6190]: ERROR nova.compute.manager [instance: d761da60-7bb1-415e-b5b9-eaaed124d6d2]   File "/usr/local/lib/python2.7/dist-packages/cinderclient/base.py", line 344, in _update Apr 25 06:41:57 zos057 nova-compute[6190]: ERROR nova.compute.manager [instance: d761da60-7bb1-415e-b5b9-eaaed124d6d2]     resp, body = self.api.client.put(url, body=body, **kwargs) Apr 25 06:41:57 zos057 nova-compute[6190]: ERROR nova.compute.manager [instance: d761da60-7bb1-415e-b5b9-eaaed124d6d2]   File "/usr/local/lib/python2.7/dist-packages/cinderclient/client.py", line 206, in put Apr 25 06:41:57 zos057 nova-compute[6190]: ERROR nova.compute.manager [instance: d761da60-7bb1-415e-b5b9-eaaed124d6d2]     return self._cs_request(url, 'PUT', **kwargs) Apr 25 06:41:57 zos057 nova-compute[6190]: ERROR nova.compute.manager [instance: d761da60-7bb1-415e-b5b9-eaaed124d6d2]   File "/usr/local/lib/python2.7/dist-packages/cinderclient/client.py", line 191, in _cs_request Apr 25 06:41:57 zos057 nova-compute[6190]: ERROR nova.compute.manager [instance: d761da60-7bb1-415e-b5b9-eaaed124d6d2]     return self.request(url, method, **kwargs) Apr 25 06:41:57 zos057 nova-compute[6190]: ERROR nova.compute.manager [instance: d761da60-7bb1-415e-b5b9-eaaed124d6d2]   File "/usr/local/lib/python2.7/dist-packages/cinderclient/client.py", line 177, in request Apr 25 06:41:57 zos057 nova-compute[6190]: ERROR nova.compute.manager [instance: d761da60-7bb1-415e-b5b9-eaaed124d6d2]     raise exceptions.from_response(resp, body) Apr 25 06:41:57 zos057 nova-compute[6190]: ERROR nova.compute.manager [instance: d761da60-7bb1-415e-b5b9-eaaed124d6d2] ClientException: Unable to update the attachment. (HTTP 500) (Request-ID: req-550f6b9c-7f22-4dce-adbe-f6843e0aa3ce) Apr 25 06:41:57 zos057 nova-compute[6190]: ERROR nova.compute.manager [instance: d761da60-7bb1-415e-b5b9-eaaed124d6d2] Apr 25 06:41:57 zos057 nova-compute[6190]: ERROR nova.compute.manager [None req-751d4586-cd97-4a8f-9423-f2bc4b1f1269 service nova] [instance: d761da60-7bb1-415e-b5b9-eaaed124d6d2] Build of instance d761da60-7bb1-415e-b5b9-eaaed124d6d2 aborted: Unable to update the attachment. (HTTP 500) (Request-ID: req-550f6b9c-7f22-4dce-adbe-f6843e0aa3ce): BuildAbortException: Build of instance d761da60-7bb1-415e-b5b9-eaaed124d6d2 aborted: Unable to update the attachment. (HTTP 500) (Request-ID: req-550f6b9c-7f22-4dce-adbe-f6843e0aa3ce) Apr 25 06:41:57 zos057 nova-compute[6190]: ERROR nova.compute.manager [instance: d761da60-7bb1-415e-b5b9-eaaed124d6d2] Traceback (most recent call last): Apr 25 06:41:57 zos057 nova-compute[6190]: ERROR nova.compute.manager [instance: d761da60-7bb1-415e-b5b9-eaaed124d6d2]   File "/opt/stack/nova/nova/compute/manager.py", line 1839, in _do_build_and_run_instance Apr 25 06:41:57 zos057 nova-compute[6190]: ERROR nova.compute.manager [instance: d761da60-7bb1-415e-b5b9-eaaed124d6d2]     filter_properties, request_spec) Apr 25 06:41:57 zos057 nova-compute[6190]: ERROR nova.compute.manager [instance: d761da60-7bb1-415e-b5b9-eaaed124d6d2]   File "/opt/stack/nova/nova/compute/manager.py", line 2052, in _build_and_run_instance Apr 25 06:41:57 zos057 nova-compute[6190]: ERROR nova.compute.manager [instance: d761da60-7bb1-415e-b5b9-eaaed124d6d2] bdms=block_device_mapping) Apr 25 06:41:57 zos057 nova-compute[6190]: ERROR nova.compute.manager [instance: d761da60-7bb1-415e-b5b9-eaaed124d6d2]   File "/usr/local/lib/python2.7/dist-packages/oslo_utils/excutils.py", line 220, in __exit__ Apr 25 06:41:57 zos057 nova-compute[6190]: ERROR nova.compute.manager [instance: d761da60-7bb1-415e-b5b9-eaaed124d6d2]     self.force_reraise() Apr 25 06:41:57 zos057 nova-compute[6190]: ERROR nova.compute.manager [instance: d761da60-7bb1-415e-b5b9-eaaed124d6d2]   File "/usr/local/lib/python2.7/dist-packages/oslo_utils/excutils.py", line 196, in force_reraise Apr 25 06:41:57 zos057 nova-compute[6190]: ERROR nova.compute.manager [instance: d761da60-7bb1-415e-b5b9-eaaed124d6d2] six.reraise(self.type_, self.value, self.tb) Apr 25 06:41:57 zos057 nova-compute[6190]: ERROR nova.compute.manager [instance: d761da60-7bb1-415e-b5b9-eaaed124d6d2]   File "/opt/stack/nova/nova/compute/manager.py", line 2004, in _build_and_run_instance Apr 25 06:41:57 zos057 nova-compute[6190]: ERROR nova.compute.manager [instance: d761da60-7bb1-415e-b5b9-eaaed124d6d2] block_device_mapping) as resources: Apr 25 06:41:57 zos057 nova-compute[6190]: ERROR nova.compute.manager [instance: d761da60-7bb1-415e-b5b9-eaaed124d6d2]   File "/usr/lib/python2.7/contextlib.py", line 17, in __enter__ Apr 25 06:41:57 zos057 nova-compute[6190]: ERROR nova.compute.manager [instance: d761da60-7bb1-415e-b5b9-eaaed124d6d2]     return self.gen.next() Apr 25 06:41:57 zos057 nova-compute[6190]: ERROR nova.compute.manager [instance: d761da60-7bb1-415e-b5b9-eaaed124d6d2]   File "/opt/stack/nova/nova/compute/manager.py", line 2211, in _build_resources Apr 25 06:41:57 zos057 nova-compute[6190]: ERROR nova.compute.manager [instance: d761da60-7bb1-415e-b5b9-eaaed124d6d2] reason=e.format_message()) Apr 25 06:41:57 zos057 nova-compute[6190]: ERROR nova.compute.manager [instance: d761da60-7bb1-415e-b5b9-eaaed124d6d2] BuildAbortException: Build of instance d761da60-7bb1-415e-b5b9-eaaed124d6d2 aborted: Unable to update the attachment. (HTTP 500) (Request-ID: req-550f6b9c-7f22-4dce-adbe-f6843e0aa3ce) Apr 25 06:41:57 zos057 nova-compute[6190]: ERROR nova.compute.manager [instance: d761da60-7bb1-415e-b5b9-eaaed124d6d2]


[3] Apr 25 06:41:57 zos057 devstack@c-api.service[11490]: ERROR cinder.api.v3.attachments [req-f9f3364b-4dd8-4195-a60a-2f0e44c1f2ea req-550f6b9c-7f22-4dce-adbe-f6843e0aa3ce admin admin] Unable to update the attachment.: MessagingTimeout: Timed out waiting for a reply to message ID fe836528e2ea43edabe8004845837f4f Apr 25 06:41:57 zos057 devstack@c-api.service[11490]: ERROR cinder.api.v3.attachments Traceback (most recent call last): Apr 25 06:41:57 zos057 devstack@c-api.service[11490]: ERROR cinder.api.v3.attachments   File "/opt/stack/cinder/cinder/api/v3/attachments.py", line 228, in update Apr 25 06:41:57 zos057 devstack@c-api.service[11490]: ERROR cinder.api.v3.attachments     connector)) Apr 25 06:41:57 zos057 devstack@c-api.service[11490]: ERROR cinder.api.v3.attachments   File "/opt/stack/cinder/cinder/volume/api.py", line 2158, in attachment_update Apr 25 06:41:57 zos057 devstack@c-api.service[11490]: ERROR cinder.api.v3.attachments     attachment_ref.id)) Apr 25 06:41:57 zos057 devstack@c-api.service[11490]: ERROR cinder.api.v3.attachments   File "/opt/stack/cinder/cinder/rpc.py", line 187, in _wrapper Apr 25 06:41:57 zos057 devstack@c-api.service[11490]: ERROR cinder.api.v3.attachments     return f(self, *args, **kwargs) Apr 25 06:41:57 zos057 devstack@c-api.service[11490]: ERROR cinder.api.v3.attachments   File "/opt/stack/cinder/cinder/volume/rpcapi.py", line 442, in attachment_update Apr 25 06:41:57 zos057 devstack@c-api.service[11490]: ERROR cinder.api.v3.attachments     attachment_id=attachment_id) Apr 25 06:41:57 zos057 devstack@c-api.service[11490]: ERROR cinder.api.v3.attachments   File "/usr/local/lib/python2.7/dist-packages/oslo_messaging/rpc/client.py", line 174, in call Apr 25 06:41:57 zos057 devstack@c-api.service[11490]: ERROR cinder.api.v3.attachments     retry=self.retry) Apr 25 06:41:57 zos057 devstack@c-api.service[11490]: ERROR cinder.api.v3.attachments   File "/usr/local/lib/python2.7/dist-packages/oslo_messaging/transport.py", line 131, in _send Apr 25 06:41:57 zos057 devstack@c-api.service[11490]: ERROR cinder.api.v3.attachments     timeout=timeout, retry=retry) Apr 25 06:41:57 zos057 devstack@c-api.service[11490]: ERROR cinder.api.v3.attachments   File "/usr/local/lib/python2.7/dist-packages/oslo_messaging/_drivers/amqpdriver.py", line 559, in send Apr 25 06:41:57 zos057 devstack@c-api.service[11490]: ERROR cinder.api.v3.attachments     retry=retry) Apr 25 06:41:57 zos057 devstack@c-api.service[11490]: ERROR cinder.api.v3.attachments   File "/usr/local/lib/python2.7/dist-packages/oslo_messaging/_drivers/amqpdriver.py", line 548, in _send Apr 25 06:41:57 zos057 devstack@c-api.service[11490]: ERROR cinder.api.v3.attachments     result = self._waiter.wait(msg_id, timeout) Apr 25 06:41:57 zos057 devstack@c-api.service[11490]: ERROR cinder.api.v3.attachments   File "/usr/local/lib/python2.7/dist-packages/oslo_messaging/_drivers/amqpdriver.py", line 440, in wait Apr 25 06:41:57 zos057 devstack@c-api.service[11490]: ERROR cinder.api.v3.attachments     message = self.waiters.get(msg_id, timeout=timeout) Apr 25 06:41:57 zos057 devstack@c-api.service[11490]: ERROR cinder.api.v3.attachments   File "/usr/local/lib/python2.7/dist-packages/oslo_messaging/_drivers/amqpdriver.py", line 328, in get Apr 25 06:41:57 zos057 devstack@c-api.service[11490]: ERROR cinder.api.v3.attachments     'to message ID %s' % msg_id) Apr 25 06:41:57 zos057 devstack@c-api.service[11490]: ERROR cinder.api.v3.attachments MessagingTimeout: Timed out waiting for a reply to message ID fe836528e2ea43edabe8004845837f4f Apr 25 06:41:57 zos057 devstack@c-api.service[11490]: ERROR cinder.api.v3.attachments Apr 25 06:42:47 zos057 cinder-volume[11475]: ERROR oslo_messaging.rpc.server [req-f9f3364b-4dd8-4195-a60a-2f0e44c1f2ea req-550f6b9c-7f22-4dce-adbe-f6843e0aa3ce admin None] Exception during message handling: VolumeAttachmentNotFound: Volume attachment could not be found with filter: attachment_id = 266ef7e1-4735-40f1-b704-509472f565cb. Apr 25 06:42:47 zos057 cinder-volume[11475]: ERROR oslo_messaging.rpc.server Traceback (most recent call last): Apr 25 06:42:47 zos057 cinder-volume[11475]: ERROR oslo_messaging.rpc.server   File "/usr/local/lib/python2.7/dist-packages/oslo_messaging/rpc/server.py", line 163, in _process_incoming Apr 25 06:42:47 zos057 cinder-volume[11475]: ERROR oslo_messaging.rpc.server     res = self.dispatcher.dispatch(message) Apr 25 06:42:47 zos057 cinder-volume[11475]: ERROR oslo_messaging.rpc.server   File "/usr/local/lib/python2.7/dist-packages/oslo_messaging/rpc/dispatcher.py", line 220, in dispatch Apr 25 06:42:47 zos057 cinder-volume[11475]: ERROR oslo_messaging.rpc.server     return self._do_dispatch(endpoint, method, ctxt, args) Apr 25 06:42:47 zos057 cinder-volume[11475]: ERROR oslo_messaging.rpc.server   File "/usr/local/lib/python2.7/dist-packages/oslo_messaging/rpc/dispatcher.py", line 190, in _do_dispatch Apr 25 06:42:47 zos057 cinder-volume[11475]: ERROR oslo_messaging.rpc.server     result = func(ctxt, **new_args) Apr 25 06:42:47 zos057 cinder-volume[11475]: ERROR oslo_messaging.rpc.server   File "/opt/stack/cinder/cinder/volume/manager.py", line 4378, in attachment_update Apr 25 06:42:47 zos057 cinder-volume[11475]: ERROR oslo_messaging.rpc.server     connector) Apr 25 06:42:47 zos057 cinder-volume[11475]: ERROR oslo_messaging.rpc.server   File "/opt/stack/cinder/cinder/volume/manager.py", line 4349, in _connection_create Apr 25 06:42:47 zos057 cinder-volume[11475]: ERROR oslo_messaging.rpc.server self.db.volume_attachment_update(ctxt, attachment.id, values) Apr 25 06:42:47 zos057 cinder-volume[11475]: ERROR oslo_messaging.rpc.server   File "/opt/stack/cinder/cinder/db/api.py", line 365, in volume_attachment_update Apr 25 06:42:47 zos057 cinder-volume[11475]: ERROR oslo_messaging.rpc.server     return IMPL.volume_attachment_update(context, attachment_id, values) Apr 25 06:42:47 zos057 cinder-volume[11475]: ERROR oslo_messaging.rpc.server   File "/opt/stack/cinder/cinder/db/sqlalchemy/api.py", line 182, in wrapper Apr 25 06:42:47 zos057 cinder-volume[11475]: ERROR oslo_messaging.rpc.server     return f(*args, **kwargs) Apr 25 06:42:47 zos057 cinder-volume[11475]: ERROR oslo_messaging.rpc.server   File "/opt/stack/cinder/cinder/db/sqlalchemy/api.py", line 2674, in volume_attachment_update Apr 25 06:42:47 zos057 cinder-volume[11475]: ERROR oslo_messaging.rpc.server     filter='attachment_id = ' + attachment_id) Apr 25 06:42:47 zos057 cinder-volume[11475]: ERROR oslo_messaging.rpc.server VolumeAttachmentNotFound: Volume attachment could not be found with filter: attachment_id = 266ef7e1-4735-40f1-b704-509472f565cb. Apr 25 06:42:47 zos057 cinder-volume[11475]: ERROR oslo_messaging.rpc.server


--
---------------------------------------------------------------------------------------------------
Sreeram Vancheeswaran
System z Firmware - Openstack Development
IBM Systems & Technology Lab, Bangalore, India
Phone:  +91 80 40660826     Mob: +91-9341411511
Email :sree...@linux.vnet.ibm.com



__________________________________________________________________________
OpenStack Development Mailing List (not for usage questions)
Unsubscribe: openstack-dev-requ...@lists.openstack.org?subject:unsubscribe
http://lists.openstack.org/cgi-bin/mailman/listinfo/openstack-dev


You're doing boot from volume so nova-api should be creating the volume attachment record [1] and then nova-compute is updating the attachment with the compute host connector, which also creates the export in the backend storage via cinder. For whatever reason, the attachment_id nova-compute is passing to cinder is not found, but I wouldn't know why. You'll likely need to trace the request through the nova-api, nova-compute, cinder-api and cinder-volume logs, and trace 266ef7e1-4735-40f1-b704-509472f565cb which is the attachment ID. Like I said, nova-api creates it, will store it in the block_device_mappings table, and reference it later in nova-compute when actually attaching the volume to the instance on the compute host. The fact you're getting down to cinder-volume does mean that when nova-compute called cinder-api to update the volume attachment, cinder-api found the attachment in the database, otherwise it would return a 404 response to nova-compute. Maybe you're hitting some weird race?

It's also weird that cinder-api is hitting an RPC messaging timeout even though cinder-volume clearly failed, that should be raised back up to cinder-api and spewed back to the caller (nova-compute) as a 500 error.

Also, I should probably confirm, are you booting from an existing volume, or booting from an image or volume snapshot where nova-compute then creates the volume in Cinder and then attaches it to the server? If so, that flow doesn't yet create volume attachment records, which is what patch [2] is for.

[1] https://github.com/openstack/nova/blob/0a642e2eee8d430ddcccf2947aedcca1a0a0b005/nova/compute/api.py#L3830
[2] https://review.openstack.org/#/c/541420/

--

Thanks,

Matt

__________________________________________________________________________
OpenStack Development Mailing List (not for usage questions)
Unsubscribe: openstack-dev-requ...@lists.openstack.org?subject:unsubscribe
http://lists.openstack.org/cgi-bin/mailman/listinfo/openstack-dev

Reply via email to