Project

General

Profile

Download (222 KB)

action #106912 » full-stack-shutdown-again-detailed-log.txt

mkittler, 2022-02-16 11:59

 
# OPENQA_BASEDIR: /tmp/7v4CAal1xt/full-stack.d
# OPENQA_CONFIG: /tmp/7v4CAal1xt/full-stack.d/config
[INFO] using database schema "public"
[info] [pid:12072] setting database search path to public when registering Minion plugin
ok 1 - assets are prefetched
# Used ports: {}
# Starting WebSocket service. Port: 9527
# Bogus: 0 | No wait: 0
# PID of openqa-websocket: 12076
# Starting WebUI service. Port: 9526
# PID of openqa-webapi: 12077
[info] [pid:12077] setting database search path to public when registering Minion plugin
[info] Listening at "http://127.0.0.1:9527"
Web application available at http://127.0.0.1:9527
# PID of openqa-livehandler: 12156
ok 2 - resultdir "/tmp/7v4CAal1xt/full-stack.d/openqa/testresults" exists
ok 3 - on main page
ok 4 - no one logged in
ok 5 - click_ok'Login clicked'
ok 6 - back on main page
ok 7 - click_ok'disable tour permanently'
ok 8 - click_ok'confirm dismissing tour'
[warn] [pid:12077] Unable to wakeup scheduler: Connection refused
ok 9 - click_ok'Clicked All Tests to look for scheduled job'
ok 10 - tests followed
# Wait for jQuery successful: wait before checking for scheduled job
[debug] [pid:12077] Unrecognized referer 'localhost'
[debug] [pid:12077] Unrecognized referer 'localhost'
ok 11 - scheduled test page
ok 12 - test 1 is scheduled
ok 13 - no unexpected js warnings after test 1 was scheduled
# Subtest: testhelper
ok 1 - BAIL_OUT invoked
[debug] [pid:12077] Unrecognized referer 'localhost'
# scheduled jobs: [
# {
# 'cluster_jobs' => {
# '1' => {
# 'chained_children' => [],
# 'chained_parents' => [],
# 'directly_chained_children' => [],
# 'directly_chained_parents' => [],
# 'is_parent_or_initial_job' => 1,
# 'ok' => 0,
# 'parallel_children' => [],
# 'parallel_parents' => [],
# 'state' => 'scheduled'
# }
# },
# 'id' => 1,
# 'priority' => 50,
# 'priority_offset' => 0,
# 'state' => 'scheduled',
# 'test' => 'core',
# 'worker_classes' => [
# 'qemu_i386'
# ]
# }
# ]
# free workers: []
ok 2 - fail invoked
1..2
ok 14 - testhelper
ok 15 - Worker started as IPC::Run=HASH(0x55eab0de40c0)
ok 16 - job with worker class qemu_i386 scheduled
[info] [pid:12162] worker 1:
- config file: /tmp/7v4CAal1xt/full-stack.d/config/workers.ini
- worker hostname: 1234cbae1a16
- isotovideo version: 24
- websocket API version: 1
- web UI hosts: http://localhost:9526
- class: qemu_i386,qemu_x86_64
- no cleanup: no
- pool directory: /tmp/7v4CAal1xt/full-stack.d/openqa/pool/1
[info] [pid:12162] Project dir for host http://localhost:9526 is /tmp/7v4CAal1xt/full-stack.d/openqa/share
[info] [pid:12162] Registering with openQA http://localhost:9526
[info] [pid:12162] Establishing ws connection via ws://localhost:9526/api/v1/ws/1
ok 17 - at least one free worker with class qemu_i386 registered
[info] [pid:12162] Registered and connected via websockets with openQA host http://localhost:9526 and worker ID 1
[debug] [pid:12072] +=----------------=+
[debug] [pid:12072] -> Scheduling new jobs.
[debug] [pid:12072] Free workers: 1/1
[debug] [pid:12076] Updating seen of worker 1 from worker_status (free)
[debug] [pid:12072] Scheduled jobs: 1
[debug] [pid:12072] Need to schedule 1 parallel jobs for job 1 (with priority 50)
[debug] [pid:12072] Assigned job '1' to worker ID '1'
[debug] [pid:12072] [Job#1] Prepare for being processed by worker 1
[debug] [pid:12076] Started to send message to 1 for job(s) 1
[debug] [pid:12162] Accepting job 1 from http://localhost:9526.
[debug] [pid:12072] Sent job(s) '1' to worker '1'
[debug] [pid:12072] Scheduler took 0.10719s to perform operations and allocated 1 jobs
[debug] [pid:12162] Setting job 1 from http://localhost:9526 up
[debug] [pid:12072] Allocated: { job => 1, worker => 1 }
[debug] [pid:12162] Preparing Mojo::IOLoop::ReadWriteProcess::Session
[info] [pid:12162] +++ setup notes +++
[info] [pid:12162] Running on 1234cbae1a16:1 (Linux 5.11.0-1027-aws #30~20.04.1-Ubuntu SMP Thu Jan 13 11:46:53 UTC 2022 x86_64)
[debug] [pid:12162] Job settings:
[debug] [pid:12162]
ARCH=i386
BUILD=1
DISTRI=tinycore
FLAVOR=flavor
INTEGRATION_TESTS=1
ISO=Core-7.2.iso
JOBTOKEN=Dlzx3oXeqolMvMJJ
LOG_LEVEL=debug
MACHINE=coolone
NAME=00000001-tinycore-1-flavor-i386-Build1-core@coolone
OPENQA_HOSTNAME=localhost:9526
OPENQA_URL=http://localhost:9526
PAUSE_AT=shutdown
PRJDIR=/tmp/7v4CAal1xt/full-stack.d/openqa/share
PUBLISH_HDD_1=core-hdd.qcow2
QEMU=i386
QEMUPORT=20012
QEMU_NO_FDC_SET=1
QEMU_NO_KVM=1
QEMU_NO_TABLET=1
RETRY_DELAY=5
RETRY_DELAY_IF_WEBUI_BUSY=60
TEST=core
UEFI_PFLASH_VARS=/usr/share/qemu/ovmf-x86_64.bin
VERSION=1
VNC=91
WORKER_CLASS=qemu_i386,qemu_x86_64
WORKER_HOSTNAME=127.0.0.1
WORKER_ID=1
WORKER_INSTANCE=1
[debug] [pid:12162] Linked asset "/tmp/7v4CAal1xt/full-stack.d/openqa/share/factory/iso/Core-7.2.iso" to "/tmp/7v4CAal1xt/full-stack.d/openqa/pool/1/Core-7.2.iso"
[debug] [pid:12162] Symlinked from "/tmp/7v4CAal1xt/full-stack.d/openqa/share/tests/tinycore" to "/tmp/7v4CAal1xt/full-stack.d/openqa/pool/1/tinycore"
[info] [pid:12162] Preparing cgroup to start isotovideo
[warn] [pid:12162] Disabling cgroup usage because cgroup creation failed: mkdir /sys/fs/cgroup/systemd/docker: Permission denied at /usr/lib/perl5/vendor_perl/5.26.1/Mojo/File.pm line 84.
[info] [pid:12162] You can define a custom slice with OPENQA_CGROUP_SLICE or indicating the base mount with MOJO_CGROUP_FS.
[info] [pid:12162] Starting isotovideo container
# Wait for jQuery successful: wait_for_result_panel: waiting for '(?^u:State: running)' (count 0 of 3240)
[debug] [pid:12162] Registered process:12169
[info] [pid:12169] 12169: WORKING 1
[info] [pid:12162] isotovideo has been started (PID: 12169)
[debug] [pid:12169] +++ worker notes +++
[debug] [pid:12162] Running job 1 from http://localhost:9526: 00000001-tinycore-1-flavor-i386-Build1-core@coolone.
[debug] [pid:12162] REST-API call: POST http://localhost:9526/api/v1/jobs/1/status
[debug] [pid:12076] Worker 1 accepted job 1
[debug] [pid:12076] Updating seen of worker 1 from worker_status (working)
[debug] [pid:12162] Upload concluded (no current module)
# Wait for jQuery successful: wait_for_result_panel: waiting for '(?^u:State: running)' (count 1 of 3240)
# Wait for jQuery successful: wait_for_result_panel: waiting for '(?^u:State: running)' (count 2 of 3240)
# Wait for jQuery successful: wait_for_result_panel: waiting for '(?^u:State: running)' (count 3 of 3240)
# Wait for jQuery successful: wait_for_result_panel: waiting for '(?^u:State: running)' (count 4 of 3240)
[debug] [pid:12077] Unrecognized referer 'localhost'
[debug] [pid:12077] Unrecognized referer 'localhost'
[debug] [pid:12077] Unrecognized referer 'localhost'
[debug] [pid:12077] Unrecognized referer 'localhost'
[debug] [pid:12156] connecting to os-autoinst command server for job 1 at ws://127.0.0.1:20013/Dlzx3oXeqolMvMJJ/ws
[debug] [pid:12077] Unrecognized referer 'localhost'
[debug] [pid:12077] Asking the worker 1 to start providing livestream for job 1
[debug] [pid:12162] Starting livelog
[debug] [pid:12162] REST-API call: POST http://localhost:9526/api/v1/jobs/1/status
[debug] [pid:12162] Upload concluded (no current module)
# Wait for jQuery successful: wait_for_result_panel: waiting for '(?^u:State: running)' (count 5 of 3240)
ok 18 - \#nav-item-for-live present
ok 19 - test 1 is running
# Subtest: wait until developer console becomes available
[debug] [pid:12077] Asking worker 1 to stop providing livestream for job 1
[debug] [pid:12162] Stopping livelog
# Waiting for 'URL for os-autoinst cmd srv' to become available
# waiting for worker to propagate URL for os-autoinst cmd srv
# Wait for jQuery successful: developer console available
ok 1 - No unexpected js warnings
ok 2 - found connection opened at 112
1..2
ok 20 - wait until developer console becomes available
# Subtest: pause at certain test
ok 1 - No unexpected js warnings
[debug] [pid:12162] REST-API call: POST http://localhost:9526/api/v1/jobs/1/status
[debug] [pid:12162] Upload concluded (no current module)
# waiting for paused, developer console contains:
# status: Connecting to ws://127.0.0.1:20013/Dlzx3oXeqolMvMJJ/ws
# status: Using proxy: no
# status: Connection opened
# ==> {"cmd":"status"}
# Wait for jQuery successful: (?^u:(\"paused\":|\"test_execution_paused\":\".*\")) remaining wait time 1075s
# waiting for paused, developer console contains:
# status: Connecting to ws://127.0.0.1:20013/Dlzx3oXeqolMvMJJ/ws
# status: Using proxy: no
# status: Connection opened
# ==> {"cmd":"status"}
# <== {"current_api_function":null,"current_test_full_name":null,"devel_mode_major_version":1,"devel_mode_minor_version":1,"pause_on_next_command":0,"pause_on_screen_mismatch":false,"pause_test_name":"shutdown","running":null,"tags":null,"test_execution_paused":0}
# <== {"can_handle":{"cmd":"backend_can_handle","function":"snapshots","json_cmd_token":"UooadNSe"},"current_api_function":"can_handle"}
# <== {"current_test_full_name":"tests-boot","set_current_test":"boot"}
# <== {"check_screen":{"check":0,"mustmatch":"core","timeout":15},"current_api_function":"assert_screen"}
# <== {"current_api_function":"send_key","send_key":{"cmd":"backend_send_key","json_cmd_token":"VpdUKuZr","key":"ret"}}
# <== {"check_screen":{"check":0,"mustmatch":"on_prompt","timeout":90},"current_api_function":"assert_screen"}
# Wait for jQuery successful: (?^u:(\"paused\":|\"test_execution_paused\":\".*\")) remaining wait time 1070s
[debug] [pid:12162] REST-API call: POST http://localhost:9526/api/v1/jobs/1/status
[debug] [pid:12162] Upload concluded (at boot)
# Wait for jQuery successful: (?^u:(\"paused\":|\"test_execution_paused\":\".*\")) remaining wait time 1065s
ok 2 - found paused at 1451
ok 3 - No unexpected js warnings
ok 4 - found resume at 2280
1..4
ok 21 - pause at certain test
# Subtest: schedule job
[debug] [pid:12077] Unrecognized referer 'localhost'
[debug] [pid:12077] Unrecognized referer 'localhost'
[debug] [pid:12077] Unrecognized referer 'localhost'
[debug] [pid:12156] connecting to os-autoinst command server for job 1 at ws://127.0.0.1:20013/Dlzx3oXeqolMvMJJ/ws
[debug] [pid:12077] Unrecognized referer 'localhost'
[debug] [pid:12077] Asking the worker 1 to start providing livestream for job 1
[debug] [pid:12162] Starting livelog
[debug] [pid:12162] REST-API call: POST http://localhost:9526/api/v1/jobs/1/status
[debug] [pid:12077] Unrecognized referer 'localhost'
[debug] [pid:12077] creating f41/844/68dbb276a03240907d0e7e500d.png
[debug] [pid:12077] creating 68d/7ac/83452b72555f8a6b386629f91f.png
# Wait for jQuery successful: wait_for_result_panel: waiting for '(?^u:Result: passed)' (count 0 of 3240)
[debug] [pid:12401] Optimizing /tmp/7v4CAal1xt/full-stack.d/openqa/pool/1/testresults/boot-1.png
[debug] [pid:12401] Uploading artefact boot-1.png as f4184468dbb276a03240907d0e7e500d
[debug] [pid:12401] Optimizing /tmp/7v4CAal1xt/full-stack.d/openqa/pool/1/testresults/.thumbs/boot-1.png
[debug] [pid:12401] Uploading artefact boot-1.png as f4184468dbb276a03240907d0e7e500d
[debug] [pid:12401] Optimizing /tmp/7v4CAal1xt/full-stack.d/openqa/pool/1/testresults/boot-2.png
[debug] [pid:12401] Uploading artefact boot-2.png as 68d7ac83452b72555f8a6b386629f91f
[debug] [pid:12401] Optimizing /tmp/7v4CAal1xt/full-stack.d/openqa/pool/1/testresults/.thumbs/boot-2.png
[debug] [pid:12401] Uploading artefact boot-2.png as 68d7ac83452b72555f8a6b386629f91f
[debug] [pid:12162] Upload concluded (up to boot)
# Wait for jQuery successful: wait_for_result_panel: waiting for '(?^u:Result: passed)' (count 1 of 3240)
# Wait for jQuery successful: wait_for_result_panel: waiting for '(?^u:Result: passed)' (count 2 of 3240)
[debug] [pid:12076] Updating seen of worker 1 from worker_status (working)
[debug] [pid:12162] REST-API call: POST http://localhost:9526/api/v1/jobs/1/status
[debug] [pid:12162] Upload concluded (at shutdown)
# Wait for jQuery successful: wait_for_result_panel: waiting for '(?^u:Result: passed)' (count 3 of 3240)
# Wait for jQuery successful: wait_for_result_panel: waiting for '(?^u:Result: passed)' (count 4 of 3240)
[debug] [pid:12162] REST-API call: POST http://localhost:9526/api/v1/jobs/1/status
[debug] [pid:12162] Upload concluded (at shutdown)
# Wait for jQuery successful: wait_for_result_panel: waiting for '(?^u:Result: passed)' (count 5 of 3240)
# Wait for jQuery successful: wait_for_result_panel: waiting for '(?^u:Result: passed)' (count 6 of 3240)
[debug] [pid:12162] REST-API call: POST http://localhost:9526/api/v1/jobs/1/status
# Wait for jQuery successful: wait_for_result_panel: waiting for '(?^u:Result: passed)' (count 7 of 3240)
[debug] [pid:12162] Upload concluded (at shutdown)
# Wait for jQuery successful: wait_for_result_panel: waiting for '(?^u:Result: passed)' (count 8 of 3240)
[debug] [pid:12162] REST-API call: POST http://localhost:9526/api/v1/jobs/1/status
# Wait for jQuery successful: wait_for_result_panel: waiting for '(?^u:Result: passed)' (count 9 of 3240)
[debug] [pid:12162] Upload concluded (at shutdown)
[debug] [pid:12077] Unrecognized referer 'localhost'
[debug] [pid:12077] Unrecognized referer 'localhost'
[debug] looking for "f41/844/.thumbs/68dbb276a03240907d0e7e500d.png" in ["/tmp/7v4CAal1xt/full-stack.d/openqa/images"]
[debug] found bless({
path => "/tmp/7v4CAal1xt/full-stack.d/openqa/images/f41/844/.thumbs/68dbb276a03240907d0e7e500d.png",
pid => 12077,
}, "Mojo::Asset::File")
[debug] looking for "68d/7ac/.thumbs/83452b72555f8a6b386629f91f.png" in ["/tmp/7v4CAal1xt/full-stack.d/openqa/images"]
[debug] found bless({
path => "/tmp/7v4CAal1xt/full-stack.d/openqa/images/68d/7ac/.thumbs/83452b72555f8a6b386629f91f.png",
pid => 12077,
}, "Mojo::Asset::File")
# Wait for jQuery successful: wait_for_result_panel: waiting for '(?^u:Result: passed)' (count 10 of 3240)
# Wait for jQuery successful: wait_for_result_panel: waiting for '(?^u:Result: passed)' (count 11 of 3240)
[debug] [pid:12162] REST-API call: POST http://localhost:9526/api/v1/jobs/1/status
[debug] [pid:12077] creating e3b/43b/69c91fe4072dac1037f416c281.png
[debug] [pid:12077] creating e3b/43b/69c91fe4072dac1037f416c281.png
[debug] [pid:12077] creating 4ec/328/64be46d7336c00b3b3f4a5fe6d.png
[debug] [pid:12411] Optimizing /tmp/7v4CAal1xt/full-stack.d/openqa/pool/1/testresults/shutdown-2.png
[debug] [pid:12411] Uploading artefact shutdown-2.png as 4ec32864be46d7336c00b3b3f4a5fe6d
[debug] [pid:12411] Optimizing /tmp/7v4CAal1xt/full-stack.d/openqa/pool/1/testresults/.thumbs/shutdown-2.png
[debug] [pid:12411] Uploading artefact shutdown-2.png as 4ec32864be46d7336c00b3b3f4a5fe6d
[debug] [pid:12411] Optimizing /tmp/7v4CAal1xt/full-stack.d/openqa/pool/1/testresults/assert_screen-2.png
[debug] [pid:12411] Uploading artefact assert_screen-2.png as e3b43b69c91fe4072dac1037f416c281
[debug] [pid:12411] Optimizing /tmp/7v4CAal1xt/full-stack.d/openqa/pool/1/testresults/.thumbs/assert_screen-2.png
[debug] [pid:12411] Uploading artefact assert_screen-2.png as e3b43b69c91fe4072dac1037f416c281
[debug] [pid:12162] Upload concluded (up to shutdown)
# Wait for jQuery successful: wait_for_result_panel: waiting for '(?^u:Result: passed)' (count 12 of 3240)
[info] [pid:12162] Isotovideo exit status: 0
[debug] [pid:12162] Stopping job 1 from http://localhost:9526: 00000001-tinycore-1-flavor-i386-Build1-core@coolone - reason: done
[debug] [pid:12162] REST-API call: POST http://localhost:9526/api/v1/jobs/1/status
[info] [pid:12162] +++ worker notes +++
[info] [pid:12162] End time: 2022-02-15 12:27:53
[info] [pid:12162] Result: done
[info] [pid:12422] Uploading core-hdd.qcow2
[info] [pid:12422] Uploading core-hdd.qcow2 using multiple chunks
[info] [pid:12422] core-hdd.qcow2: local upload (no chunks needed)
# Wait for jQuery successful: wait_for_result_panel: waiting for '(?^u:Result: passed)' (count 13 of 3240)
[info] [pid:12422] Uploading video.ogv
[debug] [pid:12422] Uploading artefact video.ogv
[info] [pid:12422] Uploading vars.json
[debug] [pid:12422] Uploading artefact vars.json
[info] [pid:12422] Uploading autoinst-log.txt
[debug] [pid:12422] Uploading artefact autoinst-log.txt
[info] [pid:12422] Uploading worker-log.txt
[debug] [pid:12422] Uploading artefact worker-log.txt
[info] [pid:12422] Uploading serial0.txt
[debug] [pid:12422] Uploading artefact serial0.txt
[info] [pid:12422] Uploading video_time.vtt
[debug] [pid:12422] Uploading artefact video_time.vtt
[info] [pid:12422] Uploading serial_terminal.txt
[debug] [pid:12422] Uploading artefact serial_terminal.txt
[info] [pid:12422] Uploading virtio_console1.log
[debug] [pid:12422] Uploading artefact virtio_console1.log
[debug] [pid:12162] Considering job 1 as regularly done
[debug] [pid:12162] REST-API call: POST http://localhost:9526/api/v1/jobs/1/status
[debug] [pid:12077] creating e3b/43b/69c91fe4072dac1037f416c281.png
[debug] [pid:12077] creating e3b/43b/69c91fe4072dac1037f416c281.png
[debug] [pid:12077] creating f41/844/68dbb276a03240907d0e7e500d.png
[debug] [pid:12077] creating 68d/7ac/83452b72555f8a6b386629f91f.png
[debug] [pid:12077] creating 4ec/328/64be46d7336c00b3b3f4a5fe6d.png
[debug] [pid:12162] Upload concluded (no current module)
[debug] [pid:12162] REST-API call: POST http://localhost:9526/api/v1/jobs/1/set_done?worker_id=1
# Wait for jQuery successful: wait_for_result_panel: waiting for '(?^u:Result: passed)' (count 14 of 3240)
[debug] [pid:12162] Job 1 from http://localhost:9526 finished - reason: done
[debug] [pid:12162] Cleaning up for next job
# Wait for jQuery successful: wait_for_result_panel: waiting for '(?^u:Result: passed)' (count 15 of 3240)
# Wait for jQuery successful: wait_for_result_panel: waiting for '(?^u:Result: passed)' (count 16 of 3240)
# Wait for jQuery successful: wait_for_result_panel: waiting for '(?^u:Result: passed)' (count 17 of 3240)
# Wait for jQuery successful: wait_for_result_panel: waiting for '(?^u:Result: passed)' (count 18 of 3240)
# Wait for jQuery successful: wait_for_result_panel: waiting for '(?^u:Result: passed)' (count 19 of 3240)
[debug] [pid:12077] Unrecognized referer 'localhost'
[debug] [pid:12077] Unrecognized referer 'localhost'
[debug] [pid:12077] Unrecognized referer 'localhost'
[debug] looking for "e3b/43b/.thumbs/69c91fe4072dac1037f416c281.png" in ["/tmp/7v4CAal1xt/full-stack.d/openqa/images"]
[debug] found bless({
path => "/tmp/7v4CAal1xt/full-stack.d/openqa/images/e3b/43b/.thumbs/69c91fe4072dac1037f416c281.png",
pid => 12077,
}, "Mojo::Asset::File")
[debug] looking for "4ec/328/.thumbs/64be46d7336c00b3b3f4a5fe6d.png" in ["/tmp/7v4CAal1xt/full-stack.d/openqa/images"]
[debug] found bless({
path => "/tmp/7v4CAal1xt/full-stack.d/openqa/images/4ec/328/.thumbs/64be46d7336c00b3b3f4a5fe6d.png",
pid => 12077,
}, "Mojo::Asset::File")
# Wait for jQuery successful: wait_for_result_panel: waiting for '(?^u:Result: passed)' (count 20 of 3240)
ok 1 - job 1 passed
ok 2 - autoinst log file generated
ok 3 - worker log file generated
ok 4 - autoinst log uploaded
ok 5 - worker log uploaded
ok 6 - local upload feature used
ok 7 - image of hdd uploaded
ok 8 - can stat /tmp/7v4CAal1xt/full-stack.d/openqa/share/factory/hdd/core-hdd.qcow2
ok 9 - exported image has correct permissions (420 -> 0644)
ok 10 - regular post via client script
ok 11 - send JSON data via client
ok 12 - group has been altered correctly
1..12
ok 22 - schedule job
# Subtest: clone job that crashes
[debug] Restarting job 1
[debug] [pid:12077] Duplicating jobs: {
1 => {
chained_children => [],
chained_parents => [],
directly_chained_children => [],
directly_chained_parents => [],
is_parent_or_initial_job => 1,
ok => 1,
parallel_children => [],
parallel_parents => [],
state => "done",
},
}
[debug] [pid:12077] Job 1 duplicated as 2
[warn] [pid:12077] Unable to wakeup scheduler: Connection refused
ok 1 - client returned new test_url for test 2
[debug] [pid:12077] Unrecognized referer 'localhost'
ok 2 - test 1 is restarted
[debug] looking for "f41/844/.thumbs/68dbb276a03240907d0e7e500d.png" in ["/tmp/7v4CAal1xt/full-stack.d/openqa/images"]
[debug] found bless({
path => "/tmp/7v4CAal1xt/full-stack.d/openqa/images/f41/844/.thumbs/68dbb276a03240907d0e7e500d.png",
pid => 12077,
}, "Mojo::Asset::File")
[debug] looking for "e3b/43b/.thumbs/69c91fe4072dac1037f416c281.png" in ["/tmp/7v4CAal1xt/full-stack.d/openqa/images"]
[debug] found bless({
path => "/tmp/7v4CAal1xt/full-stack.d/openqa/images/e3b/43b/.thumbs/69c91fe4072dac1037f416c281.png",
pid => 12077,
}, "Mojo::Asset::File")
[debug] looking for "68d/7ac/.thumbs/83452b72555f8a6b386629f91f.png" in ["/tmp/7v4CAal1xt/full-stack.d/openqa/images"]
[debug] found bless({
path => "/tmp/7v4CAal1xt/full-stack.d/openqa/images/68d/7ac/.thumbs/83452b72555f8a6b386629f91f.png",
pid => 12077,
}, "Mojo::Asset::File")
[debug] looking for "4ec/328/.thumbs/64be46d7336c00b3b3f4a5fe6d.png" in ["/tmp/7v4CAal1xt/full-stack.d/openqa/images"]
[debug] found bless({
path => "/tmp/7v4CAal1xt/full-stack.d/openqa/images/4ec/328/.thumbs/64be46d7336c00b3b3f4a5fe6d.png",
pid => 12077,
}, "Mojo::Asset::File")
[debug] [pid:12077] Unrecognized referer 'localhost'
ok 3 - click_ok'clicked link to test 2'
[debug] [pid:12077] Unrecognized referer 'localhost'
ok 4 - job with worker class qemu_i386 scheduled
[debug] [pid:12077] Unrecognized referer 'localhost'
ok 5 - at least one free worker with class qemu_i386 registered
[debug] [pid:12072] +=----------------=+
[debug] [pid:12072] -> Scheduling new jobs.
[debug] [pid:12072] Free workers: 1/1
[debug] [pid:12072] Scheduled jobs: 1
[debug] [pid:12072] Need to schedule 1 parallel jobs for job 2 (with priority 50)
[debug] [pid:12072] Assigned job '2' to worker ID '1'
[debug] [pid:12072] [Job#2] Prepare for being processed by worker 1
[debug] [pid:12076] Started to send message to 1 for job(s) 2
[debug] [pid:12072] Sent job(s) '2' to worker '1'
[debug] [pid:12072] Scheduler took 0.10311s to perform operations and allocated 1 jobs
[debug] [pid:12162] Accepting job 2 from http://localhost:9526.
[debug] [pid:12072] Allocated: { job => 2, worker => 1 }
[debug] [pid:12162] Setting job 2 from http://localhost:9526 up
[debug] [pid:12162] Preparing Mojo::IOLoop::ReadWriteProcess::Session
[info] [pid:12162] +++ setup notes +++
[info] [pid:12162] Running on 1234cbae1a16:1 (Linux 5.11.0-1027-aws #30~20.04.1-Ubuntu SMP Thu Jan 13 11:46:53 UTC 2022 x86_64)
[debug] [pid:12162] Job settings:
[debug] [pid:12162]
ARCH=i386
BUILD=1
DISTRI=tinycore
FLAVOR=flavor
INTEGRATION_TESTS=1
ISO=Core-7.2.iso
JOBTOKEN=W5s4P1p_dmxSymZf
LOG_LEVEL=debug
MACHINE=coolone
NAME=00000002-tinycore-1-flavor-i386-Build1-core@coolone
OPENQA_HOSTNAME=localhost:9526
OPENQA_URL=http://localhost:9526
PAUSE_AT=shutdown
PRJDIR=/tmp/7v4CAal1xt/full-stack.d/openqa/share
PUBLISH_HDD_1=core-hdd.qcow2
QEMU=i386
QEMUPORT=20012
QEMU_NO_FDC_SET=1
QEMU_NO_KVM=1
QEMU_NO_TABLET=1
RETRY_DELAY=5
RETRY_DELAY_IF_WEBUI_BUSY=60
TEST=core
UEFI_PFLASH_VARS=/usr/share/qemu/ovmf-x86_64.bin
VERSION=1
VNC=91
WORKER_CLASS=qemu_i386,qemu_x86_64
WORKER_HOSTNAME=127.0.0.1
WORKER_ID=1
WORKER_INSTANCE=1
[debug] [pid:12162] Linked asset "/tmp/7v4CAal1xt/full-stack.d/openqa/share/factory/iso/Core-7.2.iso" to "/tmp/7v4CAal1xt/full-stack.d/openqa/pool/1/Core-7.2.iso"
[debug] [pid:12162] Symlinked from "/tmp/7v4CAal1xt/full-stack.d/openqa/share/tests/tinycore" to "/tmp/7v4CAal1xt/full-stack.d/openqa/pool/1/tinycore"
[info] [pid:12162] Preparing cgroup to start isotovideo
[warn] [pid:12162] Disabling cgroup usage because cgroup creation failed: mkdir /sys/fs/cgroup/systemd/docker: Permission denied at /usr/lib/perl5/vendor_perl/5.26.1/Mojo/File.pm line 84.
[info] [pid:12162] You can define a custom slice with OPENQA_CGROUP_SLICE or indicating the base mount with MOJO_CGROUP_FS.
[info] [pid:12162] Starting isotovideo container
# Wait for jQuery successful: wait_for_result_panel: waiting for '(?^u:State: running)' (count 0 of 3240)
[debug] [pid:12162] Registered process:12434
[info] [pid:12434] 12434: WORKING 2
[info] [pid:12162] isotovideo has been started (PID: 12434)
[debug] [pid:12434] +++ worker notes +++
[debug] [pid:12162] Running job 2 from http://localhost:9526: 00000002-tinycore-1-flavor-i386-Build1-core@coolone.
[debug] [pid:12162] REST-API call: POST http://localhost:9526/api/v1/jobs/2/status
[debug] [pid:12076] Worker 1 accepted job 2
[debug] [pid:12076] Updating seen of worker 1 from worker_status (working)
[debug] [pid:12162] Upload concluded (no current module)
# Wait for jQuery successful: wait_for_result_panel: waiting for '(?^u:State: running)' (count 1 of 3240)
# Wait for jQuery successful: wait_for_result_panel: waiting for '(?^u:State: running)' (count 2 of 3240)
# Wait for jQuery successful: wait_for_result_panel: waiting for '(?^u:State: running)' (count 3 of 3240)
# Wait for jQuery successful: wait_for_result_panel: waiting for '(?^u:State: running)' (count 4 of 3240)
# Wait for jQuery successful: wait_for_result_panel: waiting for '(?^u:State: running)' (count 5 of 3240)
# Wait for jQuery successful: wait_for_result_panel: waiting for '(?^u:State: running)' (count 6 of 3240)
# Wait for jQuery successful: wait_for_result_panel: waiting for '(?^u:State: running)' (count 7 of 3240)
# Wait for jQuery successful: wait_for_result_panel: waiting for '(?^u:State: running)' (count 8 of 3240)
# Wait for jQuery successful: wait_for_result_panel: waiting for '(?^u:State: running)' (count 9 of 3240)
[debug] [pid:12077] Unrecognized referer 'localhost'
[debug] [pid:12077] Unrecognized referer 'localhost'
[debug] [pid:12077] Unrecognized referer 'localhost'
[debug] [pid:12156] connecting to os-autoinst command server for job 2 at ws://127.0.0.1:20013/W5s4P1p_dmxSymZf/ws
[debug] [pid:12077] Unrecognized referer 'localhost'
[debug] [pid:12077] Unrecognized referer 'localhost'
[debug] [pid:12077] Asking the worker 1 to start providing livestream for job 2
[debug] [pid:12162] Starting livelog
[debug] [pid:12162] REST-API call: POST http://localhost:9526/api/v1/jobs/2/status
# Wait for jQuery successful: wait_for_result_panel: waiting for '(?^u:State: running)' (count 10 of 3240)
[debug] [pid:12162] Upload concluded (at boot)
ok 6 - \#nav-item-for-live present
ok 7 - job 2 running
[info] [pid:12162] Received signal TERM
[debug] [pid:12162] Stopping job 2 from http://localhost:9526: 00000002-tinycore-1-flavor-i386-Build1-core@coolone - reason: quit
[debug] [pid:12162] REST-API call: POST http://localhost:9526/api/v1/jobs/2/status
[debug] [pid:12162] Announcing job termination (due to quit) to command server via http://localhost:20013/W5s4P1p_dmxSymZf/broadcast
[info] [pid:12162] Isotovideo exit status: 1
[info] [pid:12162] +++ worker notes +++
[info] [pid:12162] End time: 2022-02-15 12:28:09
[info] [pid:12162] Result: quit
[debug] [pid:12162] REST-API call: POST http://localhost:9526/api/v1/jobs/2/status
[debug] [pid:12162] Upload concluded (at boot)
[debug] [pid:12162] Job 2 stopped as incomplete
[debug] [pid:12162] Duplicating job 2
[debug] [pid:12162] REST-API call: POST http://localhost:9526/api/v1/jobs/2/duplicate?dup_type_auto=1
[debug] Restarting job 2
[debug] [pid:12077] Duplicating jobs: {
2 => {
chained_children => [],
chained_parents => [],
directly_chained_children => [],
directly_chained_parents => [],
is_parent_or_initial_job => 1,
ok => 0,
parallel_children => [],
parallel_parents => [],
state => "uploading",
},
}
[debug] [pid:12077] Job 2 duplicated as 3
[warn] [pid:12077] Unable to wakeup scheduler: Connection refused
[debug] [pid:12162] Unable to read result-assert_screen.json: Can't open file "/tmp/7v4CAal1xt/full-stack.d/openqa/pool/1/testresults/result-assert_screen.json": No such file or directory at /usr/lib/perl5/vendor_perl/5.26.1/Mojo/File.pm line 132.
Mojo::File::slurp(Mojo::File=SCALAR(0x561ec5f0eb80)) called at /home/squamata/project/script/../lib/OpenQA/Worker/Job.pm line 1098
eval {...} called at /home/squamata/project/script/../lib/OpenQA/Worker/Job.pm line 1098
OpenQA::Worker::Job::_read_json_file(OpenQA::Worker::Job=HASH(0x561ec5ef7908), "result-assert_screen.json") called at /home/squamata/project/script/../lib/OpenQA/Worker/Job.pm line 1154
OpenQA::Worker::Job::_read_module_result(OpenQA::Worker::Job=HASH(0x561ec5ef7908), "assert_screen") called at /home/squamata/project/script/../lib/OpenQA/Worker/Job.pm line 1116
OpenQA::Worker::Job::_read_result_file(OpenQA::Worker::Job=HASH(0x561ec5ef7908), "", ARRAY(0x561ec5e48050)) called at /home/squamata/project/script/../lib/OpenQA/Worker/Job.pm line 786
OpenQA::Worker::Job::_upload_results_step_0_prepare(OpenQA::Worker::Job=HASH(0x561ec5ef7908), CODE(0x561ec5ef2858)) called at /home/squamata/project/script/../lib/OpenQA/Worker/Job.pm line 715
OpenQA::Worker::Job::_upload_results(OpenQA::Worker::Job=HASH(0x561ec5ef7908), CODE(0x561ec5ef2858)) called at /home/squamata/project/script/../lib/OpenQA/Worker/Job.pm line 526
OpenQA::Worker::Job::__ANON__(HASH(0x561ec5f0ea60)) called at /home/squamata/project/script/../lib/OpenQA/Worker/WebUIConnection.pm line 301
OpenQA::Worker::WebUIConnection::__ANON__(OpenQA::Client=HASH(0x561ec5ddbfe8), Mojo::Transaction::HTTP=HASH(0x561ec5f11f28), 1) called at /home/squamata/project/script/../lib/OpenQA/Worker/WebUIConnection.pm line 335
OpenQA::Worker::WebUIConnection::__ANON__(OpenQA::Client=HASH(0x561ec5ddbfe8), Mojo::Transaction::HTTP=HASH(0x561ec5f11f28)) called at /usr/lib/perl5/vendor_perl/5.26.1/Mojo/UserAgent.pm line 249
Mojo::UserAgent::_finish(OpenQA::Client=HASH(0x561ec5ddbfe8), "f11d9491955ba7568cd0146b8b40003d") called at /usr/lib/perl5/vendor_perl/5.26.1/Mojo/UserAgent.pm line 276
Mojo::UserAgent::_read(OpenQA::Client=HASH(0x561ec5ddbfe8), "f11d9491955ba7568cd0146b8b40003d", "HTTP/1.1 200 OK\x{d}\x{a}Content-Type: application/json;charset=UTF-8"...) called at /usr/lib/perl5/vendor_perl/5.26.1/Mojo/UserAgent.pm line 136
Mojo::UserAgent::__ANON__(Mojo::IOLoop::Stream=HASH(0x561ec5f092a0)) called at /usr/lib/perl5/vendor_perl/5.26.1/Mojo/EventEmitter.pm line 15
Mojo::EventEmitter::emit(Mojo::IOLoop::Stream=HASH(0x561ec5f092a0), "read", "HTTP/1.1 200 OK\x{d}\x{a}Content-Type: application/json;charset=UTF-8"...) called at /usr/lib/perl5/vendor_perl/5.26.1/Mojo/IOLoop/Stream.pm line 109
Mojo::IOLoop::Stream::_read(Mojo::IOLoop::Stream=HASH(0x561ec5f092a0)) called at /usr/lib/perl5/vendor_perl/5.26.1/Mojo/IOLoop/Stream.pm line 57
Mojo::IOLoop::Stream::__ANON__(Mojo::Reactor::Poll=HASH(0x561ec3d72ba0)) called at /usr/lib/perl5/vendor_perl/5.26.1/Mojo/Reactor/Poll.pm line 141
eval {...} called at /usr/lib/perl5/vendor_perl/5.26.1/Mojo/Reactor/Poll.pm line 141
Mojo::Reactor::Poll::_try(Mojo::Reactor::Poll=HASH(0x561ec3d72ba0), "I/O watcher", CODE(0x561ec5e3bbe0), 0) called at /usr/lib/perl5/vendor_perl/5.26.1/Mojo/Reactor/Poll.pm line 60
Mojo::Reactor::Poll::one_tick(Mojo::Reactor::Poll=HASH(0x561ec3d72ba0)) called at /usr/lib/perl5/vendor_perl/5.26.1/Mojo/Reactor/Poll.pm line 101
Mojo::Reactor::Poll::start(Mojo::Reactor::Poll=HASH(0x561ec3d72ba0)) called at /usr/lib/perl5/vendor_perl/5.26.1/Mojo/IOLoop.pm line 134
Mojo::IOLoop::start(Mojo::IOLoop=HASH(0x561ec3acd7f0)) called at /home/squamata/project/script/../lib/OpenQA/Worker.pm line 376
OpenQA::Worker::exec(OpenQA::Worker=HASH(0x561ec5dcd640)) called at ./script/worker line 126
[debug] [pid:12162] REST-API call: POST http://localhost:9526/api/v1/jobs/2/status
[debug] [pid:12077] creating f41/844/68dbb276a03240907d0e7e500d.png
[debug] [pid:12162] Upload concluded (at boot)
[debug] [pid:12162] REST-API call: POST http://localhost:9526/api/v1/jobs/2/set_done?reason=quit%3A+worker+has+been+stopped+or+restarted&result=incomplete&worker_id=1
[debug] [pid:12077] checking take over from 1: GOOD vs assert_screen:none,shutdown:none
[debug] [pid:12162] Job 2 from http://localhost:9526 finished - reason: quit
[debug] [pid:12162] Informing http://localhost:9526 that we are going offline
[info] [pid:12076] Worker 1 websocket connection closed - 1006
# Wait for jQuery successful: wait_for_result_panel: waiting for '(?^u:Result: incomplete)' (count 0 of 3240)
# Wait for jQuery successful: wait_for_result_panel: waiting for '(?^u:Result: incomplete)' (count 1 of 3240)
# Wait for jQuery successful: wait_for_result_panel: waiting for '(?^u:Result: incomplete)' (count 2 of 3240)
[debug] [pid:12077] Unrecognized referer 'localhost'
[debug] [pid:12077] Unrecognized referer 'localhost'
[debug] [pid:12077] Unrecognized referer 'localhost'
[debug] looking for "f41/844/.thumbs/68dbb276a03240907d0e7e500d.png" in ["/tmp/7v4CAal1xt/full-stack.d/openqa/images"]
[debug] found bless({
path => "/tmp/7v4CAal1xt/full-stack.d/openqa/images/f41/844/.thumbs/68dbb276a03240907d0e7e500d.png",
pid => 12077,
}, "Mojo::Asset::File")
# Wait for jQuery successful: wait_for_result_panel: waiting for '(?^u:Result: incomplete)' (count 3 of 3240)
ok 8 - job 2 crashed
ok 9 - test 2 is restarted by killing worker
1..9
ok 23 - clone job that crashes
# Subtest: cancel a scheduled job
[warn] [pid:12077] Unable to wakeup scheduler: Connection refused
ok 1 - click_ok'Clicked All Tests'
# Wait for jQuery successful: wait for All Tests displayed before looking for 3
[debug] [pid:12077] Unrecognized referer 'localhost'
ok 2 - click_ok'clicked on 3'
[debug] [pid:12077] Unrecognized referer 'localhost'
[debug] [pid:12077] Unrecognized referer 'localhost'
# Wait for jQuery successful: wait_for_result_panel: waiting for '(?^u:State: scheduled)' (count 0 of 8100)
ok 3 - Job 3 was scheduled
1..3
ok 24 - cancel a scheduled job
ok 25 - click_ok'Clicked All Tests to go to test 4'
# Wait for jQuery successful: wait for All Tests displayed before looking for 3
[debug] [pid:12077] Unrecognized referer 'localhost'
[debug] [pid:12077] Unrecognized referer 'localhost'
ok 26 - click_ok'clicked on 4'
ok 27 - scheduled test page
ok 28 - test 4 is scheduled
ok 29 - no unexpected js warnings after test 4 was scheduled
[debug] [pid:12077] Unrecognized referer 'localhost'
ok 30 - Worker started as IPC::Run=HASH(0x55eab0eb69d0)
ok 31 - job with worker class qemu_i386 scheduled
[info] [pid:12644] worker 1:
- config file: /tmp/7v4CAal1xt/full-stack.d/config/workers.ini
- worker hostname: 1234cbae1a16
- isotovideo version: 24
- websocket API version: 1
- web UI hosts: http://localhost:9526
- class: qemu_i386,qemu_x86_64
- no cleanup: no
- pool directory: /tmp/7v4CAal1xt/full-stack.d/openqa/pool/1
[info] [pid:12644] Project dir for host http://localhost:9526 is /tmp/7v4CAal1xt/full-stack.d/openqa/share
[info] [pid:12644] Registering with openQA http://localhost:9526
[info] [pid:12644] Establishing ws connection via ws://localhost:9526/api/v1/ws/1
[info] [pid:12644] Registered and connected via websockets with openQA host http://localhost:9526 and worker ID 1
[debug] [pid:12076] Updating seen of worker 1 from worker_status (free)
ok 32 - at least one free worker with class qemu_i386 registered
[debug] [pid:12072] +=----------------=+
[debug] [pid:12072] -> Scheduling new jobs.
[debug] [pid:12072] Free workers: 1/1
[debug] [pid:12072] Scheduled jobs: 1
[debug] [pid:12072] Need to schedule 1 parallel jobs for job 4 (with priority 50)
[debug] [pid:12072] Assigned job '4' to worker ID '1'
[debug] [pid:12072] [Job#4] Prepare for being processed by worker 1
[debug] [pid:12076] Started to send message to 1 for job(s) 4
[debug] [pid:12072] Sent job(s) '4' to worker '1'
[debug] [pid:12072] Scheduler took 0.10219s to perform operations and allocated 1 jobs
[debug] [pid:12072] Allocated: { job => 4, worker => 1 }
# Subtest: incomplete job because of setup failure
[debug] [pid:12644] Accepting job 4 from http://localhost:9526.
[debug] [pid:12644] Setting job 4 from http://localhost:9526 up
[debug] [pid:12644] Preparing Mojo::IOLoop::ReadWriteProcess::Session
[info] [pid:12644] +++ setup notes +++
[info] [pid:12644] Running on 1234cbae1a16:1 (Linux 5.11.0-1027-aws #30~20.04.1-Ubuntu SMP Thu Jan 13 11:46:53 UTC 2022 x86_64)
[debug] [pid:12644] Job settings:
[debug] [pid:12644]
ARCH=i386
BUILD=1
DISTRI=tinycore
FLAVOR=flavor
HDD_1=nihilist_disk.hda
INTEGRATION_TESTS=1
ISO=Core-7.2.iso
JOBTOKEN=jYLqqzusM3UiJ4qg
LOG_LEVEL=debug
MACHINE=noassets
NAME=00000004-tinycore-1-flavor-i386-Build1-core@noassets
OPENQA_HOSTNAME=localhost:9526
OPENQA_URL=http://localhost:9526
PRJDIR=/tmp/7v4CAal1xt/full-stack.d/openqa/share
PUBLISH_HDD_1=core-hdd.qcow2
QEMU=i386
QEMUPORT=20012
QEMU_NO_FDC_SET=1
QEMU_NO_KVM=1
QEMU_NO_TABLET=1
RETRY_DELAY=5
RETRY_DELAY_IF_WEBUI_BUSY=60
TEST=core
UEFI_PFLASH_VARS=/usr/share/qemu/ovmf-x86_64.bin
VERSION=1
VNC=91
WORKER_CLASS=qemu_i386,qemu_x86_64
WORKER_HOSTNAME=127.0.0.1
WORKER_ID=1
WORKER_INSTANCE=1
# Wait for jQuery successful: wait_for_result_panel: waiting for '(?^u:Result: incomplete)' (count 0 of 3240)
[error] [pid:12644] HDD_1 handling Cannot find HDD_1 asset hdd/nihilist_disk.hda!
[error] [pid:12644] Unable to setup job 4: Cannot find HDD_1 asset hdd/nihilist_disk.hda!
[debug] [pid:12644] Stopping job 4 from http://localhost:9526: 00000004-tinycore-1-flavor-i386-Build1-core@noassets - reason: setup failure
[debug] [pid:12644] REST-API call: POST http://localhost:9526/api/v1/jobs/4/status
[debug] [pid:12076] Worker 1 accepted job 4
[info] [pid:12644] +++ worker notes +++
[info] [pid:12644] End time: 2022-02-15 12:28:18
[info] [pid:12644] Result: setup failure
[info] [pid:12650] Uploading autoinst-log.txt
[debug] [pid:12650] Uploading artefact autoinst-log.txt
[info] [pid:12650] Uploading worker-log.txt
[debug] [pid:12650] Uploading artefact worker-log.txt
[debug] [pid:12644] Job 4 stopped as incomplete
[warn] [pid:12644] Unable to upload results of the job because no command server URL or worker ID have been set.
[debug] [pid:12644] Upload concluded (no current module)
[debug] [pid:12644] REST-API call: POST http://localhost:9526/api/v1/jobs/4/set_done?reason=asset+failure%3A+Cannot+find+HDD_1+asset+hdd%2Fnihilist_disk.hda%21&result=incomplete&worker_id=1
[debug] [pid:12644] Job 4 from http://localhost:9526 finished - reason: setup failure
[debug] [pid:12644] Cleaning up for next job
# Wait for jQuery successful: wait_for_result_panel: waiting for '(?^u:Result: incomplete)' (count 1 of 3240)
# Wait for jQuery successful: wait_for_result_panel: waiting for '(?^u:Result: incomplete)' (count 2 of 3240)
# Wait for jQuery successful: wait_for_result_panel: waiting for '(?^u:Result: incomplete)' (count 3 of 3240)
# Wait for jQuery successful: wait_for_result_panel: waiting for '(?^u:Result: incomplete)' (count 4 of 3240)
[debug] [pid:12077] Unrecognized referer 'localhost'
[debug] [pid:12077] Unrecognized referer 'localhost'
# Wait for jQuery successful: wait_for_result_panel: waiting for '(?^u:Result: incomplete)' (count 5 of 3240)
ok 1 - Job 4 crashed
# Waiting for 'autoinst-log.txt' to become available
ok 2 - Test 4 result correct: setup failure
ok 3 - Test 4 correct autoinst setup notes
ok 4 - Test 4: upload of autoinst-log.txt logged
[info] [pid:12644] Received signal TERM
[debug] [pid:12644] Informing http://localhost:9526 that we are going offline
[info] [pid:12076] Worker 1 websocket connection closed - 1006
1..4
ok 33 - incomplete job because of setup failure
ok 34 - Setting up Cache directory
ok 35 - Config file created
# Subtest: Cache tests
ok 1 - cache.sqlite is not present
# Starting cache minion worker
# Waiting for 'cache service at http://127.0.0.1:9530' to become available
# Starting worker cache service on port 9530
# Waiting for 'cache service worker' to become available
[warn] [pid:12077] Unable to wakeup scheduler: Connection refused
[debug] [pid:12077] Unrecognized referer 'localhost'
ok 2 - test 5 is scheduled
ok 3 - Worker started as IPC::Run=HASH(0x55eab0eca758)
[debug] [pid:12077] Unrecognized referer 'localhost'
ok 4 - job with worker class qemu_i386 scheduled
[info] [pid:12658] worker 1:
- config file: /tmp/7v4CAal1xt/full-stack.d/config/workers.ini
- worker hostname: 1234cbae1a16
- isotovideo version: 24
- websocket API version: 1
- web UI hosts: http://localhost:9526
- class: qemu_i386,qemu_x86_64
- no cleanup: no
- pool directory: /tmp/7v4CAal1xt/full-stack.d/openqa/pool/1
[info] [pid:12658] CACHE: caching is enabled, setting up /tmp/7v4CAal1xt/full-stack.d/cache/localhost
[info] [pid:12658] Project dir for host http://localhost:9526 is /tmp/7v4CAal1xt/full-stack.d/openqa/share
[info] [pid:12658] Registering with openQA http://localhost:9526
[info] [pid:12658] Establishing ws connection via ws://localhost:9526/api/v1/ws/1
[info] [pid:12658] Registered and connected via websockets with openQA host http://localhost:9526 and worker ID 1
[debug] [pid:12076] Updating seen of worker 1 from worker_status (free)
ok 5 - at least one free worker with class qemu_i386 registered
[debug] [pid:12072] +=----------------=+
[debug] [pid:12072] -> Scheduling new jobs.
[debug] [pid:12072] Free workers: 1/1
[debug] [pid:12072] Scheduled jobs: 1
[debug] [pid:12072] Need to schedule 1 parallel jobs for job 5 (with priority 50)
[debug] [pid:12072] Assigned job '5' to worker ID '1'
[debug] [pid:12072] [Job#5] Prepare for being processed by worker 1
[debug] [pid:12076] Started to send message to 1 for job(s) 5
[debug] [pid:12072] Sent job(s) '5' to worker '1'
[debug] [pid:12072] Scheduler took 0.09552s to perform operations and allocated 1 jobs
[debug] [pid:12658] Accepting job 5 from http://localhost:9526.
[debug] [pid:12072] Allocated: { job => 5, worker => 1 }
[debug] [pid:12658] Setting job 5 from http://localhost:9526 up
[debug] [pid:12658] Preparing Mojo::IOLoop::ReadWriteProcess::Session
[info] [pid:12658] +++ setup notes +++
[info] [pid:12658] Running on 1234cbae1a16:1 (Linux 5.11.0-1027-aws #30~20.04.1-Ubuntu SMP Thu Jan 13 11:46:53 UTC 2022 x86_64)
[debug] [pid:12658] Job settings:
[debug] [pid:12658]
ARCH=i386
BUILD=1
CACHEDIRECTORY=/tmp/7v4CAal1xt/full-stack.d/cache
CACHELIMIT=50
DISTRI=tinycore
FLAVOR=flavor
INTEGRATION_TESTS=1
ISO=Core-7.2.iso
JOBTOKEN=UHDsvGadPNTdhlYW
LOCAL_UPLOAD=0
LOG_LEVEL=debug
MACHINE=coolone
NAME=00000005-tinycore-1-flavor-i386-Build1-core@coolone
OPENQA_HOSTNAME=localhost:9526
OPENQA_URL=http://localhost:9526
PRJDIR=/tmp/7v4CAal1xt/full-stack.d/openqa/share
PUBLISH_HDD_1=
QEMU=i386
QEMUPORT=20012
QEMU_NO_FDC_SET=1
QEMU_NO_KVM=1
QEMU_NO_TABLET=1
RETRY_DELAY=5
RETRY_DELAY_IF_WEBUI_BUSY=60
TEST=core
UEFI_PFLASH_VARS=/usr/share/qemu/ovmf-x86_64.bin
VERSION=1
VNC=91
WORKER_CLASS=qemu_i386,qemu_x86_64
WORKER_ID=1
WORKER_INSTANCE=1
# Wait for jQuery successful: wait_for_result_panel: waiting for '(?^u:State: running)' (count 0 of 3240)
[debug] [pid:12658] Found ISO, caching Core-7.2.iso
[info] [pid:12658] Downloading Core-7.2.iso, request #1 sent to Cache Service
[debug] [pid:12658] Updating status so job 5 is not considered dead.
[debug] [pid:12658] REST-API call: POST http://localhost:9526/api/v1/jobs/5/status
[debug] [pid:12076] Worker 1 accepted job 5
[debug] redirect to /assets/iso/Core-7.2.iso
# Wait for jQuery successful: wait_for_result_panel: waiting for '(?^u:State: running)' (count 1 of 3240)
# Wait for jQuery successful: wait_for_result_panel: waiting for '(?^u:State: running)' (count 2 of 3240)
# Wait for jQuery successful: wait_for_result_panel: waiting for '(?^u:State: running)' (count 3 of 3240)
# Wait for jQuery successful: wait_for_result_panel: waiting for '(?^u:State: running)' (count 4 of 3240)
[debug] [pid:12077] Unrecognized referer 'localhost'
[debug] [pid:12077] Unrecognized referer 'localhost'
[debug] [pid:12077] Unrecognized referer 'localhost'
[debug] attempt to open ws proxy for job tinycore-1-flavor-i386-Build1-core@coolone (5) where URL to os-autoinst command server is unknown
[debug] [pid:12077] Unrecognized referer 'localhost'
[debug] [pid:12077] Unrecognized referer 'localhost'
[debug] [pid:12077] Asking the worker 1 to start providing livestream for job 5
# Wait for jQuery successful: wait_for_result_panel: waiting for '(?^u:State: running)' (count 5 of 3240)
ok 6 - \#nav-item-for-live present
ok 7 - job 5 running
# Subtest: results of test 5
ok 1 - cache.sqlite file created
ok 2 - Directory within cache, not present after deploy
ok 3 - File within cache, not present after deploy
# Waiting for 'finished download' to become available
[debug] [pid:12658] Updating status so job 5 is not considered dead.
[debug] [pid:12658] REST-API call: POST http://localhost:9526/api/v1/jobs/5/status
[info] [pid:12658] Download of Core-7.2.iso processed
[debug] [pid:12658] Linked asset "/tmp/7v4CAal1xt/full-stack.d/cache/localhost/Core-7.2.iso" to "/tmp/7v4CAal1xt/full-stack.d/openqa/pool/1/Core-7.2.iso"
[debug] [pid:12658] Symlinked from "/tmp/7v4CAal1xt/full-stack.d/openqa/share/tests/tinycore" to "/tmp/7v4CAal1xt/full-stack.d/openqa/pool/1/tinycore"
[info] [pid:12658] Preparing cgroup to start isotovideo
[warn] [pid:12658] Disabling cgroup usage because cgroup creation failed: mkdir /sys/fs/cgroup/systemd/docker: Permission denied at /usr/lib/perl5/vendor_perl/5.26.1/Mojo/File.pm line 84.
[info] [pid:12658] You can define a custom slice with OPENQA_CGROUP_SLICE or indicating the base mount with MOJO_CGROUP_FS.
[info] [pid:12658] Starting isotovideo container
[debug] [pid:12658] Registered process:12665
[info] [pid:12665] 12665: WORKING 5
[info] [pid:12658] isotovideo has been started (PID: 12665)
[debug] [pid:12665] +++ worker notes +++
[debug] [pid:12658] Running job 5 from http://localhost:9526: 00000005-tinycore-1-flavor-i386-Build1-core@coolone.
[debug] [pid:12658] REST-API call: POST http://localhost:9526/api/v1/jobs/5/status
ok 4 - iso is hardlinked to cache
[debug] [pid:12076] Updating seen of worker 1 from worker_status (working)
# Wait for jQuery successful: wait_for_result_panel: waiting for '(?^u:Result: passed)' (count 0 of 3240)
[debug] [pid:12658] Upload concluded (no current module)
# Wait for jQuery successful: wait_for_result_panel: waiting for '(?^u:Result: passed)' (count 1 of 3240)
# Wait for jQuery successful: wait_for_result_panel: waiting for '(?^u:Result: passed)' (count 2 of 3240)
# Wait for jQuery successful: wait_for_result_panel: waiting for '(?^u:Result: passed)' (count 3 of 3240)
[debug] [pid:12077] Unrecognized referer 'localhost'
# Wait for jQuery successful: wait_for_result_panel: waiting for '(?^u:Result: passed)' (count 4 of 3240)
# Wait for jQuery successful: wait_for_result_panel: waiting for '(?^u:Result: passed)' (count 5 of 3240)
# Wait for jQuery successful: wait_for_result_panel: waiting for '(?^u:Result: passed)' (count 6 of 3240)
# Wait for jQuery successful: wait_for_result_panel: waiting for '(?^u:Result: passed)' (count 7 of 3240)
# Wait for jQuery successful: wait_for_result_panel: waiting for '(?^u:Result: passed)' (count 8 of 3240)
# Wait for jQuery successful: wait_for_result_panel: waiting for '(?^u:Result: passed)' (count 9 of 3240)
# Wait for jQuery successful: wait_for_result_panel: waiting for '(?^u:Result: passed)' (count 10 of 3240)
# Wait for jQuery successful: wait_for_result_panel: waiting for '(?^u:Result: passed)' (count 11 of 3240)
# Wait for jQuery successful: wait_for_result_panel: waiting for '(?^u:Result: passed)' (count 12 of 3240)
# Wait for jQuery successful: wait_for_result_panel: waiting for '(?^u:Result: passed)' (count 13 of 3240)
[debug] [pid:12077] Unrecognized referer 'localhost'
# Wait for jQuery successful: wait_for_result_panel: waiting for '(?^u:Result: passed)' (count 14 of 3240)
# Wait for jQuery successful: wait_for_result_panel: waiting for '(?^u:Result: passed)' (count 15 of 3240)
# Wait for jQuery successful: wait_for_result_panel: waiting for '(?^u:Result: passed)' (count 16 of 3240)
# Wait for jQuery successful: wait_for_result_panel: waiting for '(?^u:Result: passed)' (count 17 of 3240)
# Wait for jQuery successful: wait_for_result_panel: waiting for '(?^u:Result: passed)' (count 18 of 3240)
# Wait for jQuery successful: wait_for_result_panel: waiting for '(?^u:Result: passed)' (count 19 of 3240)
[debug] [pid:12658] REST-API call: POST http://localhost:9526/api/v1/jobs/5/status
[debug] [pid:12658] Upload concluded (at boot)
# Wait for jQuery successful: wait_for_result_panel: waiting for '(?^u:Result: passed)' (count 20 of 3240)
# Wait for jQuery successful: wait_for_result_panel: waiting for '(?^u:Result: passed)' (count 21 of 3240)
# Wait for jQuery successful: wait_for_result_panel: waiting for '(?^u:Result: passed)' (count 22 of 3240)
[debug] [pid:12077] Unrecognized referer 'localhost'
[debug] [pid:12077] Unrecognized referer 'localhost'
[debug] [pid:12156] connecting to os-autoinst command server for job 5 at ws://1234cbae1a16:20013/UHDsvGadPNTdhlYW/ws
# Wait for jQuery successful: wait_for_result_panel: waiting for '(?^u:Result: passed)' (count 23 of 3240)
# Wait for jQuery successful: wait_for_result_panel: waiting for '(?^u:Result: passed)' (count 24 of 3240)
# Wait for jQuery successful: wait_for_result_panel: waiting for '(?^u:Result: passed)' (count 25 of 3240)
# Wait for jQuery successful: wait_for_result_panel: waiting for '(?^u:Result: passed)' (count 26 of 3240)
# Wait for jQuery successful: wait_for_result_panel: waiting for '(?^u:Result: passed)' (count 27 of 3240)
# Wait for jQuery successful: wait_for_result_panel: waiting for '(?^u:Result: passed)' (count 28 of 3240)
# Wait for jQuery successful: wait_for_result_panel: waiting for '(?^u:Result: passed)' (count 29 of 3240)
# Wait for jQuery successful: wait_for_result_panel: waiting for '(?^u:Result: passed)' (count 30 of 3240)
# Wait for jQuery successful: wait_for_result_panel: waiting for '(?^u:Result: passed)' (count 31 of 3240)
[debug] [pid:12077] Unrecognized referer 'localhost'
# Wait for jQuery successful: wait_for_result_panel: waiting for '(?^u:Result: passed)' (count 32 of 3240)
# Wait for jQuery successful: wait_for_result_panel: waiting for '(?^u:Result: passed)' (count 33 of 3240)
# Wait for jQuery successful: wait_for_result_panel: waiting for '(?^u:Result: passed)' (count 34 of 3240)
# Wait for jQuery successful: wait_for_result_panel: waiting for '(?^u:Result: passed)' (count 35 of 3240)
# Wait for jQuery successful: wait_for_result_panel: waiting for '(?^u:Result: passed)' (count 36 of 3240)
# Wait for jQuery successful: wait_for_result_panel: waiting for '(?^u:Result: passed)' (count 37 of 3240)
[debug] [pid:12076] Updating seen of worker 1 from worker_status (working)
[debug] [pid:12658] REST-API call: POST http://localhost:9526/api/v1/jobs/5/status
[debug] [pid:12077] creating f41/844/68dbb276a03240907d0e7e500d.png
[debug] [pid:12077] creating 68d/7ac/83452b72555f8a6b386629f91f.png
[debug] [pid:12658] Upload concluded (up to boot)
# Wait for jQuery successful: wait_for_result_panel: waiting for '(?^u:Result: passed)' (count 38 of 3240)
# Wait for jQuery successful: wait_for_result_panel: waiting for '(?^u:Result: passed)' (count 39 of 3240)
# Wait for jQuery successful: wait_for_result_panel: waiting for '(?^u:Result: passed)' (count 40 of 3240)
# Wait for jQuery successful: wait_for_result_panel: waiting for '(?^u:Result: passed)' (count 41 of 3240)
[debug] [pid:12077] Unrecognized referer 'localhost'
[debug] [pid:12077] Unrecognized referer 'localhost'
[debug] looking for "68d/7ac/.thumbs/83452b72555f8a6b386629f91f.png" in ["/tmp/7v4CAal1xt/full-stack.d/openqa/images"]
[debug] found bless({
path => "/tmp/7v4CAal1xt/full-stack.d/openqa/images/68d/7ac/.thumbs/83452b72555f8a6b386629f91f.png",
pid => 12077,
}, "Mojo::Asset::File")
[debug] looking for "f41/844/.thumbs/68dbb276a03240907d0e7e500d.png" in ["/tmp/7v4CAal1xt/full-stack.d/openqa/images"]
[debug] found bless({
path => "/tmp/7v4CAal1xt/full-stack.d/openqa/images/f41/844/.thumbs/68dbb276a03240907d0e7e500d.png",
pid => 12077,
}, "Mojo::Asset::File")
# Wait for jQuery successful: wait_for_result_panel: waiting for '(?^u:Result: passed)' (count 42 of 3240)
# Wait for jQuery successful: wait_for_result_panel: waiting for '(?^u:Result: passed)' (count 43 of 3240)
# Wait for jQuery successful: wait_for_result_panel: waiting for '(?^u:Result: passed)' (count 44 of 3240)
# Wait for jQuery successful: wait_for_result_panel: waiting for '(?^u:Result: passed)' (count 45 of 3240)
# Wait for jQuery successful: wait_for_result_panel: waiting for '(?^u:Result: passed)' (count 46 of 3240)
# Wait for jQuery successful: wait_for_result_panel: waiting for '(?^u:Result: passed)' (count 47 of 3240)
# Wait for jQuery successful: wait_for_result_panel: waiting for '(?^u:Result: passed)' (count 48 of 3240)
# Wait for jQuery successful: wait_for_result_panel: waiting for '(?^u:Result: passed)' (count 49 of 3240)
# Wait for jQuery successful: wait_for_result_panel: waiting for '(?^u:Result: passed)' (count 50 of 3240)
# Wait for jQuery successful: wait_for_result_panel: waiting for '(?^u:Result: passed)' (count 51 of 3240)
[debug] [pid:12077] Unrecognized referer 'localhost'
# Wait for jQuery successful: wait_for_result_panel: waiting for '(?^u:Result: passed)' (count 52 of 3240)
# Wait for jQuery successful: wait_for_result_panel: waiting for '(?^u:Result: passed)' (count 53 of 3240)
# Wait for jQuery successful: wait_for_result_panel: waiting for '(?^u:Result: passed)' (count 54 of 3240)
[info] [pid:12658] Isotovideo exit status: 0
[debug] [pid:12658] Stopping job 5 from http://localhost:9526: 00000005-tinycore-1-flavor-i386-Build1-core@coolone - reason: done
[debug] [pid:12658] REST-API call: POST http://localhost:9526/api/v1/jobs/5/status
[info] [pid:12658] +++ worker notes +++
[info] [pid:12658] End time: 2022-02-15 12:29:07
[info] [pid:12658] Result: done
[info] [pid:12874] Uploading video.ogv
[debug] [pid:12874] Uploading artefact video.ogv
[info] [pid:12874] Uploading vars.json
[debug] [pid:12874] Uploading artefact vars.json
[info] [pid:12874] Uploading autoinst-log.txt
[debug] [pid:12874] Uploading artefact autoinst-log.txt
[info] [pid:12874] Uploading worker-log.txt
[debug] [pid:12874] Uploading artefact worker-log.txt
[info] [pid:12874] Uploading serial0.txt
[debug] [pid:12874] Uploading artefact serial0.txt
[info] [pid:12874] Uploading video_time.vtt
[debug] [pid:12874] Uploading artefact video_time.vtt
[info] [pid:12874] Uploading serial_terminal.txt
[debug] [pid:12874] Uploading artefact serial_terminal.txt
[info] [pid:12874] Uploading virtio_console1.log
[debug] [pid:12874] Uploading artefact virtio_console1.log
[debug] [pid:12658] Considering job 5 as regularly done
[debug] [pid:12658] REST-API call: POST http://localhost:9526/api/v1/jobs/5/status
# Wait for jQuery successful: wait_for_result_panel: waiting for '(?^u:Result: passed)' (count 55 of 3240)
[debug] [pid:12077] creating 68d/7ac/83452b72555f8a6b386629f91f.png
[debug] [pid:12077] creating 68d/7ac/83452b72555f8a6b386629f91f.png
[debug] [pid:12077] creating da0/10d/d856559816fdfe9ec648fa3f3f.png
[debug] [pid:12875] Optimizing /tmp/7v4CAal1xt/full-stack.d/openqa/pool/1/testresults/shutdown-2.png
[debug] [pid:12875] Uploading artefact shutdown-2.png as da010dd856559816fdfe9ec648fa3f3f
[debug] [pid:12875] Optimizing /tmp/7v4CAal1xt/full-stack.d/openqa/pool/1/testresults/.thumbs/shutdown-2.png
[debug] [pid:12875] Uploading artefact shutdown-2.png as da010dd856559816fdfe9ec648fa3f3f
[debug] [pid:12658] Upload concluded (no current module)
[debug] [pid:12658] REST-API call: POST http://localhost:9526/api/v1/jobs/5/set_done?worker_id=1
[debug] [pid:12658] Job 5 from http://localhost:9526 finished - reason: done
[debug] [pid:12658] Cleaning up for next job
# Wait for jQuery successful: wait_for_result_panel: waiting for '(?^u:Result: passed)' (count 56 of 3240)
# Wait for jQuery successful: wait_for_result_panel: waiting for '(?^u:Result: passed)' (count 57 of 3240)
# Wait for jQuery successful: wait_for_result_panel: waiting for '(?^u:Result: passed)' (count 58 of 3240)
# Wait for jQuery successful: wait_for_result_panel: waiting for '(?^u:Result: passed)' (count 59 of 3240)
# Wait for jQuery successful: wait_for_result_panel: waiting for '(?^u:Result: passed)' (count 60 of 3240)
[debug] [pid:12077] Unrecognized referer 'localhost'
[debug] [pid:12077] Unrecognized referer 'localhost'
[debug] [pid:12077] Unrecognized referer 'localhost'
[debug] looking for "da0/10d/.thumbs/d856559816fdfe9ec648fa3f3f.png" in ["/tmp/7v4CAal1xt/full-stack.d/openqa/images"]
[debug] found bless({
path => "/tmp/7v4CAal1xt/full-stack.d/openqa/images/da0/10d/.thumbs/d856559816fdfe9ec648fa3f3f.png",
pid => 12077,
}, "Mojo::Asset::File")
# Wait for jQuery successful: wait_for_result_panel: waiting for '(?^u:Result: passed)' (count 61 of 3240)
ok 5 - job 5 passed
[info] [pid:12658] Received signal TERM
[debug] [pid:12658] Informing http://localhost:9526 that we are going offline
[info] [pid:12076] Worker 1 websocket connection closed - 1006
ok 6 - Test 5 autoinst-log.txt file created
ok 7 - Test 5, downloaded the right iso
ok 8 - Test 5 Core-7.2.iso size is correct
ok 9 - Test 5 result done
ok 10 - setup notes present
ok 11 - uploading of autoinst-log.txt logged
ok 12 - worker log file generated
ok 13 - autoinst log uploaded
ok 14 - worker log uploaded
ok 15 - local upload feature not used
ok 16 - Core-7.2.iso is the first element
ok 17 - file \#5 is the newest element
1..17
ok 8 - results of test 5
[debug] Restarting job 5
[debug] [pid:12077] Duplicating jobs: {
5 => {
chained_children => [],
chained_parents => [],
directly_chained_children => [],
directly_chained_parents => [],
is_parent_or_initial_job => 1,
ok => 1,
parallel_children => [],
parallel_parents => [],
state => "done",
},
}
[debug] [pid:12077] Job 5 duplicated as 6
[warn] [pid:12077] Unable to wakeup scheduler: Connection refused
ok 9 - client returned new test_url for test 6
[debug] [pid:12077] Unrecognized referer 'localhost'
ok 10 - test 6 is scheduled
ok 11 - Worker started as IPC::Run=HASH(0x55eab0e84970)
[debug] [pid:12077] Unrecognized referer 'localhost'
ok 12 - job with worker class qemu_i386 scheduled
[info] [pid:12880] worker 1:
- config file: /tmp/7v4CAal1xt/full-stack.d/config/workers.ini
- worker hostname: 1234cbae1a16
- isotovideo version: 24
- websocket API version: 1
- web UI hosts: http://localhost:9526
- class: qemu_i386,qemu_x86_64
- no cleanup: no
- pool directory: /tmp/7v4CAal1xt/full-stack.d/openqa/pool/1
[info] [pid:12880] CACHE: caching is enabled, setting up /tmp/7v4CAal1xt/full-stack.d/cache/localhost
[info] [pid:12880] Project dir for host http://localhost:9526 is /tmp/7v4CAal1xt/full-stack.d/openqa/share
[info] [pid:12880] Registering with openQA http://localhost:9526
[info] [pid:12880] Establishing ws connection via ws://localhost:9526/api/v1/ws/1
[info] [pid:12880] Registered and connected via websockets with openQA host http://localhost:9526 and worker ID 1
[debug] [pid:12076] Updating seen of worker 1 from worker_status (free)
ok 13 - at least one free worker with class qemu_i386 registered
[debug] [pid:12072] +=----------------=+
[debug] [pid:12072] -> Scheduling new jobs.
[debug] [pid:12072] Free workers: 1/1
[debug] [pid:12072] Scheduled jobs: 1
[debug] [pid:12072] Need to schedule 1 parallel jobs for job 6 (with priority 50)
[debug] [pid:12072] Assigned job '6' to worker ID '1'
[debug] [pid:12072] [Job#6] Prepare for being processed by worker 1
[debug] [pid:12076] Started to send message to 1 for job(s) 6
[debug] [pid:12072] Sent job(s) '6' to worker '1'
[debug] [pid:12072] Scheduler took 0.10570s to perform operations and allocated 1 jobs
[debug] [pid:12880] Accepting job 6 from http://localhost:9526.
[debug] [pid:12072] Allocated: { job => 6, worker => 1 }
# Subtest: results of test 6
[debug] [pid:12880] Setting job 6 from http://localhost:9526 up
[debug] [pid:12880] Preparing Mojo::IOLoop::ReadWriteProcess::Session
[info] [pid:12880] +++ setup notes +++
[info] [pid:12880] Running on 1234cbae1a16:1 (Linux 5.11.0-1027-aws #30~20.04.1-Ubuntu SMP Thu Jan 13 11:46:53 UTC 2022 x86_64)
[debug] [pid:12880] Job settings:
[debug] [pid:12880]
ARCH=i386
BUILD=1
CACHEDIRECTORY=/tmp/7v4CAal1xt/full-stack.d/cache
CACHELIMIT=50
DISTRI=tinycore
FLAVOR=flavor
INTEGRATION_TESTS=1
ISO=Core-7.2.iso
JOBTOKEN=3qvFv7vgealwLeLC
LOCAL_UPLOAD=0
LOG_LEVEL=debug
MACHINE=coolone
NAME=00000006-tinycore-1-flavor-i386-Build1-core@coolone
OPENQA_HOSTNAME=localhost:9526
OPENQA_URL=http://localhost:9526
PRJDIR=/tmp/7v4CAal1xt/full-stack.d/openqa/share
PUBLISH_HDD_1=
QEMU=i386
QEMUPORT=20012
QEMU_NO_FDC_SET=1
QEMU_NO_KVM=1
QEMU_NO_TABLET=1
RETRY_DELAY=5
RETRY_DELAY_IF_WEBUI_BUSY=60
TEST=core
UEFI_PFLASH_VARS=/usr/share/qemu/ovmf-x86_64.bin
VERSION=1
VNC=91
WORKER_CLASS=qemu_i386,qemu_x86_64
WORKER_ID=1
WORKER_INSTANCE=1
# Wait for jQuery successful: wait_for_result_panel: waiting for '(?^u:Result: passed)' (count 0 of 3240)
[debug] [pid:12880] Found ISO, caching Core-7.2.iso
[info] [pid:12880] Downloading Core-7.2.iso, request #2 sent to Cache Service
[debug] [pid:12880] Updating status so job 6 is not considered dead.
[debug] [pid:12880] REST-API call: POST http://localhost:9526/api/v1/jobs/6/status
[debug] [pid:12076] Worker 1 accepted job 6
[debug] redirect to /assets/iso/Core-7.2.iso
# Wait for jQuery successful: wait_for_result_panel: waiting for '(?^u:Result: passed)' (count 1 of 3240)
# Wait for jQuery successful: wait_for_result_panel: waiting for '(?^u:Result: passed)' (count 2 of 3240)
# Wait for jQuery successful: wait_for_result_panel: waiting for '(?^u:Result: passed)' (count 3 of 3240)
# Wait for jQuery successful: wait_for_result_panel: waiting for '(?^u:Result: passed)' (count 4 of 3240)
[debug] [pid:12077] Unrecognized referer 'localhost'
[debug] [pid:12077] Unrecognized referer 'localhost'
[debug] [pid:12077] Unrecognized referer 'localhost'
[debug] attempt to open ws proxy for job tinycore-1-flavor-i386-Build1-core@coolone (6) where URL to os-autoinst command server is unknown
[debug] [pid:12077] Unrecognized referer 'localhost'
[debug] [pid:12077] Unrecognized referer 'localhost'
[debug] [pid:12077] Asking the worker 1 to start providing livestream for job 6
# Wait for jQuery successful: wait_for_result_panel: waiting for '(?^u:Result: passed)' (count 5 of 3240)
# Wait for jQuery successful: wait_for_result_panel: waiting for '(?^u:Result: passed)' (count 6 of 3240)
# Wait for jQuery successful: wait_for_result_panel: waiting for '(?^u:Result: passed)' (count 7 of 3240)
# Wait for jQuery successful: wait_for_result_panel: waiting for '(?^u:Result: passed)' (count 8 of 3240)
# Wait for jQuery successful: wait_for_result_panel: waiting for '(?^u:Result: passed)' (count 9 of 3240)
[debug] [pid:12880] Updating status so job 6 is not considered dead.
[debug] [pid:12880] REST-API call: POST http://localhost:9526/api/v1/jobs/6/status
[info] [pid:12880] Download of Core-7.2.iso processed
[debug] [pid:12880] Linked asset "/tmp/7v4CAal1xt/full-stack.d/cache/localhost/Core-7.2.iso" to "/tmp/7v4CAal1xt/full-stack.d/openqa/pool/1/Core-7.2.iso"
[debug] [pid:12880] Symlinked from "/tmp/7v4CAal1xt/full-stack.d/openqa/share/tests/tinycore" to "/tmp/7v4CAal1xt/full-stack.d/openqa/pool/1/tinycore"
[info] [pid:12880] Preparing cgroup to start isotovideo
[warn] [pid:12880] Disabling cgroup usage because cgroup creation failed: mkdir /sys/fs/cgroup/systemd/docker: Permission denied at /usr/lib/perl5/vendor_perl/5.26.1/Mojo/File.pm line 84.
[info] [pid:12880] You can define a custom slice with OPENQA_CGROUP_SLICE or indicating the base mount with MOJO_CGROUP_FS.
[info] [pid:12880] Starting isotovideo container
[debug] [pid:12880] Registered process:12888
[info] [pid:12888] 12888: WORKING 6
[info] [pid:12880] isotovideo has been started (PID: 12888)
[debug] [pid:12888] +++ worker notes +++
[debug] [pid:12880] Running job 6 from http://localhost:9526: 00000006-tinycore-1-flavor-i386-Build1-core@coolone.
[debug] [pid:12880] REST-API call: POST http://localhost:9526/api/v1/jobs/6/status
[debug] [pid:12076] Updating seen of worker 1 from worker_status (working)
# Wait for jQuery successful: wait_for_result_panel: waiting for '(?^u:Result: passed)' (count 10 of 3240)
[debug] [pid:12880] Upload concluded (no current module)
# Wait for jQuery successful: wait_for_result_panel: waiting for '(?^u:Result: passed)' (count 11 of 3240)
# Wait for jQuery successful: wait_for_result_panel: waiting for '(?^u:Result: passed)' (count 12 of 3240)
# Wait for jQuery successful: wait_for_result_panel: waiting for '(?^u:Result: passed)' (count 13 of 3240)
# Wait for jQuery successful: wait_for_result_panel: waiting for '(?^u:Result: passed)' (count 14 of 3240)
[debug] [pid:12077] Unrecognized referer 'localhost'
# Wait for jQuery successful: wait_for_result_panel: waiting for '(?^u:Result: passed)' (count 15 of 3240)
# Wait for jQuery successful: wait_for_result_panel: waiting for '(?^u:Result: passed)' (count 16 of 3240)
# Wait for jQuery successful: wait_for_result_panel: waiting for '(?^u:Result: passed)' (count 17 of 3240)
# Wait for jQuery successful: wait_for_result_panel: waiting for '(?^u:Result: passed)' (count 18 of 3240)
# Wait for jQuery successful: wait_for_result_panel: waiting for '(?^u:Result: passed)' (count 19 of 3240)
# Wait for jQuery successful: wait_for_result_panel: waiting for '(?^u:Result: passed)' (count 20 of 3240)
# Wait for jQuery successful: wait_for_result_panel: waiting for '(?^u:Result: passed)' (count 21 of 3240)
# Wait for jQuery successful: wait_for_result_panel: waiting for '(?^u:Result: passed)' (count 22 of 3240)
# Wait for jQuery successful: wait_for_result_panel: waiting for '(?^u:Result: passed)' (count 23 of 3240)
# Wait for jQuery successful: wait_for_result_panel: waiting for '(?^u:Result: passed)' (count 24 of 3240)
[debug] [pid:12077] Unrecognized referer 'localhost'
# Wait for jQuery successful: wait_for_result_panel: waiting for '(?^u:Result: passed)' (count 25 of 3240)
# Wait for jQuery successful: wait_for_result_panel: waiting for '(?^u:Result: passed)' (count 26 of 3240)
# Wait for jQuery successful: wait_for_result_panel: waiting for '(?^u:Result: passed)' (count 27 of 3240)
# Wait for jQuery successful: wait_for_result_panel: waiting for '(?^u:Result: passed)' (count 28 of 3240)
# Wait for jQuery successful: wait_for_result_panel: waiting for '(?^u:Result: passed)' (count 29 of 3240)
[debug] [pid:12880] REST-API call: POST http://localhost:9526/api/v1/jobs/6/status
[debug] [pid:12880] Upload concluded (at boot)
# Wait for jQuery successful: wait_for_result_panel: waiting for '(?^u:Result: passed)' (count 30 of 3240)
# Wait for jQuery successful: wait_for_result_panel: waiting for '(?^u:Result: passed)' (count 31 of 3240)
# Wait for jQuery successful: wait_for_result_panel: waiting for '(?^u:Result: passed)' (count 32 of 3240)
# Wait for jQuery successful: wait_for_result_panel: waiting for '(?^u:Result: passed)' (count 33 of 3240)
# Wait for jQuery successful: wait_for_result_panel: waiting for '(?^u:Result: passed)' (count 34 of 3240)
[debug] [pid:12077] Unrecognized referer 'localhost'
[debug] [pid:12077] Unrecognized referer 'localhost'
[debug] [pid:12156] connecting to os-autoinst command server for job 6 at ws://1234cbae1a16:20013/3qvFv7vgealwLeLC/ws
# Wait for jQuery successful: wait_for_result_panel: waiting for '(?^u:Result: passed)' (count 35 of 3240)
# Wait for jQuery successful: wait_for_result_panel: waiting for '(?^u:Result: passed)' (count 36 of 3240)
# Wait for jQuery successful: wait_for_result_panel: waiting for '(?^u:Result: passed)' (count 37 of 3240)
# Wait for jQuery successful: wait_for_result_panel: waiting for '(?^u:Result: passed)' (count 38 of 3240)
# Wait for jQuery successful: wait_for_result_panel: waiting for '(?^u:Result: passed)' (count 39 of 3240)
# Wait for jQuery successful: wait_for_result_panel: waiting for '(?^u:Result: passed)' (count 40 of 3240)
# Wait for jQuery successful: wait_for_result_panel: waiting for '(?^u:Result: passed)' (count 41 of 3240)
# Wait for jQuery successful: wait_for_result_panel: waiting for '(?^u:Result: passed)' (count 42 of 3240)
# Wait for jQuery successful: wait_for_result_panel: waiting for '(?^u:Result: passed)' (count 43 of 3240)
# Wait for jQuery successful: wait_for_result_panel: waiting for '(?^u:Result: passed)' (count 44 of 3240)
[debug] [pid:12077] Unrecognized referer 'localhost'
# Wait for jQuery successful: wait_for_result_panel: waiting for '(?^u:Result: passed)' (count 45 of 3240)
# Wait for jQuery successful: wait_for_result_panel: waiting for '(?^u:Result: passed)' (count 46 of 3240)
# Wait for jQuery successful: wait_for_result_panel: waiting for '(?^u:Result: passed)' (count 47 of 3240)
# Wait for jQuery successful: wait_for_result_panel: waiting for '(?^u:Result: passed)' (count 48 of 3240)
[debug] [pid:12076] Updating seen of worker 1 from worker_status (working)
[debug] [pid:12880] REST-API call: POST http://localhost:9526/api/v1/jobs/6/status
[debug] [pid:12077] creating f41/844/68dbb276a03240907d0e7e500d.png
[debug] [pid:12077] creating 68d/7ac/83452b72555f8a6b386629f91f.png
# Wait for jQuery successful: wait_for_result_panel: waiting for '(?^u:Result: passed)' (count 49 of 3240)
[debug] [pid:12880] Upload concluded (up to boot)
# Wait for jQuery successful: wait_for_result_panel: waiting for '(?^u:Result: passed)' (count 50 of 3240)
# Wait for jQuery successful: wait_for_result_panel: waiting for '(?^u:Result: passed)' (count 51 of 3240)
# Wait for jQuery successful: wait_for_result_panel: waiting for '(?^u:Result: passed)' (count 52 of 3240)
# Wait for jQuery successful: wait_for_result_panel: waiting for '(?^u:Result: passed)' (count 53 of 3240)
[debug] [pid:12077] Unrecognized referer 'localhost'
[debug] [pid:12077] Unrecognized referer 'localhost'
[debug] looking for "f41/844/.thumbs/68dbb276a03240907d0e7e500d.png" in ["/tmp/7v4CAal1xt/full-stack.d/openqa/images"]
[debug] found bless({
path => "/tmp/7v4CAal1xt/full-stack.d/openqa/images/f41/844/.thumbs/68dbb276a03240907d0e7e500d.png",
pid => 12077,
}, "Mojo::Asset::File")
[debug] looking for "68d/7ac/.thumbs/83452b72555f8a6b386629f91f.png" in ["/tmp/7v4CAal1xt/full-stack.d/openqa/images"]
[debug] found bless({
path => "/tmp/7v4CAal1xt/full-stack.d/openqa/images/68d/7ac/.thumbs/83452b72555f8a6b386629f91f.png",
pid => 12077,
}, "Mojo::Asset::File")
# Wait for jQuery successful: wait_for_result_panel: waiting for '(?^u:Result: passed)' (count 54 of 3240)
# Wait for jQuery successful: wait_for_result_panel: waiting for '(?^u:Result: passed)' (count 55 of 3240)
# Wait for jQuery successful: wait_for_result_panel: waiting for '(?^u:Result: passed)' (count 56 of 3240)
# Wait for jQuery successful: wait_for_result_panel: waiting for '(?^u:Result: passed)' (count 57 of 3240)
[info] [pid:12880] Isotovideo exit status: 0
[debug] [pid:12880] Stopping job 6 from http://localhost:9526: 00000006-tinycore-1-flavor-i386-Build1-core@coolone - reason: done
[debug] [pid:12880] REST-API call: POST http://localhost:9526/api/v1/jobs/6/status
[info] [pid:12880] +++ worker notes +++
[info] [pid:12880] End time: 2022-02-15 12:29:47
[info] [pid:12880] Result: done
[info] [pid:13106] Uploading video.ogv
[debug] [pid:13106] Uploading artefact video.ogv
[info] [pid:13106] Uploading vars.json
[debug] [pid:13106] Uploading artefact vars.json
[info] [pid:13106] Uploading autoinst-log.txt
[debug] [pid:13106] Uploading artefact autoinst-log.txt
[info] [pid:13106] Uploading worker-log.txt
[debug] [pid:13106] Uploading artefact worker-log.txt
[info] [pid:13106] Uploading serial0.txt
[debug] [pid:13106] Uploading artefact serial0.txt
[info] [pid:13106] Uploading video_time.vtt
[debug] [pid:13106] Uploading artefact video_time.vtt
[info] [pid:13106] Uploading serial_terminal.txt
[debug] [pid:13106] Uploading artefact serial_terminal.txt
[info] [pid:13106] Uploading virtio_console1.log
[debug] [pid:13106] Uploading artefact virtio_console1.log
[debug] [pid:12880] Considering job 6 as regularly done
[debug] [pid:12880] REST-API call: POST http://localhost:9526/api/v1/jobs/6/status
# Wait for jQuery successful: wait_for_result_panel: waiting for '(?^u:Result: passed)' (count 58 of 3240)
[debug] [pid:12077] creating 68d/7ac/83452b72555f8a6b386629f91f.png
[debug] [pid:12077] creating 68d/7ac/83452b72555f8a6b386629f91f.png
[debug] [pid:12077] creating eca/cf6/c5978e04babecd7542a8c1e2eb.png
[debug] [pid:13107] Optimizing /tmp/7v4CAal1xt/full-stack.d/openqa/pool/1/testresults/shutdown-2.png
[debug] [pid:13107] Uploading artefact shutdown-2.png as ecacf6c5978e04babecd7542a8c1e2eb
[debug] [pid:13107] Optimizing /tmp/7v4CAal1xt/full-stack.d/openqa/pool/1/testresults/.thumbs/shutdown-2.png
[debug] [pid:13107] Uploading artefact shutdown-2.png as ecacf6c5978e04babecd7542a8c1e2eb
[debug] [pid:12880] Upload concluded (no current module)
[debug] [pid:12880] REST-API call: POST http://localhost:9526/api/v1/jobs/6/set_done?worker_id=1
[debug] [pid:12880] Job 6 from http://localhost:9526 finished - reason: done
[debug] [pid:12880] Cleaning up for next job
# Wait for jQuery successful: wait_for_result_panel: waiting for '(?^u:Result: passed)' (count 59 of 3240)
# Wait for jQuery successful: wait_for_result_panel: waiting for '(?^u:Result: passed)' (count 60 of 3240)
# Wait for jQuery successful: wait_for_result_panel: waiting for '(?^u:Result: passed)' (count 61 of 3240)
# Wait for jQuery successful: wait_for_result_panel: waiting for '(?^u:Result: passed)' (count 62 of 3240)
# Wait for jQuery successful: wait_for_result_panel: waiting for '(?^u:Result: passed)' (count 63 of 3240)
[debug] [pid:12077] Unrecognized referer 'localhost'
[debug] [pid:12077] Unrecognized referer 'localhost'
[debug] [pid:12077] Unrecognized referer 'localhost'
[debug] looking for "eca/cf6/.thumbs/c5978e04babecd7542a8c1e2eb.png" in ["/tmp/7v4CAal1xt/full-stack.d/openqa/images"]
[debug] found bless({
path => "/tmp/7v4CAal1xt/full-stack.d/openqa/images/eca/cf6/.thumbs/c5978e04babecd7542a8c1e2eb.png",
pid => 12077,
}, "Mojo::Asset::File")
# Wait for jQuery successful: wait_for_result_panel: waiting for '(?^u:Result: passed)' (count 64 of 3240)
ok 1 - job 6 passed
[info] [pid:12880] Received signal TERM
[debug] [pid:12880] Informing http://localhost:9526 that we are going offline
[info] [pid:12076] Worker 1 websocket connection closed - 1006
ok 2 - Test 6 autoinst-log.txt file created
ok 3 - asset 5.qcow2 removed during cache init
ok 4 - Core-7.2.iso the most recent asset again
1..4
ok 14 - results of test 6
[debug] Restarting job 6
[debug] [pid:12077] Duplicating jobs: {
6 => {
chained_children => [],
chained_parents => [],
directly_chained_children => [],
directly_chained_parents => [],
is_parent_or_initial_job => 1,
ok => 1,
parallel_children => [],
parallel_parents => [],
state => "done",
},
}
[debug] [pid:12077] Job 6 duplicated as 7
[warn] [pid:12077] Unable to wakeup scheduler: Connection refused
ok 15 - client returned new test_url for test 7
[debug] [pid:12077] Unrecognized referer 'localhost'
ok 16 - test 7 is scheduled
ok 17 - Worker started as IPC::Run=HASH(0x55eab103c788)
[debug] [pid:12077] Unrecognized referer 'localhost'
ok 18 - job with worker class qemu_i386 scheduled
[info] [pid:13113] worker 1:
- config file: /tmp/7v4CAal1xt/full-stack.d/config/workers.ini
- worker hostname: 1234cbae1a16
- isotovideo version: 24
- websocket API version: 1
- web UI hosts: http://localhost:9526
- class: qemu_i386,qemu_x86_64
- no cleanup: no
- pool directory: /tmp/7v4CAal1xt/full-stack.d/openqa/pool/1
[info] [pid:13113] CACHE: caching is enabled, setting up /tmp/7v4CAal1xt/full-stack.d/cache/localhost
[info] [pid:13113] Project dir for host http://localhost:9526 is /tmp/7v4CAal1xt/full-stack.d/openqa/share
[info] [pid:13113] Registering with openQA http://localhost:9526
[info] [pid:13113] Establishing ws connection via ws://localhost:9526/api/v1/ws/1
[info] [pid:13113] Registered and connected via websockets with openQA host http://localhost:9526 and worker ID 1
[debug] [pid:12076] Updating seen of worker 1 from worker_status (free)
ok 19 - at least one free worker with class qemu_i386 registered
[debug] [pid:12072] +=----------------=+
[debug] [pid:12072] -> Scheduling new jobs.
[debug] [pid:12072] Free workers: 1/1
[debug] [pid:12072] Scheduled jobs: 1
[debug] [pid:12072] Need to schedule 1 parallel jobs for job 7 (with priority 50)
[debug] [pid:12072] Assigned job '7' to worker ID '1'
[debug] [pid:12072] [Job#7] Prepare for being processed by worker 1
[debug] [pid:12076] Started to send message to 1 for job(s) 7
[debug] [pid:12072] Sent job(s) '7' to worker '1'
[debug] [pid:12072] Scheduler took 0.09811s to perform operations and allocated 1 jobs
[debug] [pid:13113] Accepting job 7 from http://localhost:9526.
[debug] [pid:12072] Allocated: { job => 7, worker => 1 }
[debug] [pid:13113] Setting job 7 from http://localhost:9526 up
# Subtest: results of test 7
[debug] [pid:13113] Preparing Mojo::IOLoop::ReadWriteProcess::Session
[info] [pid:13113] +++ setup notes +++
[info] [pid:13113] Running on 1234cbae1a16:1 (Linux 5.11.0-1027-aws #30~20.04.1-Ubuntu SMP Thu Jan 13 11:46:53 UTC 2022 x86_64)
[debug] [pid:13113] Job settings:
[debug] [pid:13113]
ARCH=i386
BUILD=1
CACHEDIRECTORY=/tmp/7v4CAal1xt/full-stack.d/cache
CACHELIMIT=50
DISTRI=tinycore
FLAVOR=flavor
INTEGRATION_TESTS=1
ISO=Core-7.2.iso
JOBTOKEN=NyTrTQWMU40CyqS4
LOCAL_UPLOAD=0
LOG_LEVEL=debug
MACHINE=coolone
NAME=00000007-tinycore-1-flavor-i386-Build1-core@coolone
OPENQA_HOSTNAME=localhost:9526
OPENQA_URL=http://localhost:9526
PRJDIR=/tmp/7v4CAal1xt/full-stack.d/openqa/share
PUBLISH_HDD_1=
QEMU=i386
QEMUPORT=20012
QEMU_NO_FDC_SET=1
QEMU_NO_KVM=1
QEMU_NO_TABLET=1
RETRY_DELAY=5
RETRY_DELAY_IF_WEBUI_BUSY=60
TEST=core
UEFI_PFLASH_VARS=/usr/share/qemu/ovmf-x86_64.bin
VERSION=1
VNC=91
WORKER_CLASS=qemu_i386,qemu_x86_64
WORKER_ID=1
WORKER_INSTANCE=1
# Wait for jQuery successful: wait_for_result_panel: waiting for '(?^u:Result: passed)' (count 0 of 3240)
[debug] [pid:13113] Found ISO, caching Core-7.2.iso
[info] [pid:13113] Downloading Core-7.2.iso, request #3 sent to Cache Service
[debug] [pid:13113] Updating status so job 7 is not considered dead.
[debug] [pid:13113] REST-API call: POST http://localhost:9526/api/v1/jobs/7/status
[debug] [pid:12076] Worker 1 accepted job 7
[debug] redirect to /assets/iso/Core-7.2.iso
# Wait for jQuery successful: wait_for_result_panel: waiting for '(?^u:Result: passed)' (count 1 of 3240)
# Wait for jQuery successful: wait_for_result_panel: waiting for '(?^u:Result: passed)' (count 2 of 3240)
# Wait for jQuery successful: wait_for_result_panel: waiting for '(?^u:Result: passed)' (count 3 of 3240)
# Wait for jQuery successful: wait_for_result_panel: waiting for '(?^u:Result: passed)' (count 4 of 3240)
[debug] [pid:12077] Unrecognized referer 'localhost'
[debug] [pid:12077] Unrecognized referer 'localhost'
[debug] [pid:12077] Unrecognized referer 'localhost'
[debug] attempt to open ws proxy for job tinycore-1-flavor-i386-Build1-core@coolone (7) where URL to os-autoinst command server is unknown
[debug] [pid:12077] Unrecognized referer 'localhost'
[debug] [pid:12077] Unrecognized referer 'localhost'
[debug] [pid:12077] Asking the worker 1 to start providing livestream for job 7
# Wait for jQuery successful: wait_for_result_panel: waiting for '(?^u:Result: passed)' (count 5 of 3240)
# Wait for jQuery successful: wait_for_result_panel: waiting for '(?^u:Result: passed)' (count 6 of 3240)
# Wait for jQuery successful: wait_for_result_panel: waiting for '(?^u:Result: passed)' (count 7 of 3240)
# Wait for jQuery successful: wait_for_result_panel: waiting for '(?^u:Result: passed)' (count 8 of 3240)
# Wait for jQuery successful: wait_for_result_panel: waiting for '(?^u:Result: passed)' (count 9 of 3240)
[debug] [pid:13113] Updating status so job 7 is not considered dead.
[debug] [pid:13113] REST-API call: POST http://localhost:9526/api/v1/jobs/7/status
[info] [pid:13113] Download of Core-7.2.iso processed
[debug] [pid:13113] Linked asset "/tmp/7v4CAal1xt/full-stack.d/cache/localhost/Core-7.2.iso" to "/tmp/7v4CAal1xt/full-stack.d/openqa/pool/1/Core-7.2.iso"
[debug] [pid:13113] Symlinked from "/tmp/7v4CAal1xt/full-stack.d/openqa/share/tests/tinycore" to "/tmp/7v4CAal1xt/full-stack.d/openqa/pool/1/tinycore"
[info] [pid:13113] Preparing cgroup to start isotovideo
[warn] [pid:13113] Disabling cgroup usage because cgroup creation failed: mkdir /sys/fs/cgroup/systemd/docker: Permission denied at /usr/lib/perl5/vendor_perl/5.26.1/Mojo/File.pm line 84.
[info] [pid:13113] You can define a custom slice with OPENQA_CGROUP_SLICE or indicating the base mount with MOJO_CGROUP_FS.
[info] [pid:13113] Starting isotovideo container
[debug] [pid:13113] Registered process:13120
[info] [pid:13120] 13120: WORKING 7
[info] [pid:13113] isotovideo has been started (PID: 13120)
[debug] [pid:13120] +++ worker notes +++
[debug] [pid:13113] Running job 7 from http://localhost:9526: 00000007-tinycore-1-flavor-i386-Build1-core@coolone.
[debug] [pid:13113] REST-API call: POST http://localhost:9526/api/v1/jobs/7/status
[debug] [pid:12076] Updating seen of worker 1 from worker_status (working)
[debug] [pid:13113] Upload concluded (no current module)
# Wait for jQuery successful: wait_for_result_panel: waiting for '(?^u:Result: passed)' (count 10 of 3240)
# Wait for jQuery successful: wait_for_result_panel: waiting for '(?^u:Result: passed)' (count 11 of 3240)
# Wait for jQuery successful: wait_for_result_panel: waiting for '(?^u:Result: passed)' (count 12 of 3240)
# Wait for jQuery successful: wait_for_result_panel: waiting for '(?^u:Result: passed)' (count 13 of 3240)
[debug] [pid:12077] Unrecognized referer 'localhost'
# Wait for jQuery successful: wait_for_result_panel: waiting for '(?^u:Result: passed)' (count 14 of 3240)
# Wait for jQuery successful: wait_for_result_panel: waiting for '(?^u:Result: passed)' (count 15 of 3240)
# Wait for jQuery successful: wait_for_result_panel: waiting for '(?^u:Result: passed)' (count 16 of 3240)
# Wait for jQuery successful: wait_for_result_panel: waiting for '(?^u:Result: passed)' (count 17 of 3240)
# Wait for jQuery successful: wait_for_result_panel: waiting for '(?^u:Result: passed)' (count 18 of 3240)
# Wait for jQuery successful: wait_for_result_panel: waiting for '(?^u:Result: passed)' (count 19 of 3240)
# Wait for jQuery successful: wait_for_result_panel: waiting for '(?^u:Result: passed)' (count 20 of 3240)
# Wait for jQuery successful: wait_for_result_panel: waiting for '(?^u:Result: passed)' (count 21 of 3240)
# Wait for jQuery successful: wait_for_result_panel: waiting for '(?^u:Result: passed)' (count 22 of 3240)
# Wait for jQuery successful: wait_for_result_panel: waiting for '(?^u:Result: passed)' (count 23 of 3240)
[debug] [pid:12077] Unrecognized referer 'localhost'
# Wait for jQuery successful: wait_for_result_panel: waiting for '(?^u:Result: passed)' (count 24 of 3240)
# Wait for jQuery successful: wait_for_result_panel: waiting for '(?^u:Result: passed)' (count 25 of 3240)
# Wait for jQuery successful: wait_for_result_panel: waiting for '(?^u:Result: passed)' (count 26 of 3240)
# Wait for jQuery successful: wait_for_result_panel: waiting for '(?^u:Result: passed)' (count 27 of 3240)
# Wait for jQuery successful: wait_for_result_panel: waiting for '(?^u:Result: passed)' (count 28 of 3240)
[debug] [pid:13113] REST-API call: POST http://localhost:9526/api/v1/jobs/7/status
[debug] [pid:13113] Upload concluded (at boot)
# Wait for jQuery successful: wait_for_result_panel: waiting for '(?^u:Result: passed)' (count 29 of 3240)
# Wait for jQuery successful: wait_for_result_panel: waiting for '(?^u:Result: passed)' (count 30 of 3240)
# Wait for jQuery successful: wait_for_result_panel: waiting for '(?^u:Result: passed)' (count 31 of 3240)
# Wait for jQuery successful: wait_for_result_panel: waiting for '(?^u:Result: passed)' (count 32 of 3240)
# Wait for jQuery successful: wait_for_result_panel: waiting for '(?^u:Result: passed)' (count 33 of 3240)
[debug] [pid:12077] Unrecognized referer 'localhost'
[debug] [pid:12077] Unrecognized referer 'localhost'
[debug] [pid:12156] connecting to os-autoinst command server for job 7 at ws://1234cbae1a16:20013/NyTrTQWMU40CyqS4/ws
# Wait for jQuery successful: wait_for_result_panel: waiting for '(?^u:Result: passed)' (count 34 of 3240)
# Wait for jQuery successful: wait_for_result_panel: waiting for '(?^u:Result: passed)' (count 35 of 3240)
# Wait for jQuery successful: wait_for_result_panel: waiting for '(?^u:Result: passed)' (count 36 of 3240)
# Wait for jQuery successful: wait_for_result_panel: waiting for '(?^u:Result: passed)' (count 37 of 3240)
# Wait for jQuery successful: wait_for_result_panel: waiting for '(?^u:Result: passed)' (count 38 of 3240)
# Wait for jQuery successful: wait_for_result_panel: waiting for '(?^u:Result: passed)' (count 39 of 3240)
# Wait for jQuery successful: wait_for_result_panel: waiting for '(?^u:Result: passed)' (count 40 of 3240)
# Wait for jQuery successful: wait_for_result_panel: waiting for '(?^u:Result: passed)' (count 41 of 3240)
# Wait for jQuery successful: wait_for_result_panel: waiting for '(?^u:Result: passed)' (count 42 of 3240)
[debug] [pid:12077] Unrecognized referer 'localhost'
# Wait for jQuery successful: wait_for_result_panel: waiting for '(?^u:Result: passed)' (count 43 of 3240)
# Wait for jQuery successful: wait_for_result_panel: waiting for '(?^u:Result: passed)' (count 44 of 3240)
# Wait for jQuery successful: wait_for_result_panel: waiting for '(?^u:Result: passed)' (count 45 of 3240)
# Wait for jQuery successful: wait_for_result_panel: waiting for '(?^u:Result: passed)' (count 46 of 3240)
# Wait for jQuery successful: wait_for_result_panel: waiting for '(?^u:Result: passed)' (count 47 of 3240)
[debug] [pid:12076] Updating seen of worker 1 from worker_status (working)
[debug] [pid:13113] REST-API call: POST http://localhost:9526/api/v1/jobs/7/status
# Wait for jQuery successful: wait_for_result_panel: waiting for '(?^u:Result: passed)' (count 48 of 3240)
[debug] [pid:13113] Upload concluded (at boot)
# Wait for jQuery successful: wait_for_result_panel: waiting for '(?^u:Result: passed)' (count 49 of 3240)
# Wait for jQuery successful: wait_for_result_panel: waiting for '(?^u:Result: passed)' (count 50 of 3240)
# Wait for jQuery successful: wait_for_result_panel: waiting for '(?^u:Result: passed)' (count 51 of 3240)
# Wait for jQuery successful: wait_for_result_panel: waiting for '(?^u:Result: passed)' (count 52 of 3240)
[debug] [pid:12077] Unrecognized referer 'localhost'
# Wait for jQuery successful: wait_for_result_panel: waiting for '(?^u:Result: passed)' (count 53 of 3240)
# Wait for jQuery successful: wait_for_result_panel: waiting for '(?^u:Result: passed)' (count 54 of 3240)
# Wait for jQuery successful: wait_for_result_panel: waiting for '(?^u:Result: passed)' (count 55 of 3240)
# Wait for jQuery successful: wait_for_result_panel: waiting for '(?^u:Result: passed)' (count 56 of 3240)
# Wait for jQuery successful: wait_for_result_panel: waiting for '(?^u:Result: passed)' (count 57 of 3240)
# Wait for jQuery successful: wait_for_result_panel: waiting for '(?^u:Result: passed)' (count 58 of 3240)
# Wait for jQuery successful: wait_for_result_panel: waiting for '(?^u:Result: passed)' (count 59 of 3240)
# Wait for jQuery successful: wait_for_result_panel: waiting for '(?^u:Result: passed)' (count 60 of 3240)
# Wait for jQuery successful: wait_for_result_panel: waiting for '(?^u:Result: passed)' (count 61 of 3240)
[debug] [pid:12077] Unrecognized referer 'localhost'
# Wait for jQuery successful: wait_for_result_panel: waiting for '(?^u:Result: passed)' (count 62 of 3240)
# Wait for jQuery successful: wait_for_result_panel: waiting for '(?^u:Result: passed)' (count 63 of 3240)
# Wait for jQuery successful: wait_for_result_panel: waiting for '(?^u:Result: passed)' (count 64 of 3240)
# Wait for jQuery successful: wait_for_result_panel: waiting for '(?^u:Result: passed)' (count 65 of 3240)
# Wait for jQuery successful: wait_for_result_panel: waiting for '(?^u:Result: passed)' (count 66 of 3240)
# Wait for jQuery successful: wait_for_result_panel: waiting for '(?^u:Result: passed)' (count 67 of 3240)
[debug] [pid:13113] REST-API call: POST http://localhost:9526/api/v1/jobs/7/status
[debug] [pid:12077] creating f41/844/68dbb276a03240907d0e7e500d.png
[debug] [pid:12077] creating 68d/7ac/83452b72555f8a6b386629f91f.png
[debug] [pid:13113] Upload concluded (up to boot)
# Wait for jQuery successful: wait_for_result_panel: waiting for '(?^u:Result: passed)' (count 68 of 3240)
# Wait for jQuery successful: wait_for_result_panel: waiting for '(?^u:Result: passed)' (count 69 of 3240)
# Wait for jQuery successful: wait_for_result_panel: waiting for '(?^u:Result: passed)' (count 70 of 3240)
# Wait for jQuery successful: wait_for_result_panel: waiting for '(?^u:Result: passed)' (count 71 of 3240)
[debug] [pid:12077] Unrecognized referer 'localhost'
[debug] [pid:12077] Unrecognized referer 'localhost'
[debug] looking for "f41/844/.thumbs/68dbb276a03240907d0e7e500d.png" in ["/tmp/7v4CAal1xt/full-stack.d/openqa/images"]
[debug] found bless({
path => "/tmp/7v4CAal1xt/full-stack.d/openqa/images/f41/844/.thumbs/68dbb276a03240907d0e7e500d.png",
pid => 12077,
}, "Mojo::Asset::File")
[debug] looking for "68d/7ac/.thumbs/83452b72555f8a6b386629f91f.png" in ["/tmp/7v4CAal1xt/full-stack.d/openqa/images"]
[debug] found bless({
path => "/tmp/7v4CAal1xt/full-stack.d/openqa/images/68d/7ac/.thumbs/83452b72555f8a6b386629f91f.png",
pid => 12077,
}, "Mojo::Asset::File")
# Wait for jQuery successful: wait_for_result_panel: waiting for '(?^u:Result: passed)' (count 72 of 3240)
# Wait for jQuery successful: wait_for_result_panel: waiting for '(?^u:Result: passed)' (count 73 of 3240)
# Wait for jQuery successful: wait_for_result_panel: waiting for '(?^u:Result: passed)' (count 74 of 3240)
# Wait for jQuery successful: wait_for_result_panel: waiting for '(?^u:Result: passed)' (count 75 of 3240)
# Wait for jQuery successful: wait_for_result_panel: waiting for '(?^u:Result: passed)' (count 76 of 3240)
# Wait for jQuery successful: wait_for_result_panel: waiting for '(?^u:Result: passed)' (count 77 of 3240)
# Wait for jQuery successful: wait_for_result_panel: waiting for '(?^u:Result: passed)' (count 78 of 3240)
# Wait for jQuery successful: wait_for_result_panel: waiting for '(?^u:Result: passed)' (count 79 of 3240)
# Wait for jQuery successful: wait_for_result_panel: waiting for '(?^u:Result: passed)' (count 80 of 3240)
[debug] [pid:12077] Unrecognized referer 'localhost'
# Wait for jQuery successful: wait_for_result_panel: waiting for '(?^u:Result: passed)' (count 81 of 3240)
# Wait for jQuery successful: wait_for_result_panel: waiting for '(?^u:Result: passed)' (count 82 of 3240)
# Wait for jQuery successful: wait_for_result_panel: waiting for '(?^u:Result: passed)' (count 83 of 3240)
# Wait for jQuery successful: wait_for_result_panel: waiting for '(?^u:Result: passed)' (count 84 of 3240)
# Wait for jQuery successful: wait_for_result_panel: waiting for '(?^u:Result: passed)' (count 85 of 3240)
[debug] [pid:12076] Updating seen of worker 1 from worker_status (working)
# Wait for jQuery successful: wait_for_result_panel: waiting for '(?^u:Result: passed)' (count 86 of 3240)
[debug] [pid:13113] REST-API call: POST http://localhost:9526/api/v1/jobs/7/status
[debug] [pid:13113] Upload concluded (at shutdown)
# Wait for jQuery successful: wait_for_result_panel: waiting for '(?^u:Result: passed)' (count 87 of 3240)
# Wait for jQuery successful: wait_for_result_panel: waiting for '(?^u:Result: passed)' (count 88 of 3240)
# Wait for jQuery successful: wait_for_result_panel: waiting for '(?^u:Result: passed)' (count 89 of 3240)
# Wait for jQuery successful: wait_for_result_panel: waiting for '(?^u:Result: passed)' (count 90 of 3240)
[debug] [pid:12077] Unrecognized referer 'localhost'
# Wait for jQuery successful: wait_for_result_panel: waiting for '(?^u:Result: passed)' (count 91 of 3240)
# Wait for jQuery successful: wait_for_result_panel: waiting for '(?^u:Result: passed)' (count 92 of 3240)
# Wait for jQuery successful: wait_for_result_panel: waiting for '(?^u:Result: passed)' (count 93 of 3240)
# Wait for jQuery successful: wait_for_result_panel: waiting for '(?^u:Result: passed)' (count 94 of 3240)
# Wait for jQuery successful: wait_for_result_panel: waiting for '(?^u:Result: passed)' (count 95 of 3240)
# Wait for jQuery successful: wait_for_result_panel: waiting for '(?^u:Result: passed)' (count 96 of 3240)
# Wait for jQuery successful: wait_for_result_panel: waiting for '(?^u:Result: passed)' (count 97 of 3240)
# Wait for jQuery successful: wait_for_result_panel: waiting for '(?^u:Result: passed)' (count 98 of 3240)
# Wait for jQuery successful: wait_for_result_panel: waiting for '(?^u:Result: passed)' (count 99 of 3240)
# Wait for jQuery successful: wait_for_result_panel: waiting for '(?^u:Result: passed)' (count 100 of 3240)
[debug] [pid:12077] Unrecognized referer 'localhost'
# Wait for jQuery successful: wait_for_result_panel: waiting for '(?^u:Result: passed)' (count 101 of 3240)
# Wait for jQuery successful: wait_for_result_panel: waiting for '(?^u:Result: passed)' (count 102 of 3240)
# Wait for jQuery successful: wait_for_result_panel: waiting for '(?^u:Result: passed)' (count 103 of 3240)
# Wait for jQuery successful: wait_for_result_panel: waiting for '(?^u:Result: passed)' (count 104 of 3240)
# Wait for jQuery successful: wait_for_result_panel: waiting for '(?^u:Result: passed)' (count 105 of 3240)
[debug] [pid:13113] REST-API call: POST http://localhost:9526/api/v1/jobs/7/status
[debug] [pid:13113] Upload concluded (at shutdown)
# Wait for jQuery successful: wait_for_result_panel: waiting for '(?^u:Result: passed)' (count 106 of 3240)
# Wait for jQuery successful: wait_for_result_panel: waiting for '(?^u:Result: passed)' (count 107 of 3240)
# Wait for jQuery successful: wait_for_result_panel: waiting for '(?^u:Result: passed)' (count 108 of 3240)
# Wait for jQuery successful: wait_for_result_panel: waiting for '(?^u:Result: passed)' (count 109 of 3240)
[debug] [pid:12077] Unrecognized referer 'localhost'
# Wait for jQuery successful: wait_for_result_panel: waiting for '(?^u:Result: passed)' (count 110 of 3240)
# Wait for jQuery successful: wait_for_result_panel: waiting for '(?^u:Result: passed)' (count 111 of 3240)
# Wait for jQuery successful: wait_for_result_panel: waiting for '(?^u:Result: passed)' (count 112 of 3240)
# Wait for jQuery successful: wait_for_result_panel: waiting for '(?^u:Result: passed)' (count 113 of 3240)
# Wait for jQuery successful: wait_for_result_panel: waiting for '(?^u:Result: passed)' (count 114 of 3240)
# Wait for jQuery successful: wait_for_result_panel: waiting for '(?^u:Result: passed)' (count 115 of 3240)
# Wait for jQuery successful: wait_for_result_panel: waiting for '(?^u:Result: passed)' (count 116 of 3240)
# Wait for jQuery successful: wait_for_result_panel: waiting for '(?^u:Result: passed)' (count 117 of 3240)
# Wait for jQuery successful: wait_for_result_panel: waiting for '(?^u:Result: passed)' (count 118 of 3240)
# Wait for jQuery successful: wait_for_result_panel: waiting for '(?^u:Result: passed)' (count 119 of 3240)
[debug] [pid:12077] Unrecognized referer 'localhost'
# Wait for jQuery successful: wait_for_result_panel: waiting for '(?^u:Result: passed)' (count 120 of 3240)
# Wait for jQuery successful: wait_for_result_panel: waiting for '(?^u:Result: passed)' (count 121 of 3240)
# Wait for jQuery successful: wait_for_result_panel: waiting for '(?^u:Result: passed)' (count 122 of 3240)
# Wait for jQuery successful: wait_for_result_panel: waiting for '(?^u:Result: passed)' (count 123 of 3240)
# Wait for jQuery successful: wait_for_result_panel: waiting for '(?^u:Result: passed)' (count 124 of 3240)
[debug] [pid:12076] Updating seen of worker 1 from worker_status (working)
# Wait for jQuery successful: wait_for_result_panel: waiting for '(?^u:Result: passed)' (count 125 of 3240)
[debug] [pid:13113] REST-API call: POST http://localhost:9526/api/v1/jobs/7/status
[debug] [pid:13113] Upload concluded (at shutdown)
# Wait for jQuery successful: wait_for_result_panel: waiting for '(?^u:Result: passed)' (count 126 of 3240)
# Wait for jQuery successful: wait_for_result_panel: waiting for '(?^u:Result: passed)' (count 127 of 3240)
# Wait for jQuery successful: wait_for_result_panel: waiting for '(?^u:Result: passed)' (count 128 of 3240)
# Wait for jQuery successful: wait_for_result_panel: waiting for '(?^u:Result: passed)' (count 129 of 3240)
[debug] [pid:12077] Unrecognized referer 'localhost'
# Wait for jQuery successful: wait_for_result_panel: waiting for '(?^u:Result: passed)' (count 130 of 3240)
# Wait for jQuery successful: wait_for_result_panel: waiting for '(?^u:Result: passed)' (count 131 of 3240)
# Wait for jQuery successful: wait_for_result_panel: waiting for '(?^u:Result: passed)' (count 132 of 3240)
# Wait for jQuery successful: wait_for_result_panel: waiting for '(?^u:Result: passed)' (count 133 of 3240)
# Wait for jQuery successful: wait_for_result_panel: waiting for '(?^u:Result: passed)' (count 134 of 3240)
# Wait for jQuery successful: wait_for_result_panel: waiting for '(?^u:Result: passed)' (count 135 of 3240)
# Wait for jQuery successful: wait_for_result_panel: waiting for '(?^u:Result: passed)' (count 136 of 3240)
# Wait for jQuery successful: wait_for_result_panel: waiting for '(?^u:Result: passed)' (count 137 of 3240)
# Wait for jQuery successful: wait_for_result_panel: waiting for '(?^u:Result: passed)' (count 138 of 3240)
[debug] [pid:12077] Unrecognized referer 'localhost'
# Wait for jQuery successful: wait_for_result_panel: waiting for '(?^u:Result: passed)' (count 139 of 3240)
# Wait for jQuery successful: wait_for_result_panel: waiting for '(?^u:Result: passed)' (count 140 of 3240)
# Wait for jQuery successful: wait_for_result_panel: waiting for '(?^u:Result: passed)' (count 141 of 3240)
# Wait for jQuery successful: wait_for_result_panel: waiting for '(?^u:Result: passed)' (count 142 of 3240)
# Wait for jQuery successful: wait_for_result_panel: waiting for '(?^u:Result: passed)' (count 143 of 3240)
# Wait for jQuery successful: wait_for_result_panel: waiting for '(?^u:Result: passed)' (count 144 of 3240)
[debug] [pid:13113] REST-API call: POST http://localhost:9526/api/v1/jobs/7/status
[debug] [pid:13113] Upload concluded (at shutdown)
# Wait for jQuery successful: wait_for_result_panel: waiting for '(?^u:Result: passed)' (count 145 of 3240)
# Wait for jQuery successful: wait_for_result_panel: waiting for '(?^u:Result: passed)' (count 146 of 3240)
# Wait for jQuery successful: wait_for_result_panel: waiting for '(?^u:Result: passed)' (count 147 of 3240)
# Wait for jQuery successful: wait_for_result_panel: waiting for '(?^u:Result: passed)' (count 148 of 3240)
[debug] [pid:12077] Unrecognized referer 'localhost'
# Wait for jQuery successful: wait_for_result_panel: waiting for '(?^u:Result: passed)' (count 149 of 3240)
# Wait for jQuery successful: wait_for_result_panel: waiting for '(?^u:Result: passed)' (count 150 of 3240)
# Wait for jQuery successful: wait_for_result_panel: waiting for '(?^u:Result: passed)' (count 151 of 3240)
# Wait for jQuery successful: wait_for_result_panel: waiting for '(?^u:Result: passed)' (count 152 of 3240)
# Wait for jQuery successful: wait_for_result_panel: waiting for '(?^u:Result: passed)' (count 153 of 3240)
# Wait for jQuery successful: wait_for_result_panel: waiting for '(?^u:Result: passed)' (count 154 of 3240)
# Wait for jQuery successful: wait_for_result_panel: waiting for '(?^u:Result: passed)' (count 155 of 3240)
# Wait for jQuery successful: wait_for_result_panel: waiting for '(?^u:Result: passed)' (count 156 of 3240)
# Wait for jQuery successful: wait_for_result_panel: waiting for '(?^u:Result: passed)' (count 157 of 3240)
# Wait for jQuery successful: wait_for_result_panel: waiting for '(?^u:Result: passed)' (count 158 of 3240)
[debug] [pid:12077] Unrecognized referer 'localhost'
# Wait for jQuery successful: wait_for_result_panel: waiting for '(?^u:Result: passed)' (count 159 of 3240)
# Wait for jQuery successful: wait_for_result_panel: waiting for '(?^u:Result: passed)' (count 160 of 3240)
# Wait for jQuery successful: wait_for_result_panel: waiting for '(?^u:Result: passed)' (count 161 of 3240)
# Wait for jQuery successful: wait_for_result_panel: waiting for '(?^u:Result: passed)' (count 162 of 3240)
[debug] [pid:12076] Updating seen of worker 1 from worker_status (working)
# Wait for jQuery successful: wait_for_result_panel: waiting for '(?^u:Result: passed)' (count 163 of 3240)
[debug] [pid:13113] REST-API call: POST http://localhost:9526/api/v1/jobs/7/status
[debug] [pid:13113] Upload concluded (at shutdown)
# Wait for jQuery successful: wait_for_result_panel: waiting for '(?^u:Result: passed)' (count 164 of 3240)
# Wait for jQuery successful: wait_for_result_panel: waiting for '(?^u:Result: passed)' (count 165 of 3240)
# Wait for jQuery successful: wait_for_result_panel: waiting for '(?^u:Result: passed)' (count 166 of 3240)
# Wait for jQuery successful: wait_for_result_panel: waiting for '(?^u:Result: passed)' (count 167 of 3240)
[debug] [pid:12077] Unrecognized referer 'localhost'
# Wait for jQuery successful: wait_for_result_panel: waiting for '(?^u:Result: passed)' (count 168 of 3240)
# Wait for jQuery successful: wait_for_result_panel: waiting for '(?^u:Result: passed)' (count 169 of 3240)
# Wait for jQuery successful: wait_for_result_panel: waiting for '(?^u:Result: passed)' (count 170 of 3240)
# Wait for jQuery successful: wait_for_result_panel: waiting for '(?^u:Result: passed)' (count 171 of 3240)
# Wait for jQuery successful: wait_for_result_panel: waiting for '(?^u:Result: passed)' (count 172 of 3240)
# Wait for jQuery successful: wait_for_result_panel: waiting for '(?^u:Result: passed)' (count 173 of 3240)
# Wait for jQuery successful: wait_for_result_panel: waiting for '(?^u:Result: passed)' (count 174 of 3240)
# Wait for jQuery successful: wait_for_result_panel: waiting for '(?^u:Result: passed)' (count 175 of 3240)
# Wait for jQuery successful: wait_for_result_panel: waiting for '(?^u:Result: passed)' (count 176 of 3240)
[debug] [pid:12077] Unrecognized referer 'localhost'
# Wait for jQuery successful: wait_for_result_panel: waiting for '(?^u:Result: passed)' (count 177 of 3240)
# Wait for jQuery successful: wait_for_result_panel: waiting for '(?^u:Result: passed)' (count 178 of 3240)
# Wait for jQuery successful: wait_for_result_panel: waiting for '(?^u:Result: passed)' (count 179 of 3240)
# Wait for jQuery successful: wait_for_result_panel: waiting for '(?^u:Result: passed)' (count 180 of 3240)
# Wait for jQuery successful: wait_for_result_panel: waiting for '(?^u:Result: passed)' (count 181 of 3240)
# Wait for jQuery successful: wait_for_result_panel: waiting for '(?^u:Result: passed)' (count 182 of 3240)
[debug] [pid:13113] REST-API call: POST http://localhost:9526/api/v1/jobs/7/status
[debug] [pid:13113] Upload concluded (at shutdown)
# Wait for jQuery successful: wait_for_result_panel: waiting for '(?^u:Result: passed)' (count 183 of 3240)
# Wait for jQuery successful: wait_for_result_panel: waiting for '(?^u:Result: passed)' (count 184 of 3240)
# Wait for jQuery successful: wait_for_result_panel: waiting for '(?^u:Result: passed)' (count 185 of 3240)
# Wait for jQuery successful: wait_for_result_panel: waiting for '(?^u:Result: passed)' (count 186 of 3240)
[debug] [pid:12077] Unrecognized referer 'localhost'
# Wait for jQuery successful: wait_for_result_panel: waiting for '(?^u:Result: passed)' (count 187 of 3240)
# Wait for jQuery successful: wait_for_result_panel: waiting for '(?^u:Result: passed)' (count 188 of 3240)
# Wait for jQuery successful: wait_for_result_panel: waiting for '(?^u:Result: passed)' (count 189 of 3240)
# Wait for jQuery successful: wait_for_result_panel: waiting for '(?^u:Result: passed)' (count 190 of 3240)
# Wait for jQuery successful: wait_for_result_panel: waiting for '(?^u:Result: passed)' (count 191 of 3240)
# Wait for jQuery successful: wait_for_result_panel: waiting for '(?^u:Result: passed)' (count 192 of 3240)
# Wait for jQuery successful: wait_for_result_panel: waiting for '(?^u:Result: passed)' (count 193 of 3240)
# Wait for jQuery successful: wait_for_result_panel: waiting for '(?^u:Result: passed)' (count 194 of 3240)
# Wait for jQuery successful: wait_for_result_panel: waiting for '(?^u:Result: passed)' (count 195 of 3240)
# Wait for jQuery successful: wait_for_result_panel: waiting for '(?^u:Result: passed)' (count 196 of 3240)
[debug] [pid:12077] Unrecognized referer 'localhost'
# Wait for jQuery successful: wait_for_result_panel: waiting for '(?^u:Result: passed)' (count 197 of 3240)
# Wait for jQuery successful: wait_for_result_panel: waiting for '(?^u:Result: passed)' (count 198 of 3240)
# Wait for jQuery successful: wait_for_result_panel: waiting for '(?^u:Result: passed)' (count 199 of 3240)
# Wait for jQuery successful: wait_for_result_panel: waiting for '(?^u:Result: passed)' (count 200 of 3240)
[debug] [pid:12076] Updating seen of worker 1 from worker_status (working)
# Wait for jQuery successful: wait_for_result_panel: waiting for '(?^u:Result: passed)' (count 201 of 3240)
# Wait for jQuery successful: wait_for_result_panel: waiting for '(?^u:Result: passed)' (count 202 of 3240)
[debug] [pid:13113] REST-API call: POST http://localhost:9526/api/v1/jobs/7/status
[debug] [pid:13113] Upload concluded (at shutdown)
# Wait for jQuery successful: wait_for_result_panel: waiting for '(?^u:Result: passed)' (count 203 of 3240)
# Wait for jQuery successful: wait_for_result_panel: waiting for '(?^u:Result: passed)' (count 204 of 3240)
# Wait for jQuery successful: wait_for_result_panel: waiting for '(?^u:Result: passed)' (count 205 of 3240)
# Wait for jQuery successful: wait_for_result_panel: waiting for '(?^u:Result: passed)' (count 206 of 3240)
[debug] [pid:12077] Unrecognized referer 'localhost'
# Wait for jQuery successful: wait_for_result_panel: waiting for '(?^u:Result: passed)' (count 207 of 3240)
# Wait for jQuery successful: wait_for_result_panel: waiting for '(?^u:Result: passed)' (count 208 of 3240)
# Wait for jQuery successful: wait_for_result_panel: waiting for '(?^u:Result: passed)' (count 209 of 3240)
# Wait for jQuery successful: wait_for_result_panel: waiting for '(?^u:Result: passed)' (count 210 of 3240)
# Wait for jQuery successful: wait_for_result_panel: waiting for '(?^u:Result: passed)' (count 211 of 3240)
# Wait for jQuery successful: wait_for_result_panel: waiting for '(?^u:Result: passed)' (count 212 of 3240)
# Wait for jQuery successful: wait_for_result_panel: waiting for '(?^u:Result: passed)' (count 213 of 3240)
# Wait for jQuery successful: wait_for_result_panel: waiting for '(?^u:Result: passed)' (count 214 of 3240)
# Wait for jQuery successful: wait_for_result_panel: waiting for '(?^u:Result: passed)' (count 215 of 3240)
[debug] [pid:12077] Unrecognized referer 'localhost'
# Wait for jQuery successful: wait_for_result_panel: waiting for '(?^u:Result: passed)' (count 216 of 3240)
# Wait for jQuery successful: wait_for_result_panel: waiting for '(?^u:Result: passed)' (count 217 of 3240)
# Wait for jQuery successful: wait_for_result_panel: waiting for '(?^u:Result: passed)' (count 218 of 3240)
# Wait for jQuery successful: wait_for_result_panel: waiting for '(?^u:Result: passed)' (count 219 of 3240)
# Wait for jQuery successful: wait_for_result_panel: waiting for '(?^u:Result: passed)' (count 220 of 3240)
# Wait for jQuery successful: wait_for_result_panel: waiting for '(?^u:Result: passed)' (count 221 of 3240)
[debug] [pid:13113] REST-API call: POST http://localhost:9526/api/v1/jobs/7/status
[debug] [pid:13113] Upload concluded (at shutdown)
# Wait for jQuery successful: wait_for_result_panel: waiting for '(?^u:Result: passed)' (count 222 of 3240)
# Wait for jQuery successful: wait_for_result_panel: waiting for '(?^u:Result: passed)' (count 223 of 3240)
# Wait for jQuery successful: wait_for_result_panel: waiting for '(?^u:Result: passed)' (count 224 of 3240)
# Wait for jQuery successful: wait_for_result_panel: waiting for '(?^u:Result: passed)' (count 225 of 3240)
[debug] [pid:12077] Unrecognized referer 'localhost'
# Wait for jQuery successful: wait_for_result_panel: waiting for '(?^u:Result: passed)' (count 226 of 3240)
# Wait for jQuery successful: wait_for_result_panel: waiting for '(?^u:Result: passed)' (count 227 of 3240)
# Wait for jQuery successful: wait_for_result_panel: waiting for '(?^u:Result: passed)' (count 228 of 3240)
[info] [pid:13113] Isotovideo exit status: 0
[debug] [pid:13113] Stopping job 7 from http://localhost:9526: 00000007-tinycore-1-flavor-i386-Build1-core@coolone - reason: done
[debug] [pid:13113] REST-API call: POST http://localhost:9526/api/v1/jobs/7/status
[info] [pid:13113] +++ worker notes +++
[info] [pid:13113] End time: 2022-02-15 12:31:56
[info] [pid:13113] Result: done
[info] [pid:13355] Uploading video.ogv
[debug] [pid:13355] Uploading artefact video.ogv
[info] [pid:13355] Uploading vars.json
[debug] [pid:13355] Uploading artefact vars.json
# Wait for jQuery successful: wait_for_result_panel: waiting for '(?^u:Result: passed)' (count 229 of 3240)
[info] [pid:13355] Uploading autoinst-log.txt
[debug] [pid:13355] Uploading artefact autoinst-log.txt
[info] [pid:13355] Uploading worker-log.txt
[debug] [pid:13355] Uploading artefact worker-log.txt
[info] [pid:13355] Uploading serial0.txt
[debug] [pid:13355] Uploading artefact serial0.txt
[info] [pid:13355] Uploading video_time.vtt
[debug] [pid:13355] Uploading artefact video_time.vtt
[info] [pid:13355] Uploading serial_terminal.txt
[debug] [pid:13355] Uploading artefact serial_terminal.txt
[info] [pid:13355] Uploading virtio_console1.log
[debug] [pid:13355] Uploading artefact virtio_console1.log
[debug] [pid:13113] Considering job 7 as regularly done
[debug] [pid:13113] REST-API call: POST http://localhost:9526/api/v1/jobs/7/status
[debug] [pid:12077] creating e3b/43b/69c91fe4072dac1037f416c281.png
[debug] [pid:12077] creating e3b/43b/69c91fe4072dac1037f416c281.png
[debug] [pid:12077] creating 6fd/a92/0dc3d756977372a982f6c2ce5e.png
[debug] [pid:13356] Optimizing /tmp/7v4CAal1xt/full-stack.d/openqa/pool/1/testresults/shutdown-2.png
[debug] [pid:13356] Uploading artefact shutdown-2.png as 6fda920dc3d756977372a982f6c2ce5e
[debug] [pid:13356] Optimizing /tmp/7v4CAal1xt/full-stack.d/openqa/pool/1/testresults/.thumbs/shutdown-2.png
[debug] [pid:13356] Uploading artefact shutdown-2.png as 6fda920dc3d756977372a982f6c2ce5e
[debug] [pid:13356] Uploading artefact shutdown-3.txt
[debug] [pid:13113] Upload concluded (no current module)
[debug] [pid:13113] REST-API call: POST http://localhost:9526/api/v1/jobs/7/set_done?worker_id=1
# Wait for jQuery successful: wait_for_result_panel: waiting for '(?^u:Result: passed)' (count 230 of 3240)
[debug] [pid:12077] checking take over from 6: GOOD vs shutdown:failed
[debug] [pid:12077] checking take over from 5: GOOD vs shutdown:failed
[debug] [pid:12077] ignoring job with repeated problem
[debug] [pid:12077] checking take over from 1: GOOD vs shutdown:failed
[debug] [pid:12077] ignoring job with repeated problem
[debug] [pid:13113] Job 7 from http://localhost:9526 finished - reason: done
[debug] [pid:13113] Cleaning up for next job
# Wait for jQuery successful: wait_for_result_panel: waiting for '(?^u:Result: passed)' (count 231 of 3240)
# Wait for jQuery successful: wait_for_result_panel: waiting for '(?^u:Result: passed)' (count 232 of 3240)
# Wait for jQuery successful: wait_for_result_panel: waiting for '(?^u:Result: passed)' (count 233 of 3240)
# Wait for jQuery successful: wait_for_result_panel: waiting for '(?^u:Result: passed)' (count 234 of 3240)
# Wait for jQuery successful: wait_for_result_panel: waiting for '(?^u:Result: passed)' (count 235 of 3240)
[debug] [pid:12077] Unrecognized referer 'localhost'
[debug] [pid:12077] Unrecognized referer 'localhost'
[debug] [pid:12077] Unrecognized referer 'localhost'
[debug] looking for "e3b/43b/.thumbs/69c91fe4072dac1037f416c281.png" in ["/tmp/7v4CAal1xt/full-stack.d/openqa/images"]
[debug] found bless({
path => "/tmp/7v4CAal1xt/full-stack.d/openqa/images/e3b/43b/.thumbs/69c91fe4072dac1037f416c281.png",
pid => 12077,
}, "Mojo::Asset::File")
[debug] looking for "6fd/a92/.thumbs/0dc3d756977372a982f6c2ce5e.png" in ["/tmp/7v4CAal1xt/full-stack.d/openqa/images"]
[debug] found bless({
path => "/tmp/7v4CAal1xt/full-stack.d/openqa/images/6fd/a92/.thumbs/0dc3d756977372a982f6c2ce5e.png",
pid => 12077,
}, "Mojo::Asset::File")
# Wait for jQuery successful: wait_for_result_panel: waiting for '(?^u:Result: passed)' (count 236 of 3240)
ok 1 - No unexpected js warnings
not ok 2 - Expected result not found
not ok 3 - job 7 passed
# job info: {
# 'assigned_worker_id' => 1,
# 'blocked_by_id' => undef,
# 'clone_id' => undef,
# 'group_id' => undef,
# 'id' => 7,
# 'name' => 'tinycore-1-flavor-i386-Build1-core@coolone',
# 'origin_id' => 6,
# 'priority' => 50,
# 'result' => 'failed',
# 'settings' => {
# 'ARCH' => 'i386',
# 'BUILD' => '1',
# 'DISTRI' => 'tinycore',
# 'FLAVOR' => 'flavor',
# 'INTEGRATION_TESTS' => '1',
# 'ISO' => 'Core-7.2.iso',
# 'MACHINE' => 'coolone',
# 'NAME' => '00000007-tinycore-1-flavor-i386-Build1-core@coolone',
# 'PUBLISH_HDD_1' => '',
# 'QEMU' => 'i386',
# 'QEMU_NO_FDC_SET' => '1',
# 'QEMU_NO_KVM' => '1',
# 'QEMU_NO_TABLET' => '1',
# 'TEST' => 'core',
# 'UEFI_PFLASH_VARS' => '/usr/share/qemu/ovmf-x86_64.bin',
# 'VERSION' => '1',
# 'WORKER_CLASS' => 'qemu_i386'
# },
# 'state' => 'done',
# 't_finished' => '2022-02-15T12:31:57',
# 't_started' => '2022-02-15T12:29:56',
# 'test' => 'core'
# }
ok 4 - Test 7 autoinst-log.txt file created
ok 5 - Test 7 has worker notes
ok 6 - setup notes present
ok 7 - uploaded autoinst-log
1..7
not ok 20 - results of test 7
[warn] [pid:12077] Unable to wakeup scheduler: Connection refused
ok 21 - job with worker class qemu_i386 scheduled
ok 22 - at least one free worker with class qemu_i386 registered
[debug] [pid:12072] +=----------------=+
[debug] [pid:12072] -> Scheduling new jobs.
[debug] [pid:12072] Free workers: 1/1
[debug] [pid:12072] Scheduled jobs: 1
[debug] [pid:12072] Need to schedule 1 parallel jobs for job 8 (with priority 50)
[debug] [pid:12072] Assigned job '8' to worker ID '1'
[debug] [pid:12072] [Job#8] Prepare for being processed by worker 1
[debug] [pid:12076] Started to send message to 1 for job(s) 8
[debug] [pid:12072] Sent job(s) '8' to worker '1'
[debug] [pid:12072] Scheduler took 0.09755s to perform operations and allocated 1 jobs
[debug] [pid:12072] Allocated: { job => 8, worker => 1 }
[debug] [pid:13113] Accepting job 8 from http://localhost:9526.
[debug] [pid:13113] Setting job 8 from http://localhost:9526 up
[debug] [pid:13113] Preparing Mojo::IOLoop::ReadWriteProcess::Session
[info] [pid:13113] +++ setup notes +++
[info] [pid:13113] Running on 1234cbae1a16:1 (Linux 5.11.0-1027-aws #30~20.04.1-Ubuntu SMP Thu Jan 13 11:46:53 UTC 2022 x86_64)
[debug] [pid:13113] Job settings:
[debug] [pid:13113]
ARCH=i386
BUILD=1
CACHEDIRECTORY=/tmp/7v4CAal1xt/full-stack.d/cache
CACHELIMIT=50
DISTRI=tinycore
FLAVOR=flavor
HDD_1=non-existent.qcow2
INTEGRATION_TESTS=1
ISO=Core-7.2.iso
JOBTOKEN=02CWEpXQzQrJmeVL
LOCAL_UPLOAD=0
LOG_LEVEL=debug
MACHINE=coolone
NAME=00000008-tinycore-1-flavor-i386-Build1-core@coolone
OPENQA_HOSTNAME=localhost:9526
OPENQA_URL=http://localhost:9526
PRJDIR=/tmp/7v4CAal1xt/full-stack.d/openqa/share
PUBLISH_HDD_1=core-hdd.qcow2
QEMU=i386
QEMUPORT=20012
QEMU_NO_FDC_SET=1
QEMU_NO_KVM=1
QEMU_NO_TABLET=1
RETRY_DELAY=5
RETRY_DELAY_IF_WEBUI_BUSY=60
TEST=core
UEFI_PFLASH_VARS=/usr/share/qemu/ovmf-x86_64.bin
VERSION=1
VNC=91
WORKER_CLASS=qemu_i386,qemu_x86_64
WORKER_ID=1
WORKER_INSTANCE=1
[debug] [pid:13113] Found HDD_1, caching non-existent.qcow2
[info] [pid:13113] Downloading non-existent.qcow2, request #4 sent to Cache Service
[debug] [pid:13113] Updating status so job 8 is not considered dead.
[debug] [pid:13113] REST-API call: POST http://localhost:9526/api/v1/jobs/8/status
[debug] [pid:12077] Unrecognized referer 'localhost'
[debug] [pid:12076] Worker 1 accepted job 8
[debug] [pid:12077] Unrecognized referer 'localhost'
[debug] [pid:12076] Updating seen of worker 1 from worker_status (working)
[debug] [pid:12077] Unrecognized referer 'localhost'
[debug] [pid:12077] Unrecognized referer 'localhost'
[debug] [pid:12077] Unrecognized referer 'localhost'
[debug] attempt to open ws proxy for job tinycore-1-flavor-i386-Build1-core@coolone (8) where URL to os-autoinst command server is unknown
[debug] [pid:12077] Unrecognized referer 'localhost'
[debug] [pid:12077] Asking the worker 1 to start providing livestream for job 8
[debug] redirect to /assets/hdd/non-existent.qcow2
# Wait for jQuery successful: wait_for_result_panel: waiting for '(?^u:Result: incomplete)' (count 0 of 3240)
# Wait for jQuery successful: wait_for_result_panel: waiting for '(?^u:Result: incomplete)' (count 1 of 3240)
# Wait for jQuery successful: wait_for_result_panel: waiting for '(?^u:Result: incomplete)' (count 2 of 3240)
# Wait for jQuery successful: wait_for_result_panel: waiting for '(?^u:Result: incomplete)' (count 3 of 3240)
# Wait for jQuery successful: wait_for_result_panel: waiting for '(?^u:Result: incomplete)' (count 4 of 3240)
# Wait for jQuery successful: wait_for_result_panel: waiting for '(?^u:Result: incomplete)' (count 5 of 3240)
# Wait for jQuery successful: wait_for_result_panel: waiting for '(?^u:Result: incomplete)' (count 6 of 3240)
# Wait for jQuery successful: wait_for_result_panel: waiting for '(?^u:Result: incomplete)' (count 7 of 3240)
# Wait for jQuery successful: wait_for_result_panel: waiting for '(?^u:Result: incomplete)' (count 8 of 3240)
# Wait for jQuery successful: wait_for_result_panel: waiting for '(?^u:Result: incomplete)' (count 9 of 3240)
[debug] [pid:13113] Updating status so job 8 is not considered dead.
[debug] [pid:13113] REST-API call: POST http://localhost:9526/api/v1/jobs/8/status
[debug] [pid:12077] Unrecognized referer 'localhost'
[info] [pid:13113] Download of non-existent.qcow2 processed
[error] [pid:13113] Failed to download non-existent.qcow2 to /tmp/7v4CAal1xt/full-stack.d/cache/localhost/non-existent.qcow2
[error] [pid:13113] Unable to setup job 8: Failed to download non-existent.qcow2 to /tmp/7v4CAal1xt/full-stack.d/cache/localhost/non-existent.qcow2
[debug] [pid:13113] Stopping job 8 from http://localhost:9526: 00000008-tinycore-1-flavor-i386-Build1-core@coolone - reason: setup failure
[debug] [pid:13113] REST-API call: POST http://localhost:9526/api/v1/jobs/8/status
[info] [pid:13113] +++ worker notes +++
[info] [pid:13113] End time: 2022-02-15 12:32:06
[info] [pid:13113] Result: setup failure
[info] [pid:13363] Uploading autoinst-log.txt
[debug] [pid:13363] Uploading artefact autoinst-log.txt
[info] [pid:13363] Uploading worker-log.txt
[debug] [pid:13363] Uploading artefact worker-log.txt
[debug] [pid:13113] Job 8 stopped as incomplete
[warn] [pid:13113] Unable to upload results of the job because no command server URL or worker ID have been set.
[debug] [pid:13113] Upload concluded (no current module)
[debug] [pid:13113] REST-API call: POST http://localhost:9526/api/v1/jobs/8/set_done?reason=cache+failure%3A+Failed+to+download+non-existent.qcow2+to+%2Ftmp%2F7v4CAal1xt%2Ffull-stack.d%2Fcache%2Flocalhost%2Fnon-existent.qcow2&result=incomplete&worker_id=1
[debug] [pid:12077] Duplicating jobs: {
8 => {
chained_children => [],
chained_parents => [],
directly_chained_children => [],
directly_chained_parents => [],
is_parent_or_initial_job => 1,
ok => 0,
parallel_children => [],
parallel_parents => [],
state => "done",
},
}
[debug] [pid:12077] Job 8 duplicated as 9
[debug] [pid:13113] Job 8 from http://localhost:9526 finished - reason: setup failure
[debug] [pid:13113] Cleaning up for next job
# Wait for jQuery successful: wait_for_result_panel: waiting for '(?^u:Result: incomplete)' (count 10 of 3240)
# Wait for jQuery successful: wait_for_result_panel: waiting for '(?^u:Result: incomplete)' (count 11 of 3240)
# Wait for jQuery successful: wait_for_result_panel: waiting for '(?^u:Result: incomplete)' (count 12 of 3240)
# Wait for jQuery successful: wait_for_result_panel: waiting for '(?^u:Result: incomplete)' (count 13 of 3240)
# Wait for jQuery successful: wait_for_result_panel: waiting for '(?^u:Result: incomplete)' (count 14 of 3240)
# Wait for jQuery successful: wait_for_result_panel: waiting for '(?^u:Result: incomplete)' (count 15 of 3240)
# Wait for jQuery successful: wait_for_result_panel: waiting for '(?^u:Result: incomplete)' (count 16 of 3240)
# Wait for jQuery successful: wait_for_result_panel: waiting for '(?^u:Result: incomplete)' (count 17 of 3240)
# Wait for jQuery successful: wait_for_result_panel: waiting for '(?^u:Result: incomplete)' (count 18 of 3240)
[debug] [pid:12077] Unrecognized referer 'localhost'
[debug] [pid:12077] Unrecognized referer 'localhost'
[debug] [pid:12077] Unrecognized referer 'localhost'
[debug] [pid:12077] Unrecognized referer 'localhost'
[debug] looking for "autoinst-log.txt" in [
"/tmp/7v4CAal1xt/full-stack.d/openqa/testresults/00000/00000008-tinycore-1-flavor-i386-Build1-core\@coolone",
"/tmp/7v4CAal1xt/full-stack.d/openqa/testresults/00000/00000008-tinycore-1-flavor-i386-Build1-core\@coolone/ulogs",
]
[debug] found bless({
path => "/tmp/7v4CAal1xt/full-stack.d/openqa/testresults/00000/00000008-tinycore-1-flavor-i386-Build1-core\@coolone/autoinst-log.txt",
pid => 12077,
}, "Mojo::Asset::File")
# Wait for jQuery successful: wait_for_result_panel: waiting for '(?^u:Result: incomplete)' (count 19 of 3240)
ok 23 - job 8 is incomplete
ok 24 - reason for incomplete specified
# Subtest: log shown within details tab (without page reload)
# Wait for jQuery successful: autoinst log embedded within "Details" tab
ok 1 - element for embedded logfile present
# Wait for jQuery successful: log contents loaded
ok 2 - log contents present
1..2
ok 25 - log shown within details tab (without page reload)
# Subtest: results of test 8
ok 1 - autoinst-log.txt file created
ok 2 - worker notes present
ok 3 - setup notes present
ok 4 - autoinst-log uploaded
ok 5 - failure message found in log
ok 6 - job result result
1..6
ok 26 - results of test 8
[info] [pid:13113] Received signal TERM
[debug] [pid:13113] Informing http://localhost:9526 that we are going offline
[info] [pid:12076] Worker 1 websocket connection closed - 1006
1..26
not ok 36 - Cache tests
ok 37 - no (unexpected) warnings (via done_testing)
1..37
# Worker cache service on port 9530 stopped
# Cache minion worker stopped
/tmp/7v4CAal1xt/full-stack.d/openqa/testresults/00000/00000001-tinycore-1-flavor-i386-Build1-core@coolone/autoinst-log.txt:
[2022-02-15T12:27:28.001355Z] [info] [pid:12162] +++ setup notes +++
[2022-02-15T12:27:28.001593Z] [info] [pid:12162] Running on 1234cbae1a16:1 (Linux 5.11.0-1027-aws #30~20.04.1-Ubuntu SMP Thu Jan 13 11:46:53 UTC 2022 x86_64)
[2022-02-15T12:27:28.007666Z] [debug] [pid:12169] +++ worker notes +++
[2022-02-15T12:27:29.767964Z] [debug] Current version is a7103b16a88ac5669f56dab460989dea6c74d9fa [interface v24]
[2022-02-15T12:27:29.777649Z] [debug] git hash in tinycore: a7103b16a88ac5669f56dab460989dea6c74d9fa
[2022-02-15T12:27:29.869664Z] [debug] scheduling boot tests/boot.pm
[2022-02-15T12:27:29.870412Z] [debug] scheduling assert_screen tests/assert_screen.pm
[2022-02-15T12:27:29.871031Z] [debug] scheduling shutdown tests/shutdown.pm
[2022-02-15T12:27:29.877257Z] [info] cmdsrv: daemon reachable under http://*:20013/Dlzx3oXeqolMvMJJ/
[2022-02-15T12:27:29.879413Z] [info] Listening at "http://0.0.0.0:20013"
Web application available at http://0.0.0.0:20013
[2022-02-15T12:27:29.881441Z] [debug] git hash in tinycore/needles: a7103b16a88ac5669f56dab460989dea6c74d9fa
[2022-02-15T12:27:29.881582Z] [debug] init needles from tinycore/needles
[2022-02-15T12:27:29.883166Z] [debug] loaded 4 needles
[2022-02-15T12:27:29.886386Z] [debug] Blocking SIGCHLD and SIGTERM
[2022-02-15T12:27:30.051039Z] [debug] Unblocking SIGCHLD and SIGTERM
[2022-02-15T12:27:30.132568Z] [debug] Blocking SIGCHLD and SIGTERM
[2022-02-15T12:27:30.132755Z] [debug] 12169: channel_out 15, channel_in 14
[2022-02-15T12:27:30.250837Z] [debug] Unblocking SIGCHLD and SIGTERM
[2022-02-15T12:27:30.252449Z] [debug] 12248: cmdpipe 13, rsppipe 16
[2022-02-15T12:27:30.252538Z] [debug] started mgmt loop with pid 12248
[2022-02-15T12:27:30.354725Z] [debug] qemu version detected: 5.2.0
[2022-02-15T12:27:30.356337Z] [debug] running `/usr/bin/chattr +C /tmp/7v4CAal1xt/full-stack.d/openqa/pool/1/raid`
[2022-02-15T12:27:30.455072Z] [debug] Fatal error in command `/usr/bin/chattr +C /tmp/7v4CAal1xt/full-stack.d/openqa/pool/1/raid`: open3: exec of /usr/bin/chattr +C /tmp/7v4CAal1xt/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-02-15T12:27:30.455208Z] [debug] Configuring storage controllers and block devices
[2022-02-15T12:27:30.455988Z] [debug] running `/usr/bin/qemu-img info --output=json /tmp/7v4CAal1xt/full-stack.d/openqa/pool/1/Core-7.2.iso`
[2022-02-15T12:27:30.468838Z] [debug] Initializing block device images
[2022-02-15T12:27:30.469027Z] [debug] running `/usr/bin/qemu-img create -f qcow2 /tmp/7v4CAal1xt/full-stack.d/openqa/pool/1/raid/hd0 10G`
[2022-02-15T12:27:30.482556Z] [debug] Formatting '/tmp/7v4CAal1xt/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-02-15T12:27:30.482683Z] [debug] running `/usr/bin/qemu-img create -f qcow2 -F raw -b /tmp/7v4CAal1xt/full-stack.d/openqa/pool/1/Core-7.2.iso /tmp/7v4CAal1xt/full-stack.d/openqa/pool/1/raid/cd0-overlay0 11116544`
[2022-02-15T12:27:30.495024Z] [debug] Formatting '/tmp/7v4CAal1xt/full-stack.d/openqa/pool/1/raid/cd0-overlay0', fmt=qcow2 cluster_size=65536 extended_l2=off compression_type=zlib size=11116544 backing_file=/tmp/7v4CAal1xt/full-stack.d/openqa/pool/1/Core-7.2.iso backing_fmt=raw lazy_refcounts=off refcount_bits=16
[2022-02-15T12:27:30.495117Z] [debug] init_blockdev_images: Finished creating block devices
[2022-02-15T12:27:30.496321Z] [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=/tmp/7v4CAal1xt/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=/tmp/7v4CAal1xt/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-02-15T12:27:30.500664Z] [debug] Waiting for 0 attempts
[2022-02-15T12:27:31.501272Z] [debug] Waiting for 1 attempts
[2022-02-15T12:27:32.501642Z] [debug] Finished after 2 attempts
[2022-02-15T12:27:32.503591Z] [debug] Establishing VNC connection to localhost:5991
[2022-02-15T12:27:32.506320Z] [debug] pointer type 0 0 640 480 -257
[2022-02-15T12:27:32.506405Z] [debug] led state 0 1 1 -261
[2022-02-15T12:27:32.566236Z] [debug] Start CPU
[2022-02-15T12:27:32.566528Z] [debug] EVENT {"data":{"client":{"family":"ipv4","host":"127.0.0.1","service":"35010","websocket":false},"server":{"auth":"none","family":"ipv4","host":"0.0.0.0","service":"5991","websocket":false}},"event":"VNC_CONNECTED","timestamp":{"microseconds":504253,"seconds":1644928052}}
[2022-02-15T12:27:32.566691Z] [debug] EVENT {"data":{"client":{"family":"ipv4","host":"127.0.0.1","service":"35010","websocket":false},"server":{"auth":"none","family":"ipv4","host":"0.0.0.0","service":"5991","websocket":false}},"event":"VNC_INITIALIZED","timestamp":{"microseconds":505214,"seconds":1644928052}}
[2022-02-15T12:27:32.566810Z] [debug] EVENT {"event":"RESUME","timestamp":{"microseconds":566624,"seconds":1644928052}}
GOT GO

[2022-02-15T12:27:32.574963Z] [debug] QEMU: QEMU emulator version 5.2.0 (SUSE Linux Enterprise 15)
[2022-02-15T12:27:32.575026Z] [debug] QEMU: Copyright (c) 2003-2020 Fabrice Bellard and the QEMU Project developers
[2022-02-15T12:27:32.578677Z] [debug] Snapshots are supported
[2022-02-15T12:27:32.579879Z] [debug] ||| starting boot tests/boot.pm
[2022-02-15T12:27:32.582012Z] [debug] tests/boot.pm:9 called testapi::assert_screen
[2022-02-15T12:27:32.582368Z] [debug] <<< testapi::assert_screen(mustmatch="core", no_wait=1, timeout=15)
[2022-02-15T12:27:32.596707Z] [debug] no match: 14.9s, best candidate: boot-core (0.00)
[2022-02-15T12:27:32.697520Z] [debug] no change: 14.8s
[2022-02-15T12:27:32.704170Z] [debug] no match: 14.8s, best candidate: boot-core (0.00)
[2022-02-15T12:27:32.804918Z] [debug] no change: 14.7s
[2022-02-15T12:27:32.811662Z] [debug] no match: 14.7s, best candidate: boot-core (0.00)
[2022-02-15T12:27:32.912361Z] [debug] no change: 14.6s
[2022-02-15T12:27:32.919043Z] [debug] no match: 14.6s, best candidate: boot-core (0.00)
[2022-02-15T12:27:33.019833Z] [debug] no change: 14.5s
[2022-02-15T12:27:33.030108Z] [debug] no match: 14.5s, best candidate: boot-core (0.00)
[2022-02-15T12:27:33.209031Z] [debug] >>> testapi::_handle_found_needle: found boot-core, similarity 0.97 @ 1/74
[2022-02-15T12:27:33.209872Z] [debug] tests/boot.pm:10 called testapi::send_key
[2022-02-15T12:27:33.210007Z] [debug] <<< testapi::send_key(key="ret", do_wait=0, wait_screen_change=0)
[2022-02-15T12:27:33.479595Z] [debug] tests/boot.pm:14 called testapi::assert_screen
[2022-02-15T12:27:33.479752Z] [debug] <<< testapi::assert_screen(mustmatch="on_prompt", timeout=90)
[2022-02-15T12:27:34.139103Z] [debug] no match: 89.3s, best candidate: boot-on_prompt (0.00)
[2022-02-15T12:27:35.133617Z] [debug] no match: 88.3s, best candidate: boot-on_prompt (0.00)
[2022-02-15T12:27:36.135300Z] [debug] no match: 87.3s, best candidate: boot-on_prompt (0.00)
[2022-02-15T12:27:37.135887Z] [debug] no match: 86.3s, best candidate: boot-on_prompt (0.00)
[2022-02-15T12:27:38.204916Z] [debug] no match: 85.3s, best candidate: boot-on_prompt (0.00)
[2022-02-15T12:27:39.138040Z] [debug] no match: 84.3s, best candidate: boot-on_prompt (0.00)
[2022-02-15T12:27:40.138742Z] [debug] no match: 83.3s, best candidate: boot-on_prompt (0.00)
[2022-02-15T12:27:41.139936Z] [debug] no match: 82.3s, best candidate: boot-on_prompt (0.00)
[2022-02-15T12:27:42.141187Z] [debug] no match: 81.3s, best candidate: boot-on_prompt (0.00)
[2022-02-15T12:27:43.245051Z] [debug] >>> testapi::_handle_found_needle: found boot-on_prompt, similarity 1.00 @ 2/64
[2022-02-15T12:27:43.247437Z] [debug] ||| finished boot tests (runtime: 11 s)
[2022-02-15T12:27:43.250206Z] [debug] ||| starting assert_screen tests/assert_screen.pm
[2022-02-15T12:27:43.251143Z] [debug] tests/assert_screen.pm:9 called testapi::assert_screen
[2022-02-15T12:27:43.251276Z] [debug] <<< testapi::assert_screen(mustmatch="on_prompt", timeout=60)
[2022-02-15T12:27:44.207004Z] [debug] >>> testapi::_handle_found_needle: found boot-on_prompt, similarity 1.00 @ 2/64
[2022-02-15T12:27:44.207157Z] [debug] tests/assert_screen.pm:10 called testapi::assert_screen
[2022-02-15T12:27:44.207262Z] [debug] <<< testapi::assert_screen(mustmatch="on_prompt", timeout=30, no_wait=1)
[2022-02-15T12:27:44.284940Z] [debug] >>> testapi::_handle_found_needle: found boot-on_prompt, similarity 1.00 @ 2/64
[2022-02-15T12:27:44.286302Z] [debug] ||| finished assert_screen tests (runtime: 1 s)
[2022-02-15T12:27:44.288019Z] [debug] ||| starting shutdown tests/shutdown.pm
[2022-02-15T12:27:44.288665Z] [debug] isotovideo: pausing test execution of shutdown because we're supposed to pause at this test module
[2022-02-15T12:27:44.289164Z] [debug] tests/shutdown.pm:8 called testapi::type_string
[2022-02-15T12:27:44.289383Z] [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-02-15T12:27:44.289805Z] [debug] isotovideo: paused, so not passing backend_type_string to backend
[2022-02-15T12:27:46.276671Z] [debug] isotovideo: test execution will be resumed
[2022-02-15T12:27:46.277093Z] [debug] isotovideo: resuming, continue passing backend_type_string to backend
[2022-02-15T12:27:46.548310Z] [debug] tests/shutdown.pm:9 called testapi::type_string
[2022-02-15T12:27:46.548513Z] [debug] <<< testapi::type_string(string="poweroff\n", max_interval=250, wait_screen_changes=0, wait_still_screen=0, timeout=30, similarity_level=47)
[2022-02-15T12:27:46.853477Z] [debug] tests/shutdown.pm:10 called testapi::assert_shutdown
[2022-02-15T12:27:46.853656Z] [debug] <<< testapi::check_shutdown(timeout=90)
[2022-02-15T12:27:46.854387Z] [debug] EVENT {"data":{"path":"\/machine\/peripheral-anon\/device[2]\/virtio-backend"},"event":"NIC_RX_FILTER_CHANGED","timestamp":{"microseconds":812966,"seconds":1644928064}}
[2022-02-15T12:27:46.854600Z] [debug] QEMU status is not 'shutdown', it is 'running'
[2022-02-15T12:27:47.855934Z] [debug] QEMU status is not 'shutdown', it is 'running'
[2022-02-15T12:27:48.857302Z] [debug] QEMU status is not 'shutdown', it is 'running'
[2022-02-15T12:27:49.858699Z] [debug] QEMU status is not 'shutdown', it is 'running'
[2022-02-15T12:27:50.860191Z] [debug] QEMU status is not 'shutdown', it is 'running'
[2022-02-15T12:27:51.861332Z] [debug] EVENT {"data":{"guest":true,"reason":"guest-shutdown"},"event":"SHUTDOWN","timestamp":{"microseconds":245848,"seconds":1644928071}}
[2022-02-15T12:27:51.861465Z] [debug] EVENT {"event":"STOP","timestamp":{"microseconds":246355,"seconds":1644928071}}
[2022-02-15T12:27:51.927393Z] [debug] ||| finished shutdown tests (runtime: 7 s)
[2022-02-15T12:27:51.929157Z] [debug] stopping autotest process 12178
[2022-02-15T12:27:51.933699Z] [debug] [autotest] process exited: 0
[2022-02-15T12:27:52.034135Z] [debug] done with autotest process
[2022-02-15T12:27:52.034528Z] [debug] stopping command server 12175 because test execution ended
[2022-02-15T12:27:52.034585Z] [debug] isotovideo: informing websocket clients before stopping command server: http://127.0.0.1:20013/Dlzx3oXeqolMvMJJ/broadcast
[2022-02-15T12:27:52.046968Z] [debug] commands process exited: 0
[2022-02-15T12:27:52.147312Z] [debug] done with command server
[2022-02-15T12:27:52.147385Z] [debug] isotovideo done
[2022-02-15T12:27:52.148102Z] [debug] backend shutdown state: 1
[2022-02-15T12:27:52.148520Z] [info] ::: OpenQA::Qemu::Proc::save_state: Saving QEMU state to qemu_state.json
[2022-02-15T12:27:53.159224Z] [debug] Passing remaining frames to the video encoder
[2022-02-15T12:27:53.191900Z] [debug] Waiting for video encoder to finalize the video
[2022-02-15T12:27:53.191978Z] [debug] The built-in video encoder (pid 12318) terminated
[2022-02-15T12:27:53.192463Z] [debug] QEMU: qemu-system-i386: terminating on signal 15 from pid 12248 (/home/squamata/os-autoinst/isotovideo: backen)
[2022-02-15T12:27:53.193273Z] [debug] sending magic and exit
[2022-02-15T12:27:53.193504Z] [debug] received magic close
[2022-02-15T12:27:53.201047Z] [debug] backend process exited: 0
[2022-02-15T12:27:53.302309Z] [info] ::: backend::qemu::do_extract_assets: Extracting (?^u:^hd0$)
[2022-02-15T12:27:53.302430Z] [debug] running `nice ionice qemu-img convert -c -O qcow2 /tmp/7v4CAal1xt/full-stack.d/openqa/pool/1/raid/hd0 assets_public/core-hdd.qcow2`
[2022-02-15T12:27:53.316086Z] [debug] running `qemu-img info --output=json assets_public/core-hdd.qcow2`
[2022-02-15T12:27:53.324980Z] [debug] stopping backend process 12248
[2022-02-15T12:27:53.325055Z] [debug] done with backend process
12169: EXIT 0
[2022-02-15T12:27:53.339899Z] [info] [pid:12162] Isotovideo exit status: 0
[2022-02-15T12:27:53.377646Z] [info] [pid:12162] +++ worker notes +++
[2022-02-15T12:27:53.377966Z] [info] [pid:12162] End time: 2022-02-15 12:27:53
[2022-02-15T12:27:53.378116Z] [info] [pid:12162] Result: done
[2022-02-15T12:27:53.383264Z] [info] [pid:12422] Uploading core-hdd.qcow2
[2022-02-15T12:27:53.447143Z] [info] [pid:12422] Uploading video.ogv
[2022-02-15T12:27:53.480052Z] [info] [pid:12422] Uploading vars.json
[2022-02-15T12:27:53.509831Z] [info] [pid:12422] Uploading autoinst-log.txt
/tmp/7v4CAal1xt/full-stack.d/openqa/testresults/00000/00000001-tinycore-1-flavor-i386-Build1-core@coolone/serial0.txt:
/tmp/7v4CAal1xt/full-stack.d/openqa/testresults/00000/00000001-tinycore-1-flavor-i386-Build1-core@coolone/serial_terminal.txt:
/tmp/7v4CAal1xt/full-stack.d/openqa/testresults/00000/00000001-tinycore-1-flavor-i386-Build1-core@coolone/worker-log.txt:
[2022-02-15T12:27:28.000943Z] [debug] [pid:12162] Preparing Mojo::IOLoop::ReadWriteProcess::Session
[2022-02-15T12:27:28.001831Z] [debug] [pid:12162] Job settings:
[2022-02-15T12:27:28.001962Z] [debug] [pid:12162]
ARCH=i386
BUILD=1
DISTRI=tinycore
FLAVOR=flavor
INTEGRATION_TESTS=1
ISO=Core-7.2.iso
JOBTOKEN=Dlzx3oXeqolMvMJJ
LOG_LEVEL=debug
MACHINE=coolone
NAME=00000001-tinycore-1-flavor-i386-Build1-core@coolone
OPENQA_HOSTNAME=localhost:9526
OPENQA_URL=http://localhost:9526
PAUSE_AT=shutdown
PRJDIR=/tmp/7v4CAal1xt/full-stack.d/openqa/share
PUBLISH_HDD_1=core-hdd.qcow2
QEMU=i386
QEMUPORT=20012
QEMU_NO_FDC_SET=1
QEMU_NO_KVM=1
QEMU_NO_TABLET=1
RETRY_DELAY=5
RETRY_DELAY_IF_WEBUI_BUSY=60
TEST=core
UEFI_PFLASH_VARS=/usr/share/qemu/ovmf-x86_64.bin
VERSION=1
VNC=91
WORKER_CLASS=qemu_i386,qemu_x86_64
WORKER_HOSTNAME=127.0.0.1
WORKER_ID=1
WORKER_INSTANCE=1
[2022-02-15T12:27:28.002464Z] [debug] [pid:12162] Linked asset "/tmp/7v4CAal1xt/full-stack.d/openqa/share/factory/iso/Core-7.2.iso" to "/tmp/7v4CAal1xt/full-stack.d/openqa/pool/1/Core-7.2.iso"
[2022-02-15T12:27:28.002793Z] [debug] [pid:12162] Symlinked from "/tmp/7v4CAal1xt/full-stack.d/openqa/share/tests/tinycore" to "/tmp/7v4CAal1xt/full-stack.d/openqa/pool/1/tinycore"
[2022-02-15T12:27:28.003098Z] [info] [pid:12162] Preparing cgroup to start isotovideo
[2022-02-15T12:27:28.004094Z] [warn] [pid:12162] Disabling cgroup usage because cgroup creation failed: mkdir /sys/fs/cgroup/systemd/docker: Permission denied at /usr/lib/perl5/vendor_perl/5.26.1/Mojo/File.pm line 84.
[2022-02-15T12:27:28.004222Z] [info] [pid:12162] You can define a custom slice with OPENQA_CGROUP_SLICE or indicating the base mount with MOJO_CGROUP_FS.
[2022-02-15T12:27:28.004528Z] [info] [pid:12162] Starting isotovideo container
[2022-02-15T12:27:28.007169Z] [debug] [pid:12162] Registered process:12169
[2022-02-15T12:27:28.007434Z] [info] [pid:12169] 12169: WORKING 1
[2022-02-15T12:27:28.007651Z] [info] [pid:12162] isotovideo has been started (PID: 12169)
[2022-02-15T12:27:28.008226Z] [debug] [pid:12162] Running job 1 from http://localhost:9526: 00000001-tinycore-1-flavor-i386-Build1-core@coolone.
[2022-02-15T12:27:28.010162Z] [debug] [pid:12162] REST-API call: POST http://localhost:9526/api/v1/jobs/1/status
[2022-02-15T12:27:28.070221Z] [debug] [pid:12162] Upload concluded (no current module)
[2022-02-15T12:27:30.697761Z] [debug] [pid:12162] Starting livelog
[2022-02-15T12:27:30.699913Z] [debug] [pid:12162] REST-API call: POST http://localhost:9526/api/v1/jobs/1/status
[2022-02-15T12:27:30.749293Z] [debug] [pid:12162] Upload concluded (no current module)
[2022-02-15T12:27:30.988681Z] [debug] [pid:12162] Stopping livelog
[2022-02-15T12:27:31.750751Z] [debug] [pid:12162] REST-API call: POST http://localhost:9526/api/v1/jobs/1/status
[2022-02-15T12:27:31.796024Z] [debug] [pid:12162] Upload concluded (no current module)
[2022-02-15T12:27:41.804421Z] [debug] [pid:12162] REST-API call: POST http://localhost:9526/api/v1/jobs/1/status
[2022-02-15T12:27:41.874235Z] [debug] [pid:12162] Upload concluded (at boot)
[2022-02-15T12:27:46.594215Z] [debug] [pid:12162] Starting livelog
[2022-02-15T12:27:46.595826Z] [debug] [pid:12162] REST-API call: POST http://localhost:9526/api/v1/jobs/1/status
[2022-02-15T12:27:46.813763Z] [debug] [pid:12401] Optimizing /tmp/7v4CAal1xt/full-stack.d/openqa/pool/1/testresults/boot-1.png
[2022-02-15T12:27:46.892481Z] [debug] [pid:12401] Uploading artefact boot-1.png as f4184468dbb276a03240907d0e7e500d
[2022-02-15T12:27:46.925410Z] [debug] [pid:12401] Optimizing /tmp/7v4CAal1xt/full-stack.d/openqa/pool/1/testresults/.thumbs/boot-1.png
[2022-02-15T12:27:46.931740Z] [debug] [pid:12401] Uploading artefact boot-1.png as f4184468dbb276a03240907d0e7e500d
[2022-02-15T12:27:46.983246Z] [debug] [pid:12401] Optimizing /tmp/7v4CAal1xt/full-stack.d/openqa/pool/1/testresults/boot-2.png
[2022-02-15T12:27:47.055565Z] [debug] [pid:12401] Uploading artefact boot-2.png as 68d7ac83452b72555f8a6b386629f91f
[2022-02-15T12:27:47.091897Z] [debug] [pid:12401] Optimizing /tmp/7v4CAal1xt/full-stack.d/openqa/pool/1/testresults/.thumbs/boot-2.png
[2022-02-15T12:27:47.098460Z] [debug] [pid:12401] Uploading artefact boot-2.png as 68d7ac83452b72555f8a6b386629f91f
[2022-02-15T12:27:47.129844Z] [debug] [pid:12162] Upload concluded (up to boot)
[2022-02-15T12:27:48.131634Z] [debug] [pid:12162] REST-API call: POST http://localhost:9526/api/v1/jobs/1/status
[2022-02-15T12:27:48.197536Z] [debug] [pid:12162] Upload concluded (at shutdown)
[2022-02-15T12:27:49.200147Z] [debug] [pid:12162] REST-API call: POST http://localhost:9526/api/v1/jobs/1/status
[2022-02-15T12:27:49.277434Z] [debug] [pid:12162] Upload concluded (at shutdown)
[2022-02-15T12:27:50.279538Z] [debug] [pid:12162] REST-API call: POST http://localhost:9526/api/v1/jobs/1/status
[2022-02-15T12:27:50.350297Z] [debug] [pid:12162] Upload concluded (at shutdown)
[2022-02-15T12:27:51.352269Z] [debug] [pid:12162] REST-API call: POST http://localhost:9526/api/v1/jobs/1/status
[2022-02-15T12:27:51.415902Z] [debug] [pid:12162] Upload concluded (at shutdown)
[2022-02-15T12:27:52.418981Z] [debug] [pid:12162] REST-API call: POST http://localhost:9526/api/v1/jobs/1/status
[2022-02-15T12:27:52.528444Z] [debug] [pid:12411] Optimizing /tmp/7v4CAal1xt/full-stack.d/openqa/pool/1/testresults/shutdown-2.png
[2022-02-15T12:27:52.658308Z] [debug] [pid:12411] Uploading artefact shutdown-2.png as 4ec32864be46d7336c00b3b3f4a5fe6d
[2022-02-15T12:27:52.692427Z] [debug] [pid:12411] Optimizing /tmp/7v4CAal1xt/full-stack.d/openqa/pool/1/testresults/.thumbs/shutdown-2.png
[2022-02-15T12:27:52.698986Z] [debug] [pid:12411] Uploading artefact shutdown-2.png as 4ec32864be46d7336c00b3b3f4a5fe6d
[2022-02-15T12:27:52.731231Z] [debug] [pid:12411] Optimizing /tmp/7v4CAal1xt/full-stack.d/openqa/pool/1/testresults/assert_screen-2.png
[2022-02-15T12:27:52.806768Z] [debug] [pid:12411] Uploading artefact assert_screen-2.png as e3b43b69c91fe4072dac1037f416c281
[2022-02-15T12:27:52.839753Z] [debug] [pid:12411] Optimizing /tmp/7v4CAal1xt/full-stack.d/openqa/pool/1/testresults/.thumbs/assert_screen-2.png
[2022-02-15T12:27:52.847376Z] [debug] [pid:12411] Uploading artefact assert_screen-2.png as e3b43b69c91fe4072dac1037f416c281
[2022-02-15T12:27:52.885873Z] [debug] [pid:12162] Upload concluded (up to shutdown)
[2022-02-15T12:27:53.340241Z] [debug] [pid:12162] Stopping job 1 from http://localhost:9526: 00000001-tinycore-1-flavor-i386-Build1-core@coolone - reason: done
[2022-02-15T12:27:53.340931Z] [debug] [pid:12162] REST-API call: POST http://localhost:9526/api/v1/jobs/1/status
[2022-02-15T12:27:53.382789Z] [info] [pid:12422] Uploading core-hdd.qcow2
[2022-02-15T12:27:53.383727Z] [info] [pid:12422] Uploading core-hdd.qcow2 using multiple chunks
[2022-02-15T12:27:53.384849Z] [info] [pid:12422] core-hdd.qcow2: local upload (no chunks needed)
[2022-02-15T12:27:53.447051Z] [info] [pid:12422] Uploading video.ogv
[2022-02-15T12:27:53.447367Z] [debug] [pid:12422] Uploading artefact video.ogv
[2022-02-15T12:27:53.479959Z] [info] [pid:12422] Uploading vars.json
[2022-02-15T12:27:53.480223Z] [debug] [pid:12422] Uploading artefact vars.json
[2022-02-15T12:27:53.509724Z] [info] [pid:12422] Uploading autoinst-log.txt
[2022-02-15T12:27:53.510023Z] [debug] [pid:12422] Uploading artefact autoinst-log.txt
[2022-02-15T12:27:53.536572Z] [info] [pid:12422] Uploading worker-log.txt
[2022-02-15T12:27:53.536818Z] [debug] [pid:12422] Uploading artefact worker-log.txt
/tmp/7v4CAal1xt/full-stack.d/openqa/testresults/00000/00000004-tinycore-1-flavor-i386-Build1-core@noassets/autoinst-log.txt:
[2022-02-15T12:28:18.393375Z] [info] [pid:12644] +++ setup notes +++
[2022-02-15T12:28:18.393734Z] [info] [pid:12644] Running on 1234cbae1a16:1 (Linux 5.11.0-1027-aws #30~20.04.1-Ubuntu SMP Thu Jan 13 11:46:53 UTC 2022 x86_64)
[2022-02-15T12:28:18.394958Z] [error] [pid:12644] HDD_1 handling Cannot find HDD_1 asset hdd/nihilist_disk.hda!
[2022-02-15T12:28:18.421342Z] [info] [pid:12644] +++ worker notes +++
[2022-02-15T12:28:18.421554Z] [info] [pid:12644] End time: 2022-02-15 12:28:18
[2022-02-15T12:28:18.421642Z] [info] [pid:12644] Result: setup failure
[2022-02-15T12:28:18.426016Z] [info] [pid:12650] Uploading autoinst-log.txt
/tmp/7v4CAal1xt/full-stack.d/openqa/testresults/00000/00000004-tinycore-1-flavor-i386-Build1-core@noassets/worker-log.txt:
[2022-02-15T12:28:18.392778Z] [debug] [pid:12644] Preparing Mojo::IOLoop::ReadWriteProcess::Session
[2022-02-15T12:28:18.394101Z] [debug] [pid:12644] Job settings:
[2022-02-15T12:28:18.394325Z] [debug] [pid:12644]
ARCH=i386
BUILD=1
DISTRI=tinycore
FLAVOR=flavor
HDD_1=nihilist_disk.hda
INTEGRATION_TESTS=1
ISO=Core-7.2.iso
JOBTOKEN=jYLqqzusM3UiJ4qg
LOG_LEVEL=debug
MACHINE=noassets
NAME=00000004-tinycore-1-flavor-i386-Build1-core@noassets
OPENQA_HOSTNAME=localhost:9526
OPENQA_URL=http://localhost:9526
PRJDIR=/tmp/7v4CAal1xt/full-stack.d/openqa/share
PUBLISH_HDD_1=core-hdd.qcow2
QEMU=i386
QEMUPORT=20012
QEMU_NO_FDC_SET=1
QEMU_NO_KVM=1
QEMU_NO_TABLET=1
RETRY_DELAY=5
RETRY_DELAY_IF_WEBUI_BUSY=60
TEST=core
UEFI_PFLASH_VARS=/usr/share/qemu/ovmf-x86_64.bin
VERSION=1
VNC=91
WORKER_CLASS=qemu_i386,qemu_x86_64
WORKER_HOSTNAME=127.0.0.1
WORKER_ID=1
WORKER_INSTANCE=1
[2022-02-15T12:28:18.395194Z] [error] [pid:12644] Unable to setup job 4: Cannot find HDD_1 asset hdd/nihilist_disk.hda!
[2022-02-15T12:28:18.395425Z] [debug] [pid:12644] Stopping job 4 from http://localhost:9526: 00000004-tinycore-1-flavor-i386-Build1-core@noassets - reason: setup failure
[2022-02-15T12:28:18.396204Z] [debug] [pid:12644] REST-API call: POST http://localhost:9526/api/v1/jobs/4/status
[2022-02-15T12:28:18.425824Z] [info] [pid:12650] Uploading autoinst-log.txt
[2022-02-15T12:28:18.426336Z] [debug] [pid:12650] Uploading artefact autoinst-log.txt
[2022-02-15T12:28:18.460394Z] [info] [pid:12650] Uploading worker-log.txt
[2022-02-15T12:28:18.460660Z] [debug] [pid:12650] Uploading artefact worker-log.txt
/tmp/7v4CAal1xt/full-stack.d/openqa/testresults/00000/00000005-tinycore-1-flavor-i386-Build1-core@coolone/autoinst-log.txt:
[2022-02-15T12:28:34.036415Z] [info] [pid:12658] +++ setup notes +++
[2022-02-15T12:28:34.036665Z] [info] [pid:12658] Running on 1234cbae1a16:1 (Linux 5.11.0-1027-aws #30~20.04.1-Ubuntu SMP Thu Jan 13 11:46:53 UTC 2022 x86_64)
[2022-02-15T12:28:34.043347Z] [debug] [pid:12658] Found ISO, caching Core-7.2.iso
[2022-02-15T12:28:34.050782Z] [info] [pid:12658] Downloading Core-7.2.iso, request #1 sent to Cache Service
[2022-02-15T12:28:39.171846Z] [info] [pid:12658] Download of Core-7.2.iso processed
[2022-02-15T12:28:39.179606Z] [debug] [pid:12665] +++ worker notes +++
[2022-02-15T12:28:41.114623Z] [debug] Current version is a7103b16a88ac5669f56dab460989dea6c74d9fa [interface v24]
[2022-02-15T12:28:41.125079Z] [debug] git hash in tinycore: a7103b16a88ac5669f56dab460989dea6c74d9fa
[2022-02-15T12:28:41.222825Z] [debug] scheduling boot tests/boot.pm
[2022-02-15T12:28:41.223589Z] [debug] scheduling assert_screen tests/assert_screen.pm
[2022-02-15T12:28:41.224158Z] [debug] scheduling shutdown tests/shutdown.pm
[2022-02-15T12:28:41.230234Z] [info] cmdsrv: daemon reachable under http://*:20013/UHDsvGadPNTdhlYW/
[2022-02-15T12:28:41.232272Z] [info] Listening at "http://0.0.0.0:20013"
Web application available at http://0.0.0.0:20013
[2022-02-15T12:28:41.234300Z] [debug] git hash in tinycore/needles: a7103b16a88ac5669f56dab460989dea6c74d9fa
[2022-02-15T12:28:41.234418Z] [debug] init needles from tinycore/needles
[2022-02-15T12:28:41.235800Z] [debug] loaded 4 needles
[2022-02-15T12:28:41.238923Z] [debug] Blocking SIGCHLD and SIGTERM
[2022-02-15T12:28:41.351394Z] [debug] Unblocking SIGCHLD and SIGTERM
[2022-02-15T12:28:41.511785Z] [debug] 12665: channel_out 15, channel_in 14
[2022-02-15T12:28:41.511763Z] [debug] Blocking SIGCHLD and SIGTERM
[2022-02-15T12:28:41.650993Z] [debug] Unblocking SIGCHLD and SIGTERM
[2022-02-15T12:28:41.653556Z] [debug] 12744: cmdpipe 13, rsppipe 16
[2022-02-15T12:28:41.653742Z] [debug] started mgmt loop with pid 12744
[2022-02-15T12:28:41.853725Z] [debug] qemu version detected: 5.2.0
[2022-02-15T12:28:41.855274Z] [debug] running `/usr/bin/chattr +C /tmp/7v4CAal1xt/full-stack.d/openqa/pool/1/raid`
[2022-02-15T12:28:41.864150Z] [debug] Fatal error in command `/usr/bin/chattr +C /tmp/7v4CAal1xt/full-stack.d/openqa/pool/1/raid`: open3: exec of /usr/bin/chattr +C /tmp/7v4CAal1xt/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-02-15T12:28:41.864270Z] [debug] Configuring storage controllers and block devices
[2022-02-15T12:28:41.864961Z] [debug] running `/usr/bin/qemu-img info --output=json /tmp/7v4CAal1xt/full-stack.d/openqa/pool/1/Core-7.2.iso`
[2022-02-15T12:28:41.959567Z] [debug] Initializing block device images
[2022-02-15T12:28:41.959849Z] [debug] running `/usr/bin/qemu-img create -f qcow2 /tmp/7v4CAal1xt/full-stack.d/openqa/pool/1/raid/hd0 10G`
[2022-02-15T12:28:42.069964Z] [debug] Formatting '/tmp/7v4CAal1xt/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-02-15T12:28:42.070152Z] [debug] running `/usr/bin/qemu-img create -f qcow2 -F raw -b /tmp/7v4CAal1xt/full-stack.d/openqa/pool/1/Core-7.2.iso /tmp/7v4CAal1xt/full-stack.d/openqa/pool/1/raid/cd0-overlay0 11116544`
[2022-02-15T12:28:42.091628Z] [debug] Formatting '/tmp/7v4CAal1xt/full-stack.d/openqa/pool/1/raid/cd0-overlay0', fmt=qcow2 cluster_size=65536 extended_l2=off compression_type=zlib size=11116544 backing_file=/tmp/7v4CAal1xt/full-stack.d/openqa/pool/1/Core-7.2.iso backing_fmt=raw lazy_refcounts=off refcount_bits=16
[2022-02-15T12:28:42.091728Z] [debug] init_blockdev_images: Finished creating block devices
[2022-02-15T12:28:42.092738Z] [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=/tmp/7v4CAal1xt/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=/tmp/7v4CAal1xt/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-02-15T12:28:42.096967Z] [debug] Waiting for 0 attempts
[2022-02-15T12:28:43.097599Z] [debug] Waiting for 1 attempts
[2022-02-15T12:28:44.098021Z] [debug] Finished after 2 attempts
[2022-02-15T12:28:44.100033Z] [debug] Establishing VNC connection to localhost:5991
[2022-02-15T12:28:44.103277Z] [debug] pointer type 0 0 640 480 -257
[2022-02-15T12:28:44.103409Z] [debug] led state 0 1 1 -261
[2022-02-15T12:28:44.163086Z] [debug] Start CPU
[2022-02-15T12:28:44.163358Z] [debug] EVENT {"data":{"client":{"family":"ipv4","host":"127.0.0.1","service":"40860","websocket":false},"server":{"auth":"none","family":"ipv4","host":"0.0.0.0","service":"5991","websocket":false}},"event":"VNC_CONNECTED","timestamp":{"microseconds":100693,"seconds":1644928124}}
[2022-02-15T12:28:44.163439Z] [debug] EVENT {"data":{"client":{"family":"ipv4","host":"127.0.0.1","service":"40860","websocket":false},"server":{"auth":"none","family":"ipv4","host":"0.0.0.0","service":"5991","websocket":false}},"event":"VNC_INITIALIZED","timestamp":{"microseconds":101927,"seconds":1644928124}}
[2022-02-15T12:28:44.163539Z] [debug] EVENT {"event":"RESUME","timestamp":{"microseconds":163470,"seconds":1644928124}}
GOT GO

[2022-02-15T12:28:44.172178Z] [debug] QEMU: QEMU emulator version 5.2.0 (SUSE Linux Enterprise 15)
[2022-02-15T12:28:44.172251Z] [debug] QEMU: Copyright (c) 2003-2020 Fabrice Bellard and the QEMU Project developers
[2022-02-15T12:28:44.175941Z] [debug] Snapshots are supported
[2022-02-15T12:28:44.176878Z] [debug] ||| starting boot tests/boot.pm
[2022-02-15T12:28:44.178709Z] [debug] tests/boot.pm:9 called testapi::assert_screen
[2022-02-15T12:28:44.179032Z] [debug] <<< testapi::assert_screen(mustmatch="core", timeout=15, no_wait=1)
[2022-02-15T12:28:44.195011Z] [debug] no match: 14.9s, best candidate: boot-core (0.00)
[2022-02-15T12:28:44.295798Z] [debug] no change: 14.8s
[2022-02-15T12:28:44.305841Z] [debug] no match: 14.8s, best candidate: boot-core (0.00)
[2022-02-15T12:28:44.406692Z] [debug] no change: 14.7s
[2022-02-15T12:28:44.416383Z] [debug] no match: 14.7s, best candidate: boot-core (0.00)
[2022-02-15T12:28:44.517227Z] [debug] no change: 14.6s
[2022-02-15T12:28:44.527052Z] [debug] no match: 14.6s, best candidate: boot-core (0.00)
[2022-02-15T12:28:44.627902Z] [debug] no change: 14.5s
[2022-02-15T12:28:44.637797Z] [debug] no match: 14.5s, best candidate: boot-core (0.00)
[2022-02-15T12:28:44.826349Z] [debug] >>> testapi::_handle_found_needle: found boot-core, similarity 0.97 @ 1/74
[2022-02-15T12:28:44.827120Z] [debug] tests/boot.pm:10 called testapi::send_key
[2022-02-15T12:28:44.827256Z] [debug] <<< testapi::send_key(key="ret", wait_screen_change=0, do_wait=0)
[2022-02-15T12:28:45.096906Z] [debug] tests/boot.pm:14 called testapi::assert_screen
[2022-02-15T12:28:45.097100Z] [debug] <<< testapi::assert_screen(mustmatch="on_prompt", timeout=90)
[2022-02-15T12:28:45.744296Z] [debug] no match: 89.3s, best candidate: boot-on_prompt (0.00)
[2022-02-15T12:28:46.741728Z] [debug] no match: 88.3s, best candidate: boot-on_prompt (0.00)
[2022-02-15T12:28:47.741809Z] [debug] no match: 87.3s, best candidate: boot-on_prompt (0.00)
[2022-02-15T12:28:48.743279Z] [debug] no match: 86.3s, best candidate: boot-on_prompt (0.00)
[2022-02-15T12:28:49.785602Z] [debug] no match: 85.3s, best candidate: boot-on_prompt (0.00)
[2022-02-15T12:28:50.744546Z] [debug] no match: 84.3s, best candidate: boot-on_prompt (0.00)
[2022-02-15T12:28:51.744919Z] [debug] no match: 83.3s, best candidate: boot-on_prompt (0.00)
[2022-02-15T12:28:52.746015Z] [debug] no match: 82.3s, best candidate: boot-on_prompt (0.00)
[2022-02-15T12:28:53.747204Z] [debug] no match: 81.3s, best candidate: boot-on_prompt (0.00)
[2022-02-15T12:28:54.797723Z] [debug] no match: 80.3s, best candidate: boot-on_prompt (0.00)
[2022-02-15T12:28:55.748521Z] [debug] no match: 79.3s, best candidate: boot-on_prompt (0.00)
[2022-02-15T12:28:56.749891Z] [debug] no match: 78.3s, best candidate: boot-on_prompt (0.00)
[2022-02-15T12:28:57.751035Z] [debug] no match: 77.3s, best candidate: boot-on_prompt (0.00)
[2022-02-15T12:28:58.818009Z] [debug] >>> testapi::_handle_found_needle: found boot-on_prompt, similarity 1.00 @ 2/64
[2022-02-15T12:28:58.820606Z] [debug] ||| finished boot tests (runtime: 14 s)
[2022-02-15T12:28:58.822496Z] [debug] ||| starting assert_screen tests/assert_screen.pm
[2022-02-15T12:28:58.823435Z] [debug] tests/assert_screen.pm:9 called testapi::assert_screen
[2022-02-15T12:28:58.823612Z] [debug] <<< testapi::assert_screen(mustmatch="on_prompt", timeout=60)
[2022-02-15T12:28:59.819680Z] [debug] >>> testapi::_handle_found_needle: found boot-on_prompt, similarity 1.00 @ 2/64
[2022-02-15T12:28:59.819834Z] [debug] tests/assert_screen.pm:10 called testapi::assert_screen
[2022-02-15T12:28:59.819943Z] [debug] <<< testapi::assert_screen(mustmatch="on_prompt", timeout=30, no_wait=1)
[2022-02-15T12:28:59.888265Z] [debug] >>> testapi::_handle_found_needle: found boot-on_prompt, similarity 1.00 @ 2/64
[2022-02-15T12:28:59.889638Z] [debug] ||| finished assert_screen tests (runtime: 1 s)
[2022-02-15T12:28:59.890711Z] [debug] ||| starting shutdown tests/shutdown.pm
[2022-02-15T12:28:59.891500Z] [debug] tests/shutdown.pm:8 called testapi::type_string
[2022-02-15T12:28:59.891687Z] [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-02-15T12:29:00.163314Z] [debug] tests/shutdown.pm:9 called testapi::type_string
[2022-02-15T12:29:00.163568Z] [debug] <<< testapi::type_string(string="poweroff\n", max_interval=250, wait_screen_changes=0, wait_still_screen=0, timeout=30, similarity_level=47)
[2022-02-15T12:29:00.469202Z] [debug] tests/shutdown.pm:10 called testapi::assert_shutdown
[2022-02-15T12:29:00.469362Z] [debug] <<< testapi::check_shutdown(timeout=90)
[2022-02-15T12:29:00.470521Z] [debug] QEMU status is not 'shutdown', it is 'running'
[2022-02-15T12:29:01.472095Z] [debug] QEMU status is not 'shutdown', it is 'running'
[2022-02-15T12:29:02.473548Z] [debug] QEMU status is not 'shutdown', it is 'running'
[2022-02-15T12:29:03.475087Z] [debug] QEMU status is not 'shutdown', it is 'running'
[2022-02-15T12:29:04.476564Z] [debug] QEMU status is not 'shutdown', it is 'running'
[2022-02-15T12:29:05.477986Z] [debug] QEMU status is not 'shutdown', it is 'running'
[2022-02-15T12:29:06.479179Z] [debug] EVENT {"data":{"guest":true,"reason":"guest-shutdown"},"event":"SHUTDOWN","timestamp":{"microseconds":611596,"seconds":1644928145}}
[2022-02-15T12:29:06.479281Z] [debug] EVENT {"event":"STOP","timestamp":{"microseconds":612179,"seconds":1644928145}}
[2022-02-15T12:29:06.549037Z] [debug] ||| finished shutdown tests (runtime: 7 s)
[2022-02-15T12:29:06.550718Z] [debug] stopping autotest process 12674
[2022-02-15T12:29:06.558484Z] [debug] [autotest] process exited: 0
[2022-02-15T12:29:06.658941Z] [debug] done with autotest process
[2022-02-15T12:29:06.659333Z] [debug] stopping command server 12671 because test execution ended
[2022-02-15T12:29:06.659404Z] [debug] isotovideo: informing websocket clients before stopping command server: http://127.0.0.1:20013/UHDsvGadPNTdhlYW/broadcast
[2022-02-15T12:29:06.674685Z] [debug] commands process exited: 0
[2022-02-15T12:29:06.775065Z] [debug] done with command server
[2022-02-15T12:29:06.775134Z] [debug] isotovideo done
[2022-02-15T12:29:06.775987Z] [debug] backend shutdown state: 1
[2022-02-15T12:29:06.776536Z] [info] ::: OpenQA::Qemu::Proc::save_state: Saving QEMU state to qemu_state.json
[2022-02-15T12:29:07.791040Z] [debug] Passing remaining frames to the video encoder
[2022-02-15T12:29:07.816092Z] [debug] Waiting for video encoder to finalize the video
[2022-02-15T12:29:07.816176Z] [debug] The built-in video encoder (pid 12814) terminated
[2022-02-15T12:29:07.816705Z] [debug] QEMU: qemu-system-i386: terminating on signal 15 from pid 12744 (/home/squamata/os-autoinst/isotovideo: backen)
[2022-02-15T12:29:07.817652Z] [debug] sending magic and exit
[2022-02-15T12:29:07.817889Z] [debug] received magic close
[2022-02-15T12:29:07.825119Z] [debug] backend process exited: 0
[2022-02-15T12:29:07.926270Z] [debug] stopping backend process 12744
[2022-02-15T12:29:07.926376Z] [debug] done with backend process
12665: EXIT 0
[2022-02-15T12:29:07.947692Z] [info] [pid:12658] Isotovideo exit status: 0
[2022-02-15T12:29:07.984863Z] [info] [pid:12658] +++ worker notes +++
[2022-02-15T12:29:07.985080Z] [info] [pid:12658] End time: 2022-02-15 12:29:07
[2022-02-15T12:29:07.985171Z] [info] [pid:12658] Result: done
[2022-02-15T12:29:07.990161Z] [info] [pid:12874] Uploading video.ogv
[2022-02-15T12:29:08.037462Z] [info] [pid:12874] Uploading vars.json
[2022-02-15T12:29:08.067967Z] [info] [pid:12874] Uploading autoinst-log.txt
/tmp/7v4CAal1xt/full-stack.d/openqa/testresults/00000/00000005-tinycore-1-flavor-i386-Build1-core@coolone/serial0.txt:
/tmp/7v4CAal1xt/full-stack.d/openqa/testresults/00000/00000005-tinycore-1-flavor-i386-Build1-core@coolone/serial_terminal.txt:
/tmp/7v4CAal1xt/full-stack.d/openqa/testresults/00000/00000005-tinycore-1-flavor-i386-Build1-core@coolone/worker-log.txt:
[2022-02-15T12:28:34.035973Z] [debug] [pid:12658] Preparing Mojo::IOLoop::ReadWriteProcess::Session
[2022-02-15T12:28:34.036919Z] [debug] [pid:12658] Job settings:
[2022-02-15T12:28:34.037056Z] [debug] [pid:12658]
ARCH=i386
BUILD=1
CACHEDIRECTORY=/tmp/7v4CAal1xt/full-stack.d/cache
CACHELIMIT=50
DISTRI=tinycore
FLAVOR=flavor
INTEGRATION_TESTS=1
ISO=Core-7.2.iso
JOBTOKEN=UHDsvGadPNTdhlYW
LOCAL_UPLOAD=0
LOG_LEVEL=debug
MACHINE=coolone
NAME=00000005-tinycore-1-flavor-i386-Build1-core@coolone
OPENQA_HOSTNAME=localhost:9526
OPENQA_URL=http://localhost:9526
PRJDIR=/tmp/7v4CAal1xt/full-stack.d/openqa/share
PUBLISH_HDD_1=
QEMU=i386
QEMUPORT=20012
QEMU_NO_FDC_SET=1
QEMU_NO_KVM=1
QEMU_NO_TABLET=1
RETRY_DELAY=5
RETRY_DELAY_IF_WEBUI_BUSY=60
TEST=core
UEFI_PFLASH_VARS=/usr/share/qemu/ovmf-x86_64.bin
VERSION=1
VNC=91
WORKER_CLASS=qemu_i386,qemu_x86_64
WORKER_ID=1
WORKER_INSTANCE=1
[2022-02-15T12:28:34.051092Z] [debug] [pid:12658] Updating status so job 5 is not considered dead.
[2022-02-15T12:28:34.051566Z] [debug] [pid:12658] REST-API call: POST http://localhost:9526/api/v1/jobs/5/status
[2022-02-15T12:28:39.111193Z] [debug] [pid:12658] Updating status so job 5 is not considered dead.
[2022-02-15T12:28:39.111922Z] [debug] [pid:12658] REST-API call: POST http://localhost:9526/api/v1/jobs/5/status
[2022-02-15T12:28:39.173963Z] [debug] [pid:12658] Linked asset "/tmp/7v4CAal1xt/full-stack.d/cache/localhost/Core-7.2.iso" to "/tmp/7v4CAal1xt/full-stack.d/openqa/pool/1/Core-7.2.iso"
[2022-02-15T12:28:39.174387Z] [debug] [pid:12658] Symlinked from "/tmp/7v4CAal1xt/full-stack.d/openqa/share/tests/tinycore" to "/tmp/7v4CAal1xt/full-stack.d/openqa/pool/1/tinycore"
[2022-02-15T12:28:39.174701Z] [info] [pid:12658] Preparing cgroup to start isotovideo
[2022-02-15T12:28:39.175920Z] [warn] [pid:12658] Disabling cgroup usage because cgroup creation failed: mkdir /sys/fs/cgroup/systemd/docker: Permission denied at /usr/lib/perl5/vendor_perl/5.26.1/Mojo/File.pm line 84.
[2022-02-15T12:28:39.176055Z] [info] [pid:12658] You can define a custom slice with OPENQA_CGROUP_SLICE or indicating the base mount with MOJO_CGROUP_FS.
[2022-02-15T12:28:39.176364Z] [info] [pid:12658] Starting isotovideo container
[2022-02-15T12:28:39.179027Z] [debug] [pid:12658] Registered process:12665
[2022-02-15T12:28:39.179340Z] [info] [pid:12665] 12665: WORKING 5
[2022-02-15T12:28:39.179513Z] [info] [pid:12658] isotovideo has been started (PID: 12665)
[2022-02-15T12:28:39.180285Z] [debug] [pid:12658] Running job 5 from http://localhost:9526: 00000005-tinycore-1-flavor-i386-Build1-core@coolone.
[2022-02-15T12:28:39.183241Z] [debug] [pid:12658] REST-API call: POST http://localhost:9526/api/v1/jobs/5/status
[2022-02-15T12:28:39.262622Z] [debug] [pid:12658] Upload concluded (no current module)
[2022-02-15T12:28:49.272181Z] [debug] [pid:12658] REST-API call: POST http://localhost:9526/api/v1/jobs/5/status
[2022-02-15T12:28:49.352624Z] [debug] [pid:12658] Upload concluded (at boot)
[2022-02-15T12:28:59.354084Z] [debug] [pid:12658] REST-API call: POST http://localhost:9526/api/v1/jobs/5/status
[2022-02-15T12:28:59.476819Z] [debug] [pid:12658] Upload concluded (up to boot)
[2022-02-15T12:29:07.948029Z] [debug] [pid:12658] Stopping job 5 from http://localhost:9526: 00000005-tinycore-1-flavor-i386-Build1-core@coolone - reason: done
[2022-02-15T12:29:07.948772Z] [debug] [pid:12658] REST-API call: POST http://localhost:9526/api/v1/jobs/5/status
[2022-02-15T12:29:07.989976Z] [info] [pid:12874] Uploading video.ogv
[2022-02-15T12:29:07.990471Z] [debug] [pid:12874] Uploading artefact video.ogv
[2022-02-15T12:29:08.037372Z] [info] [pid:12874] Uploading vars.json
[2022-02-15T12:29:08.037636Z] [debug] [pid:12874] Uploading artefact vars.json
[2022-02-15T12:29:08.067828Z] [info] [pid:12874] Uploading autoinst-log.txt
[2022-02-15T12:29:08.068264Z] [debug] [pid:12874] Uploading artefact autoinst-log.txt
[2022-02-15T12:29:08.107527Z] [info] [pid:12874] Uploading worker-log.txt
[2022-02-15T12:29:08.107787Z] [debug] [pid:12874] Uploading artefact worker-log.txt
/tmp/7v4CAal1xt/full-stack.d/openqa/testresults/00000/00000006-tinycore-1-flavor-i386-Build1-core@coolone/autoinst-log.txt:
[2022-02-15T12:29:17.524573Z] [info] [pid:12880] +++ setup notes +++
[2022-02-15T12:29:17.524924Z] [info] [pid:12880] Running on 1234cbae1a16:1 (Linux 5.11.0-1027-aws #30~20.04.1-Ubuntu SMP Thu Jan 13 11:46:53 UTC 2022 x86_64)
[2022-02-15T12:29:17.532475Z] [debug] [pid:12880] Found ISO, caching Core-7.2.iso
[2022-02-15T12:29:17.539498Z] [info] [pid:12880] Downloading Core-7.2.iso, request #2 sent to Cache Service
[2022-02-15T12:29:22.649137Z] [info] [pid:12880] Download of Core-7.2.iso processed
[2022-02-15T12:29:22.656470Z] [debug] [pid:12888] +++ worker notes +++
[2022-02-15T12:29:24.499561Z] [debug] Current version is a7103b16a88ac5669f56dab460989dea6c74d9fa [interface v24]
[2022-02-15T12:29:24.508473Z] [debug] git hash in tinycore: a7103b16a88ac5669f56dab460989dea6c74d9fa
[2022-02-15T12:29:24.596215Z] [debug] scheduling boot tests/boot.pm
[2022-02-15T12:29:24.596887Z] [debug] scheduling assert_screen tests/assert_screen.pm
[2022-02-15T12:29:24.597449Z] [debug] scheduling shutdown tests/shutdown.pm
[2022-02-15T12:29:24.603243Z] [info] cmdsrv: daemon reachable under http://*:20013/3qvFv7vgealwLeLC/
[2022-02-15T12:29:24.605135Z] [info] Listening at "http://0.0.0.0:20013"
Web application available at http://0.0.0.0:20013
[2022-02-15T12:29:24.606655Z] [debug] git hash in tinycore/needles: a7103b16a88ac5669f56dab460989dea6c74d9fa
[2022-02-15T12:29:24.606773Z] [debug] init needles from tinycore/needles
[2022-02-15T12:29:24.608171Z] [debug] loaded 4 needles
[2022-02-15T12:29:24.610674Z] [debug] Blocking SIGCHLD and SIGTERM
[2022-02-15T12:29:24.750421Z] [debug] Unblocking SIGCHLD and SIGTERM
[2022-02-15T12:29:24.857323Z] [debug] Blocking SIGCHLD and SIGTERM
[2022-02-15T12:29:24.857572Z] [debug] 12888: channel_out 15, channel_in 14
[2022-02-15T12:29:25.050605Z] [debug] Unblocking SIGCHLD and SIGTERM
[2022-02-15T12:29:25.051981Z] [debug] 12978: cmdpipe 13, rsppipe 16
[2022-02-15T12:29:25.052066Z] [debug] started mgmt loop with pid 12978
[2022-02-15T12:29:25.254440Z] [debug] qemu version detected: 5.2.0
[2022-02-15T12:29:25.256257Z] [debug] running `/usr/bin/chattr +C /tmp/7v4CAal1xt/full-stack.d/openqa/pool/1/raid`
[2022-02-15T12:29:25.266253Z] [debug] Fatal error in command `/usr/bin/chattr +C /tmp/7v4CAal1xt/full-stack.d/openqa/pool/1/raid`: open3: exec of /usr/bin/chattr +C /tmp/7v4CAal1xt/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-02-15T12:29:25.266392Z] [debug] Configuring storage controllers and block devices
[2022-02-15T12:29:25.267277Z] [debug] running `/usr/bin/qemu-img info --output=json /tmp/7v4CAal1xt/full-stack.d/openqa/pool/1/Core-7.2.iso`
[2022-02-15T12:29:25.280062Z] [debug] Initializing block device images
[2022-02-15T12:29:25.280356Z] [debug] running `/usr/bin/qemu-img create -f qcow2 /tmp/7v4CAal1xt/full-stack.d/openqa/pool/1/raid/hd0 10G`
[2022-02-15T12:29:25.353921Z] [debug] Formatting '/tmp/7v4CAal1xt/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-02-15T12:29:25.354099Z] [debug] running `/usr/bin/qemu-img create -f qcow2 -F raw -b /tmp/7v4CAal1xt/full-stack.d/openqa/pool/1/Core-7.2.iso /tmp/7v4CAal1xt/full-stack.d/openqa/pool/1/raid/cd0-overlay0 11116544`
[2022-02-15T12:29:25.367722Z] [debug] Formatting '/tmp/7v4CAal1xt/full-stack.d/openqa/pool/1/raid/cd0-overlay0', fmt=qcow2 cluster_size=65536 extended_l2=off compression_type=zlib size=11116544 backing_file=/tmp/7v4CAal1xt/full-stack.d/openqa/pool/1/Core-7.2.iso backing_fmt=raw lazy_refcounts=off refcount_bits=16
[2022-02-15T12:29:25.367850Z] [debug] init_blockdev_images: Finished creating block devices
[2022-02-15T12:29:25.369209Z] [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=/tmp/7v4CAal1xt/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=/tmp/7v4CAal1xt/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-02-15T12:29:25.374630Z] [debug] Waiting for 0 attempts
[2022-02-15T12:29:26.375446Z] [debug] Waiting for 1 attempts
[2022-02-15T12:29:27.375928Z] [debug] Finished after 2 attempts
[2022-02-15T12:29:27.378292Z] [debug] Establishing VNC connection to localhost:5991
[2022-02-15T12:29:27.381396Z] [debug] pointer type 0 0 640 480 -257
[2022-02-15T12:29:27.381543Z] [debug] led state 0 1 1 -261
[2022-02-15T12:29:27.443003Z] [debug] Start CPU
[2022-02-15T12:29:27.443370Z] [debug] EVENT {"data":{"client":{"family":"ipv4","host":"127.0.0.1","service":"44898","websocket":false},"server":{"auth":"none","family":"ipv4","host":"0.0.0.0","service":"5991","websocket":false}},"event":"VNC_CONNECTED","timestamp":{"microseconds":379112,"seconds":1644928167}}
[2022-02-15T12:29:27.443495Z] [debug] EVENT {"data":{"client":{"family":"ipv4","host":"127.0.0.1","service":"44898","websocket":false},"server":{"auth":"none","family":"ipv4","host":"0.0.0.0","service":"5991","websocket":false}},"event":"VNC_INITIALIZED","timestamp":{"microseconds":380071,"seconds":1644928167}}
[2022-02-15T12:29:27.443591Z] [debug] EVENT {"event":"RESUME","timestamp":{"microseconds":443388,"seconds":1644928167}}
GOT GO

[2022-02-15T12:29:27.454474Z] [debug] QEMU: QEMU emulator version 5.2.0 (SUSE Linux Enterprise 15)
[2022-02-15T12:29:27.454555Z] [debug] QEMU: Copyright (c) 2003-2020 Fabrice Bellard and the QEMU Project developers
[2022-02-15T12:29:27.458514Z] [debug] Snapshots are supported
[2022-02-15T12:29:27.459535Z] [debug] ||| starting boot tests/boot.pm
[2022-02-15T12:29:27.461546Z] [debug] tests/boot.pm:9 called testapi::assert_screen
[2022-02-15T12:29:27.461863Z] [debug] <<< testapi::assert_screen(mustmatch="core", timeout=15, no_wait=1)
[2022-02-15T12:29:27.482340Z] [debug] no match: 14.9s, best candidate: boot-core (0.00)
[2022-02-15T12:29:27.583166Z] [debug] no change: 14.8s
[2022-02-15T12:29:27.593210Z] [debug] no match: 14.8s, best candidate: boot-core (0.00)
[2022-02-15T12:29:27.694043Z] [debug] no change: 14.7s
[2022-02-15T12:29:27.704197Z] [debug] no match: 14.7s, best candidate: boot-core (0.00)
[2022-02-15T12:29:27.805026Z] [debug] no change: 14.6s
[2022-02-15T12:29:27.814747Z] [debug] no match: 14.6s, best candidate: boot-core (0.00)
[2022-02-15T12:29:27.915520Z] [debug] no change: 14.5s
[2022-02-15T12:29:27.922834Z] [debug] no match: 14.5s, best candidate: boot-core (0.00)
[2022-02-15T12:29:28.109092Z] [debug] >>> testapi::_handle_found_needle: found boot-core, similarity 0.97 @ 1/74
[2022-02-15T12:29:28.109620Z] [debug] tests/boot.pm:10 called testapi::send_key
[2022-02-15T12:29:28.109751Z] [debug] <<< testapi::send_key(key="ret", do_wait=0, wait_screen_change=0)
[2022-02-15T12:29:28.378986Z] [debug] tests/boot.pm:14 called testapi::assert_screen
[2022-02-15T12:29:28.379166Z] [debug] <<< testapi::assert_screen(mustmatch="on_prompt", timeout=90)
[2022-02-15T12:29:29.028950Z] [debug] no match: 89.3s, best candidate: boot-on_prompt (0.00)
[2022-02-15T12:29:30.026665Z] [debug] no match: 88.3s, best candidate: boot-on_prompt (0.00)
[2022-02-15T12:29:31.027692Z] [debug] no match: 87.3s, best candidate: boot-on_prompt (0.00)
[2022-02-15T12:29:32.028591Z] [debug] no match: 86.3s, best candidate: boot-on_prompt (0.00)
[2022-02-15T12:29:33.081388Z] [debug] no match: 85.3s, best candidate: boot-on_prompt (0.00)
[2022-02-15T12:29:34.030620Z] [debug] no match: 84.3s, best candidate: boot-on_prompt (0.00)
[2022-02-15T12:29:35.032260Z] [debug] no match: 83.3s, best candidate: boot-on_prompt (0.00)
[2022-02-15T12:29:36.033491Z] [debug] no match: 82.3s, best candidate: boot-on_prompt (0.00)
[2022-02-15T12:29:37.033042Z] [debug] no match: 81.3s, best candidate: boot-on_prompt (0.00)
[2022-02-15T12:29:38.077329Z] [debug] no match: 80.3s, best candidate: boot-on_prompt (0.00)
[2022-02-15T12:29:39.107139Z] [debug] >>> testapi::_handle_found_needle: found boot-on_prompt, similarity 1.00 @ 2/64
[2022-02-15T12:29:39.110155Z] [debug] ||| finished boot tests (runtime: 12 s)
[2022-02-15T12:29:39.111335Z] [debug] ||| starting assert_screen tests/assert_screen.pm
[2022-02-15T12:29:39.112112Z] [debug] tests/assert_screen.pm:9 called testapi::assert_screen
[2022-02-15T12:29:39.112273Z] [debug] <<< testapi::assert_screen(mustmatch="on_prompt", timeout=60)
[2022-02-15T12:29:40.099497Z] [debug] >>> testapi::_handle_found_needle: found boot-on_prompt, similarity 1.00 @ 2/64
[2022-02-15T12:29:40.099662Z] [debug] tests/assert_screen.pm:10 called testapi::assert_screen
[2022-02-15T12:29:40.099769Z] [debug] <<< testapi::assert_screen(mustmatch="on_prompt", no_wait=1, timeout=30)
[2022-02-15T12:29:40.173278Z] [debug] >>> testapi::_handle_found_needle: found boot-on_prompt, similarity 1.00 @ 2/64
[2022-02-15T12:29:40.174573Z] [debug] ||| finished assert_screen tests (runtime: 1 s)
[2022-02-15T12:29:40.176025Z] [debug] ||| starting shutdown tests/shutdown.pm
[2022-02-15T12:29:40.177079Z] [debug] tests/shutdown.pm:8 called testapi::type_string
[2022-02-15T12:29:40.177354Z] [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-02-15T12:29:40.449105Z] [debug] tests/shutdown.pm:9 called testapi::type_string
[2022-02-15T12:29:40.449308Z] [debug] <<< testapi::type_string(string="poweroff\n", max_interval=250, wait_screen_changes=0, wait_still_screen=0, timeout=30, similarity_level=47)
[2022-02-15T12:29:40.754584Z] [debug] tests/shutdown.pm:10 called testapi::assert_shutdown
[2022-02-15T12:29:40.754787Z] [debug] <<< testapi::check_shutdown(timeout=90)
[2022-02-15T12:29:40.756051Z] [debug] QEMU status is not 'shutdown', it is 'running'
[2022-02-15T12:29:41.757550Z] [debug] QEMU status is not 'shutdown', it is 'running'
[2022-02-15T12:29:42.759402Z] [debug] QEMU status is not 'shutdown', it is 'running'
[2022-02-15T12:29:43.761105Z] [debug] QEMU status is not 'shutdown', it is 'running'
[2022-02-15T12:29:44.762695Z] [debug] QEMU status is not 'shutdown', it is 'running'
[2022-02-15T12:29:45.763833Z] [debug] EVENT {"data":{"guest":true,"reason":"guest-shutdown"},"event":"SHUTDOWN","timestamp":{"microseconds":446536,"seconds":1644928185}}
[2022-02-15T12:29:45.763958Z] [debug] EVENT {"event":"STOP","timestamp":{"microseconds":447258,"seconds":1644928185}}
[2022-02-15T12:29:45.829999Z] [debug] ||| finished shutdown tests (runtime: 5 s)
[2022-02-15T12:29:45.831858Z] [debug] stopping autotest process 12908
[2022-02-15T12:29:45.838747Z] [debug] [autotest] process exited: 0
[2022-02-15T12:29:45.939207Z] [debug] done with autotest process
[2022-02-15T12:29:45.939686Z] [debug] stopping command server 12905 because test execution ended
[2022-02-15T12:29:45.939780Z] [debug] isotovideo: informing websocket clients before stopping command server: http://127.0.0.1:20013/3qvFv7vgealwLeLC/broadcast
[2022-02-15T12:29:45.954517Z] [debug] commands process exited: 0
[2022-02-15T12:29:46.054932Z] [debug] done with command server
[2022-02-15T12:29:46.055021Z] [debug] isotovideo done
[2022-02-15T12:29:46.055962Z] [debug] backend shutdown state: 1
[2022-02-15T12:29:46.056698Z] [info] ::: OpenQA::Qemu::Proc::save_state: Saving QEMU state to qemu_state.json
[2022-02-15T12:29:47.068061Z] [debug] Passing remaining frames to the video encoder
[2022-02-15T12:29:47.095360Z] [debug] Waiting for video encoder to finalize the video
[2022-02-15T12:29:47.095434Z] [debug] The built-in video encoder (pid 13048) terminated
[2022-02-15T12:29:47.095934Z] [debug] QEMU: qemu-system-i386: terminating on signal 15 from pid 12978 (/home/squamata/os-autoinst/isotovideo: backen)
[2022-02-15T12:29:47.096746Z] [debug] sending magic and exit
[2022-02-15T12:29:47.096980Z] [debug] received magic close
[2022-02-15T12:29:47.105764Z] [debug] backend process exited: 0
[2022-02-15T12:29:47.206784Z] [debug] stopping backend process 12978
[2022-02-15T12:29:47.206907Z] [debug] done with backend process
12888: EXIT 0
[2022-02-15T12:29:47.222737Z] [info] [pid:12880] Isotovideo exit status: 0
[2022-02-15T12:29:47.251991Z] [info] [pid:12880] +++ worker notes +++
[2022-02-15T12:29:47.252354Z] [info] [pid:12880] End time: 2022-02-15 12:29:47
[2022-02-15T12:29:47.252528Z] [info] [pid:12880] Result: done
[2022-02-15T12:29:47.258835Z] [info] [pid:13106] Uploading video.ogv
[2022-02-15T12:29:47.296799Z] [info] [pid:13106] Uploading vars.json
[2022-02-15T12:29:47.327009Z] [info] [pid:13106] Uploading autoinst-log.txt
/tmp/7v4CAal1xt/full-stack.d/openqa/testresults/00000/00000006-tinycore-1-flavor-i386-Build1-core@coolone/serial0.txt:
/tmp/7v4CAal1xt/full-stack.d/openqa/testresults/00000/00000006-tinycore-1-flavor-i386-Build1-core@coolone/serial_terminal.txt:
/tmp/7v4CAal1xt/full-stack.d/openqa/testresults/00000/00000006-tinycore-1-flavor-i386-Build1-core@coolone/worker-log.txt:
[2022-02-15T12:29:17.524010Z] [debug] [pid:12880] Preparing Mojo::IOLoop::ReadWriteProcess::Session
[2022-02-15T12:29:17.525293Z] [debug] [pid:12880] Job settings:
[2022-02-15T12:29:17.525517Z] [debug] [pid:12880]
ARCH=i386
BUILD=1
CACHEDIRECTORY=/tmp/7v4CAal1xt/full-stack.d/cache
CACHELIMIT=50
DISTRI=tinycore
FLAVOR=flavor
INTEGRATION_TESTS=1
ISO=Core-7.2.iso
JOBTOKEN=3qvFv7vgealwLeLC
LOCAL_UPLOAD=0
LOG_LEVEL=debug
MACHINE=coolone
NAME=00000006-tinycore-1-flavor-i386-Build1-core@coolone
OPENQA_HOSTNAME=localhost:9526
OPENQA_URL=http://localhost:9526
PRJDIR=/tmp/7v4CAal1xt/full-stack.d/openqa/share
PUBLISH_HDD_1=
QEMU=i386
QEMUPORT=20012
QEMU_NO_FDC_SET=1
QEMU_NO_KVM=1
QEMU_NO_TABLET=1
RETRY_DELAY=5
RETRY_DELAY_IF_WEBUI_BUSY=60
TEST=core
UEFI_PFLASH_VARS=/usr/share/qemu/ovmf-x86_64.bin
VERSION=1
VNC=91
WORKER_CLASS=qemu_i386,qemu_x86_64
WORKER_ID=1
WORKER_INSTANCE=1
[2022-02-15T12:29:17.539819Z] [debug] [pid:12880] Updating status so job 6 is not considered dead.
[2022-02-15T12:29:17.540294Z] [debug] [pid:12880] REST-API call: POST http://localhost:9526/api/v1/jobs/6/status
[2022-02-15T12:29:22.591116Z] [debug] [pid:12880] Updating status so job 6 is not considered dead.
[2022-02-15T12:29:22.591691Z] [debug] [pid:12880] REST-API call: POST http://localhost:9526/api/v1/jobs/6/status
[2022-02-15T12:29:22.651310Z] [debug] [pid:12880] Linked asset "/tmp/7v4CAal1xt/full-stack.d/cache/localhost/Core-7.2.iso" to "/tmp/7v4CAal1xt/full-stack.d/openqa/pool/1/Core-7.2.iso"
[2022-02-15T12:29:22.651726Z] [debug] [pid:12880] Symlinked from "/tmp/7v4CAal1xt/full-stack.d/openqa/share/tests/tinycore" to "/tmp/7v4CAal1xt/full-stack.d/openqa/pool/1/tinycore"
[2022-02-15T12:29:22.652030Z] [info] [pid:12880] Preparing cgroup to start isotovideo
[2022-02-15T12:29:22.653176Z] [warn] [pid:12880] Disabling cgroup usage because cgroup creation failed: mkdir /sys/fs/cgroup/systemd/docker: Permission denied at /usr/lib/perl5/vendor_perl/5.26.1/Mojo/File.pm line 84.
[2022-02-15T12:29:22.653307Z] [info] [pid:12880] You can define a custom slice with OPENQA_CGROUP_SLICE or indicating the base mount with MOJO_CGROUP_FS.
[2022-02-15T12:29:22.653611Z] [info] [pid:12880] Starting isotovideo container
[2022-02-15T12:29:22.655960Z] [debug] [pid:12880] Registered process:12888
[2022-02-15T12:29:22.656234Z] [info] [pid:12888] 12888: WORKING 6
[2022-02-15T12:29:22.656449Z] [info] [pid:12880] isotovideo has been started (PID: 12888)
[2022-02-15T12:29:22.657056Z] [debug] [pid:12880] Running job 6 from http://localhost:9526: 00000006-tinycore-1-flavor-i386-Build1-core@coolone.
[2022-02-15T12:29:22.659778Z] [debug] [pid:12880] REST-API call: POST http://localhost:9526/api/v1/jobs/6/status
[2022-02-15T12:29:22.712334Z] [debug] [pid:12880] Upload concluded (no current module)
[2022-02-15T12:29:32.720125Z] [debug] [pid:12880] REST-API call: POST http://localhost:9526/api/v1/jobs/6/status
[2022-02-15T12:29:32.802070Z] [debug] [pid:12880] Upload concluded (at boot)
[2022-02-15T12:29:42.803792Z] [debug] [pid:12880] REST-API call: POST http://localhost:9526/api/v1/jobs/6/status
[2022-02-15T12:29:42.930303Z] [debug] [pid:12880] Upload concluded (up to boot)
[2022-02-15T12:29:47.223132Z] [debug] [pid:12880] Stopping job 6 from http://localhost:9526: 00000006-tinycore-1-flavor-i386-Build1-core@coolone - reason: done
[2022-02-15T12:29:47.223842Z] [debug] [pid:12880] REST-API call: POST http://localhost:9526/api/v1/jobs/6/status
[2022-02-15T12:29:47.258592Z] [info] [pid:13106] Uploading video.ogv
[2022-02-15T12:29:47.259328Z] [debug] [pid:13106] Uploading artefact video.ogv
[2022-02-15T12:29:47.296670Z] [info] [pid:13106] Uploading vars.json
[2022-02-15T12:29:47.297066Z] [debug] [pid:13106] Uploading artefact vars.json
[2022-02-15T12:29:47.326834Z] [info] [pid:13106] Uploading autoinst-log.txt
[2022-02-15T12:29:47.327281Z] [debug] [pid:13106] Uploading artefact autoinst-log.txt
[2022-02-15T12:29:47.357730Z] [info] [pid:13106] Uploading worker-log.txt
[2022-02-15T12:29:47.358018Z] [debug] [pid:13106] Uploading artefact worker-log.txt
/tmp/7v4CAal1xt/full-stack.d/openqa/testresults/00000/00000007-tinycore-1-flavor-i386-Build1-core@coolone/autoinst-log.txt:
[2022-02-15T12:29:56.705497Z] [info] [pid:13113] +++ setup notes +++
[2022-02-15T12:29:56.705727Z] [info] [pid:13113] Running on 1234cbae1a16:1 (Linux 5.11.0-1027-aws #30~20.04.1-Ubuntu SMP Thu Jan 13 11:46:53 UTC 2022 x86_64)
[2022-02-15T12:29:56.713655Z] [debug] [pid:13113] Found ISO, caching Core-7.2.iso
[2022-02-15T12:29:56.721786Z] [info] [pid:13113] Downloading Core-7.2.iso, request #3 sent to Cache Service
[2022-02-15T12:30:01.835373Z] [info] [pid:13113] Download of Core-7.2.iso processed
[2022-02-15T12:30:01.843674Z] [debug] [pid:13120] +++ worker notes +++
[2022-02-15T12:30:03.814331Z] [debug] Current version is a7103b16a88ac5669f56dab460989dea6c74d9fa [interface v24]
[2022-02-15T12:30:03.825100Z] [debug] git hash in tinycore: a7103b16a88ac5669f56dab460989dea6c74d9fa
[2022-02-15T12:30:03.924937Z] [debug] scheduling boot tests/boot.pm
[2022-02-15T12:30:03.925790Z] [debug] scheduling assert_screen tests/assert_screen.pm
[2022-02-15T12:30:03.926460Z] [debug] scheduling shutdown tests/shutdown.pm
[2022-02-15T12:30:03.933264Z] [info] cmdsrv: daemon reachable under http://*:20013/NyTrTQWMU40CyqS4/
[2022-02-15T12:30:03.935234Z] [info] Listening at "http://0.0.0.0:20013"
Web application available at http://0.0.0.0:20013
[2022-02-15T12:30:03.936974Z] [debug] git hash in tinycore/needles: a7103b16a88ac5669f56dab460989dea6c74d9fa
[2022-02-15T12:30:03.937096Z] [debug] init needles from tinycore/needles
[2022-02-15T12:30:03.938376Z] [debug] loaded 4 needles
[2022-02-15T12:30:03.941194Z] [debug] Blocking SIGCHLD and SIGTERM
[2022-02-15T12:30:04.054625Z] [debug] Unblocking SIGCHLD and SIGTERM
[2022-02-15T12:30:04.176281Z] [debug] Blocking SIGCHLD and SIGTERM
[2022-02-15T12:30:04.176407Z] [debug] 13120: channel_out 15, channel_in 14
[2022-02-15T12:30:04.350643Z] [debug] Unblocking SIGCHLD and SIGTERM
[2022-02-15T12:30:04.352545Z] [debug] 13214: cmdpipe 13, rsppipe 16
[2022-02-15T12:30:04.352660Z] [debug] started mgmt loop with pid 13214
[2022-02-15T12:30:04.553266Z] [debug] qemu version detected: 5.2.0
[2022-02-15T12:30:04.554868Z] [debug] running `/usr/bin/chattr +C /tmp/7v4CAal1xt/full-stack.d/openqa/pool/1/raid`
[2022-02-15T12:30:04.563131Z] [debug] Fatal error in command `/usr/bin/chattr +C /tmp/7v4CAal1xt/full-stack.d/openqa/pool/1/raid`: open3: exec of /usr/bin/chattr +C /tmp/7v4CAal1xt/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-02-15T12:30:04.563224Z] [debug] Configuring storage controllers and block devices
[2022-02-15T12:30:04.563807Z] [debug] running `/usr/bin/qemu-img info --output=json /tmp/7v4CAal1xt/full-stack.d/openqa/pool/1/Core-7.2.iso`
[2022-02-15T12:30:04.574308Z] [debug] Initializing block device images
[2022-02-15T12:30:04.574504Z] [debug] running `/usr/bin/qemu-img create -f qcow2 /tmp/7v4CAal1xt/full-stack.d/openqa/pool/1/raid/hd0 10G`
[2022-02-15T12:30:04.587418Z] [debug] Formatting '/tmp/7v4CAal1xt/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-02-15T12:30:04.587553Z] [debug] running `/usr/bin/qemu-img create -f qcow2 -F raw -b /tmp/7v4CAal1xt/full-stack.d/openqa/pool/1/Core-7.2.iso /tmp/7v4CAal1xt/full-stack.d/openqa/pool/1/raid/cd0-overlay0 11116544`
[2022-02-15T12:30:04.599179Z] [debug] Formatting '/tmp/7v4CAal1xt/full-stack.d/openqa/pool/1/raid/cd0-overlay0', fmt=qcow2 cluster_size=65536 extended_l2=off compression_type=zlib size=11116544 backing_file=/tmp/7v4CAal1xt/full-stack.d/openqa/pool/1/Core-7.2.iso backing_fmt=raw lazy_refcounts=off refcount_bits=16
[2022-02-15T12:30:04.599271Z] [debug] init_blockdev_images: Finished creating block devices
[2022-02-15T12:30:04.600313Z] [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=/tmp/7v4CAal1xt/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=/tmp/7v4CAal1xt/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-02-15T12:30:04.604322Z] [debug] Waiting for 0 attempts
[2022-02-15T12:30:05.604972Z] [debug] Waiting for 1 attempts
[2022-02-15T12:30:06.605400Z] [debug] Finished after 2 attempts
[2022-02-15T12:30:06.607832Z] [debug] Establishing VNC connection to localhost:5991
[2022-02-15T12:30:06.610964Z] [debug] pointer type 0 0 640 480 -257
[2022-02-15T12:30:06.611113Z] [debug] led state 0 1 1 -261
[2022-02-15T12:30:06.670643Z] [debug] Start CPU
[2022-02-15T12:30:06.670978Z] [debug] EVENT {"data":{"client":{"family":"ipv4","host":"127.0.0.1","service":"47352","websocket":false},"server":{"auth":"none","family":"ipv4","host":"0.0.0.0","service":"5991","websocket":false}},"event":"VNC_CONNECTED","timestamp":{"microseconds":608598,"seconds":1644928206}}
[2022-02-15T12:30:06.671074Z] [debug] EVENT {"data":{"client":{"family":"ipv4","host":"127.0.0.1","service":"47352","websocket":false},"server":{"auth":"none","family":"ipv4","host":"0.0.0.0","service":"5991","websocket":false}},"event":"VNC_INITIALIZED","timestamp":{"microseconds":609563,"seconds":1644928206}}
[2022-02-15T12:30:06.671141Z] [debug] EVENT {"event":"RESUME","timestamp":{"microseconds":671062,"seconds":1644928206}}
GOT GO

[2022-02-15T12:30:06.679085Z] [debug] QEMU: QEMU emulator version 5.2.0 (SUSE Linux Enterprise 15)
[2022-02-15T12:30:06.679143Z] [debug] QEMU: Copyright (c) 2003-2020 Fabrice Bellard and the QEMU Project developers
[2022-02-15T12:30:06.682545Z] [debug] Snapshots are supported
[2022-02-15T12:30:06.683729Z] [debug] ||| starting boot tests/boot.pm
[2022-02-15T12:30:06.685985Z] [debug] tests/boot.pm:9 called testapi::assert_screen
[2022-02-15T12:30:06.686361Z] [debug] <<< testapi::assert_screen(mustmatch="core", timeout=15, no_wait=1)
[2022-02-15T12:30:06.700419Z] [debug] no match: 14.9s, best candidate: boot-core (0.00)
[2022-02-15T12:30:06.801153Z] [debug] no change: 14.8s
[2022-02-15T12:30:06.809744Z] [debug] no match: 14.8s, best candidate: boot-core (0.00)
[2022-02-15T12:30:06.910484Z] [debug] no change: 14.7s
[2022-02-15T12:30:06.917192Z] [debug] no match: 14.7s, best candidate: boot-core (0.00)
[2022-02-15T12:30:07.017933Z] [debug] no change: 14.6s
[2022-02-15T12:30:07.024717Z] [debug] no match: 14.6s, best candidate: boot-core (0.00)
[2022-02-15T12:30:07.125518Z] [debug] no change: 14.5s
[2022-02-15T12:30:07.134823Z] [debug] no match: 14.5s, best candidate: boot-core (0.00)
[2022-02-15T12:30:07.331434Z] [debug] >>> testapi::_handle_found_needle: found boot-core, similarity 0.97 @ 1/74
[2022-02-15T12:30:07.332261Z] [debug] tests/boot.pm:10 called testapi::send_key
[2022-02-15T12:30:07.332397Z] [debug] <<< testapi::send_key(key="ret", wait_screen_change=0, do_wait=0)
[2022-02-15T12:30:07.602261Z] [debug] tests/boot.pm:14 called testapi::assert_screen
[2022-02-15T12:30:07.602421Z] [debug] <<< testapi::assert_screen(mustmatch="on_prompt", timeout=90)
[2022-02-15T12:30:08.241080Z] [debug] no match: 89.3s, best candidate: boot-on_prompt (0.00)
[2022-02-15T12:30:09.239031Z] [debug] no match: 88.3s, best candidate: boot-on_prompt (0.00)
[2022-02-15T12:30:10.239732Z] [debug] no match: 87.3s, best candidate: boot-on_prompt (0.00)
[2022-02-15T12:30:11.240536Z] [debug] no match: 86.3s, best candidate: boot-on_prompt (0.00)
[2022-02-15T12:30:12.284183Z] [debug] no match: 85.3s, best candidate: boot-on_prompt (0.00)
[2022-02-15T12:30:13.243429Z] [debug] no match: 84.3s, best candidate: boot-on_prompt (0.00)
[2022-02-15T12:30:14.250893Z] [debug] no match: 83.3s, best candidate: boot-on_prompt (0.00)
[2022-02-15T12:30:15.244456Z] [debug] no match: 82.3s, best candidate: boot-on_prompt (0.00)
[2022-02-15T12:30:16.245635Z] [debug] no match: 81.3s, best candidate: boot-on_prompt (0.00)
[2022-02-15T12:30:17.290398Z] [debug] no match: 80.3s, best candidate: boot-on_prompt (0.00)
[2022-02-15T12:30:18.247487Z] [debug] no match: 79.3s, best candidate: boot-on_prompt (0.00)
[2022-02-15T12:30:19.248117Z] [debug] no match: 78.3s, best candidate: boot-on_prompt (0.00)
[2022-02-15T12:30:20.248476Z] [debug] no match: 77.3s, best candidate: boot-on_prompt (0.00)
[2022-02-15T12:30:21.249634Z] [debug] no match: 76.3s, best candidate: boot-on_prompt (0.00)
[2022-02-15T12:30:22.370453Z] [debug] >>> testapi::_handle_found_needle: found boot-on_prompt, similarity 1.00 @ 2/64
[2022-02-15T12:30:22.374020Z] [debug] ||| finished boot tests (runtime: 16 s)
[2022-02-15T12:30:22.375138Z] [debug] ||| starting assert_screen tests/assert_screen.pm
[2022-02-15T12:30:22.375777Z] [debug] tests/assert_screen.pm:9 called testapi::assert_screen
[2022-02-15T12:30:22.375889Z] [debug] <<< testapi::assert_screen(mustmatch="on_prompt", timeout=60)
[2022-02-15T12:30:23.323411Z] [debug] >>> testapi::_handle_found_needle: found boot-on_prompt, similarity 1.00 @ 2/64
[2022-02-15T12:30:23.323585Z] [debug] tests/assert_screen.pm:10 called testapi::assert_screen
[2022-02-15T12:30:23.323700Z] [debug] <<< testapi::assert_screen(mustmatch="on_prompt", timeout=30, no_wait=1)
[2022-02-15T12:30:23.397251Z] [debug] >>> testapi::_handle_found_needle: found boot-on_prompt, similarity 1.00 @ 2/64
[2022-02-15T12:30:23.398459Z] [debug] ||| finished assert_screen tests (runtime: 1 s)
[2022-02-15T12:30:23.399556Z] [debug] ||| starting shutdown tests/shutdown.pm
[2022-02-15T12:30:23.400299Z] [debug] tests/shutdown.pm:8 called testapi::type_string
[2022-02-15T12:30:23.400468Z] [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-02-15T12:30:23.671645Z] [debug] tests/shutdown.pm:9 called testapi::type_string
[2022-02-15T12:30:23.671846Z] [debug] <<< testapi::type_string(string="poweroff\n", max_interval=250, wait_screen_changes=0, wait_still_screen=0, timeout=30, similarity_level=47)
[2022-02-15T12:30:23.976613Z] [debug] tests/shutdown.pm:10 called testapi::assert_shutdown
[2022-02-15T12:30:23.976768Z] [debug] <<< testapi::check_shutdown(timeout=90)
[2022-02-15T12:30:23.977601Z] [debug] QEMU status is not 'shutdown', it is 'running'
[2022-02-15T12:30:24.978574Z] [debug] EVENT {"data":{"path":"\/machine\/peripheral-anon\/device[2]\/virtio-backend"},"event":"NIC_RX_FILTER_CHANGED","timestamp":{"microseconds":798568,"seconds":1644928224}}
[2022-02-15T12:30:24.978769Z] [debug] QEMU status is not 'shutdown', it is 'running'
[2022-02-15T12:30:25.980202Z] [debug] QEMU status is not 'shutdown', it is 'running'
[2022-02-15T12:30:26.981697Z] [debug] QEMU status is not 'shutdown', it is 'running'
[2022-02-15T12:30:27.983129Z] [debug] QEMU status is not 'shutdown', it is 'running'
[2022-02-15T12:30:28.984521Z] [debug] QEMU status is not 'shutdown', it is 'running'
[2022-02-15T12:30:29.986015Z] [debug] QEMU status is not 'shutdown', it is 'running'
[2022-02-15T12:30:30.987833Z] [debug] QEMU status is not 'shutdown', it is 'running'
[2022-02-15T12:30:31.989409Z] [debug] QEMU status is not 'shutdown', it is 'running'
[2022-02-15T12:30:32.990952Z] [debug] QEMU status is not 'shutdown', it is 'running'
[2022-02-15T12:30:33.992506Z] [debug] QEMU status is not 'shutdown', it is 'running'
[2022-02-15T12:30:34.994180Z] [debug] QEMU status is not 'shutdown', it is 'running'
[2022-02-15T12:30:35.995702Z] [debug] QEMU status is not 'shutdown', it is 'running'
[2022-02-15T12:30:36.997284Z] [debug] QEMU status is not 'shutdown', it is 'running'
[2022-02-15T12:30:37.998701Z] [debug] QEMU status is not 'shutdown', it is 'running'
[2022-02-15T12:30:39.000077Z] [debug] QEMU status is not 'shutdown', it is 'running'
[2022-02-15T12:30:40.001426Z] [debug] QEMU status is not 'shutdown', it is 'running'
[2022-02-15T12:30:41.002793Z] [debug] QEMU status is not 'shutdown', it is 'running'
[2022-02-15T12:30:42.004222Z] [debug] QEMU status is not 'shutdown', it is 'running'
[2022-02-15T12:30:43.005663Z] [debug] QEMU status is not 'shutdown', it is 'running'
[2022-02-15T12:30:44.007088Z] [debug] QEMU status is not 'shutdown', it is 'running'
[2022-02-15T12:30:45.009225Z] [debug] QEMU status is not 'shutdown', it is 'running'
[2022-02-15T12:30:46.010647Z] [debug] QEMU status is not 'shutdown', it is 'running'
[2022-02-15T12:30:47.012001Z] [debug] QEMU status is not 'shutdown', it is 'running'
[2022-02-15T12:30:48.013345Z] [debug] QEMU status is not 'shutdown', it is 'running'
[2022-02-15T12:30:49.014707Z] [debug] QEMU status is not 'shutdown', it is 'running'
[2022-02-15T12:30:50.016237Z] [debug] QEMU status is not 'shutdown', it is 'running'
[2022-02-15T12:30:51.017733Z] [debug] QEMU status is not 'shutdown', it is 'running'
[2022-02-15T12:30:52.019127Z] [debug] QEMU status is not 'shutdown', it is 'running'
[2022-02-15T12:30:53.020473Z] [debug] QEMU status is not 'shutdown', it is 'running'
[2022-02-15T12:30:54.022002Z] [debug] QEMU status is not 'shutdown', it is 'running'
[2022-02-15T12:30:55.023478Z] [debug] QEMU status is not 'shutdown', it is 'running'
[2022-02-15T12:30:56.024798Z] [debug] QEMU status is not 'shutdown', it is 'running'
[2022-02-15T12:30:57.026197Z] [debug] QEMU status is not 'shutdown', it is 'running'
[2022-02-15T12:30:58.027597Z] [debug] QEMU status is not 'shutdown', it is 'running'
[2022-02-15T12:30:59.028949Z] [debug] QEMU status is not 'shutdown', it is 'running'
[2022-02-15T12:31:00.030382Z] [debug] QEMU status is not 'shutdown', it is 'running'
[2022-02-15T12:31:01.031751Z] [debug] QEMU status is not 'shutdown', it is 'running'
[2022-02-15T12:31:02.033322Z] [debug] QEMU status is not 'shutdown', it is 'running'
[2022-02-15T12:31:03.034643Z] [debug] QEMU status is not 'shutdown', it is 'running'
[2022-02-15T12:31:04.035983Z] [debug] QEMU status is not 'shutdown', it is 'running'
[2022-02-15T12:31:05.037390Z] [debug] QEMU status is not 'shutdown', it is 'running'
[2022-02-15T12:31:06.038745Z] [debug] QEMU status is not 'shutdown', it is 'running'
[2022-02-15T12:31:07.040077Z] [debug] QEMU status is not 'shutdown', it is 'running'
[2022-02-15T12:31:08.041514Z] [debug] QEMU status is not 'shutdown', it is 'running'
[2022-02-15T12:31:09.042758Z] [debug] QEMU status is not 'shutdown', it is 'running'
[2022-02-15T12:31:10.044073Z] [debug] QEMU status is not 'shutdown', it is 'running'
[2022-02-15T12:31:11.045563Z] [debug] QEMU status is not 'shutdown', it is 'running'
[2022-02-15T12:31:12.047049Z] [debug] QEMU status is not 'shutdown', it is 'running'
[2022-02-15T12:31:13.048395Z] [debug] QEMU status is not 'shutdown', it is 'running'
[2022-02-15T12:31:14.050472Z] [debug] QEMU status is not 'shutdown', it is 'running'
[2022-02-15T12:31:15.052414Z] [debug] QEMU status is not 'shutdown', it is 'running'
[2022-02-15T12:31:16.054248Z] [debug] QEMU status is not 'shutdown', it is 'running'
[2022-02-15T12:31:17.056032Z] [debug] QEMU status is not 'shutdown', it is 'running'
[2022-02-15T12:31:18.057735Z] [debug] QEMU status is not 'shutdown', it is 'running'
[2022-02-15T12:31:19.059430Z] [debug] QEMU status is not 'shutdown', it is 'running'
[2022-02-15T12:31:20.061007Z] [debug] QEMU status is not 'shutdown', it is 'running'
[2022-02-15T12:31:21.062687Z] [debug] QEMU status is not 'shutdown', it is 'running'
[2022-02-15T12:31:22.064236Z] [debug] QEMU status is not 'shutdown', it is 'running'
[2022-02-15T12:31:23.065755Z] [debug] QEMU status is not 'shutdown', it is 'running'
[2022-02-15T12:31:24.067307Z] [debug] QEMU status is not 'shutdown', it is 'running'
[2022-02-15T12:31:25.068789Z] [debug] QEMU status is not 'shutdown', it is 'running'
[2022-02-15T12:31:26.070303Z] [debug] QEMU status is not 'shutdown', it is 'running'
[2022-02-15T12:31:27.071919Z] [debug] QEMU status is not 'shutdown', it is 'running'
[2022-02-15T12:31:28.073276Z] [debug] QEMU status is not 'shutdown', it is 'running'
[2022-02-15T12:31:29.074616Z] [debug] QEMU status is not 'shutdown', it is 'running'
[2022-02-15T12:31:30.076077Z] [debug] QEMU status is not 'shutdown', it is 'running'
[2022-02-15T12:31:31.077578Z] [debug] QEMU status is not 'shutdown', it is 'running'
[2022-02-15T12:31:32.079056Z] [debug] QEMU status is not 'shutdown', it is 'running'
[2022-02-15T12:31:33.080466Z] [debug] QEMU status is not 'shutdown', it is 'running'
[2022-02-15T12:31:34.081957Z] [debug] QEMU status is not 'shutdown', it is 'running'
[2022-02-15T12:31:35.083433Z] [debug] QEMU status is not 'shutdown', it is 'running'
[2022-02-15T12:31:36.084782Z] [debug] QEMU status is not 'shutdown', it is 'running'
[2022-02-15T12:31:37.086272Z] [debug] QEMU status is not 'shutdown', it is 'running'
[2022-02-15T12:31:38.087737Z] [debug] QEMU status is not 'shutdown', it is 'running'
[2022-02-15T12:31:39.089124Z] [debug] QEMU status is not 'shutdown', it is 'running'
[2022-02-15T12:31:40.090500Z] [debug] QEMU status is not 'shutdown', it is 'running'
[2022-02-15T12:31:41.091951Z] [debug] QEMU status is not 'shutdown', it is 'running'
[2022-02-15T12:31:42.093492Z] [debug] QEMU status is not 'shutdown', it is 'running'
[2022-02-15T12:31:43.094993Z] [debug] QEMU status is not 'shutdown', it is 'running'
[2022-02-15T12:31:44.096513Z] [debug] QEMU status is not 'shutdown', it is 'running'
[2022-02-15T12:31:45.098016Z] [debug] QEMU status is not 'shutdown', it is 'running'
[2022-02-15T12:31:46.099536Z] [debug] QEMU status is not 'shutdown', it is 'running'
[2022-02-15T12:31:47.101013Z] [debug] QEMU status is not 'shutdown', it is 'running'
[2022-02-15T12:31:48.102416Z] [debug] QEMU status is not 'shutdown', it is 'running'
[2022-02-15T12:31:49.103731Z] [debug] QEMU status is not 'shutdown', it is 'running'
[2022-02-15T12:31:50.105142Z] [debug] QEMU status is not 'shutdown', it is 'running'
[2022-02-15T12:31:51.106659Z] [debug] QEMU status is not 'shutdown', it is 'running'
[2022-02-15T12:31:52.108181Z] [debug] QEMU status is not 'shutdown', it is 'running'
[2022-02-15T12:31:53.109628Z] [debug] QEMU status is not 'shutdown', it is 'running'
[2022-02-15T12:31:54.110983Z] [debug] QEMU status is not 'shutdown', it is 'running'
[2022-02-15T12:31:55.174986Z] [info] ::: basetest::runtest: # Test died: Machine didn't shut down! at tinycore/tests/shutdown.pm line 10.
[2022-02-15T12:31:55.177594Z] [debug] ||| finished shutdown tests (runtime: 92 s)
[2022-02-15T12:31:55.177662Z] [debug] ||| post fail hooks runtime: 0 s
[2022-02-15T12:31:55.177961Z] [debug] stopping overall test execution after a fatal test failure
[2022-02-15T12:31:55.178722Z] [debug] stopping autotest process 13144
[2022-02-15T12:31:55.184647Z] [debug] [autotest] process exited: 0
[2022-02-15T12:31:55.285073Z] [debug] done with autotest process
[2022-02-15T12:31:55.285743Z] [debug] stopping command server 13141 because test execution ended
[2022-02-15T12:31:55.285851Z] [debug] isotovideo: informing websocket clients before stopping command server: http://127.0.0.1:20013/NyTrTQWMU40CyqS4/broadcast
[2022-02-15T12:31:55.301550Z] [debug] commands process exited: 0
[2022-02-15T12:31:55.401915Z] [debug] done with command server
[2022-02-15T12:31:55.401993Z] [debug] isotovideo done
[2022-02-15T12:31:55.402737Z] [debug] QEMU status is not 'shutdown', it is 'running'
[2022-02-15T12:31:55.402887Z] [debug] backend shutdown state:
[2022-02-15T12:31:55.403295Z] [info] ::: OpenQA::Qemu::Proc::save_state: Saving QEMU state to qemu_state.json
[2022-02-15T12:31:56.414550Z] [debug] Passing remaining frames to the video encoder
[2022-02-15T12:31:56.437922Z] [debug] Waiting for video encoder to finalize the video
[2022-02-15T12:31:56.437993Z] [debug] The built-in video encoder (pid 13284) terminated
[2022-02-15T12:31:56.438524Z] [debug] QEMU: qemu-system-i386: terminating on signal 15 from pid 13214 (/home/squamata/os-autoinst/isotovideo: backen)
[2022-02-15T12:31:56.439473Z] [debug] sending magic and exit
[2022-02-15T12:31:56.439705Z] [debug] received magic close
[2022-02-15T12:31:56.449547Z] [debug] backend process exited: 0
[2022-02-15T12:31:56.550455Z] [debug] stopping backend process 13214
[2022-02-15T12:31:56.550526Z] [debug] done with backend process
13120: EXIT 0
[2022-02-15T12:31:56.566874Z] [info] [pid:13113] Isotovideo exit status: 0
[2022-02-15T12:31:56.599551Z] [info] [pid:13113] +++ worker notes +++
[2022-02-15T12:31:56.599759Z] [info] [pid:13113] End time: 2022-02-15 12:31:56
[2022-02-15T12:31:56.599852Z] [info] [pid:13113] Result: done
[2022-02-15T12:31:56.604907Z] [info] [pid:13355] Uploading video.ogv
[2022-02-15T12:31:56.650212Z] [info] [pid:13355] Uploading vars.json
[2022-02-15T12:31:56.691318Z] [info] [pid:13355] Uploading autoinst-log.txt
/tmp/7v4CAal1xt/full-stack.d/openqa/testresults/00000/00000007-tinycore-1-flavor-i386-Build1-core@coolone/serial0.txt:
/tmp/7v4CAal1xt/full-stack.d/openqa/testresults/00000/00000007-tinycore-1-flavor-i386-Build1-core@coolone/serial_terminal.txt:
/tmp/7v4CAal1xt/full-stack.d/openqa/testresults/00000/00000007-tinycore-1-flavor-i386-Build1-core@coolone/shutdown-3.txt:
# Test died: Machine didn't shut down! at tinycore/tests/shutdown.pm line 10.
/tmp/7v4CAal1xt/full-stack.d/openqa/testresults/00000/00000007-tinycore-1-flavor-i386-Build1-core@coolone/worker-log.txt:
[2022-02-15T12:29:56.705078Z] [debug] [pid:13113] Preparing Mojo::IOLoop::ReadWriteProcess::Session
[2022-02-15T12:29:56.706055Z] [debug] [pid:13113] Job settings:
[2022-02-15T12:29:56.706195Z] [debug] [pid:13113]
ARCH=i386
BUILD=1
CACHEDIRECTORY=/tmp/7v4CAal1xt/full-stack.d/cache
CACHELIMIT=50
DISTRI=tinycore
FLAVOR=flavor
INTEGRATION_TESTS=1
ISO=Core-7.2.iso
JOBTOKEN=NyTrTQWMU40CyqS4
LOCAL_UPLOAD=0
LOG_LEVEL=debug
MACHINE=coolone
NAME=00000007-tinycore-1-flavor-i386-Build1-core@coolone
OPENQA_HOSTNAME=localhost:9526
OPENQA_URL=http://localhost:9526
PRJDIR=/tmp/7v4CAal1xt/full-stack.d/openqa/share
PUBLISH_HDD_1=
QEMU=i386
QEMUPORT=20012
QEMU_NO_FDC_SET=1
QEMU_NO_KVM=1
QEMU_NO_TABLET=1
RETRY_DELAY=5
RETRY_DELAY_IF_WEBUI_BUSY=60
TEST=core
UEFI_PFLASH_VARS=/usr/share/qemu/ovmf-x86_64.bin
VERSION=1
VNC=91
WORKER_CLASS=qemu_i386,qemu_x86_64
WORKER_ID=1
WORKER_INSTANCE=1
[2022-02-15T12:29:56.722035Z] [debug] [pid:13113] Updating status so job 7 is not considered dead.
[2022-02-15T12:29:56.722504Z] [debug] [pid:13113] REST-API call: POST http://localhost:9526/api/v1/jobs/7/status
[2022-02-15T12:30:01.783136Z] [debug] [pid:13113] Updating status so job 7 is not considered dead.
[2022-02-15T12:30:01.783729Z] [debug] [pid:13113] REST-API call: POST http://localhost:9526/api/v1/jobs/7/status
[2022-02-15T12:30:01.837831Z] [debug] [pid:13113] Linked asset "/tmp/7v4CAal1xt/full-stack.d/cache/localhost/Core-7.2.iso" to "/tmp/7v4CAal1xt/full-stack.d/openqa/pool/1/Core-7.2.iso"
[2022-02-15T12:30:01.838278Z] [debug] [pid:13113] Symlinked from "/tmp/7v4CAal1xt/full-stack.d/openqa/share/tests/tinycore" to "/tmp/7v4CAal1xt/full-stack.d/openqa/pool/1/tinycore"
[2022-02-15T12:30:01.838660Z] [info] [pid:13113] Preparing cgroup to start isotovideo
[2022-02-15T12:30:01.839867Z] [warn] [pid:13113] Disabling cgroup usage because cgroup creation failed: mkdir /sys/fs/cgroup/systemd/docker: Permission denied at /usr/lib/perl5/vendor_perl/5.26.1/Mojo/File.pm line 84.
[2022-02-15T12:30:01.840004Z] [info] [pid:13113] You can define a custom slice with OPENQA_CGROUP_SLICE or indicating the base mount with MOJO_CGROUP_FS.
[2022-02-15T12:30:01.840324Z] [info] [pid:13113] Starting isotovideo container
[2022-02-15T12:30:01.843130Z] [debug] [pid:13113] Registered process:13120
[2022-02-15T12:30:01.843427Z] [info] [pid:13120] 13120: WORKING 7
[2022-02-15T12:30:01.843640Z] [info] [pid:13113] isotovideo has been started (PID: 13120)
[2022-02-15T12:30:01.844241Z] [debug] [pid:13113] Running job 7 from http://localhost:9526: 00000007-tinycore-1-flavor-i386-Build1-core@coolone.
[2022-02-15T12:30:01.846921Z] [debug] [pid:13113] REST-API call: POST http://localhost:9526/api/v1/jobs/7/status
[2022-02-15T12:30:01.903865Z] [debug] [pid:13113] Upload concluded (no current module)
[2022-02-15T12:30:11.912144Z] [debug] [pid:13113] REST-API call: POST http://localhost:9526/api/v1/jobs/7/status
[2022-02-15T12:30:11.986649Z] [debug] [pid:13113] Upload concluded (at boot)
[2022-02-15T12:30:21.987764Z] [debug] [pid:13113] REST-API call: POST http://localhost:9526/api/v1/jobs/7/status
[2022-02-15T12:30:22.050710Z] [debug] [pid:13113] Upload concluded (at boot)
[2022-02-15T12:30:32.060439Z] [debug] [pid:13113] REST-API call: POST http://localhost:9526/api/v1/jobs/7/status
[2022-02-15T12:30:32.208212Z] [debug] [pid:13113] Upload concluded (up to boot)
[2022-02-15T12:30:42.210057Z] [debug] [pid:13113] REST-API call: POST http://localhost:9526/api/v1/jobs/7/status
[2022-02-15T12:30:42.292589Z] [debug] [pid:13113] Upload concluded (at shutdown)
[2022-02-15T12:30:52.304006Z] [debug] [pid:13113] REST-API call: POST http://localhost:9526/api/v1/jobs/7/status
[2022-02-15T12:30:52.364354Z] [debug] [pid:13113] Upload concluded (at shutdown)
[2022-02-15T12:31:02.366920Z] [debug] [pid:13113] REST-API call: POST http://localhost:9526/api/v1/jobs/7/status
[2022-02-15T12:31:02.460213Z] [debug] [pid:13113] Upload concluded (at shutdown)
[2022-02-15T12:31:12.469946Z] [debug] [pid:13113] REST-API call: POST http://localhost:9526/api/v1/jobs/7/status
[2022-02-15T12:31:12.549781Z] [debug] [pid:13113] Upload concluded (at shutdown)
[2022-02-15T12:31:22.552354Z] [debug] [pid:13113] REST-API call: POST http://localhost:9526/api/v1/jobs/7/status
[2022-02-15T12:31:22.665269Z] [debug] [pid:13113] Upload concluded (at shutdown)
[2022-02-15T12:31:32.676352Z] [debug] [pid:13113] REST-API call: POST http://localhost:9526/api/v1/jobs/7/status
[2022-02-15T12:31:32.760474Z] [debug] [pid:13113] Upload concluded (at shutdown)
[2022-02-15T12:31:42.762642Z] [debug] [pid:13113] REST-API call: POST http://localhost:9526/api/v1/jobs/7/status
[2022-02-15T12:31:42.823082Z] [debug] [pid:13113] Upload concluded (at shutdown)
[2022-02-15T12:31:52.832799Z] [debug] [pid:13113] REST-API call: POST http://localhost:9526/api/v1/jobs/7/status
[2022-02-15T12:31:52.897949Z] [debug] [pid:13113] Upload concluded (at shutdown)
[2022-02-15T12:31:56.567214Z] [debug] [pid:13113] Stopping job 7 from http://localhost:9526: 00000007-tinycore-1-flavor-i386-Build1-core@coolone - reason: done
[2022-02-15T12:31:56.567929Z] [debug] [pid:13113] REST-API call: POST http://localhost:9526/api/v1/jobs/7/status
[2022-02-15T12:31:56.604711Z] [info] [pid:13355] Uploading video.ogv
[2022-02-15T12:31:56.605221Z] [debug] [pid:13355] Uploading artefact video.ogv
[2022-02-15T12:31:56.650105Z] [info] [pid:13355] Uploading vars.json
[2022-02-15T12:31:56.650397Z] [debug] [pid:13355] Uploading artefact vars.json
[2022-02-15T12:31:56.691175Z] [info] [pid:13355] Uploading autoinst-log.txt
[2022-02-15T12:31:56.691552Z] [debug] [pid:13355] Uploading artefact autoinst-log.txt
[2022-02-15T12:31:56.731236Z] [info] [pid:13355] Uploading worker-log.txt
[2022-02-15T12:31:56.731530Z] [debug] [pid:13355] Uploading artefact worker-log.txt
/tmp/7v4CAal1xt/full-stack.d/openqa/testresults/00000/00000008-tinycore-1-flavor-i386-Build1-core@coolone/autoinst-log.txt:
[2022-02-15T12:32:01.726820Z] [info] [pid:13113] +++ setup notes +++
[2022-02-15T12:32:01.727062Z] [info] [pid:13113] Running on 1234cbae1a16:1 (Linux 5.11.0-1027-aws #30~20.04.1-Ubuntu SMP Thu Jan 13 11:46:53 UTC 2022 x86_64)
[2022-02-15T12:32:01.734268Z] [debug] [pid:13113] Found HDD_1, caching non-existent.qcow2
[2022-02-15T12:32:01.740532Z] [info] [pid:13113] Downloading non-existent.qcow2, request #4 sent to Cache Service
[2022-02-15T12:32:06.945076Z] [info] [pid:13113] Download of non-existent.qcow2 processed
[2022-02-15T12:32:06.947067Z] [error] [pid:13113] Failed to download non-existent.qcow2 to /tmp/7v4CAal1xt/full-stack.d/cache/localhost/non-existent.qcow2
[2022-02-15T12:32:06.974473Z] [info] [pid:13113] +++ worker notes +++
[2022-02-15T12:32:06.974750Z] [info] [pid:13113] End time: 2022-02-15 12:32:06
[2022-02-15T12:32:06.974912Z] [info] [pid:13113] Result: setup failure
[2022-02-15T12:32:06.979814Z] [info] [pid:13363] Uploading autoinst-log.txt
/tmp/7v4CAal1xt/full-stack.d/openqa/testresults/00000/00000008-tinycore-1-flavor-i386-Build1-core@coolone/worker-log.txt:
[2022-02-15T12:32:01.726536Z] [debug] [pid:13113] Preparing Mojo::IOLoop::ReadWriteProcess::Session
[2022-02-15T12:32:01.727305Z] [debug] [pid:13113] Job settings:
[2022-02-15T12:32:01.727445Z] [debug] [pid:13113]
ARCH=i386
BUILD=1
CACHEDIRECTORY=/tmp/7v4CAal1xt/full-stack.d/cache
CACHELIMIT=50
DISTRI=tinycore
FLAVOR=flavor
HDD_1=non-existent.qcow2
INTEGRATION_TESTS=1
ISO=Core-7.2.iso
JOBTOKEN=02CWEpXQzQrJmeVL
LOCAL_UPLOAD=0
LOG_LEVEL=debug
MACHINE=coolone
NAME=00000008-tinycore-1-flavor-i386-Build1-core@coolone
OPENQA_HOSTNAME=localhost:9526
OPENQA_URL=http://localhost:9526
PRJDIR=/tmp/7v4CAal1xt/full-stack.d/openqa/share
PUBLISH_HDD_1=core-hdd.qcow2
QEMU=i386
QEMUPORT=20012
QEMU_NO_FDC_SET=1
QEMU_NO_KVM=1
QEMU_NO_TABLET=1
RETRY_DELAY=5
RETRY_DELAY_IF_WEBUI_BUSY=60
TEST=core
UEFI_PFLASH_VARS=/usr/share/qemu/ovmf-x86_64.bin
VERSION=1
VNC=91
WORKER_CLASS=qemu_i386,qemu_x86_64
WORKER_ID=1
WORKER_INSTANCE=1
[2022-02-15T12:32:01.740736Z] [debug] [pid:13113] Updating status so job 8 is not considered dead.
[2022-02-15T12:32:01.741166Z] [debug] [pid:13113] REST-API call: POST http://localhost:9526/api/v1/jobs/8/status
[2022-02-15T12:32:06.867128Z] [debug] [pid:13113] Updating status so job 8 is not considered dead.
[2022-02-15T12:32:06.867726Z] [debug] [pid:13113] REST-API call: POST http://localhost:9526/api/v1/jobs/8/status
[2022-02-15T12:32:06.947263Z] [error] [pid:13113] Unable to setup job 8: Failed to download non-existent.qcow2 to /tmp/7v4CAal1xt/full-stack.d/cache/localhost/non-existent.qcow2
[2022-02-15T12:32:06.947437Z] [debug] [pid:13113] Stopping job 8 from http://localhost:9526: 00000008-tinycore-1-flavor-i386-Build1-core@coolone - reason: setup failure
[2022-02-15T12:32:06.947896Z] [debug] [pid:13113] REST-API call: POST http://localhost:9526/api/v1/jobs/8/status
[2022-02-15T12:32:06.979624Z] [info] [pid:13363] Uploading autoinst-log.txt
[2022-02-15T12:32:06.980133Z] [debug] [pid:13363] Uploading artefact autoinst-log.txt
[2022-02-15T12:32:07.018540Z] [info] [pid:13363] Uploading worker-log.txt
[2022-02-15T12:32:07.018812Z] [debug] [pid:13363] Uploading artefact worker-log.txt
(2-2/12)