QA » openQA Project

Actually, the output stated the failures:

{"blocked_by_id":null,"id":13603796,"result":"parallel_failed","state":"done"}
{"blocked_by_id":null,"id":13603797,"result":"failed","state":"done"}

So this should be probably more about the test failure: https://openqa.suse.de/tests/13603797

There is a lot of log messages mentioning "waiting" which is not shown to be successful or unsuccessful.

That's wrong. The log mentioned in the ticket description shows failed and parallel_failed:

Job state of job ID 13603796: running, waiting …
{"blocked_by_id":null,"id":13603796,"result":"parallel_failed","state":"done"}
{"blocked_by_id":null,"id":13603797,"result":"failed","state":"done"}
+ rm -f /tmp/tmp.wT5SJe6WBi
Cleaning up project directory and file based variables 00:01
ERROR: Job failed: exit code 1

This test just failed due to the problem in setup_multimachine that I've already fixed in #156067.

There were still three failures earlier today (after my fixed for #156067 had been merged). I'll have a look into them.

Passing job:

[2024-02-27T12:14:40.544405+01:00] [debug] [pid:118334] >>> testapi::wait_serial: (?^u:mvtMU-\d+-): ok
[2024-02-27T12:14:40.544500+01:00] [debug] [pid:118334] barrier wait 'MM_SETUP_DONE'
[2024-02-27T12:14:40.544595+01:00] [debug] [pid:118334] tests/network/setup_multimachine.pm:56 called lockapi::barrier_wait
[2024-02-27T12:14:40.544688+01:00] [debug] [pid:118334] <<< testapi::record_info(title="Paused", output="Wait for MM_SETUP_DONE (on parent job)", result="ok")
[2024-02-27T12:14:40.574018+01:00] [debug] [pid:118334] barrier 'MM_SETUP_DONE' not released, sleeping 5 seconds
[2024-02-27T12:14:45.593869+01:00] [debug] [pid:118334] tests/network/setup_multimachine.pm:56 called lockapi::barrier_wait
[2024-02-27T12:14:45.594169+01:00] [debug] [pid:118334] <<< testapi::record_info(title="Paused 0m5s", output="Wait for MM_SETUP_DONE (on parent job)", result="ok")
[2024-02-27T12:14:45.594608+01:00] [debug] [pid:118334] barrier wait 'MM_SETUP_PING_CHECK_DONE'
[2024-02-27T12:14:45.594777+01:00] [debug] [pid:118334] tests/network/setup_multimachine.pm:60 called lockapi::barrier_wait
[2024-02-27T12:14:45.594967+01:00] [debug] [pid:118334] <<< testapi::record_info(title="Paused", output="Wait for MM_SETUP_PING_CHECK_DONE (on parent job)", result="ok")

Failing job:

[2024-02-27T12:14:45.527797+01:00] [debug] [pid:67399] >>> testapi::wait_serial: (?^u:xn1dA-\d+-): ok
[2024-02-27T12:14:45.527866+01:00] [debug] [pid:67399] barrier wait 'MM_SETUP_PING_CHECK_DONE'
[2024-02-27T12:14:45.527933+01:00] [debug] [pid:67399] tests/network/setup_multimachine.pm:60 called lockapi::barrier_wait
[2024-02-27T12:14:45.528007+01:00] [debug] [pid:67399] <<< testapi::record_info(title="Paused", output="Wait for MM_SETUP_PING_CHECK_DONE (on parent job)", result="ok")
[2024-02-27T12:14:45.546329+01:00] [debug] [pid:67399] barrier 'MM_SETUP_PING_CHECK_DONE' not released, sleeping 5 seconds
[2024-02-27T12:14:50.565092+01:00] [debug] [pid:67399] tests/network/setup_multimachine.pm:60 called lockapi::barrier_wait
[2024-02-27T12:14:50.565280+01:00] [debug] [pid:67399] <<< bmwqemu::mydie(cause_of_death="acquiring barrier 'MM_SETUP_PING_CHECK_DONE': lock owner already finished")
[2024-02-27T12:14:50.626107+01:00] [info] [pid:67399] ::: basetest::runtest: # Test died: mydie at /usr/lib/os-autoinst/bmwqemu.pm line 266.
    bmwqemu::mydie("acquiring barrier 'MM_SETUP_PING_CHECK_DONE': lock owner alre"...) called at /usr/lib/os-autoinst/lockapi.pm line 36
    lockapi::_try_lock("barrier", "MM_SETUP_PING_CHECK_DONE", HASH(0x55f07c0a6990)) called at /usr/lib/os-autoinst/lockapi.pm line 119
    lockapi::_wait_action("MM_SETUP_PING_CHECK_DONE", undef, 0) called at /usr/lib/os-autoinst/lockapi.pm line 140
    lockapi::barrier_wait("MM_SETUP_PING_CHECK_DONE") called at sle/tests/network/setup_multimachine.pm line 60

So the following happened:

1. The client reached the barrier first (14:45.546329).
2. It then slept 5 seconds to wait for the server.
3. Meanwhile, the server reached the barrier (14:45.594608). Because the client had reached the barrier before it could just continue and finish. There's no wait_for_children in the test code that would prevent it from finishing.
4. Then the client checked the barrier again (after the 5 seconds of sleeping) and ran into the error lock owner already finished which is expected considering the previous point.

I think that the lock API behaves that way is very problematic. I suppose we usually workaround that by adding a wait_for_children at the end of the parent's test code. However, I'll have a look whether we can improve the openQA so this is not necessary.

EDIT: Improving the API would be possible but of course change the semantics (and thus basically break compatibility). So I went with adding wait_for_children which is also what our documentation already suggests: https://github.com/os-autoinst/os-autoinst-distri-opensuse/pull/18754

https://github.com/os-autoinst/os-autoinst-distri-opensuse/pull/18754 merged as well

PR for adding a retry: https://gitlab.suse.de/openqa/scripts-ci/-/merge_requests/4

https://gitlab.suse.de/openqa/scripts-ci/-/merge_requests/4 merged

https://github.com/os-autoinst/os-autoinst-distri-opensuse/pull/18754 caused problems, see https://github.com/os-autoinst/os-autoinst-distri-opensuse/pull/18754#issuecomment-1968256104 , reverted with https://github.com/os-autoinst/os-autoinst-distri-opensuse/pull/18757 (merged)

I created https://github.com/os-autoinst/os-autoinst-distri-opensuse/pull/18758 and https://github.com/os-autoinst/os-autoinst-distri-opensuse/pull/18759 to bring back my changes after they had to be reverted.

Everything is merged now again. I'll keep having a look at https://openqa.suse.de/tests/latest?arch=x86_64&distri=sle&flavor=Server-DVD-Updates&machine=64bit&test=ping_client&version=15-SP5 and https://openqa.opensuse.org/tests/latest?arch=x86_64&distri=opensuse&flavor=DVD&machine=64bit&test=ping_client&version=Tumbleweed to see whether the change is effective.