Project

General

Profile

action #107941 » autoinst-log.txt

mkittler, 2022-03-07 14:46

 
[2022-03-04T14:51:20.929506Z] [info] [pid:5677] +++ setup notes +++
[2022-03-04T14:51:20.929720Z] [info] [pid:5677] Running on 2352cabdad7e:1 (Linux 5.11.0-1027-aws #30~20.04.1-Ubuntu SMP Thu Jan 13 11:46:53 UTC 2022 x86_64)
[2022-03-04T14:51:20.935400Z] [debug] [pid:5684] +++ worker notes +++
[2022-03-04T14:51:22.661668Z] [debug] Current version is d410cc0dd1aa541233ea295ddfbe1d94a78c33ad [interface v25]
[2022-03-04T14:51:22.670058Z] [debug] git hash in tinycore: d410cc0dd1aa541233ea295ddfbe1d94a78c33ad
[2022-03-04T14:51:22.754594Z] [debug] scheduling boot tests/boot.pm
[2022-03-04T14:51:22.755257Z] [debug] scheduling assert_screen tests/assert_screen.pm
[2022-03-04T14:51:22.755824Z] [debug] scheduling shutdown tests/shutdown.pm
[2022-03-04T14:51:22.762148Z] [info] cmdsrv: daemon reachable under http://*:20013/HuJE8brETsErmS7X/
[2022-03-04T14:51:22.764194Z] [info] Listening at "http://0.0.0.0:20013"
Web application available at http://0.0.0.0:20013
[2022-03-04T14:51:22.765537Z] [debug] git hash in tinycore/needles: d410cc0dd1aa541233ea295ddfbe1d94a78c33ad
[2022-03-04T14:51:22.765645Z] [debug] init needles from tinycore/needles
[2022-03-04T14:51:22.767064Z] [debug] loaded 4 needles
[2022-03-04T14:51:22.769864Z] [debug] Blocking SIGCHLD and SIGTERM
[2022-03-04T14:51:22.954791Z] [debug] Unblocking SIGCHLD and SIGTERM
[2022-03-04T14:51:23.025511Z] [debug] Blocking SIGCHLD and SIGTERM
[2022-03-04T14:51:23.025593Z] [debug] 5684: channel_out 15, channel_in 14
[2022-03-04T14:51:23.155465Z] [debug] Unblocking SIGCHLD and SIGTERM
[2022-03-04T14:51:23.158135Z] [debug] 5763: cmdpipe 13, rsppipe 16
[2022-03-04T14:51:23.158320Z] [debug] started mgmt loop with pid 5763
[2022-03-04T14:51:23.356208Z] [debug] qemu version detected: 5.2.0
[2022-03-04T14:51:23.357333Z] [debug] running `/usr/bin/chattr +C /home/squamata/project/test-results/fullstack/full-stack.d/openqa/pool/1/raid`
[2022-03-04T14:51:23.364269Z] [debug] Fatal error in command `/usr/bin/chattr +C /home/squamata/project/test-results/fullstack/full-stack.d/openqa/pool/1/raid`: open3: exec of /usr/bin/chattr +C /home/squamata/project/test-results/fullstack/full-stack.d/openqa/pool/1/raid failed: No such file or directory at /usr/lib/perl5/vendor_perl/5.26.1/Mojo/IOLoop/ReadWriteProcess.pm line 127.
[2022-03-04T14:51:23.364352Z] [debug] Configuring storage controllers and block devices
[2022-03-04T14:51:23.364897Z] [debug] running `/usr/bin/qemu-img info --output=json /home/squamata/project/test-results/fullstack/full-stack.d/openqa/pool/1/Core-7.2.iso`
[2022-03-04T14:51:23.373703Z] [debug] Initializing block device images
[2022-03-04T14:51:23.373899Z] [debug] running `/usr/bin/qemu-img create -f qcow2 /home/squamata/project/test-results/fullstack/full-stack.d/openqa/pool/1/raid/hd0 10G`
[2022-03-04T14:51:23.414249Z] [debug] Formatting '/home/squamata/project/test-results/fullstack/full-stack.d/openqa/pool/1/raid/hd0', fmt=qcow2 cluster_size=65536 extended_l2=off compression_type=zlib size=10737418240 lazy_refcounts=off refcount_bits=16
[2022-03-04T14:51:23.414368Z] [debug] running `/usr/bin/qemu-img create -f qcow2 -F raw -b /home/squamata/project/test-results/fullstack/full-stack.d/openqa/pool/1/Core-7.2.iso /home/squamata/project/test-results/fullstack/full-stack.d/openqa/pool/1/raid/cd0-overlay0 11116544`
[2022-03-04T14:51:23.460632Z] [debug] Formatting '/home/squamata/project/test-results/fullstack/full-stack.d/openqa/pool/1/raid/cd0-overlay0', fmt=qcow2 cluster_size=65536 extended_l2=off compression_type=zlib size=11116544 backing_file=/home/squamata/project/test-results/fullstack/full-stack.d/openqa/pool/1/Core-7.2.iso backing_fmt=raw lazy_refcounts=off refcount_bits=16
[2022-03-04T14:51:23.460721Z] [debug] init_blockdev_images: Finished creating block devices
[2022-03-04T14:51:23.461726Z] [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 -no-shutdown -vnc :91,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 -device virtio-scsi-pci,id=scsi0 -blockdev driver=file,node-name=hd0-file,filename=/home/squamata/project/test-results/fullstack/full-stack.d/openqa/pool/1/raid/hd0,cache.no-flush=on -blockdev driver=qcow2,node-name=hd0,file=hd0-file,cache.no-flush=on -device virtio-blk,id=hd0-device,drive=hd0,serial=hd0 -blockdev driver=file,node-name=cd0-overlay0-file,filename=/home/squamata/project/test-results/fullstack/full-stack.d/openqa/pool/1/raid/cd0-overlay0,cache.no-flush=on -blockdev driver=qcow2,node-name=cd0-overlay0,file=cd0-overlay0-file,cache.no-flush=on -device scsi-cd,id=cd0-device,drive=cd0-overlay0,serial=cd0
[2022-03-04T14:51:23.465833Z] [debug] Waiting for 0 attempts
[2022-03-04T14:51:24.466442Z] [debug] Waiting for 1 attempts
[2022-03-04T14:51:25.466815Z] [debug] Finished after 2 attempts
[2022-03-04T14:51:25.468759Z] [debug] Establishing VNC connection to localhost:5991
[2022-03-04T14:51:25.471346Z] [debug] pointer type 0 0 640 480 -257
[2022-03-04T14:51:25.471429Z] [debug] led state 0 1 1 -261
[2022-03-04T14:51:25.530740Z] [debug] Start CPU
[2022-03-04T14:51:25.531012Z] [debug] EVENT {"data":{"client":{"family":"ipv4","host":"127.0.0.1","service":"34314","websocket":false},"server":{"auth":"none","family":"ipv4","host":"0.0.0.0","service":"5991","websocket":false}},"event":"VNC_CONNECTED","timestamp":{"microseconds":469379,"seconds":1646405485}}
[2022-03-04T14:51:25.531098Z] [debug] EVENT {"data":{"client":{"family":"ipv4","host":"127.0.0.1","service":"34314","websocket":false},"server":{"auth":"none","family":"ipv4","host":"0.0.0.0","service":"5991","websocket":false}},"event":"VNC_INITIALIZED","timestamp":{"microseconds":470311,"seconds":1646405485}}
[2022-03-04T14:51:25.531269Z] [debug] EVENT {"event":"RESUME","timestamp":{"microseconds":531198,"seconds":1646405485}}
GOT GO

[2022-03-04T14:51:25.539149Z] [debug] QEMU: QEMU emulator version 5.2.0 (SUSE Linux Enterprise 15)
[2022-03-04T14:51:25.539208Z] [debug] QEMU: Copyright (c) 2003-2020 Fabrice Bellard and the QEMU Project developers
[2022-03-04T14:51:25.542545Z] [debug] Snapshots are supported
[2022-03-04T14:51:25.543379Z] [debug] ||| starting boot tests/boot.pm
[2022-03-04T14:51:25.544855Z] [debug] tests/boot.pm:9 called testapi::assert_screen
[2022-03-04T14:51:25.545117Z] [debug] <<< testapi::assert_screen(mustmatch="core", timeout=15, no_wait=1)
[2022-03-04T14:51:25.558951Z] [debug] no match: 14.9s, best candidate: boot-core (0.00)
[2022-03-04T14:51:25.659693Z] [debug] no change: 14.8s
[2022-03-04T14:51:25.666334Z] [debug] no match: 14.8s, best candidate: boot-core (0.00)
[2022-03-04T14:51:25.767147Z] [debug] no change: 14.7s
[2022-03-04T14:51:25.773766Z] [debug] no match: 14.7s, best candidate: boot-core (0.00)
[2022-03-04T14:51:25.874552Z] [debug] no change: 14.6s
[2022-03-04T14:51:25.881183Z] [debug] no match: 14.6s, best candidate: boot-core (0.00)
[2022-03-04T14:51:25.982025Z] [debug] no change: 14.5s
[2022-03-04T14:51:25.988610Z] [debug] no match: 14.5s, best candidate: boot-core (0.00)
[2022-03-04T14:51:26.166842Z] [debug] >>> testapi::_handle_found_needle: found boot-core, similarity 0.97 @ 1/74
[2022-03-04T14:51:26.167572Z] [debug] tests/boot.pm:10 called testapi::send_key
[2022-03-04T14:51:26.167693Z] [debug] <<< testapi::send_key(key="ret", wait_screen_change=0, do_wait=0)
[2022-03-04T14:51:26.437488Z] [debug] tests/boot.pm:14 called testapi::assert_screen
[2022-03-04T14:51:26.437660Z] [debug] <<< testapi::assert_screen(mustmatch="on_prompt", timeout=90)
[2022-03-04T14:51:27.094900Z] [debug] no match: 89.3s, best candidate: boot-on_prompt (0.00)
[2022-03-04T14:51:28.091629Z] [debug] no match: 88.3s, best candidate: boot-on_prompt (0.00)
[2022-03-04T14:51:29.092813Z] [debug] no match: 87.3s, best candidate: boot-on_prompt (0.00)
[2022-03-04T14:51:30.093423Z] [debug] no match: 86.3s, best candidate: boot-on_prompt (0.00)
[2022-03-04T14:51:31.134225Z] [debug] no match: 85.3s, best candidate: boot-on_prompt (0.00)
[2022-03-04T14:51:32.095479Z] [debug] no match: 84.3s, best candidate: boot-on_prompt (0.00)
[2022-03-04T14:51:33.095598Z] [debug] no match: 83.3s, best candidate: boot-on_prompt (0.00)
[2022-03-04T14:51:34.096524Z] [debug] no match: 82.3s, best candidate: boot-on_prompt (0.00)
[2022-03-04T14:51:35.097265Z] [debug] no match: 81.3s, best candidate: boot-on_prompt (0.00)
[2022-03-04T14:51:36.138225Z] [debug] no match: 80.3s, best candidate: boot-on_prompt (0.00)
[2022-03-04T14:51:37.175418Z] [debug] >>> testapi::_handle_found_needle: found boot-on_prompt, similarity 1.00 @ 2/64
[2022-03-04T14:51:37.178074Z] [debug] ||| finished boot tests (runtime: 12 s)
[2022-03-04T14:51:37.179184Z] [debug] ||| starting assert_screen tests/assert_screen.pm
[2022-03-04T14:51:37.179878Z] [debug] tests/assert_screen.pm:9 called testapi::assert_screen
[2022-03-04T14:51:37.180022Z] [debug] <<< testapi::assert_screen(mustmatch="on_prompt", timeout=60)
[2022-03-04T14:51:38.161545Z] [debug] >>> testapi::_handle_found_needle: found boot-on_prompt, similarity 1.00 @ 2/64
[2022-03-04T14:51:38.161809Z] [debug] tests/assert_screen.pm:10 called testapi::assert_screen
[2022-03-04T14:51:38.161981Z] [debug] <<< testapi::assert_screen(mustmatch="on_prompt", no_wait=1, timeout=30)
[2022-03-04T14:51:38.229251Z] [debug] >>> testapi::_handle_found_needle: found boot-on_prompt, similarity 1.00 @ 2/64
[2022-03-04T14:51:38.230446Z] [debug] ||| finished assert_screen tests (runtime: 1 s)
[2022-03-04T14:51:38.231341Z] [debug] ||| starting shutdown tests/shutdown.pm
[2022-03-04T14:51:38.231718Z] [debug] isotovideo: pausing test execution of shutdown because we're supposed to pause at this test module
[2022-03-04T14:51:38.232081Z] [debug] tests/shutdown.pm:8 called testapi::enter_cmd
[2022-03-04T14:51:38.232236Z] [debug] <<< testapi::type_string(string="sudo poweroff", max_interval=250, wait_screen_changes=0, wait_still_screen=0, timeout=30, similarity_level=47)
[2022-03-04T14:51:38.232554Z] [debug] isotovideo: paused, so not passing backend_type_string to backend
[2022-03-04T14:51:39.340673Z] [debug] isotovideo: test execution will be resumed
[2022-03-04T14:51:39.341050Z] [debug] isotovideo: resuming, continue passing backend_type_string to backend
[2022-03-04T14:51:39.814719Z] [debug] tests/shutdown.pm:9 called testapi::assert_shutdown
[2022-03-04T14:51:39.814862Z] [debug] <<< testapi::check_shutdown(timeout=90)
[2022-03-04T14:51:39.815695Z] [debug] QEMU status is not 'shutdown', it is 'running'
[2022-03-04T14:51:40.816931Z] [debug] QEMU status is not 'shutdown', it is 'running'
[2022-03-04T14:51:41.818229Z] [debug] QEMU status is not 'shutdown', it is 'running'
[2022-03-04T14:51:42.819379Z] [debug] EVENT {"data":{"path":"\/machine\/peripheral-anon\/device[2]\/virtio-backend"},"event":"NIC_RX_FILTER_CHANGED","timestamp":{"microseconds":976855,"seconds":1646405501}}
[2022-03-04T14:51:42.819577Z] [debug] QEMU status is not 'shutdown', it is 'running'
[2022-03-04T14:51:43.820885Z] [debug] QEMU status is not 'shutdown', it is 'running'
[2022-03-04T14:51:44.822302Z] [debug] QEMU status is not 'shutdown', it is 'running'
[2022-03-04T14:51:45.823569Z] [debug] QEMU status is not 'shutdown', it is 'running'
[2022-03-04T14:51:46.824914Z] [debug] QEMU status is not 'shutdown', it is 'running'
[2022-03-04T14:51:47.826305Z] [debug] QEMU status is not 'shutdown', it is 'running'
[2022-03-04T14:51:48.827757Z] [debug] QEMU status is not 'shutdown', it is 'running'
[2022-03-04T14:51:49.828941Z] [debug] QEMU status is not 'shutdown', it is 'running'
[2022-03-04T14:51:50.830323Z] [debug] QEMU status is not 'shutdown', it is 'running'
[2022-03-04T14:51:51.831668Z] [debug] QEMU status is not 'shutdown', it is 'running'
[2022-03-04T14:51:52.833051Z] [debug] QEMU status is not 'shutdown', it is 'running'
[2022-03-04T14:51:53.834539Z] [debug] QEMU status is not 'shutdown', it is 'running'
[2022-03-04T14:51:54.835834Z] [debug] QEMU status is not 'shutdown', it is 'running'
[2022-03-04T14:51:55.837226Z] [debug] QEMU status is not 'shutdown', it is 'running'
[2022-03-04T14:51:56.838739Z] [debug] QEMU status is not 'shutdown', it is 'running'
[2022-03-04T14:51:57.840131Z] [debug] QEMU status is not 'shutdown', it is 'running'
[2022-03-04T14:51:58.841385Z] [debug] QEMU status is not 'shutdown', it is 'running'
[2022-03-04T14:51:59.842817Z] [debug] QEMU status is not 'shutdown', it is 'running'
[2022-03-04T14:52:00.844296Z] [debug] QEMU status is not 'shutdown', it is 'running'
[2022-03-04T14:52:01.845845Z] [debug] QEMU status is not 'shutdown', it is 'running'
[2022-03-04T14:52:02.847156Z] [debug] QEMU status is not 'shutdown', it is 'running'
[2022-03-04T14:52:03.848558Z] [debug] QEMU status is not 'shutdown', it is 'running'
[2022-03-04T14:52:04.850050Z] [debug] QEMU status is not 'shutdown', it is 'running'
[2022-03-04T14:52:05.851408Z] [debug] QEMU status is not 'shutdown', it is 'running'
[2022-03-04T14:52:06.852872Z] [debug] QEMU status is not 'shutdown', it is 'running'
[2022-03-04T14:52:07.854301Z] [debug] QEMU status is not 'shutdown', it is 'running'
[2022-03-04T14:52:08.855742Z] [debug] QEMU status is not 'shutdown', it is 'running'
[2022-03-04T14:52:09.857333Z] [debug] QEMU status is not 'shutdown', it is 'running'
[2022-03-04T14:52:10.858800Z] [debug] QEMU status is not 'shutdown', it is 'running'
[2022-03-04T14:52:11.860365Z] [debug] QEMU status is not 'shutdown', it is 'running'
[2022-03-04T14:52:12.861811Z] [debug] QEMU status is not 'shutdown', it is 'running'
[2022-03-04T14:52:13.863243Z] [debug] QEMU status is not 'shutdown', it is 'running'
[2022-03-04T14:52:14.864704Z] [debug] QEMU status is not 'shutdown', it is 'running'
[2022-03-04T14:52:15.866295Z] [debug] QEMU status is not 'shutdown', it is 'running'
[2022-03-04T14:52:16.867674Z] [debug] QEMU status is not 'shutdown', it is 'running'
[2022-03-04T14:52:17.869112Z] [debug] QEMU status is not 'shutdown', it is 'running'
[2022-03-04T14:52:18.870595Z] [debug] QEMU status is not 'shutdown', it is 'running'
[2022-03-04T14:52:19.872018Z] [debug] QEMU status is not 'shutdown', it is 'running'
[2022-03-04T14:52:20.873323Z] [debug] QEMU status is not 'shutdown', it is 'running'
[2022-03-04T14:52:21.874688Z] [debug] QEMU status is not 'shutdown', it is 'running'
[2022-03-04T14:52:22.876012Z] [debug] QEMU status is not 'shutdown', it is 'running'
[2022-03-04T14:52:23.877436Z] [debug] QEMU status is not 'shutdown', it is 'running'
[2022-03-04T14:52:24.878760Z] [debug] QEMU status is not 'shutdown', it is 'running'
[2022-03-04T14:52:25.880108Z] [debug] QEMU status is not 'shutdown', it is 'running'
[2022-03-04T14:52:26.881540Z] [debug] QEMU status is not 'shutdown', it is 'running'
[2022-03-04T14:52:27.882983Z] [debug] QEMU status is not 'shutdown', it is 'running'
[2022-03-04T14:52:28.884458Z] [debug] QEMU status is not 'shutdown', it is 'running'
[2022-03-04T14:52:29.885883Z] [debug] QEMU status is not 'shutdown', it is 'running'
[2022-03-04T14:52:30.887286Z] [debug] QEMU status is not 'shutdown', it is 'running'
[2022-03-04T14:52:31.888789Z] [debug] QEMU status is not 'shutdown', it is 'running'
[2022-03-04T14:52:32.890108Z] [debug] QEMU status is not 'shutdown', it is 'running'
[2022-03-04T14:52:33.891583Z] [debug] QEMU status is not 'shutdown', it is 'running'
[2022-03-04T14:52:34.893003Z] [debug] QEMU status is not 'shutdown', it is 'running'
[2022-03-04T14:52:35.894322Z] [debug] QEMU status is not 'shutdown', it is 'running'
[2022-03-04T14:52:36.895673Z] [debug] QEMU status is not 'shutdown', it is 'running'
[2022-03-04T14:52:37.897013Z] [debug] QEMU status is not 'shutdown', it is 'running'
[2022-03-04T14:52:38.898517Z] [debug] QEMU status is not 'shutdown', it is 'running'
[2022-03-04T14:52:39.899860Z] [debug] QEMU status is not 'shutdown', it is 'running'
[2022-03-04T14:52:40.901191Z] [debug] QEMU status is not 'shutdown', it is 'running'
[2022-03-04T14:52:41.902602Z] [debug] QEMU status is not 'shutdown', it is 'running'
[2022-03-04T14:52:42.903885Z] [debug] QEMU status is not 'shutdown', it is 'running'
[2022-03-04T14:52:43.905183Z] [debug] QEMU status is not 'shutdown', it is 'running'
[2022-03-04T14:52:44.906619Z] [debug] QEMU status is not 'shutdown', it is 'running'
[2022-03-04T14:52:45.908007Z] [debug] QEMU status is not 'shutdown', it is 'running'
[2022-03-04T14:52:46.909432Z] [debug] QEMU status is not 'shutdown', it is 'running'
[2022-03-04T14:52:47.910810Z] [debug] QEMU status is not 'shutdown', it is 'running'
[2022-03-04T14:52:48.912165Z] [debug] QEMU status is not 'shutdown', it is 'running'
[2022-03-04T14:52:49.913451Z] [debug] QEMU status is not 'shutdown', it is 'running'
[2022-03-04T14:52:50.914764Z] [debug] QEMU status is not 'shutdown', it is 'running'
[2022-03-04T14:52:51.916084Z] [debug] QEMU status is not 'shutdown', it is 'running'
[2022-03-04T14:52:52.917420Z] [debug] QEMU status is not 'shutdown', it is 'running'
[2022-03-04T14:52:53.918792Z] [debug] QEMU status is not 'shutdown', it is 'running'
[2022-03-04T14:52:54.920232Z] [debug] QEMU status is not 'shutdown', it is 'running'
[2022-03-04T14:52:55.921644Z] [debug] QEMU status is not 'shutdown', it is 'running'
[2022-03-04T14:52:56.922892Z] [debug] QEMU status is not 'shutdown', it is 'running'
[2022-03-04T14:52:57.924286Z] [debug] QEMU status is not 'shutdown', it is 'running'
[2022-03-04T14:52:58.925657Z] [debug] QEMU status is not 'shutdown', it is 'running'
[2022-03-04T14:52:59.926951Z] [debug] QEMU status is not 'shutdown', it is 'running'
[2022-03-04T14:53:00.928387Z] [debug] QEMU status is not 'shutdown', it is 'running'
[2022-03-04T14:53:01.929738Z] [debug] QEMU status is not 'shutdown', it is 'running'
[2022-03-04T14:53:02.931012Z] [debug] QEMU status is not 'shutdown', it is 'running'
[2022-03-04T14:53:03.932380Z] [debug] QEMU status is not 'shutdown', it is 'running'
[2022-03-04T14:53:04.933757Z] [debug] QEMU status is not 'shutdown', it is 'running'
[2022-03-04T14:53:05.935171Z] [debug] QEMU status is not 'shutdown', it is 'running'
[2022-03-04T14:53:06.936548Z] [debug] QEMU status is not 'shutdown', it is 'running'
[2022-03-04T14:53:07.937887Z] [debug] QEMU status is not 'shutdown', it is 'running'
[2022-03-04T14:53:08.939239Z] [debug] QEMU status is not 'shutdown', it is 'running'
[2022-03-04T14:53:09.940573Z] [debug] QEMU status is not 'shutdown', it is 'running'
[2022-03-04T14:53:11.000724Z] [info] ::: basetest::runtest: # Test died: Machine didn't shut down! at tinycore/tests/shutdown.pm line 9.
[2022-03-04T14:53:11.002986Z] [debug] ||| finished shutdown tests (runtime: 92 s)
[2022-03-04T14:53:11.003049Z] [debug] ||| post fail hooks runtime: 0 s
[2022-03-04T14:53:11.003330Z] [debug] stopping overall test execution after a fatal test failure
[2022-03-04T14:53:11.004284Z] [debug] stopping autotest process 5693
[2022-03-04T14:53:11.008317Z] [debug] [autotest] process exited: 0
[2022-03-04T14:53:11.108699Z] [debug] done with autotest process
[2022-03-04T14:53:11.109088Z] [debug] stopping command server 5690 because test execution ended
[2022-03-04T14:53:11.109150Z] [debug] isotovideo: informing websocket clients before stopping command server: http://127.0.0.1:20013/HuJE8brETsErmS7X/broadcast
[2022-03-04T14:53:11.121881Z] [debug] commands process exited: 0
[2022-03-04T14:53:11.222225Z] [debug] done with command server
[2022-03-04T14:53:11.222291Z] [debug] isotovideo done
[2022-03-04T14:53:11.222974Z] [debug] QEMU status is not 'shutdown', it is 'running'
[2022-03-04T14:53:11.223101Z] [debug] backend shutdown state:
[2022-03-04T14:53:11.223456Z] [info] ::: OpenQA::Qemu::Proc::save_state: Saving QEMU state to qemu_state.json
[2022-03-04T14:53:12.233059Z] [debug] Passing remaining frames to the video encoder
[2022-03-04T14:53:12.255539Z] [debug] Waiting for video encoder to finalize the video
[2022-03-04T14:53:12.255623Z] [debug] The built-in video encoder (pid 5833) terminated
[2022-03-04T14:53:12.256111Z] [debug] QEMU: qemu-system-i386: terminating on signal 15 from pid 5763 (/home/squamata/os-autoinst/isotovideo: backen)
[2022-03-04T14:53:12.256900Z] [debug] sending magic and exit
[2022-03-04T14:53:12.257133Z] [debug] received magic close
[2022-03-04T14:53:12.263160Z] [debug] backend process exited: 0
[2022-03-04T14:53:12.364031Z] [debug] stopping backend process 5763
[2022-03-04T14:53:12.364099Z] [debug] done with backend process
5684: EXIT 0
[2022-03-04T14:53:12.379620Z] [info] [pid:5677] Isotovideo exit status: 0
[2022-03-04T14:53:12.409284Z] [info] [pid:5677] +++ worker notes +++
[2022-03-04T14:53:12.409584Z] [info] [pid:5677] End time: 2022-03-04 14:53:12
[2022-03-04T14:53:12.409722Z] [info] [pid:5677] Result: done
[2022-03-04T14:53:12.416420Z] [info] [pid:6006] Uploading video.ogv
[2022-03-04T14:53:12.446305Z] [info] [pid:6006] Uploading vars.json
[2022-03-04T14:53:12.470062Z] [info] [pid:6006] Uploading autoinst-log.txt
(1-1/2)