QA (public) » openQA Project (public)

interesting, could be linked to #72079 , @ggardet_arm can you also take a look into this while working on #72079? Maybe a different qemu version helps here as well?

I have seen this error very sporadically, even before the upgrade.

Problem seems to be caused by previous test modules failing, see the rollback ending in the log followed by log messages about a virtio console and then the error:

[2020-10-11T17:17:35.867 CEST] [debug] QEMU: Copyright (c) 2003-2019 Fabrice Bellard and the QEMU Project developers
[2020-10-11T17:17:35.878 CEST] [debug] <<< consoles::virtio_terminal::open_pipe(pipe_prefix="/var/lib/openqa/pool/3/virtio_console")
[2020-10-11T17:17:35.879 CEST] [info] ::: consoles::virtio_terminal::open_pipe: Set PIPE_SZ from 65536 to 1048576
[2020-10-11T17:17:35.879 CEST] [info] ::: consoles::virtio_terminal::open_pipe: Set PIPE_SZ from 65536 to 1048576
[2020-10-11T17:17:35.879 CEST] [debug] ||| starting health_check tests/transactional/health_check.pm
[2020-10-11T17:17:35.881 CEST] [debug] tests/transactional/health_check.pm:42 called testapi::script_run
[2020-10-11T17:17:35.881 CEST] [debug] <<< testapi::script_run(cmd="rpm -q health-checker", quiet=undef, output="", timeout=undef)
[2020-10-11T17:17:35.882 CEST] [debug] tests/transactional/health_check.pm:42 called testapi::script_run
[2020-10-11T17:17:35.882 CEST] [debug] <<< testapi::type_string(string="rpm -q health-checker", max_interval=250, wait_screen_changes=0, wait_still_screen=0, timeout=30, similarity_level=47)
[2020-10-11T17:17:35.883 CEST] [debug] <<< consoles::serial_screen::type_string(cmd="backend_type_string", max_interval=250, json_cmd_token="QjmuvdRC", text="rpm -q health-checker")
[2020-10-11T17:17:35.883 CEST] [debug] tests/transactional/health_check.pm:42 called testapi::script_run
[2020-10-11T17:17:35.883 CEST] [debug] <<< testapi::type_string(string="; echo Jhv3u-\$?- > /dev/ttyAMA0\n", max_interval=250, wait_screen_changes=0, wait_still_screen=0, timeout=30, similarity_level=47)
[2020-10-11T17:17:35.884 CEST] [debug] <<< consoles::serial_screen::type_string(text="; echo Jhv3u-\$?- > /dev/ttyAMA0\n", json_cmd_token="vheCfIqe", max_interval=250, cmd="backend_type_string")
[2020-10-11T17:17:35.884 CEST] [debug] tests/transactional/health_check.pm:42 called testapi::script_run
[2020-10-11T17:17:35.885 CEST] [debug] <<< testapi::wait_serial(timeout=30, quiet=undef, no_regex=0, expect_not_found=0, record_output=undef, buffer_size=undef, regexp=qr/Jhv3u-\d+-/)
[2020-10-11T17:17:35.886 CEST] [debug] <<< consoles::serial_screen::read_until(json_cmd_token="CdDITOwF", regexp="(?^:Jhv3u-\\d+-)", pattern="(?^:Jhv3u-\\d+-)", timeout=60, record_output=undef, expect_not_found=0, buffer_size=undef, cmd="backend_wait_serial", quiet=undef, no_regex=0)
[2020-10-11T17:18:37.028 CEST] [debug] >>> testapi::wait_serial: (?^:Jhv3u-\d+-): fail
[2020-10-11T17:18:37.029 CEST] [debug] tests/transactional/health_check.pm:48 called testapi::validate_script_output
[2020-10-11T17:18:37.029 CEST] [debug] <<< testapi::type_string(string="cat - > /tmp/scriptIWeHA.sh;\n", max_interval=250, wait_screen_changes=0, wait_still_screen=0, timeout=30, similarity_level=47)
[2020-10-11T17:18:37.030 CEST] [debug] <<< consoles::serial_screen::type_string(cmd="backend_type_string", json_cmd_token="klzuekgn", max_interval=250, text="cat - > /tmp/scriptIWeHA.sh;\n")
[2020-10-11T17:18:37.031 CEST] [debug] tests/transactional/health_check.pm:48 called testapi::validate_script_output
[2020-10-11T17:18:37.031 CEST] [debug] <<< testapi::type_string(string="health-checker\n", max_interval=250, wait_screen_changes=0, wait_still_screen=0, timeout=30, similarity_level=47)
[2020-10-11T17:18:37.032 CEST] [debug] <<< consoles::serial_screen::type_string(cmd="backend_type_string", text="health-checker\n", max_interval=250, json_cmd_token="wEobsqaz")
[2020-10-11T17:18:37.032 CEST] [debug] tests/transactional/health_check.pm:48 called testapi::validate_script_output
[2020-10-11T17:18:37.032 CEST] [debug] <<< testapi::send_key(key="ctrl-d", wait_screen_change=0, do_wait=0)
[2020-10-11T17:18:37.034 CEST] [debug] Backend process died, backend errors are reported below in the following lines:
Virtio terminal and svirt serial terminal do not support send_key. Use
type_string (possibly with an ANSI/XTERM escape sequence), or switch to a
console which sends key presses, not terminal codes.
 at /usr/lib/os-autoinst/backend/baseclass.pm line 787.

compared to the last green https://openqa.opensuse.org/tests/1426590/file/autoinst-log.txt showing

[2020-10-10T07:08:51.154 UTC] [debug] ||| finished rebootmgr transactional at 2020-10-10 07:08:51 (785 s)
[2020-10-10T07:08:51.158 UTC] [debug] ||| starting health_check tests/transactional/health_check.pm
[2020-10-10T07:08:51.159 UTC] [debug] tests/transactional/health_check.pm:42 called testapi::script_run
[2020-10-10T07:08:51.159 UTC] [debug] <<< testapi::script_run(cmd="rpm -q health-checker", timeout=undef, quiet=undef, output="")
[2020-10-10T07:08:51.160 UTC] [debug] tests/transactional/health_check.pm:42 called testapi::script_run
[2020-10-10T07:08:51.160 UTC] [debug] <<< testapi::type_string(string="rpm -q health-checker", max_interval=250, wait_screen_changes=0, wait_still_screen=0, timeout=30, similarity_level=47)
[2020-10-10T07:08:54.188 UTC] [debug] tests/transactional/health_check.pm:42 called testapi::script_run
[2020-10-10T07:08:54.189 UTC] [debug] <<< testapi::type_string(string="; echo Jhv3u-\$?- > /dev/ttyAMA0\n", max_interval=250, wait_screen_changes=0, wait_still_screen=0, timeout=30, similarity_level=47)
[2020-10-10T07:08:59.296 UTC] [debug] tests/transactional/health_check.pm:42 called testapi::script_run
[2020-10-10T07:08:59.296 UTC] [debug] <<< testapi::wait_serial(quiet=undef, regexp=qr/Jhv3u-\d+-/, no_regex=0, expect_not_found=0, buffer_size=undef, timeout=30, record_output=undef)
[2020-10-10T07:09:00.402 UTC] [debug] >>> testapi::wait_serial: (?^:Jhv3u-\d+-): ok
[2020-10-10T07:09:00.402 UTC] [debug] tests/transactional/health_check.pm:48 called testapi::validate_script_output
[2020-10-10T07:09:00.403 UTC] [debug] <<< testapi::type_string(string="cat - > /tmp/scriptIWeHA.sh;\n", max_interval=250, wait_screen_changes=0, wait_still_screen=0, timeout=30, similarity_level=47)
[2020-10-10T07:09:04.938 UTC] [debug] tests/transactional/health_check.pm:48 called testapi::validate_script_output
[2020-10-10T07:09:04.938 UTC] [debug] <<< testapi::type_string(string="health-checker\n", max_interval=250, wait_screen_changes=0, wait_still_screen=0, timeout=30, similarity_level=47)
[2020-10-10T07:09:07.101 UTC] [debug] tests/transactional/health_check.pm:48 called testapi::validate_script_output
[2020-10-10T07:09:07.101 UTC] [debug] <<< testapi::send_key(key="ctrl-d", wait_screen_change=0, do_wait=0)
[2020-10-10T07:09:07.874 UTC] [debug] tests/transactional/health_check.pm:48 called testapi::validate_script_output
[2020-10-10T07:09:07.875 UTC] [debug] <<< testapi::type_string(string="(echo IWeHA; bash -eox pipefail /tmp/scriptIWeHA.sh ; echo SCRIPT_FINISHEDIWeHA-\$?-) | tee /dev/ttyAMA0\n", max_interval=250, wait_screen_changes=0, wait_still_screen=0, timeout=30, similarity_level=47)
[2020-10-10T07:09:25.366 UTC] [debug] tests/transactional/health_check.pm:48 called testapi::validate_script_output
[2020-10-10T07:09:25.367 UTC] [debug] <<< testapi::wait_serial(timeout=30, record_output=1, no_regex=0, quiet=undef, expect_not_found=0, regexp="SCRIPT_FINISHEDIWeHA-\\d+-", buffer_size=undef)
[2020-10-10T07:09:27.477 UTC] [debug] >>> testapi::wait_serial: SCRIPT_FINISHEDIWeHA-\d+-: ok

both jobs have VIRTIO_CONSOLE=1

The send_key call seems to come from valid_script_output that calls script_output which has the code:

    if (testapi::is_serial_terminal) {
        my $heretag = 'EOT_' . $marker;
        my $cat     = "cat > $script_path << '$heretag'; echo $marker-\$?-";
        testapi::wait_serial($self->{serial_term_prompt}, no_regex => 1, quiet => $args{quiet});
        bmwqemu::log_call("Content of $script_path :\n \"$cat\" \n");
        testapi::type_string($cat . "\n");
        testapi::wait_serial("$cat", no_regex => 1, quiet => $args{quiet});
        # Wait for input prompt of here tag before typing $script. This avoids
        # messy output, like duplicate output of $script. We do this in a second
        # wait_serial() call, to avoid issues during new line detection.
        testapi::wait_serial('> ', no_regex => 1, quiet => $args{quiet});
        testapi::type_string("$script\n$heretag\n");
        testapi::wait_serial("> $heretag", no_regex => 1, quiet => $args{quiet});
        testapi::wait_serial("$marker-0-", quiet => $args{quiet});
    }   
    elsif ($args{type_command}) {
        my $cat = "cat - > $script_path;\n";
        testapi::type_string($cat);
        testapi::type_string($script . "\n");
        testapi::send_key('ctrl-d');
    }   

so it seems that testapi::is_serial_terminal evaluates to false here. Maybe the problem is related to the test module tests/transactional/health_check.pm does not have an explicit select_console call. Now I am asking myself: Clearly this is not a "product bug" but should the job incomplete or fail? The "incomplete" is not commonly seen as a problem that would need to be fixed in the test distribution. This might be even more so because in the reason it says "backend died" and not "tests died". I suggest we change that to say "tests died".

As the actual error in tests was fixed by ggardet_arm we do not need to regard this as high anymore. Also I tried to clarify better what we could do with an explicit feature request in #75388