|
## Run 7
|
|
Build directory: /hdd/openqa-devel/build/os-autoinst-ninja
|
|
[1/2] cd /hdd/openqa-devel/repos/os-autoinst && /hdd/openqa-devel/repos/os-autoinst/tools/invoke-tests --prove-tool /usr/bin/prove --make-tool /usr/bin/ninja --build-directory /hdd/openqa-devel/build/os-autoinst-ninja
|
|
t/99-full-stack.t ..
|
|
# data dir: /hdd/openqa-devel/repos/os-autoinst/t/data/
|
|
# pool dir: /tmp/99-full-stack.t-UV_h/pool/
|
|
[2022-01-24T15:48:24.035658+01:00] [debug] Current version is 7ef72e209567425123d4311781f3024f52d88f3a [interface v24]
|
|
[2022-01-24T15:48:24.045406+01:00] [debug] git hash in /hdd/openqa-devel/repos/os-autoinst/t/data//tests: 7ef72e209567425123d4311781f3024f52d88f3a
|
|
[2022-01-24T15:48:24.117379+01:00] [debug] scheduling freeze tests/freeze.pm
|
|
[2022-01-24T15:48:24.122165+01:00] [debug] scheduling pre_boot tests/pre_boot.py
|
|
[2022-01-24T15:48:24.122973+01:00] [debug] scheduling boot tests/boot.pm
|
|
[2022-01-24T15:48:24.123605+01:00] [debug] scheduling assert_screen tests/assert_screen.pm
|
|
[2022-01-24T15:48:24.124425+01:00] [debug] scheduling typing tests/typing.pm
|
|
[2022-01-24T15:48:24.125124+01:00] [debug] scheduling select_console_fail_test tests/select_console_fail_test.pm
|
|
[2022-01-24T15:48:24.125877+01:00] [debug] scheduling select_ssh_console_fail_test tests/select_ssh_console_fail_test.pm
|
|
[2022-01-24T15:48:24.126705+01:00] [debug] scheduling assert_screen_fail_test tests/assert_screen_fail_test.pm
|
|
[2022-01-24T15:48:24.127737+01:00] [debug] scheduling reload_needles tests/reload_needles.pm
|
|
[2022-01-24T15:48:24.128530+01:00] [debug] scheduling modify_and_upload_file tests/modify_and_upload_file.pm
|
|
[2022-01-24T15:48:24.129346+01:00] [debug] scheduling shutdown tests/shutdown.pm
|
|
[2022-01-24T15:48:24.136620+01:00] [info] cmdsrv: daemon reachable under http://*:15223/yUWgUjfTeq/
|
|
[2022-01-24T15:48:24.138318+01:00] [info] Listening at "http://[::]:15223"
|
|
Web application available at http://[::]:15223
|
|
[2022-01-24T15:48:24.139727+01:00] [debug] git hash in /hdd/openqa-devel/repos/os-autoinst/t/data//tests/needles: 7ef72e209567425123d4311781f3024f52d88f3a
|
|
[2022-01-24T15:48:24.139904+01:00] [debug] init needles from /hdd/openqa-devel/repos/os-autoinst/t/data//tests/needles
|
|
[2022-01-24T15:48:24.141264+01:00] [debug] loaded 4 needles
|
|
[2022-01-24T15:48:24.143753+01:00] [debug] Blocking SIGCHLD and SIGTERM
|
|
[2022-01-24T15:48:24.173126+01:00] [debug] Unblocking SIGCHLD and SIGTERM
|
|
[2022-01-24T15:48:24.337704+01:00] [debug] Blocking SIGCHLD and SIGTERM
|
|
[2022-01-24T15:48:24.337856+01:00] [debug] 10435: channel_out 20, channel_in 19
|
|
[2022-01-24T15:48:24.378976+01:00] [debug] Unblocking SIGCHLD and SIGTERM
|
|
[2022-01-24T15:48:24.381604+01:00] [debug] 10457: cmdpipe 18, rsppipe 21
|
|
[2022-01-24T15:48:24.381755+01:00] [debug] started mgmt loop with pid 10457
|
|
[2022-01-24T15:48:24.419964+01:00] [debug] qemu version detected: 6.2.0
|
|
[2022-01-24T15:48:24.421569+01:00] [debug] running `/usr/bin/chattr +C /tmp/99-full-stack.t-UV_h/pool/raid`
|
|
[2022-01-24T15:48:24.441444+01:00] [debug] Command `/usr/bin/chattr +C /tmp/99-full-stack.t-UV_h/pool/raid` terminated with 1
|
|
/usr/bin/chattr: Operation not supported while reading flags on /tmp/99-full-stack.t-UV_h/pool/raid
|
|
[2022-01-24T15:48:24.441635+01:00] [debug] Configuring storage controllers and block devices
|
|
[2022-01-24T15:48:24.442498+01:00] [debug] running `/usr/bin/qemu-img info --output=json /hdd/openqa-devel/repos/os-autoinst/t/data/Core-7.2.iso`
|
|
[2022-01-24T15:48:24.463792+01:00] [debug] Initializing block device images
|
|
[2022-01-24T15:48:24.464133+01:00] [debug] running `/usr/bin/qemu-img create -f qcow2 /tmp/99-full-stack.t-UV_h/pool/raid/hd0 10G`
|
|
[2022-01-24T15:48:24.486557+01:00] [debug] Formatting '/tmp/99-full-stack.t-UV_h/pool/raid/hd0', fmt=qcow2 cluster_size=65536 extended_l2=off compression_type=zlib size=10737418240 lazy_refcounts=off refcount_bits=16
|
|
[2022-01-24T15:48:24.486778+01:00] [debug] running `/usr/bin/qemu-img create -f qcow2 -F raw -b /hdd/openqa-devel/repos/os-autoinst/t/data/Core-7.2.iso /tmp/99-full-stack.t-UV_h/pool/raid/cd0-overlay0 11116544`
|
|
[2022-01-24T15:48:24.505237+01:00] [debug] Formatting '/tmp/99-full-stack.t-UV_h/pool/raid/cd0-overlay0', fmt=qcow2 cluster_size=65536 extended_l2=off compression_type=zlib size=11116544 backing_file=/hdd/openqa-devel/repos/os-autoinst/t/data/Core-7.2.iso backing_fmt=raw lazy_refcounts=off refcount_bits=16
|
|
[2022-01-24T15:48:24.505438+01:00] [debug] init_blockdev_images: Finished creating block devices
|
|
[2022-01-24T15:48:24.506988+01:00] [debug] starting: /usr/bin/qemu-system-i386 -only-migratable -chardev ringbuf,id=serial0,logfile=serial0,logappend=on -serial chardev:serial0 -audiodev none,id=snd0 -device intel-hda -device hda-output,audiodev=snd0 -m 1024 -netdev user,id=qanet0 -device virtio-net,netdev=qanet0,mac=52:54:00:12:34:56 -boot once=d -smp 1 -enable-kvm -no-shutdown -vnc :90,share=force-shared -device virtio-serial -chardev pipe,id=virtio_console,path=virtio_console,logfile=virtio_console.log,logappend=on -device virtconsole,chardev=virtio_console,name=org.openqa.console.virtio_console -chardev pipe,id=virtio_console1,path=virtio_console1,logfile=virtio_console1.log,logappend=on -device virtconsole,chardev=virtio_console1,name=org.openqa.console.virtio_console1 -chardev socket,path=qmp_socket,server=on,wait=off,id=qmp_socket,logfile=qmp_socket.log,logappend=on -qmp chardev:qmp_socket -S -blockdev driver=file,node-name=hd0-file,filename=/tmp/99-full-stack.t-UV_h/pool/raid/hd0,cache.no-flush=on -blockdev driver=qcow2,node-name=hd0,file=hd0-file,cache.no-flush=on -device ide-hd,id=hd0-device,drive=hd0,serial=hd0 -blockdev driver=file,node-name=cd0-overlay0-file,filename=/tmp/99-full-stack.t-UV_h/pool/raid/cd0-overlay0,cache.no-flush=on -blockdev driver=qcow2,node-name=cd0-overlay0,file=cd0-overlay0-file,cache.no-flush=on -device ide-cd,id=cd0-device,drive=cd0-overlay0,serial=cd0
|
|
[2022-01-24T15:48:24.510237+01:00] [debug] Waiting for 0 attempts
|
|
[2022-01-24T15:48:25.510958+01:00] [debug] Waiting for 1 attempts
|
|
[2022-01-24T15:48:26.511637+01:00] [debug] Finished after 2 attempts
|
|
[2022-01-24T15:48:26.515656+01:00] [debug] Establishing VNC connection to localhost:5990
|
|
[2022-01-24T15:48:26.522143+01:00] [debug] pointer type 0 0 640 480 -257
|
|
[2022-01-24T15:48:26.522370+01:00] [debug] led state 0 1 1 -261
|
|
[2022-01-24T15:48:26.580149+01:00] [debug] Start CPU
|
|
[2022-01-24T15:48:26.580549+01:00] [debug] EVENT {"data":{"client":{"family":"ipv4","host":"127.0.0.1","service":"41410","websocket":false},"server":{"auth":"none","family":"ipv4","host":"0.0.0.0","service":"5990","websocket":false}},"event":"VNC_CONNECTED","timestamp":{"microseconds":517209,"seconds":1643035706}}
|
|
[2022-01-24T15:48:26.580708+01:00] [debug] EVENT {"data":{"client":{"family":"ipv4","host":"127.0.0.1","service":"41410","websocket":false},"server":{"auth":"none","family":"ipv4","host":"0.0.0.0","service":"5990","websocket":false}},"event":"VNC_INITIALIZED","timestamp":{"microseconds":520050,"seconds":1643035706}}
|
|
[2022-01-24T15:48:26.580842+01:00] [debug] EVENT {"event":"RESUME","timestamp":{"microseconds":580560,"seconds":1643035706}}
|
|
GOT GO
|
|
[2022-01-24T15:48:26.586224+01:00] [debug] QEMU: QEMU emulator version 6.2.0 (openSUSE Tumbleweed)
|
|
[2022-01-24T15:48:26.586356+01:00] [debug] QEMU: Copyright (c) 2003-2021 Fabrice Bellard and the QEMU Project developers
|
|
[2022-01-24T15:48:26.590933+01:00] [debug] Snapshots are supported
|
|
[2022-01-24T15:48:26.592525+01:00] [debug] ||| starting freeze tests/freeze.pm
|
|
[2022-01-24T15:48:26.594651+01:00] [debug] Call freeze_vm within a post_fail_hook or very early in your test
|
|
[2022-01-24T15:48:26.594885+01:00] [debug] tests/freeze.pm:8 called testapi::freeze_vm
|
|
[2022-01-24T15:48:26.594956+01:00] [debug] <<< testapi::freeze_vm()
|
|
[2022-01-24T15:48:26.596978+01:00] [debug] EVENT {"event":"STOP","timestamp":{"microseconds":596827,"seconds":1643035706}}
|
|
[2022-01-24T15:48:26.597425+01:00] [debug] Simply freeze the vm and resume right before the first assert screen is done
|
|
[2022-01-24T15:48:26.597641+01:00] [debug] tests/freeze.pm:10 called testapi::resume_vm
|
|
[2022-01-24T15:48:26.597681+01:00] [debug] <<< testapi::resume_vm()
|
|
[2022-01-24T15:48:26.599095+01:00] [debug] EVENT {"event":"RESUME","timestamp":{"microseconds":598973,"seconds":1643035706}}
|
|
[2022-01-24T15:48:26.602078+01:00] [debug] ||| finished freeze tests (runtime: 0 s)
|
|
[2022-01-24T15:48:26.707993+01:00] [debug] ||| starting pre_boot tests/pre_boot.py
|
|
[2022-01-24T15:48:26.708652+01:00] [debug]
|
|
[2022-01-24T15:48:26.708905+01:00] [debug] <<< testapi::send_key(key="esc", do_wait=0, wait_screen_change=0)
|
|
[2022-01-24T15:48:26.978203+01:00] [debug]
|
|
[2022-01-24T15:48:26.978339+01:00] [debug] <<< testapi::check_screen(mustmatch="should_not_match", timeout=0)
|
|
[2022-01-24T15:48:26.978913+01:00] [info] ::: backend::baseclass::set_tags_to_assert: NO matching needles for should_not_match
|
|
[2022-01-24T15:48:27.587495+01:00] [debug] no match: -0.7s
|
|
[2022-01-24T15:48:27.737994+01:00] [debug] >>> testapi::_check_backend_response: match=should_not_match timed out after 0 (check_screen)
|
|
[2022-01-24T15:48:27.757093+01:00] [debug] ||| finished pre_boot tests (runtime: 1 s)
|
|
[2022-01-24T15:48:27.757970+01:00] [debug] ||| starting boot tests/boot.pm
|
|
[2022-01-24T15:48:27.758598+01:00] [debug] tests/boot.pm:9 called testapi::assert_screen
|
|
[2022-01-24T15:48:27.758726+01:00] [debug] <<< testapi::assert_screen(mustmatch="core", no_wait=1, timeout=15)
|
|
[2022-01-24T15:48:27.850876+01:00] [debug] >>> testapi::_handle_found_needle: found boot-core, similarity 0.97 @ 1/74
|
|
[2022-01-24T15:48:27.851115+01:00] [debug] tests/boot.pm:10 called testapi::send_key
|
|
[2022-01-24T15:48:27.851307+01:00] [debug] <<< testapi::send_key(key="ret", wait_screen_change=0, do_wait=0)
|
|
[2022-01-24T15:48:28.119570+01:00] [debug] tests/boot.pm:14 called testapi::assert_screen
|
|
[2022-01-24T15:48:28.119709+01:00] [debug] <<< testapi::assert_screen(mustmatch="on_prompt", timeout=90)
|
|
[2022-01-24T15:48:28.765907+01:00] [debug] no match: 89.3s, best candidate: boot-on_prompt (0.00)
|
|
[2022-01-24T15:48:29.762122+01:00] [debug] no match: 88.3s, best candidate: boot-on_prompt (0.00)
|
|
[2022-01-24T15:48:30.865935+01:00] [debug] >>> testapi::_handle_found_needle: found boot-on_prompt, similarity 1.00 @ 2/64
|
|
[2022-01-24T15:48:30.866447+01:00] [debug] ||| finished boot tests (runtime: 3 s)
|
|
[2022-01-24T15:48:30.867245+01:00] [debug] ||| starting assert_screen tests/assert_screen.pm
|
|
[2022-01-24T15:48:30.867820+01:00] [debug] tests/assert_screen.pm:9 called testapi::assert_screen
|
|
[2022-01-24T15:48:30.867943+01:00] [debug] <<< testapi::assert_screen(mustmatch="on_prompt", timeout=60)
|
|
[2022-01-24T15:48:31.862173+01:00] [debug] >>> testapi::_handle_found_needle: found boot-on_prompt, similarity 1.00 @ 2/64
|
|
[2022-01-24T15:48:31.862451+01:00] [debug] tests/assert_screen.pm:10 called testapi::assert_screen
|
|
[2022-01-24T15:48:31.862604+01:00] [debug] <<< testapi::assert_screen(mustmatch="on_prompt", no_wait=1, timeout=30)
|
|
[2022-01-24T15:48:31.937599+01:00] [debug] >>> testapi::_handle_found_needle: found boot-on_prompt, similarity 1.00 @ 2/64
|
|
[2022-01-24T15:48:31.938121+01:00] [debug] ||| finished assert_screen tests (runtime: 1 s)
|
|
[2022-01-24T15:48:31.939107+01:00] [debug] ||| starting typing tests/typing.pm
|
|
[2022-01-24T15:48:31.940054+01:00] [debug] tests/typing.pm:8 called testapi::assert_script_run
|
|
[2022-01-24T15:48:31.940223+01:00] [debug] <<< testapi::assert_script_run(cmd="cat /proc/cpuinfo", fail_message="", quiet=undef, timeout=90)
|
|
[2022-01-24T15:48:31.940442+01:00] [debug] tests/typing.pm:8 called testapi::assert_script_run
|
|
[2022-01-24T15:48:31.940612+01:00] [debug] <<< testapi::type_string(string="cat /proc/cpuinfo", max_interval=250, wait_screen_changes=0, wait_still_screen=0, timeout=30, similarity_level=47)
|
|
[2022-01-24T15:48:32.521073+01:00] [debug] tests/typing.pm:8 called testapi::assert_script_run
|
|
[2022-01-24T15:48:32.521558+01:00] [debug] <<< testapi::type_string(string="; echo X6MQS-\$?- > /dev/ttyS0\n", max_interval=250, wait_screen_changes=0, wait_still_screen=0, timeout=30, similarity_level=47)
|
|
[2022-01-24T15:48:33.678152+01:00] [debug] tests/typing.pm:8 called testapi::assert_script_run
|
|
[2022-01-24T15:48:33.678362+01:00] [debug] <<< testapi::wait_serial(timeout=90, buffer_size=undef, quiet=undef, record_output=undef, regexp=qr/X6MQS-\d+-/u, no_regex=0, expect_not_found=0)
|
|
[2022-01-24T15:48:34.767217+01:00] [debug] >>> testapi::wait_serial: (?^u:X6MQS-\d+-): ok
|
|
[2022-01-24T15:48:34.767394+01:00] [debug] tests/typing.pm:9 called testapi::type_string
|
|
[2022-01-24T15:48:34.767619+01:00] [debug] <<< testapi::type_string(string="cat > text <<EOF\n", max_interval=250, wait_screen_changes=0, wait_still_screen=0, timeout=30, similarity_level=47)
|
|
[2022-01-24T15:48:35.448772+01:00] [debug] tests/typing.pm:26 called testapi::type_string
|
|
[2022-01-24T15:48:35.449408+01:00] [debug] <<< testapi::type_string(string="==Description==\nBy default, a viewer/client uses TCP port 5900 to connect to a server (or 5800 for browser access), but can also be set to use any other port. Alternatively, a server can connect to a viewer in \"listening mode\" (by default on port 5500). One advantage of listening mode is that the server site does not have to configure its firewall/NAT to allow access on the specified ports; the burden is on the viewer, which is useful if the server site has no computer expertise, while the viewer user would be expected to be more knowledgeable.\n\nAlthough RFB started as a relatively simple protocol, it has been enhanced with additional features (such as file transfers) and more sophisticated [[Data compression|compression]] and security techniques as it has developed. To maintain seamless cross-compatibility between the many different VNC client and server implementations, the clients and servers negotiate a connection using the best RFB version, and the most appropriate compression and security options that they can both support.\n\n== History ==\n\nRFB was originally developed at [[Olivetti Research Laboratory]] (ORL) as a remote display technology to be used by a simple [[thin client]] with [[Asynchronous Transfer Mode|ATM]] connectivity called a Videotile. In order to keep the device as simple as possible, RFB was developed and used in preference to any of the existing remote display technologies.\n\nRFB found a second and more enduring use when VNC was developed. VNC was released as [[open source]] software and the RFB specification published on the web. Since then RFB has been a free protocol which anybody can use.\n\nWhen ORL was closed in 2002 some of the key people behind VNC and RFB formed [[RealVNC]], Ltd., in order to continue development of VNC and to maintain the RFB protocol. The current RFB protocol is published on the RealVNC website.\n", max_interval=250, wait_screen_changes=0, wait_still_screen=0, timeout=30, similarity_level=47)
|
|
[2022-01-24T15:49:41.132507+01:00] [debug] tests/typing.pm:27 called testapi::type_string
|
|
[2022-01-24T15:49:41.132844+01:00] [debug] <<< testapi::type_string(string="\nEOF\n", max_interval=250, wait_screen_changes=0, wait_still_screen=0, timeout=30, similarity_level=47)
|
|
[2022-01-24T15:49:41.354639+01:00] [debug] tests/typing.pm:28 called testapi::script_run
|
|
[2022-01-24T15:49:41.354993+01:00] [debug] <<< testapi::script_run(cmd="echo '924095f2cb4d622a8796de66a5e0a44a text' > text.md5", quiet=undef, die_on_timeout=-1, output="", timeout=30)
|
|
[2022-01-24T15:49:41.355181+01:00] [debug] tests/typing.pm:28 called testapi::script_run
|
|
[2022-01-24T15:49:41.355349+01:00] [debug] <<< testapi::type_string(string="echo '924095f2cb4d622a8796de66a5e0a44a text' > text.md5", max_interval=250, wait_screen_changes=0, wait_still_screen=0, timeout=30, similarity_level=47)
|
|
[2022-01-24T15:49:43.301458+01:00] [debug] tests/typing.pm:28 called testapi::script_run
|
|
[2022-01-24T15:49:43.301739+01:00] [debug] <<< testapi::type_string(string="; echo NZLuk-\$?- > /dev/ttyS0\n", max_interval=250, wait_screen_changes=0, wait_still_screen=0, timeout=30, similarity_level=47)
|
|
[2022-01-24T15:49:44.451878+01:00] [debug] tests/typing.pm:28 called testapi::script_run
|
|
[2022-01-24T15:49:44.452108+01:00] [debug] <<< testapi::wait_serial(expect_not_found=0, buffer_size=undef, timeout=30, no_regex=0, regexp=qr/NZLuk-\d+-/u, record_output=undef, quiet=undef)
|
|
[2022-01-24T15:49:45.535271+01:00] [debug] >>> testapi::wait_serial: (?^u:NZLuk-\d+-): ok
|
|
[2022-01-24T15:49:45.535437+01:00] [warn] !!! testapi::script_run: DEPRECATED call of script_run() in tests/typing.pm:28 add `die_on_timeout => ?` to the call or set
|
|
$distri->{script_run_die_on_timeout} to avoid this
|
|
warning
|
|
[2022-01-24T15:49:45.535570+01:00] [debug] tests/typing.pm:29 called testapi::assert_script_run
|
|
[2022-01-24T15:49:45.535722+01:00] [debug] <<< testapi::assert_script_run(cmd="md5sum -c text.md5", timeout=90, fail_message="", quiet=undef)
|
|
[2022-01-24T15:49:45.535837+01:00] [debug] tests/typing.pm:29 called testapi::assert_script_run
|
|
[2022-01-24T15:49:45.535976+01:00] [debug] <<< testapi::type_string(string="md5sum -c text.md5", max_interval=250, wait_screen_changes=0, wait_still_screen=0, timeout=30, similarity_level=47)
|
|
[2022-01-24T15:49:46.148308+01:00] [debug] tests/typing.pm:29 called testapi::assert_script_run
|
|
[2022-01-24T15:49:46.148578+01:00] [debug] <<< testapi::type_string(string="; echo 6i9D7-\$?- > /dev/ttyS0\n", max_interval=250, wait_screen_changes=0, wait_still_screen=0, timeout=30, similarity_level=47)
|
|
[2022-01-24T15:49:47.253543+01:00] [debug] tests/typing.pm:29 called testapi::assert_script_run
|
|
[2022-01-24T15:49:47.254214+01:00] [debug] <<< testapi::wait_serial(expect_not_found=0, buffer_size=undef, timeout=90, no_regex=0, quiet=undef, record_output=undef, regexp=qr/6i9D7-\d+-/u)
|
|
[2022-01-24T15:49:48.359843+01:00] [debug] >>> testapi::wait_serial: (?^u:6i9D7-\d+-): ok
|
|
[2022-01-24T15:49:48.360082+01:00] [debug] tests/typing.pm:32 called testapi::script_run
|
|
[2022-01-24T15:49:48.360301+01:00] [debug] <<< testapi::script_run(cmd="alias bash=sh", quiet=undef, output="", timeout=0, die_on_timeout=-1)
|
|
[2022-01-24T15:49:48.360454+01:00] [debug] tests/typing.pm:32 called testapi::script_run
|
|
[2022-01-24T15:49:48.360580+01:00] [debug] <<< testapi::type_string(string="alias bash=sh", max_interval=250, wait_screen_changes=0, wait_still_screen=0, timeout=30, similarity_level=47)
|
|
[2022-01-24T15:49:48.801430+01:00] [debug] tests/typing.pm:32 called testapi::script_run
|
|
[2022-01-24T15:49:48.801582+01:00] [debug] <<< testapi::send_key(key="ret", do_wait=0, wait_screen_change=0)
|
|
[2022-01-24T15:49:49.069872+01:00] [debug] tests/typing.pm:33 called testapi::script_output
|
|
[2022-01-24T15:49:49.070183+01:00] [debug] <<< testapi::type_string(string="cat - > /tmp/scriptQF9Xl.sh;", max_interval=250, wait_screen_changes=0, wait_still_screen=0, timeout=30, similarity_level=47)
|
|
[2022-01-24T15:49:50.092908+01:00] [debug] tests/typing.pm:33 called testapi::script_output
|
|
[2022-01-24T15:49:50.093149+01:00] [debug] <<< testapi::type_string(string="\n", max_interval=250, wait_screen_changes=0, wait_still_screen=0, timeout=30, similarity_level=47)
|
|
[2022-01-24T15:49:50.128036+01:00] [debug] tests/typing.pm:33 called testapi::script_output
|
|
[2022-01-24T15:49:50.128358+01:00] [debug] <<< testapi::type_string(string="mount\n", max_interval=250, wait_screen_changes=0, wait_still_screen=0, timeout=30, similarity_level=47)
|
|
[2022-01-24T15:49:50.333070+01:00] [debug] tests/typing.pm:33 called testapi::script_output
|
|
[2022-01-24T15:49:50.333344+01:00] [debug] <<< testapi::send_key(key="ctrl-d", do_wait=0, wait_screen_change=0)
|
|
[2022-01-24T15:49:50.669039+01:00] [debug] tests/typing.pm:33 called testapi::script_output
|
|
[2022-01-24T15:49:50.669446+01:00] [debug] <<< testapi::type_string(string="(echo QF9Xl; bash -eox pipefail /tmp/scriptQF9Xl.sh ; echo SCRIPT_FINISHEDQF9Xl-\$?-) | tee /dev/ttyS0\n", max_interval=250, wait_screen_changes=0, wait_still_screen=0, timeout=30, similarity_level=47)
|
|
[2022-01-24T15:49:54.643704+01:00] [debug] tests/typing.pm:33 called testapi::script_output
|
|
[2022-01-24T15:49:54.643981+01:00] [debug] <<< testapi::wait_serial(expect_not_found=0, buffer_size=undef, timeout=90, no_regex=0, regexp="SCRIPT_FINISHEDQF9Xl-\\d+-", quiet=undef, record_output=1)
|
|
[2022-01-24T15:49:55.727982+01:00] [debug] >>> testapi::wait_serial: SCRIPT_FINISHEDQF9Xl-\d+-: ok
|
|
[2022-01-24T15:49:55.728237+01:00] [debug] tests/typing.pm:38 called testapi::type_string
|
|
[2022-01-24T15:49:55.728411+01:00] [debug] <<< testapi::type_string(string="echo do not wait_still_screen\n", max_interval=50, wait_screen_changes=0, wait_still_screen=0, timeout=30, similarity_level=47)
|
|
[2022-01-24T15:50:01.170119+01:00] [debug] tests/typing.pm:39 called testapi::type_string
|
|
[2022-01-24T15:50:01.170448+01:00] [debug] <<< testapi::type_string(string="echo type string and wait for .2 seconds\n", max_interval=250, wait_screen_changes=0, wait_still_screen="0.2", timeout=30, similarity_level=47)
|
|
[2022-01-24T15:50:02.571194+01:00] [debug] tests/typing.pm:39 called testapi::type_string
|
|
[2022-01-24T15:50:02.571496+01:00] [debug] <<< testapi::wait_still_screen(similarity_level=47, stilltime="0.2", timeout=30)
|
|
[2022-01-24T15:50:03.581571+01:00] [debug] >>> testapi::wait_still_screen: detected same image for 0.2 seconds, last detected similarity is 50.028504689842
|
|
[2022-01-24T15:50:03.581772+01:00] [debug] tests/typing.pm:40 called testapi::type_string
|
|
[2022-01-24T15:50:03.582006+01:00] [debug] <<< testapi::type_string(string="echo test\necho wait\necho 1se\n", max_interval=100, wait_screen_changes=0, wait_still_screen=1, timeout=30, similarity_level=47)
|
|
[2022-01-24T15:50:07.476171+01:00] [debug] tests/typing.pm:40 called testapi::type_string
|
|
[2022-01-24T15:50:07.476675+01:00] [debug] <<< testapi::wait_still_screen(similarity_level=47, timeout=30, stilltime=1)
|
|
[2022-01-24T15:50:08.991937+01:00] [debug] >>> testapi::wait_still_screen: detected same image for 1 seconds, last detected similarity is 50.028504689842
|
|
[2022-01-24T15:50:08.992182+01:00] [debug] tests/typing.pm:41 called testapi::type_string
|
|
[2022-01-24T15:50:08.992477+01:00] [debug] <<< testapi::type_string(string="echo test if wait_screen_change functions as expected\n", max_interval=150, wait_screen_changes=0, wait_still_screen=1, timeout=30, similarity_level=47)
|
|
[2022-01-24T15:50:15.365424+01:00] [debug] tests/typing.pm:41 called testapi::type_string
|
|
[2022-01-24T15:50:15.365647+01:00] [debug] <<< testapi::wait_still_screen(timeout=30, stilltime=1, similarity_level=47)
|
|
[2022-01-24T15:50:16.889038+01:00] [debug] >>> testapi::wait_still_screen: detected same image for 1 seconds, last detected similarity is 50.028504689842
|
|
[2022-01-24T15:50:16.889281+01:00] [debug] tests/typing.pm:42 called testapi::type_string
|
|
[2022-01-24T15:50:16.889660+01:00] [debug] <<< testapi::type_string(string="echo wait_still_screen for .1 seconds\n", max_interval=200, wait_screen_changes=0, wait_still_screen="0.1", timeout=30, similarity_level=47)
|
|
[2022-01-24T15:50:20.976166+01:00] [debug] tests/typing.pm:42 called testapi::type_string
|
|
[2022-01-24T15:50:20.976663+01:00] [debug] <<< testapi::wait_still_screen(stilltime="0.1", timeout=30, similarity_level=47)
|
|
[2022-01-24T15:50:22.501237+01:00] [debug] >>> testapi::wait_still_screen: detected same image for 0.1 seconds, last detected similarity is 1000000
|
|
[2022-01-24T15:50:22.501757+01:00] [debug] tests/typing.pm:43 called testapi::type_string
|
|
[2022-01-24T15:50:22.502061+01:00] [debug] <<< testapi::type_string(string="echo 'ignore \\r'\r\n", max_interval=250, wait_screen_changes=0, wait_still_screen=0, timeout=30, similarity_level=47)
|
|
[2022-01-24T15:50:23.082061+01:00] [debug] ||| finished typing tests (runtime: 112 s)
|
|
[2022-01-24T15:50:23.083067+01:00] [debug] ||| starting select_console_fail_test tests/select_console_fail_test.pm
|
|
[2022-01-24T15:50:23.083829+01:00] [debug] tests/select_console_fail_test.pm:8 called testapi::select_console
|
|
[2022-01-24T15:50:23.083959+01:00] [debug] <<< testapi::select_console(testapi_console="brokenvnc")
|
|
[2022-01-24T15:50:23.084530+01:00] [debug] Establishing VNC connection to novnc.nowhere:5901
|
|
[2022-01-24T15:50:25.272757+01:00] [warn] !!! consoles::VNC::login: Error connecting to VNC server <novnc.nowhere:5901>: IO::Socket::INET: Bad hostname 'novnc.nowhere'
|
|
[2022-01-24T15:50:26.336843+01:00] [warn] !!! consoles::VNC::login: Error connecting to VNC server <novnc.nowhere:5901>: IO::Socket::INET: Bad hostname 'novnc.nowhere'
|
|
[2022-01-24T15:50:27.401243+01:00] [warn] !!! consoles::VNC::login: Error connecting to VNC server <novnc.nowhere:5901>: IO::Socket::INET: Bad hostname 'novnc.nowhere'
|
|
[2022-01-24T15:50:28.464294+01:00] [warn] !!! consoles::VNC::login: Error connecting to VNC server <novnc.nowhere:5901>: IO::Socket::INET: Bad hostname 'novnc.nowhere'
|
|
[2022-01-24T15:50:29.534189+01:00] [warn] !!! consoles::VNC::login: Error connecting to VNC server <novnc.nowhere:5901>: IO::Socket::INET: Bad hostname 'novnc.nowhere'
|
|
[2022-01-24T15:50:30.599023+01:00] [warn] !!! consoles::VNC::login: Error connecting to VNC server <novnc.nowhere:5901>: IO::Socket::INET: Bad hostname 'novnc.nowhere'
|
|
[2022-01-24T15:50:31.662373+01:00] [warn] !!! consoles::VNC::login: Error connecting to VNC server <novnc.nowhere:5901>: IO::Socket::INET: Bad hostname 'novnc.nowhere'
|
|
[2022-01-24T15:50:32.724521+01:00] [warn] !!! consoles::VNC::login: Error connecting to VNC server <novnc.nowhere:5901>: IO::Socket::INET: Bad hostname 'novnc.nowhere'
|
|
[2022-01-24T15:50:33.889204+01:00] [info] ::: basetest::runtest: # Test died: Error connecting to VNC server <novnc.nowhere:5901>: IO::Socket::INET: Bad hostname 'novnc.nowhere' at /hdd/openqa-devel/repos/os-autoinst/t/../testapi.pm line 1762.
|
|
|
|
[2022-01-24T15:50:33.890664+01:00] [debug] ||| finished select_console_fail_test tests (runtime: 10 s)
|
|
[2022-01-24T15:50:33.890763+01:00] [debug] ||| post fail hooks runtime: 0 s
|
|
[2022-01-24T15:50:33.891094+01:00] [debug] ||| starting select_ssh_console_fail_test tests/select_ssh_console_fail_test.pm
|
|
[2022-01-24T15:50:33.891815+01:00] [debug] tests/select_ssh_console_fail_test.pm:8 called testapi::select_console
|
|
[2022-01-24T15:50:33.891918+01:00] [debug] <<< testapi::select_console(testapi_console="brokeniucv")
|
|
[2022-01-24T15:50:33.892667+01:00] [debug] <<< backend::baseclass::new_ssh_connection(username="root", hostname="noIucvconn.nowhere", password=undef)
|
|
[2022-01-24T15:50:33.959022+01:00] [debug] Could not connect to root@noIucvconn.nowhere, Retrying after some seconds...
|
|
[2022-01-24T15:50:34.021122+01:00] [debug] Could not connect to root@noIucvconn.nowhere, Retrying after some seconds...
|
|
[2022-01-24T15:50:34.050722+01:00] [debug] considering VNC stalled, no update for 11.02 seconds
|
|
[2022-01-24T15:50:34.102072+01:00] [info] ::: basetest::runtest: # Test died: Error connecting to <root@noIucvconn.nowhere>: Name or service not known at /hdd/openqa-devel/repos/os-autoinst/t/../testapi.pm line 1762.
|
|
|
|
[2022-01-24T15:50:34.104912+01:00] [debug] ||| finished select_ssh_console_fail_test tests (runtime: 1 s)
|
|
[2022-01-24T15:50:34.105025+01:00] [debug] ||| post fail hooks runtime: 0 s
|
|
[2022-01-24T15:50:34.105361+01:00] [debug] ||| starting assert_screen_fail_test tests/assert_screen_fail_test.pm
|
|
[2022-01-24T15:50:34.106153+01:00] [debug] tests/assert_screen_fail_test.pm:9 called (eval) -> tests/assert_screen_fail_test.pm:9 called testapi::assert_screen
|
|
[2022-01-24T15:50:34.106304+01:00] [debug] <<< testapi::assert_screen(mustmatch=[
|
|
"no_tag",
|
|
"no_tag2"
|
|
], no_wait=1, timeout=1)
|
|
[2022-01-24T15:50:34.106953+01:00] [info] ::: backend::baseclass::set_tags_to_assert: NO matching needles for no_tag,no_tag2
|
|
[2022-01-24T15:50:34.107422+01:00] [debug] no match: 0.9s
|
|
[2022-01-24T15:50:34.208365+01:00] [debug] no change: 0.8s
|
|
[2022-01-24T15:50:34.290314+01:00] [debug] pointer type 0 0 720 400 -257
|
|
[2022-01-24T15:50:34.290458+01:00] [debug] led state 0 1 1 -261
|
|
[2022-01-24T15:50:34.309063+01:00] [debug] no change: 0.7s
|
|
[2022-01-24T15:50:34.410474+01:00] [debug] no change: 0.6s
|
|
[2022-01-24T15:50:34.511690+01:00] [debug] no change: 0.5s
|
|
[2022-01-24T15:50:34.612464+01:00] [debug] no change: 0.4s
|
|
[2022-01-24T15:50:34.713209+01:00] [debug] no change: 0.3s
|
|
[2022-01-24T15:50:34.813919+01:00] [debug] no match: 0.2s
|
|
[2022-01-24T15:50:34.915743+01:00] [debug] no change: 0.1s
|
|
[2022-01-24T15:50:35.016732+01:00] [debug] no change: 0.0s
|
|
[2022-01-24T15:50:35.117705+01:00] [debug] no match: -0.1s
|
|
[2022-01-24T15:50:35.414859+01:00] [debug] >>> testapi::_check_backend_response: match=no_tag,no_tag2 timed out after 1 (assert_screen)
|
|
[2022-01-24T15:50:35.491410+01:00] [debug] no candidate needle with tag(s) 'no_tag, no_tag2' matched
|
|
[2022-01-24T15:50:35.491605+01:00] [debug] tests/assert_screen_fail_test.pm:12 called (eval) -> tests/assert_screen_fail_test.pm:12 called testapi::assert_screen
|
|
[2022-01-24T15:50:35.491773+01:00] [debug] <<< testapi::assert_screen(mustmatch="no_tag3", timeout=1, no_wait=1)
|
|
[2022-01-24T15:50:35.492473+01:00] [info] ::: backend::baseclass::set_tags_to_assert: NO matching needles for no_tag3
|
|
[2022-01-24T15:50:35.493149+01:00] [debug] no match: 0.9s
|
|
[2022-01-24T15:50:35.593967+01:00] [debug] no change: 0.8s
|
|
[2022-01-24T15:50:35.695016+01:00] [debug] no change: 0.7s
|
|
[2022-01-24T15:50:35.796637+01:00] [debug] no change: 0.6s
|
|
[2022-01-24T15:50:35.897550+01:00] [debug] no change: 0.5s
|
|
[2022-01-24T15:50:35.998272+01:00] [debug] no change: 0.4s
|
|
[2022-01-24T15:50:36.098981+01:00] [debug] no change: 0.3s
|
|
[2022-01-24T15:50:36.200340+01:00] [debug] no change: 0.2s
|
|
[2022-01-24T15:50:36.301453+01:00] [debug] no match: 0.1s
|
|
[2022-01-24T15:50:36.403881+01:00] [debug] no change: 0.0s
|
|
[2022-01-24T15:50:36.504577+01:00] [debug] no match: -0.1s
|
|
[2022-01-24T15:50:36.684304+01:00] [debug] >>> testapi::_check_backend_response: match=no_tag3 timed out after 1 (assert_screen)
|
|
[2022-01-24T15:50:36.722594+01:00] [debug] no candidate needle with tag(s) 'no_tag3' matched
|
|
[2022-01-24T15:50:36.724297+01:00] [debug] ||| finished assert_screen_fail_test tests (runtime: 2 s)
|
|
[2022-01-24T15:50:36.724356+01:00] [debug] ||| post fail hooks runtime: 0 s
|
|
[2022-01-24T15:50:36.724559+01:00] [debug] test assert_screen_fail_test failed
|
|
|
|
[2022-01-24T15:50:36.724620+01:00] [debug] ||| starting reload_needles tests/reload_needles.pm
|
|
[2022-01-24T15:50:36.725289+01:00] [debug] tests/reload_needles.pm:10 called testapi::type_string
|
|
[2022-01-24T15:50:36.725524+01:00] [debug] <<< testapi::type_string(string="echo HALLO\n", max_interval=250, wait_screen_changes=0, wait_still_screen=0, timeout=30, similarity_level=47)
|
|
[2022-01-24T15:50:37.186652+01:00] [debug] tests/reload_needles.pm:11 called testapi::assert_screen
|
|
[2022-01-24T15:50:37.186871+01:00] [debug] <<< testapi::assert_screen(mustmatch="no-importa", timeout=30)
|
|
[2022-01-24T15:50:37.512173+01:00] [debug] no match: 29.6s, best candidate: no-importa-v1 (0.00)
|
|
[2022-01-24T15:50:38.508090+01:00] [debug] no match: 28.6s, best candidate: no-importa-v1 (0.96)
|
|
[2022-01-24T15:50:39.513383+01:00] [debug] no match: 27.6s, best candidate: no-importa-v1 (0.96)
|
|
[2022-01-24T15:50:40.510740+01:00] [debug] no match: 26.6s, best candidate: no-importa-v1 (0.96)
|
|
[2022-01-24T15:50:41.559698+01:00] [debug] no match: 25.6s, best candidate: no-importa-v1 (0.96)
|
|
[2022-01-24T15:50:42.513864+01:00] [debug] no match: 24.6s, best candidate: no-importa-v1 (0.96)
|
|
[2022-01-24T15:50:43.512978+01:00] [debug] no match: 23.6s, best candidate: no-importa-v1 (0.96)
|
|
[2022-01-24T15:50:44.517906+01:00] [debug] no match: 22.6s, best candidate: no-importa-v1 (0.96)
|
|
[2022-01-24T15:50:45.517104+01:00] [debug] no match: 21.6s, best candidate: no-importa-v1 (0.96)
|
|
[2022-01-24T15:50:46.560955+01:00] [debug] no match: 20.6s, best candidate: no-importa-v1 (0.96)
|
|
[2022-01-24T15:50:47.518995+01:00] [debug] no match: 19.6s, best candidate: no-importa-v1 (0.96)
|
|
[2022-01-24T15:50:48.517875+01:00] [debug] no match: 18.6s, best candidate: no-importa-v1 (0.96)
|
|
[2022-01-24T15:50:49.520084+01:00] [debug] no match: 17.6s, best candidate: no-importa-v1 (0.96)
|
|
[2022-01-24T15:50:50.520270+01:00] [debug] no match: 16.6s, best candidate: no-importa-v1 (0.96)
|
|
[2022-01-24T15:50:51.617159+01:00] [debug] no match: 15.6s, best candidate: no-importa-v1 (0.96)
|
|
[2022-01-24T15:50:52.525967+01:00] [debug] no match: 14.6s, best candidate: no-importa-v1 (0.96)
|
|
[2022-01-24T15:50:53.526620+01:00] [debug] no match: 13.6s, best candidate: no-importa-v1 (0.96)
|
|
[2022-01-24T15:50:54.524127+01:00] [debug] no match: 12.6s, best candidate: no-importa-v1 (0.96)
|
|
[2022-01-24T15:50:55.525911+01:00] [debug] no match: 11.6s, best candidate: no-importa-v1 (0.96)
|
|
[2022-01-24T15:50:56.577688+01:00] [debug] no match: 10.6s, best candidate: no-importa-v1 (0.96)
|
|
[2022-01-24T15:50:57.531396+01:00] [debug] no match: 9.6s, best candidate: no-importa-v1 (0.96)
|
|
[2022-01-24T15:50:58.530017+01:00] [debug] no match: 8.6s, best candidate: no-importa-v1 (0.96)
|
|
[2022-01-24T15:50:59.529814+01:00] [debug] no match: 7.6s, best candidate: no-importa-v1 (0.96)
|
|
[2022-01-24T15:51:00.533565+01:00] [debug] no match: 6.6s, best candidate: no-importa-v1 (0.96)
|
|
[2022-01-24T15:51:01.584016+01:00] [debug] no match: 5.6s, best candidate: no-importa-v1 (0.96)
|
|
[2022-01-24T15:51:02.532182+01:00] [debug] no match: 4.6s, best candidate: no-importa-v1 (0.96)
|
|
[2022-01-24T15:51:03.536653+01:00] [debug] no match: 3.6s, best candidate: no-importa-v1 (0.96)
|
|
[2022-01-24T15:51:04.537849+01:00] [debug] no match: 2.6s, best candidate: no-importa-v1 (0.96)
|
|
[2022-01-24T15:51:05.538912+01:00] [debug] no match: 1.6s, best candidate: no-importa-v1 (0.96)
|
|
[2022-01-24T15:51:06.581123+01:00] [debug] no match: 0.6s, best candidate: no-importa-v1 (0.96)
|
|
[2022-01-24T15:51:07.586327+01:00] [debug] no match: -0.4s, best candidate: no-importa-v1 (0.96)
|
|
[2022-01-24T15:51:07.761684+01:00] [debug] >>> testapi::_check_backend_response: match=no-importa timed out after 30 (assert_screen)
|
|
[2022-01-24T15:51:07.799706+01:00] [info] ::: basetest::runtest: # Test died: no candidate needle with tag(s) 'no-importa' matched
|
|
[2022-01-24T15:51:07.801392+01:00] [debug] ||| finished reload_needles tests (runtime: 31 s)
|
|
[2022-01-24T15:51:07.801473+01:00] [debug] ||| post fail hooks runtime: 0 s
|
|
[2022-01-24T15:51:07.801775+01:00] [debug] ||| starting modify_and_upload_file tests/modify_and_upload_file.pm
|
|
[2022-01-24T15:51:07.802476+01:00] [debug] tests/modify_and_upload_file.pm:23 called testapi::get_test_data
|
|
[2022-01-24T15:51:07.802608+01:00] [debug] <<< testapi::get_test_data(path="/hdd/openqa-devel/repos/os-autoinst/t/data//tests/data/autoinst.xml")
|
|
[2022-01-24T15:51:07.804132+01:00] [debug] tests/modify_and_upload_file.pm:25 called testapi::type_string
|
|
[2022-01-24T15:51:07.804329+01:00] [debug] <<< testapi::type_string(string="echo get_test_data returned expected file\n", max_interval=250, wait_screen_changes=0, wait_still_screen=0, timeout=30, similarity_level=47)
|
|
[2022-01-24T15:51:09.266877+01:00] [debug] tests/modify_and_upload_file.pm:30 called testapi::save_tmp_file
|
|
[2022-01-24T15:51:09.267019+01:00] [debug] <<< testapi::save_tmp_file(path="modified.xml")
|
|
[2022-01-24T15:51:09.267283+01:00] [debug] tests/modify_and_upload_file.pm:32 called testapi::assert_script_run
|
|
[2022-01-24T15:51:09.267462+01:00] [debug] <<< testapi::assert_script_run(cmd="wget -q http://10.0.2.2:15223/yUWgUjfTeq/files/modified.xml", fail_message="", quiet=undef, timeout=90)
|
|
[2022-01-24T15:51:09.267618+01:00] [debug] tests/modify_and_upload_file.pm:32 called testapi::assert_script_run
|
|
[2022-01-24T15:51:09.267810+01:00] [debug] <<< testapi::type_string(string="wget -q http://10.0.2.2:15223/yUWgUjfTeq/files/modified.xml", max_interval=250, wait_screen_changes=0, wait_still_screen=0, timeout=30, similarity_level=47)
|
|
[2022-01-24T15:51:11.379808+01:00] [debug] tests/modify_and_upload_file.pm:32 called testapi::assert_script_run
|
|
[2022-01-24T15:51:11.380212+01:00] [debug] <<< testapi::type_string(string="; echo YhZFh-\$?- > /dev/ttyS0\n", max_interval=250, wait_screen_changes=0, wait_still_screen=0, timeout=30, similarity_level=47)
|
|
[2022-01-24T15:51:12.530347+01:00] [debug] tests/modify_and_upload_file.pm:32 called testapi::assert_script_run
|
|
[2022-01-24T15:51:12.530573+01:00] [debug] <<< testapi::wait_serial(no_regex=0, quiet=undef, record_output=undef, regexp=qr/YhZFh-\d+-/u, buffer_size=undef, timeout=90, expect_not_found=0)
|
|
[2022-01-24T15:51:13.616350+01:00] [debug] >>> testapi::wait_serial: (?^u:YhZFh-\d+-): ok
|
|
[2022-01-24T15:51:13.616547+01:00] [debug] tests/modify_and_upload_file.pm:33 called testapi::script_run
|
|
[2022-01-24T15:51:13.616701+01:00] [debug] <<< testapi::script_run(cmd="echo '72d2c15cb10535f36862d7d2eecc8a79 modified.xml' > modified.md5", output="", timeout=30, die_on_timeout=-1, quiet=undef)
|
|
[2022-01-24T15:51:13.616808+01:00] [debug] tests/modify_and_upload_file.pm:33 called testapi::script_run
|
|
[2022-01-24T15:51:13.616924+01:00] [debug] <<< testapi::type_string(string="echo '72d2c15cb10535f36862d7d2eecc8a79 modified.xml' > modified.md5", max_interval=250, wait_screen_changes=0, wait_still_screen=0, timeout=30, similarity_level=47)
|
|
[2022-01-24T15:51:15.941470+01:00] [debug] tests/modify_and_upload_file.pm:33 called testapi::script_run
|
|
[2022-01-24T15:51:15.941677+01:00] [debug] <<< testapi::type_string(string="; echo ~liyM-\$?- > /dev/ttyS0\n", max_interval=250, wait_screen_changes=0, wait_still_screen=0, timeout=30, similarity_level=47)
|
|
[2022-01-24T15:51:17.062060+01:00] [debug] tests/modify_and_upload_file.pm:33 called testapi::script_run
|
|
[2022-01-24T15:51:17.062257+01:00] [debug] <<< testapi::wait_serial(expect_not_found=0, timeout=30, buffer_size=undef, regexp=qr/~liyM-\d+-/u, quiet=undef, record_output=undef, no_regex=0)
|
|
[2022-01-24T15:51:18.161743+01:00] [debug] >>> testapi::wait_serial: (?^u:~liyM-\d+-): ok
|
|
[2022-01-24T15:51:18.161905+01:00] [warn] !!! testapi::script_run: DEPRECATED call of script_run() in tests/modify_and_upload_file.pm:33 add `die_on_timeout => ?` to the call or set
|
|
$distri->{script_run_die_on_timeout} to avoid this
|
|
warning
|
|
[2022-01-24T15:51:18.162039+01:00] [debug] tests/modify_and_upload_file.pm:34 called testapi::assert_script_run
|
|
[2022-01-24T15:51:18.162237+01:00] [debug] <<< testapi::assert_script_run(cmd="md5sum -c modified.md5", quiet=undef, fail_message="", timeout=90)
|
|
[2022-01-24T15:51:18.162406+01:00] [debug] tests/modify_and_upload_file.pm:34 called testapi::assert_script_run
|
|
[2022-01-24T15:51:18.162553+01:00] [debug] <<< testapi::type_string(string="md5sum -c modified.md5", max_interval=250, wait_screen_changes=0, wait_still_screen=0, timeout=30, similarity_level=47)
|
|
[2022-01-24T15:51:18.911574+01:00] [debug] tests/modify_and_upload_file.pm:34 called testapi::assert_script_run
|
|
[2022-01-24T15:51:18.912052+01:00] [debug] <<< testapi::type_string(string="; echo ib~GQ-\$?- > /dev/ttyS0\n", max_interval=250, wait_screen_changes=0, wait_still_screen=0, timeout=30, similarity_level=47)
|
|
[2022-01-24T15:51:20.051475+01:00] [debug] tests/modify_and_upload_file.pm:34 called testapi::assert_script_run
|
|
[2022-01-24T15:51:20.051735+01:00] [debug] <<< testapi::wait_serial(expect_not_found=0, timeout=90, buffer_size=undef, regexp=qr/ib~GQ-\d+-/u, record_output=undef, quiet=undef, no_regex=0)
|
|
[2022-01-24T15:51:21.146899+01:00] [debug] >>> testapi::wait_serial: (?^u:ib~GQ-\d+-): ok
|
|
[2022-01-24T15:51:21.147141+01:00] [debug] tests/modify_and_upload_file.pm:36 called testapi::type_string
|
|
[2022-01-24T15:51:21.147364+01:00] [debug] <<< testapi::type_string(string="echo save_tmp_file returned expected file\n", max_interval=250, wait_screen_changes=0, wait_still_screen=0, timeout=30, similarity_level=47)
|
|
[2022-01-24T15:51:22.608135+01:00] [debug] ||| finished modify_and_upload_file tests (runtime: 15 s)
|
|
[2022-01-24T15:51:22.609128+01:00] [debug] ||| starting shutdown tests/shutdown.pm
|
|
[2022-01-24T15:51:22.609861+01:00] [debug] tests/shutdown.pm:8 called testapi::type_string
|
|
[2022-01-24T15:51:22.610069+01:00] [debug] <<< testapi::type_string(string="sudo su\n", max_interval=250, wait_screen_changes=0, wait_still_screen=0, timeout=30, similarity_level=47)
|
|
[2022-01-24T15:51:22.883400+01:00] [debug] tests/shutdown.pm:9 called testapi::type_string
|
|
[2022-01-24T15:51:22.883963+01:00] [debug] <<< testapi::type_string(string="poweroff\n", max_interval=250, wait_screen_changes=0, wait_still_screen=0, timeout=30, similarity_level=47)
|
|
[2022-01-24T15:51:23.193734+01:00] [debug] tests/shutdown.pm:10 called testapi::assert_shutdown
|
|
[2022-01-24T15:51:23.193862+01:00] [debug] <<< testapi::check_shutdown(timeout=60)
|
|
[2022-01-24T15:51:23.194459+01:00] [debug] EVENT {"data":{"path":"\/machine\/peripheral-anon\/device[2]\/virtio-backend"},"event":"NIC_RX_FILTER_CHANGED","timestamp":{"microseconds":87928,"seconds":1643035710}}
|
|
[2022-01-24T15:51:23.194651+01:00] [debug] EVENT {"data":{"client":{"family":"ipv4","host":"127.0.0.1","service":"41410","websocket":false},"server":{"auth":"none","family":"ipv4","host":"0.0.0.0","service":"5990","websocket":false}},"event":"VNC_DISCONNECTED","timestamp":{"microseconds":51006,"seconds":1643035834}}
|
|
[2022-01-24T15:51:23.194823+01:00] [debug] EVENT {"data":{"client":{"family":"ipv4","host":"127.0.0.1","service":"41412","websocket":false},"server":{"auth":"none","family":"ipv4","host":"0.0.0.0","service":"5990","websocket":false}},"event":"VNC_CONNECTED","timestamp":{"microseconds":51181,"seconds":1643035834}}
|
|
[2022-01-24T15:51:23.194943+01:00] [debug] EVENT {"data":{"client":{"family":"ipv4","host":"127.0.0.1","service":"41412","websocket":false},"server":{"auth":"none","family":"ipv4","host":"0.0.0.0","service":"5990","websocket":false}},"event":"VNC_INITIALIZED","timestamp":{"microseconds":52004,"seconds":1643035834}}
|
|
[2022-01-24T15:51:23.195091+01:00] [debug] QEMU status is not 'shutdown', it is 'running'
|
|
[2022-01-24T15:51:24.197142+01:00] [debug] QEMU status is not 'shutdown', it is 'running'
|
|
[2022-01-24T15:51:25.200087+01:00] [debug] QEMU status is not 'shutdown', it is 'running'
|
|
[2022-01-24T15:51:26.202592+01:00] [debug] QEMU status is not 'shutdown', it is 'running'
|
|
[2022-01-24T15:51:27.205630+01:00] [debug] QEMU status is not 'shutdown', it is 'running'
|
|
[2022-01-24T15:51:28.207454+01:00] [debug] EVENT {"data":{"guest":true,"reason":"guest-shutdown"},"event":"SHUTDOWN","timestamp":{"microseconds":224340,"seconds":1643035887}}
|
|
[2022-01-24T15:51:28.207724+01:00] [debug] EVENT {"event":"STOP","timestamp":{"microseconds":227849,"seconds":1643035887}}
|
|
[2022-01-24T15:51:28.303259+01:00] [debug] ||| finished shutdown tests (runtime: 6 s)
|
|
[2022-01-24T15:51:28.304626+01:00] [debug] stopping autotest process 10443
|
|
[2022-01-24T15:51:28.309868+01:00] [debug] [autotest] process exited: 0
|
|
[2022-01-24T15:51:28.410393+01:00] [debug] done with autotest process
|
|
[2022-01-24T15:51:28.411224+01:00] [debug] stopping command server 10440 because test execution ended
|
|
[2022-01-24T15:51:28.411371+01:00] [debug] isotovideo: informing websocket clients before stopping command server: http://127.0.0.1:15223/yUWgUjfTeq/broadcast
|
|
[2022-01-24T15:51:28.428171+01:00] [debug] commands process exited: 0
|
|
[2022-01-24T15:51:28.528683+01:00] [debug] done with command server
|
|
[2022-01-24T15:51:28.528756+01:00] [debug] isotovideo done
|
|
[2022-01-24T15:51:28.529599+01:00] [debug] backend shutdown state: 1
|
|
[2022-01-24T15:51:28.529997+01:00] [info] ::: OpenQA::Qemu::Proc::save_state: Saving QEMU state to qemu_state.json
|
|
[2022-01-24T15:51:29.583666+01:00] [debug] Passing remaining frames to the video encoder
|
|
[2022-01-24T15:51:29.622076+01:00] [debug] Waiting for video encoder to finalize the video
|
|
[2022-01-24T15:51:29.622185+01:00] [debug] The built-in video encoder (pid 10471) terminated
|
|
[2022-01-24T15:51:29.622880+01:00] [debug] QEMU: qemu-system-i386: terminating on signal 15 from pid 10457 (/hdd/openqa-devel/repos/os-autoinst/t/../isotovideo: backen)
|
|
[2022-01-24T15:51:29.623675+01:00] [debug] sending magic and exit
|
|
[2022-01-24T15:51:29.623899+01:00] [debug] received magic close
|
|
[2022-01-24T15:51:29.631831+01:00] [debug] backend process exited: 0
|
|
[2022-01-24T15:51:29.733633+01:00] [debug] stopping backend process 10457
|
|
[2022-01-24T15:51:29.733863+01:00] [debug] done with backend process
|
|
10435: EXIT 0
|
|
ok 1 - test executed fine
|
|
ok 2 - Snapshots are enabled
|
|
ok 3 - Tests did not fail within modules
|
|
ok 4 - test type string and do not wait
|
|
ok 5 - test type string and wait for .2 seconds
|
|
ok 6 - test type string and wait for 1 seconds
|
|
ok 7 - test type string and wait for .1 seconds
|
|
ok 8 - Machine properly paused
|
|
ok 9 - Machine properly resumed
|
|
ok 10 - get_test_data test
|
|
ok 11 - save_tmp_file test
|
|
ok 12 - No warning about expected termination
|
|
ok 13 - Result in testresults/result-assert_screen.json is ok
|
|
ok 14 - Result in testresults/result-boot.json is ok
|
|
ok 15 - Result in testresults/result-freeze.json is ok
|
|
ok 16 - Result in testresults/result-modify_and_upload_file.json is ok
|
|
ok 17 - Result in testresults/result-pre_boot.json is ok
|
|
not ok 18 - Result in testresults/result-reload_needles.json is ok
|
|
|
|
# Failed test 'Result in testresults/result-reload_needles.json is ok'
|
|
# at t/99-full-stack.t line 68.
|
|
# got: 'fail'
|
|
# expected: 'ok'
|
|
Bailout called. Further testing stopped: testresults/result-reload_needles.json failed
|
|
Bail out! testresults/result-reload_needles.json failed
|
|
FAILED--Further testing stopped: testresults/result-reload_needles.json failed
|
|
FAILED: CMakeFiles/test-perl-testsuite /hdd/openqa-devel/build/os-autoinst-ninja/CMakeFiles/test-perl-testsuite
|
|
cd /hdd/openqa-devel/repos/os-autoinst && /hdd/openqa-devel/repos/os-autoinst/tools/invoke-tests --prove-tool /usr/bin/prove --make-tool /usr/bin/ninja --build-directory /hdd/openqa-devel/build/os-autoinst-ninja
|
|
ninja: build stopped: subcommand failed.
|
|
## count_fail_ratio: Run: 7. Fails: 1. Fail ratio 14%
|
|
## Run 8
|
|
Build directory: /hdd/openqa-devel/build/os-autoinst-ninja
|
|
[1/2] cd /hdd/openqa-devel/repos/os-autoinst && /hdd/openqa-devel/repos/os-autoinst/tools/invoke-tests --prove-tool /usr/bin/prove --make-tool /usr/bin/ninja --build-directory /hdd/openqa-devel/build/os-autoinst-ninja
|
|
t/99-full-stack.t ..
|
|
# data dir: /hdd/openqa-devel/repos/os-autoinst/t/data/
|
|
# pool dir: /tmp/99-full-stack.t-1ia6/pool/
|
|
[2022-01-24T15:51:30.595019+01:00] [debug] Current version is 7ef72e209567425123d4311781f3024f52d88f3a [interface v24]
|
|
[2022-01-24T15:51:30.604794+01:00] [debug] git hash in /hdd/openqa-devel/repos/os-autoinst/t/data//tests: 7ef72e209567425123d4311781f3024f52d88f3a
|
|
[2022-01-24T15:51:30.680149+01:00] [debug] scheduling freeze tests/freeze.pm
|
|
[2022-01-24T15:51:30.684418+01:00] [debug] scheduling pre_boot tests/pre_boot.py
|
|
[2022-01-24T15:51:30.685117+01:00] [debug] scheduling boot tests/boot.pm
|
|
[2022-01-24T15:51:30.685707+01:00] [debug] scheduling assert_screen tests/assert_screen.pm
|
|
[2022-01-24T15:51:30.686571+01:00] [debug] scheduling typing tests/typing.pm
|
|
[2022-01-24T15:51:30.687195+01:00] [debug] scheduling select_console_fail_test tests/select_console_fail_test.pm
|
|
[2022-01-24T15:51:30.687780+01:00] [debug] scheduling select_ssh_console_fail_test tests/select_ssh_console_fail_test.pm
|
|
[2022-01-24T15:51:30.688481+01:00] [debug] scheduling assert_screen_fail_test tests/assert_screen_fail_test.pm
|
|
[2022-01-24T15:51:30.689171+01:00] [debug] scheduling reload_needles tests/reload_needles.pm
|
|
[2022-01-24T15:51:30.689861+01:00] [debug] scheduling modify_and_upload_file tests/modify_and_upload_file.pm
|
|
[2022-01-24T15:51:30.690535+01:00] [debug] scheduling shutdown tests/shutdown.pm
|
|
[2022-01-24T15:51:30.697917+01:00] [info] cmdsrv: daemon reachable under http://*:15223/LSeWDgmwis/
|
|
[2022-01-24T15:51:30.699954+01:00] [info] Listening at "http://[::]:15223"
|
|
Web application available at http://[::]:15223
|
|
[2022-01-24T15:51:30.701214+01:00] [debug] git hash in /hdd/openqa-devel/repos/os-autoinst/t/data//tests/needles: 7ef72e209567425123d4311781f3024f52d88f3a
|
|
[2022-01-24T15:51:30.701373+01:00] [debug] init needles from /hdd/openqa-devel/repos/os-autoinst/t/data//tests/needles
|
|
[2022-01-24T15:51:30.702814+01:00] [debug] loaded 4 needles
|
|
[2022-01-24T15:51:30.706164+01:00] [debug] Blocking SIGCHLD and SIGTERM
|
|
[2022-01-24T15:51:30.741925+01:00] [debug] Unblocking SIGCHLD and SIGTERM
|
|
[2022-01-24T15:51:30.900388+01:00] [debug] Blocking SIGCHLD and SIGTERM
|
|
[2022-01-24T15:51:30.900484+01:00] [debug] 10663: channel_out 20, channel_in 19
|
|
[2022-01-24T15:51:30.943725+01:00] [debug] Unblocking SIGCHLD and SIGTERM
|
|
[2022-01-24T15:51:30.946412+01:00] [debug] 10685: cmdpipe 18, rsppipe 21
|
|
[2022-01-24T15:51:30.946600+01:00] [debug] started mgmt loop with pid 10685
|
|
[2022-01-24T15:51:30.987470+01:00] [debug] qemu version detected: 6.2.0
|
|
[2022-01-24T15:51:30.989162+01:00] [debug] running `/usr/bin/chattr +C /tmp/99-full-stack.t-1ia6/pool/raid`
|
|
[2022-01-24T15:51:31.006061+01:00] [debug] Command `/usr/bin/chattr +C /tmp/99-full-stack.t-1ia6/pool/raid` terminated with 1
|
|
/usr/bin/chattr: Operation not supported while reading flags on /tmp/99-full-stack.t-1ia6/pool/raid
|
|
[2022-01-24T15:51:31.006254+01:00] [debug] Configuring storage controllers and block devices
|
|
[2022-01-24T15:51:31.007138+01:00] [debug] running `/usr/bin/qemu-img info --output=json /hdd/openqa-devel/repos/os-autoinst/t/data/Core-7.2.iso`
|
|
[2022-01-24T15:51:31.030045+01:00] [debug] Initializing block device images
|
|
[2022-01-24T15:51:31.030613+01:00] [debug] running `/usr/bin/qemu-img create -f qcow2 /tmp/99-full-stack.t-1ia6/pool/raid/hd0 10G`
|
|
[2022-01-24T15:51:31.069477+01:00] [debug] Formatting '/tmp/99-full-stack.t-1ia6/pool/raid/hd0', fmt=qcow2 cluster_size=65536 extended_l2=off compression_type=zlib size=10737418240 lazy_refcounts=off refcount_bits=16
|
|
[2022-01-24T15:51:31.069633+01:00] [debug] running `/usr/bin/qemu-img create -f qcow2 -F raw -b /hdd/openqa-devel/repos/os-autoinst/t/data/Core-7.2.iso /tmp/99-full-stack.t-1ia6/pool/raid/cd0-overlay0 11116544`
|
|
[2022-01-24T15:51:31.081572+01:00] [debug] Formatting '/tmp/99-full-stack.t-1ia6/pool/raid/cd0-overlay0', fmt=qcow2 cluster_size=65536 extended_l2=off compression_type=zlib size=11116544 backing_file=/hdd/openqa-devel/repos/os-autoinst/t/data/Core-7.2.iso backing_fmt=raw lazy_refcounts=off refcount_bits=16
|
|
[2022-01-24T15:51:31.081712+01:00] [debug] init_blockdev_images: Finished creating block devices
|
|
[2022-01-24T15:51:31.083223+01:00] [debug] starting: /usr/bin/qemu-system-i386 -only-migratable -chardev ringbuf,id=serial0,logfile=serial0,logappend=on -serial chardev:serial0 -audiodev none,id=snd0 -device intel-hda -device hda-output,audiodev=snd0 -m 1024 -netdev user,id=qanet0 -device virtio-net,netdev=qanet0,mac=52:54:00:12:34:56 -boot once=d -smp 1 -enable-kvm -no-shutdown -vnc :90,share=force-shared -device virtio-serial -chardev pipe,id=virtio_console,path=virtio_console,logfile=virtio_console.log,logappend=on -device virtconsole,chardev=virtio_console,name=org.openqa.console.virtio_console -chardev pipe,id=virtio_console1,path=virtio_console1,logfile=virtio_console1.log,logappend=on -device virtconsole,chardev=virtio_console1,name=org.openqa.console.virtio_console1 -chardev socket,path=qmp_socket,server=on,wait=off,id=qmp_socket,logfile=qmp_socket.log,logappend=on -qmp chardev:qmp_socket -S -blockdev driver=file,node-name=hd0-file,filename=/tmp/99-full-stack.t-1ia6/pool/raid/hd0,cache.no-flush=on -blockdev driver=qcow2,node-name=hd0,file=hd0-file,cache.no-flush=on -device ide-hd,id=hd0-device,drive=hd0,serial=hd0 -blockdev driver=file,node-name=cd0-overlay0-file,filename=/tmp/99-full-stack.t-1ia6/pool/raid/cd0-overlay0,cache.no-flush=on -blockdev driver=qcow2,node-name=cd0-overlay0,file=cd0-overlay0-file,cache.no-flush=on -device ide-cd,id=cd0-device,drive=cd0-overlay0,serial=cd0
|
|
[2022-01-24T15:51:31.086553+01:00] [debug] Waiting for 0 attempts
|
|
[2022-01-24T15:51:32.087565+01:00] [debug] Waiting for 1 attempts
|
|
[2022-01-24T15:51:33.088278+01:00] [debug] Finished after 2 attempts
|
|
[2022-01-24T15:51:33.093001+01:00] [debug] Establishing VNC connection to localhost:5990
|
|
[2022-01-24T15:51:33.100334+01:00] [debug] pointer type 0 0 640 480 -257
|
|
[2022-01-24T15:51:33.100676+01:00] [debug] led state 0 1 1 -261
|
|
[2022-01-24T15:51:33.157543+01:00] [debug] Start CPU
|
|
[2022-01-24T15:51:33.158154+01:00] [debug] EVENT {"data":{"client":{"family":"ipv4","host":"127.0.0.1","service":"41414","websocket":false},"server":{"auth":"none","family":"ipv4","host":"0.0.0.0","service":"5990","websocket":false}},"event":"VNC_CONNECTED","timestamp":{"microseconds":94698,"seconds":1643035893}}
|
|
[2022-01-24T15:51:33.158379+01:00] [debug] EVENT {"data":{"client":{"family":"ipv4","host":"127.0.0.1","service":"41414","websocket":false},"server":{"auth":"none","family":"ipv4","host":"0.0.0.0","service":"5990","websocket":false}},"event":"VNC_INITIALIZED","timestamp":{"microseconds":97647,"seconds":1643035893}}
|
|
[2022-01-24T15:51:33.158534+01:00] [debug] EVENT {"event":"RESUME","timestamp":{"microseconds":158154,"seconds":1643035893}}
|
|
GOT GO
|
|
[2022-01-24T15:51:33.162875+01:00] [debug] QEMU: QEMU emulator version 6.2.0 (openSUSE Tumbleweed)
|
|
[2022-01-24T15:51:33.162963+01:00] [debug] QEMU: Copyright (c) 2003-2021 Fabrice Bellard and the QEMU Project developers
|
|
[2022-01-24T15:51:33.166465+01:00] [debug] Snapshots are supported
|
|
[2022-01-24T15:51:33.168179+01:00] [debug] ||| starting freeze tests/freeze.pm
|
|
[2022-01-24T15:51:33.170130+01:00] [debug] Call freeze_vm within a post_fail_hook or very early in your test
|
|
[2022-01-24T15:51:33.170406+01:00] [debug] tests/freeze.pm:8 called testapi::freeze_vm
|
|
[2022-01-24T15:51:33.170469+01:00] [debug] <<< testapi::freeze_vm()
|
|
[2022-01-24T15:51:33.171882+01:00] [debug] EVENT {"event":"STOP","timestamp":{"microseconds":171753,"seconds":1643035893}}
|
|
[2022-01-24T15:51:33.172395+01:00] [debug] Simply freeze the vm and resume right before the first assert screen is done
|
|
[2022-01-24T15:51:33.172710+01:00] [debug] tests/freeze.pm:10 called testapi::resume_vm
|
|
[2022-01-24T15:51:33.172806+01:00] [debug] <<< testapi::resume_vm()
|
|
[2022-01-24T15:51:33.174838+01:00] [debug] EVENT {"event":"RESUME","timestamp":{"microseconds":174664,"seconds":1643035893}}
|
|
[2022-01-24T15:51:33.177971+01:00] [debug] ||| finished freeze tests (runtime: 0 s)
|
|
[2022-01-24T15:51:33.285027+01:00] [debug] ||| starting pre_boot tests/pre_boot.py
|
|
[2022-01-24T15:51:33.285831+01:00] [debug]
|
|
[2022-01-24T15:51:33.286083+01:00] [debug] <<< testapi::send_key(key="esc", do_wait=0, wait_screen_change=0)
|
|
[2022-01-24T15:51:33.555995+01:00] [debug]
|
|
[2022-01-24T15:51:33.556428+01:00] [debug] <<< testapi::check_screen(mustmatch="should_not_match", timeout=0)
|
|
[2022-01-24T15:51:33.558204+01:00] [info] ::: backend::baseclass::set_tags_to_assert: NO matching needles for should_not_match
|
|
[2022-01-24T15:51:34.164921+01:00] [debug] no match: -0.7s
|
|
[2022-01-24T15:51:34.319377+01:00] [debug] >>> testapi::_check_backend_response: match=should_not_match timed out after 0 (check_screen)
|
|
[2022-01-24T15:51:34.338992+01:00] [debug] ||| finished pre_boot tests (runtime: 1 s)
|
|
[2022-01-24T15:51:34.340065+01:00] [debug] ||| starting boot tests/boot.pm
|
|
[2022-01-24T15:51:34.340839+01:00] [debug] tests/boot.pm:9 called testapi::assert_screen
|
|
[2022-01-24T15:51:34.340991+01:00] [debug] <<< testapi::assert_screen(mustmatch="core", timeout=15, no_wait=1)
|
|
[2022-01-24T15:51:34.435788+01:00] [debug] >>> testapi::_handle_found_needle: found boot-core, similarity 0.97 @ 1/74
|
|
[2022-01-24T15:51:34.435970+01:00] [debug] tests/boot.pm:10 called testapi::send_key
|
|
[2022-01-24T15:51:34.436092+01:00] [debug] <<< testapi::send_key(key="ret", do_wait=0, wait_screen_change=0)
|
|
[2022-01-24T15:51:34.704301+01:00] [debug] tests/boot.pm:14 called testapi::assert_screen
|
|
[2022-01-24T15:51:34.704448+01:00] [debug] <<< testapi::assert_screen(mustmatch="on_prompt", timeout=90)
|
|
[2022-01-24T15:51:35.347647+01:00] [debug] no match: 89.3s, best candidate: boot-on_prompt (0.00)
|
|
[2022-01-24T15:51:36.344828+01:00] [debug] no match: 88.3s, best candidate: boot-on_prompt (0.00)
|
|
[2022-01-24T15:51:37.430885+01:00] [debug] >>> testapi::_handle_found_needle: found boot-on_prompt, similarity 1.00 @ 2/64
|
|
[2022-01-24T15:51:37.431367+01:00] [debug] ||| finished boot tests (runtime: 3 s)
|
|
[2022-01-24T15:51:37.432282+01:00] [debug] ||| starting assert_screen tests/assert_screen.pm
|
|
[2022-01-24T15:51:37.432938+01:00] [debug] tests/assert_screen.pm:9 called testapi::assert_screen
|
|
[2022-01-24T15:51:37.433069+01:00] [debug] <<< testapi::assert_screen(mustmatch="on_prompt", timeout=60)
|
|
[2022-01-24T15:51:38.424141+01:00] [debug] >>> testapi::_handle_found_needle: found boot-on_prompt, similarity 1.00 @ 2/64
|
|
[2022-01-24T15:51:38.424321+01:00] [debug] tests/assert_screen.pm:10 called testapi::assert_screen
|
|
[2022-01-24T15:51:38.424442+01:00] [debug] <<< testapi::assert_screen(mustmatch="on_prompt", timeout=30, no_wait=1)
|
|
[2022-01-24T15:51:38.504+01:00] [debug] >>> testapi::_handle_found_needle: found boot-on_prompt, similarity 1.00 @ 2/64
|
|
[2022-01-24T15:51:38.504623+01:00] [debug] ||| finished assert_screen tests (runtime: 1 s)
|
|
[2022-01-24T15:51:38.505763+01:00] [debug] ||| starting typing tests/typing.pm
|
|
[2022-01-24T15:51:38.506432+01:00] [debug] tests/typing.pm:8 called testapi::assert_script_run
|
|
[2022-01-24T15:51:38.506598+01:00] [debug] <<< testapi::assert_script_run(cmd="cat /proc/cpuinfo", fail_message="", quiet=undef, timeout=90)
|
|
[2022-01-24T15:51:38.506784+01:00] [debug] tests/typing.pm:8 called testapi::assert_script_run
|
|
[2022-01-24T15:51:38.506924+01:00] [debug] <<< testapi::type_string(string="cat /proc/cpuinfo", max_interval=250, wait_screen_changes=0, wait_still_screen=0, timeout=30, similarity_level=47)
|
|
[2022-01-24T15:51:39.084603+01:00] [debug] tests/typing.pm:8 called testapi::assert_script_run
|
|
[2022-01-24T15:51:39.084814+01:00] [debug] <<< testapi::type_string(string="; echo X6MQS-\$?- > /dev/ttyS0\n", max_interval=250, wait_screen_changes=0, wait_still_screen=0, timeout=30, similarity_level=47)
|
|
[2022-01-24T15:51:40.240571+01:00] [debug] tests/typing.pm:8 called testapi::assert_script_run
|
|
[2022-01-24T15:51:40.240807+01:00] [debug] <<< testapi::wait_serial(no_regex=0, record_output=undef, timeout=90, regexp=qr/X6MQS-\d+-/u, quiet=undef, buffer_size=undef, expect_not_found=0)
|
|
[2022-01-24T15:51:42.327550+01:00] [debug] >>> testapi::wait_serial: (?^u:X6MQS-\d+-): ok
|
|
[2022-01-24T15:51:42.327733+01:00] [debug] tests/typing.pm:9 called testapi::type_string
|
|
[2022-01-24T15:51:42.327902+01:00] [debug] <<< testapi::type_string(string="cat > text <<EOF\n", max_interval=250, wait_screen_changes=0, wait_still_screen=0, timeout=30, similarity_level=47)
|
|
[2022-01-24T15:51:43.008364+01:00] [debug] tests/typing.pm:26 called testapi::type_string
|
|
[2022-01-24T15:51:43.009431+01:00] [debug] <<< testapi::type_string(string="==Description==\nBy default, a viewer/client uses TCP port 5900 to connect to a server (or 5800 for browser access), but can also be set to use any other port. Alternatively, a server can connect to a viewer in \"listening mode\" (by default on port 5500). One advantage of listening mode is that the server site does not have to configure its firewall/NAT to allow access on the specified ports; the burden is on the viewer, which is useful if the server site has no computer expertise, while the viewer user would be expected to be more knowledgeable.\n\nAlthough RFB started as a relatively simple protocol, it has been enhanced with additional features (such as file transfers) and more sophisticated [[Data compression|compression]] and security techniques as it has developed. To maintain seamless cross-compatibility between the many different VNC client and server implementations, the clients and servers negotiate a connection using the best RFB version, and the most appropriate compression and security options that they can both support.\n\n== History ==\n\nRFB was originally developed at [[Olivetti Research Laboratory]] (ORL) as a remote display technology to be used by a simple [[thin client]] with [[Asynchronous Transfer Mode|ATM]] connectivity called a Videotile. In order to keep the device as simple as possible, RFB was developed and used in preference to any of the existing remote display technologies.\n\nRFB found a second and more enduring use when VNC was developed. VNC was released as [[open source]] software and the RFB specification published on the web. Since then RFB has been a free protocol which anybody can use.\n\nWhen ORL was closed in 2002 some of the key people behind VNC and RFB formed [[RealVNC]], Ltd., in order to continue development of VNC and to maintain the RFB protocol. The current RFB protocol is published on the RealVNC website.\n", max_interval=250, wait_screen_changes=0, wait_still_screen=0, timeout=30, similarity_level=47)
|
|
[2022-01-24T15:52:48.602370+01:00] [debug] tests/typing.pm:27 called testapi::type_string
|
|
[2022-01-24T15:52:48.602592+01:00] [debug] <<< testapi::type_string(string="\nEOF\n", max_interval=250, wait_screen_changes=0, wait_still_screen=0, timeout=30, similarity_level=47)
|
|
[2022-01-24T15:52:48.823607+01:00] [debug] tests/typing.pm:28 called testapi::script_run
|
|
[2022-01-24T15:52:48.823795+01:00] [debug] <<< testapi::script_run(cmd="echo '924095f2cb4d622a8796de66a5e0a44a text' > text.md5", timeout=30, die_on_timeout=-1, quiet=undef, output="")
|
|
[2022-01-24T15:52:48.823912+01:00] [debug] tests/typing.pm:28 called testapi::script_run
|
|
[2022-01-24T15:52:48.824043+01:00] [debug] <<< testapi::type_string(string="echo '924095f2cb4d622a8796de66a5e0a44a text' > text.md5", max_interval=250, wait_screen_changes=0, wait_still_screen=0, timeout=30, similarity_level=47)
|
|
[2022-01-24T15:52:50.755249+01:00] [debug] tests/typing.pm:28 called testapi::script_run
|
|
[2022-01-24T15:52:50.755534+01:00] [debug] <<< testapi::type_string(string="; echo NZLuk-\$?- > /dev/ttyS0\n", max_interval=250, wait_screen_changes=0, wait_still_screen=0, timeout=30, similarity_level=47)
|
|
[2022-01-24T15:52:51.905689+01:00] [debug] tests/typing.pm:28 called testapi::script_run
|
|
[2022-01-24T15:52:51.906645+01:00] [debug] <<< testapi::wait_serial(buffer_size=undef, quiet=undef, expect_not_found=0, timeout=30, regexp=qr/NZLuk-\d+-/u, record_output=undef, no_regex=0)
|
|
[2022-01-24T15:52:53.001612+01:00] [debug] >>> testapi::wait_serial: (?^u:NZLuk-\d+-): ok
|
|
[2022-01-24T15:52:53.001841+01:00] [warn] !!! testapi::script_run: DEPRECATED call of script_run() in tests/typing.pm:28 add `die_on_timeout => ?` to the call or set
|
|
$distri->{script_run_die_on_timeout} to avoid this
|
|
warning
|
|
[2022-01-24T15:52:53.002044+01:00] [debug] tests/typing.pm:29 called testapi::assert_script_run
|
|
[2022-01-24T15:52:53.002244+01:00] [debug] <<< testapi::assert_script_run(cmd="md5sum -c text.md5", timeout=90, quiet=undef, fail_message="")
|
|
[2022-01-24T15:52:53.002410+01:00] [debug] tests/typing.pm:29 called testapi::assert_script_run
|
|
[2022-01-24T15:52:53.002737+01:00] [debug] <<< testapi::type_string(string="md5sum -c text.md5", max_interval=250, wait_screen_changes=0, wait_still_screen=0, timeout=30, similarity_level=47)
|
|
[2022-01-24T15:52:53.618927+01:00] [debug] tests/typing.pm:29 called testapi::assert_script_run
|
|
[2022-01-24T15:52:53.619297+01:00] [debug] <<< testapi::type_string(string="; echo 6i9D7-\$?- > /dev/ttyS0\n", max_interval=250, wait_screen_changes=0, wait_still_screen=0, timeout=30, similarity_level=47)
|
|
[2022-01-24T15:52:54.723604+01:00] [debug] tests/typing.pm:29 called testapi::assert_script_run
|
|
[2022-01-24T15:52:54.724178+01:00] [debug] <<< testapi::wait_serial(expect_not_found=0, quiet=undef, buffer_size=undef, no_regex=0, regexp=qr/6i9D7-\d+-/u, timeout=90, record_output=undef)
|
|
[2022-01-24T15:52:55.809821+01:00] [debug] >>> testapi::wait_serial: (?^u:6i9D7-\d+-): ok
|
|
[2022-01-24T15:52:55.810063+01:00] [debug] tests/typing.pm:32 called testapi::script_run
|
|
[2022-01-24T15:52:55.810258+01:00] [debug] <<< testapi::script_run(cmd="alias bash=sh", quiet=undef, die_on_timeout=-1, timeout=0, output="")
|
|
[2022-01-24T15:52:55.810372+01:00] [debug] tests/typing.pm:32 called testapi::script_run
|
|
[2022-01-24T15:52:55.810507+01:00] [debug] <<< testapi::type_string(string="alias bash=sh", max_interval=250, wait_screen_changes=0, wait_still_screen=0, timeout=30, similarity_level=47)
|
|
[2022-01-24T15:52:56.253688+01:00] [debug] tests/typing.pm:32 called testapi::script_run
|
|
[2022-01-24T15:52:56.254073+01:00] [debug] <<< testapi::send_key(key="ret", do_wait=0, wait_screen_change=0)
|
|
[2022-01-24T15:52:56.524198+01:00] [debug] tests/typing.pm:33 called testapi::script_output
|
|
[2022-01-24T15:52:56.524905+01:00] [debug] <<< testapi::type_string(string="cat - > /tmp/scriptQF9Xl.sh;", max_interval=250, wait_screen_changes=0, wait_still_screen=0, timeout=30, similarity_level=47)
|
|
[2022-01-24T15:52:57.550675+01:00] [debug] tests/typing.pm:33 called testapi::script_output
|
|
[2022-01-24T15:52:57.551148+01:00] [debug] <<< testapi::type_string(string="\n", max_interval=250, wait_screen_changes=0, wait_still_screen=0, timeout=30, similarity_level=47)
|
|
[2022-01-24T15:52:57.586257+01:00] [debug] tests/typing.pm:33 called testapi::script_output
|
|
[2022-01-24T15:52:57.586499+01:00] [debug] <<< testapi::type_string(string="mount\n", max_interval=250, wait_screen_changes=0, wait_still_screen=0, timeout=30, similarity_level=47)
|
|
[2022-01-24T15:52:57.792530+01:00] [debug] tests/typing.pm:33 called testapi::script_output
|
|
[2022-01-24T15:52:57.793299+01:00] [debug] <<< testapi::send_key(key="ctrl-d", wait_screen_change=0, do_wait=0)
|
|
[2022-01-24T15:52:58.129074+01:00] [debug] tests/typing.pm:33 called testapi::script_output
|
|
[2022-01-24T15:52:58.129273+01:00] [debug] <<< testapi::type_string(string="(echo QF9Xl; bash -eox pipefail /tmp/scriptQF9Xl.sh ; echo SCRIPT_FINISHEDQF9Xl-\$?-) | tee /dev/ttyS0\n", max_interval=250, wait_screen_changes=0, wait_still_screen=0, timeout=30, similarity_level=47)
|
|
[2022-01-24T15:53:02.101523+01:00] [debug] tests/typing.pm:33 called testapi::script_output
|
|
[2022-01-24T15:53:02.101922+01:00] [debug] <<< testapi::wait_serial(regexp="SCRIPT_FINISHEDQF9Xl-\\d+-", timeout=90, record_output=1, no_regex=0, expect_not_found=0, buffer_size=undef, quiet=undef)
|
|
[2022-01-24T15:53:03.195326+01:00] [debug] >>> testapi::wait_serial: SCRIPT_FINISHEDQF9Xl-\d+-: ok
|
|
[2022-01-24T15:53:03.195577+01:00] [debug] tests/typing.pm:38 called testapi::type_string
|
|
[2022-01-24T15:53:03.195787+01:00] [debug] <<< testapi::type_string(string="echo do not wait_still_screen\n", max_interval=50, wait_screen_changes=0, wait_still_screen=0, timeout=30, similarity_level=47)
|
|
[2022-01-24T15:53:08.637942+01:00] [debug] tests/typing.pm:39 called testapi::type_string
|
|
[2022-01-24T15:53:08.638237+01:00] [debug] <<< testapi::type_string(string="echo type string and wait for .2 seconds\n", max_interval=250, wait_screen_changes=0, wait_still_screen="0.2", timeout=30, similarity_level=47)
|
|
[2022-01-24T15:53:10.045117+01:00] [debug] tests/typing.pm:39 called testapi::type_string
|
|
[2022-01-24T15:53:10.045592+01:00] [debug] <<< testapi::wait_still_screen(stilltime="0.2", similarity_level=47, timeout=30)
|
|
[2022-01-24T15:53:11.058651+01:00] [debug] >>> testapi::wait_still_screen: detected same image for 0.2 seconds, last detected similarity is 1000000
|
|
[2022-01-24T15:53:11.059213+01:00] [debug] tests/typing.pm:40 called testapi::type_string
|
|
[2022-01-24T15:53:11.059894+01:00] [debug] <<< testapi::type_string(string="echo test\necho wait\necho 1se\n", max_interval=100, wait_screen_changes=0, wait_still_screen=1, timeout=30, similarity_level=47)
|
|
[2022-01-24T15:53:14.962472+01:00] [debug] tests/typing.pm:40 called testapi::type_string
|
|
[2022-01-24T15:53:14.962732+01:00] [debug] <<< testapi::wait_still_screen(timeout=30, similarity_level=47, stilltime=1)
|
|
[2022-01-24T15:53:16.476222+01:00] [debug] >>> testapi::wait_still_screen: detected same image for 1 seconds, last detected similarity is 50.028504689842
|
|
[2022-01-24T15:53:16.476662+01:00] [debug] tests/typing.pm:41 called testapi::type_string
|
|
[2022-01-24T15:53:16.477154+01:00] [debug] <<< testapi::type_string(string="echo test if wait_screen_change functions as expected\n", max_interval=150, wait_screen_changes=0, wait_still_screen=1, timeout=30, similarity_level=47)
|
|
[2022-01-24T15:53:22.851259+01:00] [debug] tests/typing.pm:41 called testapi::type_string
|
|
[2022-01-24T15:53:22.851712+01:00] [debug] <<< testapi::wait_still_screen(stilltime=1, similarity_level=47, timeout=30)
|
|
[2022-01-24T15:53:24.366380+01:00] [debug] >>> testapi::wait_still_screen: detected same image for 1 seconds, last detected similarity is 50.028504689842
|
|
[2022-01-24T15:53:24.366693+01:00] [debug] tests/typing.pm:42 called testapi::type_string
|
|
[2022-01-24T15:53:24.367101+01:00] [debug] <<< testapi::type_string(string="echo wait_still_screen for .1 seconds\n", max_interval=200, wait_screen_changes=0, wait_still_screen="0.1", timeout=30, similarity_level=47)
|
|
[2022-01-24T15:53:28.452441+01:00] [debug] tests/typing.pm:42 called testapi::type_string
|
|
[2022-01-24T15:53:28.453052+01:00] [debug] <<< testapi::wait_still_screen(timeout=30, similarity_level=47, stilltime="0.1")
|
|
[2022-01-24T15:53:29.990673+01:00] [debug] >>> testapi::wait_still_screen: detected same image for 0.1 seconds, last detected similarity is 50.028504689842
|
|
[2022-01-24T15:53:29.990932+01:00] [debug] tests/typing.pm:43 called testapi::type_string
|
|
[2022-01-24T15:53:29.991338+01:00] [debug] <<< testapi::type_string(string="echo 'ignore \\r'\r\n", max_interval=250, wait_screen_changes=0, wait_still_screen=0, timeout=30, similarity_level=47)
|
|
[2022-01-24T15:53:30.570823+01:00] [debug] ||| finished typing tests (runtime: 112 s)
|
|
[2022-01-24T15:53:30.571823+01:00] [debug] ||| starting select_console_fail_test tests/select_console_fail_test.pm
|
|
[2022-01-24T15:53:30.572533+01:00] [debug] tests/select_console_fail_test.pm:8 called testapi::select_console
|
|
[2022-01-24T15:53:30.572636+01:00] [debug] <<< testapi::select_console(testapi_console="brokenvnc")
|
|
[2022-01-24T15:53:30.573142+01:00] [debug] Establishing VNC connection to novnc.nowhere:5901
|
|
[2022-01-24T15:53:32.767384+01:00] [warn] !!! consoles::VNC::login: Error connecting to VNC server <novnc.nowhere:5901>: IO::Socket::INET: Bad hostname 'novnc.nowhere'
|
|
[2022-01-24T15:53:33.832947+01:00] [warn] !!! consoles::VNC::login: Error connecting to VNC server <novnc.nowhere:5901>: IO::Socket::INET: Bad hostname 'novnc.nowhere'
|
|
[2022-01-24T15:53:34.895302+01:00] [warn] !!! consoles::VNC::login: Error connecting to VNC server <novnc.nowhere:5901>: IO::Socket::INET: Bad hostname 'novnc.nowhere'
|
|
[2022-01-24T15:53:35.961196+01:00] [warn] !!! consoles::VNC::login: Error connecting to VNC server <novnc.nowhere:5901>: IO::Socket::INET: Bad hostname 'novnc.nowhere'
|
|
[2022-01-24T15:53:37.026573+01:00] [warn] !!! consoles::VNC::login: Error connecting to VNC server <novnc.nowhere:5901>: IO::Socket::INET: Bad hostname 'novnc.nowhere'
|
|
[2022-01-24T15:53:38.091977+01:00] [warn] !!! consoles::VNC::login: Error connecting to VNC server <novnc.nowhere:5901>: IO::Socket::INET: Bad hostname 'novnc.nowhere'
|
|
[2022-01-24T15:53:39.156006+01:00] [warn] !!! consoles::VNC::login: Error connecting to VNC server <novnc.nowhere:5901>: IO::Socket::INET: Bad hostname 'novnc.nowhere'
|
|
[2022-01-24T15:53:40.219320+01:00] [warn] !!! consoles::VNC::login: Error connecting to VNC server <novnc.nowhere:5901>: IO::Socket::INET: Bad hostname 'novnc.nowhere'
|
|
[2022-01-24T15:53:41.391429+01:00] [info] ::: basetest::runtest: # Test died: Error connecting to VNC server <novnc.nowhere:5901>: IO::Socket::INET: Bad hostname 'novnc.nowhere' at /hdd/openqa-devel/repos/os-autoinst/t/../testapi.pm line 1762.
|
|
|
|
[2022-01-24T15:53:41.392910+01:00] [debug] ||| finished select_console_fail_test tests (runtime: 11 s)
|
|
[2022-01-24T15:53:41.392971+01:00] [debug] ||| post fail hooks runtime: 0 s
|
|
[2022-01-24T15:53:41.393247+01:00] [debug] ||| starting select_ssh_console_fail_test tests/select_ssh_console_fail_test.pm
|
|
[2022-01-24T15:53:41.393853+01:00] [debug] tests/select_ssh_console_fail_test.pm:8 called testapi::select_console
|
|
[2022-01-24T15:53:41.393956+01:00] [debug] <<< testapi::select_console(testapi_console="brokeniucv")
|
|
[2022-01-24T15:53:41.394663+01:00] [debug] <<< backend::baseclass::new_ssh_connection(hostname="noIucvconn.nowhere", username="root", password=undef)
|
|
[2022-01-24T15:53:41.460783+01:00] [debug] Could not connect to root@noIucvconn.nowhere, Retrying after some seconds...
|
|
[2022-01-24T15:53:41.524900+01:00] [debug] Could not connect to root@noIucvconn.nowhere, Retrying after some seconds...
|
|
[2022-01-24T15:53:41.611861+01:00] [info] ::: basetest::runtest: # Test died: Error connecting to <root@noIucvconn.nowhere>: Name or service not known at /hdd/openqa-devel/repos/os-autoinst/t/../testapi.pm line 1762.
|
|
|
|
[2022-01-24T15:53:41.613159+01:00] [debug] ||| finished select_ssh_console_fail_test tests (runtime: 0 s)
|
|
[2022-01-24T15:53:41.613220+01:00] [debug] ||| post fail hooks runtime: 0 s
|
|
[2022-01-24T15:53:41.613443+01:00] [debug] ||| starting assert_screen_fail_test tests/assert_screen_fail_test.pm
|
|
[2022-01-24T15:53:41.614195+01:00] [debug] tests/assert_screen_fail_test.pm:9 called (eval) -> tests/assert_screen_fail_test.pm:9 called testapi::assert_screen
|
|
[2022-01-24T15:53:41.614427+01:00] [debug] <<< testapi::assert_screen(mustmatch=[
|
|
"no_tag",
|
|
"no_tag2"
|
|
], timeout=1, no_wait=1)
|
|
[2022-01-24T15:53:41.615188+01:00] [info] ::: backend::baseclass::set_tags_to_assert: NO matching needles for no_tag,no_tag2
|
|
[2022-01-24T15:53:41.615674+01:00] [debug] no match: 0.9s
|
|
[2022-01-24T15:53:41.716614+01:00] [debug] no change: 0.8s
|
|
[2022-01-24T15:53:41.817569+01:00] [debug] no match: 0.7s
|
|
[2022-01-24T15:53:41.919529+01:00] [debug] no change: 0.6s
|
|
[2022-01-24T15:53:42.020806+01:00] [debug] no change: 0.5s
|
|
[2022-01-24T15:53:42.121892+01:00] [debug] no change: 0.4s
|
|
[2022-01-24T15:53:42.222767+01:00] [debug] no change: 0.3s
|
|
[2022-01-24T15:53:42.323895+01:00] [debug] no match: 0.2s
|
|
[2022-01-24T15:53:42.426142+01:00] [debug] no change: 0.1s
|
|
[2022-01-24T15:53:42.526731+01:00] [debug] no change: 0.0s
|
|
[2022-01-24T15:53:42.627381+01:00] [debug] no match: -0.1s
|
|
[2022-01-24T15:53:42.894754+01:00] [debug] >>> testapi::_check_backend_response: match=no_tag,no_tag2 timed out after 1 (assert_screen)
|
|
[2022-01-24T15:53:42.973635+01:00] [debug] no candidate needle with tag(s) 'no_tag, no_tag2' matched
|
|
[2022-01-24T15:53:42.973937+01:00] [debug] tests/assert_screen_fail_test.pm:12 called (eval) -> tests/assert_screen_fail_test.pm:12 called testapi::assert_screen
|
|
[2022-01-24T15:53:42.974175+01:00] [debug] <<< testapi::assert_screen(mustmatch="no_tag3", timeout=1, no_wait=1)
|
|
[2022-01-24T15:53:42.974958+01:00] [info] ::: backend::baseclass::set_tags_to_assert: NO matching needles for no_tag3
|
|
[2022-01-24T15:53:42.975613+01:00] [debug] no match: 0.9s
|
|
[2022-01-24T15:53:43.076255+01:00] [debug] no change: 0.8s
|
|
[2022-01-24T15:53:43.176910+01:00] [debug] no change: 0.7s
|
|
[2022-01-24T15:53:43.278010+01:00] [debug] no change: 0.6s
|
|
[2022-01-24T15:53:43.379392+01:00] [debug] no match: 0.5s
|
|
[2022-01-24T15:53:43.483093+01:00] [debug] no change: 0.4s
|
|
[2022-01-24T15:53:43.584561+01:00] [debug] no change: 0.3s
|
|
[2022-01-24T15:53:43.685520+01:00] [debug] no change: 0.2s
|
|
[2022-01-24T15:53:43.786218+01:00] [debug] no change: 0.1s
|
|
[2022-01-24T15:53:43.886907+01:00] [debug] no match: 0.0s
|
|
[2022-01-24T15:53:43.989137+01:00] [debug] no match: -0.1s
|
|
[2022-01-24T15:53:44.207015+01:00] [debug] >>> testapi::_check_backend_response: match=no_tag3 timed out after 1 (assert_screen)
|
|
[2022-01-24T15:53:44.245101+01:00] [debug] no candidate needle with tag(s) 'no_tag3' matched
|
|
[2022-01-24T15:53:44.246607+01:00] [debug] ||| finished assert_screen_fail_test tests (runtime: 3 s)
|
|
[2022-01-24T15:53:44.246687+01:00] [debug] ||| post fail hooks runtime: 0 s
|
|
[2022-01-24T15:53:44.246959+01:00] [debug] test assert_screen_fail_test failed
|
|
|
|
[2022-01-24T15:53:44.247055+01:00] [debug] ||| starting reload_needles tests/reload_needles.pm
|
|
[2022-01-24T15:53:44.247648+01:00] [debug] tests/reload_needles.pm:10 called testapi::type_string
|
|
[2022-01-24T15:53:44.247884+01:00] [debug] <<< testapi::type_string(string="echo HALLO\n", max_interval=250, wait_screen_changes=0, wait_still_screen=0, timeout=30, similarity_level=47)
|
|
[2022-01-24T15:53:44.706296+01:00] [debug] tests/reload_needles.pm:11 called testapi::assert_screen
|
|
[2022-01-24T15:53:44.706470+01:00] [debug] <<< testapi::assert_screen(mustmatch="no-importa", timeout=30)
|
|
[2022-01-24T15:53:44.995471+01:00] [debug] no match: 29.7s, best candidate: no-importa-v1 (0.00)
|
|
[2022-01-24T15:53:46.090596+01:00] [debug] >>> testapi::_handle_found_needle: found no-importa-v1, similarity 0.99 @ 90/350
|
|
[2022-01-24T15:53:46.100801+01:00] [debug] git hash in /hdd/openqa-devel/repos/os-autoinst/t/data//tests/needles: 7ef72e209567425123d4311781f3024f52d88f3a
|
|
[2022-01-24T15:53:46.101036+01:00] [debug] init needles from /hdd/openqa-devel/repos/os-autoinst/t/data//tests/needles
|
|
[2022-01-24T15:53:46.102547+01:00] [debug] loaded 4 needles
|
|
[2022-01-24T15:53:46.103211+01:00] [debug] tests/reload_needles.pm:15 called testapi::assert_screen
|
|
[2022-01-24T15:53:46.103352+01:00] [debug] <<< testapi::assert_screen(mustmatch="no-importa", timeout=30)
|
|
[2022-01-24T15:53:47.078561+01:00] [debug] >>> testapi::_handle_found_needle: found no-importa-v2, similarity 1.00 @ 85/353
|
|
[2022-01-24T15:53:47.079063+01:00] [debug] ||| finished reload_needles tests (runtime: 3 s)
|
|
[2022-01-24T15:53:47.079944+01:00] [debug] ||| starting modify_and_upload_file tests/modify_and_upload_file.pm
|
|
[2022-01-24T15:53:47.080743+01:00] [debug] tests/modify_and_upload_file.pm:23 called testapi::get_test_data
|
|
[2022-01-24T15:53:47.080842+01:00] [debug] <<< testapi::get_test_data(path="/hdd/openqa-devel/repos/os-autoinst/t/data//tests/data/autoinst.xml")
|
|
[2022-01-24T15:53:47.082284+01:00] [debug] tests/modify_and_upload_file.pm:25 called testapi::type_string
|
|
[2022-01-24T15:53:47.082435+01:00] [debug] <<< testapi::type_string(string="echo get_test_data returned expected file\n", max_interval=250, wait_screen_changes=0, wait_still_screen=0, timeout=30, similarity_level=47)
|
|
[2022-01-24T15:53:48.552+01:00] [debug] tests/modify_and_upload_file.pm:30 called testapi::save_tmp_file
|
|
[2022-01-24T15:53:48.552167+01:00] [debug] <<< testapi::save_tmp_file(path="modified.xml")
|
|
[2022-01-24T15:53:48.552499+01:00] [debug] tests/modify_and_upload_file.pm:32 called testapi::assert_script_run
|
|
[2022-01-24T15:53:48.552791+01:00] [debug] <<< testapi::assert_script_run(cmd="wget -q http://10.0.2.2:15223/LSeWDgmwis/files/modified.xml", quiet=undef, timeout=90, fail_message="")
|
|
[2022-01-24T15:53:48.553008+01:00] [debug] tests/modify_and_upload_file.pm:32 called testapi::assert_script_run
|
|
[2022-01-24T15:53:48.553283+01:00] [debug] <<< testapi::type_string(string="wget -q http://10.0.2.2:15223/LSeWDgmwis/files/modified.xml", max_interval=250, wait_screen_changes=0, wait_still_screen=0, timeout=30, similarity_level=47)
|
|
[2022-01-24T15:53:50.666015+01:00] [debug] tests/modify_and_upload_file.pm:32 called testapi::assert_script_run
|
|
[2022-01-24T15:53:50.666646+01:00] [debug] <<< testapi::type_string(string="; echo M2sJ_-\$?- > /dev/ttyS0\n", max_interval=250, wait_screen_changes=0, wait_still_screen=0, timeout=30, similarity_level=47)
|
|
[2022-01-24T15:53:51.805160+01:00] [debug] tests/modify_and_upload_file.pm:32 called testapi::assert_script_run
|
|
[2022-01-24T15:53:51.805387+01:00] [debug] <<< testapi::wait_serial(no_regex=0, record_output=undef, regexp=qr/M2sJ_-\d+-/u, timeout=90, expect_not_found=0, quiet=undef, buffer_size=undef)
|
|
[2022-01-24T15:53:52.888324+01:00] [debug] >>> testapi::wait_serial: (?^u:M2sJ_-\d+-): ok
|
|
[2022-01-24T15:53:52.888513+01:00] [debug] tests/modify_and_upload_file.pm:33 called testapi::script_run
|
|
[2022-01-24T15:53:52.888723+01:00] [debug] <<< testapi::script_run(cmd="echo '72d2c15cb10535f36862d7d2eecc8a79 modified.xml' > modified.md5", output="", quiet=undef, die_on_timeout=-1, timeout=30)
|
|
[2022-01-24T15:53:52.888860+01:00] [debug] tests/modify_and_upload_file.pm:33 called testapi::script_run
|
|
[2022-01-24T15:53:52.889064+01:00] [debug] <<< testapi::type_string(string="echo '72d2c15cb10535f36862d7d2eecc8a79 modified.xml' > modified.md5", max_interval=250, wait_screen_changes=0, wait_still_screen=0, timeout=30, similarity_level=47)
|
|
[2022-01-24T15:53:55.214991+01:00] [debug] tests/modify_and_upload_file.pm:33 called testapi::script_run
|
|
[2022-01-24T15:53:55.215325+01:00] [debug] <<< testapi::type_string(string="; echo ~liyM-\$?- > /dev/ttyS0\n", max_interval=250, wait_screen_changes=0, wait_still_screen=0, timeout=30, similarity_level=47)
|
|
[2022-01-24T15:53:56.347567+01:00] [debug] tests/modify_and_upload_file.pm:33 called testapi::script_run
|
|
[2022-01-24T15:53:56.347834+01:00] [debug] <<< testapi::wait_serial(timeout=30, regexp=qr/~liyM-\d+-/u, record_output=undef, no_regex=0, buffer_size=undef, quiet=undef, expect_not_found=0)
|
|
[2022-01-24T15:53:57.439365+01:00] [debug] >>> testapi::wait_serial: (?^u:~liyM-\d+-): ok
|
|
[2022-01-24T15:53:57.439532+01:00] [warn] !!! testapi::script_run: DEPRECATED call of script_run() in tests/modify_and_upload_file.pm:33 add `die_on_timeout => ?` to the call or set
|
|
$distri->{script_run_die_on_timeout} to avoid this
|
|
warning
|
|
[2022-01-24T15:53:57.439687+01:00] [debug] tests/modify_and_upload_file.pm:34 called testapi::assert_script_run
|
|
[2022-01-24T15:53:57.439826+01:00] [debug] <<< testapi::assert_script_run(cmd="md5sum -c modified.md5", fail_message="", timeout=90, quiet=undef)
|
|
[2022-01-24T15:53:57.439954+01:00] [debug] tests/modify_and_upload_file.pm:34 called testapi::assert_script_run
|
|
[2022-01-24T15:53:57.440093+01:00] [debug] <<< testapi::type_string(string="md5sum -c modified.md5", max_interval=250, wait_screen_changes=0, wait_still_screen=0, timeout=30, similarity_level=47)
|
|
[2022-01-24T15:53:58.187150+01:00] [debug] tests/modify_and_upload_file.pm:34 called testapi::assert_script_run
|
|
[2022-01-24T15:53:58.187483+01:00] [debug] <<< testapi::type_string(string="; echo ib~GQ-\$?- > /dev/ttyS0\n", max_interval=250, wait_screen_changes=0, wait_still_screen=0, timeout=30, similarity_level=47)
|
|
[2022-01-24T15:53:59.326742+01:00] [debug] tests/modify_and_upload_file.pm:34 called testapi::assert_script_run
|
|
[2022-01-24T15:53:59.327322+01:00] [debug] <<< testapi::wait_serial(buffer_size=undef, quiet=undef, expect_not_found=0, no_regex=0, record_output=undef, timeout=90, regexp=qr/ib~GQ-\d+-/u)
|
|
[2022-01-24T15:54:00.416567+01:00] [debug] >>> testapi::wait_serial: (?^u:ib~GQ-\d+-): ok
|
|
[2022-01-24T15:54:00.416867+01:00] [debug] tests/modify_and_upload_file.pm:36 called testapi::type_string
|
|
[2022-01-24T15:54:00.417105+01:00] [debug] <<< testapi::type_string(string="echo save_tmp_file returned expected file\n", max_interval=250, wait_screen_changes=0, wait_still_screen=0, timeout=30, similarity_level=47)
|
|
[2022-01-24T15:54:01.879877+01:00] [debug] ||| finished modify_and_upload_file tests (runtime: 14 s)
|
|
[2022-01-24T15:54:01.882440+01:00] [debug] ||| starting shutdown tests/shutdown.pm
|
|
[2022-01-24T15:54:01.884466+01:00] [debug] tests/shutdown.pm:8 called testapi::type_string
|
|
[2022-01-24T15:54:01.885173+01:00] [debug] <<< testapi::type_string(string="sudo su\n", max_interval=250, wait_screen_changes=0, wait_still_screen=0, timeout=30, similarity_level=47)
|
|
[2022-01-24T15:54:02.157571+01:00] [debug] tests/shutdown.pm:9 called testapi::type_string
|
|
[2022-01-24T15:54:02.157879+01:00] [debug] <<< testapi::type_string(string="poweroff\n", max_interval=250, wait_screen_changes=0, wait_still_screen=0, timeout=30, similarity_level=47)
|
|
[2022-01-24T15:54:02.472488+01:00] [debug] tests/shutdown.pm:10 called testapi::assert_shutdown
|
|
[2022-01-24T15:54:02.472798+01:00] [debug] <<< testapi::check_shutdown(timeout=60)
|
|
[2022-01-24T15:54:02.474128+01:00] [debug] EVENT {"data":{"path":"\/machine\/peripheral-anon\/device[2]\/virtio-backend"},"event":"NIC_RX_FILTER_CHANGED","timestamp":{"microseconds":726029,"seconds":1643035896}}
|
|
[2022-01-24T15:54:02.474530+01:00] [debug] QEMU status is not 'shutdown', it is 'running'
|
|
[2022-01-24T15:54:03.476979+01:00] [debug] QEMU status is not 'shutdown', it is 'running'
|
|
[2022-01-24T15:54:04.479887+01:00] [debug] QEMU status is not 'shutdown', it is 'running'
|
|
[2022-01-24T15:54:05.482520+01:00] [debug] QEMU status is not 'shutdown', it is 'running'
|
|
[2022-01-24T15:54:06.485013+01:00] [debug] QEMU status is not 'shutdown', it is 'running'
|
|
[2022-01-24T15:54:07.487346+01:00] [debug] EVENT {"data":{"guest":true,"reason":"guest-shutdown"},"event":"SHUTDOWN","timestamp":{"microseconds":539076,"seconds":1643036046}}
|
|
[2022-01-24T15:54:07.487636+01:00] [debug] EVENT {"event":"STOP","timestamp":{"microseconds":540638,"seconds":1643036046}}
|
|
[2022-01-24T15:54:07.585421+01:00] [debug] ||| finished shutdown tests (runtime: 6 s)
|
|
[2022-01-24T15:54:07.586772+01:00] [debug] stopping autotest process 10671
|
|
[2022-01-24T15:54:07.591003+01:00] [debug] [autotest] process exited: 0
|
|
[2022-01-24T15:54:07.691389+01:00] [debug] done with autotest process
|
|
[2022-01-24T15:54:07.692105+01:00] [debug] stopping command server 10668 because test execution ended
|
|
[2022-01-24T15:54:07.692290+01:00] [debug] isotovideo: informing websocket clients before stopping command server: http://127.0.0.1:15223/LSeWDgmwis/broadcast
|
|
[2022-01-24T15:54:07.707065+01:00] [debug] commands process exited: 0
|
|
[2022-01-24T15:54:07.807526+01:00] [debug] done with command server
|
|
[2022-01-24T15:54:07.807739+01:00] [debug] isotovideo done
|
|
[2022-01-24T15:54:07.809979+01:00] [debug] backend shutdown state: 1
|
|
[2022-01-24T15:54:07.811074+01:00] [info] ::: OpenQA::Qemu::Proc::save_state: Saving QEMU state to qemu_state.json
|
|
[2022-01-24T15:54:08.876336+01:00] [debug] Passing remaining frames to the video encoder
|
|
[2022-01-24T15:54:08.905428+01:00] [debug] Waiting for video encoder to finalize the video
|
|
[2022-01-24T15:54:08.905520+01:00] [debug] The built-in video encoder (pid 10699) terminated
|
|
[2022-01-24T15:54:08.906214+01:00] [debug] QEMU: qemu-system-i386: terminating on signal 15 from pid 10685 (/hdd/openqa-devel/repos/os-autoinst/t/../isotovideo: backen)
|
|
[2022-01-24T15:54:08.906939+01:00] [debug] sending magic and exit
|
|
[2022-01-24T15:54:08.907159+01:00] [debug] received magic close
|
|
[2022-01-24T15:54:08.916922+01:00] [debug] backend process exited: 0
|
|
[2022-01-24T15:54:09.017826+01:00] [debug] stopping backend process 10685
|
|
[2022-01-24T15:54:09.017899+01:00] [debug] done with backend process
|
|
10663: EXIT 0
|
|
ok 1 - test executed fine
|
|
ok 2 - Snapshots are enabled
|
|
ok 3 - Tests did not fail within modules
|
|
ok 4 - test type string and do not wait
|
|
ok 5 - test type string and wait for .2 seconds
|
|
ok 6 - test type string and wait for 1 seconds
|
|
ok 7 - test type string and wait for .1 seconds
|
|
ok 8 - Machine properly paused
|
|
ok 9 - Machine properly resumed
|
|
ok 10 - get_test_data test
|
|
ok 11 - save_tmp_file test
|
|
ok 12 - No warning about expected termination
|
|
ok 13 - Result in testresults/result-assert_screen.json is ok
|
|
ok 14 - Result in testresults/result-boot.json is ok
|
|
ok 15 - Result in testresults/result-freeze.json is ok
|
|
ok 16 - Result in testresults/result-modify_and_upload_file.json is ok
|
|
ok 17 - Result in testresults/result-pre_boot.json is ok
|
|
ok 18 - Result in testresults/result-reload_needles.json is ok
|
|
ok 19 - Result in testresults/result-shutdown.json is ok
|
|
ok 20 - Result in testresults/result-typing.json is ok
|
|
ok 21 - Result in testresults/result-assert_screen_fail_test.json is fail
|
|
ok 22 - Result in testresults/result-select_console_fail_test.json is fail
|
|
ok 23 - Result in testresults/result-select_ssh_console_fail_test.json is fail
|
|
# Subtest: Assert screen failure
|
|
ok 1 - Assert screen failures
|
|
1..1
|
|
ok 24 - Assert screen failure
|
|
ok 25 - no (unexpected) warnings (via done_testing)
|
|
1..25
|
|
ok
|
|
All tests successful.
|
|
Files=1, Tests=25, 160 wallclock secs ( 0.09 usr 0.01 sys + 32.85 cusr 4.30 csys = 37.25 CPU)
|
|
Result: PASS
|
|
## count_fail_ratio: Run: 8. Fails: 1. Fail ratio 12%
|