http://logs.openstack.org/13/579113/14/gate/tempest-full/08a8313/job-output.txt.gz#_2018-07-10_15_23_00_712024
This is where the backup manager is getting the connection properties from os-brick:
http://logs.openstack.org/13/579113/14/gate/tempest-full/08a8313/controller/logs/screen-c-bak.txt.gz#_Jul_10_15_05_08_634730
Jul 10 15:05:08.634730 ubuntu-xenial-rax-dfw-0000637920 cinder-backup[18729]: DEBUG os_brick.utils [None req-8316e6e8-b9d6-4403-9742-8e2fbe245815 tempest-VolumesSnapshotTestJSON-312702933 None] <== get_connector_properties: return (14ms) {'initiator': u'iqn.1993-08.org.debian:01:f82dea4cc99', 'ip': u'10.208.96.143', 'platform': u'x86_64', 'host': u'ubuntu-xenial-rax-dfw-0000637920', 'do_local_attach': False, 'os_type': u'linux2', 'multipath': False} {{(pid=18729) trace_logging_wrapper /usr/local/lib/python2.7/dist-packages/os_brick/utils.py:170}}
And then 1 minute later we get the RPC messaging timeout:
Jul 10 15:06:11.116296 ubuntu-xenial-rax-dfw-0000637920 cinder-backup[18729]: ERROR oslo_messaging.rpc.server [None req-8316e6e8-b9d6-4403-9742-8e2fbe245815 tempest-VolumesSnapshotTestJSON-312702933 None] Exception during message handling: MessagingTimeout: Timed out waiting for a reply to message ID c4e7ab3ab3044f5bb7ba85cebbc9f8cb
Jul 10 15:06:11.116618 ubuntu-xenial-rax-dfw-0000637920 cinder-backup[18729]: ERROR oslo_messaging.rpc.server Traceback (most recent call last):
Jul 10 15:06:11.116915 ubuntu-xenial-rax-dfw-0000637920 cinder-backup[18729]: ERROR oslo_messaging.rpc.server File "/usr/local/lib/python2.7/dist-packages/oslo_messaging/rpc/server.py", line 163, in _process_incoming
Jul 10 15:06:11.117254 ubuntu-xenial-rax-dfw-0000637920 cinder-backup[18729]: ERROR oslo_messaging.rpc.server res = self.dispatcher.dispatch(message)
Jul 10 15:06:11.117569 ubuntu-xenial-rax-dfw-0000637920 cinder-backup[18729]: ERROR oslo_messaging.rpc.server File "/usr/local/lib/python2.7/dist-packages/oslo_messaging/rpc/dispatcher.py", line 265, in dispatch
Jul 10 15:06:11.117881 ubuntu-xenial-rax-dfw-0000637920 cinder-backup[18729]: ERROR oslo_messaging.rpc.server return self._do_dispatch(endpoint, method, ctxt, args)
Jul 10 15:06:11.118187 ubuntu-xenial-rax-dfw-0000637920 cinder-backup[18729]: ERROR oslo_messaging.rpc.server File "/usr/local/lib/python2.7/dist-packages/oslo_messaging/rpc/dispatcher.py", line 194, in _do_dispatch
Jul 10 15:06:11.118432 ubuntu-xenial-rax-dfw-0000637920 cinder-backup[18729]: ERROR oslo_messaging.rpc.server result = func(ctxt, **new_args)
Jul 10 15:06:11.118644 ubuntu-xenial-rax-dfw-0000637920 cinder-backup[18729]: ERROR oslo_messaging.rpc.server File "/opt/stack/cinder/cinder/backup/manager.py", line 423, in create_backup
Jul 10 15:06:11.118871 ubuntu-xenial-rax-dfw-0000637920 cinder-backup[18729]: ERROR oslo_messaging.rpc.server self._update_backup_error(backup, six.text_type(err))
Jul 10 15:06:11.119076 ubuntu-xenial-rax-dfw-0000637920 cinder-backup[18729]: ERROR oslo_messaging.rpc.server File "/usr/local/lib/python2.7/dist-packages/oslo_utils/excutils.py", line 220, in __exit__
Jul 10 15:06:11.119289 ubuntu-xenial-rax-dfw-0000637920 cinder-backup[18729]: ERROR oslo_messaging.rpc.server self.force_reraise()
Jul 10 15:06:11.119620 ubuntu-xenial-rax-dfw-0000637920 cinder-backup[18729]: ERROR oslo_messaging.rpc.server File "/usr/local/lib/python2.7/dist-packages/oslo_utils/excutils.py", line 196, in force_reraise
Jul 10 15:06:11.119938 ubuntu-xenial-rax-dfw-0000637920 cinder-backup[18729]: ERROR oslo_messaging.rpc.server six.reraise(self.type_, self.value, self.tb)
Jul 10 15:06:11.120269 ubuntu-xenial-rax-dfw-0000637920 cinder-backup[18729]: ERROR oslo_messaging.rpc.server File "/opt/stack/cinder/cinder/backup/manager.py", line 412, in create_backup
Jul 10 15:06:11.120591 ubuntu-xenial-rax-dfw-0000637920 cinder-backup[18729]: ERROR oslo_messaging.rpc.server updates = self._run_backup(context, backup, volume)
Jul 10 15:06:11.120930 ubuntu-xenial-rax-dfw-0000637920 cinder-backup[18729]: ERROR oslo_messaging.rpc.server File "/opt/stack/cinder/cinder/backup/manager.py", line 483, in _run_backup
Jul 10 15:06:11.121252 ubuntu-xenial-rax-dfw-0000637920 cinder-backup[18729]: ERROR oslo_messaging.rpc.server backup_device.is_snapshot)
Jul 10 15:06:11.121576 ubuntu-xenial-rax-dfw-0000637920 cinder-backup[18729]: ERROR oslo_messaging.rpc.server File "/opt/stack/cinder/cinder/backup/manager.py", line 1075, in _attach_device
Jul 10 15:06:11.121828 ubuntu-xenial-rax-dfw-0000637920 cinder-backup[18729]: ERROR oslo_messaging.rpc.server return self._attach_volume(ctxt, backup_device, properties)
Jul 10 15:06:11.122035 ubuntu-xenial-rax-dfw-0000637920 cinder-backup[18729]: ERROR oslo_messaging.rpc.server File "/opt/stack/cinder/cinder/backup/manager.py", line 1097, in _attach_volume
Jul 10 15:06:11.122238 ubuntu-xenial-rax-dfw-0000637920 cinder-backup[18729]: ERROR oslo_messaging.rpc.server {'volume_id', volume.id})
Jul 10 15:06:11.122454 ubuntu-xenial-rax-dfw-0000637920 cinder-backup[18729]: ERROR oslo_messaging.rpc.server File "/usr/local/lib/python2.7/dist-packages/oslo_utils/excutils.py", line 220, in __exit__
Jul 10 15:06:11.122659 ubuntu-xenial-rax-dfw-0000637920 cinder-backup[18729]: ERROR oslo_messaging.rpc.server self.force_reraise()
Jul 10 15:06:11.122861 ubuntu-xenial-rax-dfw-0000637920 cinder-backup[18729]: ERROR oslo_messaging.rpc.server File "/usr/local/lib/python2.7/dist-packages/oslo_utils/excutils.py", line 196, in force_reraise
Jul 10 15:06:11.123063 ubuntu-xenial-rax-dfw-0000637920 cinder-backup[18729]: ERROR oslo_messaging.rpc.server six.reraise(self.type_, self.value, self.tb)
Jul 10 15:06:11.123265 ubuntu-xenial-rax-dfw-0000637920 cinder-backup[18729]: ERROR oslo_messaging.rpc.server File "/opt/stack/cinder/cinder/backup/manager.py", line 1085, in _attach_volume
Jul 10 15:06:11.123499 ubuntu-xenial-rax-dfw-0000637920 cinder-backup[18729]: ERROR oslo_messaging.rpc.server properties)
Jul 10 15:06:11.123706 ubuntu-xenial-rax-dfw-0000637920 cinder-backup[18729]: ERROR oslo_messaging.rpc.server File "/opt/stack/cinder/cinder/volume/rpcapi.py", line 226, in initialize_connection
Jul 10 15:06:11.123909 ubuntu-xenial-rax-dfw-0000637920 cinder-backup[18729]: ERROR oslo_messaging.rpc.server volume=volume)
Jul 10 15:06:11.124124 ubuntu-xenial-rax-dfw-0000637920 cinder-backup[18729]: ERROR oslo_messaging.rpc.server File "/usr/local/lib/python2.7/dist-packages/oslo_messaging/rpc/client.py", line 179, in call
Jul 10 15:06:11.124327 ubuntu-xenial-rax-dfw-0000637920 cinder-backup[18729]: ERROR oslo_messaging.rpc.server retry=self.retry)
Jul 10 15:06:11.125117 ubuntu-xenial-rax-dfw-0000637920 cinder-backup[18729]: ERROR oslo_messaging.rpc.server File "/usr/local/lib/python2.7/dist-packages/oslo_messaging/transport.py", line 133, in _send
Jul 10 15:06:11.125336 ubuntu-xenial-rax-dfw-0000637920 cinder-backup[18729]: ERROR oslo_messaging.rpc.server retry=retry)
Jul 10 15:06:11.125576 ubuntu-xenial-rax-dfw-0000637920 cinder-backup[18729]: ERROR oslo_messaging.rpc.server File "/usr/local/lib/python2.7/dist-packages/oslo_messaging/_drivers/amqpdriver.py", line 584, in send
Jul 10 15:06:11.125854 ubuntu-xenial-rax-dfw-0000637920 cinder-backup[18729]: ERROR oslo_messaging.rpc.server call_monitor_timeout, retry=retry)
Jul 10 15:06:11.126069 ubuntu-xenial-rax-dfw-0000637920 cinder-backup[18729]: ERROR oslo_messaging.rpc.server File "/usr/local/lib/python2.7/dist-packages/oslo_messaging/_drivers/amqpdriver.py", line 573, in _send
Jul 10 15:06:11.126289 ubuntu-xenial-rax-dfw-0000637920 cinder-backup[18729]: ERROR oslo_messaging.rpc.server call_monitor_timeout)
Jul 10 15:06:11.126492 ubuntu-xenial-rax-dfw-0000637920 cinder-backup[18729]: ERROR oslo_messaging.rpc.server File "/usr/local/lib/python2.7/dist-packages/oslo_messaging/_drivers/amqpdriver.py", line 459, in wait
Jul 10 15:06:11.126694 ubuntu-xenial-rax-dfw-0000637920 cinder-backup[18729]: ERROR oslo_messaging.rpc.server message = self.waiters.get(msg_id, timeout=timeout)
Jul 10 15:06:11.126897 ubuntu-xenial-rax-dfw-0000637920 cinder-backup[18729]: ERROR oslo_messaging.rpc.server File "/usr/local/lib/python2.7/dist-packages/oslo_messaging/_drivers/amqpdriver.py", line 336, in get
Jul 10 15:06:11.127109 ubuntu-xenial-rax-dfw-0000637920 cinder-backup[18729]: ERROR oslo_messaging.rpc.server 'to message ID %s' % msg_id)
Jul 10 15:06:11.127313 ubuntu-xenial-rax-dfw-0000637920 cinder-backup[18729]: ERROR oslo_messaging.rpc.server MessagingTimeout: Timed out waiting for a reply to message ID c4e7ab3ab3044f5bb7ba85cebbc9f8cb
Jul 10 15:06:11.127538 ubuntu-xenial-rax-dfw-0000637920 cinder-backup[18729]: ERROR oslo_messaging.rpc.server
This would be similar to bug 1763712 where "normal" volume attach flows intermittently timeout during initialize connection (or attachment update).
