This problem was reproduced in CI for one of my stable/wallaby patches: https://zuul.opendev.org/t/openstack/build/3ae58b4f95d7442fb9110c4044acee2b/logs https://1f24fdc3bf9479288b3a-225501c9cce0e8ba4bd0f4849071211d.ssl.cf1.rackcdn.com/888333/1/check/nova-next/3ae58b4/compute1/logs/libvirt/qemu/instance-00000011_log.txt https://1f24fdc3bf9479288b3a-225501c9cce0e8ba4bd0f4849071211d.ssl.cf1.rackcdn.com/888333/1/check/nova-next/3ae58b4/compute1/logs/libvirt/libvirtd_log.txt https://1f24fdc3bf9479288b3a-225501c9cce0e8ba4bd0f4849071211d.ssl.cf1.rackcdn.com/888333/1/check/nova-next/3ae58b4/compute1/logs/screen-n-cpu.txt https://1f24fdc3bf9479288b3a-225501c9cce0e8ba4bd0f4849071211d.ssl.cf1.rackcdn.com/888333/1/check/nova-next/3ae58b4/job-output.txt
Extracts:
Jul 13 08:35:22.230036 np0034667036 nova-compute[54149]: WARNING nova.virt.libvirt.driver [None req-7222880d-af15-4a90-b16d-24bdf5763e09 None None] Received event <DeviceRemovedEvent: 1689237322.2269797, dd46f9ba-2352-4da6-be3a-ecf68757e3c0 => virtio-disk1> from libvirt but the driver is not waiting for it; ignored. Jul 13 08:35:22.242368 np0034667036 nova-compute[54149]: ERROR nova.virt.libvirt.driver [None req-473da26b-0641-4cda-84ef-9e451e5eddb9 tempest-TestVolumeSwap-869256485 tempest-TestVolumeSwap-869256485-project-admin] Failure rebasing volume /dev/sda on vdb.: libvirt.libvirtError: invalid argument: disk 'vdb' not found in domain Jul 13 08:35:22.242368 np0034667036 nova-compute[54149]: ERROR nova.virt.libvirt.driver Traceback (most recent call last): Jul 13 08:35:22.242368 np0034667036 nova-compute[54149]: ERROR nova.virt.libvirt.driver File "/opt/stack/nova/nova/virt/libvirt/driver.py", line 2128, in _swap_volume Jul 13 08:35:22.242368 np0034667036 nova-compute[54149]: ERROR nova.virt.libvirt.driver while not dev.is_job_complete(): Jul 13 08:35:22.242368 np0034667036 nova-compute[54149]: ERROR nova.virt.libvirt.driver File "/opt/stack/nova/nova/virt/libvirt/guest.py", line 810, in is_job_complete Jul 13 08:35:22.242368 np0034667036 nova-compute[54149]: ERROR nova.virt.libvirt.driver status = self.get_job_info() Jul 13 08:35:22.242368 np0034667036 nova-compute[54149]: ERROR nova.virt.libvirt.driver File "/opt/stack/nova/nova/virt/libvirt/guest.py", line 717, in get_job_info Jul 13 08:35:22.242368 np0034667036 nova-compute[54149]: ERROR nova.virt.libvirt.driver status = self._guest._domain.blockJobInfo(self._disk, flags=0) Jul 13 08:35:22.242368 np0034667036 nova-compute[54149]: ERROR nova.virt.libvirt.driver File "/usr/local/lib/python3.8/dist-packages/eventlet/tpool.py", line 190, in doit Jul 13 08:35:22.242368 np0034667036 nova-compute[54149]: ERROR nova.virt.libvirt.driver result = proxy_call(self._autowrap, f, *args, **kwargs) Jul 13 08:35:22.242368 np0034667036 nova-compute[54149]: ERROR nova.virt.libvirt.driver File "/usr/local/lib/python3.8/dist-packages/eventlet/tpool.py", line 148, in proxy_call Jul 13 08:35:22.242368 np0034667036 nova-compute[54149]: ERROR nova.virt.libvirt.driver rv = execute(f, *args, **kwargs) Jul 13 08:35:22.242368 np0034667036 nova-compute[54149]: ERROR nova.virt.libvirt.driver File "/usr/local/lib/python3.8/dist-packages/eventlet/tpool.py", line 129, in execute Jul 13 08:35:22.242368 np0034667036 nova-compute[54149]: ERROR nova.virt.libvirt.driver six.reraise(c, e, tb) Jul 13 08:35:22.242368 np0034667036 nova-compute[54149]: ERROR nova.virt.libvirt.driver File "/usr/local/lib/python3.8/dist-packages/six.py", line 703, in reraise Jul 13 08:35:22.242368 np0034667036 nova-compute[54149]: ERROR nova.virt.libvirt.driver raise value Jul 13 08:35:22.242368 np0034667036 nova-compute[54149]: ERROR nova.virt.libvirt.driver File "/usr/local/lib/python3.8/dist-packages/eventlet/tpool.py", line 83, in tworker Jul 13 08:35:22.242368 np0034667036 nova-compute[54149]: ERROR nova.virt.libvirt.driver rv = meth(*args, **kwargs) Jul 13 08:35:22.242368 np0034667036 nova-compute[54149]: ERROR nova.virt.libvirt.driver File "/usr/lib/python3/dist-packages/libvirt.py", line 898, in blockJobInfo Jul 13 08:35:22.242368 np0034667036 nova-compute[54149]: ERROR nova.virt.libvirt.driver if ret is None: raise libvirtError ('virDomainGetBlockJobInfo() failed', dom=self) Jul 13 08:35:22.242368 np0034667036 nova-compute[54149]: ERROR nova.virt.libvirt.driver libvirt.libvirtError: invalid argument: disk 'vdb' not found in domain Jul 13 08:35:22.242368 np0034667036 nova-compute[54149]: ERROR nova.virt.libvirt.driver
2023-07-13 08:35:22.226+0000: 44724: debug : qemuMonitorEmitEvent:1198 : mon=0x7f6bcc07b080 event=DEVICE_DELETED 2023-07-13 08:35:22.226+0000: 44724: debug : qemuProcessHandleEvent:551 : vm=0x7f6bbc0b6db0 2023-07-13 08:35:22.226+0000: 44724: debug : virObjectEventNew:631 : obj=0x55ea304db760 2023-07-13 08:35:22.226+0000: 44724: debug : qemuMonitorJSONIOProcessEvent:205 : handle DEVICE_DELETED handler=0x7f6bc1e3db80 data=0x55ea304ad810 2023-07-13 08:35:22.226+0000: 44724: debug : qemuMonitorEmitDeviceDeleted:1432 : mon=0x7f6bcc07b080 2023-07-13 08:35:22.226+0000: 44724: debug : qemuProcessHandleDeviceDeleted:1364 : Device virtio-disk1 removed from domain 0x7f6bbc0b6db0 instance-00000011 2023-07-13 08:35:22.226+0000: 44724: debug : virObjectEventDispose:124 : obj=0x55ea304db760 2023-07-13 08:35:22.226+0000: 57688: debug : qemuProcessEventHandler:4866 : vm=0x7f6bbc0b6db0, event=2 2023-07-13 08:35:22.226+0000: 57688: debug : processDeviceDeletedEvent:4282 : Removing device virtio-disk1 from domain 0x7f6bbc0b6db0 instance-00000011 2023-07-13 08:35:22.226+0000: 57688: debug : qemuDomainObjBeginJobInternal:9416 : Starting job: job=modify agentJob=none asyncJob=none (vm=0x7f6bbc0b6db0 name=instance-00000011, current job=none agentJob=none async=none) 2023-07-13 08:35:22.226+0000: 57688: debug : qemuDomainObjBeginJobInternal:9470 : Started job: modify (async=none vm=0x7f6bbc0b6db0 name=instance-00000011) 2023-07-13 08:35:22.226+0000: 57688: debug : qemuDomainRemoveDiskDevice:4218 : Removing disk virtio-disk1 from domain 0x7f6bbc0b6db0 instance-00000011 2023-07-13 08:35:22.226+0000: 57688: debug : qemuDomainObjEnterMonitorInternal:9869 : Entering monitor (mon=0x7f6bcc07b080 vm=0x7f6bbc0b6db0 name=instance-00000011) 2023-07-13 08:35:22.226+0000: 57688: debug : qemuDomainObjExitMonitorInternal:9892 : Exited monitor (mon=0x7f6bcc07b080 vm=0x7f6bbc0b6db0 name=instance-00000011) 2023-07-13 08:35:22.226+0000: 57688: debug : virObjectEventNew:631 : obj=0x7f6b80029ba0 2023-07-13 08:35:22.226+0000: 44724: debug : virObjectEventDispose:124 : obj=0x7f6b80029ba0 2023-07-13 08:35:22.227+0000: 57688: debug : qemuDomainObjEndJob:9746 : Stopping job: modify (async=none vm=0x7f6bbc0b6db0 name=instance-00000011) 2023-07-13 08:35:22.233+0000: 44727: debug : virThreadJobSet:93 : Thread 44727 (virNetServerHandleJob) is now running job remoteDispatchDomainGetBlockJobInfo 2023-07-13 08:35:22.233+0000: 44727: debug : qemuDomainObjBeginJobInternal:9416 : Starting job: job=query agentJob=none asyncJob=none (vm=0x7f6bbc0b6db0 name=instance-00000011, current job=none agentJob=none async=none) 2023-07-13 08:35:22.233+0000: 44727: debug : qemuDomainObjBeginJobInternal:9470 : Started job: query (async=none vm=0x7f6bbc0b6db0 name=instance-00000011) 2023-07-13 08:35:22.233+0000: 44727: error : qemuDomainDiskByName:13629 : invalid argument: disk 'vdb' not found in domain 2023-07-13 08:35:22.233+0000: 44727: debug : qemuDomainObjEndJob:9746 : Stopping job: query (async=none vm=0x7f6bbc0b6db0 name=instance-00000011)
This problem was reproduced in CI for one of my stable/wallaby patches: /zuul.opendev. org/t/openstack /build/ 3ae58b4f95d7442 fb9110c4044acee 2b/logs /1f24fdc3bf9479 288b3a- 225501c9cce0e8b a4bd0f484907121 1d.ssl. cf1.rackcdn. com/888333/ 1/check/ nova-next/ 3ae58b4/ compute1/ logs/libvirt/ qemu/instance- 00000011_ log.txt /1f24fdc3bf9479 288b3a- 225501c9cce0e8b a4bd0f484907121 1d.ssl. cf1.rackcdn. com/888333/ 1/check/ nova-next/ 3ae58b4/ compute1/ logs/libvirt/ libvirtd_ log.txt /1f24fdc3bf9479 288b3a- 225501c9cce0e8b a4bd0f484907121 1d.ssl. cf1.rackcdn. com/888333/ 1/check/ nova-next/ 3ae58b4/ compute1/ logs/screen- n-cpu.txt /1f24fdc3bf9479 288b3a- 225501c9cce0e8b a4bd0f484907121 1d.ssl. cf1.rackcdn. com/888333/ 1/check/ nova-next/ 3ae58b4/ job-output. txt
https:/
https:/
https:/
https:/
https:/
Extracts:
Jul 13 08:35:22.230036 np0034667036 nova-compute[ 54149]: WARNING nova.virt. libvirt. driver [None req-7222880d- af15-4a90- b16d-24bdf5763e 09 None None] Received event <DeviceRemovedE vent: 1689237322.2269797, dd46f9ba- 2352-4da6- be3a-ecf68757e3 c0 => virtio-disk1> from libvirt but the driver is not waiting for it; ignored. 54149]: ERROR nova.virt. libvirt. driver [None req-473da26b- 0641-4cda- 84ef-9e451e5edd b9 tempest- TestVolumeSwap- 869256485 tempest- TestVolumeSwap- 869256485- project- admin] Failure rebasing volume /dev/sda on vdb.: libvirt. libvirtError: invalid argument: disk 'vdb' not found in domain 54149]: ERROR nova.virt. libvirt. driver Traceback (most recent call last): 54149]: ERROR nova.virt. libvirt. driver File "/opt/stack/ nova/nova/ virt/libvirt/ driver. py", line 2128, in _swap_volume 54149]: ERROR nova.virt. libvirt. driver while not dev.is_ job_complete( ): 54149]: ERROR nova.virt. libvirt. driver File "/opt/stack/ nova/nova/ virt/libvirt/ guest.py" , line 810, in is_job_complete 54149]: ERROR nova.virt. libvirt. driver status = self.get_job_info() 54149]: ERROR nova.virt. libvirt. driver File "/opt/stack/ nova/nova/ virt/libvirt/ guest.py" , line 717, in get_job_info 54149]: ERROR nova.virt. libvirt. driver status = self._guest. _domain. blockJobInfo( self._disk, flags=0) 54149]: ERROR nova.virt. libvirt. driver File "/usr/local/ lib/python3. 8/dist- packages/ eventlet/ tpool.py" , line 190, in doit 54149]: ERROR nova.virt. libvirt. driver result = proxy_call( self._autowrap, f, *args, **kwargs) 54149]: ERROR nova.virt. libvirt. driver File "/usr/local/ lib/python3. 8/dist- packages/ eventlet/ tpool.py" , line 148, in proxy_call 54149]: ERROR nova.virt. libvirt. driver rv = execute(f, *args, **kwargs) 54149]: ERROR nova.virt. libvirt. driver File "/usr/local/ lib/python3. 8/dist- packages/ eventlet/ tpool.py" , line 129, in execute 54149]: ERROR nova.virt. libvirt. driver six.reraise(c, e, tb) 54149]: ERROR nova.virt. libvirt. driver File "/usr/local/ lib/python3. 8/dist- packages/ six.py" , line 703, in reraise 54149]: ERROR nova.virt. libvirt. driver raise value 54149]: ERROR nova.virt. libvirt. driver File "/usr/local/ lib/python3. 8/dist- packages/ eventlet/ tpool.py" , line 83, in tworker 54149]: ERROR nova.virt. libvirt. driver rv = meth(*args, **kwargs) 54149]: ERROR nova.virt. libvirt. driver File "/usr/lib/ python3/ dist-packages/ libvirt. py", line 898, in blockJobInfo 54149]: ERROR nova.virt. libvirt. driver if ret is None: raise libvirtError ('virDomainGetB lockJobInfo( ) failed', dom=self) 54149]: ERROR nova.virt. libvirt. driver libvirt. libvirtError: invalid argument: disk 'vdb' not found in domain 54149]: ERROR nova.virt. libvirt. driver
Jul 13 08:35:22.242368 np0034667036 nova-compute[
Jul 13 08:35:22.242368 np0034667036 nova-compute[
Jul 13 08:35:22.242368 np0034667036 nova-compute[
Jul 13 08:35:22.242368 np0034667036 nova-compute[
Jul 13 08:35:22.242368 np0034667036 nova-compute[
Jul 13 08:35:22.242368 np0034667036 nova-compute[
Jul 13 08:35:22.242368 np0034667036 nova-compute[
Jul 13 08:35:22.242368 np0034667036 nova-compute[
Jul 13 08:35:22.242368 np0034667036 nova-compute[
Jul 13 08:35:22.242368 np0034667036 nova-compute[
Jul 13 08:35:22.242368 np0034667036 nova-compute[
Jul 13 08:35:22.242368 np0034667036 nova-compute[
Jul 13 08:35:22.242368 np0034667036 nova-compute[
Jul 13 08:35:22.242368 np0034667036 nova-compute[
Jul 13 08:35:22.242368 np0034667036 nova-compute[
Jul 13 08:35:22.242368 np0034667036 nova-compute[
Jul 13 08:35:22.242368 np0034667036 nova-compute[
Jul 13 08:35:22.242368 np0034667036 nova-compute[
Jul 13 08:35:22.242368 np0034667036 nova-compute[
Jul 13 08:35:22.242368 np0034667036 nova-compute[
Jul 13 08:35:22.242368 np0034667036 nova-compute[
Jul 13 08:35:22.242368 np0034667036 nova-compute[
2023-07-13 08:35:22.226+0000: 44724: debug : qemuMonitorEmit Event:1198 : mon=0x7f6bcc07b080 event=DEVICE_ DELETED leEvent: 551 : vm=0x7f6bbc0b6db0 ew:631 : obj=0x55ea304db760 IOProcessEvent: 205 : handle DEVICE_DELETED handler= 0x7f6bc1e3db80 data=0x55ea304ad810 DeviceDeleted: 1432 : mon=0x7f6bcc07b080 leDeviceDeleted :1364 : Device virtio-disk1 removed from domain 0x7f6bbc0b6db0 instance-00000011 ispose: 124 : obj=0x55ea304db760 tHandler: 4866 : vm=0x7f6bbc0b6db0, event=2 letedEvent: 4282 : Removing device virtio-disk1 from domain 0x7f6bbc0b6db0 instance-00000011 ginJobInternal: 9416 : Starting job: job=modify agentJob=none asyncJob=none (vm=0x7f6bbc0b6db0 name=instance- 00000011, current job=none agentJob=none async=none) ginJobInternal: 9470 : Started job: modify (async=none vm=0x7f6bbc0b6db0 name=instance- 00000011) eDiskDevice: 4218 : Removing disk virtio-disk1 from domain 0x7f6bbc0b6db0 instance-00000011 terMonitorInter nal:9869 : Entering monitor (mon=0x7f6bcc07b080 vm=0x7f6bbc0b6db0 name=instance- 00000011) itMonitorIntern al:9892 : Exited monitor (mon=0x7f6bcc07b080 vm=0x7f6bbc0b6db0 name=instance- 00000011) ew:631 : obj=0x7f6b80029ba0 ispose: 124 : obj=0x7f6b80029ba0 dJob:9746 : Stopping job: modify (async=none vm=0x7f6bbc0b6db0 name=instance- 00000011) ndleJob) is now running job remoteDispatchD omainGetBlockJo bInfo ginJobInternal: 9416 : Starting job: job=query agentJob=none asyncJob=none (vm=0x7f6bbc0b6db0 name=instance- 00000011, current job=none agentJob=none async=none) ginJobInternal: 9470 : Started job: query (async=none vm=0x7f6bbc0b6db0 name=instance- 00000011) yName:13629 : invalid argument: disk 'vdb' not found in domain dJob:9746 : Stopping job: query (async=none vm=0x7f6bbc0b6db0 name=instance- 00000011)
2023-07-13 08:35:22.226+0000: 44724: debug : qemuProcessHand
2023-07-13 08:35:22.226+0000: 44724: debug : virObjectEventN
2023-07-13 08:35:22.226+0000: 44724: debug : qemuMonitorJSON
2023-07-13 08:35:22.226+0000: 44724: debug : qemuMonitorEmit
2023-07-13 08:35:22.226+0000: 44724: debug : qemuProcessHand
2023-07-13 08:35:22.226+0000: 44724: debug : virObjectEventD
2023-07-13 08:35:22.226+0000: 57688: debug : qemuProcessEven
2023-07-13 08:35:22.226+0000: 57688: debug : processDeviceDe
2023-07-13 08:35:22.226+0000: 57688: debug : qemuDomainObjBe
2023-07-13 08:35:22.226+0000: 57688: debug : qemuDomainObjBe
2023-07-13 08:35:22.226+0000: 57688: debug : qemuDomainRemov
2023-07-13 08:35:22.226+0000: 57688: debug : qemuDomainObjEn
2023-07-13 08:35:22.226+0000: 57688: debug : qemuDomainObjEx
2023-07-13 08:35:22.226+0000: 57688: debug : virObjectEventN
2023-07-13 08:35:22.226+0000: 44724: debug : virObjectEventD
2023-07-13 08:35:22.227+0000: 57688: debug : qemuDomainObjEn
2023-07-13 08:35:22.233+0000: 44727: debug : virThreadJobSet:93 : Thread 44727 (virNetServerHa
2023-07-13 08:35:22.233+0000: 44727: debug : qemuDomainObjBe
2023-07-13 08:35:22.233+0000: 44727: debug : qemuDomainObjBe
2023-07-13 08:35:22.233+0000: 44727: error : qemuDomainDiskB
2023-07-13 08:35:22.233+0000: 44727: debug : qemuDomainObjEn