QA » openQA Project

https://openqa.suse.de/tests/4853225 shows an interesting error after the VNC connection failed. I think the VNC connection issue is not the root cause of this issue and is handled in different tickets (e.g. https://progress.opensuse.org/issues/71236). However, it seems like os-autoinst crashes on tearing down the connection. Here's the interesting part of autoinst.log. So first you see the connection errors:

[2020-10-20T15:28:10.878 CEST] [debug] WARNING: check_asserted_screen took 12.61 seconds for 122 candidate needles - make your needles more specific
[2020-10-20T15:28:10.878 CEST] [debug] no match: 30.4s, best candidate: import-untrusted-gpg-key-SES6-bsc123456-20180921 (0.00)
[2020-10-20T15:28:10.881 CEST] [debug] considering VNC stalled, no update for 16.16 seconds
[2020-10-20T15:28:12.884 CEST] [debug] Error connecting to VNC server <10.161.145.85:5901>: IO::Socket::INET: connect: Connection refused
[2020-10-20T15:28:13.885 CEST] [debug] Error connecting to VNC server <10.161.145.85:5901>: IO::Socket::INET: connect: Connection refused
[2020-10-20T15:28:14.886 CEST] [debug] Error connecting to VNC server <10.161.145.85:5901>: IO::Socket::INET: connect: Connection refused
[2020-10-20T15:28:15.887 CEST] [debug] Error connecting to VNC server <10.161.145.85:5901>: IO::Socket::INET: connect: Connection refused
[2020-10-20T15:28:16.888 CEST] [debug] Error connecting to VNC server <10.161.145.85:5901>: IO::Socket::INET: connect: Connection refused
[2020-10-20T15:28:17.889 CEST] [debug] Error connecting to VNC server <10.161.145.85:5901>: IO::Socket::INET: connect: Connection refused
[2020-10-20T15:28:18.890 CEST] [debug] Error connecting to VNC server <10.161.145.85:5901>: IO::Socket::INET: connect: Connection refused
[2020-10-20T15:28:19.891 CEST] [debug] Error connecting to VNC server <10.161.145.85:5901>: IO::Socket::INET: connect: Connection refused
[2020-10-20T15:28:20.893 CEST] [debug] Backend process died, backend errors are reported below in the following lines:
Error connecting to VNC server <10.161.145.85:5901>: IO::Socket::INET: connect: Connection refused
[2020-10-20T15:28:20.894 CEST] [debug] Closing SSH serial connection with s390zp18.suse.de
[2020-10-20T15:28:20.894 CEST] [debug] Destroying openQA-SUT-6 virtual machine
[2020-10-20T15:28:20.895 CEST] [debug] <<< backend::baseclass::run_ssh_cmd(cmd="virsh destroy openQA-SUT-6", wantarray=0, keep_open=1)
[2020-10-20T15:28:20.895 CEST] [debug] <<< backend::baseclass::run_ssh(cmd="virsh destroy openQA-SUT-6", wantarray=0, keep_open=1)
[2020-10-20T15:28:20.895 CEST] [debug] <<< backend::baseclass::new_ssh_connection(blocking=1, wantarray=0, keep_open=1)
[2020-10-20T15:28:21.605 CEST] [debug] [run_ssh_cmd(virsh destroy openQA-SUT-6)] stdout:
Domain openQA-SUT-6 destroyed


[2020-10-20T15:28:21.605 CEST] [debug] [run_ssh_cmd(virsh destroy openQA-SUT-6)] exit-code: 0
[2020-10-20T15:28:21.605 CEST] [debug] <<< backend::baseclass::run_ssh_cmd(cmd="virsh undefine --snapshots-metadata openQA-SUT-6", keep_open=1, wantarray=0)
[2020-10-20T15:28:21.605 CEST] [debug] <<< backend::baseclass::run_ssh(cmd="virsh undefine --snapshots-metadata openQA-SUT-6", keep_open=1, wantarray=0)
[2020-10-20T15:28:21.605 CEST] [debug] <<< backend::baseclass::new_ssh_connection(keep_open=1, wantarray=0, blocking=1)
[2020-10-20T15:28:21.642 CEST] [debug] [run_ssh_cmd(virsh undefine --snapshots-metadata openQA-SUT-6)] stdout:
Domain openQA-SUT-6 has been undefined


[2020-10-20T15:28:21.642 CEST] [debug] [run_ssh_cmd(virsh undefine --snapshots-metadata openQA-SUT-6)] exit-code: 0
[2020-10-20T15:28:21.642 CEST] [debug] Passing remaining frames to the video encoder
[2020-10-20T15:28:21.644 CEST] [debug] Waiting for video encoder to finalize the video
[2020-10-20T15:28:21.644 CEST] [debug] The built-in video encoder (pid 302770) terminated

but then the part where I think stuff goes wrong:

[2020-10-20T15:28:21.644 CEST] [debug] SSH disconnect hostname=s390zp18.suse.de,username=root
[2020-10-20T15:28:21.644 CEST] [debug] sending magic and exit
[2020-10-20T15:28:21.644 CEST] [debug] received magic close
[2020-10-20T15:28:21.645 CEST] [debug] backend got TERM
[2020-10-20T15:28:21.645 CEST] [debug] sending magic and exit
[2020-10-20T15:28:21.645 CEST] [debug] capture loop failed myjsonrpc: remote end terminated connection, stopping at /usr/lib/os-autoinst/myjsonrpc.pm line 57.

[2020-10-20T15:28:21.645 CEST] [debug] sending magic and exit
[2020-10-20T15:28:21.645 CEST] [debug] Backend process died, backend errors are reported below in the following lines:
myjsonrpc: remote end terminated connection, stopping at /usr/lib/os-autoinst/myjsonrpc.pm line 57.

[2020-10-20T15:28:21.645 CEST] [debug] sending magic and exit
Use of uninitialized value $_[2] in substr at /usr/lib/perl5/5.26.1/ppc64le-linux-thread-multi/IO/Handle.pm line 475.
Use of uninitialized value $_[1] in substr at /usr/lib/perl5/5.26.1/ppc64le-linux-thread-multi/IO/Handle.pm line 475.
[2020-10-20T15:28:21.656 CEST] [debug] backend process exited: 16
XIO:  fatal IO error 11 (Resource temporarily unavailable) on X server ":37887"
      after 28809 requests (28809 known processed) with 0 events remaining.
xterm: fatal IO error 11 (Resource temporarily unavailable) or KillClient on X server ":37887"
[2020-10-20T15:28:21.657 CEST] [debug] Driver backend collected unknown process with pid 302792 and exit status: 1
[2020-10-20T15:28:21.658 CEST] [debug] stopping command server 302730 because test execution ended
[2020-10-20T15:28:21.658 CEST] [debug] isotovideo: informing websocket clients before stopping command server: http://127.0.0.1:20363/W2xIVjJ1oTuKdPpA/broadcast
[2020-10-20T15:28:21.658 CEST] [debug] Driver backend collected unknown process with pid 302796 and exit status: 0
[2020-10-20T15:28:21.658 CEST] [debug] Driver backend collected unknown process with pid 302794 and exit status: 84
[2020-10-20T15:28:21.662 CEST] [debug] Driver backend collected unknown process with pid 302772 and exit status: 0
[2020-10-20T15:28:21.670 CEST] [debug] commands process exited: 0
[2020-10-20T15:28:21.770 CEST] [debug] done with command server
[2020-10-20T15:28:21.770 CEST] [debug] stopping autotest process 302738
[2020-10-20T15:28:21.770 CEST] [debug] autotest received signal TERM, saving results of current test before exiting
[2020-10-20T15:28:21.783 CEST] [debug] [autotest] process exited: 1
[2020-10-20T15:28:21.884 CEST] [debug] done with autotest process
[2020-10-20T15:28:21.884 CEST] [debug] isotovideo failed
[2020-10-20T15:28:21.884 CEST] [debug] stopping backend process 302739
[2020-10-20T15:28:21.884 CEST] [debug] done with backend process

Looking at the "Use of uninitialized value" we might also face an upstream bug but I'm unsure if stuff like $_[1] indicates some wrongly passed parameters so a quick look from a skilled perl programmer who's into openQA's codebase would be highly appreciated :)