QA (public) » openQA Project (public)

I would suggest that we can create a needle that would try to match the current screen: https://openqa.suse.de/tests/2843000#step/hostname_inst/5, if it matches (except for the ip address), mark it as a failed test, with a reference to either a progress ticket or a bsc. That should be good enogh for the first run

Note that the message

[2019-04-02T18:12:34.094 CEST] [debug] isotovideo: unable to inform websocket clients about stopping command server: Request timeout at /usr/bin/isotovideo line 171.

does not mean the test timed out after reaching the configured timeout of usually 2 hours.

It just means that isotovideo could not tell the websocket clients that the test execution ended. This is required for the developer mode to suppress irritating error messages. This debug message has nothing to do with the test execution itself. It is printed after the test execution has already ended.

I'm not sure why it fails, though. But it looks like it actually just took more than 15 seconds to distribute that message to the openqa-livehandler daemon.

Looking at the job history there are indeed timed-out jobs. But still, the error message stated under 'Observation' has nothing to do with these timeouts.

It seems that the test execution time has been reduced in more recent testruns (e.g. https://openqa.suse.de/tests/2862771).

compare
normal test run takes less than 60 minutes:
https://openqa.suse.de/tests/2862771/file/video.ogv at 3:29

with incomplete test run takes about 3 hours:
https://openqa.suse.de/tests/2763448/file/video.ogv at end 5:00
running test code from apachetest.pm

I found the performance from incomplete test is poor, but I don't think it takes really exact 3:00 hours.
If SUT is not done with test, then It should stop kvm guest for running further test modules, but this is failed which mentioned in

isotovideo: unable to inform websocket clients about stopping command server

so what I can say: all tests till consoletest_finish runs completely and successfully.
We have for this case only a problem for: isotovideo send command to end running tests on SUT after 3:00 hours, but SUT is overloaded somehow and it cannot stop working and it continues running till end of tests.

need to check:
https://openqa.suse.de/tests/2867413#next_previous

@zluo

If SUT is not done with test, then It should stop kvm guest for running further test modules, but this is failed which mentioned in

The message 'isotovideo: unable to inform websocket clients about stopping command server' and the problem that the SUT continues to run are not related.

over 100 test runs on osd don't show this issue.
2 failures: ssc_registration (executed by grenache-1:13) and reconnect_mgmt_console (executed by grenache-1:14) which are not related with this issue.

compare successful test runs:
https://openqa.suse.de/tests/2867385/file/autoinst-log.txt

[2019-05-07T10:59:08.462 CEST] [debug] /var/lib/openqa/cache/openqa.suse.de/tests/sle/tests/console/consoletest_finish.pm:40 called testapi::wait_still_screen
[2019-05-07T10:59:08.462 CEST] [debug] <<< testapi::wait_still_screen(timeout=30, stilltime=2, similarity_level=47)
[2019-05-07T10:59:10.502 CEST] [debug] >>> testapi::wait_still_screen: detected same image for 2 seconds, last detected similarity is 1000000
[2019-05-07T10:59:10.729 CEST] [debug] ||| finished consoletest_finish console at 2019-05-07 08:59:10 (13 s)
[2019-05-07T10:59:10.730 CEST] [debug] killing autotest process 333213
[2019-05-07T10:59:10.733 CEST] [debug] [autotest] process exited: 0
[2019-05-07T10:59:11.734 CEST] [debug] done with autotest process
[2019-05-07T10:59:11.734 CEST] [debug] killing command server 333212 because test execution ended
[2019-05-07T10:59:11.734 CEST] [debug] isotovideo: informing websocket clients before stopping command server: http://127.0.0.1:20123/heeley63kbisPxst/broadcast
[2019-05-07T10:59:12.744 CEST] [debug] commands process exited: 0
[2019-05-07T10:59:13.745 CEST] [debug] done with command server
[2019-05-07T10:59:13.745 CEST] [debug] isotovideo done
[2019-05-07T10:59:13.843 CEST] [debug] Connection to root@s390p8.suse.de established
[2019-05-07T10:59:13.843 CEST] [debug] <<< backend::svirt::run_cmd(Net::SSH2=SCALAR(0x100205e8c00)='! virsh  dominfo openQA-SUT-1 | grep -w \'shut off\'', hostname='s390p8.suse.de', password='.zKVM.')
[2019-05-07T10:59:13.931 CEST] [debug] Command executed: '! virsh  dominfo openQA-SUT-1 | grep -w 'shut off'', ret=0
[2019-05-07T10:59:13.943 CEST] [debug] BACKEND SHUTDOWN 0
[2019-05-07T10:59:13.944 CEST] [debug] Destroying openQA-SUT-1 virtual machine
[2019-05-07T10:59:14.030 CEST] [debug] Connection to root@s390p8.suse.de established
[2019-05-07T10:59:14.030 CEST] [debug] <<< backend::svirt::run_cmd(Net::SSH2=SCALAR(0x1003dc3d870)='virsh destroy openQA-SUT-1', password='.zKVM.', hostname='s390p8.suse.de')
[2019-05-07T10:59:14.562 CEST] [debug] Command's stdout:
Domain openQA-SUT-1 destroyed

with

https://openqa.suse.de/tests/2763448/file/worker-log.txt

[2019-04-02T19:39:00.0200 CEST] [warn] [pid:542426] max job time exceeded, aborting 02763448-sle-15-SP1-Installer-DVD-s390x-Build204.1-gnome+proxy_SCC+allmodules@s390x-kvm-sle12
[2019-04-02T19:39:00.0200 CEST] [debug] [pid:542426] stop_job timeout
[2019-04-02T19:39:00.0200 CEST] [debug] [pid:542426] ## removing timer update_status
[2019-04-02T19:39:00.0200 CEST] [debug] [pid:542426] ## removing timer job_timeout
[2019-04-02T19:39:00.0201 CEST] [debug] [pid:542426] POST http://openqa.suse.de/api/v1/jobs/2763448/status
[2019-04-02T19:39:00.0272 CEST] [info] [pid:542426] trying to stop job gracefully by announcing it to command server via http://localhost:20123/FLA9DxoQcuJX3vgy/broadcast
[2019-04-02T19:39:00.0273 CEST] [error] [pid:542426] unable to stop the command server gracefully: 
[2019-04-02T19:39:00.0273 CEST] [error] [pid:542426] command server likely not reachable at all
[2019-04-02T19:39:09.0054 CEST] [info] [pid:542426] uploading logs_from_installation_system-y2logs.tar.bz2

we can see only difference here is something wrong with command server which is not reachable.

https://openqa.suse.de/tests/2763448/file/autoinst-log.txt

started with time [2019-04-02T16:38:49.0684 CEST] till [2019-04-02T18:12:19.078 CEST] it took about 1 hour 34 minutes to get all tests finished.

in worker.log we see
[2019-04-02T19:39:00.0200 CEST] max job time exceeded

The virsh command itself does not hang because Command executed is really printed after the command is executed.

This leaves only the SSH connection. After Command executed the SSH channel is attempted to be closed. Then it might download a file via SCP if open_serial_console_via_ssh has been called previously. But that's actually not the case in the failed job. Not sure whether closing the SSH channel would cause this timeout. But we actullay don't set any timeout for the SSH connection so the default of having no timeout applies (https://metacpan.org/pod/Net::SSH2#timeout-(-timeout_ms-)).

Than it is 'flushing frames'. Maybe it hangs there. It could be the case because that involves blocking IPC with the video encoder. But then it likely wouldn't be an svirt backend-specific issue.

I guess we have to add more debug printing to find out where it actually hangs and wait until it happens again.

PR for debugging whether it gets stuck before or after 'flushing frames': https://github.com/os-autoinst/os-autoinst/pull/1148

I'm not that sure why this is blocked by "Connection timed out".

Perhaps you stop picking assignees if that assignee doesn't work on it for half a year?

If it's a team feature, perhaps it shouldn't be in Category 'Concrete Bugs'?

And I'm still wondering why this is blocked by "Connection timed out" (maybe the tickets are just related?).

mkittler wrote:

And I'm still wondering why this is blocked by "Connection timed out" (maybe the tickets are just related?).

It is not blocked, the status is "new" now.
If you refer to the relation, it is because it was blocked. Removing the relation would remove information. A relation of blocked by with a closed ticket (see strikethrough) is not considered by U-Team as blocked anymore.

Is it still happening? If that's the case, is the log messag flushing frames printed?