Project

General

Profile

Actions
Copy link

action #75019

open

s390 job via ppc64le worker incompletes on failure to connect to VNC due to "Use of uninitialized value $_[2] in substr at /usr/lib/perl5/5.26.1/ppc64le-linux-thread-multi/IO/Handle.pm"

Added by nicksinger about 4 years ago. Updated over 2 years ago.

Status:
New
Priority:
Low
Assignee:
-
Category:
Feature requests
Target version:
QA - future
Start date:
2020-10-21
Due date:
% Done:

0%

Estimated time:

Description

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 :)

Related issues 2 (1 open — 1 closed)

Related to openQA Project - action #71236: job incompletes with auto_review:"backend died: Error connecting to VNC server <openqaw5-xen.qa.suse.de:5901>: IO::Socket::INET: connect: Connection refused"Rejectedokurz2020-09-11

Actions
Related to openQA Project - action #73525: Job incompletes with auto_review:"backend died: unexpected end of data at /usr/lib/os-autoinst/consoles/VNC.pm.*":retryNew2020-10-19

Actions
Actions
Copy link
 #1

Updated by nicksinger about 4 years ago

  • Related to action #71236: job incompletes with auto_review:"backend died: Error connecting to VNC server <openqaw5-xen.qa.suse.de:5901>: IO::Socket::INET: connect: Connection refused" added
Actions
Copy link
 #2

Updated by okurz about 4 years ago

  • Target version set to Ready
Actions
Copy link
 #3

Updated by okurz about 4 years ago

  • Related to action #73525: Job incompletes with auto_review:"backend died: unexpected end of data at /usr/lib/os-autoinst/consoles/VNC.pm.*":retry added
Actions
Copy link
 #4

Updated by okurz about 4 years ago

  • Category set to Feature requests
  • Priority changed from Normal to Low
  • Target version changed from Ready to future

I think this is something we had in forever (hence setting "Low") and is mostly a case of "misleading error output" so I regard it as "Feature requests" category rather than a regression. Also not including in our backlog. We have plans for tickets in related areas which might improve the behaviour indirectly anyway.

Actions
Copy link
 #5

Updated by jlausuch over 2 years ago

I just hit this error while setting up a new openQA instance
http://marvin5.arch.suse.cz/tests/10#

[2022-05-23T14:15:00.151489+02:00] [info] +++ setup notes +++
[2022-05-23T14:15:00.151872+02:00] [info] Running on marvin5:1 (Linux 5.17.0-freqinv #1 SMP PREEMPT Thu May 19 14:38:54 CEST 2022 x86_64)
[2022-05-23T14:15:00.970819+02:00] [debug] +++ worker notes +++
[2022-05-23T14:15:01.384795+02:00] [debug] Current version is 4.6.1653078548.548335f [interface v25]
[2022-05-23T14:15:01.396503+02:00] [debug] git hash in sle: c43f32f8ed93c166a0e2c213fb4ead3774faded2
[2022-05-23T14:15:01.728667+02:00] [debug] default desktop: gnome
[2022-05-23T14:15:01.729029+02:00] [debug] usingenv ADDONURL=
[2022-05-23T14:15:01.729095+02:00] [debug] usingenv DESKTOP=textmode
[2022-05-23T14:15:01.729159+02:00] [debug] usingenv DISTRI=sle
[2022-05-23T14:15:01.729210+02:00] [debug] usingenv NOAUTOLOGIN=1
[2022-05-23T14:15:01.729260+02:00] [debug] usingenv QEMUCPU=qemu64
[2022-05-23T14:15:01.729314+02:00] [debug] usingenv INSTLANG=en_US
[2022-05-23T14:15:01.729367+02:00] [debug] usingenv DVD=1
[2022-05-23T14:15:01.729426+02:00] [debug] usingenv ISO=SLE-15-SP3-Full-x86_64-GM-Media1.iso
[2022-05-23T14:15:01.729478+02:00] [debug] usingenv ISO_MAXSIZE=94007459840
[2022-05-23T14:15:01.729531+02:00] [debug] usingenv SYSTEM_ROLE=default
[2022-05-23T14:15:01.729581+02:00] [debug] usingenv SCC_REGISTER=installation
[2022-05-23T14:15:01.729630+02:00] [debug] usingenv SLE_PRODUCT=sles
[2022-05-23T14:15:01.729680+02:00] [debug] usingenv VIDEOMODE=text
[2022-05-23T14:15:01.763012+02:00] [debug] scheduling boot_to_desktop tests/boot/boot_to_desktop.pm
[2022-05-23T14:15:01.783740+02:00] [debug] scheduling containerd_crictl tests/containers/containerd_crictl.pm
[2022-05-23T14:15:01.784278+02:00] [debug] scheduling containerd_nerdctl tests/containers/containerd_nerdctl.pm
[2022-05-23T14:15:01.784906+02:00] [debug] scheduling coredump_collect tests/console/coredump_collect.pm
[2022-05-23T14:15:01.793313+02:00] [info] cmdsrv: daemon reachable under http://*:20013/mhYiBq_fNjnsbRxv/
[2022-05-23T14:15:01.796333+02:00] [debug] git hash in sle/products/sle/needles: 8687682b4c3c5446558cdd65c4b162bbc8d934fd
[2022-05-23T14:15:01.796474+02:00] [debug] init needles from sle/products/sle/needles
[2022-05-23T14:15:01.796489+02:00] [info] Listening at "http://0.0.0.0:20013"
Web application available at http://0.0.0.0:20013
[2022-05-23T14:15:03.104332+02:00] [debug] loaded 12036 needles
[2022-05-23T14:15:03.177487+02:00] [debug] [autotest] process exited: 136
[2022-05-23T14:15:03.264295+02:00] [debug] 23858: channel_out 15, channel_in 14
Use of uninitialized value $_[2] in substr at /usr/lib/perl5/site_perl/5.26.1/x86_64-linux-thread-multi/IO/Handle.pm line 453.
    IO::Handle::write(IO::Pipe::End=GLOB(0x5653f360d940), undef, undef) called at /usr/lib/perl5/vendor_perl/5.26.1/Mojo/IOLoop/ReadWriteProcess.pm line 335
    Mojo::IOLoop::ReadWriteProcess::_fork(Mojo::IOLoop::ReadWriteProcess=HASH(0x5653f35d4c20), CODE(0x5653f35ea6e0)) called at /usr/lib/perl5/vendor_perl/5.26.1/Mojo/IOLoop/ReadWriteProcess.pm line 488
    Mojo::IOLoop::ReadWriteProcess::start(Mojo::IOLoop::ReadWriteProcess=HASH(0x5653f35d4c20)) called at /usr/lib/os-autoinst/backend/driver.pm line 75
    backend::driver::start(backend::driver=HASH(0x5653f47f0750)) called at /usr/lib/os-autoinst/backend/driver.pm line 39
    backend::driver::new("backend::driver", "qemu") called at /usr/bin/isotovideo line 207
    main::init_backend() called at /usr/bin/isotovideo line 258
Use of uninitialized value $_[1] in substr at /usr/lib/perl5/site_perl/5.26.1/x86_64-linux-thread-multi/IO/Handle.pm line 453.
    IO::Handle::write(IO::Pipe::End=GLOB(0x5653f360d940), undef, undef) called at /usr/lib/perl5/vendor_perl/5.26.1/Mojo/IOLoop/ReadWriteProcess.pm line 335
    Mojo::IOLoop::ReadWriteProcess::_fork(Mojo::IOLoop::ReadWriteProcess=HASH(0x5653f35d4c20), CODE(0x5653f35ea6e0)) called at /usr/lib/perl5/vendor_perl/5.26.1/Mojo/IOLoop/ReadWriteProcess.pm line 488
    Mojo::IOLoop::ReadWriteProcess::start(Mojo::IOLoop::ReadWriteProcess=HASH(0x5653f35d4c20)) called at /usr/lib/os-autoinst/backend/driver.pm line 75
    backend::driver::start(backend::driver=HASH(0x5653f47f0750)) called at /usr/lib/os-autoinst/backend/driver.pm line 39
    backend::driver::new("backend::driver", "qemu") called at /usr/bin/isotovideo line 207
    main::init_backend() called at /usr/bin/isotovideo line 258
[2022-05-23T14:15:03.283838+02:00] [debug] backend process exited: 32
myjsonrpc: remote end terminated connection, stopping at /usr/lib/os-autoinst/myjsonrpc.pm line 43, <GEN15> line 20.
    myjsonrpc::send_json(IO::Pipe::End=GLOB(0x5653f360a7c0), HASH(0x5653f0083828)) called at /usr/lib/os-autoinst/backend/driver.pm line 126
    backend::driver::_send_json(backend::driver=HASH(0x5653f47f0750), HASH(0x5653f0083828)) called at /usr/lib/os-autoinst/backend/driver.pm line 107
    backend::driver::start_vm(backend::driver=HASH(0x5653f47f0750)) called at /usr/bin/isotovideo line 263
[2022-05-23T14:15:03.285273+02:00] [debug] stopping command server 23863 because test execution ended through exception
[2022-05-23T14:15:03.485777+02:00] [debug] done with command server
[2022-05-23T14:15:03.485860+02:00] [debug] stopping autotest process 23866
[2022-05-23T14:15:03.485965+02:00] [debug] done with autotest process
23858: EXIT 1
[2022-05-23T14:15:03.548681+02:00] [info] Isotovideo exit status: 1
[2022-05-23T14:15:03.662341+02:00] [info] +++ worker notes +++
[2022-05-23T14:15:03.662614+02:00] [info] End time: 2022-05-23 12:15:03
[2022-05-23T14:15:03.662769+02:00] [info] Result: died
[2022-05-23T14:15:03.668761+02:00] [info] Uploading vars.json
[2022-05-23T14:15:03.782481+02:00] [info] Uploading autoinst-log.txt

Update: after reinstalling perl and installing it again (besides all openqa packages) it works:

zypper rm perl
zypper in perl
zypper in openvswitch openQA openQA-worker os-autoinst os-autoinst-openvswitch

I just made sure the repo I am installing it from is:
http://download.opensuse.org/repositories/devel:/openQA/openSUSE_Leap_15.3/

And 

rpm -q perl-Mojo-IOLoop-ReadWriteProcess
perl-Mojo-IOLoop-ReadWriteProcess-0.32-lp153.33.1.noarch

is the same version before and after, so I am not sure what was causing that exception...

Actions
Copy link

Also available in: Atom PDF