Hanging test: Testcase Cancellation timeout? #49
Description
I have a test that got stuck (also, not reproducibly). In the log I can find virtchd: testvm: Sender hung up unexpectedly. We might want to cancel a test case if it takes longer than 10 minutes or so?
This is the log:
Show the very long log
Running test: test_live_migration
controllerVM: must succeed: virsh define /etc/domain-chv.xml
controllerVM # [ 68.815334] polkitd[1023]: Registered Authentication Agent for unix-process:1758:6878 (system bus name :1.46 [/nix/store/xbajm3ijh97bx5y28z5qs1q8sp4mdgci-polkit-126-bin/bin/pkttyagent --process 1758 --notify-fd 4 --fallback], object path /org/freedesktop/PolicyKit1/AuthenticationAgent, locale en_US.UTF-8)
controllerVM # [ 68.819406] polkitd[1023]: Unregistered Authentication Agent for unix-process:1758:6878 (system bus name :1.46, object path /org/freedesktop/PolicyKit1/AuthenticationAgent, locale en_US.UTF-8) (disconnected from bus)
controllerVM: (finished: must succeed: virsh define /etc/domain-chv.xml, in 0.06 seconds)
controllerVM: must succeed: virsh start testvm
controllerVM # [ 68.879325] polkitd[1023]: Registered Authentication Agent for unix-process:1767:6884 (system bus name :1.47 [/nix/store/xbajm3ijh97bx5y28z5qs1q8sp4mdgci-polkit-126-bin/bin/pkttyagent --process 1767 --notify-fd 4 --fallback], object path /org/freedesktop/PolicyKit1/AuthenticationAgent, locale en_US.UTF-8)
controllerVM # [ 68.884172] polkitd[1023]: Unregistered Authentication Agent for unix-process:1767:6884 (system bus name :1.47, object path /org/freedesktop/PolicyKit1/AuthenticationAgent, locale en_US.UTF-8) (disconnected from bus)
controllerVM # [ 68.894389] virtchd[1659]: Commit hash: 0000000000000000000000000000000000000000
controllerVM # [ 68.900314] virtchd[1659]: error from service: GDBus.Error:org.freedesktop.machine1.NoMachineForPID: PID 1777 does not belong to any known machine
controllerVM # [ 68.911326] systemd-networkd[525]: vnet0: Link UP
controllerVM # [ 68.911485] systemd-networkd[525]: vnet0: Gained carrier
controllerVM # [ 68.911841] virtchd[1659]: payload sent with net-add request to CH = {"id":"net_0","mac":"52:54:00:e5:b8:ef","num_queues":2}
controllerVM # [ 68.914796] systemd-machined[724]: New machine ch-1777-testvm.
controllerVM # [ 68.922799] systemd-networkd[525]: vnet0: Configuring with /etc/systemd/network/10-vnet0.network.
controllerVM # [ 68.924206] systemd[1]: Started Virtual Machine ch-1777-testvm.
controllerVM # [ 68.970736] br0: port 1(vnet0) entered blocking state
controllerVM # [ 68.971114] br0: port 1(vnet0) entered disabled state
controllerVM # [ 68.971451] vnet0: entered allmulticast mode
controllerVM # [ 68.971782] vnet0: entered promiscuous mode
controllerVM # [ 68.927250] virtchd[1659]: curl perform[ 68.972097] br0: port 1(vnet0) entered blocking state
controllerVM #
controllerVM # [ 68.972414] br0: port 1(vnet0) entered forwarding state
controllerVM # [ 68.933112] systemd-networkd[525]: br0: Gained carrier
controllerVM # [ 69.026414] virtchd[1659]: done
controllerVM # [ 69.026589] virtchd[1659]: HTTP Response:
controllerVM: (finished: must succeed: virsh start testvm, in 0.20 seconds)
Wait for ssh 0/100
controllerVM # [ 69.297655] virtchd[1659]: testvm: Unknown event: virtio-device:activated
controllerVM # [ 69.312885] virtchd[1659]: testvm: Unknown event: virtio-device:activated
controllerVM # [ 69.383684] virtchd[1659]: testvm: Unknown event: virtio-device:activated
controllerVM # [ 71.308535] virtchd[1659]: testvm: Unknown event: virtio-device:reset
controllerVM # [ 71.308937] virtchd[1659]: testvm: Unknown event: virtio-device:reset
controllerVM # [ 71.309430] virtchd[1659]: testvm: Unknown event: virtio-device:reset
controllerVM # [ 71.755390] virtchd[1659]: testvm: Unknown event: virtio-device:activated
controllerVM # [ 71.762859] virtchd[1659]: testvm: Unknown event: virtio-device:activated
controllerVM # ssh: connect to host 192.168.1.2 port 22: No route to host
controllerVM # [ 72.596386] virtchd[1659]: testvm: Unknown event: virtio-device:activated
controllerVM # [ 72.605032] virtchd[1659]: testvm: Unknown event: virtio-device:activated
Wait for ssh 1/100
controllerVM # ssh: connect to host 192.168.1.2 port 22: No route to host
Wait for ssh 2/100
controllerVM # [ 77.721816] virtproxyd[1300]: internal error: connection closed due to keepalive timeout
controllerVM # [ 77.722668] virtproxyd[1300]: internal error: client socket is closed
controllerVM # [ 77.722864] virtproxyd[1300]: unexpected domain event deregister failure
controllerVM # [ 77.723355] virtproxyd[1300]: internal error: client socket is closed
controllerVM # ssh: connect to host 192.168.1.2 port 22: No route to host
Wait for ssh 3/100
controllerVM # Warning: Permanently added '192.168.1.2' (ED25519) to the list of known hosts.
controllerVM: must succeed: virsh attach-device testvm /etc/new_interface.xml
controllerVM # [ 81.910689] polkitd[1023]: Registered Authentication Agent for unix-process:1836:8187 (system bus name :1.48 [/nix/store/xbajm3ijh97bx5y28z5qs1q8sp4mdgci-polkit-126-bin/bin/pkttyagent --process 1836 --notify-fd 4 --fallback], object path /org/freedesktop/PolicyKit1/AuthenticationAgent, locale en_US.UTF-8)
controllerVM # [ 81.914037] polkitd[1023]: Unregistered Authentication Agent for unix-process:1836:8187 (system bus name :1.48, object path /org/freedesktop/PolicyKit1/AuthenticationAgent, locale en_US.UTF-8) (disconnected from bus)
controllerVM # [ 81.924509] virtchd[1659]: chDomainAttachDeviceFlags
controllerVM # <interface type='ethernet'>
controllerVM # <mac address='52:54:00:e5:b8:dd'/>
controllerVM # <target dev='tap0'/>
controllerVM # <model type='virtio'/>
controllerVM # <driver queues='1'/>
controllerVM # </interface>
controllerVM #
controllerVM #
controllerVM # [ 81.926187] virtchd[1659]: Flags: 1
controllerVM # [ 81.926331] virtchd[1659]: chDomainAttachDeviceFlags xml: <interface type='ethernet'>
controllerVM # <mac address='52:54:00:e5:b8:dd'/>
controllerVM # <target dev='tap0'/>
controllerVM # <model type='virtio'/>
controllerVM # <driver queues='1'/>
controllerVM # </interface>
controllerVM #
controllerVM # [ 81.927575] virtchd[1659]: Try to insert net device
controllerVM # [ 81.935801] virtchd[1659]: payload sent with net-add request to CH = {"id":"net_1","mac":"52:54:00:e5:b8:dd","num_queues":2}
controllerVM # [ 81.937355] systemd-networkd[525]: tap0: Link UP
controllerVM # [ 81.937808] systemd-networkd[525]: tap0: Gained carrier
controllerVM # [ 81.941429] (udev-worker)[1847]: Network interface NamePolicy= disabled on kernel command line.
controllerVM: (finished: must succeed: virsh attach-device testvm /etc/new_interface.xml, in 0.07 seconds)
controllerVM: must succeed: qemu-img create -f raw /nfs-root/disk.img 100M
controllerVM # [ 81.951616] virtchd[1659]: testvm: Unknown event: virtio-device:activated
controllerVM: (finished: must succeed: qemu-img create -f raw /nfs-root/disk.img 100M, in 0.03 seconds)
controllerVM: must succeed: chmod 0666 /nfs-root/disk.img
controllerVM: (finished: must succeed: chmod 0666 /nfs-root/disk.img, in 0.01 seconds)
controllerVM: must succeed: virsh attach-disk --domain testvm --target vdb --persistent --source /var/lib/libvirt/storage-pools/nfs-share/disk.img
controllerVM # [ 82.019617] polkitd[1023]: Registered Authentication Agent for unix-process:1861:8198 (system bus name :1.49 [/nix/store/xbajm3ijh97bx5y28z5qs1q8sp4mdgci-polkit-126-bin/bin/pkttyagent --process 1861 --notify-fd 4 --fallback], object path /org/freedesktop/PolicyKit1/AuthenticationAgent, locale en_US.UTF-8)
controllerVM # [ 82.023731] polkitd[1023]: Unregistered Authentication Agent for unix-process:1861:8198 (system bus name :1.49, object path /org/freedesktop/PolicyKit1/AuthenticationAgent, locale en_US.UTF-8) (disconnected from bus)
controllerVM # [ 82.034725] virtchd[1659]: chDomainAttachDeviceFlags
controllerVM # <disk type='file'>
controllerVM # <source file='/var/lib/libvirt/storage-pools/nfs-share/disk.img'/>
controllerVM # <target dev='vdb'/>
controllerVM # </disk>
controllerVM #
controllerVM #
controllerVM # [ 82.035562] virtchd[1659]: Flags: 3
controllerVM # [ 82.036160] virtchd[1659]: virDomainDiskInsert
controllerVM # [ 82.036359] virtchd[1659]: chDomainAttachDeviceFlags xml: <disk type='file'>
controllerVM # <source file='/var/lib/libvirt/storage-pools/nfs-share/disk.img'/>
controllerVM # <target dev='vdb'/>
controllerVM # </disk>
controllerVM #
controllerVM # [ 82.038588] virtchd[1659]: Reponse code from CH: 200
controllerVM #
controllerVM # [ 82.038895] virtchd[1659]: HTTP Response: {"id":"virtio-disk1","bdf":"0000:00:06.0"}
controllerVM # [ 82.039092] virtchd[1659]: Disk : dst: vdb drivername: (null) alias: virtio-disk1
controllerVM # [ 82.047298] virtchd[1659]: testvm: Unknown event: virtio-device:activated
controllerVM: (finished: must succeed: virsh attach-disk --domain testvm --target vdb --persistent --source /var/lib/libvirt/storage-pools/nfs-share/disk.img, in 0.07 seconds)
controllerVM: must succeed: virsh migrate --domain testvm --desturi ch+tcp://192.168.100.2/session --persistent --live --p2p
controllerVM # [ 82.089495] polkitd[1023]: Registered Authentication Agent for unix-process:1871:8205 (system bus name :1.50 [/nix/store/xbajm3ijh97bx5y28z5qs1q8sp4mdgci-polkit-126-bin/bin/pkttyagent --process 1871 --notify-fd 4 --fallback], object path /org/freedesktop/PolicyKit1/AuthenticationAgent, locale en_US.UTF-8)
controllerVM # [ 82.092548] polkitd[1023]: Unregistered Authentication Agent for unix-process:1871:8205 (system bus name :1.50, object path /org/freedesktop/PolicyKit1/AuthenticationAgent, locale en_US.UTF-8) (disconnected from bus)
controllerVM # [ 82.105682] virtchd[1659]: chDomainMigratePerform3Params dconnuri: ch+tcp://192.168.100.2/session dname: (null)
controllerVM # [ 82.105856] virtchd[1659]: chDomainMigratePerform3 0x7fab5c008270 (null) (null) 0 0x7fab66de4948 0x7fab66de493c ch+tcp://192.168.100.2/session (null) 11 (null) 0
controllerVM # [ 82.106214] virtchd[1659]: Got dconnuri. Probably p2p/direct migration. Do special extra handling
controllerVM # [ 82.106485] virtchd[1659]: Got domain xml: <domain type='kvm' id='1777'>
controllerVM # <name>testvm</name>
controllerVM # <uuid>4eb6319a-4302-4407-9a56-802fc7e6a422</uuid>
controllerVM # <memory unit='KiB'>2097152</memory>
controllerVM # <currentMemory unit='KiB'>2097152</currentMemory>
controllerVM # <vcpu placement='static'>2</vcpu>
controllerVM # <resource>
controllerVM # <partition>/machine</partition>
controllerVM # </resource>
controllerVM # <os>
controllerVM # <type arch='x86_64'>hvm</type>
controllerVM # <kernel>/etc/CLOUDHV.fd</kernel>
controllerVM # <boot dev='hd'/>
controllerVM # </os>
controllerVM # <clock offset='utc'/>
controllerVM # <on_poweroff>destroy</on_poweroff>
controllerVM # <on_reboot>restart</on_reboot>
controllerVM # <on_crash>destroy</on_crash>
controllerVM # <devices>
controllerVM # <emulator>cloud-hypervisor</emulator>
controllerVM # <disk type='file' device='disk'>
controllerVM # <source file='/var/lib/libvirt/storage-pools/nfs-share/nixos.img'/>
controllerVM # <target dev='vda' bus='virtio'/>
controllerVM # <alias name='virtio-disk0'/>
controllerVM # </disk>
controllerVM # <disk type='file' device='disk'>
controllerVM # <source file='/var/lib/libvirt/storage-pools/nfs-share/disk.img'/>
controllerVM # <target dev='vdb' bus='virtio'/>
controllerVM # <alias name='virtio-disk1'/>
controllerVM # </disk>
controllerVM # <interface type='ethernet'>
controllerVM # <mac address='52:54:00:e5:b8:ef'/>
controllerVM # <target dev='vnet0'/>
controllerVM # <model type='virtio'/>
controllerVM # <driver queues='1'/>
controllerVM # <alias name='net_0'/>
controllerVM # <address type='pci' domain='0x0000' bus='0x00' slot='0x01' function='0x0'/>
controllerVM # </interface>
controllerVM # <interface type='ethernet'>
controllerVM # <mac address='52:54:00:e5:b8:dd'/>
controllerVM # <target dev='tap0'/>
controllerVM # <model type='virtio'/>
controllerVM # <driver queues='1'/>
controllerVM # <alias name='net_1'/>
controllerVM # <address type='pci' domain='0x0000' bus='0x00' slot='0x02' function='0x0'/>
controllerVM # </interface>
controllerVM # <serial type='pty'>
controllerVM # <source path='/dev/pts/0'/>
controllerVM # <target port='0'/>
controllerVM # </serial>
controllerVM # </devices>
controllerVM # </domain>
controllerVM #
computeVM # [ 82.163618] systemd[1]: Listening on libvirt proxy daemon admin socket.
computeVM # [ 82.163808] systemd[1]: Listening on libvirt proxy daemon read-only socket.
computeVM # [ 82.165373] systemd[1]: Starting libvirt proxy daemon...
computeVM # [ 82.209202] systemd[1]: Started libvirt proxy daemon.
computeVM # [ 82.219805] virtchd[844]: libvirt version: 11.3.0
computeVM # [ 82.220102] virtchd[844]: hostname: computeVM
computeVM # [ 82.220271] virtchd[844]: chDomainMigratePrepare3 0x7f4130004ad0 (null) 0 0x7f4136061970 0x7f413606196c 192.168.100.2 0x7f4118002dc0 11 (null) <domain type='kvm' id='1777'>
computeVM # <name>testvm</name>
computeVM # <uuid>4eb6319a-4302-4407-9a56-802fc7e6a422</uuid>
computeVM # <memory unit='KiB'>2097152</memory>
computeVM # <currentMemory unit='KiB'>2097152</currentMemory>
computeVM # <vcpu placement='static'>2</vcpu>
computeVM # <resource>
computeVM # <partition>/machine</partition>
computeVM # </resource>
computeVM # <os>
computeVM # <type arch='x86_64'>hvm</type>
computeVM # <kernel>/etc/CLOUDHV.fd</kernel>
computeVM # <boot dev='hd'/>
computeVM # </os>
computeVM # <clock offset='utc'/>
computeVM # <on_poweroff>destroy</on_poweroff>
computeVM # <on_reboot>restart</on_reboot>
computeVM # <on_crash>destroy</on_crash>
computeVM # <devices>
computeVM # <emulator>cloud-hypervisor</emulator>
computeVM # <disk type='file' device='disk'>
computeVM # <source file='/var/lib/libvirt/storage-pools/nfs-share/nixos.img'/>
computeVM # <target dev='vda' bus='virtio'/>
computeVM # <alias name='virtio-disk0'/>
computeVM # </disk>
computeVM # <disk type='file' device='disk'>
computeVM # <source file='/var/lib/libvirt/storage-pools/nfs-share/disk.img'/>
computeVM # <target dev='vdb' bus='virtio'/>
computeVM # <alias name='virtio-disk1'/>
computeVM # </disk>
computeVM # <interface type='ethernet'>
computeVM # <mac address='52:54:00:e5:b8:ef'/>
computeVM # <target dev='vnet0'/>
computeVM # <model type='virtio'/>
computeVM # <driver queues='1'/>
computeVM # <alias name='net_0'/>
computeVM # <address type='pci' domain='0x0000' bus='0x00' slot='0x01' function='0x0'/>
computeVM # </interface>
computeVM # <interface type='ethernet'>
computeVM # <mac address='52:54:00:e5:b8:dd'/>
computeVM # <target dev='tap0'/>
computeVM # <model type='virtio'/>
computeVM # <driver queues='1'/>
computeVM # <alias name='net_1'/>
computeVM # <address type='pci' domain='0x0000' bus='0x00' slot='0x02' function='0x0'/>
computeVM # </interface>
computeVM # <serial type='pty'>
computeVM # <source path='/dev/pts/0'/>
computeVM # <target port='0'/>
computeVM # </serial>
computeVM # </devices>
computeVM # </domain>
computeVM #
computeVM # [ 82.226390] virtchd[844]: Creating domain log file for testvm domain
computeVM # [ 82.235206] virtchd[844]: error from service: GDBus.Error:org.freedesktop.machine1.NoMachineForPID: PID 1248 does not belong to any known machine
computeVM # [ 82.238043] systemd-machined[722]: New machine ch-1248-testvm.
computeVM # [ 82.249367] systemd[1]: Started Virtual Machine ch-1248-testvm.
computeVM # [ 82.254945] virtchd[844]: Try creating migration thread (nil) 0x7f4118007f00 0x7f40e8003080
computeVM # [ 82.255185] virtchd[844]: Finished creating migration thread
computeVM # [ 82.255601] virtchd[844]: In thread. 49152 0x7f41180073e0 0x7f4118007f00 0x7f40e8003080
computeVM # [ 82.255844] virtchd[844]: In virCHMonitorMigrationReceive
computeVM # [ 82.256143] virtchd[844]: Receive VM from url tcp:0.0.0.0:49152 json: {"receiver_url":"tcp:0.0.0.0:49152","net_fds":[{"id":"net_0","num_fds":1},{"id":"net_1","num_fds":1}]}
computeVM # [ 82.256406] virtchd[844]: create network devices
computeVM # [ 82.268854] systemd-networkd[534]: vnet0: Link UP
computeVM # [ 82.269068] systemd-networkd[534]: vnet0: Gained carrier
computeVM # [ 82.272927] (udev-worker)[1258]: Network interface NamePolicy= disabled on kernel command line.
computeVM # [ 82.282615] virtchd[844]: domain interface start devices
computeVM # [ 82.282915] virtchd[844]: socketsendmsgwithfds
computeVM # [ 82.283538] virtchd[844]: wait for response
computeVM # [ 82.283867] virtchd[844]: persist domain on receiving side
computeVM # [ 82.285339] systemd-networkd[534]: tap0: Link UP
computeVM # [ 82.285640] systemd-networkd[534]: tap0: Gained carrier
computeVM # [ 82.287186] virtchd[844]: Fin migrationPrepare
controllerVM # [ 82.239880] virtchd[1659]: Got uri_out that will be used for CHV migration: tcp:192.168.100.2:49152
controllerVM # [ 82.240117] virtchd[1659]: Send VM to url tcp:192.168.100.2:49152 json {"destination_url":"tcp:192.168.100.2:49152"}
computeVM # [ 82.291264] systemd-networkd[534]: vnet0: Configuring with /etc/systemd/network/10-vnet0.network.
controllerVM # [ 82.241918] virtchd[1659]: P2P: Call finish on remote context
computeVM # [ 82.292163] virtchd[844]: chDomainMigrateFinish3 0x7f4130004ad0 testvm (null) 0 0x7f4137864970 0x7f413786496c 11 0
computeVM # [ 82.296996] (udev-worker)[1262]: Network interface NamePolicy= disabled on kernel command line.
computeVM # [ 82.359489] br0: port 1(vnet0) entered blocking state
computeVM # [ 82.359734] br0: port 1(vnet0) entered disabled state
computeVM # [ 82.360572] vnet0: entered allmulticast mode
computeVM # [ 82.360797] vnet0: entered promiscuous mode
computeVM # [ 82.361040] br0: port 1(vnet0) entered blocking state
computeVM # [ 82.361331] br0: port 1(vnet0) entered forwarding state
computeVM # [ 82.303156] systemd-networkd[534]: br0: Gained carrier
controllerVM # [ 83.012275] systemd-networkd[525]: tap0: Link DOWN
controllerVM # [ 83.012919] systemd-networkd[525]: tap0: Lost carrier
controllerVM # [ 83.019467] s[ 83.063606] br0: port 1(vnet0) entered disabled state
controllerVM # ystemd-networkd[525]: vnet0: Link DOWN
controllerVM # [ 83.019754] systemd-networkd[525]: vnet0: Lost carrier
controllerVM # [ 83.064864] vnet0 (unregistering): left allmulticast mode
controllerVM # [ 83.065398] vnet0 (unregistering): left promiscuous mode
controllerVM # [ 83.065880] br0: port 1(vnet0) entered disabled state
controllerVM # [ 83.143590] virtchd[1659]: testvm: Sender hung up unexpectedly!
controllerVM # [ 83.144624] systemd[1]: machine-ch\x2d1777\x2dtestvm.scope: Deactivated successfully.
controllerVM # [ 83.145562] systemd[1]: machine-ch\x2d1777\x2dtestvm.scope: Consumed 8.218s CPU time, 1G memory peak, 40B incoming IP traffic, 60B outgoing IP traffic.
controllerVM # [ 83.148283] systemd-machined[724]: Machine ch-1777-testvm terminated.
computeVM # [ 83.333652] systemd-networkd[534]: tap0: Gained IPv6LL
controllerVM # [ 84.036971] systemd-networkd[525]: br0: Lost carrier
computeVM # [ 84.165384] systemd-networkd[534]: br0: Gained IPv6LL
controllerVM # [ 131.144291] systemd[1]: virtstoraged.service: Deactivated successfully.
controllerVM # [ 131.145046] systemd[1]: virtstoraged.service: Consumed 71ms CPU time, 6.4M memory peak, 4K written to disk, 928B incoming IP traffic, 1.3K outgoing IP traffic.
computeVM # [ 132.099455] systemd[1]: virtstoraged.service: Deactivated successfully.
controllerVM # [ 197.827507] systemd[1]: virtproxyd.service: Deactivated successfully.
controllerVM # [ 917.759436] systemd[1]: Starting Cleanup of Temporary Directories...
controllerVM # [ 917.826520] systemd[1]: systemd-tmpfiles-clean.service: Deactivated successfully.
controllerVM # [ 917.827297] systemd[1]: Finished Cleanup of Temporary Directories.
computeVM # [ 920.693853] systemd[1]: Starting Cleanup of Temporary Directories...
computeVM # [ 920.760498] systemd[1]: systemd-tmpfiles-clean.service: Deactivated successfully.
computeVM # [ 920.761019] systemd[1]: Finished Cleanup of Temporary Directories.