QA » openQA Project

Note that I re-triggered the build and it passed this time so maybe we don't need to exclude it for now, but it's still racy of course I meant to. I think after my toggling work-around for #108530#note-23 it's actually being rebuilt.

I prepared a branch to exclude the test because it looks to me like increasing the timeout won't help, considering it fails before there's any meaningful output: https://github.com/os-autoinst/os-autoinst/pull/2139

cdywan wrote:

After discussing it in the daily I'm going to try and propose a follow-up branch to exclude the test only on ppc64le e.g. using something like %ifnarch ppc64le.

https://github.com/os-autoinst/os-autoinst/pull/2142

I found various examples of %ifarch ppc64le in the wild so that's what I'm using now.

Now I saw it on x86_64: https://build.opensuse.org/package/live_build_log/devel:openQA/os-autoinst/openSUSE_Tumbleweed/x86_64

[  572s] 3: Bailout called.  Further testing stopped:  test './t/27-consoles-vmware.t' exceeds runtime limit of '200' seconds
[  572s] 3: [17:59:59] ./t/27-consoles-vmware.t ................... 
[  572s] 3: # Subtest: test configuration with fake URL
[  572s] 3:     ok 1 - noop if URL not set
[  572s] 3:     ok 2 - log message present without secrets
[  572s] 3:     ok 3 - VMWare "console" returned if URL is set
[  572s] 3:     ok 4 - hostname saved as original hostname
[  572s] 3:     ok 5 - original hostname set to hostname
[  572s] 3:     ok 6 - hostname assigned
[  572s] 3:     ok 7 - hostname set to localhost
[  572s] 3:     ok 8 - description assigned
[  572s] 3:     ok 9 - description set accordingly
[  572s] 3:     ok 10 - dewebsockify called with expected args
[  572s] 3:     ok 11 - hostname set
[  572s] 3:     ok 12 - no VM-ID set (as our URL did not include one)
[  572s] 3:     ok 13 - username set
[  572s] 3:     ok 14 - password set (with URL-encoded character)
[  572s] 3:     ok 15 - protocol configured from URL
[  572s] 3:     ok 16 - host configured from URL
[  572s] 3:     ok 17 - specific VM-ID configured from URL
[  572s] 3:     1..17
[  572s] 3: ok 1 - test configuration with fake URL
[  572s] 3: # Subtest: request WebSockets URL
[  572s] 3:     ok 1 - auth error handled
[  572s] 3:     ok 2 - ws request error handled
[  572s] 3:     ok 3 - no ws URL handled
[  572s] 3:     ok 4 - no cookie handled
[  572s] 3:     ok 5 - URL found
[  572s] 3:     ok 6 - cookie returned
[  572s] 3:     1..6
[  572s] 3: ok 2 - request WebSockets URL
[  572s] 3: # Subtest: deducing VNC over WebSockets URL from vars
[  572s] 3:     ok 1 - no URL if VMWARE_VNC_OVER_WS not set
[  572s] 3:     ok 2 - no URL if VIRSH_GUEST not matching
[  572s] 3:     ok 3 - error if vars specified inconsistently
[  572s] 3:     ok 4 - error if password missing
[  572s] 3:     ok 5 - URL deduced from vars
[  572s] 3:     ok 6 - original hostname used to check if VIRSH_GUEST matching
[  572s] 3:     1..6
[  572s] 3: ok 3 - deducing VNC over WebSockets URL from vars
[  572s] 3: # Subtest: turning WebSocket into normal socket via dewebsockify
[  572s] 3:     ok 1 - could start test WebSocket server
[  572s] 3:     ok 2 - dewebsockify PID tracked
[  572s] 3:     # unable to connect to dewebsockify on port 49607: Connection refused (will try again 1999 times)
[  572s] 3:     # unable to connect to dewebsockify on port 49607: Connection refused (will try again 1998 times)
[  572s] 3:     # unable to connect to dewebsockify on port 49607: Connection refused (will try again 1997 times)
[  572s] 3:     # unable to connect to dewebsockify on port 49607: Connection refused (will try again 1996 times)
[  572s] 3:     # unable to connect to dewebsockify on port 49607: Connection refused (will try again 1995 times)
[  572s] 3:     # unable to connect to dewebsockify on port 49607: Connection refused (will try again 1994 times)
[  572s] 3:     # unable to connect to dewebsockify on port 49607: Connection refused (will try again 1993 times)
[  572s] 3:     # unable to connect to dewebsockify on port 49607: Connection refused (will try again 1992 times)
[  572s] 3:     # unable to connect to dewebsockify on port 49607: Connection refused (will try again 1991 times)
[  572s] 3:     # unable to connect to dewebsockify on port 49607: Connection refused (will try again 1990 times)
[  572s] 3:     ok 3 - expected data received via raw socket
[  572s] 3:     ok 4 - expected data received via WebSocket
[  572s] 3:     # unable to connect to dewebsockify on port 49607: Connection refused (will try again 1989 times)
[  572s] 3:     # unable to connect to dewebsockify on port 49607: Connection refused (will try again 1988 times)
[  572s] 3:     # unable to connect to dewebsockify on port 49607: Connection refused (will try again 1987 times)
[  572s] 3:     # unable to connect to dewebsockify on port 49607: Connection refused (will try again 1986 times)
[  572s] 3:     # unable to connect to dewebsockify on port 49607: Connection refused (will try again 1985 times)
[  572s] 3:     # unable to connect to dewebsockify on port 49607: Connection refused (will try again 1984 times)
[  572s] 3:     # unable to connect to dewebsockify on port 49607: Connection refused (will try again 1983 times)
[  572s] 3:     # unable to connect to dewebsockify on port 49607: Connection refused (will try again 1982 times)
[  572s] 3:     # unable to connect to dewebsockify on port 49607: Connection refused (will try again 1981 times)
[  572s] 3:     # unable to connect to dewebsockify on port 49607: Connection refused (will try again 1980 times)
[  572s] 3:     ok 5 - error logged
[  572s] 3:     # unable to connect to dewebsockify on port 49607: Connection refused (will try again 1979 times)
[  572s] 3:     # unable to connect to dewebsockify on port 49607: Connection refused (will try again 1978 times)
[  572s] 3:     # unable to connect to dewebsockify on port 49607: Connection refused (will try again 1977 times)
[  572s] 3:     # unable to connect to dewebsockify on port 49607: Connection refused (will try again 1976 times)
[  572s] 3:     # unable to connect to dewebsockify on port 49607: Connection refused (will try again 1975 times)
[  572s] 3:     # unable to connect to dewebsockify on port 49607: Connection refused (will try again 1974 times)
[  572s] 3:     # unable to connect to dewebsockify on port 49607: Connection refused (will try again 1973 times)
[  572s] 3:     # unable to connect to dewebsockify on port 49607: Connection refused (will try again 1972 times)
[  572s] 3: Dubious, test returned 255 (wstat 65280, 0xff00)
[  572s] 3: All 4 subtests passed 
[  572s] 3: [17:59:59]
[  572s] 3: 
[  572s] 3: Test Summary Report
[  572s] 3: -------------------
[  572s] 3: ./t/27-consoles-vmware.t                 (Wstat: 65280 (exited 255) Tests: 4 Failed: 0)
[  572s] 3:   Non-zero exit status: 255
[  572s] 3:   Parse errors: No plan found in TAP output

At least it seems to execute some of the tests...

Unfortunately it happened again but I haven't saved the entire log. So I'm waiting for another occurrence and will preserve the OBS build log.

Unfortunately these logs don't contain much to go on. For now I'll just disable the test completely in OBS: https://github.com/os-autoinst/os-autoinst/pull/2162

Considering also the last logs I'm wondering whether this test is really only taking so long on OBS. It doesn't reach the time limit in a moment where it looks stuck (like a loop of always failing connection attempts, in fact it ends with a successful connection being logged and the previous subtest which are very similar have passed before). However, we already scale the timeout to be 200 seconds. Even with coverage enabled it takes locally < 5 seconds. So it seems very unlikely that it really takes that long. Unfortunately we cannot see how much time passed between the log lines because CMake just replies the output as one big junk.

When this test passes on OBS it is actually very fast as well:

…
[  158s] ok 5 - multiple attempts to launch VNC server
[  158s] # Subtest: test against real VMWare instance
[  158s]     1..0 # SKIP Set OS_AUTOINST_TEST_AGAINST_REAL_VMWARE_INSTANCE to run this test.
[  158s] ok 6 # skip Set OS_AUTOINST_TEST_AGAINST_REAL_VMWARE_INSTANCE to run this test.
[  158s] ok 7 - no (unexpected) warnings (via done_testing)
[  158s] 1..7
[  158s] ok     1619 ms ( 0.01 usr  0.00 sys +  1.39 cusr  0.15 csys =  1.55 CPU)
[  160s] [10:02:07] ./t/27-consoles-vnc.t ...................... 
…

So something must hang after the connection has been established and before waitpid is executed.

This PR which has unbuffered output enabled shows where it hangs: https://github.com/os-autoinst/os-autoinst/pull/2167

[  159s] 3: [14:02:16] ./t/27-consoles-vmware.t ................... 
[  159s] 3: # Subtest: test configuration with fake URL
[  159s] 3:     ok 1 - noop if URL not set
[  159s] 3:     ok 2 - log message present without secrets
[  159s] 3:     ok 3 - VMWare "console" returned if URL is set
[  159s] 3:     ok 4 - hostname saved as original hostname
[  159s] 3:     ok 5 - original hostname set to hostname
[  159s] 3:     ok 6 - hostname assigned
[  159s] 3:     ok 7 - hostname set to localhost
[  159s] 3:     ok 8 - description assigned
[  159s] 3:     ok 9 - description set accordingly
[  159s] 3:     ok 10 - dewebsockify called with expected args
[  159s] 3:     ok 11 - hostname set
[  159s] 3:     ok 12 - no VM-ID set (as our URL did not include one)
[  159s] 3:     ok 13 - username set
[  159s] 3:     ok 14 - password set (with URL-encoded character)
[  159s] 3:     ok 15 - protocol configured from URL
[  159s] 3:     ok 16 - host configured from URL
[  159s] 3:     ok 17 - specific VM-ID configured from URL
[  159s] 3:     1..17
[  159s] 3: ok 1 - test configuration with fake URL
[  159s] 3: # Subtest: request WebSockets URL
[  159s] 3:     ok 1 - auth error handled
[  159s] 3:     ok 2 - ws request error handled
[  159s] 3:     ok 3 - no ws URL handled
[  159s] 3:     ok 4 - no cookie handled
[  159s] 3:     ok 5 - URL found
[  159s] 3:     ok 6 - cookie returned
[  159s] 3:     1..6
[  159s] 3: ok 2 - request WebSockets URL
[  159s] 3: # Subtest: deducing VNC over WebSockets URL from vars
[  159s] 3:     ok 1 - no URL if VMWARE_VNC_OVER_WS not set
[  159s] 3:     ok 2 - no URL if VIRSH_GUEST not matching
[  159s] 3:     ok 3 - error if vars specified inconsistently
[  159s] 3:     ok 4 - error if password missing
[  159s] 3:     ok 5 - URL deduced from vars
[  159s] 3:     ok 6 - original hostname used to check if VIRSH_GUEST matching
[  159s] 3:     1..6
[  159s] 3: ok 3 - deducing VNC over WebSockets URL from vars
[  159s] 3: # Subtest: turning WebSocket into normal socket via dewebsockify
[  159s] 3:     ok 1 - could start test WebSocket server
[  159s] 3:     ok 2 - dewebsockify PID tracked: 3910
[  159s] 3:     # connecting to dewebsockify on port 46259
[  159s] 3:     # unable to connect to dewebsockify on port 46259: Connection refused (will try again 499 times)
[  159s] 3:     # connecting to dewebsockify on port 46259
[  159s] 3:     # unable to connect to dewebsockify on port 46259: Connection refused (will try again 498 times)
[  159s] 3:     # connecting to dewebsockify on port 46259
[  159s] 3:     # unable to connect to dewebsockify on port 46259: Connection refused (will try again 497 times)
[  159s] 3:     # connecting to dewebsockify on port 46259
[  159s] 3:     # unable to connect to dewebsockify on port 46259: Connection refused (will try again 496 times)
[  159s] 3:     # connecting to dewebsockify on port 46259
[  159s] 3:     # connection to dewebsockify established via port 46259
[  159s] 3:     ok 3 - expected data received via raw socket
[  159s] 3:     ok 4 - expected data received via WebSocket
[  159s] 3:     # waiting for dewebsockify process to terminate, pid: 3910
[  159s] 3:     # Subtest: handle error when WebSocket server is not reachable
[  159s] 3:         # connecting to dewebsockify on port 46259
[  159s] 3:         # unable to connect to dewebsockify on port 46259: Connection refused (will try again 499 times)
[  159s] 3:         # connecting to dewebsockify on port 46259
[  159s] 3:         # unable to connect to dewebsockify on port 46259: Connection refused (will try again 498 times)
[  159s] 3:         # connecting to dewebsockify on port 46259
[  159s] 3:         # unable to connect to dewebsockify on port 46259: Connection refused (will try again 497 times)
[  159s] 3:         # connecting to dewebsockify on port 46259
[  159s] 3:         # unable to connect to dewebsockify on port 46259: Connection refused (will try again 496 times)
[  160s] 3:         # connecting to dewebsockify on port 46259
[  160s] 3:         # connection to dewebsockify established via port 46259
[  160s] 3:         # closing connection to dewebsockify immediately
[  160s] 3:         # waiting for dewebsockify process to terminate, pid: 3911
[  160s] 3:         ok 1 - error logged
[  160s] 3:         1..1
[  160s] 3:     ok 5 - handle error when WebSocket server is not reachable
[  160s] 3:     # Subtest: handle error when HTTP server is not upgrading to WebSockets
[  160s] 3:         # connecting to dewebsockify on port 46259
[  160s] 3:         # unable to connect to dewebsockify on port 46259: Connection refused (will try again 499 times)
[  160s] 3:         # connecting to dewebsockify on port 46259
[  160s] 3:         # unable to connect to dewebsockify on port 46259: Connection refused (will try again 498 times)
[  160s] 3:         # connecting to dewebsockify on port 46259
[  160s] 3:         # unable to connect to dewebsockify on port 46259: Connection refused (will try again 497 times)
[  160s] 3:         # connecting to dewebsockify on port 46259
[  160s] 3:         # unable to connect to dewebsockify on port 46259: Connection refused (will try again 496 times)
[  160s] 3:         # connecting to dewebsockify on port 46259
[  160s] 3:         # connection to dewebsockify established via port 46259
[  358s] 3: Bailout called.  Further testing stopped:  test './t/27-consoles-vmware.t' exceeds runtime limit of '200' seconds
[  358s] 3: Bail out!  test './t/27-consoles-vmware.t' exceeds runtime limit of '200' seconds
[  358s] 3: Dubious, test returned 255 (wstat 65280, 0xff00)
[  358s] 3: All 4 subtests passed

So the test execution was very fast before and it really just hangs on the last line.

The test is expecting dewebsockify to terminate and close the connection here. Then it'll stop the event loop but that apparently never happens. So there must be something wrong with that, e.g. the callback registered via $self->tx->on(finish => sub { Mojo::IOLoop->stop }); is never invoked. (Commenting out that line will obviously reproduce the issue; the question is why it is not invoked in some cases.)

Note that https://github.com/os-autoinst/os-autoinst/pull/2167 contains a commit to simplify the VMWare test a little bit. So the line $t->ua->ioloop->start until $client_callback; is no longer a loop. I'm not sure yet whether that helped. I was under the impression it did not because TW checks are reported as failing. However, if I now look on the logs on OBS itself everything looks good. I'll retrigger the build a few times to see whether that's actually stable.

Had a quick look at the test code, and two things did jump out at me, 1) there is a lot of open/close/read... calls without exception handling, and i did not see autodie being used (so they could fail quietly), 2) there is mixed use of $t->ua->ioloop->... and Mojo::IOLoop->..., which can easily result in deadlocks if more than one event loop gets initialized accidentally, best to only use one way to reference the event loop instance.

Since the test only fails in a specific environment, it might be interesting to know if the event loop backend used is Mojo::Reactor::Poll or Mojo::Reactor::EV. There are slight differences in behavior that could make replicating a problem very hard.

cdywan wrote:

I'm also trying to get a better idea of what https://github.com/os-autoinst/os-autoinst/blob/master/t/27-consoles-vmware.t#L191 does and maybe provide some fresh input

That's the reconnect for the next attempt, delayed by 0.1 seconds.

mkittler wrote:

Note that https://github.com/os-autoinst/os-autoinst/pull/2167 contains a commit to simplify the VMWare test a little bit. So the line $t->ua->ioloop->start until $client_callback; is no longer a loop.

I just don't see how that would make a difference. In the unbuffered output we are seeing multiple unable to connect to dewebsockify on port... messages, and that would mean $client_callback is true anyway since that callback has been called multiple times.