I'm getting the feeling that the error logging of `ssh-setup/nova` is working inconsistently. Consider the following two log excerpts from one of the autopkgtest-cloud-worker journals:
autopkgtest [22:23:29]: test launch-test: preparing testbed
Waiting...
Creating nova instance adt-lunar-s390x-libomxmad-20230104-220149-juju-4d1272-prod-proposed-migration-9 f
rom image adt/ubuntu-lunar-s390x-server-20230103.img (UUID 2a986d1c-2fa0-4a0e-b9bc-2915b9deda73)...
Waiting...
Creating nova instance adt-lunar-s390x-libomxmad-20230104-220149-juju-4d1272-prod-proposed-migration-9 f
rom image adt/ubuntu-lunar-s390x-server-20230103.img (UUID 2a986d1c-2fa0-4a0e-b9bc-2915b9deda73)...
Timed out waiting for ssh. Aborting! Console log:
------- nova console-log 8f057152-58df-4517-984b-4e8621df8424 (adt-lunar-s390x-libomxmad-20230104-220149-juju-4d1272-prod-proposed-migration-9) ------
Ubuntu Lunar Lobster (development branch) auto-syncubuntu-lunar-daily-s390x-server-20221227-disk1 sclp_line0
auto-syncubuntu-lunar-daily-s390x-server-20221227-disk1 login:
---------------------------------------------------
------- nova show 8f057152-58df-4517-984b-4e8621df8424 (adt-lunar-s390x-libomxmad-20230104-220149-juju-4d1272-prod-proposed-migration-9) ------
In the above excerpt we can see "Timed out waiting for ssh" and then the `nova show` and `nova console-log`. However, here we have very little information about what went wrong:
autopkgtest [22:51:16]: test clone-reprepro: preparing testbed
Waiting...
Creating nova instance adt-jammy-s390x-dgit-20230104-215159-juju-4d1272-prod-proposed-migration-9 from image adt/ubuntu-jammy-s390x-server-20230103.img (UUID 0a7a472d-9a85-43af-ab6b-26b50466bd6e)...
Waiting...
Creating nova instance adt-jammy-s390x-dgit-20230104-215159-juju-4d1272-prod-proposed-migration-9 from image adt/ubuntu-jammy-s390x-server-20230103.img (UUID 0a7a472d-9a85-43af-ab6b-26b50466bd6e)...
ERROR (CommandError): Unable to delete the specified server(s).
Unexpected error:
Traceback (most recent call last):
File "/home/ubuntu/autopkgtest/lib/VirtSubproc.py", line 740, in mainloop
command()
File "/home/ubuntu/autopkgtest/lib/VirtSubproc.py", line 669, in command
r = f(c, ce)
File "/home/ubuntu/autopkgtest/lib/VirtSubproc.py", line 302, in cmd_revert
caller.hook_revert()
File "/home/ubuntu/autopkgtest/virt/autopkgtest-virt-ssh", line 444, in hook_revert
host_setup('revert')
File "/home/ubuntu/autopkgtest/virt/autopkgtest-virt-ssh", line 263, in host_setup
execute_setup_script(command)
File "/home/ubuntu/autopkgtest/virt/autopkgtest-virt-ssh", line 202, in execute_setup_script
(status, out, err) = VirtSubproc.execute_timeout(
File "/home/ubuntu/autopkgtest/lib/VirtSubproc.py", line 144, in execute_timeout
(out, err) = sp.communicate(instr)
File "/usr/lib/python3.8/subprocess.py", line 1028, in communicate
stdout, stderr = self._communicate(input, endtime, timeout)
File "/usr/lib/python3.8/subprocess.py", line 1868, in _communicate
ready = selector.select(timeout)
File "/usr/lib/python3.8/selectors.py", line 415, in select
fd_event_list = self._selector.poll(timeout)
File "/home/ubuntu/autopkgtest/lib/VirtSubproc.py", line 64, in alarm_handler
raise Timeout()
VirtSubproc.Timeout
autopkgtest [23:23:51]: ERROR: testbed failure: cannot send to testbed [Errno 32] Broken pipe
I guess it is also possible there is another failure case we are not catching.