Result of the verification runs: FAIL¶
Findings¶
Based on this VR (S390-zVM):
Screenshots look quite the same like on S390-KVM here, but shutdown test gets canceled
Looking at autoinst-log.txt (failed test):
[2022-05-13T05:03:57.867209+02:00] [debug] assert_shutdown_with_soft_timeout(): soft_timeout=60
[2022-05-13T05:03:57.867382+02:00] [debug] tests/shutdown/shutdown.pm:16 called power_action_utils::power_action -> lib/power_action_utils.pm:324 called power_action_utils::assert_shutdown_with_soft_timeout -> lib/power_action_utils.pm:413 called testapi::check_shutdown
[2022-05-13T05:03:57.867513+02:00] [debug] <<< testapi::check_shutdown(timeout=60)
[2022-05-13T05:03:57.868149+02:00] [debug] Backend does not implement is_shutdown - just sleeping
[2022-05-13T05:04:01.755365+02:00] [debug] considering VNC stalled, no update for 4.00 seconds
[2022-05-13T05:04:01.759817+02:00] [info] ::: backend::baseclass::die_handler: Backend process died, backend errors are reported below in the following lines:
unexpected end of data at /usr/lib/os-autoinst/consoles/VNC.pm line 179.
[2022-05-13T05:04:01.760201+02:00] [debug] Passing remaining frames to the video encoder
[2022-05-13T05:04:01.790305+02:00] [debug] Waiting for video encoder to finalize the video
[2022-05-13T05:04:01.790448+02:00] [debug] The built-in video encoder (pid 1516) terminated
[2022-05-13T05:04:01.790680+02:00] [debug] sending magic and exit
[2022-05-13T05:04:01.791367+02:00] [debug] received magic close
Use of uninitialized value $fname in concatenation (.) or string at /usr/lib/os-autoinst/log.pm line 57.
log::fctwarn("THERE IS NOTHING TO READ 16 5 4") called at /usr/bin/isotovideo line 344
[2022-05-13T05:04:01.792490+02:00] [warn] !!! : THERE IS NOTHING TO READ 16 5 4
[2022-05-13T05:04:01.792691+02:00] [debug] stopping command server 1370 because test execution ended
VNC is complaining that it gets an unexpected end of data, but for me that looks quite normal, when the host is down, there is no VNC server running, so where should the data come from.
The autoinst-log.txt from the S390-KVM test looks quite different:
[2022-05-03T07:44:26.806619+02:00] [debug] assert_shutdown_with_soft_timeout(): soft_timeout=60
[2022-05-03T07:44:26.806865+02:00] [debug] tests/shutdown/shutdown.pm:16 called power_action_utils::power_action -> lib/power_action_utils.pm:331 called power_action_utils::assert_shutdown_with_soft_timeout -> lib/power_action_utils.pm:420 called testapi::check_shutdown
[2022-05-03T07:44:26.806990+02:00] [debug] <<< testapi::check_shutdown(timeout=60)
[2022-05-03T07:44:26.807782+02:00] [debug] <<< backend::baseclass::run_ssh_cmd(cmd="! virsh dominfo openQA-SUT-6 | grep -w 'shut off'", wantarray=0, keep_open=1)
[2022-05-03T07:44:26.808002+02:00] [debug] <<< backend::baseclass::run_ssh(cmd="! virsh dominfo openQA-SUT-6 | grep -w 'shut off'", keep_open=1, wantarray=0)
[2022-05-03T07:44:26.808131+02:00] [debug] <<< backend::baseclass::new_ssh_connection(keep_open=1, blocking=1, wantarray=0)
[2022-05-03T07:44:26.855827+02:00] [debug] Use existing SSH connection (key:hostname=s390zp18.suse.de,username=root,port=22)
[2022-05-03T07:44:26.898990+02:00] [debug] [run_ssh_cmd(! virsh dominfo openQA-SUT-6 | grep -w 'shut off')] exit-code: 0
[2022-05-03T07:44:27.900433+02:00] [debug] <<< backend::baseclass::run_ssh_cmd(cmd="! virsh dominfo openQA-SUT-6 | grep -w 'shut off'", wantarray=0, keep_open=1)
[2022-05-03T07:44:27.900626+02:00] [debug] <<< backend::baseclass::run_ssh(cmd="! virsh dominfo openQA-SUT-6 | grep -w 'shut off'", wantarray=0, keep_open=1)
[2022-05-03T07:44:27.900757+02:00] [debug] <<< backend::baseclass::new_ssh_connection(blocking=1, keep_open=1, wantarray=0)
[2022-05-03T07:44:27.945994+02:00] [debug] Use existing SSH connection (key:hostname=s390zp18.suse.de,username=root,port=22)
Interesting point is that here the backend starts running ssh commands after check_shutdown.