Trying to post more log from same run 2024-01-24 18:10:52,234 139089 INFO [tempest.lib.common.ssh] Creating ssh connection to '10.246.182.211:22' as 'ubuntu' with public key authentication 2024-01-24 18:11:23,786 139089 INFO [tempest.lib.common.ssh] ssh connection to ubuntu@10.246.182.211 successfully created 2024-01-24 18:11:23,787 139089 DEBUG [tempest.lib.common.utils.linux.remote_client] Remote command: set -eu -o pipefail; PATH=$PATH:/sbin:/usr/sbin; sudo sh -c "date > /tmp/timestamp; sync" 2024-01-24 18:11:23,787 139089 INFO [tempest.lib.common.ssh] Creating ssh connection to '10.246.182.211:22' as 'ubuntu' with public key authentication 2024-01-24 18:11:23,966 139089 INFO [tempest.lib.common.ssh] ssh connection to ubuntu@10.246.182.211 successfully created 2024-01-24 18:11:26,386 139089 DEBUG [tempest.lib.common.utils.linux.remote_client] Remote command: set -eu -o pipefail; PATH=$PATH:/sbin:/usr/sbin; sudo cat /tmp/timestamp 2024-01-24 18:11:26,386 139089 INFO [tempest.lib.common.ssh] Creating ssh connection to '10.246.182.211:22' as 'ubuntu' with public key authentication 2024-01-24 18:11:26,434 139089 INFO [tempest.lib.common.ssh] ssh connection to ubuntu@10.246.182.211 successfully created 2024-01-24 18:11:35,795 139089 INFO [tempest.common.waiters] State transition "ACTIVE/shelving" ==> "SHELVED_OFFLOADED/None" after 8 second wait 2024-01-24 18:11:38,907 139089 INFO [tempest.common.waiters] State transition "SHELVED_OFFLOADED/unshelving" ==> "SHELVED_OFFLOADED/spawning" after 2 second wait 2024-01-24 18:11:44,382 139089 INFO [tempest.common.waiters] State transition "SHELVED_OFFLOADED/spawning" ==> "ACTIVE/None" after 8 second wait 2024-01-24 18:11:44,383 139089 INFO [tempest.lib.common.ssh] Creating ssh connection to '10.246.182.211:22' as 'ubuntu' with public key authentication 2024-01-24 18:11:59,778 139089 WARNING [tempest.lib.common.ssh] Failed to establish authenticated ssh connection to ubuntu@10.246.182.211 ([Errno None] Unable to connect to port 22 on 10.246.182.211). Number attempts: 1. Retry after 2 seconds. 2024-01-24 18:12:02,282 139089 WARNING [tempest.lib.common.ssh] Failed to establish authenticated ssh connection to ubuntu@10.246.182.211 ([Errno None] Unable to connect to port 22 on 10.246.182.211). Number attempts: 2. Retry after 3 seconds. 2024-01-24 18:12:06,127 139089 INFO [tempest.lib.common.ssh] ssh connection to ubuntu@10.246.182.211 successfully created 2024-01-24 18:12:06,128 139089 DEBUG [tempest.lib.common.utils.linux.remote_client] Remote command: set -eu -o pipefail; PATH=$PATH:/sbin:/usr/sbin; sudo cat /tmp/timestamp 2024-01-24 18:12:06,129 139089 INFO [tempest.lib.common.ssh] Creating ssh connection to '10.246.182.211:22' as 'ubuntu' with public key authentication 2024-01-24 18:12:06,509 139089 INFO [tempest.lib.common.ssh] ssh connection to ubuntu@10.246.182.211 successfully created 2024-01-24 18:12:07,387 139089 ERROR [tempest.lib.common.utils.linux.remote_client] (TestShelveInstance:test_shelve_volume_backed_instance) Executing command on 10.246.182.211 failed. Error: Command 'set -eu -o pipefail; PATH=$PATH:/sbin:/usr/sbin; sudo cat /tmp/timestamp' failed, exit status: 1, stderr: cat: /tmp/timestamp: No such file or directory nova-compute log 2024-01-24 18:10:47.103 1773994 INFO nova.compute.manager [req-cde71d46-e68f-47de-942a-ee917730c9d1 - - - - -] [instance: ab19b985-3348-4efe-b89d-7613172ad83d] VM Started (Lifecycle Event) 2024-01-24 18:10:47.107 1773994 INFO nova.virt.libvirt.driver [-] [instance: ab19b985-3348-4efe-b89d-7613172ad83d] Instance spawned successfully. 2024-01-24 18:10:47.152 1773994 INFO nova.compute.manager [req-cde71d46-e68f-47de-942a-ee917730c9d1 - - - - -] [instance: ab19b985-3348-4efe-b89d-7613172ad83d] During sync_power_state the instance has a pending task (spawning). Skip. 2024-01-24 18:10:47.152 1773994 INFO nova.compute.manager [req-cde71d46-e68f-47de-942a-ee917730c9d1 - - - - -] [instance: ab19b985-3348-4efe-b89d-7613172ad83d] VM Paused (Lifecycle Event) 2024-01-24 18:10:47.173 1773994 INFO nova.compute.manager [req-cde71d46-e68f-47de-942a-ee917730c9d1 - - - - -] [instance: ab19b985-3348-4efe-b89d-7613172ad83d] VM Resumed (Lifecycle Event) 2024-01-24 18:10:47.189 1773994 INFO nova.compute.manager [req-06d3c78c-e75f-4c70-9aed-98fcfc448368 901ac55362b14df2b85e70108d2483d4 522d33bee871460b97f190ebe6056951 - 02eb9a79fe48408ea7094c218489b4f6 02eb9a79fe48408ea7094c218489b4f6] [instance: ab19b985-3348-4efe-b89d-7613172ad83d] Took 3.88 seconds to spawn the instance on the hypervisor. 2024-01-24 18:10:47.232 1773994 INFO nova.compute.manager [req-cde71d46-e68f-47de-942a-ee917730c9d1 - - - - -] [instance: ab19b985-3348-4efe-b89d-7613172ad83d] During sync_power_state the instance has a pending task (spawning). Skip. 2024-01-24 18:10:47.268 1773994 INFO nova.compute.manager [req-06d3c78c-e75f-4c70-9aed-98fcfc448368 901ac55362b14df2b85e70108d2483d4 522d33bee871460b97f190ebe6056951 - 02eb9a79fe48408ea7094c218489b4f6 02eb9a79fe48408ea7094c218489b4f6] [instance: ab19b985-3348-4efe-b89d-7613172ad83d] Took 7.05 seconds to build instance. 2024-01-24 18:10:48.302 1773994 WARNING nova.compute.manager [req-1c646d14-04e0-442e-988a-7245869e11a3 1a505a6a35c4490196d2d33a3a8298b5 0ff89803dacf4eb4bd58aeef137b8ff3 - bf9986706c2d408f88d1a4ee29ed1952 bf9986706c2d408f88d1a4ee29ed1952] [instance: ab19b985-3348-4efe-b89d-7613172ad83d] Received unexpected event network-vif-plugged-2a8f679d-5568-4f2f-aae8-0445c57e61f7 for instance with vm_state active and task_state None. 2024-01-24 18:11:27.511 1773994 INFO nova.compute.manager [req-45174ab6-1c28-4ddf-85df-7fe3d38f6b3c 901ac55362b14df2b85e70108d2483d4 522d33bee871460b97f190ebe6056951 - 02eb9a79fe48408ea7094c218489b4f6 02eb9a79fe48408ea7094c218489b4f6] [instance: ab19b985-3348-4efe-b89d-7613172ad83d] Shelve offloading 2024-01-24 18:11:31.708 1773994 WARNING nova.compute.manager [req-7837f468-d794-4771-aa56-84dc88f71317 1a505a6a35c4490196d2d33a3a8298b5 0ff89803dacf4eb4bd58aeef137b8ff3 - bf9986706c2d408f88d1a4ee29ed1952 bf9986706c2d408f88d1a4ee29ed1952] [instance: ab19b985-3348-4efe-b89d-7613172ad83d] Received unexpected event network-vif-unplugged-2a8f679d-5568-4f2f-aae8-0445c57e61f7 for instance with vm_state active and task_state shelving. 2024-01-24 18:11:32.052 1773994 INFO nova.virt.libvirt.driver [req-45174ab6-1c28-4ddf-85df-7fe3d38f6b3c 901ac55362b14df2b85e70108d2483d4 522d33bee871460b97f190ebe6056951 - 02eb9a79fe48408ea7094c218489b4f6 02eb9a79fe48408ea7094c218489b4f6] [instance: ab19b985-3348-4efe-b89d-7613172ad83d] Instance shutdown successfully after 4 seconds. 2024-01-24 18:11:32.080 1773994 INFO nova.virt.libvirt.driver [-] [instance: ab19b985-3348-4efe-b89d-7613172ad83d] Instance destroyed successfully. 2024-01-24 18:11:33.310 1773994 INFO nova.virt.libvirt.driver [-] [instance: ab19b985-3348-4efe-b89d-7613172ad83d] Instance destroyed successfully. 2024-01-24 18:11:33.349 1773994 INFO nova.virt.libvirt.driver [req-45174ab6-1c28-4ddf-85df-7fe3d38f6b3c 901ac55362b14df2b85e70108d2483d4 522d33bee871460b97f190ebe6056951 - 02eb9a79fe48408ea7094c218489b4f6 02eb9a79fe48408ea7094c218489b4f6] [instance: ab19b985-3348-4efe-b89d-7613172ad83d] Deleting instance files /var/lib/nova/instances/ab19b985-3348-4efe-b89d-7613172ad83d_del 2024-01-24 18:11:33.350 1773994 INFO nova.virt.libvirt.driver [req-45174ab6-1c28-4ddf-85df-7fe3d38f6b3c 901ac55362b14df2b85e70108d2483d4 522d33bee871460b97f190ebe6056951 - 02eb9a79fe48408ea7094c218489b4f6 02eb9a79fe48408ea7094c218489b4f6] [instance: ab19b985-3348-4efe-b89d-7613172ad83d] Deletion of /var/lib/nova/instances/ab19b985-3348-4efe-b89d-7613172ad83d_del complete 2024-01-24 18:11:33.738 1773994 WARNING nova.compute.manager [req-35f9f91c-6597-47f5-9973-903615c5f11d 1a505a6a35c4490196d2d33a3a8298b5 0ff89803dacf4eb4bd58aeef137b8ff3 - bf9986706c2d408f88d1a4ee29ed1952 bf9986706c2d408f88d1a4ee29ed1952] [instance: ab19b985-3348-4efe-b89d-7613172ad83d] Received unexpected event network-vif-plugged-2a8f679d-5568-4f2f-aae8-0445c57e61f7 for instance with vm_state active and task_state shelving. 2024-01-24 18:11:33.934 1773994 INFO nova.scheduler.client.report [req-45174ab6-1c28-4ddf-85df-7fe3d38f6b3c 901ac55362b14df2b85e70108d2483d4 522d33bee871460b97f190ebe6056951 - 02eb9a79fe48408ea7094c218489b4f6 02eb9a79fe48408ea7094c218489b4f6] Deleted allocations for instance ab19b985-3348-4efe-b89d-7613172ad83d 2024-01-24 18:11:38.253 1773994 INFO nova.compute.manager [req-f771fb53-b2cd-421f-8718-d49b7b81229f 901ac55362b14df2b85e70108d2483d4 522d33bee871460b97f190ebe6056951 - 02eb9a79fe48408ea7094c218489b4f6 02eb9a79fe48408ea7094c218489b4f6] [instance: ab19b985-3348-4efe-b89d-7613172ad83d] Unshelving 2024-01-24 18:11:38.410 1773994 INFO nova.virt.block_device [req-f771fb53-b2cd-421f-8718-d49b7b81229f 901ac55362b14df2b85e70108d2483d4 522d33bee871460b97f190ebe6056951 - 02eb9a79fe48408ea7094c218489b4f6 02eb9a79fe48408ea7094c218489b4f6] [instance: ab19b985-3348-4efe-b89d-7613172ad83d] Booting with volume c0f7e1ff-9236-4127-b175-9831068bde3f at /dev/vda 2024-01-24 18:11:39.265 1773994 INFO nova.compute.claims [req-f771fb53-b2cd-421f-8718-d49b7b81229f 901ac55362b14df2b85e70108d2483d4 522d33bee871460b97f190ebe6056951 - 02eb9a79fe48408ea7094c218489b4f6 02eb9a79fe48408ea7094c218489b4f6] [instance: ab19b985-3348-4efe-b89d-7613172ad83d] Claim successful on node solqa-lab1-server-51.nosilo.lab1.solutionsqa 2024-01-24 18:11:40.067 1773994 INFO nova.virt.libvirt.driver [req-f771fb53-b2cd-421f-8718-d49b7b81229f 901ac55362b14df2b85e70108d2483d4 522d33bee871460b97f190ebe6056951 - 02eb9a79fe48408ea7094c218489b4f6 02eb9a79fe48408ea7094c218489b4f6] [instance: ab19b985-3348-4efe-b89d-7613172ad83d] Creating image 2024-01-24 18:11:42.099 1773994 INFO nova.compute.manager [req-cde71d46-e68f-47de-942a-ee917730c9d1 - - - - -] [instance: ab19b985-3348-4efe-b89d-7613172ad83d] VM Started (Lifecycle Event) 2024-01-24 18:11:42.125 1773994 INFO nova.compute.manager [req-cde71d46-e68f-47de-942a-ee917730c9d1 - - - - -] [instance: ab19b985-3348-4efe-b89d-7613172ad83d] VM Paused (Lifecycle Event) 2024-01-24 18:11:42.226 1773994 INFO nova.compute.manager [req-cde71d46-e68f-47de-942a-ee917730c9d1 - - - - -] [instance: ab19b985-3348-4efe-b89d-7613172ad83d] During sync_power_state the instance has a pending task (spawning). Skip. 2024-01-24 18:11:43.200 1773994 INFO nova.compute.manager [req-cde71d46-e68f-47de-942a-ee917730c9d1 - - - - -] [instance: ab19b985-3348-4efe-b89d-7613172ad83d] VM Resumed (Lifecycle Event) 2024-01-24 18:11:43.204 1773994 INFO nova.virt.libvirt.driver [-] [instance: ab19b985-3348-4efe-b89d-7613172ad83d] Instance spawned successfully. 2024-01-24 18:11:43.233 1773994 INFO nova.compute.manager [req-cde71d46-e68f-47de-942a-ee917730c9d1 - - - - -] [instance: ab19b985-3348-4efe-b89d-7613172ad83d] During sync_power_state the instance has a pending task (spawning). Skip. 2024-01-24 18:11:45.221 1773994 WARNING nova.compute.manager [req-23135856-97b3-421f-84a5-d062056c9ec0 1a505a6a35c4490196d2d33a3a8298b5 0ff89803dacf4eb4bd58aeef137b8ff3 - bf9986706c2d408f88d1a4ee29ed1952 bf9986706c2d408f88d1a4ee29ed1952] [instance: ab19b985-3348-4efe-b89d-7613172ad83d] Received unexpected event network-vif-plugged-2a8f679d-5568-4f2f-aae8-0445c57e61f7 for instance with vm_state active and task_state None. 2024-01-24 18:12:08.474 1773994 INFO nova.compute.manager [req-13d082f2-61d6-43c9-aa5a-a59c57da3e1a 901ac55362b14df2b85e70108d2483d4 522d33bee871460b97f190ebe6056951 - 02eb9a79fe48408ea7094c218489b4f6 02eb9a79fe48408ea7094c218489b4f6] [instance: ab19b985-3348-4efe-b89d-7613172ad83d] Terminating instance 2024-01-24 18:12:09.151 1773994 INFO nova.virt.libvirt.driver [-] [instance: ab19b985-3348-4efe-b89d-7613172ad83d] Instance destroyed successfully.