http://logs.openstack.org/66/633566/1/check/tempest-full-parallel/2a5eeca/controller/logs/screen-c-api.txt#_Jan_29_00_21_05_738408
Jan 29 00:21:05.738408 ubuntu-bionic-ovh-bhs1-0002199912 <email address hidden>[12973]: ERROR cinder.api.v3.attachments [req-d6667da6-d6a8-4912-8396-99d1a0b26631 req-10ef42dc-1cac-46c8-85b2-2166df98df94 tempest-VolumesExtendAttachedTest-619719536 tempest-VolumesExtendAttachedTest-619719536] Unable to update the attachment.: MessagingTimeout: Timed out waiting for a reply to message ID 51cf19ab9b244e1e9fe8598633187403
Jan 29 00:21:05.738408 ubuntu-bionic-ovh-bhs1-0002199912 <email address hidden>[12973]: ERROR cinder.api.v3.attachments Traceback (most recent call last):
Jan 29 00:21:05.738408 ubuntu-bionic-ovh-bhs1-0002199912 <email address hidden>[12973]: ERROR cinder.api.v3.attachments File "/opt/stack/cinder/cinder/api/v3/attachments.py", line 238, in update
Jan 29 00:21:05.738408 ubuntu-bionic-ovh-bhs1-0002199912 <email address hidden>[12973]: ERROR cinder.api.v3.attachments connector))
Jan 29 00:21:05.738408 ubuntu-bionic-ovh-bhs1-0002199912 <email address hidden>[12973]: ERROR cinder.api.v3.attachments File "/opt/stack/cinder/cinder/volume/api.py", line 2183, in attachment_update
Jan 29 00:21:05.738408 ubuntu-bionic-ovh-bhs1-0002199912 <email address hidden>[12973]: ERROR cinder.api.v3.attachments attachment_ref.id))
Jan 29 00:21:05.738408 ubuntu-bionic-ovh-bhs1-0002199912 <email address hidden>[12973]: ERROR cinder.api.v3.attachments File "/opt/stack/cinder/cinder/rpc.py", line 187, in _wrapper
Jan 29 00:21:05.738408 ubuntu-bionic-ovh-bhs1-0002199912 <email address hidden>[12973]: ERROR cinder.api.v3.attachments return f(self, *args, **kwargs)
Jan 29 00:21:05.738408 ubuntu-bionic-ovh-bhs1-0002199912 <email address hidden>[12973]: ERROR cinder.api.v3.attachments File "/opt/stack/cinder/cinder/volume/rpcapi.py", line 450, in attachment_update
Jan 29 00:21:05.738408 ubuntu-bionic-ovh-bhs1-0002199912 <email address hidden>[12973]: ERROR cinder.api.v3.attachments attachment_id=attachment_id)
Jan 29 00:21:05.738408 ubuntu-bionic-ovh-bhs1-0002199912 <email address hidden>[12973]: ERROR cinder.api.v3.attachments File "/usr/local/lib/python2.7/dist-packages/oslo_messaging/rpc/client.py", line 179, in call
Jan 29 00:21:05.738408 ubuntu-bionic-ovh-bhs1-0002199912 <email address hidden>[12973]: ERROR cinder.api.v3.attachments retry=self.retry)
Jan 29 00:21:05.738408 ubuntu-bionic-ovh-bhs1-0002199912 <email address hidden>[12973]: ERROR cinder.api.v3.attachments File "/usr/local/lib/python2.7/dist-packages/oslo_messaging/transport.py", line 128, in _send
Jan 29 00:21:05.738408 ubuntu-bionic-ovh-bhs1-0002199912 <email address hidden>[12973]: ERROR cinder.api.v3.attachments retry=retry)
Jan 29 00:21:05.738408 ubuntu-bionic-ovh-bhs1-0002199912 <email address hidden>[12973]: ERROR cinder.api.v3.attachments File "/usr/local/lib/python2.7/dist-packages/oslo_messaging/_drivers/amqpdriver.py", line 645, in send
Jan 29 00:21:05.738408 ubuntu-bionic-ovh-bhs1-0002199912 <email address hidden>[12973]: ERROR cinder.api.v3.attachments call_monitor_timeout, retry=retry)
Jan 29 00:21:05.738408 ubuntu-bionic-ovh-bhs1-0002199912 <email address hidden>[12973]: ERROR cinder.api.v3.attachments File "/usr/local/lib/python2.7/dist-packages/oslo_messaging/_drivers/amqpdriver.py", line 634, in _send
Jan 29 00:21:05.738408 ubuntu-bionic-ovh-bhs1-0002199912 <email address hidden>[12973]: ERROR cinder.api.v3.attachments call_monitor_timeout)
Jan 29 00:21:05.738408 ubuntu-bionic-ovh-bhs1-0002199912 <email address hidden>[12973]: ERROR cinder.api.v3.attachments File "/usr/local/lib/python2.7/dist-packages/oslo_messaging/_drivers/amqpdriver.py", line 520, in wait
Jan 29 00:21:05.738408 ubuntu-bionic-ovh-bhs1-0002199912 <email address hidden>[12973]: ERROR cinder.api.v3.attachments message = self.waiters.get(msg_id, timeout=timeout)
Jan 29 00:21:05.738408 ubuntu-bionic-ovh-bhs1-0002199912 <email address hidden>[12973]: ERROR cinder.api.v3.attachments File "/usr/local/lib/python2.7/dist-packages/oslo_messaging/_drivers/amqpdriver.py", line 397, in get
Jan 29 00:21:05.738408 ubuntu-bionic-ovh-bhs1-0002199912 <email address hidden>[12973]: ERROR cinder.api.v3.attachments 'to message ID %s' % msg_id)
Jan 29 00:21:05.738408 ubuntu-bionic-ovh-bhs1-0002199912 <email address hidden>[12973]: ERROR cinder.api.v3.attachments MessagingTimeout: Timed out waiting for a reply to message ID 51cf19ab9b244e1e9fe8598633187403
Jan 29 00:21:05.738408 ubuntu-bionic-ovh-bhs1-0002199912 <email address hidden>[12973]: ERROR cinder.api.v3.attachments
http://logstash.openstack.org/#dashboard/file/logstash.json?query=message%3A%5C%22MessagingTimeout%5C%22%20AND%20tags%3A%5C%22screen-c-api.txt%5C%22&from=10d
For that particular request, there is a VolumeAttachmentNotFound trace in cinder-volume logs:
http://logs.openstack.org/66/633566/1/check/tempest-full-parallel/2a5eeca/controller/logs/screen-c-vol.txt#_Jan_29_00_21_07_114482
Jan 29 00:21:07.114482 ubuntu-bionic-ovh-bhs1-0002199912 cinder-volume[14122]: ERROR oslo_messaging.rpc.server [req-d6667da6-d6a8-4912-8396-99d1a0b26631 req-10ef42dc-1cac-46c8-85b2-2166df98df94 tempest-VolumesExtendAttachedTest-619719536 None] Exception during message handling: VolumeAttachmentNotFound: Volume attachment could not be found with filter: attachment_id = 5609ac83-2a2e-4207-b52b-4cea6371ecd2.
Jan 29 00:21:07.114482 ubuntu-bionic-ovh-bhs1-0002199912 cinder-volume[14122]: ERROR oslo_messaging.rpc.server Traceback (most recent call last):
Jan 29 00:21:07.114482 ubuntu-bionic-ovh-bhs1-0002199912 cinder-volume[14122]: ERROR oslo_messaging.rpc.server File "/usr/local/lib/python2.7/dist-packages/oslo_messaging/rpc/server.py", line 166, in _process_incoming
Jan 29 00:21:07.114482 ubuntu-bionic-ovh-bhs1-0002199912 cinder-volume[14122]: ERROR oslo_messaging.rpc.server res = self.dispatcher.dispatch(message)
Jan 29 00:21:07.114482 ubuntu-bionic-ovh-bhs1-0002199912 cinder-volume[14122]: ERROR oslo_messaging.rpc.server File "/usr/local/lib/python2.7/dist-packages/oslo_messaging/rpc/dispatcher.py", line 265, in dispatch
Jan 29 00:21:07.114482 ubuntu-bionic-ovh-bhs1-0002199912 cinder-volume[14122]: ERROR oslo_messaging.rpc.server return self._do_dispatch(endpoint, method, ctxt, args)
Jan 29 00:21:07.114482 ubuntu-bionic-ovh-bhs1-0002199912 cinder-volume[14122]: ERROR oslo_messaging.rpc.server File "/usr/local/lib/python2.7/dist-packages/oslo_messaging/rpc/dispatcher.py", line 194, in _do_dispatch
Jan 29 00:21:07.114482 ubuntu-bionic-ovh-bhs1-0002199912 cinder-volume[14122]: ERROR oslo_messaging.rpc.server result = func(ctxt, **new_args)
Jan 29 00:21:07.114482 ubuntu-bionic-ovh-bhs1-0002199912 cinder-volume[14122]: ERROR oslo_messaging.rpc.server File "/opt/stack/cinder/cinder/volume/manager.py", line 4513, in attachment_update
Jan 29 00:21:07.114482 ubuntu-bionic-ovh-bhs1-0002199912 cinder-volume[14122]: ERROR oslo_messaging.rpc.server connector)
Jan 29 00:21:07.114482 ubuntu-bionic-ovh-bhs1-0002199912 cinder-volume[14122]: ERROR oslo_messaging.rpc.server File "/opt/stack/cinder/cinder/volume/manager.py", line 4474, in _connection_create
Jan 29 00:21:07.114482 ubuntu-bionic-ovh-bhs1-0002199912 cinder-volume[14122]: ERROR oslo_messaging.rpc.server self.db.volume_attachment_update(ctxt, attachment.id, values)
Jan 29 00:21:07.114482 ubuntu-bionic-ovh-bhs1-0002199912 cinder-volume[14122]: ERROR oslo_messaging.rpc.server File "/opt/stack/cinder/cinder/db/api.py", line 365, in volume_attachment_update
Jan 29 00:21:07.114482 ubuntu-bionic-ovh-bhs1-0002199912 cinder-volume[14122]: ERROR oslo_messaging.rpc.server return IMPL.volume_attachment_update(context, attachment_id, values)
Jan 29 00:21:07.114482 ubuntu-bionic-ovh-bhs1-0002199912 cinder-volume[14122]: ERROR oslo_messaging.rpc.server File "/opt/stack/cinder/cinder/db/sqlalchemy/api.py", line 183, in wrapper
Jan 29 00:21:07.114482 ubuntu-bionic-ovh-bhs1-0002199912 cinder-volume[14122]: ERROR oslo_messaging.rpc.server return f(*args, **kwargs)
Jan 29 00:21:07.114482 ubuntu-bionic-ovh-bhs1-0002199912 cinder-volume[14122]: ERROR oslo_messaging.rpc.server File "/opt/stack/cinder/cinder/db/sqlalchemy/api.py", line 2683, in volume_attachment_update
Jan 29 00:21:07.114482 ubuntu-bionic-ovh-bhs1-0002199912 cinder-volume[14122]: ERROR oslo_messaging.rpc.server filter='attachment_id = ' + attachment_id)
Jan 29 00:21:07.114482 ubuntu-bionic-ovh-bhs1-0002199912 cinder-volume[14122]: ERROR oslo_messaging.rpc.server VolumeAttachmentNotFound: Volume attachment could not be found with filter: attachment_id = 5609ac83-2a2e-4207-b52b-4cea6371ecd2.
Jan 29 00:21:07.114482 ubuntu-bionic-ovh-bhs1-0002199912 cinder-volume[14122]: ERROR oslo_messaging.rpc.server
And that must be screwing up the response to the API which results in the timeout.
Something is messed up because looking at the c-api logs, the MessagingTimeout happens before even 60 seconds have passed. The request starts here:
Jan 29 00:21:05.263845 ubuntu-
and times out here:
Jan 29 00:21:05.738408 ubuntu-
That's not even the total time that the RPC call from c-api to c-vol would take, so why are we getting a MessagingTimeout rather than the VolumeAttachmen