QA (public) » openQA Project (public) » openQA Tests (public)

Just a small PR so we have the actual logfile for investigation: https://github.com/os-autoinst/os-autoinst-distri-openQA/pull/206 Correct uploading of autoinst-log.txt

Example of failure with the autoinst-log.txt attached: https://openqa.opensuse.org/tests/4471721

https://openqa.opensuse.org/tests/overview?distri=openqa&version=Tumbleweed&build=b10n1k%2Fos-autoinst-distri-openQA%23fix_sporadic_tests 2 failed out of 100

I set up a virtual machine and I compared the logs:

failed job logsfailed job logs

good job logsgood job logs

ybonatakis wrote in #note-15:

I set up a virtual machine and I compared the logs:

{{collapse(failed job logs)
[2024-09-16T09:38:21.788738-04:00] [debug] [pid:124359] ||| finished boot tests (runtime: 11 s)
[2024-09-16T09:38:21.793705-04:00] [debug] [pid:124339] [autotest] process exited: 0
[2024-09-16T09:38:21.794268-04:00] [debug] [pid:124339] stopping command server 124356 because test execution ended
[2024-09-16T09:38:21.794336-04:00] [debug] [pid:124339] isotovideo: informing websocket clients before stopping command server: http://127.0.0.1:20013/IUjZf4snrxneedUn/broadcast
[2024-09-16T09:38:21.821683-04:00] [debug] [pid:124339] commands process exited: 0
[2024-09-16T09:38:21.921957-04:00] [debug] [pid:124339] done with command server
[2024-09-16T09:38:21.922056-04:00] [debug] [pid:124339] stopping autotest process 124359
[2024-09-16T09:38:21.922138-04:00] [debug] [pid:124339] done with autotest process
[2024-09-16T09:38:21.922191-04:00] [debug] [pid:124339] isotovideo failed
[2024-09-16T09:38:21.923372-04:00] [debug] [pid:124339] stopping backend process 124360
[2024-09-16T09:38:21.923566-04:00] [debug] [pid:124360] backend got TERM
[2024-09-16T09:38:21.924008-04:00] [info] [pid:124360] ::: OpenQA::Qemu::Proc::save_state: Saving QEMU state to qemu_state.json
[2024-09-16T09:38:22.978555-04:00] [debug] [pid:124360] Passing remaining frames to the video encoder
[out#0/webm @ 0x555a322309c0] video:20KiB audio:0KiB subtitle:0KiB other streams:0KiB global headers:0KiB muxing overhead: 3.039424%
frame= 24 fps=2.0 q=50.0 Lsize= 20KiB time=00:00:00.95 bitrate= 174.3kbits/s speed=0.0779x

[2024-09-16T09:38:24.081336-04:00] [debug] [pid:124360] Waiting for video encoder to finalize the video
[2024-09-16T09:38:24.081465-04:00] [debug] [pid:124360] The external video encoder (pid 124362) terminated
[2024-09-16T09:38:24.081668-04:00] [debug] [pid:124360] The built-in video encoder (pid 124363) terminated
[2024-09-16T09:38:24.082421-04:00] [debug] [pid:124360] QEMU: qemu-system-x86_64: terminating on signal 15 from pid 124360 (/usr/bin/isotovideo: backend)
[2024-09-16T09:38:24.083632-04:00] [debug] [pid:124360] sending magic and exit
[2024-09-16T09:38:24.228532-04:00] [debug] [pid:124339] done with backend process
124339: EXIT 1
[2024-09-16T09:38:24.283590-04:00] [info] Isotovideo exit status: 1
}}

{{collapse(good job logs)
[2024-09-17T04:27:18.239032-04:00] [debug] [pid:10746] stopping autotest process 10782
[2024-09-17T04:27:18.242803-04:00] [debug] [pid:10746] [autotest] process exited: 0
[2024-09-17T04:27:18.346308-04:00] [debug] [pid:10746] done with autotest process
[2024-09-17T04:27:18.347247-04:00] [debug] [pid:10746] stopping command server 10775 because test execution ended
[2024-09-17T04:27:18.347427-04:00] [debug] [pid:10746] isotovideo: informing websocket clients before stopping command server: http://127.0.0.1:20013/1BzRWhMNYgs94svW/broadcast
[2024-09-17T04:27:18.499693-04:00] [debug] [pid:10746] commands process exited: 0
[2024-09-17T04:27:18.600627-04:00] [debug] [pid:10746] done with command server
[2024-09-17T04:27:18.600955-04:00] [debug] [pid:10746] isotovideo done
[2024-09-17T04:27:18.608242-04:00] [debug] [pid:10786] QEMU status is not 'shutdown', it is 'running'
[2024-09-17T04:27:18.609286-04:00] [debug] [pid:10746] backend shutdown state: 0
[2024-09-17T04:27:18.611449-04:00] [info] [pid:10786] ::: OpenQA::Qemu::Proc::save_state: Saving QEMU state to qemu_state.json
[2024-09-17T04:28:01.158750-04:00] [debug] [pid:10786] Passing remaining frames to the video encoder[out#0/webm @ 0x55a05fdbf9c0] video:12KiB audio:0KiB subtitle:0KiB other streams:0KiB global headers:0KiB muxing overhead: 6.289207%frame= 66 fps=0.9 q=50.0 Lsize= 13KiB time=00:00:02.70 bitrate= 39.0kbits/s speed=0.0362x

[2024-09-17T04:28:02.324960-04:00] [debug] [pid:10786] Waiting for video encoder to finalize the video
[2024-09-17T04:28:02.325313-04:00] [debug] [pid:10786] The built-in video encoder (pid 10791) terminated
[2024-09-17T04:28:02.325423-04:00] [debug] [pid:10786] The external video encoder (pid 10790) terminated
[2024-09-17T04:28:02.332402-04:00] [debug] [pid:10786] QEMU: qemu-system-x86_64: terminating on signal 15 from pid 10786 (/usr/bin/isotovideo: backend)
[2024-09-17T04:28:02.335732-04:00] [debug] [pid:10786] sending magic and exit
[2024-09-17T04:28:02.336304-04:00] [debug] [pid:10746] received magic close
[2024-09-17T04:28:02.343881-04:00] [debug] [pid:10746] backend process exited: 0
[2024-09-17T04:28:02.450525-04:00] [debug] [pid:10746] stopping backend process 10786
[2024-09-17T04:28:02.450650-04:00] [debug] [pid:10746] done with backend process10746: EXIT 0
[2024-09-17T04:28:02.702003-04:00] [info] Isotovideo exit status: 0
[2024-09-17T04:27:18.239032-04:00] [debug] [pid:10746] stopping autotest process 10782
10746: EXIT 0
[2024-09-17T04:28:02.702003-04:00] [info] Isotovideo exit status: 0
[2024-09-17T04:28:02.450650-04:00] [debug] [pid:10746] done with backend process
}}

autotest process seems to start termination earlier but I am not sure. I tried to dig into the code but there are different places which are executing tasks at that point and I cant understand whats the sequence

ybonatakis runs tests locally to reproduce

I tried to reproduce like so, using https://openqa.opensuse.org/tests/latest?arch=x86_64&distri=openqa&flavor=dev&machine=64bit-2G&test=openqa_from_bootstrap&version=Tumbleweed#downloads for the image:

wget https://openqa.opensuse.org/tests/4493151/asset/hdd/opensuse-Tumbleweed-x86_64-20240917-minimalx@64bit.qcow2
isotovideo -e CASEDIR=https://github.com/os-autoinst/os-autoinst-distri-openQA/ NEEDLES_DIR=https://github.com/os-autoinst/os-autoinst-needles-openQA QEMU_NO_KVM=1 QEMU=x86_64 HDD_1=opensuse-Tumbleweed-x86_64-20240917-minimalx@64bit.qcow2
[...]
[2024-09-19T16:46:25.500999+02:00] [info] [pid:171843] ::: basetest::runtest: # Test died: no candidate needle with tag(s) 'openqa-desktop' matched
[...]
[2024-09-19T16:46:59.397550+02:00] [debug] [pid:171843] post_fail_hook failed: command 'ip a del 10.0.2.2/15 dev br1' timed out at ~/bau/oa/repos/distri-openQA/os-autoinst-distri-openQA/lib/openQAcoretest.pm line 10.

After removing the failing script_run from lib/openQAcoretest.pm I get this:

[2024-09-19T17:16:22.339125+02:00] [debug] [pid:249716] post_fail_hook failed: command 'ps -ef | tee running_processes.txt' timed out at ~/bau/oa/repos/distri-openQA/os-autoinst-distri-openQA/lib/utils.pm line 11.

That's presumably the upload to a non-existing web UI timing out. Is there any way to get to the logs produced by post_fail_hook?

This is an autogenerated message for openQA integration by the openqa_review script:

This bug is still referenced in a failing openQA test: openqa_install+publish
https://openqa.opensuse.org/tests/4634462#step/tests/1

To prevent further reminder comments one of the following options should be followed:

1. The test scenario is fixed by applying the bug fix to the tested product or the test is adjusted
2. The openQA job group is moved to "Released" or "EOL" (End-of-Life)
3. The bugref in the openQA scenario is removed or replaced, e.g. label:wontfix:boo1234

Expect the next reminder at the earliest in 28 days if nothing changes in this ticket.

So to be sure, I used isotovideo directly as mentioned earlier. The issue can be reproduced usually within twenty runs:

[2024-11-11T11:57:46.375712-05:00] [debug] [pid:124619] Waiting for video encoder to finalize the video
[2024-11-11T11:57:46.376082-05:00] [debug] [pid:124619] The external video encoder (pid 124621) terminated
[2024-11-11T11:57:46.376251-05:00] [debug] [pid:124619] The built-in video encoder (pid 124622) terminated
[2024-11-11T11:57:46.378280-05:00] [debug] [pid:124619] QEMU: qemu-system-x86_64: terminating on signal 15 from pid 124619 (/usr/bin/isotovideo: backend)
[2024-11-11T11:57:46.380877-05:00] [debug] [pid:124619] sending magic and exit
[2024-11-11T11:57:46.545817-05:00] [debug] [pid:124599] done with backend process
124599: EXIT 1
[2024-11-11T11:57:46.613745-05:00] [info] Isotovideo exit status: 1
[2024-11-11T11:57:46.722113-05:00] [info] +++ worker notes +++
[2024-11-11T11:57:46.722836-05:00] [info] End time: 2024-11-11 16:57:46
[2024-11-11T11:57:46.722981-05:00] [info] Result: died
[2024-11-11T11:57:46.750790-05:00] [info] Uploading video.webm
[2024-11-11T11:57:46.803408-05:00] [info] Uploading autoinst-log.txt

after that I did try to just execute the inner test with isotovideo to see if that is stable, executed 500 tests without any issue.

As a next step I would like to create a minimal working example for the bug to reproduce. From the latest failure, one can see that the test is successfully executed inside osautoinst/test_running but a test module later, it is already showing as incomplete a few modules later and even long before the shutdown, so it shouldn't be related to shutting down the openQA inside the test (as I initially thought).

Minor improvement https://github.com/os-autoinst/os-autoinst-distri-openQA/pull/216 for the published HDD to be reusable right away by our current tests.

So far I am able to reproduce the issue within 20 tests; when using the image generated by a successful run and spawning the same test (without the openQA installation part of course), the issue is not reproducible anymore (or it needs a way more runs, which I am trying at this moment). Anyway, my observation leads to a hypothesis that the issue is connected either to a very first test or that the machine needs a reboot before first use. I will see, if the issue goes away if I introduce reboot just after the installation.

What I don't understand is why stop_commands is apparently called before stop_autotest:

[2024-11-11T11:57:25.417909-05:00] [debug] [pid:124599] stopping command server 124615 because test execution ended     <----- shouldn't be called that early
[2024-11-11T11:57:25.418077-05:00] [debug] [pid:124599] isotovideo: informing websocket clients before stopping command server: http://127.0.0.1:20013/ZaiH7djgcxpbtus1/broadcast
[2024-11-11T11:57:25.441790-05:00] [debug] [pid:124599] commands process exited: 0
[2024-11-11T11:57:25.542427-05:00] [debug] [pid:124599] done with command server
[2024-11-11T11:57:25.542619-05:00] [debug] [pid:124599] stopping autotest process 124618
[2024-11-11T11:57:25.542794-05:00] [debug] [pid:124599] done with autotest process

I ran the inner test locally, shortened the test module to return immediately, added some sleep in the tests_done handling, but the stop_commands was always executed after that.

I started a bunch of tests with DEBUG_JSON_RPC=1 in the inner test and got one failure:

https://openqa.opensuse.org/tests/4688380
We can see that tests_done is sent via myjsorpc:
https://openqa.opensuse.org/tests/4688380/logfile?filename=tests-autoinst-log.txt#line-211
But it is also read 4 lines below. Actually I cannot see that the token XcpFXfMJ is ever read.
But even before that apparently stop_command_processing is called. That would happen when the response is not defined.

[2024-12-06T13:57:41.592234-05:00] [debug] [pid:8923] send_json(5) JSON={"cmd":"tests_done","completed":1,"died":0,"json_cmd_token":"XcpFXfMJ"}
[2024-12-06T13:57:41.595469-05:00] [debug] [pid:8904] [autotest] process exited: 0
[2024-12-06T13:57:41.595601-05:00] [debug] [pid:8904] send_json(3) JSON={"json_cmd_token":"WqAryXaW","stop_processing_isotovideo_com":1}
[2024-12-06T13:57:41.595677-05:00] [debug] [pid:8920] read_json(4)
[2024-12-06T13:57:41.595757-05:00] [debug] [pid:8920] read_json(4) json_cmd_token=WqAryXaW
[2024-12-06T13:57:41.595883-05:00] [debug] [pid:8904] stopping command server 8920 because test execution ended

I haven't reproduced it locally yet.
I think it could be useful to get a fresh VM and do the installation like in one of the openqa-in-openqa tests and try to reproduce it there.
Also I could try pausing the test and starting the inner test via vncviewer repeatedly.

https://github.com/os-autoinst/os-autoinst-distri-openQA/pull/217 Upload list of jobs for easier debugging