QA » openQA Project

https://openqa.opensuse.org/tests/2157847#step/shutdown/2

Notes from the meeting:

1. The mentioned job (https://openqa.opensuse.org/tests/2157847#step/shutdown/2) fails likely because it has to switch from the graphical environment to the text console which can take a while. There's no good synchronization in the test (only wait_screen_change) so it isn't completely surprising that the machine might not be ready. However, our tests (the openQA fullstack test) does not have to switch consoles. Hence, it is likely a different issue.
2. We could try system_powerdown instead of typing poweroff. This would also help us getting fullstack test coverage for that feature.
3. Note that 2. would potentially still mask a problem in the command processing when the developer mode is used to pause/resume tests. So it might still make sense to follow my suggestions from the ticket description to have a look at it.
4. One could try to reproduce the issue within os-autoinst's fullstack test (by setting the test variable INTEGRATION_TESTS to avoid being blocked by #104971).

mkittler wrote:

Notes from the meeting:

1. The mentioned job (https://openqa.opensuse.org/tests/2157847#step/shutdown/2) fails likely because it has to switch from the graphical environment to the text console which can take a while. There's no good synchronization in the test (only wait_screen_change) so it isn't completely surprising that the machine might not be ready. However, our tests (the openQA fullstack test) does not have to switch consoles. Hence, it is likely a different issue.
2. We could try system_powerdown instead of typing poweroff. This would also help us getting fullstack test coverage for that feature.
3. Note that 2. would potentially still mask a problem in the command processing when the developer mode is used to pause/resume tests. So it might still make sense to follow my suggestions from the ticket description to have a look at it.

I tried with a patch

--- a/t/data/tests/tests/shutdown.pm
+++ b/t/data/tests/tests/shutdown.pm
@@ -5,8 +5,7 @@ use Mojo::Base 'basetest', -signatures;
 use testapi;

 sub run {
-    type_string "sudo su\n";
-    type_string "poweroff\n";
+    power 'off';
     assert_shutdown(get_var('INTEGRATION_TESTS') ? 90 : undef);
 }

but this made the full stack test fail with

# [2022-01-26T14:06:27.097610+01:00] [debug] ||| starting shutdown tests/shutdown.pm
# [2022-01-26T14:06:27.099532+01:00] [debug] tests/shutdown.pm:8 called testapi::power
# [2022-01-26T14:06:27.099805+01:00] [debug] <<< testapi::power(action="off")
# [2022-01-26T14:06:27.101367+01:00] [debug] EVENT {"data":{"path":"\/machine\/peripheral-anon\/device[2]\/virtio-backend"},"event":"NIC_RX_FILTER_CHANGED","timestamp":{"microseconds":297928,"seconds":1643202242}}
# [2022-01-26T14:06:27.102545+01:00] [debug] tests/shutdown.pm:9 called testapi::assert_shutdown
# [2022-01-26T14:06:27.102821+01:00] [debug] <<< testapi::check_shutdown(timeout=60)
# [2022-01-26T14:06:27.104357+01:00] [debug] EVENT {"data":{"guest":false,"reason":"host-qmp-quit"},"event":"SHUTDOWN","timestamp":{"microseconds":101650,"seconds":1643202387}}
# dmesg: read kernel buffer failed: Operation not permitted
# [2022-01-26T14:06:27.297549+01:00] [info] ::: OpenQA::Qemu::Proc::save_state: Saving QEMU state to qemu_state.json
# [2022-01-26T14:06:27.299926+01:00] [debug] sending magic and exit
# Unexpected end of data 0
# [2022-01-26T14:06:27.311086+01:00] [debug] backend process exited: 0
# [2022-01-26T14:06:27.311343+01:00] [info] ::: backend::driver::__ANON__: Driver backend collected unknown process with pid 11622 and exit status: 1
# [2022-01-26T14:06:27.331434+01:00] [debug] stopping command server 11591 because test execution ended
# [2022-01-26T14:06:27.331546+01:00] [debug] isotovideo: informing websocket clients before stopping command server: http://127.0.0.1:15223/xyHXbClMTX/broadcast
# [2022-01-26T14:06:27.917100+01:00] [debug] commands process exited: 0
# [2022-01-26T14:06:28.018790+01:00] [debug] done with command server
# Use of uninitialized value $serial in split at /home/okurz/local/os-autoinst/os-autoinst/t/../basetest.pm line 705.
# [2022-01-26T14:06:28.019081+01:00] [debug] stopping autotest process 11594
# [2022-01-26T14:06:28.019540+01:00] [debug] autotest received signal TERM, saving results of current test before exiting
# [2022-01-26T14:06:28.029389+01:00] [debug] [autotest] process exited: 1
# [2022-01-26T14:06:28.130022+01:00] [debug] done with autotest process
# [2022-01-26T14:06:28.130247+01:00] [debug] isotovideo failed
# [2022-01-26T14:06:28.131252+01:00] [debug] stopping backend process 11608
# [2022-01-26T14:06:28.131403+01:00] [debug] done with backend process
# 11586: EXIT 1
# '
#     doesn't match '(?^u:\d*: EXIT 0)'

#   Failed test 'Result in testresults/result-shutdown.json is ok'
#   at t/99-full-stack.t line 68.
#          got: 'canceled'
#     expected: 'ok'
# Looks like you failed 2 tests of 25.
t/99-full-stack.t .. Dubious, test returned 2 (wstat 512, 0x200)
Failed 2/25 subtests 

Test Summary Report
-------------------
t/99-full-stack.t (Wstat: 512 Tests: 25 Failed: 2)
  Failed tests:  1, 19
  Non-zero exit status: 2
Files=1, Tests=25, 155 wallclock secs ( 0.08 usr  0.02 sys + 42.57 cusr  4.93 csys = 47.60 CPU)
Result: FAIL

I don't understand right now what this means.

1. One could try to reproduce the issue within os-autoinst's fullstack test (by setting the test variable INTEGRATION_TESTS to avoid being blocked by #104971).

I could so far not reproduce the issue with cd ~/local/os-autoinst/os-autoinst/t/data/tests && runs=100 count_fail_ratio isotovideo -d INTEGRATION_TESTS=1 CASEDIR=.) after 40 runs.

power 'off' is invoking QEMU's quit command and thus causing QEMU to terminate completely. Therefore the further queries for the VMs state aren't working anymore. Considering how the QEMU backend is implemented I suppose power 'off' is not generally useful. I tried power 'acpi' instead which is using system_powerdown. Annoyingly the Tinycore system doesn't react to it at all.

I conducted over 50 runs in https://github.com/os-autoinst/openQA/pull/4496 (where I forced the new os-autoinst version) and couldn't reproduce the issue anymore. I found one occurrence of another failure (see epic comment). I'll consider the ticket resolved when the new os-autoinst version is updated in openQA's CI.

Seems like we have regressions on other backends though, is the VNC implementation used for IPMI backend as well?

By the way, the regression has nothing to do with changes I made for this ticket (https://github.com/os-autoinst/os-autoinst/pull/1945) so I'm removing the link.