Here are some extracts from nova-compute.log demonstrating the issue:


2021-06-09 07:52:02.839 6222 INFO nova.compute.claims [req-7d02abb5-4337-440f-a02f-62f571856218 58f7c51142914f8ca5364b053bee5ad5 b2e4daac950844b2b8abc906f55ccbd1 - default default] [instance: 20333ac0-5c0a-4acb-920f-2dbbb5567b7d] Attempting claim on node zbk130721.zbk.sys11cloud.net: memory 4096 MB, disk 50 GB, vcpus 2 CPU
2021-06-09 07:52:02.841 6222 INFO nova.compute.claims [req-7d02abb5-4337-440f-a02f-62f571856218 58f7c51142914f8ca5364b053bee5ad5 b2e4daac950844b2b8abc906f55ccbd1 - default default] [instance: 20333ac0-5c0a-4acb-920f-2dbbb5567b7d] Total memory: 515889 MB, used: 4096.00 MB
2021-06-09 07:52:02.842 6222 INFO nova.compute.claims [req-7d02abb5-4337-440f-a02f-62f571856218 58f7c51142914f8ca5364b053bee5ad5 b2e4daac950844b2b8abc906f55ccbd1 - default default] [instance: 20333ac0-5c0a-4acb-920f-2dbbb5567b7d] memory limit: 419159.00 MB, free: 415063.00 MB
2021-06-09 07:52:02.843 6222 INFO nova.compute.claims [req-7d02abb5-4337-440f-a02f-62f571856218 58f7c51142914f8ca5364b053bee5ad5 b2e4daac950844b2b8abc906f55ccbd1 - default default] [instance: 20333ac0-5c0a-4acb-920f-2dbbb5567b7d] Total disk: 7600 GB, used: 25.00 GB
2021-06-09 07:52:02.844 6222 INFO nova.compute.claims [req-7d02abb5-4337-440f-a02f-62f571856218 58f7c51142914f8ca5364b053bee5ad5 b2e4daac950844b2b8abc906f55ccbd1 - default default] [instance: 20333ac0-5c0a-4acb-920f-2dbbb5567b7d] disk limit: 7600.00 GB, free: 7575.00 GB
2021-06-09 07:52:02.845 6222 INFO nova.compute.claims [req-7d02abb5-4337-440f-a02f-62f571856218 58f7c51142914f8ca5364b053bee5ad5 b2e4daac950844b2b8abc906f55ccbd1 - default default] [instance: 20333ac0-5c0a-4acb-920f-2dbbb5567b7d] Total vcpu: 56 VCPU, used: 1.00 VCPU
2021-06-09 07:52:02.845 6222 INFO nova.compute.claims [req-7d02abb5-4337-440f-a02f-62f571856218 58f7c51142914f8ca5364b053bee5ad5 b2e4daac950844b2b8abc906f55ccbd1 - default default] [instance: 20333ac0-5c0a-4acb-920f-2dbbb5567b7d] vcpu limit: 112.00 VCPU, free: 111.00 VCPU
2021-06-09 07:52:02.848 6222 INFO nova.compute.claims [req-7d02abb5-4337-440f-a02f-62f571856218 58f7c51142914f8ca5364b053bee5ad5 b2e4daac950844b2b8abc906f55ccbd1 - default default] [instance: 20333ac0-5c0a-4acb-920f-2dbbb5567b7d] Claim successful on node zbk130721.zbk.sys11cloud.net
2021-06-09 07:52:04.470 6222 INFO nova.virt.libvirt.driver [req-7d02abb5-4337-440f-a02f-62f571856218 58f7c51142914f8ca5364b053bee5ad5 b2e4daac950844b2b8abc906f55ccbd1 - default default] [instance: 20333ac0-5c0a-4acb-920f-2dbbb5567b7d] Creating image

>>> Note that the messages about "Final resource view", which normally occur every minute, don't happen here.

2021-06-09 07:53:03.997 6222 WARNING nova.compute.manager [req-05df4f56-bf30-4010-bf69-84138fa6e9c3 b5eda099dee946f98035f38053ad40a2 ee12936a687f4c709451ee9b55b3bd21 - default default] [instance: 20333ac0-5c0a-4acb-920f-2dbbb5567b7d] Received unexpected event network-vif-unplugged-83f83edc-9b4c-4c77-8e49-4bf8b95c0a19 for instance with vm_state building and task_state spawning.
2021-06-09 07:53:03.998 6222 WARNING nova.compute.manager [req-c8009d14-7bdc-419e-94ac-aa2708cf489c b5eda099dee946f98035f38053ad40a2 ee12936a687f4c709451ee9b55b3bd21 - default default] [instance: 20333ac0-5c0a-4acb-920f-2dbbb5567b7d] Received unexpected event network-vif-plugged-83f83edc-9b4c-4c77-8e49-4bf8b95c0a19 for instance with vm_state building and task_state spawning.
2021-06-09 07:53:19.534 6222 WARNING oslo.service.loopingcall [-] Function 'nova.servicegroup.drivers.db.DbDriver._report_state' run outlasted interval by 5.54 sec
2021-06-09 07:54:19.760 6222 WARNING oslo.service.loopingcall [-] Function 'nova.servicegroup.drivers.db.DbDriver._report_state' run outlasted interval by 50.22 sec
2021-06-09 07:54:43.328 6222 WARNING oslo.service.loopingcall [-] Function 'nova.servicegroup.drivers.db.DbDriver._report_state' run outlasted interval by 13.56 sec
2021-06-09 07:58:43.414 6222 ERROR oslo.messaging._drivers.impl_rabbit [-] [309689ae-b7f0-4c70-b8f5-48df7a3c53eb] AMQP server on zbk130719.zbk.sys11cloud.net:5671 is unreachable: [Errno 104] Connection reset by peer. Trying again in 1 seconds.: error: [Errno 104] Connection reset by peer
2021-06-09 07:58:43.416 6222 ERROR oslo.messaging._drivers.impl_rabbit [-] [9d3d68e2-26c9-4cb2-83fe-c04a75ca53e6] AMQP server on zbk130709.zbk.sys11cloud.net:5671 is unreachable: [Errno 104] Connection reset by peer. Trying again in 1 seconds.: error: [Errno 104] Connection reset by peer
2021-06-09 07:58:43.417 6222 INFO oslo.messaging._drivers.impl_rabbit [-] A recoverable connection/channel error occurred, trying to reconnect: [Errno 104] Connection reset by peer
2021-06-09 07:58:43.425 6222 INFO oslo.messaging._drivers.impl_rabbit [-] A recoverable connection/channel error occurred, trying to reconnect: [Errno 104] Connection reset by peer
2021-06-09 07:58:43.431 6222 WARNING nova.servicegroup.drivers.db [-] Lost connection to nova-conductor for reporting service status.: MessagingTimeout: Timed out waiting for a reply to message ID 519626b5a145499b8ce2c856733f6b62
2021-06-09 07:58:43.432 6222 WARNING oslo.service.loopingcall [-] Function 'nova.servicegroup.drivers.db.DbDriver._report_state' run outlasted interval by 193.92 sec
2021-06-09 07:58:43.432 6222 ERROR nova.network.base_api [req-c8009d14-7bdc-419e-94ac-aa2708cf489c b5eda099dee946f98035f38053ad40a2 ee12936a687f4c709451ee9b55b3bd21 - default default] [instance: 20333ac0-5c0a-4acb-920f-2dbbb5567b7d] Failed storing info cache: MessagingTimeout: Timed out waiting for a reply to message ID 289a0168b6914bc797441bc9e1e965b7
2021-06-09 07:58:43.432 6222 ERROR nova.network.base_api [instance: 20333ac0-5c0a-4acb-920f-2dbbb5567b7d] Traceback (most recent call last):
2021-06-09 07:58:43.432 6222 ERROR nova.network.base_api [instance: 20333ac0-5c0a-4acb-920f-2dbbb5567b7d]   File "/usr/lib/python2.7/dist-packages/nova/network/base_api.py", line 55, in update_instance_cache_with_nw_info
2021-06-09 07:58:43.432 6222 ERROR nova.network.base_api [instance: 20333ac0-5c0a-4acb-920f-2dbbb5567b7d]     ic.save(update_cells=update_cells)
2021-06-09 07:58:43.432 6222 ERROR nova.network.base_api [instance: 20333ac0-5c0a-4acb-920f-2dbbb5567b7d]   File "/usr/lib/python2.7/dist-packages/oslo_versionedobjects/base.py", line 210, in wrapper
2021-06-09 07:58:43.432 6222 ERROR nova.network.base_api [instance: 20333ac0-5c0a-4acb-920f-2dbbb5567b7d]     ctxt, self, fn.__name__, args, kwargs)
2021-06-09 07:58:43.432 6222 ERROR nova.network.base_api [instance: 20333ac0-5c0a-4acb-920f-2dbbb5567b7d]   File "/usr/lib/python2.7/dist-packages/nova/conductor/rpcapi.py", line 245, in object_action
2021-06-09 07:58:43.432 6222 ERROR nova.network.base_api [instance: 20333ac0-5c0a-4acb-920f-2dbbb5567b7d]     objmethod=objmethod, args=args, kwargs=kwargs)
2021-06-09 07:58:43.432 6222 ERROR nova.network.base_api [instance: 20333ac0-5c0a-4acb-920f-2dbbb5567b7d]   File "/usr/lib/python2.7/dist-packages/oslo_messaging/rpc/client.py", line 174, in call
2021-06-09 07:58:43.432 6222 ERROR nova.network.base_api [instance: 20333ac0-5c0a-4acb-920f-2dbbb5567b7d]     retry=self.retry)
2021-06-09 07:58:43.432 6222 ERROR nova.network.base_api [instance: 20333ac0-5c0a-4acb-920f-2dbbb5567b7d]   File "/usr/lib/python2.7/dist-packages/oslo_messaging/transport.py", line 131, in _send
2021-06-09 07:58:43.432 6222 ERROR nova.network.base_api [instance: 20333ac0-5c0a-4acb-920f-2dbbb5567b7d]     timeout=timeout, retry=retry)
2021-06-09 07:58:43.432 6222 ERROR nova.network.base_api [instance: 20333ac0-5c0a-4acb-920f-2dbbb5567b7d]   File "/usr/lib/python2.7/dist-packages/oslo_messaging/_drivers/amqpdriver.py", line 625, in send
2021-06-09 07:58:43.432 6222 ERROR nova.network.base_api [instance: 20333ac0-5c0a-4acb-920f-2dbbb5567b7d]     retry=retry)
2021-06-09 07:58:43.432 6222 ERROR nova.network.base_api [instance: 20333ac0-5c0a-4acb-920f-2dbbb5567b7d]   File "/usr/lib/python2.7/dist-packages/oslo_messaging/_drivers/amqpdriver.py", line 614, in _send
2021-06-09 07:58:43.432 6222 ERROR nova.network.base_api [instance: 20333ac0-5c0a-4acb-920f-2dbbb5567b7d]     result = self._waiter.wait(msg_id, timeout)
2021-06-09 07:58:43.432 6222 ERROR nova.network.base_api [instance: 20333ac0-5c0a-4acb-920f-2dbbb5567b7d]   File "/usr/lib/python2.7/dist-packages/oslo_messaging/_drivers/amqpdriver.py", line 506, in wait
2021-06-09 07:58:43.432 6222 ERROR nova.network.base_api [instance: 20333ac0-5c0a-4acb-920f-2dbbb5567b7d]     message = self.waiters.get(msg_id, timeout=timeout)
2021-06-09 07:58:43.432 6222 ERROR nova.network.base_api [instance: 20333ac0-5c0a-4acb-920f-2dbbb5567b7d]   File "/usr/lib/python2.7/dist-packages/oslo_messaging/_drivers/amqpdriver.py", line 394, in get
2021-06-09 07:58:43.432 6222 ERROR nova.network.base_api [instance: 20333ac0-5c0a-4acb-920f-2dbbb5567b7d]     'to message ID %s' % msg_id)
2021-06-09 07:58:43.432 6222 ERROR nova.network.base_api [instance: 20333ac0-5c0a-4acb-920f-2dbbb5567b7d] MessagingTimeout: Timed out waiting for a reply to message ID 289a0168b6914bc797441bc9e1e965b7
2021-06-09 07:58:43.432 6222 ERROR nova.network.base_api [instance: 20333ac0-5c0a-4acb-920f-2dbbb5567b7d] 
2021-06-09 07:58:43.438 6222 ERROR oslo_messaging.rpc.server [req-c8009d14-7bdc-419e-94ac-aa2708cf489c b5eda099dee946f98035f38053ad40a2 ee12936a687f4c709451ee9b55b3bd21 - default default] Exception during message handling: MessagingTimeout: Timed out waiting for a reply to message ID 289a0168b6914bc797441bc9e1e965b7
2021-06-09 07:58:43.438 6222 ERROR oslo_messaging.rpc.server Traceback (most recent call last):
2021-06-09 07:58:43.438 6222 ERROR oslo_messaging.rpc.server   File "/usr/lib/python2.7/dist-packages/oslo_messaging/rpc/server.py", line 166, in _process_incoming
2021-06-09 07:58:43.438 6222 ERROR oslo_messaging.rpc.server     res = self.dispatcher.dispatch(message)
2021-06-09 07:58:43.438 6222 ERROR oslo_messaging.rpc.server   File "/usr/lib/python2.7/dist-packages/oslo_messaging/rpc/dispatcher.py", line 220, in dispatch
2021-06-09 07:58:43.438 6222 ERROR oslo_messaging.rpc.server     return self._do_dispatch(endpoint, method, ctxt, args)
2021-06-09 07:58:43.438 6222 ERROR oslo_messaging.rpc.server   File "/usr/lib/python2.7/dist-packages/oslo_messaging/rpc/dispatcher.py", line 190, in _do_dispatch
2021-06-09 07:58:43.438 6222 ERROR oslo_messaging.rpc.server     result = func(ctxt, **new_args)
2021-06-09 07:58:43.438 6222 ERROR oslo_messaging.rpc.server   File "/usr/lib/python2.7/dist-packages/nova/exception_wrapper.py", line 76, in wrapped
2021-06-09 07:58:43.438 6222 ERROR oslo_messaging.rpc.server     function_name, call_dict, binary)
2021-06-09 07:58:43.438 6222 ERROR oslo_messaging.rpc.server   File "/usr/lib/python2.7/dist-packages/oslo_utils/excutils.py", line 220, in __exit__
2021-06-09 07:58:43.438 6222 ERROR oslo_messaging.rpc.server     self.force_reraise()
2021-06-09 07:58:43.438 6222 ERROR oslo_messaging.rpc.server   File "/usr/lib/python2.7/dist-packages/oslo_utils/excutils.py", line 196, in force_reraise
2021-06-09 07:58:43.438 6222 ERROR oslo_messaging.rpc.server     six.reraise(self.type_, self.value, self.tb)
2021-06-09 07:58:43.438 6222 ERROR oslo_messaging.rpc.server   File "/usr/lib/python2.7/dist-packages/nova/exception_wrapper.py", line 67, in wrapped
2021-06-09 07:58:43.438 6222 ERROR oslo_messaging.rpc.server     return f(self, context, *args, **kw)
2021-06-09 07:58:43.438 6222 ERROR oslo_messaging.rpc.server   File "/usr/lib/python2.7/dist-packages/nova/compute/manager.py", line 7961, in external_instance_event
2021-06-09 07:58:43.438 6222 ERROR oslo_messaging.rpc.server     context, instance, refresh_vif_id=event.tag)
2021-06-09 07:58:43.438 6222 ERROR oslo_messaging.rpc.server   File "/usr/lib/python2.7/dist-packages/nova/network/base_api.py", line 257, in get_instance_nw_info
2021-06-09 07:58:43.438 6222 ERROR oslo_messaging.rpc.server     update_cells=update_cells)
2021-06-09 07:58:43.438 6222 ERROR oslo_messaging.rpc.server   File "/usr/lib/python2.7/dist-packages/nova/hooks.py", line 154, in inner
2021-06-09 07:58:43.438 6222 ERROR oslo_messaging.rpc.server     rv = f(*args, **kwargs)
2021-06-09 07:58:43.438 6222 ERROR oslo_messaging.rpc.server   File "/usr/lib/python2.7/dist-packages/nova/network/base_api.py", line 59, in update_instance_cache_with_nw_info
2021-06-09 07:58:43.438 6222 ERROR oslo_messaging.rpc.server     LOG.exception('Failed storing info cache', instance=instance)
2021-06-09 07:58:43.438 6222 ERROR oslo_messaging.rpc.server   File "/usr/lib/python2.7/dist-packages/oslo_utils/excutils.py", line 220, in __exit__
2021-06-09 07:58:43.438 6222 ERROR oslo_messaging.rpc.server     self.force_reraise()
2021-06-09 07:58:43.438 6222 ERROR oslo_messaging.rpc.server   File "/usr/lib/python2.7/dist-packages/oslo_utils/excutils.py", line 196, in force_reraise
2021-06-09 07:58:43.438 6222 ERROR oslo_messaging.rpc.server     six.reraise(self.type_, self.value, self.tb)
2021-06-09 07:58:43.438 6222 ERROR oslo_messaging.rpc.server   File "/usr/lib/python2.7/dist-packages/nova/network/base_api.py", line 55, in update_instance_cache_with_nw_info
2021-06-09 07:58:43.438 6222 ERROR oslo_messaging.rpc.server     ic.save(update_cells=update_cells)
2021-06-09 07:58:43.438 6222 ERROR oslo_messaging.rpc.server   File "/usr/lib/python2.7/dist-packages/oslo_versionedobjects/base.py", line 210, in wrapper
2021-06-09 07:58:43.438 6222 ERROR oslo_messaging.rpc.server     ctxt, self, fn.__name__, args, kwargs)
2021-06-09 07:58:43.438 6222 ERROR oslo_messaging.rpc.server   File "/usr/lib/python2.7/dist-packages/nova/conductor/rpcapi.py", line 245, in object_action
2021-06-09 07:58:43.438 6222 ERROR oslo_messaging.rpc.server     objmethod=objmethod, args=args, kwargs=kwargs)
2021-06-09 07:58:43.438 6222 ERROR oslo_messaging.rpc.server   File "/usr/lib/python2.7/dist-packages/oslo_messaging/rpc/client.py", line 174, in call
2021-06-09 07:58:43.438 6222 ERROR oslo_messaging.rpc.server     retry=self.retry)
2021-06-09 07:58:43.438 6222 ERROR oslo_messaging.rpc.server   File "/usr/lib/python2.7/dist-packages/oslo_messaging/transport.py", line 131, in _send
2021-06-09 07:58:43.438 6222 ERROR oslo_messaging.rpc.server     timeout=timeout, retry=retry)
2021-06-09 07:58:43.438 6222 ERROR oslo_messaging.rpc.server   File "/usr/lib/python2.7/dist-packages/oslo_messaging/_drivers/amqpdriver.py", line 625, in send
2021-06-09 07:58:43.438 6222 ERROR oslo_messaging.rpc.server     retry=retry)
2021-06-09 07:58:43.438 6222 ERROR oslo_messaging.rpc.server   File "/usr/lib/python2.7/dist-packages/oslo_messaging/_drivers/amqpdriver.py", line 614, in _send
2021-06-09 07:58:43.438 6222 ERROR oslo_messaging.rpc.server     result = self._waiter.wait(msg_id, timeout)
2021-06-09 07:58:43.438 6222 ERROR oslo_messaging.rpc.server   File "/usr/lib/python2.7/dist-packages/oslo_messaging/_drivers/amqpdriver.py", line 506, in wait
2021-06-09 07:58:43.438 6222 ERROR oslo_messaging.rpc.server     message = self.waiters.get(msg_id, timeout=timeout)
2021-06-09 07:58:43.438 6222 ERROR oslo_messaging.rpc.server   File "/usr/lib/python2.7/dist-packages/oslo_messaging/_drivers/amqpdriver.py", line 394, in get
2021-06-09 07:58:43.438 6222 ERROR oslo_messaging.rpc.server     'to message ID %s' % msg_id)
2021-06-09 07:58:43.438 6222 ERROR oslo_messaging.rpc.server MessagingTimeout: Timed out waiting for a reply to message ID 289a0168b6914bc797441bc9e1e965b7
2021-06-09 07:58:43.438 6222 ERROR oslo_messaging.rpc.server 
2021-06-09 07:59:09.484 6222 ERROR oslo.messaging._drivers.impl_rabbit [-] [52c6bb57-5ca9-4e12-a914-e3456309a7b4] AMQP server on zbk130709.zbk.sys11cloud.net:5671 is unreachable: [Errno 104] Connection reset by peer. Trying again in 1 seconds.: error: [Errno 104] Connection reset by peer
2021-06-09 08:01:25.116 6222 ERROR oslo.messaging._drivers.impl_rabbit [-] [9d3d68e2-26c9-4cb2-83fe-c04a75ca53e6] AMQP server on zbk130709.zbk.sys11cloud.net:5671 is unreachable: <AMQPError: unknown error>. Trying again in 1 seconds.: RecoverableConnectionError: <AMQPError: unknown error>
2021-06-09 08:01:25.118 6222 ERROR oslo.messaging._drivers.impl_rabbit [-] [309689ae-b7f0-4c70-b8f5-48df7a3c53eb] AMQP server on zbk130719.zbk.sys11cloud.net:5671 is unreachable: <AMQPError: unknown error>. Trying again in 1 seconds.: RecoverableConnectionError: <AMQPError: unknown error>
2021-06-09 08:02:30.541 6222 ERROR oslo.messaging._drivers.impl_rabbit [-] [52c6bb57-5ca9-4e12-a914-e3456309a7b4] AMQP server on zbk130709.zbk.sys11cloud.net:5671 is unreachable: [Errno 104] Connection reset by peer. Trying again in 1 seconds.: error: [Errno 104] Connection reset by peer
2021-06-09 08:02:30.587 6222 INFO oslo.messaging._drivers.impl_rabbit [-] [9d3d68e2-26c9-4cb2-83fe-c04a75ca53e6] Reconnected to AMQP server on zbk130709.zbk.sys11cloud.net:5671 via [amqp] client with port 56558.
2021-06-09 08:02:30.590 6222 INFO oslo_messaging._drivers.amqpdriver [-] No calling threads waiting for msg_id : 289a0168b6914bc797441bc9e1e965b7
2021-06-09 08:02:30.591 6222 INFO oslo_messaging._drivers.amqpdriver [-] No calling threads waiting for msg_id : 519626b5a145499b8ce2c856733f6b62
2021-06-09 08:02:30.599 6222 INFO oslo.messaging._drivers.impl_rabbit [-] [309689ae-b7f0-4c70-b8f5-48df7a3c53eb] Reconnected to AMQP server on zbk130719.zbk.sys11cloud.net:5671 via [amqp] client with port 56494.
2021-06-09 08:02:31.581 6222 INFO oslo.messaging._drivers.impl_rabbit [-] [52c6bb57-5ca9-4e12-a914-e3456309a7b4] Reconnected to AMQP server on zbk130717.zbk.sys11cloud.net:5671 via [amqp] client with port 32840.
2021-06-09 08:02:31.591 6222 INFO nova.compute.resource_tracker [req-4891bc71-73fd-43f9-961e-737437c09c72 - - - - -] Final resource view: name=zbk130721.zbk.sys11cloud.net phys_ram=515889MB used_ram=8192MB phys_disk=7600GB used_disk=75GB total_vcpus=56 used_vcpus=3 pci_stats=[]
2021-06-09 08:02:31.653 6222 INFO nova.servicegroup.drivers.db [-] Recovered from being unable to report status.
2021-06-09 08:02:31.653 6222 WARNING oslo.service.loopingcall [-] Function 'nova.servicegroup.drivers.db.DbDriver._report_state' run outlasted interval by 192.17 sec
2021-06-09 08:02:50.660 6222 WARNING nova.compute.manager [req-4891bc71-73fd-43f9-961e-737437c09c72 - - - - -] While synchronizing instance power states, found 2 instances in the database and 1 instances on the hypervisor.
2021-06-09 08:02:51.929 6222 INFO nova.compute.resource_tracker [req-4891bc71-73fd-43f9-961e-737437c09c72 - - - - -] Final resource view: name=zbk130721.zbk.sys11cloud.net phys_ram=515889MB used_ram=8192MB phys_disk=7600GB used_disk=75GB total_vcpus=56 used_vcpus=3 pci_stats=[]
2021-06-09 08:03:12.479 6222 INFO nova.compute.resource_tracker [req-4891bc71-73fd-43f9-961e-737437c09c72 - - - - -] Final resource view: name=zbk130721.zbk.sys11cloud.net phys_ram=515889MB used_ram=8192MB phys_disk=7600GB used_disk=75GB total_vcpus=56 used_vcpus=3 pci_stats=[]
2021-06-09 08:04:12.623 6222 INFO nova.compute.resource_tracker [req-4891bc71-73fd-43f9-961e-737437c09c72 - - - - -] Final resource view: name=zbk130721.zbk.sys11cloud.net phys_ram=515889MB used_ram=8192MB phys_disk=7600GB used_disk=75GB total_vcpus=56 used_vcpus=3 pci_stats=[]
2021-06-09 08:05:14.482 6222 INFO nova.compute.resource_tracker [req-4891bc71-73fd-43f9-961e-737437c09c72 - - - - -] Final resource view: name=zbk130721.zbk.sys11cloud.net phys_ram=515889MB used_ram=8192MB phys_disk=7600GB used_disk=75GB total_vcpus=56 used_vcpus=3 pci_stats=[]
2021-06-09 08:06:16.669 6222 INFO nova.compute.resource_tracker [req-4891bc71-73fd-43f9-961e-737437c09c72 - - - - -] Final resource view: name=zbk130721.zbk.sys11cloud.net phys_ram=515889MB used_ram=8192MB phys_disk=7600GB used_disk=75GB total_vcpus=56 used_vcpus=3 pci_stats=[]
2021-06-09 08:07:16.486 6222 INFO nova.compute.resource_tracker [req-4891bc71-73fd-43f9-961e-737437c09c72 - - - - -] Final resource view: name=zbk130721.zbk.sys11cloud.net phys_ram=515889MB used_ram=8192MB phys_disk=7600GB used_disk=75GB total_vcpus=56 used_vcpus=3 pci_stats=[]
2021-06-09 08:07:42.088 6222 INFO nova.network.linux_net [req-7d02abb5-4337-440f-a02f-62f571856218 58f7c51142914f8ca5364b053bee5ad5 b2e4daac950844b2b8abc906f55ccbd1 - default default] SysEleven: binding midonet port 83f83edc-9b4c-4c77-8e49-4bf8b95c0a19 on dev tap83f83edc-9b
2021-06-09 08:07:43.641 6222 INFO nova.compute.manager [req-885630f3-d18c-4ca9-83ec-beb08f4dfe52 - - - - -] [instance: 20333ac0-5c0a-4acb-920f-2dbbb5567b7d] VM Resumed (Lifecycle Event)
2021-06-09 08:07:43.650 6222 INFO nova.virt.libvirt.driver [-] [instance: 20333ac0-5c0a-4acb-920f-2dbbb5567b7d] Instance spawned successfully.
2021-06-09 08:07:43.651 6222 INFO nova.compute.manager [req-7d02abb5-4337-440f-a02f-62f571856218 58f7c51142914f8ca5364b053bee5ad5 b2e4daac950844b2b8abc906f55ccbd1 - default default] [instance: 20333ac0-5c0a-4acb-920f-2dbbb5567b7d] Took 939.18 seconds to spawn the instance on the hypervisor.
2021-06-09 08:07:43.843 6222 INFO nova.network.linux_net [req-885630f3-d18c-4ca9-83ec-beb08f4dfe52 - - - - -] SysEleven: binding midonet port 83f83edc-9b4c-4c77-8e49-4bf8b95c0a19 on dev tap83f83edc-9b
2021-06-09 08:07:43.863 6222 INFO nova.compute.manager [req-7d02abb5-4337-440f-a02f-62f571856218 58f7c51142914f8ca5364b053bee5ad5 b2e4daac950844b2b8abc906f55ccbd1 - default default] [instance: 20333ac0-5c0a-4acb-920f-2dbbb5567b7d] Took 941.10 seconds to build instance.
2021-06-09 08:07:43.957 6222 INFO nova.compute.manager [-] [instance: 20333ac0-5c0a-4acb-920f-2dbbb5567b7d] During sync_power_state the instance has a pending task (spawning). Skip.
2021-06-09 08:07:44.058 6222 INFO nova.compute.manager [req-885630f3-d18c-4ca9-83ec-beb08f4dfe52 - - - - -] [instance: 20333ac0-5c0a-4acb-920f-2dbbb5567b7d] VM Started (Lifecycle Event)
2021-06-09 08:08:17.050 6222 INFO nova.compute.resource_tracker [req-4891bc71-73fd-43f9-961e-737437c09c72 - - - - -] Final resource view: name=zbk130721.zbk.sys11cloud.net phys_ram=515889MB used_ram=8192MB phys_disk=7600GB used_disk=75GB total_vcpus=56 used_vcpus=3 pci_stats=[]


With the above patch applied, and the VM creation repeated, it succeeds (I had added lots of extra logging as well):

2021-06-09 15:13:19.469 45120 INFO nova.compute.claims [req-061b67d6-92d0-47ec-a2ce-969beefb940e 58f7c51142914f8ca5364b053bee5ad5 b2e4daac950844b2b8abc906f55ccbd1 - default default] [instance: 7fd69c0b-312f-4532-9944-9a59fe5a96a3] Attempting claim on node zbk130721.zbk.sys11cloud.net: memory 4096 MB, disk 50 GB, vcpus 2 CPU
2021-06-09 15:13:19.471 45120 INFO nova.compute.claims [req-061b67d6-92d0-47ec-a2ce-969beefb940e 58f7c51142914f8ca5364b053bee5ad5 b2e4daac950844b2b8abc906f55ccbd1 - default default] [instance: 7fd69c0b-312f-4532-9944-9a59fe5a96a3] Total memory: 515889 MB, used: 4096.00 MB
2021-06-09 15:13:19.472 45120 INFO nova.compute.claims [req-061b67d6-92d0-47ec-a2ce-969beefb940e 58f7c51142914f8ca5364b053bee5ad5 b2e4daac950844b2b8abc906f55ccbd1 - default default] [instance: 7fd69c0b-312f-4532-9944-9a59fe5a96a3] memory limit: 419159.00 MB, free: 415063.00 MB
2021-06-09 15:13:19.472 45120 INFO nova.compute.claims [req-061b67d6-92d0-47ec-a2ce-969beefb940e 58f7c51142914f8ca5364b053bee5ad5 b2e4daac950844b2b8abc906f55ccbd1 - default default] [instance: 7fd69c0b-312f-4532-9944-9a59fe5a96a3] Total disk: 7600 GB, used: 25.00 GB
2021-06-09 15:13:19.473 45120 INFO nova.compute.claims [req-061b67d6-92d0-47ec-a2ce-969beefb940e 58f7c51142914f8ca5364b053bee5ad5 b2e4daac950844b2b8abc906f55ccbd1 - default default] [instance: 7fd69c0b-312f-4532-9944-9a59fe5a96a3] disk limit: 7600.00 GB, free: 7575.00 GB
2021-06-09 15:13:19.474 45120 INFO nova.compute.claims [req-061b67d6-92d0-47ec-a2ce-969beefb940e 58f7c51142914f8ca5364b053bee5ad5 b2e4daac950844b2b8abc906f55ccbd1 - default default] [instance: 7fd69c0b-312f-4532-9944-9a59fe5a96a3] Total vcpu: 56 VCPU, used: 1.00 VCPU
2021-06-09 15:13:19.474 45120 INFO nova.compute.claims [req-061b67d6-92d0-47ec-a2ce-969beefb940e 58f7c51142914f8ca5364b053bee5ad5 b2e4daac950844b2b8abc906f55ccbd1 - default default] [instance: 7fd69c0b-312f-4532-9944-9a59fe5a96a3] vcpu limit: 112.00 VCPU, free: 111.00 VCPU
2021-06-09 15:13:19.476 45120 INFO nova.compute.claims [req-061b67d6-92d0-47ec-a2ce-969beefb940e 58f7c51142914f8ca5364b053bee5ad5 b2e4daac950844b2b8abc906f55ccbd1 - default default] [instance: 7fd69c0b-312f-4532-9944-9a59fe5a96a3] Claim successful on node zbk130721.zbk.sys11cloud.net
2021-06-09 15:13:20.103 45120 INFO nova.virt.osinfo [req-061b67d6-92d0-47ec-a2ce-969beefb940e 58f7c51142914f8ca5364b053bee5ad5 b2e4daac950844b2b8abc906f55ccbd1 - default default] Cannot load Libosinfo: (No module named gi.repository.Libosinfo)
2021-06-09 15:13:21.167 45120 INFO nova.virt.libvirt.driver [req-061b67d6-92d0-47ec-a2ce-969beefb940e 58f7c51142914f8ca5364b053bee5ad5 b2e4daac950844b2b8abc906f55ccbd1 - default default] [instance: 7fd69c0b-312f-4532-9944-9a59fe5a96a3] Creating image
2021-06-09 15:13:21.168 45120 WARNING nova.virt.libvirt.driver [req-061b67d6-92d0-47ec-a2ce-969beefb940e 58f7c51142914f8ca5364b053bee5ad5 b2e4daac950844b2b8abc906f55ccbd1 - default default] [instance: 7fd69c0b-312f-4532-9944-9a59fe5a96a3] disk_mapping: {'disk': {'bus': 'virtio', 'boot_index': '1', 'type': 'disk', 'dev': u'vda'}, 'root': {'bus': 'virtio', 'boot_index': '1', 'type': 'disk', 'dev': u'vda'}}
2021-06-09 15:13:21.169 45120 WARNING nova.virt.libvirt.driver [req-061b67d6-92d0-47ec-a2ce-969beefb940e 58f7c51142914f8ca5364b053bee5ad5 b2e4daac950844b2b8abc906f55ccbd1 - default default] [instance: 7fd69c0b-312f-4532-9944-9a59fe5a96a3] disk_images: None
2021-06-09 15:13:21.170 45120 WARNING nova.virt.libvirt.driver [req-061b67d6-92d0-47ec-a2ce-969beefb940e 58f7c51142914f8ca5364b053bee5ad5 b2e4daac950844b2b8abc906f55ccbd1 - default default] [instance: 7fd69c0b-312f-4532-9944-9a59fe5a96a3] disk_images: {'kernel_id': u'', 'image_id': u'aad4f7fd-d7be-448e-9579-1dfbcfc1fdba', 'ramdisk_id': u''}
2021-06-09 15:13:21.171 45120 WARNING nova.virt.libvirt.driver [req-061b67d6-92d0-47ec-a2ce-969beefb940e 58f7c51142914f8ca5364b053bee5ad5 b2e4daac950844b2b8abc906f55ccbd1 - default default] [instance: 7fd69c0b-312f-4532-9944-9a59fe5a96a3] CONF.libvirt.virt_type = kvm
2021-06-09 15:13:21.172 45120 WARNING nova.virt.libvirt.driver [req-061b67d6-92d0-47ec-a2ce-969beefb940e 58f7c51142914f8ca5364b053bee5ad5 b2e4daac950844b2b8abc906f55ccbd1 - default default] [instance: 7fd69c0b-312f-4532-9944-9a59fe5a96a3] Calling self._create_and_inject_local_root(context, instance,...
2021-06-09 15:13:21.174 45120 WARNING nova.virt.libvirt.driver [req-061b67d6-92d0-47ec-a2ce-969beefb940e 58f7c51142914f8ca5364b053bee5ad5 b2e4daac950844b2b8abc906f55ccbd1 - default default] [instance: 7fd69c0b-312f-4532-9944-9a59fe5a96a3] _create_and_inject_local_root: need_inject = False
2021-06-09 15:13:21.175 45120 WARNING nova.virt.libvirt.driver [req-061b67d6-92d0-47ec-a2ce-969beefb940e 58f7c51142914f8ca5364b053bee5ad5 b2e4daac950844b2b8abc906f55ccbd1 - default default] [instance: 7fd69c0b-312f-4532-9944-9a59fe5a96a3] _create_and_inject_local_root: booted_from_volume = False
2021-06-09 15:13:21.176 45120 WARNING nova.virt.libvirt.driver [req-061b67d6-92d0-47ec-a2ce-969beefb940e 58f7c51142914f8ca5364b053bee5ad5 b2e4daac950844b2b8abc906f55ccbd1 - default default] [instance: 7fd69c0b-312f-4532-9944-9a59fe5a96a3] not booted_from_volume: root_fname=fc2284ec9a4126f54c519ddbb9449ce1ca2f52de, size=53687091200
2021-06-09 15:13:21.177 45120 WARNING nova.virt.libvirt.driver [req-061b67d6-92d0-47ec-a2ce-969beefb940e 58f7c51142914f8ca5364b053bee5ad5 b2e4daac950844b2b8abc906f55ccbd1 - default default] [instance: 7fd69c0b-312f-4532-9944-9a59fe5a96a3] backend=<nova.virt.libvirt.imagebackend.Lvm object at 0x7f8bd4462c50>
2021-06-09 15:13:21.177 45120 WARNING nova.virt.libvirt.driver [req-061b67d6-92d0-47ec-a2ce-969beefb940e 58f7c51142914f8ca5364b053bee5ad5 b2e4daac950844b2b8abc906f55ccbd1 - default default] [instance: 7fd69c0b-312f-4532-9944-9a59fe5a96a3] ****** fetch_func = libvirt_utils.fetch_image
2021-06-09 15:13:21.178 45120 WARNING nova.virt.libvirt.driver [req-061b67d6-92d0-47ec-a2ce-969beefb940e 58f7c51142914f8ca5364b053bee5ad5 b2e4daac950844b2b8abc906f55ccbd1 - default default] [instance: 7fd69c0b-312f-4532-9944-9a59fe5a96a3] fetch_func = <function fetch_image at 0x7f8bda2fc6e0>
2021-06-09 15:13:21.178 45120 WARNING nova.virt.libvirt.driver [req-061b67d6-92d0-47ec-a2ce-969beefb940e 58f7c51142914f8ca5364b053bee5ad5 b2e4daac950844b2b8abc906f55ccbd1 - default default] [instance: 7fd69c0b-312f-4532-9944-9a59fe5a96a3] Calling self._try_fetch_image_cache(backend, fetch_func, context...
2021-06-09 15:13:21.179 45120 WARNING nova.virt.libvirt.driver [req-061b67d6-92d0-47ec-a2ce-969beefb940e 58f7c51142914f8ca5364b053bee5ad5 b2e4daac950844b2b8abc906f55ccbd1 - default default] Entering _try_fetch_image_cache
2021-06-09 15:13:21.180 45120 WARNING nova.virt.libvirt.driver [req-061b67d6-92d0-47ec-a2ce-969beefb940e 58f7c51142914f8ca5364b053bee5ad5 b2e4daac950844b2b8abc906f55ccbd1 - default default] Calling image.cache(fetch_func=fetch_func,...  image=<nova.virt.libvirt.imagebackend.Lvm object at 0x7f8bd4462c50> fetch_func=<function fetch_image at 0x7f8bda2fc6e0>
2021-06-09 15:13:21.185 45120 WARNING nova.virt.libvirt.imagebackend [req-061b67d6-92d0-47ec-a2ce-969beefb940e 58f7c51142914f8ca5364b053bee5ad5 b2e4daac950844b2b8abc906f55ccbd1 - default default] Image.cache /var/lib/nova/instances/_base/fc2284ec9a4126f54c519ddbb9449ce1ca2f52de
2021-06-09 15:13:21.185 45120 WARNING nova.virt.libvirt.imagebackend [req-061b67d6-92d0-47ec-a2ce-969beefb940e 58f7c51142914f8ca5364b053bee5ad5 b2e4daac950844b2b8abc906f55ccbd1 - default default] Calling self.create_image(fetch_func_sync, base, size...
2021-06-09 15:13:21.186 45120 WARNING nova.virt.libvirt.imagebackend [req-061b67d6-92d0-47ec-a2ce-969beefb940e 58f7c51142914f8ca5364b053bee5ad5 b2e4daac950844b2b8abc906f55ccbd1 - default default] entering Lvm.create_image()
2021-06-09 15:13:21.189 45120 WARNING nova.virt.libvirt.imagebackend [req-061b67d6-92d0-47ec-a2ce-969beefb940e 58f7c51142914f8ca5364b053bee5ad5 b2e4daac950844b2b8abc906f55ccbd1 - default default] Entering @utils.synchronized(filename:fc2284ec9a4126f54c519ddbb9449ce1ca2f52de , external=True, lock_path=self.lock_path:/var/lib/nova/instances/locks) fetch_func_sync: base:/var/lib/nova/instances/_base/fc2284ec9a4126f54c519ddbb9449ce1ca2f52de target:/var/lib/nova/instances/_base/fc2284ec9a4126f54c519ddbb9449ce1ca2f52de exists:False
2021-06-09 15:13:21.190 45120 WARNING nova.virt.libvirt.imagebackend [req-061b67d6-92d0-47ec-a2ce-969beefb940e 58f7c51142914f8ca5364b053bee5ad5 b2e4daac950844b2b8abc906f55ccbd1 - default default] calling fetch_func = <function fetch_image at 0x7f8bda2fc6e0>
2021-06-09 15:13:21.190 45120 WARNING nova.virt.libvirt.utils [req-061b67d6-92d0-47ec-a2ce-969beefb940e 58f7c51142914f8ca5364b053bee5ad5 b2e4daac950844b2b8abc906f55ccbd1 - default default] Entering fetch_image(context, target, image_id): <Context {'domain': None, 'project_name': u'olaftestproject', 'global_request_id': None, 'project_domain': u'default', 'timestamp': '2021-06-09T15:13:15.571236', 'auth_token': u'gAAAAABgwNp2o7YzYYrCmVVSStn5yGfZ76CEqNPbwsDBppyuoyhM8WIYpvCI3UQIV63EwTwfumRmUoqOG3RgkT7lg2YpEjhqFTsreBmALUWNRAKSxAtXyeh33phmPrUB8OyVad-CLMlpsZl3v3YtGgCKhp0woYKH6ACeyHCyBu2KvOBdxwk0foE', 'remote_address': u'10.32.0.10, 10.32.0.4', 'quota_class': None, 'resource_uuid': None, 'is_admin': False, 'user': u'58f7c51142914f8ca5364b053bee5ad5', 'service_catalog': [{u'endpoints': [{u'adminURL': u'https://api.zbk.sys11cloud.net:9311', u'region': u'zbk', u'internalURL': u'https://api.zbk.sys11cloud.net:9311', u'publicURL': u'https://api.zbk.cloud.syseleven.net:9311'}], u'type': u'key-manager', u'name': u'barbican'}, {u'endpoints': [{u'adminURL': u'https://api.zbk.sys11cloud.net:8776/v3/b2e4daac950844b2b8abc906f55ccbd1', u'region': u'zbk', u'internalURL': u'https://api.zbk.sys11cloud.net:8776/v3/b2e4daac950844b2b8abc906f55ccbd1', u'publicURL': u'https://api.zbk.cloud.syseleven.net:8776/v3/b2e4daac950844b2b8abc906f55ccbd1'}], u'type': u'volumev3', u'name': u'cinderv3'}, {u'endpoints': [{u'adminURL': u'https://api.zbk.sys11cloud.net:9696', u'region': u'zbk', u'internalURL': u'https://api.zbk.sys11cloud.net:9696', u'publicURL': u'https://api.zbk.cloud.syseleven.net:9696'}], u'type': u'network', u'name': u'neutron'}, {u'endpoints': [{u'adminURL': u'https://api.zbk.sys11cloud.net:8776/v2/b2e4daac950844b2b8abc906f55ccbd1', u'region': u'zbk', u'internalURL': u'https://api.zbk.sys11cloud.net:8776/v2/b2e4daac950844b2b8abc906f55ccbd1', u'publicURL': u'https://api.zbk.cloud.syseleven.net:8776/v2/b2e4daac950844b2b8abc906f55ccbd1'}], u'type': u'volumev2', u'name': u'cinderv2'}, {u'endpoints': [{u'adminURL': u'https://api.zbk.sys11cloud.net:9292', u'region': u'zbk', u'internalURL': u'https://api.zbk.sys11cloud.net:9292', u'publicURL': u'https://api.zbk.cloud.syseleven.net:9292'}], u'type': u'image', u'name': u'glance'}, {u'endpoints': [{u'adminURL': u'https://api.zbk.sys11cloud.net:8778', u'region': u'zbk', u'internalURL': u'https://api.zbk.sys11cloud.net:8778'}], u'type': u'placement', u'name': u'placement'}], 'tenant': u'b2e4daac950844b2b8abc906f55ccbd1', 'read_only': False, 'project_id': u'b2e4daac950844b2b8abc906f55ccbd1', 'user_id': u'58f7c51142914f8ca5364b053bee5ad5', 'show_deleted': False, 'roles': [u'user', u'operator', u'viewer'], 'user_identity': u'58f7c51142914f8ca5364b053bee5ad5 b2e4daac950844b2b8abc906f55ccbd1 - default default', 'is_admin_project': True, 'project': u'b2e4daac950844b2b8abc906f55ccbd1', 'read_deleted': u'no', 'request_id': u'req-061b67d6-92d0-47ec-a2ce-969beefb940e', 'instance_lock_checked': False, 'user_domain': u'default', 'user_name': u'olaftestuser'}> /var/lib/nova/instances/_base/fc2284ec9a4126f54c519ddbb9449ce1ca2f52de aad4f7fd-d7be-448e-9579-1dfbcfc1fdba
2021-06-09 15:13:21.192 45120 WARNING nova.virt.images [req-061b67d6-92d0-47ec-a2ce-969beefb940e 58f7c51142914f8ca5364b053bee5ad5 b2e4daac950844b2b8abc906f55ccbd1 - default default] Entering fetch_to_raw() calling fetch()
2021-06-09 15:13:21.192 45120 WARNING nova.virt.images [req-061b67d6-92d0-47ec-a2ce-969beefb940e 58f7c51142914f8ca5364b053bee5ad5 b2e4daac950844b2b8abc906f55ccbd1 - default default] Entering fetch(), calling IMAGE_API.download(context, image_href, dest_path=path)
2021-06-09 15:13:21.193 45120 WARNING nova.image.api [req-061b67d6-92d0-47ec-a2ce-969beefb940e 58f7c51142914f8ca5364b053bee5ad5 b2e4daac950844b2b8abc906f55ccbd1 - default default] download: calling session.download() session:<nova.image.glance.GlanceImageServiceV2 object at 0x7f8bd437f650>
2021-06-09 15:13:21.194 45120 WARNING nova.image.glance [req-061b67d6-92d0-47ec-a2ce-969beefb940e 58f7c51142914f8ca5364b053bee5ad5 b2e4daac950844b2b8abc906f55ccbd1 - default default] Entering GlanceImageServiceV2.download()
2021-06-09 15:13:21.195 45120 WARNING nova.image.glance [req-061b67d6-92d0-47ec-a2ce-969beefb940e 58f7c51142914f8ca5364b053bee5ad5 b2e4daac950844b2b8abc906f55ccbd1 - default default] CONF.glance.allowed_direct_url_schemes=[]

>>> Printing a stack trace here to remember how we got here...
>>> Line numbers may be a bit off due to extra LOG statements...

2021-06-09 15:13:21.197 45120 WARNING nova.image.glance [req-061b67d6-92d0-47ec-a2ce-969beefb940e 58f7c51142914f8ca5364b053bee5ad5 b2e4daac950844b2b8abc906f55ccbd1 - default default] full stack trace: Traceback (most recent call last):
  File "/usr/lib/python2.7/dist-packages/nova/utils.py", line 938, in context_wrapper
    func(*args, **kwargs)
  File "/usr/lib/python2.7/dist-packages/oslo_concurrency/lockutils.py", line 277, in inner
    return f(*args, **kwargs)
  File "/usr/lib/python2.7/dist-packages/nova/compute/manager.py", line 1819, in _locked_do_build_and_run_instance
    result = self._do_build_and_run_instance(*args, **kwargs)
  File "/usr/lib/python2.7/dist-packages/nova/hooks.py", line 154, in inner
    rv = f(*args, **kwargs)
  File "/usr/lib/python2.7/dist-packages/nova/exception_wrapper.py", line 67, in wrapped
    return f(self, context, *args, **kw)
  File "/usr/lib/python2.7/dist-packages/nova/compute/manager.py", line 158, in decorated_function
    return function(self, context, *args, **kwargs)
  File "/usr/lib/python2.7/dist-packages/nova/compute/utils.py", line 1000, in decorated_function
    return function(self, context, *args, **kwargs)
  File "/usr/lib/python2.7/dist-packages/nova/compute/manager.py", line 204, in decorated_function
    return function(self, context, *args, **kwargs)
  File "/usr/lib/python2.7/dist-packages/nova/compute/manager.py", line 1923, in _do_build_and_run_instance
    filter_properties, request_spec)
  File "/usr/lib/python2.7/dist-packages/nova/compute/manager.py", line 2114, in _build_and_run_instance
    block_device_info=block_device_info)
  File "/usr/lib/python2.7/dist-packages/nova/virt/libvirt/driver.py", line 3153, in spawn
    block_device_info=block_device_info)
  File "/usr/lib/python2.7/dist-packages/nova/virt/libvirt/driver.py", line 3571, in _create_image
    fallback_from_host)
  File "/usr/lib/python2.7/dist-packages/nova/virt/libvirt/driver.py", line 3681, in _create_and_inject_local_root
    instance, size, fallback_from_host)
  File "/usr/lib/python2.7/dist-packages/nova/virt/libvirt/driver.py", line 7789, in _try_fetch_image_cache
    size=size)
  File "/usr/lib/python2.7/dist-packages/nova/virt/libvirt/imagebackend.py", line 284, in cache
    *args, **kwargs)
  File "/usr/lib/python2.7/dist-packages/nova/virt/libvirt/imagebackend.py", line 822, in create_image
    prepare_template(target=base, *args, **kwargs)
  File "/usr/lib/python2.7/dist-packages/oslo_concurrency/lockutils.py", line 277, in inner
    return f(*args, **kwargs)
  File "/usr/lib/python2.7/dist-packages/nova/virt/libvirt/imagebackend.py", line 277, in fetch_func_sync
    fetch_func(target=target, *args, **kwargs)
  File "/usr/lib/python2.7/dist-packages/nova/virt/libvirt/utils.py", line 382, in fetch_image
    images.fetch_to_raw(context, image_id, target)
  File "/usr/lib/python2.7/dist-packages/nova/virt/images.py", line 168, in fetch_to_raw
    fetch(context, image_href, path_tmp)
  File "/usr/lib/python2.7/dist-packages/nova/virt/images.py", line 157, in fetch
    IMAGE_API.download(context, image_href, dest_path=path)
  File "/usr/lib/python2.7/dist-packages/nova/image/api.py", line 197, in download
    dst_path=dest_path)
  File "/usr/lib/python2.7/dist-packages/nova/image/glance.py", line 334, in download
    LOG.warning("full stack trace: %(x)s", {'x': full_stack()})

2021-06-09 15:13:21.198 45120 WARNING nova.image.glance [req-061b67d6-92d0-47ec-a2ce-969beefb940e 58f7c51142914f8ca5364b053bee5ad5 b2e4daac950844b2b8abc906f55ccbd1 - default default] calling image_chunks = self._client.call(context, 2, 'data', args=(image_id,))
2021-06-09 15:13:21.699 45120 WARNING nova.image.glance [req-061b67d6-92d0-47ec-a2ce-969beefb940e 58f7c51142914f8ca5364b053bee5ad5 b2e4daac950844b2b8abc906f55ccbd1 - default default] image_chunks = self._client.call(context, 2, 'data', args=(image_id,)) returned
2021-06-09 15:13:21.700 45120 WARNING nova.image.glance [req-061b67d6-92d0-47ec-a2ce-969beefb940e 58f7c51142914f8ca5364b053bee5ad5 b2e4daac950844b2b8abc906f55ccbd1 - default default] image_chunks = <glanceclient.common.utils.IterableWithLength object at 0x7f8bd430df90>
2021-06-09 15:13:21.706 45120 WARNING nova.image.glance [req-061b67d6-92d0-47ec-a2ce-969beefb940e 58f7c51142914f8ca5364b053bee5ad5 b2e4daac950844b2b8abc906f55ccbd1 - default default] data (the output file)=<open file '/var/lib/nova/instances/_base/fc2284ec9a4126f54c519ddbb9449ce1ca2f52de.part', mode 'wb' at 0x7f8bd43a9150>
2021-06-09 15:13:21.707 45120 WARNING nova.image.glance [req-061b67d6-92d0-47ec-a2ce-969beefb940e 58f7c51142914f8ca5364b053bee5ad5 b2e4daac950844b2b8abc906f55ccbd1 - default default] starting loop for chunk in image_chunks

>>> Note how there are now extra messages from other parts of nova even during the download loop.

2021-06-09 15:13:22.450 45120 WARNING nova.compute.manager [req-575c7333-c3d5-44c6-a12c-0042862fc7cc b5eda099dee946f98035f38053ad40a2 ee12936a687f4c709451ee9b55b3bd21 - default default] [instance: 7fd69c0b-312f-4532-9944-9a59fe5a96a3] Received unexpected event network-vif-unplugged-b1b9c0cb-1278-4a31-8db1-7baee3a816ba for instance with vm_state building and task_state spawning.
2021-06-09 15:13:24.683 45120 WARNING nova.compute.manager [req-8370ec42-5f90-4e13-bdcf-8aa06c2d5818 b5eda099dee946f98035f38053ad40a2 ee12936a687f4c709451ee9b55b3bd21 - default default] [instance: 7fd69c0b-312f-4532-9944-9a59fe5a96a3] Received unexpected event network-vif-plugged-b1b9c0cb-1278-4a31-8db1-7baee3a816ba for instance with vm_state building and task_state spawning.
2021-06-09 15:14:00.240 45120 INFO nova.compute.resource_tracker [req-8512af00-804e-4f8e-bfc7-3f11976e498b - - - - -] Final resource view: name=zbk130721.zbk.sys11cloud.net phys_ram=515889MB used_ram=8192MB phys_disk=7600GB used_disk=75GB total_vcpus=56 used_vcpus=3 pci_stats=[]
2021-06-09 15:15:00.118 45120 INFO nova.compute.resource_tracker [req-8512af00-804e-4f8e-bfc7-3f11976e498b - - - - -] Final resource view: name=zbk130721.zbk.sys11cloud.net phys_ram=515889MB used_ram=8192MB phys_disk=7600GB used_disk=75GB total_vcpus=56 used_vcpus=3 pci_stats=[]
2021-06-09 15:16:01.351 45120 INFO nova.compute.resource_tracker [req-8512af00-804e-4f8e-bfc7-3f11976e498b - - - - -] Final resource view: name=zbk130721.zbk.sys11cloud.net phys_ram=515889MB used_ram=8192MB phys_disk=7600GB used_disk=75GB total_vcpus=56 used_vcpus=3 pci_stats=[]
2021-06-09 15:17:01.087 45120 INFO nova.compute.resource_tracker [req-8512af00-804e-4f8e-bfc7-3f11976e498b - - - - -] Final resource view: name=zbk130721.zbk.sys11cloud.net phys_ram=515889MB used_ram=8192MB phys_disk=7600GB used_disk=75GB total_vcpus=56 used_vcpus=3 pci_stats=[]
2021-06-09 15:18:01.882 45120 INFO nova.compute.resource_tracker [req-8512af00-804e-4f8e-bfc7-3f11976e498b - - - - -] Final resource view: name=zbk130721.zbk.sys11cloud.net phys_ram=515889MB used_ram=8192MB phys_disk=7600GB used_disk=75GB total_vcpus=56 used_vcpus=3 pci_stats=[]
2021-06-09 15:19:03.974 45120 INFO nova.compute.resource_tracker [req-8512af00-804e-4f8e-bfc7-3f11976e498b - - - - -] Final resource view: name=zbk130721.zbk.sys11cloud.net phys_ram=515889MB used_ram=8192MB phys_disk=7600GB used_disk=75GB total_vcpus=56 used_vcpus=3 pci_stats=[]
2021-06-09 15:20:04.865 45120 INFO nova.compute.resource_tracker [req-8512af00-804e-4f8e-bfc7-3f11976e498b - - - - -] Final resource view: name=zbk130721.zbk.sys11cloud.net phys_ram=515889MB used_ram=8192MB phys_disk=7600GB used_disk=75GB total_vcpus=56 used_vcpus=3 pci_stats=[]
2021-06-09 15:21:06.814 45120 INFO nova.compute.resource_tracker [req-8512af00-804e-4f8e-bfc7-3f11976e498b - - - - -] Final resource view: name=zbk130721.zbk.sys11cloud.net phys_ram=515889MB used_ram=8192MB phys_disk=7600GB used_disk=75GB total_vcpus=56 used_vcpus=3 pci_stats=[]
2021-06-09 15:21:55.651 45120 INFO nova.compute.manager [req-8512af00-804e-4f8e-bfc7-3f11976e498b - - - - -] Updating bandwidth usage cache
2021-06-09 15:21:55.750 45120 INFO nova.compute.manager [req-8512af00-804e-4f8e-bfc7-3f11976e498b - - - - -] Bandwidth usage not supported by libvirt.LibvirtDriver.
2021-06-09 15:22:09.515 45120 INFO nova.compute.resource_tracker [req-8512af00-804e-4f8e-bfc7-3f11976e498b - - - - -] Final resource view: name=zbk130721.zbk.sys11cloud.net phys_ram=515889MB used_ram=8192MB phys_disk=7600GB used_disk=75GB total_vcpus=56 used_vcpus=3 pci_stats=[]
2021-06-09 15:22:53.820 45120 WARNING nova.compute.manager [req-8512af00-804e-4f8e-bfc7-3f11976e498b - - - - -] While synchronizing instance power states, found 2 instances in the database and 1 instances on the hypervisor.
2021-06-09 15:23:09.009 45120 INFO nova.compute.resource_tracker [req-8512af00-804e-4f8e-bfc7-3f11976e498b - - - - -] Final resource view: name=zbk130721.zbk.sys11cloud.net phys_ram=515889MB used_ram=8192MB phys_disk=7600GB used_disk=75GB total_vcpus=56 used_vcpus=3 pci_stats=[]
2021-06-09 15:23:40.091 45120 WARNING nova.image.api [req-061b67d6-92d0-47ec-a2ce-969beefb940e 58f7c51142914f8ca5364b053bee5ad5 b2e4daac950844b2b8abc906f55ccbd1 - default default] download: session.download() returned foo:None

>>> Here the tight download loop is finally done.

2021-06-09 15:23:40.094 45120 WARNING nova.virt.images [req-061b67d6-92d0-47ec-a2ce-969beefb940e 58f7c51142914f8ca5364b053bee5ad5 b2e4daac950844b2b8abc906f55ccbd1 - default default] fetch() returns
2021-06-09 15:23:40.095 45120 WARNING nova.virt.images [req-061b67d6-92d0-47ec-a2ce-969beefb940e 58f7c51142914f8ca5364b053bee5ad5 b2e4daac950844b2b8abc906f55ccbd1 - default default] fetch() returned
2021-06-09 15:24:08.901 45120 INFO nova.compute.resource_tracker [req-8512af00-804e-4f8e-bfc7-3f11976e498b - - - - -] Final resource view: name=zbk130721.zbk.sys11cloud.net phys_ram=515889MB used_ram=8192MB phys_disk=7600GB used_disk=75GB total_vcpus=56 used_vcpus=3 pci_stats=[]
2021-06-09 15:25:08.915 45120 INFO nova.compute.resource_tracker [req-8512af00-804e-4f8e-bfc7-3f11976e498b - - - - -] Final resource view: name=zbk130721.zbk.sys11cloud.net phys_ram=515889MB used_ram=8192MB phys_disk=7600GB used_disk=75GB total_vcpus=56 used_vcpus=3 pci_stats=[]
2021-06-09 15:25:54.585 45120 WARNING nova.virt.libvirt.utils [req-061b67d6-92d0-47ec-a2ce-969beefb940e 58f7c51142914f8ca5364b053bee5ad5 b2e4daac950844b2b8abc906f55ccbd1 - default default] fetch_image(context, target, image_id) returns
2021-06-09 15:25:54.588 45120 WARNING nova.virt.libvirt.imagebackend [req-061b67d6-92d0-47ec-a2ce-969beefb940e 58f7c51142914f8ca5364b053bee5ad5 b2e4daac950844b2b8abc906f55ccbd1 - default default] fetch_func = <function fetch_image at 0x7f8bda2fc6e0> returned
2021-06-09 15:25:54.589 45120 WARNING nova.virt.libvirt.imagebackend [req-061b67d6-92d0-47ec-a2ce-969beefb940e 58f7c51142914f8ca5364b053bee5ad5 b2e4daac950844b2b8abc906f55ccbd1 - default default] fetch_func_sync returning
2021-06-09 15:25:54.591 45120 WARNING nova.virt.libvirt.imagebackend [req-061b67d6-92d0-47ec-a2ce-969beefb940e 58f7c51142914f8ca5364b053bee5ad5 b2e4daac950844b2b8abc906f55ccbd1 - default default] Calling Lvm.create_image.create_lvm_image()
2021-06-09 15:25:54.592 45120 WARNING nova.virt.libvirt.imagebackend [req-061b67d6-92d0-47ec-a2ce-969beefb940e 58f7c51142914f8ca5364b053bee5ad5 b2e4daac950844b2b8abc906f55ccbd1 - default default] entering Lvm.create_image.create_lvm_image()
2021-06-09 15:25:55.309 45120 WARNING nova.virt.libvirt.imagebackend [req-061b67d6-92d0-47ec-a2ce-969beefb940e 58f7c51142914f8ca5364b053bee5ad5 b2e4daac950844b2b8abc906f55ccbd1 - default default] calling images.convert_image_unsafe(...
2021-06-09 15:26:08.843 45120 INFO nova.compute.resource_tracker [req-8512af00-804e-4f8e-bfc7-3f11976e498b - - - - -] Final resource view: name=zbk130721.zbk.sys11cloud.net phys_ram=515889MB used_ram=8192MB phys_disk=7600GB used_disk=75GB total_vcpus=56 used_vcpus=3 pci_stats=[]
2021-06-09 15:27:08.925 45120 INFO nova.compute.resource_tracker [req-8512af00-804e-4f8e-bfc7-3f11976e498b - - - - -] Final resource view: name=zbk130721.zbk.sys11cloud.net phys_ram=515889MB used_ram=8192MB phys_disk=7600GB used_disk=75GB total_vcpus=56 used_vcpus=3 pci_stats=[]
2021-06-09 15:28:09.026 45120 INFO nova.compute.resource_tracker [req-8512af00-804e-4f8e-bfc7-3f11976e498b - - - - -] Final resource view: name=zbk130721.zbk.sys11cloud.net phys_ram=515889MB used_ram=8192MB phys_disk=7600GB used_disk=75GB total_vcpus=56 used_vcpus=3 pci_stats=[]
2021-06-09 15:28:52.654 45120 WARNING nova.virt.libvirt.imagebackend [req-061b67d6-92d0-47ec-a2ce-969beefb940e 58f7c51142914f8ca5364b053bee5ad5 b2e4daac950844b2b8abc906f55ccbd1 - default default] images.convert_image_unsafe(... returned
2021-06-09 15:28:52.655 45120 WARNING nova.virt.libvirt.imagebackend [req-061b67d6-92d0-47ec-a2ce-969beefb940e 58f7c51142914f8ca5364b053bee5ad5 b2e4daac950844b2b8abc906f55ccbd1 - default default] Lvm.create_image.create_lvm_image() returns
2021-06-09 15:28:52.656 45120 WARNING nova.virt.libvirt.imagebackend [req-061b67d6-92d0-47ec-a2ce-969beefb940e 58f7c51142914f8ca5364b053bee5ad5 b2e4daac950844b2b8abc906f55ccbd1 - default default] Lvm.create_image.create_lvm_image() returned
2021-06-09 15:28:52.657 45120 WARNING nova.virt.libvirt.imagebackend [req-061b67d6-92d0-47ec-a2ce-969beefb940e 58f7c51142914f8ca5364b053bee5ad5 b2e4daac950844b2b8abc906f55ccbd1 - default default] Lvm.create_image() returns
2021-06-09 15:28:52.829 45120 WARNING nova.virt.libvirt.driver [req-061b67d6-92d0-47ec-a2ce-969beefb940e 58f7c51142914f8ca5364b053bee5ad5 b2e4daac950844b2b8abc906f55ccbd1 - default default] image.cache(fetch_func=fetch_func,... returned
2021-06-09 15:28:52.831 45120 WARNING nova.virt.libvirt.driver [req-061b67d6-92d0-47ec-a2ce-969beefb940e 58f7c51142914f8ca5364b053bee5ad5 b2e4daac950844b2b8abc906f55ccbd1 - default default] Returning from _try_fetch_image_cache
2021-06-09 15:28:52.832 45120 WARNING nova.virt.libvirt.driver [req-061b67d6-92d0-47ec-a2ce-969beefb940e 58f7c51142914f8ca5364b053bee5ad5 b2e4daac950844b2b8abc906f55ccbd1 - default default] [instance: 7fd69c0b-312f-4532-9944-9a59fe5a96a3] self._try_fetch_image_cache() returned
2021-06-09 15:28:52.833 45120 WARNING nova.virt.libvirt.driver [req-061b67d6-92d0-47ec-a2ce-969beefb940e 58f7c51142914f8ca5364b053bee5ad5 b2e4daac950844b2b8abc906f55ccbd1 - default default] [instance: 7fd69c0b-312f-4532-9944-9a59fe5a96a3] _create_and_inject_local_root returning
2021-06-09 15:28:52.834 45120 WARNING nova.virt.libvirt.driver [req-061b67d6-92d0-47ec-a2ce-969beefb940e 58f7c51142914f8ca5364b053bee5ad5 b2e4daac950844b2b8abc906f55ccbd1 - default default] [instance: 7fd69c0b-312f-4532-9944-9a59fe5a96a3] for idx, eph in enumerate(driver.block_device_info_get_ephemerals(...
2021-06-09 15:28:53.391 45120 INFO nova.network.linux_net [req-061b67d6-92d0-47ec-a2ce-969beefb940e 58f7c51142914f8ca5364b053bee5ad5 b2e4daac950844b2b8abc906f55ccbd1 - default default] SysEleven: binding midonet port b1b9c0cb-1278-4a31-8db1-7baee3a816ba on dev tapb1b9c0cb-12
2021-06-09 15:28:54.905 45120 INFO nova.compute.manager [-] [instance: 7fd69c0b-312f-4532-9944-9a59fe5a96a3] VM Resumed (Lifecycle Event)
2021-06-09 15:28:54.914 45120 INFO nova.virt.libvirt.driver [-] [instance: 7fd69c0b-312f-4532-9944-9a59fe5a96a3] Instance spawned successfully.
2021-06-09 15:28:54.915 45120 INFO nova.compute.manager [req-061b67d6-92d0-47ec-a2ce-969beefb940e 58f7c51142914f8ca5364b053bee5ad5 b2e4daac950844b2b8abc906f55ccbd1 - default default] [instance: 7fd69c0b-312f-4532-9944-9a59fe5a96a3] Took 933.75 seconds to spawn the instance on the hypervisor.
2021-06-09 15:28:55.094 45120 INFO nova.network.linux_net [req-86e0be5a-bc4d-4ab0-b660-247e9f04251b - - - - -] SysEleven: binding midonet port b1b9c0cb-1278-4a31-8db1-7baee3a816ba on dev tapb1b9c0cb-12
2021-06-09 15:28:55.117 45120 INFO nova.compute.manager [req-061b67d6-92d0-47ec-a2ce-969beefb940e 58f7c51142914f8ca5364b053bee5ad5 b2e4daac950844b2b8abc906f55ccbd1 - default default] [instance: 7fd69c0b-312f-4532-9944-9a59fe5a96a3] Took 935.73 seconds to build instance.
2021-06-09 15:28:55.211 45120 INFO nova.compute.manager [-] [instance: 7fd69c0b-312f-4532-9944-9a59fe5a96a3] During sync_power_state the instance has a pending task (spawning). Skip.
2021-06-09 15:28:55.338 45120 INFO nova.compute.manager [req-86e0be5a-bc4d-4ab0-b660-247e9f04251b - - - - -] [instance: 7fd69c0b-312f-4532-9944-9a59fe5a96a3] VM Started (Lifecycle Event)
2021-06-09 15:29:08.919 45120 INFO nova.compute.resource_tracker [req-8512af00-804e-4f8e-bfc7-3f11976e498b - - - - -] Final resource view: name=zbk130721.zbk.sys11cloud.net phys_ram=515889MB used_ram=8192MB phys_disk=7600GB used_disk=75GB total_vcpus=56 used_vcpus=3 pci_stats=[]


And here is the same problem, observed on Ussuri. It seems Ussuri doesn't log the once-a-minute "Final resource view" messages, but still network connection problems are visible.
It seems to recover better (or maybe that is only because there is less logged in general) but it still looks bad.


2021-06-15 15:49:49.566 40716 INFO nova.compute.claims [req-ad88e62a-2642-4342-88f2-1109c395895b 40eb6bf6a0ee4ea4b423b9408cf3e942 53207fef76924467ab5d1d719df24c3b - default default] [instance: 623027ee-3f40-4175-9019-9df346e7000c] Claim successful on node ybk130218.ybk.sys11cloud.net
2021-06-15 15:49:49.989 40716 INFO nova.virt.osinfo [req-ad88e62a-2642-4342-88f2-1109c395895b 40eb6bf6a0ee4ea4b423b9408cf3e942 53207fef76924467ab5d1d719df24c3b - default default] Cannot load Libosinfo: (cannot import name Libosinfo, introspection typelib not found)
2021-06-15 15:49:50.360 40716 INFO nova.virt.libvirt.driver [req-ad88e62a-2642-4342-88f2-1109c395895b 40eb6bf6a0ee4ea4b423b9408cf3e942 53207fef76924467ab5d1d719df24c3b - default default] [instance: 623027ee-3f40-4175-9019-9df346e7000c] Creating image
2021-06-15 15:52:35.502 40716 ERROR oslo.messaging._drivers.impl_rabbit [-] [ad8920d7-f227-412e-aab3-d849a1cdccff] AMQP server on ybk130237.ybk.sys11cloud.net:5671 is unreachable: Too many heartbeats missed. Trying again in 1 seconds.: amqp.exceptions.ConnectionForced: Too many heartbeats missed
2021-06-15 15:52:35.503 40716 ERROR oslo.messaging._drivers.impl_rabbit [-] [35b13cef-9b02-4daa-ac97-9986c7361f22] AMQP server on ybk130237.ybk.sys11cloud.net:5671 is unreachable: [Errno 104] Connection reset by peer. Trying again in 1 seconds.: ConnectionResetError: [Errno 104] Connection reset by peer
2021-06-15 15:52:35.504 40716 INFO oslo.messaging._drivers.impl_rabbit [-] A recoverable connection/channel error occurred, trying to reconnect: [Errno 104] Connection reset by peer
2021-06-15 15:52:35.511 40716 ERROR oslo.messaging._drivers.impl_rabbit [-] [5322eb95-ffc3-4503-8eac-9ae2ee3cef8a] AMQP server on ybk130229.ybk.sys11cloud.net:5671 is unreachable: . Trying again in 1 seconds.: socket.timeout
2021-06-15 15:52:39.384 40716 INFO oslo.messaging._drivers.impl_rabbit [-] [ad8920d7-f227-412e-aab3-d849a1cdccff] Reconnected to AMQP server on ybk130237.ybk.sys11cloud.net:5671 via [amqp] client with port 38230.
2021-06-15 15:52:39.385 40716 INFO oslo.messaging._drivers.impl_rabbit [-] [5322eb95-ffc3-4503-8eac-9ae2ee3cef8a] Reconnected to AMQP server on ybk130229.ybk.sys11cloud.net:5671 via [amqp] client with port 59932.
2021-06-15 15:52:50.763 40716 WARNING oslo.service.loopingcall [-] Function 'nova.servicegroup.drivers.db.DbDriver._report_state' run outlasted interval by 132.35 sec
2021-06-15 15:52:50.770 40716 INFO oslo.messaging._drivers.impl_rabbit [-] [35b13cef-9b02-4daa-ac97-9986c7361f22] Reconnected to AMQP server on ybk130237.ybk.sys11cloud.net:5671 via [amqp] client with port 38232.
2021-06-15 15:55:39.782 40716 ERROR oslo.messaging._drivers.impl_rabbit [-] [ad8920d7-f227-412e-aab3-d849a1cdccff] AMQP server on ybk130237.ybk.sys11cloud.net:5671 is unreachable: [Errno 104] Connection reset by peer. Trying again in 1 seconds.: ConnectionResetError: [Errno 104] Connection reset by peer
2021-06-15 15:55:39.786 40716 INFO oslo.messaging._drivers.impl_rabbit [-] A recoverable connection/channel error occurred, trying to reconnect: Server unexpectedly closed connection
2021-06-15 15:55:39.797 40716 ERROR oslo.messaging._drivers.impl_rabbit [-] [35b13cef-9b02-4daa-ac97-9986c7361f22] AMQP server on ybk130237.ybk.sys11cloud.net:5671 is unreachable: [Errno 104] Connection reset by peer. Trying again in 1 seconds.: ConnectionResetError: [Errno 104] Connection reset by peer
2021-06-15 15:55:39.798 40716 ERROR oslo.messaging._drivers.impl_rabbit [-] [5322eb95-ffc3-4503-8eac-9ae2ee3cef8a] AMQP server on ybk130229.ybk.sys11cloud.net:5671 is unreachable: Server unexpectedly closed connection. Trying again in 1 seconds.: OSError: Server unexpectedly closed connection
2021-06-15 15:55:40.838 40716 INFO oslo.messaging._drivers.impl_rabbit [-] [ad8920d7-f227-412e-aab3-d849a1cdccff] Reconnected to AMQP server on ybk130237.ybk.sys11cloud.net:5671 via [amqp] client with port 38474.
2021-06-15 15:55:40.840 40716 INFO oslo.messaging._drivers.impl_rabbit [-] [5322eb95-ffc3-4503-8eac-9ae2ee3cef8a] Reconnected to AMQP server on ybk130229.ybk.sys11cloud.net:5671 via [amqp] client with port 60176.
2021-06-15 15:55:40.851 40716 INFO oslo.messaging._drivers.impl_rabbit [-] [35b13cef-9b02-4daa-ac97-9986c7361f22] Reconnected to AMQP server on ybk130237.ybk.sys11cloud.net:5671 via [amqp] client with port 38476.
2021-06-15 15:58:59.155 40716 WARNING nova.compute.manager [req-b4484ab0-3aae-4a54-a821-53135f9b040c - - - - -] While synchronizing instance power states, found 1 instances in the database and 0 instances on the hypervisor.
2021-06-15 15:59:34.779 40716 INFO oslo.privsep.daemon [req-ad88e62a-2642-4342-88f2-1109c395895b 40eb6bf6a0ee4ea4b423b9408cf3e942 53207fef76924467ab5d1d719df24c3b - default default] Running privsep helper: ['sudo', 'nova-rootwrap', '/etc/nova/rootwrap.conf', 'privsep-helper', '--config-file', '/etc/nova/nova.conf', '--config-file', '/etc/nova/nova-compute.conf', '--privsep_context', 'vif_plug_ovs.privsep.vif_plug', '--privsep_sock_path', '/tmp/tmpurpre275/privsep.sock']
2021-06-15 15:59:35.345 40716 INFO oslo.privsep.daemon [req-ad88e62a-2642-4342-88f2-1109c395895b 40eb6bf6a0ee4ea4b423b9408cf3e942 53207fef76924467ab5d1d719df24c3b - default default] Spawned new privsep daemon via rootwrap
2021-06-15 15:59:35.261 2029 INFO oslo.privsep.daemon [-] privsep daemon starting
2021-06-15 15:59:35.268 2029 INFO oslo.privsep.daemon [-] privsep process running with uid/gid: 0/0
2021-06-15 15:59:35.271 2029 INFO oslo.privsep.daemon [-] privsep process running with capabilities (eff/prm/inh): CAP_NET_ADMIN/CAP_NET_ADMIN/none
2021-06-15 15:59:35.272 2029 INFO oslo.privsep.daemon [-] privsep daemon running as pid 2029
2021-06-15 15:59:35.485 40716 INFO os_vif [req-ad88e62a-2642-4342-88f2-1109c395895b 40eb6bf6a0ee4ea4b423b9408cf3e942 53207fef76924467ab5d1d719df24c3b - default default] Successfully plugged vif VIFOpenVSwitch(active=False,address=fa:16:3e:5f:4b:53,bridge_name='br-int',has_traffic_filtering=True,id=c90e49c2-39db-4397-b74d-a3c0e902e9d8,network=Network(87c0169e-c9d5-4e12-9364-08a7bb32eb89),plugin='ovs',port_profile=VIFPortProfileOpenVSwitch,preserve_on_delete=True,vif_name='tapc90e49c2-39')
2021-06-15 15:59:36.968 40716 INFO nova.compute.manager [-] [instance: 623027ee-3f40-4175-9019-9df346e7000c] VM Started (Lifecycle Event)
2021-06-15 15:59:37.032 40716 INFO nova.compute.manager [req-115b892a-0690-495b-96d0-3c80cc50715d - - - - -] [instance: 623027ee-3f40-4175-9019-9df346e7000c] VM Paused (Lifecycle Event)
2021-06-15 15:59:37.133 40716 INFO nova.compute.manager [req-115b892a-0690-495b-96d0-3c80cc50715d - - - - -] [instance: 623027ee-3f40-4175-9019-9df346e7000c] During sync_power_state the instance has a pending task (spawning). Skip.
2021-06-15 15:59:52.690 40716 INFO nova.compute.manager [req-115b892a-0690-495b-96d0-3c80cc50715d - - - - -] [instance: 623027ee-3f40-4175-9019-9df346e7000c] VM Resumed (Lifecycle Event)
2021-06-15 15:59:52.696 40716 INFO nova.virt.libvirt.driver [-] [instance: 623027ee-3f40-4175-9019-9df346e7000c] Instance spawned successfully.
2021-06-15 15:59:52.697 40716 INFO nova.compute.manager [req-ad88e62a-2642-4342-88f2-1109c395895b 40eb6bf6a0ee4ea4b423b9408cf3e942 53207fef76924467ab5d1d719df24c3b - default default] [instance: 623027ee-3f40-4175-9019-9df346e7000c] Took 602.34 seconds to spawn the instance on the hypervisor.
2021-06-15 15:59:52.712 40716 INFO os_vif [req-115b892a-0690-495b-96d0-3c80cc50715d - - - - -] Successfully plugged vif VIFOpenVSwitch(active=False,address=fa:16:3e:5f:4b:53,bridge_name='br-int',has_traffic_filtering=True,id=c90e49c2-39db-4397-b74d-a3c0e902e9d8,network=Network(87c0169e-c9d5-4e12-9364-08a7bb32eb89),plugin='ovs',port_profile=VIFPortProfileOpenVSwitch,preserve_on_delete=True,vif_name='tapc90e49c2-39')
2021-06-15 15:59:52.778 40716 INFO nova.compute.manager [req-115b892a-0690-495b-96d0-3c80cc50715d - - - - -] [instance: 623027ee-3f40-4175-9019-9df346e7000c] During sync_power_state the instance has a pending task (spawning). Skip.
2021-06-15 15:59:52.835 40716 INFO nova.compute.manager [req-ad88e62a-2642-4342-88f2-1109c395895b 40eb6bf6a0ee4ea4b423b9408cf3e942 53207fef76924467ab5d1d719df24c3b - default default] [instance: 623027ee-3f40-4175-9019-9df346e7000c] Took 603.31 seconds to build instance.
2021-06-15 15:59:52.867 40716 INFO nova.compute.manager [-] [instance: 623027ee-3f40-4175-9019-9df346e7000c] During sync_power_state the instance has a pending task (spawning). Skip.
2021-06-15 15:59:54.859 40716 WARNING nova.compute.manager [req-83a940ac-a8f7-460e-a6d2-300493484a85 b18382c4c69444cd85f6317410428b76 e2722f7433ee4a2da43d10b94ecd364a - default default] [instance: 623027ee-3f40-4175-9019-9df346e7000c] Received unexpected event network-vif-plugged-c90e49c2-39db-4397-b74d-a3c0e902e9d8 for instance with vm_state active and task_state None.