Project

General

Profile

coordination #98952 ยป full-stack-shutdown-problem.t

mkittler, 2022-03-01 15:42

 
# OPENQA_BASEDIR: /home/squamata/project/test-results/fullstack/full-stack.d
# OPENQA_CONFIG: /home/squamata/project/test-results/fullstack/full-stack.d/config
[INFO] using database schema "public"
[info] [pid:14560] 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: 14565
# Starting WebUI service. Port: 9526
# PID of openqa-webapi: 14566
[info] [pid:14566] 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: 14643
ok 2 - resultdir "/home/squamata/project/test-results/fullstack/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:14566] 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:14566] Unrecognized referer 'localhost'
[debug] [pid:14566] 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:14566] 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(0x557426513988)
ok 16 - job with worker class qemu_i386 scheduled
[info] [pid:14649] worker 1:
- config file: /home/squamata/project/test-results/fullstack/full-stack.d/config/workers.ini
- worker hostname: 1a81a2b0ff0f
- isotovideo version: 25
- websocket API version: 1
- web UI hosts: http://localhost:9526
- class: qemu_i386,qemu_x86_64
- no cleanup: no
- pool directory: /home/squamata/project/test-results/fullstack/full-stack.d/openqa/pool/1
[info] [pid:14649] Project dir for host http://localhost:9526 is /home/squamata/project/test-results/fullstack/full-stack.d/openqa/share
[info] [pid:14649] Registering with openQA http://localhost:9526
ok 17 - at least one free worker with class qemu_i386 registered
[info] [pid:14649] Establishing ws connection via ws://localhost:9526/api/v1/ws/1
[debug] [pid:14560] +=----------------=+
[debug] [pid:14560] -> Scheduling new jobs.
[debug] [pid:14560] Free workers: 1/1
[debug] [pid:14560] Scheduled jobs: 1
[debug] [pid:14560] Need to schedule 1 parallel jobs for job 1 (with priority 50)
[info] [pid:14649] Registered and connected via websockets with openQA host http://localhost:9526 and worker ID 1
[debug] [pid:14560] Assigned job '1' to worker ID '1'
[debug] [pid:14560] [Job#1] Prepare for being processed by worker 1
[debug] [pid:14565] Updating seen of worker 1 from worker_status (free)
[debug] [pid:14565] Started to send message to 1 for job(s) 1
[debug] [pid:14560] Sent job(s) '1' to worker '1'
[debug] [pid:14560] Scheduler took 0.09654s to perform operations and allocated 1 jobs
[debug] [pid:14649] Accepting job 1 from http://localhost:9526.
[debug] [pid:14560] Allocated: { job => 1, worker => 1 }
[debug] [pid:14649] Setting job 1 from http://localhost:9526 up
[debug] [pid:14649] Preparing Mojo::IOLoop::ReadWriteProcess::Session
[info] [pid:14649] +++ setup notes +++
[info] [pid:14649] Running on 1a81a2b0ff0f: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:14649] Job settings:
[debug] [pid:14649]
ARCH=i386
BUILD=1
DISTRI=tinycore
FLAVOR=flavor
INTEGRATION_TESTS=1
ISO=Core-7.2.iso
JOBTOKEN=N503ZgOJZf1SW84y
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=/home/squamata/project/test-results/fullstack/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:14649] Linked asset "/home/squamata/project/test-results/fullstack/full-stack.d/openqa/share/factory/iso/Core-7.2.iso" to "/home/squamata/project/test-results/fullstack/full-stack.d/openqa/pool/1/Core-7.2.iso"
[debug] [pid:14649] Symlinked from "/home/squamata/project/test-results/fullstack/full-stack.d/openqa/share/tests/tinycore" to "/home/squamata/project/test-results/fullstack/full-stack.d/openqa/pool/1/tinycore"
[info] [pid:14649] Preparing cgroup to start isotovideo
[warn] [pid:14649] 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.
# Wait for jQuery successful: wait_for_result_panel: waiting for '(?^u:State: running)' (count 0 of 3240)
[info] [pid:14649] You can define a custom slice with OPENQA_CGROUP_SLICE or indicating the base mount with MOJO_CGROUP_FS.
[info] [pid:14649] Starting isotovideo container
[debug] [pid:14649] Registered process:14656
[info] [pid:14656] 14656: WORKING 1
[debug] [pid:14656] +++ worker notes +++
[info] [pid:14649] isotovideo has been started (PID: 14656)
[debug] [pid:14649] Running job 1 from http://localhost:9526: 00000001-tinycore-1-flavor-i386-Build1-core@coolone.
[debug] [pid:14649] REST-API call: POST http://localhost:9526/api/v1/jobs/1/status
[debug] [pid:14565] Worker 1 accepted job 1
[debug] [pid:14565] Updating seen of worker 1 from worker_status (working)
[debug] [pid:14649] 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)
[debug] [pid:14566] Unrecognized referer 'localhost'
[debug] [pid:14566] Unrecognized referer 'localhost'
[debug] [pid:14566] Unrecognized referer 'localhost'
[debug] [pid:14643] connecting to os-autoinst command server for job 1 at ws://127.0.0.1:20013/N503ZgOJZf1SW84y/ws
[debug] [pid:14566] Unrecognized referer 'localhost'
[debug] [pid:14566] Unrecognized referer 'localhost'
[debug] [pid:14566] Asking the worker 1 to start providing livestream for job 1
[debug] [pid:14649] Starting livelog
[debug] [pid:14649] REST-API call: POST http://localhost:9526/api/v1/jobs/1/status
[debug] [pid:14649] Upload concluded (no current module)
# Wait for jQuery successful: wait_for_result_panel: waiting for '(?^u:State: running)' (count 6 of 3240)
ok 18 - \#nav-item-for-live present
ok 19 - test 1 is running
# Subtest: wait until developer console becomes available
[debug] [pid:14566] Asking worker 1 to stop providing livestream for job 1
[debug] [pid:14649] 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:14649] REST-API call: POST http://localhost:9526/api/v1/jobs/1/status
[debug] [pid:14649] Upload concluded (no current module)
# waiting for paused, developer console contains:
# status: Connecting to ws://127.0.0.1:20013/N503ZgOJZf1SW84y/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/N503ZgOJZf1SW84y/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":"uuDcaiKN"},"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":"xYluZbnG","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:14649] REST-API call: POST http://localhost:9526/api/v1/jobs/1/status
[debug] [pid:14649] 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 2286
1..4
ok 21 - pause at certain test
# Subtest: schedule job
[debug] [pid:14566] Unrecognized referer 'localhost'
[debug] [pid:14566] Unrecognized referer 'localhost'
[debug] [pid:14566] Unrecognized referer 'localhost'
[debug] [pid:14566] Unrecognized referer 'localhost'
[debug] [pid:14643] connecting to os-autoinst command server for job 1 at ws://127.0.0.1:20013/N503ZgOJZf1SW84y/ws
[debug] [pid:14566] Asking the worker 1 to start providing livestream for job 1
[debug] [pid:14649] Starting livelog
[debug] [pid:14649] REST-API call: POST http://localhost:9526/api/v1/jobs/1/status
[debug] [pid:14566] Unrecognized referer 'localhost'
[debug] [pid:14566] creating f41/844/68dbb276a03240907d0e7e500d.png
[debug] [pid:14566] creating 68d/7ac/83452b72555f8a6b386629f91f.png
[debug] [pid:14880] Optimizing /home/squamata/project/test-results/fullstack/full-stack.d/openqa/pool/1/testresults/boot-2.png
# Wait for jQuery successful: wait_for_result_panel: waiting for '(?^u:Result: passed)' (count 0 of 3240)
[debug] [pid:14880] Uploading artefact boot-2.png as 68d7ac83452b72555f8a6b386629f91f
[debug] [pid:14880] Optimizing /home/squamata/project/test-results/fullstack/full-stack.d/openqa/pool/1/testresults/.thumbs/boot-2.png
[debug] [pid:14880] Uploading artefact boot-2.png as 68d7ac83452b72555f8a6b386629f91f
[debug] [pid:14880] Optimizing /home/squamata/project/test-results/fullstack/full-stack.d/openqa/pool/1/testresults/boot-1.png
[debug] [pid:14880] Uploading artefact boot-1.png as f4184468dbb276a03240907d0e7e500d
[debug] [pid:14880] Optimizing /home/squamata/project/test-results/fullstack/full-stack.d/openqa/pool/1/testresults/.thumbs/boot-1.png
[debug] [pid:14880] Uploading artefact boot-1.png as f4184468dbb276a03240907d0e7e500d
[debug] [pid:14649] 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:14565] Updating seen of worker 1 from worker_status (working)
[debug] [pid:14649] REST-API call: POST http://localhost:9526/api/v1/jobs/1/status
[debug] [pid:14649] 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:14649] REST-API call: POST http://localhost:9526/api/v1/jobs/1/status
[debug] [pid:14649] 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:14649] REST-API call: POST http://localhost:9526/api/v1/jobs/1/status
[debug] [pid:14649] Upload concluded (at shutdown)
# 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)
[debug] [pid:14649] REST-API call: POST http://localhost:9526/api/v1/jobs/1/status
[debug] [pid:14649] Upload concluded (at shutdown)
# Wait for jQuery successful: wait_for_result_panel: waiting for '(?^u:Result: passed)' (count 9 of 3240)
[debug] [pid:14566] Unrecognized referer 'localhost'
[debug] [pid:14566] Unrecognized referer 'localhost'
[debug] looking for "f41/844/.thumbs/68dbb276a03240907d0e7e500d.png" in [
"/home/squamata/project/test-results/fullstack/full-stack.d/openqa/images",
]
[debug] found bless({
path => "/home/squamata/project/test-results/fullstack/full-stack.d/openqa/images/f41/844/.thumbs/68dbb276a03240907d0e7e500d.png",
pid => 14566,
}, "Mojo::Asset::File")
[debug] looking for "68d/7ac/.thumbs/83452b72555f8a6b386629f91f.png" in [
"/home/squamata/project/test-results/fullstack/full-stack.d/openqa/images",
]
[debug] found bless({
path => "/home/squamata/project/test-results/fullstack/full-stack.d/openqa/images/68d/7ac/.thumbs/83452b72555f8a6b386629f91f.png",
pid => 14566,
}, "Mojo::Asset::File")
# Wait for jQuery successful: wait_for_result_panel: waiting for '(?^u:Result: passed)' (count 10 of 3240)
[debug] [pid:14649] REST-API call: POST http://localhost:9526/api/v1/jobs/1/status
[debug] [pid:14566] creating 68d/7ac/83452b72555f8a6b386629f91f.png
[debug] [pid:14566] creating 68d/7ac/83452b72555f8a6b386629f91f.png
# Wait for jQuery successful: wait_for_result_panel: waiting for '(?^u:Result: passed)' (count 11 of 3240)
[debug] [pid:14566] creating f1e/d19/aa4bfd65612d1d5fc58b221bf2.png
[debug] [pid:14890] Optimizing /home/squamata/project/test-results/fullstack/full-stack.d/openqa/pool/1/testresults/shutdown-2.png
[debug] [pid:14890] Uploading artefact shutdown-2.png as f1ed19aa4bfd65612d1d5fc58b221bf2
[debug] [pid:14890] Optimizing /home/squamata/project/test-results/fullstack/full-stack.d/openqa/pool/1/testresults/.thumbs/shutdown-2.png
[debug] [pid:14890] Uploading artefact shutdown-2.png as f1ed19aa4bfd65612d1d5fc58b221bf2
[debug] [pid:14649] Upload concluded (up to shutdown)
# Wait for jQuery successful: wait_for_result_panel: waiting for '(?^u:Result: passed)' (count 12 of 3240)
[info] [pid:14649] Isotovideo exit status: 0
[debug] [pid:14649] Stopping job 1 from http://localhost:9526: 00000001-tinycore-1-flavor-i386-Build1-core@coolone - reason: done
[debug] [pid:14649] REST-API call: POST http://localhost:9526/api/v1/jobs/1/status
[info] [pid:14649] +++ worker notes +++
[info] [pid:14649] End time: 2022-03-01 15:27:34
[info] [pid:14649] Result: done
[info] [pid:14899] Uploading core-hdd.qcow2
[info] [pid:14899] Uploading core-hdd.qcow2 using multiple chunks
[info] [pid:14899] core-hdd.qcow2: local upload (no chunks needed)
[info] [pid:14899] Uploading video.ogv
[debug] [pid:14899] Uploading artefact video.ogv
[info] [pid:14899] Uploading vars.json
[debug] [pid:14899] Uploading artefact vars.json
[info] [pid:14899] Uploading autoinst-log.txt
[debug] [pid:14899] Uploading artefact autoinst-log.txt
# Wait for jQuery successful: wait_for_result_panel: waiting for '(?^u:Result: passed)' (count 13 of 3240)
[info] [pid:14899] Uploading worker-log.txt
[debug] [pid:14899] Uploading artefact worker-log.txt
[info] [pid:14899] Uploading serial0.txt
[debug] [pid:14899] Uploading artefact serial0.txt
[info] [pid:14899] Uploading video_time.vtt
[debug] [pid:14899] Uploading artefact video_time.vtt
[info] [pid:14899] Uploading serial_terminal.txt
[debug] [pid:14899] Uploading artefact serial_terminal.txt
[info] [pid:14899] Uploading virtio_console1.log
[debug] [pid:14899] Uploading artefact virtio_console1.log
[debug] [pid:14649] Considering job 1 as regularly done
[debug] [pid:14649] REST-API call: POST http://localhost:9526/api/v1/jobs/1/status
[debug] [pid:14566] creating 68d/7ac/83452b72555f8a6b386629f91f.png
[debug] [pid:14566] creating 68d/7ac/83452b72555f8a6b386629f91f.png
[debug] [pid:14566] creating f41/844/68dbb276a03240907d0e7e500d.png
[debug] [pid:14566] creating 68d/7ac/83452b72555f8a6b386629f91f.png
[debug] [pid:14566] creating f1e/d19/aa4bfd65612d1d5fc58b221bf2.png
[debug] [pid:14649] Upload concluded (no current module)
[debug] [pid:14649] REST-API call: POST http://localhost:9526/api/v1/jobs/1/set_done?worker_id=1
[debug] [pid:14649] Job 1 from http://localhost:9526 finished - reason: done
[debug] [pid:14649] Cleaning up for next job
# 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:14566] Unrecognized referer 'localhost'
[debug] [pid:14566] Unrecognized referer 'localhost'
[debug] [pid:14566] Unrecognized referer 'localhost'
[debug] looking for "f1e/d19/.thumbs/aa4bfd65612d1d5fc58b221bf2.png" in [
"/home/squamata/project/test-results/fullstack/full-stack.d/openqa/images",
]
[debug] found bless({
path => "/home/squamata/project/test-results/fullstack/full-stack.d/openqa/images/f1e/d19/.thumbs/aa4bfd65612d1d5fc58b221bf2.png",
pid => 14566,
}, "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 /home/squamata/project/test-results/fullstack/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:14566] 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:14566] Job 1 duplicated as 2
[warn] [pid:14566] Unable to wakeup scheduler: Connection refused
ok 1 - client returned new test_url for test 2
[debug] [pid:14566] Unrecognized referer 'localhost'
ok 2 - test 1 is restarted
[debug] looking for "68d/7ac/.thumbs/83452b72555f8a6b386629f91f.png" in [
"/home/squamata/project/test-results/fullstack/full-stack.d/openqa/images",
]
[debug] found bless({
path => "/home/squamata/project/test-results/fullstack/full-stack.d/openqa/images/68d/7ac/.thumbs/83452b72555f8a6b386629f91f.png",
pid => 14566,
}, "Mojo::Asset::File")
[debug] looking for "f41/844/.thumbs/68dbb276a03240907d0e7e500d.png" in [
"/home/squamata/project/test-results/fullstack/full-stack.d/openqa/images",
]
[debug] found bless({
path => "/home/squamata/project/test-results/fullstack/full-stack.d/openqa/images/f41/844/.thumbs/68dbb276a03240907d0e7e500d.png",
pid => 14566,
}, "Mojo::Asset::File")
[debug] [pid:14566] Unrecognized referer 'localhost'
[debug] looking for "f1e/d19/.thumbs/aa4bfd65612d1d5fc58b221bf2.png" in [
"/home/squamata/project/test-results/fullstack/full-stack.d/openqa/images",
]
[debug] found bless({
path => "/home/squamata/project/test-results/fullstack/full-stack.d/openqa/images/f1e/d19/.thumbs/aa4bfd65612d1d5fc58b221bf2.png",
pid => 14566,
}, "Mojo::Asset::File")
ok 3 - click_ok'clicked link to test 2'
[debug] [pid:14566] Unrecognized referer 'localhost'
ok 4 - job with worker class qemu_i386 scheduled
[debug] [pid:14566] Unrecognized referer 'localhost'
ok 5 - at least one free worker with class qemu_i386 registered
[debug] [pid:14560] +=----------------=+
[debug] [pid:14560] -> Scheduling new jobs.
[debug] [pid:14560] Free workers: 1/1
[debug] [pid:14560] Scheduled jobs: 1
[debug] [pid:14560] Need to schedule 1 parallel jobs for job 2 (with priority 50)
[debug] [pid:14560] Assigned job '2' to worker ID '1'
[debug] [pid:14560] [Job#2] Prepare for being processed by worker 1
[debug] [pid:14565] Started to send message to 1 for job(s) 2
[debug] [pid:14560] Sent job(s) '2' to worker '1'
[debug] [pid:14560] Scheduler took 0.11342s to perform operations and allocated 1 jobs
[debug] [pid:14560] Allocated: { job => 2, worker => 1 }
[debug] [pid:14649] Accepting job 2 from http://localhost:9526.
[debug] [pid:14649] Setting job 2 from http://localhost:9526 up
[debug] [pid:14649] Preparing Mojo::IOLoop::ReadWriteProcess::Session
[info] [pid:14649] +++ setup notes +++
[info] [pid:14649] Running on 1a81a2b0ff0f: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:14649] Job settings:
[debug] [pid:14649]
ARCH=i386
BUILD=1
DISTRI=tinycore
FLAVOR=flavor
INTEGRATION_TESTS=1
ISO=Core-7.2.iso
JOBTOKEN=G7cORS23YXmPkIHP
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=/home/squamata/project/test-results/fullstack/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:14649] Linked asset "/home/squamata/project/test-results/fullstack/full-stack.d/openqa/share/factory/iso/Core-7.2.iso" to "/home/squamata/project/test-results/fullstack/full-stack.d/openqa/pool/1/Core-7.2.iso"
[debug] [pid:14649] Symlinked from "/home/squamata/project/test-results/fullstack/full-stack.d/openqa/share/tests/tinycore" to "/home/squamata/project/test-results/fullstack/full-stack.d/openqa/pool/1/tinycore"
[info] [pid:14649] Preparing cgroup to start isotovideo
[warn] [pid:14649] 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:14649] You can define a custom slice with OPENQA_CGROUP_SLICE or indicating the base mount with MOJO_CGROUP_FS.
[info] [pid:14649] Starting isotovideo container
# Wait for jQuery successful: wait_for_result_panel: waiting for '(?^u:State: running)' (count 0 of 3240)
[debug] [pid:14649] Registered process:14912
[info] [pid:14912] 14912: WORKING 2
[info] [pid:14649] isotovideo has been started (PID: 14912)
[debug] [pid:14912] +++ worker notes +++
[debug] [pid:14649] Running job 2 from http://localhost:9526: 00000002-tinycore-1-flavor-i386-Build1-core@coolone.
[debug] [pid:14649] REST-API call: POST http://localhost:9526/api/v1/jobs/2/status
[debug] [pid:14565] Worker 1 accepted job 2
[debug] [pid:14565] Updating seen of worker 1 from worker_status (working)
[debug] [pid:14649] 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:14566] Unrecognized referer 'localhost'
[debug] [pid:14566] Unrecognized referer 'localhost'
[debug] [pid:14566] Unrecognized referer 'localhost'
[debug] [pid:14566] Unrecognized referer 'localhost'
[debug] [pid:14643] connecting to os-autoinst command server for job 2 at ws://127.0.0.1:20013/G7cORS23YXmPkIHP/ws
[debug] [pid:14566] Unrecognized referer 'localhost'
[debug] [pid:14566] Asking the worker 1 to start providing livestream for job 2
[debug] [pid:14649] Starting livelog
[debug] [pid:14649] REST-API call: POST http://localhost:9526/api/v1/jobs/2/status
[debug] [pid:14649] Upload concluded (at boot)
# Wait for jQuery successful: wait_for_result_panel: waiting for '(?^u:State: running)' (count 10 of 3240)
ok 6 - \#nav-item-for-live present
ok 7 - job 2 running
[info] [pid:14649] Received signal TERM
[debug] [pid:14649] Stopping job 2 from http://localhost:9526: 00000002-tinycore-1-flavor-i386-Build1-core@coolone - reason: quit
[debug] [pid:14649] REST-API call: POST http://localhost:9526/api/v1/jobs/2/status
[debug] [pid:14649] Announcing job termination (due to quit) to command server via http://localhost:20013/G7cORS23YXmPkIHP/broadcast
[info] [pid:14649] Isotovideo exit status: 1
[info] [pid:14649] +++ worker notes +++
[info] [pid:14649] End time: 2022-03-01 15:27:50
[info] [pid:14649] Result: quit
[debug] [pid:14649] Job 2 stopped as incomplete
[debug] [pid:14649] Duplicating job 2
[debug] [pid:14649] REST-API call: POST http://localhost:9526/api/v1/jobs/2/duplicate?dup_type_auto=1
[debug] Restarting job 2
[debug] [pid:14566] 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:14566] Job 2 duplicated as 3
[warn] [pid:14566] Unable to wakeup scheduler: Connection refused
[debug] [pid:14649] Unable to read result-assert_screen.json: Can't open file "/home/squamata/project/test-results/fullstack/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(0x55b84ce4c328)) 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(0x55b84ce24fa8), "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(0x55b84ce24fa8), "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(0x55b84ce24fa8), "", ARRAY(0x55b84ce3d590)) 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(0x55b84ce24fa8), CODE(0x55b84ce42f58)) called at /home/squamata/project/script/../lib/OpenQA/Worker/Job.pm line 715
OpenQA::Worker::Job::_upload_results(OpenQA::Worker::Job=HASH(0x55b84ce24fa8), CODE(0x55b84ce42f58)) called at /home/squamata/project/script/../lib/OpenQA/Worker/Job.pm line 526
OpenQA::Worker::Job::__ANON__(HASH(0x55b84cdfdcf8)) called at /home/squamata/project/script/../lib/OpenQA/Worker/WebUIConnection.pm line 301
OpenQA::Worker::WebUIConnection::__ANON__(OpenQA::Client=HASH(0x55b84cd14910), Mojo::Transaction::HTTP=HASH(0x55b84ce4bd40), 1) called at /home/squamata/project/script/../lib/OpenQA/Worker/WebUIConnection.pm line 335
OpenQA::Worker::WebUIConnection::__ANON__(OpenQA::Client=HASH(0x55b84cd14910), Mojo::Transaction::HTTP=HASH(0x55b84ce4bd40)) called at /usr/lib/perl5/vendor_perl/5.26.1/Mojo/UserAgent.pm line 249
Mojo::UserAgent::_finish(OpenQA::Client=HASH(0x55b84cd14910), "764adede50dff3234cd1a0a414df5489") called at /usr/lib/perl5/vendor_perl/5.26.1/Mojo/UserAgent.pm line 276
Mojo::UserAgent::_read(OpenQA::Client=HASH(0x55b84cd14910), "764adede50dff3234cd1a0a414df5489", "HTTP/1.1 200 OK\x{d}\x{a}Server: Mojolicious (Perl)\x{d}\x{a}Content-Length: "...) called at /usr/lib/perl5/vendor_perl/5.26.1/Mojo/UserAgent.pm line 136
Mojo::UserAgent::__ANON__(Mojo::IOLoop::Stream=HASH(0x55b84ce4ff58)) called at /usr/lib/perl5/vendor_perl/5.26.1/Mojo/EventEmitter.pm line 15
Mojo::EventEmitter::emit(Mojo::IOLoop::Stream=HASH(0x55b84ce4ff58), "read", "HTTP/1.1 200 OK\x{d}\x{a}Server: Mojolicious (Perl)\x{d}\x{a}Content-Length: "...) called at /usr/lib/perl5/vendor_perl/5.26.1/Mojo/IOLoop/Stream.pm line 109
Mojo::IOLoop::Stream::_read(Mojo::IOLoop::Stream=HASH(0x55b84ce4ff58)) called at /usr/lib/perl5/vendor_perl/5.26.1/Mojo/IOLoop/Stream.pm line 57
Mojo::IOLoop::Stream::__ANON__(Mojo::Reactor::Poll=HASH(0x55b84acab0d8)) 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(0x55b84acab0d8), "I/O watcher", CODE(0x55b84ce47750), 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(0x55b84acab0d8)) called at /usr/lib/perl5/vendor_perl/5.26.1/Mojo/Reactor/Poll.pm line 101
Mojo::Reactor::Poll::start(Mojo::Reactor::Poll=HASH(0x55b84acab0d8)) called at /usr/lib/perl5/vendor_perl/5.26.1/Mojo/IOLoop.pm line 134
Mojo::IOLoop::start(Mojo::IOLoop=HASH(0x55b84aa062d0)) called at /home/squamata/project/script/../lib/OpenQA/Worker.pm line 376
OpenQA::Worker::exec(OpenQA::Worker=HASH(0x55b84cd05c18)) called at ./script/worker line 126
[debug] [pid:14649] REST-API call: POST http://localhost:9526/api/v1/jobs/2/status
[debug] [pid:14566] creating f41/844/68dbb276a03240907d0e7e500d.png
[debug] [pid:14649] Upload concluded (at boot)
[debug] [pid:14649] 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:14566] checking take over from 1: GOOD vs assert_screen:none,shutdown:none
[debug] [pid:14649] Job 2 from http://localhost:9526 finished - reason: quit
[debug] [pid:14649] Informing http://localhost:9526 that we are going offline
[info] [pid:14565] 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:14566] Unrecognized referer 'localhost'
[debug] [pid:14566] Unrecognized referer 'localhost'
[debug] [pid:14566] Unrecognized referer 'localhost'
[debug] looking for "f41/844/.thumbs/68dbb276a03240907d0e7e500d.png" in [
"/home/squamata/project/test-results/fullstack/full-stack.d/openqa/images",
]
[debug] found bless({
path => "/home/squamata/project/test-results/fullstack/full-stack.d/openqa/images/f41/844/.thumbs/68dbb276a03240907d0e7e500d.png",
pid => 14566,
}, "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:14566] 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:14566] Unrecognized referer 'localhost'
ok 2 - click_ok'clicked on 3'
[debug] [pid:14566] Unrecognized referer 'localhost'
[debug] [pid:14566] 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:14566] Unrecognized referer 'localhost'
ok 26 - click_ok'clicked on 4'
ok 27 - scheduled test page
[debug] [pid:14566] Unrecognized referer 'localhost'
ok 28 - test 4 is scheduled
ok 29 - no unexpected js warnings after test 4 was scheduled
ok 30 - Worker started as IPC::Run=HASH(0x557426604aa8)
[debug] [pid:14566] Unrecognized referer 'localhost'
ok 31 - job with worker class qemu_i386 scheduled
[info] [pid:15121] worker 1:
- config file: /home/squamata/project/test-results/fullstack/full-stack.d/config/workers.ini
- worker hostname: 1a81a2b0ff0f
- isotovideo version: 25
- websocket API version: 1
- web UI hosts: http://localhost:9526
- class: qemu_i386,qemu_x86_64
- no cleanup: no
- pool directory: /home/squamata/project/test-results/fullstack/full-stack.d/openqa/pool/1
[info] [pid:15121] Project dir for host http://localhost:9526 is /home/squamata/project/test-results/fullstack/full-stack.d/openqa/share
[info] [pid:15121] Registering with openQA http://localhost:9526
[info] [pid:15121] Establishing ws connection via ws://localhost:9526/api/v1/ws/1
[info] [pid:15121] Registered and connected via websockets with openQA host http://localhost:9526 and worker ID 1
[debug] [pid:14565] Updating seen of worker 1 from worker_status (free)
ok 32 - at least one free worker with class qemu_i386 registered
[debug] [pid:14560] +=----------------=+
[debug] [pid:14560] -> Scheduling new jobs.
[debug] [pid:14560] Free workers: 1/1
[debug] [pid:14560] Scheduled jobs: 1
[debug] [pid:14560] Need to schedule 1 parallel jobs for job 4 (with priority 50)
[debug] [pid:14560] Assigned job '4' to worker ID '1'
[debug] [pid:14560] [Job#4] Prepare for being processed by worker 1
[debug] [pid:14565] Started to send message to 1 for job(s) 4
[debug] [pid:14560] Sent job(s) '4' to worker '1'
[debug] [pid:14560] Scheduler took 0.12918s to perform operations and allocated 1 jobs
[debug] [pid:14560] Allocated: { job => 4, worker => 1 }
# Subtest: incomplete job because of setup failure
[debug] [pid:15121] Accepting job 4 from http://localhost:9526.
[debug] [pid:15121] Setting job 4 from http://localhost:9526 up
[debug] [pid:15121] Preparing Mojo::IOLoop::ReadWriteProcess::Session
[info] [pid:15121] +++ setup notes +++
[info] [pid:15121] Running on 1a81a2b0ff0f: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:15121] Job settings:
[debug] [pid:15121]
ARCH=i386
BUILD=1
DISTRI=tinycore
FLAVOR=flavor
HDD_1=nihilist_disk.hda
INTEGRATION_TESTS=1
ISO=Core-7.2.iso
JOBTOKEN=Hi1Jbzdefw7ROxDn
LOG_LEVEL=debug
MACHINE=noassets
NAME=00000004-tinycore-1-flavor-i386-Build1-core@noassets
OPENQA_HOSTNAME=localhost:9526
OPENQA_URL=http://localhost:9526
PRJDIR=/home/squamata/project/test-results/fullstack/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
[error] [pid:15121] HDD_1 handling Cannot find HDD_1 asset hdd/nihilist_disk.hda!
[error] [pid:15121] Unable to setup job 4: Cannot find HDD_1 asset hdd/nihilist_disk.hda!
[debug] [pid:15121] Stopping job 4 from http://localhost:9526: 00000004-tinycore-1-flavor-i386-Build1-core@noassets - reason: setup failure
[debug] [pid:15121] REST-API call: POST http://localhost:9526/api/v1/jobs/4/status
# Wait for jQuery successful: wait_for_result_panel: waiting for '(?^u:Result: incomplete)' (count 0 of 3240)
[debug] [pid:14565] Worker 1 accepted job 4
[info] [pid:15121] +++ worker notes +++
[info] [pid:15121] End time: 2022-03-01 15:27:59
[info] [pid:15121] Result: setup failure
[info] [pid:15127] Uploading autoinst-log.txt
[debug] [pid:15127] Uploading artefact autoinst-log.txt
[info] [pid:15127] Uploading worker-log.txt
[debug] [pid:15127] Uploading artefact worker-log.txt
[debug] [pid:15121] Job 4 stopped as incomplete
[warn] [pid:15121] Unable to upload results of the job because no command server URL or worker ID have been set.
[debug] [pid:15121] Upload concluded (no current module)
[debug] [pid:15121] 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:15121] Job 4 from http://localhost:9526 finished - reason: setup failure
[debug] [pid:15121] 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)
# Wait for jQuery successful: wait_for_result_panel: waiting for '(?^u:Result: incomplete)' (count 5 of 3240)
[debug] [pid:14566] Unrecognized referer 'localhost'
[debug] [pid:14566] Unrecognized referer 'localhost'
# Wait for jQuery successful: wait_for_result_panel: waiting for '(?^u:Result: incomplete)' (count 6 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:15121] Received signal TERM
[debug] [pid:15121] Informing http://localhost:9526 that we are going offline
[info] [pid:14565] 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:14566] Unable to wakeup scheduler: Connection refused
[debug] [pid:14566] Unrecognized referer 'localhost'
ok 2 - test 5 is scheduled
ok 3 - Worker started as IPC::Run=HASH(0x55742670c998)
[debug] [pid:14566] Unrecognized referer 'localhost'
ok 4 - job with worker class qemu_i386 scheduled
[info] [pid:15136] worker 1:
- config file: /home/squamata/project/test-results/fullstack/full-stack.d/config/workers.ini
- worker hostname: 1a81a2b0ff0f
- isotovideo version: 25
- websocket API version: 1
- web UI hosts: http://localhost:9526
- class: qemu_i386,qemu_x86_64
- no cleanup: no
- pool directory: /home/squamata/project/test-results/fullstack/full-stack.d/openqa/pool/1
[info] [pid:15136] CACHE: caching is enabled, setting up /home/squamata/project/test-results/fullstack/full-stack.d/cache/localhost
[info] [pid:15136] Project dir for host http://localhost:9526 is /home/squamata/project/test-results/fullstack/full-stack.d/openqa/share
[info] [pid:15136] Registering with openQA http://localhost:9526
[info] [pid:15136] Establishing ws connection via ws://localhost:9526/api/v1/ws/1
[info] [pid:15136] Registered and connected via websockets with openQA host http://localhost:9526 and worker ID 1
[debug] [pid:14565] Updating seen of worker 1 from worker_status (free)
ok 5 - at least one free worker with class qemu_i386 registered
[debug] [pid:14560] +=----------------=+
[debug] [pid:14560] -> Scheduling new jobs.
[debug] [pid:14560] Free workers: 1/1
[debug] [pid:14560] Scheduled jobs: 1
[debug] [pid:14560] Need to schedule 1 parallel jobs for job 5 (with priority 50)
[debug] [pid:14560] Assigned job '5' to worker ID '1'
[debug] [pid:14560] [Job#5] Prepare for being processed by worker 1
[debug] [pid:14565] Started to send message to 1 for job(s) 5
[debug] [pid:14560] Sent job(s) '5' to worker '1'
[debug] [pid:14560] Scheduler took 0.10115s to perform operations and allocated 1 jobs
[debug] [pid:14560] Allocated: { job => 5, worker => 1 }
[debug] [pid:15136] Accepting job 5 from http://localhost:9526.
[debug] [pid:15136] Setting job 5 from http://localhost:9526 up
[debug] [pid:15136] Preparing Mojo::IOLoop::ReadWriteProcess::Session
[info] [pid:15136] +++ setup notes +++
[info] [pid:15136] Running on 1a81a2b0ff0f: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:15136] Job settings:
[debug] [pid:15136]
ARCH=i386
BUILD=1
CACHEDIRECTORY=/home/squamata/project/test-results/fullstack/full-stack.d/cache
CACHELIMIT=50
DISTRI=tinycore
FLAVOR=flavor
INTEGRATION_TESTS=1
ISO=Core-7.2.iso
JOBTOKEN=xBOCRMEQoRw0iLse
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=/home/squamata/project/test-results/fullstack/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:15136] Found ISO, caching Core-7.2.iso
[info] [pid:15136] Downloading Core-7.2.iso, request #1 sent to Cache Service
[debug] [pid:15136] Updating status so job 5 is not considered dead.
[debug] [pid:15136] REST-API call: POST http://localhost:9526/api/v1/jobs/5/status
[debug] [pid:14565] 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:14566] Unrecognized referer 'localhost'
[debug] [pid:14566] Unrecognized referer 'localhost'
[debug] [pid:14566] 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:14566] Unrecognized referer 'localhost'
[debug] [pid:14566] Unrecognized referer 'localhost'
[debug] [pid:14566] 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:15136] Updating status so job 5 is not considered dead.
[debug] [pid:15136] REST-API call: POST http://localhost:9526/api/v1/jobs/5/status
[info] [pid:15136] Download of Core-7.2.iso processed
[debug] [pid:15136] Linked asset "/home/squamata/project/test-results/fullstack/full-stack.d/cache/localhost/Core-7.2.iso" to "/home/squamata/project/test-results/fullstack/full-stack.d/openqa/pool/1/Core-7.2.iso"
[debug] [pid:15136] Symlinked from "/home/squamata/project/test-results/fullstack/full-stack.d/openqa/share/tests/tinycore" to "/home/squamata/project/test-results/fullstack/full-stack.d/openqa/pool/1/tinycore"
[info] [pid:15136] Preparing cgroup to start isotovideo
[warn] [pid:15136] 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:15136] You can define a custom slice with OPENQA_CGROUP_SLICE or indicating the base mount with MOJO_CGROUP_FS.
[info] [pid:15136] Starting isotovideo container
[debug] [pid:15136] Registered process:15143
[info] [pid:15143] 15143: WORKING 5
[info] [pid:15136] isotovideo has been started (PID: 15143)
[debug] [pid:15143] +++ worker notes +++
[debug] [pid:15136] Running job 5 from http://localhost:9526: 00000005-tinycore-1-flavor-i386-Build1-core@coolone.
[debug] [pid:15136] REST-API call: POST http://localhost:9526/api/v1/jobs/5/status
[debug] [pid:14565] Updating seen of worker 1 from worker_status (working)
[debug] [pid:15136] Upload concluded (no current module)
ok 4 - iso is hardlinked to cache
# Wait for jQuery successful: wait_for_result_panel: waiting for '(?^u:Result: passed)' (count 0 of 3240)
# 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:14566] Unrecognized referer 'localhost'
# 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)
# Wait for jQuery successful: wait_for_result_panel: waiting for '(?^u:Result: passed)' (count 14 of 3240)
[debug] [pid:14566] 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)
[debug] [pid:15136] REST-API call: POST http://localhost:9526/api/v1/jobs/5/status
[debug] [pid:15136] 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)
# Wait for jQuery successful: wait_for_result_panel: waiting for '(?^u:Result: passed)' (count 23 of 3240)
[debug] [pid:14566] Unrecognized referer 'localhost'
[debug] [pid:14566] Unrecognized referer 'localhost'
[debug] [pid:14643] connecting to os-autoinst command server for job 5 at ws://1a81a2b0ff0f:20013/xBOCRMEQoRw0iLse/ws
# 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)
# 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:14566] Unrecognized referer 'localhost'
# 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)
[debug] [pid:14565] Updating seen of worker 1 from worker_status (working)
[debug] [pid:15136] REST-API call: POST http://localhost:9526/api/v1/jobs/5/status
[debug] [pid:14566] creating f41/844/68dbb276a03240907d0e7e500d.png
[debug] [pid:14566] creating 68d/7ac/83452b72555f8a6b386629f91f.png
[debug] [pid:15136] Upload concluded (up to boot)
# 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)
[debug] [pid:14566] Unrecognized referer 'localhost'
[debug] [pid:14566] Unrecognized referer 'localhost'
[debug] looking for "f41/844/.thumbs/68dbb276a03240907d0e7e500d.png" in [
"/home/squamata/project/test-results/fullstack/full-stack.d/openqa/images",
]
[debug] found bless({
path => "/home/squamata/project/test-results/fullstack/full-stack.d/openqa/images/f41/844/.thumbs/68dbb276a03240907d0e7e500d.png",
pid => 14566,
}, "Mojo::Asset::File")
[debug] looking for "68d/7ac/.thumbs/83452b72555f8a6b386629f91f.png" in [
"/home/squamata/project/test-results/fullstack/full-stack.d/openqa/images",
]
[debug] found bless({
path => "/home/squamata/project/test-results/fullstack/full-stack.d/openqa/images/68d/7ac/.thumbs/83452b72555f8a6b386629f91f.png",
pid => 14566,
}, "Mojo::Asset::File")
[debug] [pid:14643] connecting to os-autoinst command server for job 5 at ws://1a81a2b0ff0f:20013/xBOCRMEQoRw0iLse/ws
# Wait for jQuery successful: wait_for_result_panel: waiting for '(?^u:Result: passed)' (count 44 of 3240)
[info] [pid:15136] Isotovideo exit status: 0
[debug] [pid:15136] Stopping job 5 from http://localhost:9526: 00000005-tinycore-1-flavor-i386-Build1-core@coolone - reason: done
[debug] [pid:15136] REST-API call: POST http://localhost:9526/api/v1/jobs/5/status
[info] [pid:15136] +++ worker notes +++
[info] [pid:15136] End time: 2022-03-01 15:28:42
[info] [pid:15136] Result: done
[info] [pid:15352] Uploading video.ogv
[debug] [pid:15352] Uploading artefact video.ogv
[info] [pid:15352] Uploading vars.json
[debug] [pid:15352] Uploading artefact vars.json
[info] [pid:15352] Uploading autoinst-log.txt
[debug] [pid:15352] Uploading artefact autoinst-log.txt
[info] [pid:15352] Uploading worker-log.txt
[debug] [pid:15352] Uploading artefact worker-log.txt
[info] [pid:15352] Uploading serial0.txt
[debug] [pid:15352] Uploading artefact serial0.txt
[info] [pid:15352] Uploading video_time.vtt
[debug] [pid:15352] Uploading artefact video_time.vtt
[info] [pid:15352] Uploading serial_terminal.txt
[debug] [pid:15352] Uploading artefact serial_terminal.txt
[info] [pid:15352] Uploading virtio_console1.log
[debug] [pid:15352] Uploading artefact virtio_console1.log
[debug] [pid:15136] Considering job 5 as regularly done
[debug] [pid:15136] REST-API call: POST http://localhost:9526/api/v1/jobs/5/status
[debug] [pid:14566] creating e3b/43b/69c91fe4072dac1037f416c281.png
[debug] [pid:14566] creating e3b/43b/69c91fe4072dac1037f416c281.png
[debug] [pid:14566] creating 4ec/328/64be46d7336c00b3b3f4a5fe6d.png
[debug] [pid:15353] Optimizing /home/squamata/project/test-results/fullstack/full-stack.d/openqa/pool/1/testresults/shutdown-2.png
# Wait for jQuery successful: wait_for_result_panel: waiting for '(?^u:Result: passed)' (count 45 of 3240)
[debug] [pid:15353] Uploading artefact shutdown-2.png as 4ec32864be46d7336c00b3b3f4a5fe6d
[debug] [pid:15353] Optimizing /home/squamata/project/test-results/fullstack/full-stack.d/openqa/pool/1/testresults/.thumbs/shutdown-2.png
[debug] [pid:15353] Uploading artefact shutdown-2.png as 4ec32864be46d7336c00b3b3f4a5fe6d
[debug] [pid:15353] Optimizing /home/squamata/project/test-results/fullstack/full-stack.d/openqa/pool/1/testresults/assert_screen-2.png
[debug] [pid:15353] Uploading artefact assert_screen-2.png as e3b43b69c91fe4072dac1037f416c281
[debug] [pid:15353] Optimizing /home/squamata/project/test-results/fullstack/full-stack.d/openqa/pool/1/testresults/.thumbs/assert_screen-2.png
[debug] [pid:15353] Uploading artefact assert_screen-2.png as e3b43b69c91fe4072dac1037f416c281
[debug] [pid:15136] Upload concluded (no current module)
[debug] [pid:15136] REST-API call: POST http://localhost:9526/api/v1/jobs/5/set_done?worker_id=1
[debug] [pid:15136] Job 5 from http://localhost:9526 finished - reason: done
[debug] [pid:15136] Cleaning up for next job
# 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)
# Wait for jQuery successful: wait_for_result_panel: waiting for '(?^u:Result: passed)' (count 52 of 3240)
[debug] [pid:14566] Unrecognized referer 'localhost'
[debug] [pid:14566] Unrecognized referer 'localhost'
[debug] [pid:14566] Unrecognized referer 'localhost'
[debug] looking for "e3b/43b/.thumbs/69c91fe4072dac1037f416c281.png" in [
"/home/squamata/project/test-results/fullstack/full-stack.d/openqa/images",
]
[debug] found bless({
path => "/home/squamata/project/test-results/fullstack/full-stack.d/openqa/images/e3b/43b/.thumbs/69c91fe4072dac1037f416c281.png",
pid => 14566,
}, "Mojo::Asset::File")
[debug] looking for "4ec/328/.thumbs/64be46d7336c00b3b3f4a5fe6d.png" in [
"/home/squamata/project/test-results/fullstack/full-stack.d/openqa/images",
]
[debug] found bless({
path => "/home/squamata/project/test-results/fullstack/full-stack.d/openqa/images/4ec/328/.thumbs/64be46d7336c00b3b3f4a5fe6d.png",
pid => 14566,
}, "Mojo::Asset::File")
# Wait for jQuery successful: wait_for_result_panel: waiting for '(?^u:Result: passed)' (count 53 of 3240)
ok 5 - job 5 passed
[info] [pid:15136] Received signal TERM
[debug] [pid:15136] Informing http://localhost:9526 that we are going offline
[info] [pid:14565] 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:14566] 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:14566] Job 5 duplicated as 6
[warn] [pid:14566] Unable to wakeup scheduler: Connection refused
ok 9 - client returned new test_url for test 6
[debug] [pid:14566] Unrecognized referer 'localhost'
ok 10 - test 6 is scheduled
ok 11 - Worker started as IPC::Run=HASH(0x55741bfab6f0)
ok 12 - job with worker class qemu_i386 scheduled
[debug] [pid:14566] Unrecognized referer 'localhost'
[info] [pid:15361] worker 1:
- config file: /home/squamata/project/test-results/fullstack/full-stack.d/config/workers.ini
- worker hostname: 1a81a2b0ff0f
- isotovideo version: 25
- websocket API version: 1
- web UI hosts: http://localhost:9526
- class: qemu_i386,qemu_x86_64
- no cleanup: no
- pool directory: /home/squamata/project/test-results/fullstack/full-stack.d/openqa/pool/1
[info] [pid:15361] CACHE: caching is enabled, setting up /home/squamata/project/test-results/fullstack/full-stack.d/cache/localhost
[info] [pid:15361] Project dir for host http://localhost:9526 is /home/squamata/project/test-results/fullstack/full-stack.d/openqa/share
[info] [pid:15361] Registering with openQA http://localhost:9526
[info] [pid:15361] Establishing ws connection via ws://localhost:9526/api/v1/ws/1
[info] [pid:15361] Registered and connected via websockets with openQA host http://localhost:9526 and worker ID 1
[debug] [pid:14565] Updating seen of worker 1 from worker_status (free)
ok 13 - at least one free worker with class qemu_i386 registered
[debug] [pid:14560] +=----------------=+
[debug] [pid:14560] -> Scheduling new jobs.
[debug] [pid:14560] Free workers: 1/1
[debug] [pid:14560] Scheduled jobs: 1
[debug] [pid:14560] Need to schedule 1 parallel jobs for job 6 (with priority 50)
[debug] [pid:14560] Assigned job '6' to worker ID '1'
[debug] [pid:14560] [Job#6] Prepare for being processed by worker 1
[debug] [pid:14565] Started to send message to 1 for job(s) 6
[debug] [pid:14560] Sent job(s) '6' to worker '1'
[debug] [pid:14560] Scheduler took 0.08337s to perform operations and allocated 1 jobs
[debug] [pid:14560] Allocated: { job => 6, worker => 1 }
[debug] [pid:15361] Accepting job 6 from http://localhost:9526.
# Subtest: results of test 6
[debug] [pid:15361] Setting job 6 from http://localhost:9526 up
[debug] [pid:15361] Preparing Mojo::IOLoop::ReadWriteProcess::Session
[info] [pid:15361] +++ setup notes +++
[info] [pid:15361] Running on 1a81a2b0ff0f: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:15361] Job settings:
[debug] [pid:15361]
ARCH=i386
BUILD=1
CACHEDIRECTORY=/home/squamata/project/test-results/fullstack/full-stack.d/cache
CACHELIMIT=50
DISTRI=tinycore
FLAVOR=flavor
INTEGRATION_TESTS=1
ISO=Core-7.2.iso
JOBTOKEN=LSwqvyqaj4Ub2NPr
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=/home/squamata/project/test-results/fullstack/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:15361] Found ISO, caching Core-7.2.iso
[info] [pid:15361] Downloading Core-7.2.iso, request #2 sent to Cache Service
[debug] [pid:15361] Updating status so job 6 is not considered dead.
[debug] [pid:15361] REST-API call: POST http://localhost:9526/api/v1/jobs/6/status
[debug] [pid:14565] 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)
# Wait for jQuery successful: wait_for_result_panel: waiting for '(?^u:Result: passed)' (count 5 of 3240)
[debug] [pid:14566] Unrecognized referer 'localhost'
[debug] [pid:14566] Unrecognized referer 'localhost'
[debug] [pid:14566] 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:14566] Unrecognized referer 'localhost'
[debug] [pid:14566] Unrecognized referer 'localhost'
[debug] [pid:14566] 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 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:15361] Updating status so job 6 is not considered dead.
[debug] [pid:15361] REST-API call: POST http://localhost:9526/api/v1/jobs/6/status
[info] [pid:15361] Download of Core-7.2.iso processed
[debug] [pid:15361] Linked asset "/home/squamata/project/test-results/fullstack/full-stack.d/cache/localhost/Core-7.2.iso" to "/home/squamata/project/test-results/fullstack/full-stack.d/openqa/pool/1/Core-7.2.iso"
[debug] [pid:15361] Symlinked from "/home/squamata/project/test-results/fullstack/full-stack.d/openqa/share/tests/tinycore" to "/home/squamata/project/test-results/fullstack/full-stack.d/openqa/pool/1/tinycore"
[info] [pid:15361] Preparing cgroup to start isotovideo
[warn] [pid:15361] 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:15361] You can define a custom slice with OPENQA_CGROUP_SLICE or indicating the base mount with MOJO_CGROUP_FS.
[info] [pid:15361] Starting isotovideo container
[debug] [pid:15361] Registered process:15368
[info] [pid:15368] 15368: WORKING 6
[info] [pid:15361] isotovideo has been started (PID: 15368)
[debug] [pid:15368] +++ worker notes +++
[debug] [pid:15361] Running job 6 from http://localhost:9526: 00000006-tinycore-1-flavor-i386-Build1-core@coolone.
[debug] [pid:15361] REST-API call: POST http://localhost:9526/api/v1/jobs/6/status
[debug] [pid:14565] Updating seen of worker 1 from worker_status (working)
[debug] [pid:15361] 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)
# Wait for jQuery successful: wait_for_result_panel: waiting for '(?^u:Result: passed)' (count 14 of 3240)
[debug] [pid:14566] 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:14566] 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:15361] REST-API call: POST http://localhost:9526/api/v1/jobs/6/status
[debug] [pid:15361] 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:14566] Unrecognized referer 'localhost'
[debug] [pid:14566] Unrecognized referer 'localhost'
[debug] [pid:14643] connecting to os-autoinst command server for job 6 at ws://1a81a2b0ff0f:20013/LSwqvyqaj4Ub2NPr/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:14566] 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:14565] Updating seen of worker 1 from worker_status (working)
[debug] [pid:15361] 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 49 of 3240)
[debug] [pid:14566] creating f41/844/68dbb276a03240907d0e7e500d.png
[debug] [pid:14566] creating 68d/7ac/83452b72555f8a6b386629f91f.png
[debug] [pid:15361] 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:14566] Unrecognized referer 'localhost'
[debug] [pid:14566] Unrecognized referer 'localhost'
[debug] looking for "f41/844/.thumbs/68dbb276a03240907d0e7e500d.png" in [
"/home/squamata/project/test-results/fullstack/full-stack.d/openqa/images",
]
[debug] found bless({
path => "/home/squamata/project/test-results/fullstack/full-stack.d/openqa/images/f41/844/.thumbs/68dbb276a03240907d0e7e500d.png",
pid => 14566,
}, "Mojo::Asset::File")
[debug] looking for "68d/7ac/.thumbs/83452b72555f8a6b386629f91f.png" in [
"/home/squamata/project/test-results/fullstack/full-stack.d/openqa/images",
]
[debug] found bless({
path => "/home/squamata/project/test-results/fullstack/full-stack.d/openqa/images/68d/7ac/.thumbs/83452b72555f8a6b386629f91f.png",
pid => 14566,
}, "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)
# 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)
# 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:14566] Unrecognized referer 'localhost'
# 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)
# Wait for jQuery successful: wait_for_result_panel: waiting for '(?^u:Result: passed)' (count 68 of 3240)
[debug] [pid:15361] REST-API call: POST http://localhost:9526/api/v1/jobs/6/status
[debug] [pid:15361] Upload concluded (at shutdown)
# 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)
# 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)
[debug] [pid:14566] Unrecognized referer 'localhost'
# 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)
# 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)
[debug] [pid:14566] Unrecognized referer 'localhost'
# 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)
# Wait for jQuery successful: wait_for_result_panel: waiting for '(?^u:Result: passed)' (count 86 of 3240)
# Wait for jQuery successful: wait_for_result_panel: waiting for '(?^u:Result: passed)' (count 87 of 3240)
[debug] [pid:14565] Updating seen of worker 1 from worker_status (working)
[debug] [pid:15361] REST-API call: POST http://localhost:9526/api/v1/jobs/6/status
[debug] [pid:15361] Upload concluded (at shutdown)
# 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)
# 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)
[debug] [pid:14566] Unrecognized referer 'localhost'
# 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)
# 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)
[debug] [pid:14566] Unrecognized referer 'localhost'
# 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)
# 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)
[debug] [pid:15361] REST-API call: POST http://localhost:9526/api/v1/jobs/6/status
[debug] [pid:15361] Upload concluded (at shutdown)
# 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)
# 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)
[debug] [pid:14566] Unrecognized referer 'localhost'
# 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)
# 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)
[debug] [pid:14566] Unrecognized referer 'localhost'
# 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)
# Wait for jQuery successful: wait_for_result_panel: waiting for '(?^u:Result: passed)' (count 125 of 3240)
# Wait for jQuery successful: wait_for_result_panel: waiting for '(?^u:Result: passed)' (count 126 of 3240)
[debug] [pid:14565] Updating seen of worker 1 from worker_status (working)
# Wait for jQuery successful: wait_for_result_panel: waiting for '(?^u:Result: passed)' (count 127 of 3240)
[debug] [pid:15361] REST-API call: POST http://localhost:9526/api/v1/jobs/6/status
[debug] [pid:15361] Upload concluded (at shutdown)
# 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)
# 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)
[debug] [pid:14566] Unrecognized referer 'localhost'
# 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)
# 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)
[debug] [pid:14566] Unrecognized referer 'localhost'
# 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)
# 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)
[debug] [pid:15361] REST-API call: POST http://localhost:9526/api/v1/jobs/6/status
[debug] [pid:15361] Upload concluded (at shutdown)
# 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)
# 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)
[debug] [pid:14566] Unrecognized referer 'localhost'
# 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)
# 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)
[debug] [pid:14566] Unrecognized referer 'localhost'
# Wait for jQuery successful: wait_for_result_panel: waiting for '(?^u:Result: passed)' (count 162 of 3240)
# Wait for jQuery successful: wait_for_result_panel: waiting for '(?^u:Result: passed)' (count 163 of 3240)
# 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)
[debug] [pid:14565] Updating seen of worker 1 from worker_status (working)
# Wait for jQuery successful: wait_for_result_panel: waiting for '(?^u:Result: passed)' (count 166 of 3240)
[debug] [pid:15361] REST-API call: POST http://localhost:9526/api/v1/jobs/6/status
[debug] [pid:15361] Upload concluded (at shutdown)
# Wait for jQuery successful: wait_for_result_panel: waiting for '(?^u:Result: passed)' (count 167 of 3240)
# 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)
[debug] [pid:14566] Unrecognized referer 'localhost'
# 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)
# 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)
[debug] [pid:14566] Unrecognized referer 'localhost'
# 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)
# 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)
[debug] [pid:15361] REST-API call: POST http://localhost:9526/api/v1/jobs/6/status
[debug] [pid:15361] Upload concluded (at shutdown)
# Wait for jQuery successful: wait_for_result_panel: waiting for '(?^u:Result: passed)' (count 186 of 3240)
# 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)
[debug] [pid:14566] Unrecognized referer 'localhost'
# 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)
# 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:14566] Unrecognized referer 'localhost'
# 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)
# 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)
[debug] [pid:14565] Updating seen of worker 1 from worker_status (working)
# Wait for jQuery successful: wait_for_result_panel: waiting for '(?^u:Result: passed)' (count 205 of 3240)
[debug] [pid:15361] REST-API call: POST http://localhost:9526/api/v1/jobs/6/status
[debug] [pid:15361] Upload concluded (at shutdown)
# Wait for jQuery successful: wait_for_result_panel: waiting for '(?^u:Result: passed)' (count 206 of 3240)
# 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)
[debug] [pid:14566] Unrecognized referer 'localhost'
# 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)
# 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)
[debug] [pid:14566] Unrecognized referer 'localhost'
# 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)
[info] [pid:15361] Isotovideo exit status: 0
[debug] [pid:15361] Stopping job 6 from http://localhost:9526: 00000006-tinycore-1-flavor-i386-Build1-core@coolone - reason: done
[debug] [pid:15361] REST-API call: POST http://localhost:9526/api/v1/jobs/6/status
[info] [pid:15361] +++ worker notes +++
[info] [pid:15361] End time: 2022-03-01 15:30:47
[info] [pid:15361] Result: done
[info] [pid:15604] Uploading video.ogv
[debug] [pid:15604] Uploading artefact video.ogv
# Wait for jQuery successful: wait_for_result_panel: waiting for '(?^u:Result: passed)' (count 222 of 3240)
[info] [pid:15604] Uploading vars.json
[debug] [pid:15604] Uploading artefact vars.json
[info] [pid:15604] Uploading autoinst-log.txt
[debug] [pid:15604] Uploading artefact autoinst-log.txt
[info] [pid:15604] Uploading worker-log.txt
[debug] [pid:15604] Uploading artefact worker-log.txt
[info] [pid:15604] Uploading serial0.txt
[debug] [pid:15604] Uploading artefact serial0.txt
[info] [pid:15604] Uploading video_time.vtt
[debug] [pid:15604] Uploading artefact video_time.vtt
[info] [pid:15604] Uploading serial_terminal.txt
[debug] [pid:15604] Uploading artefact serial_terminal.txt
[info] [pid:15604] Uploading virtio_console1.log
[debug] [pid:15604] Uploading artefact virtio_console1.log
[debug] [pid:15361] Considering job 6 as regularly done
[debug] [pid:15361] REST-API call: POST http://localhost:9526/api/v1/jobs/6/status
[debug] [pid:14566] creating 68d/7ac/83452b72555f8a6b386629f91f.png
[debug] [pid:14566] creating 68d/7ac/83452b72555f8a6b386629f91f.png
[debug] [pid:14566] creating d95/4da/9d6d29536ba2b96c0092309cbb.png
[debug] [pid:15605] Optimizing /home/squamata/project/test-results/fullstack/full-stack.d/openqa/pool/1/testresults/shutdown-2.png
[debug] [pid:15605] Uploading artefact shutdown-2.png as d954da9d6d29536ba2b96c0092309cbb
[debug] [pid:15605] Optimizing /home/squamata/project/test-results/fullstack/full-stack.d/openqa/pool/1/testresults/.thumbs/shutdown-2.png
[debug] [pid:15605] Uploading artefact shutdown-2.png as d954da9d6d29536ba2b96c0092309cbb
[debug] [pid:15605] Uploading artefact shutdown-3.txt
[debug] [pid:15361] Upload concluded (no current module)
[debug] [pid:15361] REST-API call: POST http://localhost:9526/api/v1/jobs/6/set_done?worker_id=1
[debug] [pid:14566] checking take over from 5: GOOD vs shutdown:failed
[debug] [pid:14566] checking take over from 1: GOOD vs shutdown:failed
[debug] [pid:14566] ignoring job with repeated problem
[debug] [pid:15361] Job 6 from http://localhost:9526 finished - reason: done
[debug] [pid:15361] Cleaning up for next job
# 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)
# 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)
# Wait for jQuery successful: wait_for_result_panel: waiting for '(?^u:Result: passed)' (count 229 of 3240)
[debug] [pid:14566] Unrecognized referer 'localhost'
[debug] [pid:14566] Unrecognized referer 'localhost'
[debug] [pid:14566] Unrecognized referer 'localhost'
[debug] looking for "d95/4da/.thumbs/9d6d29536ba2b96c0092309cbb.png" in [
"/home/squamata/project/test-results/fullstack/full-stack.d/openqa/images",
]
[debug] found bless({
path => "/home/squamata/project/test-results/fullstack/full-stack.d/openqa/images/d95/4da/.thumbs/9d6d29536ba2b96c0092309cbb.png",
pid => 14566,
}, "Mojo::Asset::File")
# Wait for jQuery successful: wait_for_result_panel: waiting for '(?^u:Result: passed)' (count 230 of 3240)
ok 1 - No unexpected js warnings
not ok 2 - Expected result not found
not ok 3 - job 6 passed
# job info: {
# 'assigned_worker_id' => 1,
# 'blocked_by_id' => undef,
# 'clone_id' => undef,
# 'group_id' => undef,
# 'id' => 6,
# 'name' => 'tinycore-1-flavor-i386-Build1-core@coolone',
# 'origin_id' => 5,
# 'priority' => 50,
# 'result' => 'failed',
# 'settings' => {
# 'ARCH' => 'i386',
# 'BUILD' => '1',
# 'DISTRI' => 'tinycore',
# 'FLAVOR' => 'flavor',
# 'INTEGRATION_TESTS' => '1',
# 'ISO' => 'Core-7.2.iso',
# 'MACHINE' => 'coolone',
# 'NAME' => '00000006-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-03-01T15:30:47',
# 't_started' => '2022-03-01T15:28:52',
# 'test' => 'core'
# }
[info] [pid:15361] Received signal TERM
[debug] [pid:15361] Informing http://localhost:9526 that we are going offline
[info] [pid:14565] Worker 1 websocket connection closed - 1006
ok 4 - Test 6 autoinst-log.txt file created
ok 5 - asset 5.qcow2 removed during cache init
ok 6 - Core-7.2.iso the most recent asset again
1..6
not ok 14 - results of test 6
[debug] Restarting job 6
[debug] [pid:14566] Duplicating jobs: {
6 => {
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:14566] Job 6 duplicated as 7
[warn] [pid:14566] Unable to wakeup scheduler: Connection refused
ok 15 - client returned new test_url for test 7
[debug] [pid:14566] Unrecognized referer 'localhost'
ok 16 - test 7 is scheduled
ok 17 - Worker started as IPC::Run=HASH(0x5574267342f0)
[debug] [pid:14566] Unrecognized referer 'localhost'
ok 18 - job with worker class qemu_i386 scheduled
[info] [pid:15611] worker 1:
- config file: /home/squamata/project/test-results/fullstack/full-stack.d/config/workers.ini
- worker hostname: 1a81a2b0ff0f
- isotovideo version: 25
- websocket API version: 1
- web UI hosts: http://localhost:9526
- class: qemu_i386,qemu_x86_64
- no cleanup: no
- pool directory: /home/squamata/project/test-results/fullstack/full-stack.d/openqa/pool/1
[info] [pid:15611] CACHE: caching is enabled, setting up /home/squamata/project/test-results/fullstack/full-stack.d/cache/localhost
[info] [pid:15611] Project dir for host http://localhost:9526 is /home/squamata/project/test-results/fullstack/full-stack.d/openqa/share
[info] [pid:15611] Registering with openQA http://localhost:9526
[info] [pid:15611] Establishing ws connection via ws://localhost:9526/api/v1/ws/1
[info] [pid:15611] Registered and connected via websockets with openQA host http://localhost:9526 and worker ID 1
[debug] [pid:14565] Updating seen of worker 1 from worker_status (free)
ok 19 - at least one free worker with class qemu_i386 registered
[debug] [pid:14560] +=----------------=+
[debug] [pid:14560] -> Scheduling new jobs.
[debug] [pid:14560] Free workers: 1/1
[debug] [pid:14560] Scheduled jobs: 1
[debug] [pid:14560] Need to schedule 1 parallel jobs for job 7 (with priority 50)
[debug] [pid:14560] Assigned job '7' to worker ID '1'
[debug] [pid:14560] [Job#7] Prepare for being processed by worker 1
[debug] [pid:14565] Started to send message to 1 for job(s) 7
[debug] [pid:14560] Sent job(s) '7' to worker '1'
[debug] [pid:14560] Scheduler took 0.08196s to perform operations and allocated 1 jobs
[debug] [pid:15611] Accepting job 7 from http://localhost:9526.
[debug] [pid:14560] Allocated: { job => 7, worker => 1 }
# Subtest: results of test 7
[debug] [pid:15611] Setting job 7 from http://localhost:9526 up
[debug] [pid:15611] Preparing Mojo::IOLoop::ReadWriteProcess::Session
[info] [pid:15611] +++ setup notes +++
[info] [pid:15611] Running on 1a81a2b0ff0f: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:15611] Job settings:
[debug] [pid:15611]
ARCH=i386
BUILD=1
CACHEDIRECTORY=/home/squamata/project/test-results/fullstack/full-stack.d/cache
CACHELIMIT=50
DISTRI=tinycore
FLAVOR=flavor
INTEGRATION_TESTS=1
ISO=Core-7.2.iso
JOBTOKEN=gNLfIAyXupl3BtPb
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=/home/squamata/project/test-results/fullstack/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:15611] Found ISO, caching Core-7.2.iso
[info] [pid:15611] Downloading Core-7.2.iso, request #3 sent to Cache Service
[debug] [pid:15611] Updating status so job 7 is not considered dead.
[debug] [pid:15611] REST-API call: POST http://localhost:9526/api/v1/jobs/7/status
[debug] [pid:14565] 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)
# Wait for jQuery successful: wait_for_result_panel: waiting for '(?^u:Result: passed)' (count 5 of 3240)
[debug] [pid:14566] Unrecognized referer 'localhost'
[debug] [pid:14566] Unrecognized referer 'localhost'
[debug] [pid:14566] 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:14566] Unrecognized referer 'localhost'
[debug] [pid:14566] Unrecognized referer 'localhost'
[debug] [pid:14566] 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 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:15611] Updating status so job 7 is not considered dead.
[debug] [pid:15611] REST-API call: POST http://localhost:9526/api/v1/jobs/7/status
[info] [pid:15611] Download of Core-7.2.iso processed
[debug] [pid:15611] Linked asset "/home/squamata/project/test-results/fullstack/full-stack.d/cache/localhost/Core-7.2.iso" to "/home/squamata/project/test-results/fullstack/full-stack.d/openqa/pool/1/Core-7.2.iso"
[debug] [pid:15611] Symlinked from "/home/squamata/project/test-results/fullstack/full-stack.d/openqa/share/tests/tinycore" to "/home/squamata/project/test-results/fullstack/full-stack.d/openqa/pool/1/tinycore"
[info] [pid:15611] Preparing cgroup to start isotovideo
[warn] [pid:15611] 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:15611] You can define a custom slice with OPENQA_CGROUP_SLICE or indicating the base mount with MOJO_CGROUP_FS.
[info] [pid:15611] Starting isotovideo container
[debug] [pid:15611] Registered process:15619
[info] [pid:15619] 15619: WORKING 7
[debug] [pid:15619] +++ worker notes +++
[info] [pid:15611] isotovideo has been started (PID: 15619)
# Wait for jQuery successful: wait_for_result_panel: waiting for '(?^u:Result: passed)' (count 10 of 3240)
[debug] [pid:15611] Running job 7 from http://localhost:9526: 00000007-tinycore-1-flavor-i386-Build1-core@coolone.
[debug] [pid:15611] REST-API call: POST http://localhost:9526/api/v1/jobs/7/status
[debug] [pid:14565] Updating seen of worker 1 from worker_status (working)
[debug] [pid:15611] 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:14566] 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:14566] 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:15611] REST-API call: POST http://localhost:9526/api/v1/jobs/7/status
[debug] [pid:15611] 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:14566] Unrecognized referer 'localhost'
[debug] [pid:14566] Unrecognized referer 'localhost'
[debug] [pid:14643] connecting to os-autoinst command server for job 7 at ws://1a81a2b0ff0f:20013/gNLfIAyXupl3BtPb/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)
[debug] [pid:14566] Unrecognized referer 'localhost'
# 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)
[debug] [pid:14565] Updating seen of worker 1 from worker_status (working)
[debug] [pid:15611] REST-API call: POST http://localhost:9526/api/v1/jobs/7/status
[debug] [pid:14566] creating f41/844/68dbb276a03240907d0e7e500d.png
[debug] [pid:14566] creating e3b/43b/69c91fe4072dac1037f416c281.png
[debug] [pid:15611] Upload concluded (up to 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)
[info] [pid:15611] Isotovideo exit status: 0
[debug] [pid:15611] Stopping job 7 from http://localhost:9526: 00000007-tinycore-1-flavor-i386-Build1-core@coolone - reason: done
[debug] [pid:15611] REST-API call: POST http://localhost:9526/api/v1/jobs/7/status
[info] [pid:15611] +++ worker notes +++
[info] [pid:15611] End time: 2022-03-01 15:31:23
[info] [pid:15611] Result: done
[info] [pid:15840] Uploading video.ogv
[debug] [pid:15840] Uploading artefact video.ogv
[info] [pid:15840] Uploading vars.json
[debug] [pid:15840] Uploading artefact vars.json
[info] [pid:15840] Uploading autoinst-log.txt
[debug] [pid:15840] Uploading artefact autoinst-log.txt
[info] [pid:15840] Uploading worker-log.txt
[debug] [pid:15840] Uploading artefact worker-log.txt
[info] [pid:15840] Uploading serial0.txt
[debug] [pid:15840] Uploading artefact serial0.txt
[info] [pid:15840] Uploading video_time.vtt
[debug] [pid:15840] Uploading artefact video_time.vtt
# Wait for jQuery successful: wait_for_result_panel: waiting for '(?^u:Result: passed)' (count 53 of 3240)
[info] [pid:15840] Uploading serial_terminal.txt
[debug] [pid:15840] Uploading artefact serial_terminal.txt
[info] [pid:15840] Uploading virtio_console1.log
[debug] [pid:15840] Uploading artefact virtio_console1.log
[debug] [pid:15611] Considering job 7 as regularly done
[debug] [pid:15611] REST-API call: POST http://localhost:9526/api/v1/jobs/7/status
[debug] [pid:14566] creating e3b/43b/69c91fe4072dac1037f416c281.png
[debug] [pid:14566] creating e3b/43b/69c91fe4072dac1037f416c281.png
[debug] [pid:14566] creating 9a3/9ff/f3019996d3774d4fb9a634e520.png
[debug] [pid:15841] Optimizing /home/squamata/project/test-results/fullstack/full-stack.d/openqa/pool/1/testresults/shutdown-2.png
[debug] [pid:15841] Uploading artefact shutdown-2.png as 9a39fff3019996d3774d4fb9a634e520
[debug] [pid:15841] Optimizing /home/squamata/project/test-results/fullstack/full-stack.d/openqa/pool/1/testresults/.thumbs/shutdown-2.png
[debug] [pid:15841] Uploading artefact shutdown-2.png as 9a39fff3019996d3774d4fb9a634e520
[debug] [pid:15611] Upload concluded (no current module)
[debug] [pid:15611] REST-API call: POST http://localhost:9526/api/v1/jobs/7/set_done?worker_id=1
[debug] [pid:14566] Unrecognized referer 'localhost'
[debug] [pid:15611] Job 7 from http://localhost:9526 finished - reason: done
[debug] [pid:15611] Cleaning up for next job
[debug] [pid:14566] Unrecognized referer 'localhost'
[debug] [pid:14566] Unrecognized referer 'localhost'
# Wait for jQuery successful: wait_for_result_panel: waiting for '(?^u:Result: passed)' (count 54 of 3240)
[debug] looking for "e3b/43b/.thumbs/69c91fe4072dac1037f416c281.png" in [
"/home/squamata/project/test-results/fullstack/full-stack.d/openqa/images",
]
[debug] found bless({
path => "/home/squamata/project/test-results/fullstack/full-stack.d/openqa/images/e3b/43b/.thumbs/69c91fe4072dac1037f416c281.png",
pid => 14566,
}, "Mojo::Asset::File")
ok 1 - job 7 passed
ok 2 - Test 7 autoinst-log.txt file created
ok 3 - Test 7 has worker notes
ok 4 - setup notes present
ok 5 - uploaded autoinst-log
1..5
ok 20 - results of test 7
[debug] looking for "9a3/9ff/.thumbs/f3019996d3774d4fb9a634e520.png" in [
"/home/squamata/project/test-results/fullstack/full-stack.d/openqa/images",
]
[debug] found bless({
path => "/home/squamata/project/test-results/fullstack/full-stack.d/openqa/images/9a3/9ff/.thumbs/f3019996d3774d4fb9a634e520.png",
pid => 14566,
}, "Mojo::Asset::File")
[debug] looking for "f41/844/.thumbs/68dbb276a03240907d0e7e500d.png" in [
"/home/squamata/project/test-results/fullstack/full-stack.d/openqa/images",
]
[debug] found bless({
path => "/home/squamata/project/test-results/fullstack/full-stack.d/openqa/images/f41/844/.thumbs/68dbb276a03240907d0e7e500d.png",
pid => 14566,
}, "Mojo::Asset::File")
[warn] [pid:14566] 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:14560] +=----------------=+
[debug] [pid:14560] -> Scheduling new jobs.
[debug] [pid:14560] Free workers: 1/1
[debug] [pid:14560] Scheduled jobs: 1
[debug] [pid:14560] Need to schedule 1 parallel jobs for job 8 (with priority 50)
[debug] [pid:14560] Assigned job '8' to worker ID '1'
[debug] [pid:14560] [Job#8] Prepare for being processed by worker 1
[debug] [pid:14565] Started to send message to 1 for job(s) 8
[debug] [pid:14560] Sent job(s) '8' to worker '1'
[debug] [pid:14560] Scheduler took 0.09979s to perform operations and allocated 1 jobs
[debug] [pid:14560] Allocated: { job => 8, worker => 1 }
[debug] [pid:15611] Accepting job 8 from http://localhost:9526.
[debug] [pid:15611] Setting job 8 from http://localhost:9526 up
[debug] [pid:15611] Preparing Mojo::IOLoop::ReadWriteProcess::Session
[info] [pid:15611] +++ setup notes +++
[info] [pid:15611] Running on 1a81a2b0ff0f: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:15611] Job settings:
[debug] [pid:15611]
ARCH=i386
BUILD=1
CACHEDIRECTORY=/home/squamata/project/test-results/fullstack/full-stack.d/cache
CACHELIMIT=50
DISTRI=tinycore
FLAVOR=flavor
HDD_1=non-existent.qcow2
INTEGRATION_TESTS=1
ISO=Core-7.2.iso
JOBTOKEN=FyOb_mAEM1SQZfuT
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=/home/squamata/project/test-results/fullstack/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:15611] Found HDD_1, caching non-existent.qcow2
[info] [pid:15611] Downloading non-existent.qcow2, request #4 sent to Cache Service
[debug] [pid:15611] Updating status so job 8 is not considered dead.
[debug] [pid:15611] REST-API call: POST http://localhost:9526/api/v1/jobs/8/status
[debug] [pid:14566] Unrecognized referer 'localhost'
[debug] [pid:14565] Worker 1 accepted job 8
[debug] [pid:14566] Unrecognized referer 'localhost'
[debug] [pid:14566] Unrecognized referer 'localhost'
[debug] [pid:14566] Unrecognized referer 'localhost'
[debug] [pid:14566] Unrecognized referer 'localhost'
[debug] redirect to /assets/hdd/non-existent.qcow2
[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:14566] Unrecognized referer 'localhost'
[debug] [pid:14566] Asking the worker 1 to start providing livestream for job 8
# 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:15611] Updating status so job 8 is not considered dead.
[debug] [pid:15611] REST-API call: POST http://localhost:9526/api/v1/jobs/8/status
[info] [pid:15611] Download of non-existent.qcow2 processed
[error] [pid:15611] Failed to download non-existent.qcow2 to /home/squamata/project/test-results/fullstack/full-stack.d/cache/localhost/non-existent.qcow2
[error] [pid:15611] Unable to setup job 8: Failed to download non-existent.qcow2 to /home/squamata/project/test-results/fullstack/full-stack.d/cache/localhost/non-existent.qcow2
[debug] [pid:15611] Stopping job 8 from http://localhost:9526: 00000008-tinycore-1-flavor-i386-Build1-core@coolone - reason: setup failure
[debug] [pid:15611] REST-API call: POST http://localhost:9526/api/v1/jobs/8/status
[info] [pid:15611] +++ worker notes +++
[info] [pid:15611] End time: 2022-03-01 15:31:31
[info] [pid:15611] Result: setup failure
[info] [pid:15848] Uploading autoinst-log.txt
[debug] [pid:15848] Uploading artefact autoinst-log.txt
[debug] [pid:14566] Unrecognized referer 'localhost'
[info] [pid:15848] Uploading worker-log.txt
[debug] [pid:15848] Uploading artefact worker-log.txt
[debug] [pid:14566] Unrecognized referer 'localhost'
[debug] [pid:14566] Unrecognized referer 'localhost'
[debug] [pid:15611] Job 8 stopped as incomplete
[warn] [pid:15611] Unable to upload results of the job because no command server URL or worker ID have been set.
[debug] [pid:15611] Upload concluded (no current module)
[debug] [pid:15611] REST-API call: POST http://localhost:9526/api/v1/jobs/8/set_done?reason=cache+failure%3A+Failed+to+download+non-existent.qcow2+to+%2Fhome%2Fsquamata%2Fproject%2Ftest-results%2Ffullstack%2Ffull-stack.d%2Fcache%2Flocalhost%2Fnon-existent.qcow2&result=incomplete&worker_id=1
[debug] [pid:14566] 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:14566] Job 8 duplicated as 9
[debug] [pid:15611] Job 8 from http://localhost:9526 finished - reason: setup failure
[debug] [pid:15611] 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)
# Wait for jQuery successful: wait_for_result_panel: waiting for '(?^u:Result: incomplete)' (count 19 of 3240)
[debug] [pid:14566] Unrecognized referer 'localhost'
[debug] [pid:14566] Unrecognized referer 'localhost'
[debug] [pid:14566] Unrecognized referer 'localhost'
[debug] [pid:14566] Unrecognized referer 'localhost'
[debug] looking for "autoinst-log.txt" in [
"/home/squamata/project/test-results/fullstack/full-stack.d/openqa/testresults/00000/00000008-tinycore-1-flavor-i386-Build1-core\@coolone",
"/home/squamata/project/test-results/fullstack/full-stack.d/openqa/testresults/00000/00000008-tinycore-1-flavor-i386-Build1-core\@coolone/ulogs",
]
[debug] found bless({
path => "/home/squamata/project/test-results/fullstack/full-stack.d/openqa/testresults/00000/00000008-tinycore-1-flavor-i386-Build1-core\@coolone/autoinst-log.txt",
pid => 14566,
}, "Mojo::Asset::File")
# Wait for jQuery successful: wait_for_result_panel: waiting for '(?^u:Result: incomplete)' (count 20 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:15611] Received signal TERM
[debug] [pid:15611] Informing http://localhost:9526 that we are going offline
[info] [pid:14565] Worker 1 websocket connection closed - 1006
1..26
not ok 36 - Cache tests
ok 37 - no (unexpected) warnings (via done_testing)
1..37
# Cache minion worker stopped
# Worker cache service on port 9530 stopped
/home/squamata/project/test-results/fullstack/full-stack.d/openqa/testresults/00000/00000001-tinycore-1-flavor-i386-Build1-core@coolone/autoinst-log.txt:
[2022-03-01T15:27:09.229Z] [info] [pid:14649] +++ setup notes +++
[2022-03-01T15:27:09.229484Z] [info] [pid:14649] Running on 1a81a2b0ff0f:1 (Linux 5.11.0-1027-aws #30~20.04.1-Ubuntu SMP Thu Jan 13 11:46:53 UTC 2022 x86_64)
[2022-03-01T15:27:09.237109Z] [debug] [pid:14656] +++ worker notes +++
[2022-03-01T15:27:10.955510Z] [debug] Current version is d410cc0dd1aa541233ea295ddfbe1d94a78c33ad [interface v25]
[2022-03-01T15:27:10.963938Z] [debug] git hash in tinycore: d410cc0dd1aa541233ea295ddfbe1d94a78c33ad
[2022-03-01T15:27:11.052625Z] [debug] scheduling boot tests/boot.pm
[2022-03-01T15:27:11.053369Z] [debug] scheduling assert_screen tests/assert_screen.pm
[2022-03-01T15:27:11.054045Z] [debug] scheduling shutdown tests/shutdown.pm
[2022-03-01T15:27:11.059789Z] [info] cmdsrv: daemon reachable under http://*:20013/N503ZgOJZf1SW84y/
[2022-03-01T15:27:11.061762Z] [info] Listening at "http://0.0.0.0:20013"
Web application available at http://0.0.0.0:20013
[2022-03-01T15:27:11.062907Z] [debug] git hash in tinycore/needles: d410cc0dd1aa541233ea295ddfbe1d94a78c33ad
[2022-03-01T15:27:11.063012Z] [debug] init needles from tinycore/needles
[2022-03-01T15:27:11.064311Z] [debug] loaded 4 needles
[2022-03-01T15:27:11.066999Z] [debug] Blocking SIGCHLD and SIGTERM
[2022-03-01T15:27:11.266252Z] [debug] Unblocking SIGCHLD and SIGTERM
[2022-03-01T15:27:11.329222Z] [debug] 14656: channel_out 15, channel_in 14
[2022-03-01T15:27:11.329228Z] [debug] Blocking SIGCHLD and SIGTERM
[2022-03-01T15:27:11.466319Z] [debug] Unblocking SIGCHLD and SIGTERM
[2022-03-01T15:27:11.467932Z] [debug] 14735: cmdpipe 13, rsppipe 16
[2022-03-01T15:27:11.468019Z] [debug] started mgmt loop with pid 14735
[2022-03-01T15:27:11.665204Z] [debug] qemu version detected: 5.2.0
[2022-03-01T15:27:11.666399Z] [debug] running `/usr/bin/chattr +C /home/squamata/project/test-results/fullstack/full-stack.d/openqa/pool/1/raid`
[2022-03-01T15:27:11.672599Z] [debug] Fatal error in command `/usr/bin/chattr +C /home/squamata/project/test-results/fullstack/full-stack.d/openqa/pool/1/raid`: open3: exec of /usr/bin/chattr +C /home/squamata/project/test-results/fullstack/full-stack.d/openqa/pool/1/raid failed: No such file or directory at /usr/lib/perl5/vendor_perl/5.26.1/Mojo/IOLoop/ReadWriteProcess.pm line 127.
[2022-03-01T15:27:11.672679Z] [debug] Configuring storage controllers and block devices
[2022-03-01T15:27:11.673188Z] [debug] running `/usr/bin/qemu-img info --output=json /home/squamata/project/test-results/fullstack/full-stack.d/openqa/pool/1/Core-7.2.iso`
[2022-03-01T15:27:11.681483Z] [debug] Initializing block device images
[2022-03-01T15:27:11.681649Z] [debug] running `/usr/bin/qemu-img create -f qcow2 /home/squamata/project/test-results/fullstack/full-stack.d/openqa/pool/1/raid/hd0 10G`
[2022-03-01T15:27:11.690525Z] [debug] Formatting '/home/squamata/project/test-results/fullstack/full-stack.d/openqa/pool/1/raid/hd0', fmt=qcow2 cluster_size=65536 extended_l2=off compression_type=zlib size=10737418240 lazy_refcounts=off refcount_bits=16
[2022-03-01T15:27:11.690630Z] [debug] running `/usr/bin/qemu-img create -f qcow2 -F raw -b /home/squamata/project/test-results/fullstack/full-stack.d/openqa/pool/1/Core-7.2.iso /home/squamata/project/test-results/fullstack/full-stack.d/openqa/pool/1/raid/cd0-overlay0 11116544`
[2022-03-01T15:27:11.699957Z] [debug] Formatting '/home/squamata/project/test-results/fullstack/full-stack.d/openqa/pool/1/raid/cd0-overlay0', fmt=qcow2 cluster_size=65536 extended_l2=off compression_type=zlib size=11116544 backing_file=/home/squamata/project/test-results/fullstack/full-stack.d/openqa/pool/1/Core-7.2.iso backing_fmt=raw lazy_refcounts=off refcount_bits=16
[2022-03-01T15:27:11.700033Z] [debug] init_blockdev_images: Finished creating block devices
[2022-03-01T15:27:11.700960Z] [debug] starting: /usr/bin/qemu-system-i386 -only-migratable -chardev ringbuf,id=serial0,logfile=serial0,logappend=on -serial chardev:serial0 -audiodev none,id=snd0 -device intel-hda -device hda-output,audiodev=snd0 -m 1024 -netdev user,id=qanet0 -device virtio-net,netdev=qanet0,mac=52:54:00:12:34:56 -boot once=d -smp 1 -no-shutdown -vnc :91,share=force-shared -device virtio-serial -chardev pipe,id=virtio_console,path=virtio_console,logfile=virtio_console.log,logappend=on -device virtconsole,chardev=virtio_console,name=org.openqa.console.virtio_console -chardev pipe,id=virtio_console1,path=virtio_console1,logfile=virtio_console1.log,logappend=on -device virtconsole,chardev=virtio_console1,name=org.openqa.console.virtio_console1 -chardev socket,path=qmp_socket,server=on,wait=off,id=qmp_socket,logfile=qmp_socket.log,logappend=on -qmp chardev:qmp_socket -S -device virtio-scsi-pci,id=scsi0 -blockdev driver=file,node-name=hd0-file,filename=/home/squamata/project/test-results/fullstack/full-stack.d/openqa/pool/1/raid/hd0,cache.no-flush=on -blockdev driver=qcow2,node-name=hd0,file=hd0-file,cache.no-flush=on -device virtio-blk,id=hd0-device,drive=hd0,serial=hd0 -blockdev driver=file,node-name=cd0-overlay0-file,filename=/home/squamata/project/test-results/fullstack/full-stack.d/openqa/pool/1/raid/cd0-overlay0,cache.no-flush=on -blockdev driver=qcow2,node-name=cd0-overlay0,file=cd0-overlay0-file,cache.no-flush=on -device scsi-cd,id=cd0-device,drive=cd0-overlay0,serial=cd0
[2022-03-01T15:27:11.703941Z] [debug] Waiting for 0 attempts
[2022-03-01T15:27:12.704546Z] [debug] Waiting for 1 attempts
[2022-03-01T15:27:13.704925Z] [debug] Finished after 2 attempts
[2022-03-01T15:27:13.706840Z] [debug] Establishing VNC connection to localhost:5991
[2022-03-01T15:27:13.709311Z] [debug] pointer type 0 0 640 480 -257
[2022-03-01T15:27:13.709390Z] [debug] led state 0 1 1 -261
[2022-03-01T15:27:13.768908Z] [debug] Start CPU
[2022-03-01T15:27:13.769202Z] [debug] EVENT {"data":{"client":{"family":"ipv4","host":"127.0.0.1","service":"33102","websocket":false},"server":{"auth":"none","family":"ipv4","host":"0.0.0.0","service":"5991","websocket":false}},"event":"VNC_CONNECTED","timestamp":{"microseconds":707443,"seconds":1646148433}}
[2022-03-01T15:27:13.769300Z] [debug] EVENT {"data":{"client":{"family":"ipv4","host":"127.0.0.1","service":"33102","websocket":false},"server":{"auth":"none","family":"ipv4","host":"0.0.0.0","service":"5991","websocket":false}},"event":"VNC_INITIALIZED","timestamp":{"microseconds":708330,"seconds":1646148433}}
[2022-03-01T15:27:13.769366Z] [debug] EVENT {"event":"RESUME","timestamp":{"microseconds":769273,"seconds":1646148433}}
GOT GO

[2022-03-01T15:27:13.777576Z] [debug] QEMU: QEMU emulator version 5.2.0 (SUSE Linux Enterprise 15)
[2022-03-01T15:27:13.777632Z] [debug] QEMU: Copyright (c) 2003-2020 Fabrice Bellard and the QEMU Project developers
[2022-03-01T15:27:13.781214Z] [debug] Snapshots are supported
[2022-03-01T15:27:13.782063Z] [debug] ||| starting boot tests/boot.pm
[2022-03-01T15:27:13.783971Z] [debug] tests/boot.pm:9 called testapi::assert_screen
[2022-03-01T15:27:13.784254Z] [debug] <<< testapi::assert_screen(mustmatch="core", no_wait=1, timeout=15)
[2022-03-01T15:27:13.798123Z] [debug] no match: 14.9s, best candidate: boot-core (0.00)
[2022-03-01T15:27:13.898872Z] [debug] no change: 14.8s
[2022-03-01T15:27:13.905483Z] [debug] no match: 14.8s, best candidate: boot-core (0.00)
[2022-03-01T15:27:14.006180Z] [debug] no change: 14.7s
[2022-03-01T15:27:14.012824Z] [debug] no match: 14.7s, best candidate: boot-core (0.00)
[2022-03-01T15:27:14.113611Z] [debug] no change: 14.6s
[2022-03-01T15:27:14.120191Z] [debug] no match: 14.6s, best candidate: boot-core (0.00)
[2022-03-01T15:27:14.220961Z] [debug] no change: 14.5s
[2022-03-01T15:27:14.227566Z] [debug] no match: 14.5s, best candidate: boot-core (0.00)
[2022-03-01T15:27:14.402820Z] [debug] >>> testapi::_handle_found_needle: found boot-core, similarity 0.97 @ 1/74
[2022-03-01T15:27:14.403325Z] [debug] tests/boot.pm:10 called testapi::send_key
[2022-03-01T15:27:14.403442Z] [debug] <<< testapi::send_key(key="ret", do_wait=0, wait_screen_change=0)
[2022-03-01T15:27:14.672890Z] [debug] tests/boot.pm:14 called testapi::assert_screen
[2022-03-01T15:27:14.673060Z] [debug] <<< testapi::assert_screen(mustmatch="on_prompt", timeout=90)
[2022-03-01T15:27:15.334360Z] [debug] no match: 89.3s, best candidate: boot-on_prompt (0.00)
[2022-03-01T15:27:16.331508Z] [debug] no match: 88.3s, best candidate: boot-on_prompt (0.00)
[2022-03-01T15:27:17.331829Z] [debug] no match: 87.3s, best candidate: boot-on_prompt (0.00)
[2022-03-01T15:27:18.332935Z] [debug] no match: 86.3s, best candidate: boot-on_prompt (0.00)
[2022-03-01T15:27:19.374586Z] [debug] no match: 85.3s, best candidate: boot-on_prompt (0.00)
[2022-03-01T15:27:20.335169Z] [debug] no match: 84.3s, best candidate: boot-on_prompt (0.00)
[2022-03-01T15:27:21.335756Z] [debug] no match: 83.3s, best candidate: boot-on_prompt (0.00)
[2022-03-01T15:27:22.336941Z] [debug] no match: 82.3s, best candidate: boot-on_prompt (0.00)
[2022-03-01T15:27:23.337923Z] [debug] no match: 81.3s, best candidate: boot-on_prompt (0.00)
[2022-03-01T15:27:24.440512Z] [debug] >>> testapi::_handle_found_needle: found boot-on_prompt, similarity 1.00 @ 2/64
[2022-03-01T15:27:24.443024Z] [debug] ||| finished boot tests (runtime: 11 s)
[2022-03-01T15:27:24.444214Z] [debug] ||| starting assert_screen tests/assert_screen.pm
[2022-03-01T15:27:24.444847Z] [debug] tests/assert_screen.pm:9 called testapi::assert_screen
[2022-03-01T15:27:24.444974Z] [debug] <<< testapi::assert_screen(mustmatch="on_prompt", timeout=60)
[2022-03-01T15:27:25.399173Z] [debug] >>> testapi::_handle_found_needle: found boot-on_prompt, similarity 1.00 @ 2/64
[2022-03-01T15:27:25.399322Z] [debug] tests/assert_screen.pm:10 called testapi::assert_screen
[2022-03-01T15:27:25.399426Z] [debug] <<< testapi::assert_screen(mustmatch="on_prompt", timeout=30, no_wait=1)
[2022-03-01T15:27:25.460511Z] [debug] >>> testapi::_handle_found_needle: found boot-on_prompt, similarity 1.00 @ 2/64
[2022-03-01T15:27:25.465078Z] [debug] ||| finished assert_screen tests (runtime: 1 s)
[2022-03-01T15:27:25.466026Z] [debug] ||| starting shutdown tests/shutdown.pm
[2022-03-01T15:27:25.466526Z] [debug] isotovideo: pausing test execution of shutdown because we're supposed to pause at this test module
[2022-03-01T15:27:25.466904Z] [debug] tests/shutdown.pm:8 called testapi::enter_cmd
[2022-03-01T15:27:25.467067Z] [debug] <<< testapi::type_string(string="sudo poweroff", max_interval=250, wait_screen_changes=0, wait_still_screen=0, timeout=30, similarity_level=47)
[2022-03-01T15:27:25.467438Z] [debug] isotovideo: paused, so not passing backend_type_string to backend
[2022-03-01T15:27:27.724775Z] [debug] isotovideo: test execution will be resumed
[2022-03-01T15:27:27.725148Z] [debug] isotovideo: resuming, continue passing backend_type_string to backend
[2022-03-01T15:27:28.200614Z] [debug] tests/shutdown.pm:9 called testapi::assert_shutdown
[2022-03-01T15:27:28.200803Z] [debug] <<< testapi::check_shutdown(timeout=90)
[2022-03-01T15:27:28.201482Z] [debug] EVENT {"data":{"path":"\/machine\/peripheral-anon\/device[2]\/virtio-backend"},"event":"NIC_RX_FILTER_CHANGED","timestamp":{"microseconds":727712,"seconds":1646148445}}
[2022-03-01T15:27:28.201662Z] [debug] QEMU status is not 'shutdown', it is 'running'
[2022-03-01T15:27:29.203020Z] [debug] QEMU status is not 'shutdown', it is 'running'
[2022-03-01T15:27:30.204510Z] [debug] QEMU status is not 'shutdown', it is 'running'
[2022-03-01T15:27:31.205805Z] [debug] QEMU status is not 'shutdown', it is 'running'
[2022-03-01T15:27:32.207209Z] [debug] QEMU status is not 'shutdown', it is 'running'
[2022-03-01T15:27:33.208358Z] [debug] EVENT {"data":{"guest":true,"reason":"guest-shutdown"},"event":"SHUTDOWN","timestamp":{"microseconds":660515,"seconds":1646148452}}
[2022-03-01T15:27:33.208452Z] [debug] EVENT {"event":"STOP","timestamp":{"microseconds":661035,"seconds":1646148452}}
[2022-03-01T15:27:33.273069Z] [debug] ||| finished shutdown tests (runtime: 8 s)
[2022-03-01T15:27:33.274843Z] [debug] stopping autotest process 14665
[2022-03-01T15:27:33.278860Z] [debug] [autotest] process exited: 0
[2022-03-01T15:27:33.379237Z] [debug] done with autotest process
[2022-03-01T15:27:33.379616Z] [debug] stopping command server 14662 because test execution ended
[2022-03-01T15:27:33.379681Z] [debug] isotovideo: informing websocket clients before stopping command server: http://127.0.0.1:20013/N503ZgOJZf1SW84y/broadcast
[2022-03-01T15:27:33.392235Z] [debug] commands process exited: 0
[2022-03-01T15:27:33.492591Z] [debug] done with command server
[2022-03-01T15:27:33.492662Z] [debug] isotovideo done
[2022-03-01T15:27:33.493477Z] [debug] backend shutdown state: 1
[2022-03-01T15:27:33.494007Z] [info] ::: OpenQA::Qemu::Proc::save_state: Saving QEMU state to qemu_state.json
[2022-03-01T15:27:34.502307Z] [debug] Passing remaining frames to the video encoder
[2022-03-01T15:27:34.525427Z] [debug] Waiting for video encoder to finalize the video
[2022-03-01T15:27:34.525526Z] [debug] The built-in video encoder (pid 14805) terminated
[2022-03-01T15:27:34.526032Z] [debug] QEMU: qemu-system-i386: terminating on signal 15 from pid 14735 (/home/squamata/os-autoinst/isotovideo: backen)
[2022-03-01T15:27:34.526905Z] [debug] sending magic and exit
[2022-03-01T15:27:34.527141Z] [debug] received magic close
[2022-03-01T15:27:34.532401Z] [debug] backend process exited: 0
[2022-03-01T15:27:34.633897Z] [info] ::: backend::qemu::do_extract_assets: Extracting (?^u:^hd0$)
[2022-03-01T15:27:34.634042Z] [debug] running `nice ionice qemu-img convert -c -O qcow2 /home/squamata/project/test-results/fullstack/full-stack.d/openqa/pool/1/raid/hd0 assets_public/core-hdd.qcow2`
[2022-03-01T15:27:34.647756Z] [debug] running `qemu-img info --output=json assets_public/core-hdd.qcow2`
[2022-03-01T15:27:34.655708Z] [debug] stopping backend process 14735
[2022-03-01T15:27:34.655778Z] [debug] done with backend process
14656: EXIT 0
[2022-03-01T15:27:34.671886Z] [info] [pid:14649] Isotovideo exit status: 0
[2022-03-01T15:27:34.697495Z] [info] [pid:14649] +++ worker notes +++
[2022-03-01T15:27:34.697700Z] [info] [pid:14649] End time: 2022-03-01 15:27:34
[2022-03-01T15:27:34.697791Z] [info] [pid:14649] Result: done
[2022-03-01T15:27:34.700940Z] [info] [pid:14899] Uploading core-hdd.qcow2
[2022-03-01T15:27:34.757915Z] [info] [pid:14899] Uploading video.ogv
[2022-03-01T15:27:34.787594Z] [info] [pid:14899] Uploading vars.json
[2022-03-01T15:27:34.812971Z] [info] [pid:14899] Uploading autoinst-log.txt
/home/squamata/project/test-results/fullstack/full-stack.d/openqa/testresults/00000/00000001-tinycore-1-flavor-i386-Build1-core@coolone/serial0.txt:
/home/squamata/project/test-results/fullstack/full-stack.d/openqa/testresults/00000/00000001-tinycore-1-flavor-i386-Build1-core@coolone/serial_terminal.txt:
/home/squamata/project/test-results/fullstack/full-stack.d/openqa/testresults/00000/00000001-tinycore-1-flavor-i386-Build1-core@coolone/worker-log.txt:
[2022-03-01T15:27:09.228443Z] [debug] [pid:14649] Preparing Mojo::IOLoop::ReadWriteProcess::Session
[2022-03-01T15:27:09.229844Z] [debug] [pid:14649] Job settings:
[2022-03-01T15:27:09.230062Z] [debug] [pid:14649]
ARCH=i386
BUILD=1
DISTRI=tinycore
FLAVOR=flavor
INTEGRATION_TESTS=1
ISO=Core-7.2.iso
JOBTOKEN=N503ZgOJZf1SW84y
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=/home/squamata/project/test-results/fullstack/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-03-01T15:27:09.230864Z] [debug] [pid:14649] Linked asset "/home/squamata/project/test-results/fullstack/full-stack.d/openqa/share/factory/iso/Core-7.2.iso" to "/home/squamata/project/test-results/fullstack/full-stack.d/openqa/pool/1/Core-7.2.iso"
[2022-03-01T15:27:09.231374Z] [debug] [pid:14649] Symlinked from "/home/squamata/project/test-results/fullstack/full-stack.d/openqa/share/tests/tinycore" to "/home/squamata/project/test-results/fullstack/full-stack.d/openqa/pool/1/tinycore"
[2022-03-01T15:27:09.231790Z] [info] [pid:14649] Preparing cgroup to start isotovideo
[2022-03-01T15:27:09.233165Z] [warn] [pid:14649] 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-03-01T15:27:09.233356Z] [info] [pid:14649] You can define a custom slice with OPENQA_CGROUP_SLICE or indicating the base mount with MOJO_CGROUP_FS.
[2022-03-01T15:27:09.233802Z] [info] [pid:14649] Starting isotovideo container
[2022-03-01T15:27:09.236693Z] [debug] [pid:14649] Registered process:14656
[2022-03-01T15:27:09.236894Z] [info] [pid:14656] 14656: WORKING 1
[2022-03-01T15:27:09.237269Z] [info] [pid:14649] isotovideo has been started (PID: 14656)
[2022-03-01T15:27:09.237996Z] [debug] [pid:14649] Running job 1 from http://localhost:9526: 00000001-tinycore-1-flavor-i386-Build1-core@coolone.
[2022-03-01T15:27:09.240212Z] [debug] [pid:14649] REST-API call: POST http://localhost:9526/api/v1/jobs/1/status
[2022-03-01T15:27:09.295110Z] [debug] [pid:14649] Upload concluded (no current module)
[2022-03-01T15:27:11.973563Z] [debug] [pid:14649] Starting livelog
[2022-03-01T15:27:11.974910Z] [debug] [pid:14649] REST-API call: POST http://localhost:9526/api/v1/jobs/1/status
[2022-03-01T15:27:12.020603Z] [debug] [pid:14649] Upload concluded (no current module)
[2022-03-01T15:27:12.436468Z] [debug] [pid:14649] Stopping livelog
[2022-03-01T15:27:13.022362Z] [debug] [pid:14649] REST-API call: POST http://localhost:9526/api/v1/jobs/1/status
[2022-03-01T15:27:13.063471Z] [debug] [pid:14649] Upload concluded (no current module)
[2022-03-01T15:27:23.071523Z] [debug] [pid:14649] REST-API call: POST http://localhost:9526/api/v1/jobs/1/status
[2022-03-01T15:27:23.142145Z] [debug] [pid:14649] Upload concluded (at boot)
[2022-03-01T15:27:28.006665Z] [debug] [pid:14649] Starting livelog
[2022-03-01T15:27:28.008261Z] [debug] [pid:14649] REST-API call: POST http://localhost:9526/api/v1/jobs/1/status
[2022-03-01T15:27:28.161963Z] [debug] [pid:14880] Optimizing /home/squamata/project/test-results/fullstack/full-stack.d/openqa/pool/1/testresults/boot-2.png
[2022-03-01T15:27:28.233452Z] [debug] [pid:14880] Uploading artefact boot-2.png as 68d7ac83452b72555f8a6b386629f91f
[2022-03-01T15:27:28.277299Z] [debug] [pid:14880] Optimizing /home/squamata/project/test-results/fullstack/full-stack.d/openqa/pool/1/testresults/.thumbs/boot-2.png
[2022-03-01T15:27:28.282803Z] [debug] [pid:14880] Uploading artefact boot-2.png as 68d7ac83452b72555f8a6b386629f91f
[2022-03-01T15:27:28.313068Z] [debug] [pid:14880] Optimizing /home/squamata/project/test-results/fullstack/full-stack.d/openqa/pool/1/testresults/boot-1.png
[2022-03-01T15:27:28.424816Z] [debug] [pid:14880] Uploading artefact boot-1.png as f4184468dbb276a03240907d0e7e500d
[2022-03-01T15:27:28.453938Z] [debug] [pid:14880] Optimizing /home/squamata/project/test-results/fullstack/full-stack.d/openqa/pool/1/testresults/.thumbs/boot-1.png
[2022-03-01T15:27:28.459452Z] [debug] [pid:14880] Uploading artefact boot-1.png as f4184468dbb276a03240907d0e7e500d
[2022-03-01T15:27:28.495669Z] [debug] [pid:14649] Upload concluded (up to boot)
[2022-03-01T15:27:29.497358Z] [debug] [pid:14649] REST-API call: POST http://localhost:9526/api/v1/jobs/1/status
[2022-03-01T15:27:29.553123Z] [debug] [pid:14649] Upload concluded (at shutdown)
[2022-03-01T15:27:30.555680Z] [debug] [pid:14649] REST-API call: POST http://localhost:9526/api/v1/jobs/1/status
[2022-03-01T15:27:30.620044Z] [debug] [pid:14649] Upload concluded (at shutdown)
[2022-03-01T15:27:31.622858Z] [debug] [pid:14649] REST-API call: POST http://localhost:9526/api/v1/jobs/1/status
[2022-03-01T15:27:31.685025Z] [debug] [pid:14649] Upload concluded (at shutdown)
[2022-03-01T15:27:32.687655Z] [debug] [pid:14649] REST-API call: POST http://localhost:9526/api/v1/jobs/1/status
[2022-03-01T15:27:32.743610Z] [debug] [pid:14649] Upload concluded (at shutdown)
[2022-03-01T15:27:33.746664Z] [debug] [pid:14649] REST-API call: POST http://localhost:9526/api/v1/jobs/1/status
[2022-03-01T15:27:33.845274Z] [debug] [pid:14890] Optimizing /home/squamata/project/test-results/fullstack/full-stack.d/openqa/pool/1/testresults/shutdown-2.png
[2022-03-01T15:27:33.971007Z] [debug] [pid:14890] Uploading artefact shutdown-2.png as f1ed19aa4bfd65612d1d5fc58b221bf2
[2022-03-01T15:27:34.001948Z] [debug] [pid:14890] Optimizing /home/squamata/project/test-results/fullstack/full-stack.d/openqa/pool/1/testresults/.thumbs/shutdown-2.png
[2022-03-01T15:27:34.007432Z] [debug] [pid:14890] Uploading artefact shutdown-2.png as f1ed19aa4bfd65612d1d5fc58b221bf2
[2022-03-01T15:27:34.039275Z] [debug] [pid:14649] Upload concluded (up to shutdown)
[2022-03-01T15:27:34.672205Z] [debug] [pid:14649] Stopping job 1 from http://localhost:9526: 00000001-tinycore-1-flavor-i386-Build1-core@coolone - reason: done
[2022-03-01T15:27:34.672889Z] [debug] [pid:14649] REST-API call: POST http://localhost:9526/api/v1/jobs/1/status
[2022-03-01T15:27:34.700743Z] [info] [pid:14899] Uploading core-hdd.qcow2
[2022-03-01T15:27:34.701265Z] [info] [pid:14899] Uploading core-hdd.qcow2 using multiple chunks
[2022-03-01T15:27:34.702306Z] [info] [pid:14899] core-hdd.qcow2: local upload (no chunks needed)
[2022-03-01T15:27:34.757826Z] [info] [pid:14899] Uploading video.ogv
[2022-03-01T15:27:34.758251Z] [debug] [pid:14899] Uploading artefact video.ogv
[2022-03-01T15:27:34.787504Z] [info] [pid:14899] Uploading vars.json
[2022-03-01T15:27:34.787754Z] [debug] [pid:14899] Uploading artefact vars.json
[2022-03-01T15:27:34.812875Z] [info] [pid:14899] Uploading autoinst-log.txt
[2022-03-01T15:27:34.813132Z] [debug] [pid:14899] Uploading artefact autoinst-log.txt
[2022-03-01T15:27:34.838335Z] [info] [pid:14899] Uploading worker-log.txt
[2022-03-01T15:27:34.838595Z] [debug] [pid:14899] Uploading artefact worker-log.txt
/home/squamata/project/test-results/fullstack/full-stack.d/openqa/testresults/00000/00000004-tinycore-1-flavor-i386-Build1-core@noassets/autoinst-log.txt:
[2022-03-01T15:27:59.078967Z] [info] [pid:15121] +++ setup notes +++
[2022-03-01T15:27:59.079188Z] [info] [pid:15121] Running on 1a81a2b0ff0f:1 (Linux 5.11.0-1027-aws #30~20.04.1-Ubuntu SMP Thu Jan 13 11:46:53 UTC 2022 x86_64)
[2022-03-01T15:27:59.079944Z] [error] [pid:15121] HDD_1 handling Cannot find HDD_1 asset hdd/nihilist_disk.hda!
[2022-03-01T15:27:59.104173Z] [info] [pid:15121] +++ worker notes +++
[2022-03-01T15:27:59.104368Z] [info] [pid:15121] End time: 2022-03-01 15:27:59
[2022-03-01T15:27:59.104457Z] [info] [pid:15121] Result: setup failure
[2022-03-01T15:27:59.108536Z] [info] [pid:15127] Uploading autoinst-log.txt
/home/squamata/project/test-results/fullstack/full-stack.d/openqa/testresults/00000/00000004-tinycore-1-flavor-i386-Build1-core@noassets/worker-log.txt:
[2022-03-01T15:27:59.078551Z] [debug] [pid:15121] Preparing Mojo::IOLoop::ReadWriteProcess::Session
[2022-03-01T15:27:59.079430Z] [debug] [pid:15121] Job settings:
[2022-03-01T15:27:59.079566Z] [debug] [pid:15121]
ARCH=i386
BUILD=1
DISTRI=tinycore
FLAVOR=flavor
HDD_1=nihilist_disk.hda
INTEGRATION_TESTS=1
ISO=Core-7.2.iso
JOBTOKEN=Hi1Jbzdefw7ROxDn
LOG_LEVEL=debug
MACHINE=noassets
NAME=00000004-tinycore-1-flavor-i386-Build1-core@noassets
OPENQA_HOSTNAME=localhost:9526
OPENQA_URL=http://localhost:9526
PRJDIR=/home/squamata/project/test-results/fullstack/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-03-01T15:27:59.080074Z] [error] [pid:15121] Unable to setup job 4: Cannot find HDD_1 asset hdd/nihilist_disk.hda!
[2022-03-01T15:27:59.080212Z] [debug] [pid:15121] Stopping job 4 from http://localhost:9526: 00000004-tinycore-1-flavor-i386-Build1-core@noassets - reason: setup failure
[2022-03-01T15:27:59.080718Z] [debug] [pid:15121] REST-API call: POST http://localhost:9526/api/v1/jobs/4/status
[2022-03-01T15:27:59.108364Z] [info] [pid:15127] Uploading autoinst-log.txt
[2022-03-01T15:27:59.108827Z] [debug] [pid:15127] Uploading artefact autoinst-log.txt
[2022-03-01T15:27:59.140294Z] [info] [pid:15127] Uploading worker-log.txt
[2022-03-01T15:27:59.140542Z] [debug] [pid:15127] Uploading artefact worker-log.txt
/home/squamata/project/test-results/fullstack/full-stack.d/openqa/testresults/00000/00000005-tinycore-1-flavor-i386-Build1-core@coolone/autoinst-log.txt:
[2022-03-01T15:28:14.541361Z] [info] [pid:15136] +++ setup notes +++
[2022-03-01T15:28:14.541585Z] [info] [pid:15136] Running on 1a81a2b0ff0f:1 (Linux 5.11.0-1027-aws #30~20.04.1-Ubuntu SMP Thu Jan 13 11:46:53 UTC 2022 x86_64)
[2022-03-01T15:28:14.547990Z] [debug] [pid:15136] Found ISO, caching Core-7.2.iso
[2022-03-01T15:28:14.554353Z] [info] [pid:15136] Downloading Core-7.2.iso, request #1 sent to Cache Service
[2022-03-01T15:28:19.650276Z] [info] [pid:15136] Download of Core-7.2.iso processed
[2022-03-01T15:28:19.657805Z] [debug] [pid:15143] +++ worker notes +++
[2022-03-01T15:28:21.433498Z] [debug] Current version is d410cc0dd1aa541233ea295ddfbe1d94a78c33ad [interface v25]
[2022-03-01T15:28:21.442068Z] [debug] git hash in tinycore: d410cc0dd1aa541233ea295ddfbe1d94a78c33ad
[2022-03-01T15:28:21.526219Z] [debug] scheduling boot tests/boot.pm
[2022-03-01T15:28:21.526849Z] [debug] scheduling assert_screen tests/assert_screen.pm
[2022-03-01T15:28:21.527407Z] [debug] scheduling shutdown tests/shutdown.pm
[2022-03-01T15:28:21.533158Z] [info] cmdsrv: daemon reachable under http://*:20013/xBOCRMEQoRw0iLse/
[2022-03-01T15:28:21.535100Z] [info] Listening at "http://0.0.0.0:20013"
Web application available at http://0.0.0.0:20013
[2022-03-01T15:28:21.536252Z] [debug] git hash in tinycore/needles: d410cc0dd1aa541233ea295ddfbe1d94a78c33ad
[2022-03-01T15:28:21.536359Z] [debug] init needles from tinycore/needles
[2022-03-01T15:28:21.537644Z] [debug] loaded 4 needles
[2022-03-01T15:28:21.540046Z] [debug] Blocking SIGCHLD and SIGTERM
[2022-03-01T15:28:21.666316Z] [debug] Unblocking SIGCHLD and SIGTERM
[2022-03-01T15:28:21.736077Z] [debug] Blocking SIGCHLD and SIGTERM
[2022-03-01T15:28:21.736133Z] [debug] 15143: channel_out 15, channel_in 14
[2022-03-01T15:28:21.866438Z] [debug] Unblocking SIGCHLD and SIGTERM
[2022-03-01T15:28:21.867795Z] [debug] 15222: cmdpipe 13, rsppipe 16
[2022-03-01T15:28:21.867874Z] [debug] started mgmt loop with pid 15222
[2022-03-01T15:28:22.068146Z] [debug] qemu version detected: 5.2.0
[2022-03-01T15:28:22.069302Z] [debug] running `/usr/bin/chattr +C /home/squamata/project/test-results/fullstack/full-stack.d/openqa/pool/1/raid`
[2022-03-01T15:28:22.076155Z] [debug] Fatal error in command `/usr/bin/chattr +C /home/squamata/project/test-results/fullstack/full-stack.d/openqa/pool/1/raid`: open3: exec of /usr/bin/chattr +C /home/squamata/project/test-results/fullstack/full-stack.d/openqa/pool/1/raid failed: No such file or directory at /usr/lib/perl5/vendor_perl/5.26.1/Mojo/IOLoop/ReadWriteProcess.pm line 127.
[2022-03-01T15:28:22.076249Z] [debug] Configuring storage controllers and block devices
[2022-03-01T15:28:22.076783Z] [debug] running `/usr/bin/qemu-img info --output=json /home/squamata/project/test-results/fullstack/full-stack.d/openqa/pool/1/Core-7.2.iso`
[2022-03-01T15:28:22.085881Z] [debug] Initializing block device images
[2022-03-01T15:28:22.086082Z] [debug] running `/usr/bin/qemu-img create -f qcow2 /home/squamata/project/test-results/fullstack/full-stack.d/openqa/pool/1/raid/hd0 10G`
[2022-03-01T15:28:22.097301Z] [debug] Formatting '/home/squamata/project/test-results/fullstack/full-stack.d/openqa/pool/1/raid/hd0', fmt=qcow2 cluster_size=65536 extended_l2=off compression_type=zlib size=10737418240 lazy_refcounts=off refcount_bits=16
[2022-03-01T15:28:22.097412Z] [debug] running `/usr/bin/qemu-img create -f qcow2 -F raw -b /home/squamata/project/test-results/fullstack/full-stack.d/openqa/pool/1/Core-7.2.iso /home/squamata/project/test-results/fullstack/full-stack.d/openqa/pool/1/raid/cd0-overlay0 11116544`
[2022-03-01T15:28:22.108367Z] [debug] Formatting '/home/squamata/project/test-results/fullstack/full-stack.d/openqa/pool/1/raid/cd0-overlay0', fmt=qcow2 cluster_size=65536 extended_l2=off compression_type=zlib size=11116544 backing_file=/home/squamata/project/test-results/fullstack/full-stack.d/openqa/pool/1/Core-7.2.iso backing_fmt=raw lazy_refcounts=off refcount_bits=16
[2022-03-01T15:28:22.108462Z] [debug] init_blockdev_images: Finished creating block devices
[2022-03-01T15:28:22.109462Z] [debug] starting: /usr/bin/qemu-system-i386 -only-migratable -chardev ringbuf,id=serial0,logfile=serial0,logappend=on -serial chardev:serial0 -audiodev none,id=snd0 -device intel-hda -device hda-output,audiodev=snd0 -m 1024 -netdev user,id=qanet0 -device virtio-net,netdev=qanet0,mac=52:54:00:12:34:56 -boot once=d -smp 1 -no-shutdown -vnc :91,share=force-shared -device virtio-serial -chardev pipe,id=virtio_console,path=virtio_console,logfile=virtio_console.log,logappend=on -device virtconsole,chardev=virtio_console,name=org.openqa.console.virtio_console -chardev pipe,id=virtio_console1,path=virtio_console1,logfile=virtio_console1.log,logappend=on -device virtconsole,chardev=virtio_console1,name=org.openqa.console.virtio_console1 -chardev socket,path=qmp_socket,server=on,wait=off,id=qmp_socket,logfile=qmp_socket.log,logappend=on -qmp chardev:qmp_socket -S -device virtio-scsi-pci,id=scsi0 -blockdev driver=file,node-name=hd0-file,filename=/home/squamata/project/test-results/fullstack/full-stack.d/openqa/pool/1/raid/hd0,cache.no-flush=on -blockdev driver=qcow2,node-name=hd0,file=hd0-file,cache.no-flush=on -device virtio-blk,id=hd0-device,drive=hd0,serial=hd0 -blockdev driver=file,node-name=cd0-overlay0-file,filename=/home/squamata/project/test-results/fullstack/full-stack.d/openqa/pool/1/raid/cd0-overlay0,cache.no-flush=on -blockdev driver=qcow2,node-name=cd0-overlay0,file=cd0-overlay0-file,cache.no-flush=on -device scsi-cd,id=cd0-device,drive=cd0-overlay0,serial=cd0
[2022-03-01T15:28:22.113085Z] [debug] Waiting for 0 attempts
[2022-03-01T15:28:23.113726Z] [debug] Waiting for 1 attempts
[2022-03-01T15:28:24.114158Z] [debug] Finished after 2 attempts
[2022-03-01T15:28:24.116020Z] [debug] Establishing VNC connection to localhost:5991
[2022-03-01T15:28:24.118649Z] [debug] pointer type 0 0 640 480 -257
[2022-03-01T15:28:24.118739Z] [debug] led state 0 1 1 -261
[2022-03-01T15:28:24.178150Z] [debug] Start CPU
[2022-03-01T15:28:24.178439Z] [debug] EVENT {"data":{"client":{"family":"ipv4","host":"127.0.0.1","service":"34216","websocket":false},"server":{"auth":"none","family":"ipv4","host":"0.0.0.0","service":"5991","websocket":false}},"event":"VNC_CONNECTED","timestamp":{"microseconds":116652,"seconds":1646148504}}
[2022-03-01T15:28:24.178523Z] [debug] EVENT {"data":{"client":{"family":"ipv4","host":"127.0.0.1","service":"34216","websocket":false},"server":{"auth":"none","family":"ipv4","host":"0.0.0.0","service":"5991","websocket":false}},"event":"VNC_INITIALIZED","timestamp":{"microseconds":117578,"seconds":1646148504}}
[2022-03-01T15:28:24.178619Z] [debug] EVENT {"event":"RESUME","timestamp":{"microseconds":178548,"seconds":1646148504}}
GOT GO

[2022-03-01T15:28:24.188394Z] [debug] QEMU: QEMU emulator version 5.2.0 (SUSE Linux Enterprise 15)
[2022-03-01T15:28:24.188477Z] [debug] QEMU: Copyright (c) 2003-2020 Fabrice Bellard and the QEMU Project developers
[2022-03-01T15:28:24.192206Z] [debug] Snapshots are supported
[2022-03-01T15:28:24.193350Z] [debug] ||| starting boot tests/boot.pm
[2022-03-01T15:28:24.195311Z] [debug] tests/boot.pm:9 called testapi::assert_screen
[2022-03-01T15:28:24.195690Z] [debug] <<< testapi::assert_screen(mustmatch="core", no_wait=1, timeout=15)
[2022-03-01T15:28:24.209648Z] [debug] no match: 14.9s, best candidate: boot-core (0.00)
[2022-03-01T15:28:24.310484Z] [debug] no change: 14.8s
[2022-03-01T15:28:24.317100Z] [debug] no match: 14.8s, best candidate: boot-core (0.00)
[2022-03-01T15:28:24.417775Z] [debug] no change: 14.7s
[2022-03-01T15:28:24.425345Z] [debug] no match: 14.7s, best candidate: boot-core (0.00)
[2022-03-01T15:28:24.526186Z] [debug] no change: 14.6s
[2022-03-01T15:28:24.533631Z] [debug] no match: 14.6s, best candidate: boot-core (0.00)
[2022-03-01T15:28:24.634513Z] [debug] no change: 14.5s
[2022-03-01T15:28:24.643244Z] [debug] no match: 14.5s, best candidate: boot-core (0.00)
[2022-03-01T15:28:24.835218Z] [debug] >>> testapi::_handle_found_needle: found boot-core, similarity 0.97 @ 1/74
[2022-03-01T15:28:24.835839Z] [debug] tests/boot.pm:10 called testapi::send_key
[2022-03-01T15:28:24.835965Z] [debug] <<< testapi::send_key(key="ret", do_wait=0, wait_screen_change=0)
[2022-03-01T15:28:25.105712Z] [debug] tests/boot.pm:14 called testapi::assert_screen
[2022-03-01T15:28:25.105931Z] [debug] <<< testapi::assert_screen(mustmatch="on_prompt", timeout=90)
[2022-03-01T15:28:25.749547Z] [debug] no match: 89.3s, best candidate: boot-on_prompt (0.00)
[2022-03-01T15:28:26.746295Z] [debug] no match: 88.3s, best candidate: boot-on_prompt (0.00)
[2022-03-01T15:28:27.747325Z] [debug] no match: 87.3s, best candidate: boot-on_prompt (0.00)
[2022-03-01T15:28:28.747863Z] [debug] no match: 86.3s, best candidate: boot-on_prompt (0.00)
[2022-03-01T15:28:29.795464Z] [debug] no match: 85.3s, best candidate: boot-on_prompt (0.00)
[2022-03-01T15:28:30.750221Z] [debug] no match: 84.3s, best candidate: boot-on_prompt (0.00)
[2022-03-01T15:28:31.751191Z] [debug] no match: 83.3s, best candidate: boot-on_prompt (0.00)
[2022-03-01T15:28:32.751775Z] [debug] no match: 82.3s, best candidate: boot-on_prompt (0.00)
[2022-03-01T15:28:33.752762Z] [debug] no match: 81.3s, best candidate: boot-on_prompt (0.00)
[2022-03-01T15:28:34.855811Z] [debug] >>> testapi::_handle_found_needle: found boot-on_prompt, similarity 1.00 @ 2/64
[2022-03-01T15:28:34.858212Z] [debug] ||| finished boot tests (runtime: 10 s)
[2022-03-01T15:28:34.859262Z] [debug] ||| starting assert_screen tests/assert_screen.pm
[2022-03-01T15:28:34.859938Z] [debug] tests/assert_screen.pm:9 called testapi::assert_screen
[2022-03-01T15:28:34.860052Z] [debug] <<< testapi::assert_screen(mustmatch="on_prompt", timeout=60)
[2022-03-01T15:28:35.817101Z] [debug] >>> testapi::_handle_found_needle: found boot-on_prompt, similarity 1.00 @ 2/64
[2022-03-01T15:28:35.817262Z] [debug] tests/assert_screen.pm:10 called testapi::assert_screen
[2022-03-01T15:28:35.817412Z] [debug] <<< testapi::assert_screen(mustmatch="on_prompt", no_wait=1, timeout=30)
[2022-03-01T15:28:35.890203Z] [debug] >>> testapi::_handle_found_needle: found boot-on_prompt, similarity 1.00 @ 2/64
[2022-03-01T15:28:35.891158Z] [debug] ||| finished assert_screen tests (runtime: 1 s)
[2022-03-01T15:28:35.892732Z] [debug] ||| starting shutdown tests/shutdown.pm
[2022-03-01T15:28:35.893420Z] [debug] tests/shutdown.pm:8 called testapi::enter_cmd
[2022-03-01T15:28:35.893623Z] [debug] <<< testapi::type_string(string="sudo poweroff", max_interval=250, wait_screen_changes=0, wait_still_screen=0, timeout=30, similarity_level=47)
[2022-03-01T15:28:36.376751Z] [debug] tests/shutdown.pm:9 called testapi::assert_shutdown
[2022-03-01T15:28:36.376905Z] [debug] <<< testapi::check_shutdown(timeout=90)
[2022-03-01T15:28:36.377535Z] [debug] EVENT {"data":{"path":"\/machine\/peripheral-anon\/device[2]\/virtio-backend"},"event":"NIC_RX_FILTER_CHANGED","timestamp":{"microseconds":306964,"seconds":1646148516}}
[2022-03-01T15:28:36.377715Z] [debug] QEMU status is not 'shutdown', it is 'running'
[2022-03-01T15:28:37.379157Z] [debug] QEMU status is not 'shutdown', it is 'running'
[2022-03-01T15:28:38.380504Z] [debug] QEMU status is not 'shutdown', it is 'running'
[2022-03-01T15:28:39.381832Z] [debug] QEMU status is not 'shutdown', it is 'running'
[2022-03-01T15:28:40.383187Z] [debug] QEMU status is not 'shutdown', it is 'running'
[2022-03-01T15:28:41.384245Z] [debug] EVENT {"data":{"guest":true,"reason":"guest-shutdown"},"event":"SHUTDOWN","timestamp":{"microseconds":941742,"seconds":1646148520}}
[2022-03-01T15:28:41.384350Z] [debug] EVENT {"event":"STOP","timestamp":{"microseconds":942259,"seconds":1646148520}}
[2022-03-01T15:28:41.445396Z] [debug] ||| finished shutdown tests (runtime: 6 s)
[2022-03-01T15:28:41.447757Z] [debug] stopping autotest process 15152
[2022-03-01T15:28:41.451693Z] [debug] [autotest] process exited: 0
[2022-03-01T15:28:41.552082Z] [debug] done with autotest process
[2022-03-01T15:28:41.552476Z] [debug] stopping command server 15149 because test execution ended
[2022-03-01T15:28:41.552556Z] [debug] isotovideo: informing websocket clients before stopping command server: http://127.0.0.1:20013/xBOCRMEQoRw0iLse/broadcast
[2022-03-01T15:28:41.564725Z] [debug] commands process exited: 0
[2022-03-01T15:28:41.665135Z] [debug] done with command server
[2022-03-01T15:28:41.665206Z] [debug] isotovideo done
[2022-03-01T15:28:41.665856Z] [debug] backend shutdown state: 1
[2022-03-01T15:28:41.666273Z] [info] ::: OpenQA::Qemu::Proc::save_state: Saving QEMU state to qemu_state.json
[2022-03-01T15:28:42.677199Z] [debug] Passing remaining frames to the video encoder
[2022-03-01T15:28:42.700950Z] [debug] Waiting for video encoder to finalize the video
[2022-03-01T15:28:42.701026Z] [debug] The built-in video encoder (pid 15292) terminated
[2022-03-01T15:28:42.701511Z] [debug] QEMU: qemu-system-i386: terminating on signal 15 from pid 15222 (/home/squamata/os-autoinst/isotovideo: backen)
[2022-03-01T15:28:42.702392Z] [debug] sending magic and exit
[2022-03-01T15:28:42.702617Z] [debug] received magic close
[2022-03-01T15:28:42.707832Z] [debug] backend process exited: 0
[2022-03-01T15:28:42.808798Z] [debug] stopping backend process 15222
[2022-03-01T15:28:42.808871Z] [debug] done with backend process
15143: EXIT 0
[2022-03-01T15:28:42.823769Z] [info] [pid:15136] Isotovideo exit status: 0
[2022-03-01T15:28:42.852118Z] [info] [pid:15136] +++ worker notes +++
[2022-03-01T15:28:42.852329Z] [info] [pid:15136] End time: 2022-03-01 15:28:42
[2022-03-01T15:28:42.852419Z] [info] [pid:15136] Result: done
[2022-03-01T15:28:42.857221Z] [info] [pid:15352] Uploading video.ogv
[2022-03-01T15:28:42.895433Z] [info] [pid:15352] Uploading vars.json
[2022-03-01T15:28:42.923Z] [info] [pid:15352] Uploading autoinst-log.txt
/home/squamata/project/test-results/fullstack/full-stack.d/openqa/testresults/00000/00000005-tinycore-1-flavor-i386-Build1-core@coolone/serial0.txt:
/home/squamata/project/test-results/fullstack/full-stack.d/openqa/testresults/00000/00000005-tinycore-1-flavor-i386-Build1-core@coolone/serial_terminal.txt:
/home/squamata/project/test-results/fullstack/full-stack.d/openqa/testresults/00000/00000005-tinycore-1-flavor-i386-Build1-core@coolone/worker-log.txt:
[2022-03-01T15:28:14.540950Z] [debug] [pid:15136] Preparing Mojo::IOLoop::ReadWriteProcess::Session
[2022-03-01T15:28:14.541825Z] [debug] [pid:15136] Job settings:
[2022-03-01T15:28:14.541963Z] [debug] [pid:15136]
ARCH=i386
BUILD=1
CACHEDIRECTORY=/home/squamata/project/test-results/fullstack/full-stack.d/cache
CACHELIMIT=50
DISTRI=tinycore
FLAVOR=flavor
INTEGRATION_TESTS=1
ISO=Core-7.2.iso
JOBTOKEN=xBOCRMEQoRw0iLse
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=/home/squamata/project/test-results/fullstack/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-03-01T15:28:14.554583Z] [debug] [pid:15136] Updating status so job 5 is not considered dead.
[2022-03-01T15:28:14.555027Z] [debug] [pid:15136] REST-API call: POST http://localhost:9526/api/v1/jobs/5/status
[2022-03-01T15:28:19.606335Z] [debug] [pid:15136] Updating status so job 5 is not considered dead.
[2022-03-01T15:28:19.606931Z] [debug] [pid:15136] REST-API call: POST http://localhost:9526/api/v1/jobs/5/status
[2022-03-01T15:28:19.652444Z] [debug] [pid:15136] Linked asset "/home/squamata/project/test-results/fullstack/full-stack.d/cache/localhost/Core-7.2.iso" to "/home/squamata/project/test-results/fullstack/full-stack.d/openqa/pool/1/Core-7.2.iso"
[2022-03-01T15:28:19.652991Z] [debug] [pid:15136] Symlinked from "/home/squamata/project/test-results/fullstack/full-stack.d/openqa/share/tests/tinycore" to "/home/squamata/project/test-results/fullstack/full-stack.d/openqa/pool/1/tinycore"
[2022-03-01T15:28:19.653291Z] [info] [pid:15136] Preparing cgroup to start isotovideo
[2022-03-01T15:28:19.654411Z] [warn] [pid:15136] 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-03-01T15:28:19.654542Z] [info] [pid:15136] You can define a custom slice with OPENQA_CGROUP_SLICE or indicating the base mount with MOJO_CGROUP_FS.
[2022-03-01T15:28:19.654850Z] [info] [pid:15136] Starting isotovideo container
[2022-03-01T15:28:19.657251Z] [debug] [pid:15136] Registered process:15143
[2022-03-01T15:28:19.657572Z] [info] [pid:15143] 15143: WORKING 5
[2022-03-01T15:28:19.657700Z] [info] [pid:15136] isotovideo has been started (PID: 15143)
[2022-03-01T15:28:19.658332Z] [debug] [pid:15136] Running job 5 from http://localhost:9526: 00000005-tinycore-1-flavor-i386-Build1-core@coolone.
[2022-03-01T15:28:19.661006Z] [debug] [pid:15136] REST-API call: POST http://localhost:9526/api/v1/jobs/5/status
[2022-03-01T15:28:19.703636Z] [debug] [pid:15136] Upload concluded (no current module)
[2022-03-01T15:28:29.711523Z] [debug] [pid:15136] REST-API call: POST http://localhost:9526/api/v1/jobs/5/status
[2022-03-01T15:28:29.782955Z] [debug] [pid:15136] Upload concluded (at boot)
[2022-03-01T15:28:39.785165Z] [debug] [pid:15136] REST-API call: POST http://localhost:9526/api/v1/jobs/5/status
[2022-03-01T15:28:39.879622Z] [debug] [pid:15136] Upload concluded (up to boot)
[2022-03-01T15:28:42.824133Z] [debug] [pid:15136] Stopping job 5 from http://localhost:9526: 00000005-tinycore-1-flavor-i386-Build1-core@coolone - reason: done
[2022-03-01T15:28:42.824818Z] [debug] [pid:15136] REST-API call: POST http://localhost:9526/api/v1/jobs/5/status
[2022-03-01T15:28:42.857049Z] [info] [pid:15352] Uploading video.ogv
[2022-03-01T15:28:42.857524Z] [debug] [pid:15352] Uploading artefact video.ogv
[2022-03-01T15:28:42.895340Z] [info] [pid:15352] Uploading vars.json
[2022-03-01T15:28:42.895607Z] [debug] [pid:15352] Uploading artefact vars.json
[2022-03-01T15:28:42.922890Z] [info] [pid:15352] Uploading autoinst-log.txt
[2022-03-01T15:28:42.923161Z] [debug] [pid:15352] Uploading artefact autoinst-log.txt
[2022-03-01T15:28:42.949229Z] [info] [pid:15352] Uploading worker-log.txt
[2022-03-01T15:28:42.949481Z] [debug] [pid:15352] Uploading artefact worker-log.txt
/home/squamata/project/test-results/fullstack/full-stack.d/openqa/testresults/00000/00000006-tinycore-1-flavor-i386-Build1-core@coolone/autoinst-log.txt:
[2022-03-01T15:28:52.774469Z] [info] [pid:15361] +++ setup notes +++
[2022-03-01T15:28:52.774686Z] [info] [pid:15361] Running on 1a81a2b0ff0f:1 (Linux 5.11.0-1027-aws #30~20.04.1-Ubuntu SMP Thu Jan 13 11:46:53 UTC 2022 x86_64)
[2022-03-01T15:28:52.780628Z] [debug] [pid:15361] Found ISO, caching Core-7.2.iso
[2022-03-01T15:28:52.785263Z] [info] [pid:15361] Downloading Core-7.2.iso, request #2 sent to Cache Service
[2022-03-01T15:28:57.873152Z] [info] [pid:15361] Download of Core-7.2.iso processed
[2022-03-01T15:28:57.880425Z] [debug] [pid:15368] +++ worker notes +++
[2022-03-01T15:28:59.599032Z] [debug] Current version is d410cc0dd1aa541233ea295ddfbe1d94a78c33ad [interface v25]
[2022-03-01T15:28:59.607329Z] [debug] git hash in tinycore: d410cc0dd1aa541233ea295ddfbe1d94a78c33ad
[2022-03-01T15:28:59.694256Z] [debug] scheduling boot tests/boot.pm
[2022-03-01T15:28:59.694985Z] [debug] scheduling assert_screen tests/assert_screen.pm
[2022-03-01T15:28:59.695560Z] [debug] scheduling shutdown tests/shutdown.pm
[2022-03-01T15:28:59.701416Z] [info] cmdsrv: daemon reachable under http://*:20013/LSwqvyqaj4Ub2NPr/
[2022-03-01T15:28:59.703474Z] [info] Listening at "http://0.0.0.0:20013"
Web application available at http://0.0.0.0:20013
[2022-03-01T15:28:59.704838Z] [debug] git hash in tinycore/needles: d410cc0dd1aa541233ea295ddfbe1d94a78c33ad
[2022-03-01T15:28:59.704959Z] [debug] init needles from tinycore/needles
[2022-03-01T15:28:59.706350Z] [debug] loaded 4 needles
[2022-03-01T15:28:59.709085Z] [debug] Blocking SIGCHLD and SIGTERM
[2022-03-01T15:28:59.866684Z] [debug] Unblocking SIGCHLD and SIGTERM
[2022-03-01T15:28:59.970030Z] [debug] Blocking SIGCHLD and SIGTERM
[2022-03-01T15:28:59.970327Z] [debug] 15368: channel_out 15, channel_in 14
[2022-03-01T15:29:00.165912Z] [debug] Unblocking SIGCHLD and SIGTERM
[2022-03-01T15:29:00.167288Z] [debug] 15464: cmdpipe 13, rsppipe 16
[2022-03-01T15:29:00.167372Z] [debug] started mgmt loop with pid 15464
[2022-03-01T15:29:00.365410Z] [debug] qemu version detected: 5.2.0
[2022-03-01T15:29:00.366599Z] [debug] running `/usr/bin/chattr +C /home/squamata/project/test-results/fullstack/full-stack.d/openqa/pool/1/raid`
[2022-03-01T15:29:00.373084Z] [debug] Fatal error in command `/usr/bin/chattr +C /home/squamata/project/test-results/fullstack/full-stack.d/openqa/pool/1/raid`: open3: exec of /usr/bin/chattr +C /home/squamata/project/test-results/fullstack/full-stack.d/openqa/pool/1/raid failed: No such file or directory at /usr/lib/perl5/vendor_perl/5.26.1/Mojo/IOLoop/ReadWriteProcess.pm line 127.
[2022-03-01T15:29:00.373163Z] [debug] Configuring storage controllers and block devices
[2022-03-01T15:29:00.373661Z] [debug] running `/usr/bin/qemu-img info --output=json /home/squamata/project/test-results/fullstack/full-stack.d/openqa/pool/1/Core-7.2.iso`
[2022-03-01T15:29:00.381734Z] [debug] Initializing block device images
[2022-03-01T15:29:00.381906Z] [debug] running `/usr/bin/qemu-img create -f qcow2 /home/squamata/project/test-results/fullstack/full-stack.d/openqa/pool/1/raid/hd0 10G`
[2022-03-01T15:29:00.391091Z] [debug] Formatting '/home/squamata/project/test-results/fullstack/full-stack.d/openqa/pool/1/raid/hd0', fmt=qcow2 cluster_size=65536 extended_l2=off compression_type=zlib size=10737418240 lazy_refcounts=off refcount_bits=16
[2022-03-01T15:29:00.391230Z] [debug] running `/usr/bin/qemu-img create -f qcow2 -F raw -b /home/squamata/project/test-results/fullstack/full-stack.d/openqa/pool/1/Core-7.2.iso /home/squamata/project/test-results/fullstack/full-stack.d/openqa/pool/1/raid/cd0-overlay0 11116544`
[2022-03-01T15:29:00.401131Z] [debug] Formatting '/home/squamata/project/test-results/fullstack/full-stack.d/openqa/pool/1/raid/cd0-overlay0', fmt=qcow2 cluster_size=65536 extended_l2=off compression_type=zlib size=11116544 backing_file=/home/squamata/project/test-results/fullstack/full-stack.d/openqa/pool/1/Core-7.2.iso backing_fmt=raw lazy_refcounts=off refcount_bits=16
[2022-03-01T15:29:00.401220Z] [debug] init_blockdev_images: Finished creating block devices
[2022-03-01T15:29:00.402247Z] [debug] starting: /usr/bin/qemu-system-i386 -only-migratable -chardev ringbuf,id=serial0,logfile=serial0,logappend=on -serial chardev:serial0 -audiodev none,id=snd0 -device intel-hda -device hda-output,audiodev=snd0 -m 1024 -netdev user,id=qanet0 -device virtio-net,netdev=qanet0,mac=52:54:00:12:34:56 -boot once=d -smp 1 -no-shutdown -vnc :91,share=force-shared -device virtio-serial -chardev pipe,id=virtio_console,path=virtio_console,logfile=virtio_console.log,logappend=on -device virtconsole,chardev=virtio_console,name=org.openqa.console.virtio_console -chardev pipe,id=virtio_console1,path=virtio_console1,logfile=virtio_console1.log,logappend=on -device virtconsole,chardev=virtio_console1,name=org.openqa.console.virtio_console1 -chardev socket,path=qmp_socket,server=on,wait=off,id=qmp_socket,logfile=qmp_socket.log,logappend=on -qmp chardev:qmp_socket -S -device virtio-scsi-pci,id=scsi0 -blockdev driver=file,node-name=hd0-file,filename=/home/squamata/project/test-results/fullstack/full-stack.d/openqa/pool/1/raid/hd0,cache.no-flush=on -blockdev driver=qcow2,node-name=hd0,file=hd0-file,cache.no-flush=on -device virtio-blk,id=hd0-device,drive=hd0,serial=hd0 -blockdev driver=file,node-name=cd0-overlay0-file,filename=/home/squamata/project/test-results/fullstack/full-stack.d/openqa/pool/1/raid/cd0-overlay0,cache.no-flush=on -blockdev driver=qcow2,node-name=cd0-overlay0,file=cd0-overlay0-file,cache.no-flush=on -device scsi-cd,id=cd0-device,drive=cd0-overlay0,serial=cd0
[2022-03-01T15:29:00.405583Z] [debug] Waiting for 0 attempts
[2022-03-01T15:29:01.406221Z] [debug] Waiting for 1 attempts
[2022-03-01T15:29:02.406683Z] [debug] Finished after 2 attempts
[2022-03-01T15:29:02.408636Z] [debug] Establishing VNC connection to localhost:5991
[2022-03-01T15:29:02.411263Z] [debug] pointer type 0 0 640 480 -257
[2022-03-01T15:29:02.411344Z] [debug] led state 0 1 1 -261
[2022-03-01T15:29:02.470334Z] [debug] Start CPU
[2022-03-01T15:29:02.470607Z] [debug] EVENT {"data":{"client":{"family":"ipv4","host":"127.0.0.1","service":"34954","websocket":false},"server":{"auth":"none","family":"ipv4","host":"0.0.0.0","service":"5991","websocket":false}},"event":"VNC_CONNECTED","timestamp":{"microseconds":409318,"seconds":1646148542}}
[2022-03-01T15:29:02.470692Z] [debug] EVENT {"data":{"client":{"family":"ipv4","host":"127.0.0.1","service":"34954","websocket":false},"server":{"auth":"none","family":"ipv4","host":"0.0.0.0","service":"5991","websocket":false}},"event":"VNC_INITIALIZED","timestamp":{"microseconds":410269,"seconds":1646148542}}
[2022-03-01T15:29:02.470800Z] [debug] EVENT {"event":"RESUME","timestamp":{"microseconds":470729,"seconds":1646148542}}
GOT GO

[2022-03-01T15:29:02.478563Z] [debug] QEMU: QEMU emulator version 5.2.0 (SUSE Linux Enterprise 15)
[2022-03-01T15:29:02.478619Z] [debug] QEMU: Copyright (c) 2003-2020 Fabrice Bellard and the QEMU Project developers
[2022-03-01T15:29:02.481695Z] [debug] Snapshots are supported
[2022-03-01T15:29:02.482545Z] [debug] ||| starting boot tests/boot.pm
[2022-03-01T15:29:02.484051Z] [debug] tests/boot.pm:9 called testapi::assert_screen
[2022-03-01T15:29:02.484320Z] [debug] <<< testapi::assert_screen(mustmatch="core", no_wait=1, timeout=15)
[2022-03-01T15:29:02.498140Z] [debug] no match: 14.9s, best candidate: boot-core (0.00)
[2022-03-01T15:29:02.598832Z] [debug] no change: 14.8s
[2022-03-01T15:29:02.605435Z] [debug] no match: 14.8s, best candidate: boot-core (0.00)
[2022-03-01T15:29:02.706253Z] [debug] no change: 14.7s
[2022-03-01T15:29:02.712875Z] [debug] no match: 14.7s, best candidate: boot-core (0.00)
[2022-03-01T15:29:02.813722Z] [debug] no change: 14.6s
[2022-03-01T15:29:02.820322Z] [debug] no match: 14.6s, best candidate: boot-core (0.00)
[2022-03-01T15:29:02.921125Z] [debug] no change: 14.5s
[2022-03-01T15:29:02.927738Z] [debug] no match: 14.5s, best candidate: boot-core (0.00)
[2022-03-01T15:29:03.103892Z] [debug] >>> testapi::_handle_found_needle: found boot-core, similarity 0.97 @ 1/74
[2022-03-01T15:29:03.104449Z] [debug] tests/boot.pm:10 called testapi::send_key
[2022-03-01T15:29:03.104574Z] [debug] <<< testapi::send_key(key="ret", do_wait=0, wait_screen_change=0)
[2022-03-01T15:29:03.374065Z] [debug] tests/boot.pm:14 called testapi::assert_screen
[2022-03-01T15:29:03.374262Z] [debug] <<< testapi::assert_screen(mustmatch="on_prompt", timeout=90)
[2022-03-01T15:29:04.034027Z] [debug] no match: 89.3s, best candidate: boot-on_prompt (0.00)
[2022-03-01T15:29:05.032285Z] [debug] no match: 88.3s, best candidate: boot-on_prompt (0.00)
[2022-03-01T15:29:06.032704Z] [debug] no match: 87.3s, best candidate: boot-on_prompt (0.00)
[2022-03-01T15:29:07.033867Z] [debug] no match: 86.3s, best candidate: boot-on_prompt (0.00)
[2022-03-01T15:29:08.080548Z] [debug] no match: 85.3s, best candidate: boot-on_prompt (0.00)
[2022-03-01T15:29:09.035698Z] [debug] no match: 84.3s, best candidate: boot-on_prompt (0.00)
[2022-03-01T15:29:10.036939Z] [debug] no match: 83.3s, best candidate: boot-on_prompt (0.00)
[2022-03-01T15:29:11.038223Z] [debug] no match: 82.3s, best candidate: boot-on_prompt (0.00)
[2022-03-01T15:29:12.038472Z] [debug] no match: 81.3s, best candidate: boot-on_prompt (0.00)
[2022-03-01T15:29:13.168239Z] [debug] >>> testapi::_handle_found_needle: found boot-on_prompt, similarity 1.00 @ 2/64
[2022-03-01T15:29:13.171374Z] [debug] ||| finished boot tests (runtime: 11 s)
[2022-03-01T15:29:13.172403Z] [debug] ||| starting assert_screen tests/assert_screen.pm
[2022-03-01T15:29:13.173012Z] [debug] tests/assert_screen.pm:9 called testapi::assert_screen
[2022-03-01T15:29:13.173116Z] [debug] <<< testapi::assert_screen(mustmatch="on_prompt", timeout=60)
[2022-03-01T15:29:14.108212Z] [debug] >>> testapi::_handle_found_needle: found boot-on_prompt, similarity 1.00 @ 2/64
[2022-03-01T15:29:14.108359Z] [debug] tests/assert_screen.pm:10 called testapi::assert_screen
[2022-03-01T15:29:14.108466Z] [debug] <<< testapi::assert_screen(mustmatch="on_prompt", no_wait=1, timeout=30)
[2022-03-01T15:29:14.180362Z] [debug] >>> testapi::_handle_found_needle: found boot-on_prompt, similarity 1.00 @ 2/64
[2022-03-01T15:29:14.181608Z] [debug] ||| finished assert_screen tests (runtime: 1 s)
[2022-03-01T15:29:14.183218Z] [debug] ||| starting shutdown tests/shutdown.pm
[2022-03-01T15:29:14.183945Z] [debug] tests/shutdown.pm:8 called testapi::enter_cmd
[2022-03-01T15:29:14.184103Z] [debug] <<< testapi::type_string(string="sudo poweroff", max_interval=250, wait_screen_changes=0, wait_still_screen=0, timeout=30, similarity_level=47)
[2022-03-01T15:29:14.665497Z] [debug] tests/shutdown.pm:9 called testapi::assert_shutdown
[2022-03-01T15:29:14.665673Z] [debug] <<< testapi::check_shutdown(timeout=90)
[2022-03-01T15:29:14.666327Z] [debug] EVENT {"data":{"path":"\/machine\/peripheral-anon\/device[2]\/virtio-backend"},"event":"NIC_RX_FILTER_CHANGED","timestamp":{"microseconds":73946,"seconds":1646148554}}
[2022-03-01T15:29:14.666595Z] [debug] QEMU status is not 'shutdown', it is 'running'
[2022-03-01T15:29:15.667927Z] [debug] QEMU status is not 'shutdown', it is 'running'
[2022-03-01T15:29:16.669329Z] [debug] QEMU status is not 'shutdown', it is 'running'
[2022-03-01T15:29:17.670747Z] [debug] QEMU status is not 'shutdown', it is 'running'
[2022-03-01T15:29:18.672189Z] [debug] QEMU status is not 'shutdown', it is 'running'
[2022-03-01T15:29:19.673435Z] [debug] QEMU status is not 'shutdown', it is 'running'
[2022-03-01T15:29:20.674812Z] [debug] QEMU status is not 'shutdown', it is 'running'
[2022-03-01T15:29:21.676290Z] [debug] QEMU status is not 'shutdown', it is 'running'
[2022-03-01T15:29:22.677811Z] [debug] QEMU status is not 'shutdown', it is 'running'
[2022-03-01T15:29:23.679354Z] [debug] QEMU status is not 'shutdown', it is 'running'
[2022-03-01T15:29:24.680924Z] [debug] QEMU status is not 'shutdown', it is 'running'
[2022-03-01T15:29:25.682417Z] [debug] QEMU status is not 'shutdown', it is 'running'
[2022-03-01T15:29:26.683758Z] [debug] QEMU status is not 'shutdown', it is 'running'
[2022-03-01T15:29:27.685379Z] [debug] QEMU status is not 'shutdown', it is 'running'
[2022-03-01T15:29:28.686953Z] [debug] QEMU status is not 'shutdown', it is 'running'
[2022-03-01T15:29:29.688394Z] [debug] QEMU status is not 'shutdown', it is 'running'
[2022-03-01T15:29:30.689899Z] [debug] QEMU status is not 'shutdown', it is 'running'
[2022-03-01T15:29:31.691234Z] [debug] QEMU status is not 'shutdown', it is 'running'
[2022-03-01T15:29:32.692505Z] [debug] QEMU status is not 'shutdown', it is 'running'
[2022-03-01T15:29:33.693922Z] [debug] QEMU status is not 'shutdown', it is 'running'
[2022-03-01T15:29:34.695268Z] [debug] QEMU status is not 'shutdown', it is 'running'
[2022-03-01T15:29:35.696865Z] [debug] QEMU status is not 'shutdown', it is 'running'
[2022-03-01T15:29:36.698406Z] [debug] QEMU status is not 'shutdown', it is 'running'
[2022-03-01T15:29:37.699802Z] [debug] QEMU status is not 'shutdown', it is 'running'
[2022-03-01T15:29:38.701217Z] [debug] QEMU status is not 'shutdown', it is 'running'
[2022-03-01T15:29:39.702570Z] [debug] QEMU status is not 'shutdown', it is 'running'
[2022-03-01T15:29:40.703935Z] [debug] QEMU status is not 'shutdown', it is 'running'
[2022-03-01T15:29:41.705226Z] [debug] QEMU status is not 'shutdown', it is 'running'
[2022-03-01T15:29:42.706634Z] [debug] QEMU status is not 'shutdown', it is 'running'
[2022-03-01T15:29:43.708084Z] [debug] QEMU status is not 'shutdown', it is 'running'
[2022-03-01T15:29:44.709369Z] [debug] QEMU status is not 'shutdown', it is 'running'
[2022-03-01T15:29:45.710840Z] [debug] QEMU status is not 'shutdown', it is 'running'
[2022-03-01T15:29:46.712151Z] [debug] QEMU status is not 'shutdown', it is 'running'
[2022-03-01T15:29:47.713554Z] [debug] QEMU status is not 'shutdown', it is 'running'
[2022-03-01T15:29:48.715018Z] [debug] QEMU status is not 'shutdown', it is 'running'
[2022-03-01T15:29:49.716358Z] [debug] QEMU status is not 'shutdown', it is 'running'
[2022-03-01T15:29:50.717843Z] [debug] QEMU status is not 'shutdown', it is 'running'
[2022-03-01T15:29:51.719185Z] [debug] QEMU status is not 'shutdown', it is 'running'
[2022-03-01T15:29:52.720599Z] [debug] QEMU status is not 'shutdown', it is 'running'
[2022-03-01T15:29:53.721972Z] [debug] QEMU status is not 'shutdown', it is 'running'
[2022-03-01T15:29:54.723283Z] [debug] QEMU status is not 'shutdown', it is 'running'
[2022-03-01T15:29:55.724712Z] [debug] QEMU status is not 'shutdown', it is 'running'
[2022-03-01T15:29:56.726355Z] [debug] QEMU status is not 'shutdown', it is 'running'
[2022-03-01T15:29:57.727703Z] [debug] QEMU status is not 'shutdown', it is 'running'
[2022-03-01T15:29:58.729247Z] [debug] QEMU status is not 'shutdown', it is 'running'
[2022-03-01T15:29:59.730979Z] [debug] QEMU status is not 'shutdown', it is 'running'
[2022-03-01T15:30:00.732312Z] [debug] QEMU status is not 'shutdown', it is 'running'
[2022-03-01T15:30:01.733796Z] [debug] QEMU status is not 'shutdown', it is 'running'
[2022-03-01T15:30:02.735325Z] [debug] QEMU status is not 'shutdown', it is 'running'
[2022-03-01T15:30:03.736778Z] [debug] QEMU status is not 'shutdown', it is 'running'
[2022-03-01T15:30:04.738376Z] [debug] QEMU status is not 'shutdown', it is 'running'
[2022-03-01T15:30:05.739688Z] [debug] QEMU status is not 'shutdown', it is 'running'
[2022-03-01T15:30:06.741215Z] [debug] QEMU status is not 'shutdown', it is 'running'
[2022-03-01T15:30:07.742449Z] [debug] QEMU status is not 'shutdown', it is 'running'
[2022-03-01T15:30:08.743771Z] [debug] QEMU status is not 'shutdown', it is 'running'
[2022-03-01T15:30:09.745249Z] [debug] QEMU status is not 'shutdown', it is 'running'
[2022-03-01T15:30:10.746801Z] [debug] QEMU status is not 'shutdown', it is 'running'
[2022-03-01T15:30:11.748252Z] [debug] QEMU status is not 'shutdown', it is 'running'
[2022-03-01T15:30:12.749655Z] [debug] QEMU status is not 'shutdown', it is 'running'
[2022-03-01T15:30:13.751028Z] [debug] QEMU status is not 'shutdown', it is 'running'
[2022-03-01T15:30:14.752368Z] [debug] QEMU status is not 'shutdown', it is 'running'
[2022-03-01T15:30:15.753802Z] [debug] QEMU status is not 'shutdown', it is 'running'
[2022-03-01T15:30:16.755093Z] [debug] QEMU status is not 'shutdown', it is 'running'
[2022-03-01T15:30:17.756541Z] [debug] QEMU status is not 'shutdown', it is 'running'
[2022-03-01T15:30:18.757861Z] [debug] QEMU status is not 'shutdown', it is 'running'
[2022-03-01T15:30:19.759143Z] [debug] QEMU status is not 'shutdown', it is 'running'
[2022-03-01T15:30:20.760539Z] [debug] QEMU status is not 'shutdown', it is 'running'
[2022-03-01T15:30:21.761841Z] [debug] QEMU status is not 'shutdown', it is 'running'
[2022-03-01T15:30:22.763168Z] [debug] QEMU status is not 'shutdown', it is 'running'
[2022-03-01T15:30:23.764713Z] [debug] QEMU status is not 'shutdown', it is 'running'
[2022-03-01T15:30:24.766030Z] [debug] QEMU status is not 'shutdown', it is 'running'
[2022-03-01T15:30:25.767581Z] [debug] QEMU status is not 'shutdown', it is 'running'
[2022-03-01T15:30:26.769298Z] [debug] QEMU status is not 'shutdown', it is 'running'
[2022-03-01T15:30:27.770957Z] [debug] QEMU status is not 'shutdown', it is 'running'
[2022-03-01T15:30:28.772350Z] [debug] QEMU status is not 'shutdown', it is 'running'
[2022-03-01T15:30:29.774014Z] [debug] QEMU status is not 'shutdown', it is 'running'
[2022-03-01T15:30:30.775643Z] [debug] QEMU status is not 'shutdown', it is 'running'
[2022-03-01T15:30:31.777319Z] [debug] QEMU status is not 'shutdown', it is 'running'
[2022-03-01T15:30:32.778946Z] [debug] QEMU status is not 'shutdown', it is 'running'
[2022-03-01T15:30:33.780501Z] [debug] QEMU status is not 'shutdown', it is 'running'
[2022-03-01T15:30:34.782025Z] [debug] QEMU status is not 'shutdown', it is 'running'
[2022-03-01T15:30:35.783555Z] [debug] QEMU status is not 'shutdown', it is 'running'
[2022-03-01T15:30:36.785207Z] [debug] QEMU status is not 'shutdown', it is 'running'
[2022-03-01T15:30:37.786776Z] [debug] QEMU status is not 'shutdown', it is 'running'
[2022-03-01T15:30:38.788311Z] [debug] QEMU status is not 'shutdown', it is 'running'
[2022-03-01T15:30:39.789892Z] [debug] QEMU status is not 'shutdown', it is 'running'
[2022-03-01T15:30:40.791399Z] [debug] QEMU status is not 'shutdown', it is 'running'
[2022-03-01T15:30:41.792833Z] [debug] QEMU status is not 'shutdown', it is 'running'
[2022-03-01T15:30:42.794338Z] [debug] QEMU status is not 'shutdown', it is 'running'
[2022-03-01T15:30:43.795768Z] [debug] QEMU status is not 'shutdown', it is 'running'
[2022-03-01T15:30:44.797156Z] [debug] QEMU status is not 'shutdown', it is 'running'
[2022-03-01T15:30:45.863300Z] [info] ::: basetest::runtest: # Test died: Machine didn't shut down! at tinycore/tests/shutdown.pm line 9.
[2022-03-01T15:30:45.865418Z] [debug] ||| finished shutdown tests (runtime: 91 s)
[2022-03-01T15:30:45.865473Z] [debug] ||| post fail hooks runtime: 0 s
[2022-03-01T15:30:45.865763Z] [debug] stopping overall test execution after a fatal test failure
[2022-03-01T15:30:45.866743Z] [debug] stopping autotest process 15394
[2022-03-01T15:30:45.871122Z] [debug] [autotest] process exited: 0
[2022-03-01T15:30:45.971535Z] [debug] done with autotest process
[2022-03-01T15:30:45.971976Z] [debug] stopping command server 15391 because test execution ended
[2022-03-01T15:30:45.972048Z] [debug] isotovideo: informing websocket clients before stopping command server: http://127.0.0.1:20013/LSwqvyqaj4Ub2NPr/broadcast
[2022-03-01T15:30:45.985687Z] [debug] commands process exited: 0
[2022-03-01T15:30:46.086046Z] [debug] done with command server
[2022-03-01T15:30:46.086145Z] [debug] isotovideo done
[2022-03-01T15:30:46.086886Z] [debug] QEMU status is not 'shutdown', it is 'running'
[2022-03-01T15:30:46.087033Z] [debug] backend shutdown state:
[2022-03-01T15:30:46.087435Z] [info] ::: OpenQA::Qemu::Proc::save_state: Saving QEMU state to qemu_state.json
[2022-03-01T15:30:47.099097Z] [debug] Passing remaining frames to the video encoder
[2022-03-01T15:30:47.121523Z] [debug] Waiting for video encoder to finalize the video
[2022-03-01T15:30:47.121599Z] [debug] The built-in video encoder (pid 15534) terminated
[2022-03-01T15:30:47.122162Z] [debug] QEMU: qemu-system-i386: terminating on signal 15 from pid 15464 (/home/squamata/os-autoinst/isotovideo: backen)
[2022-03-01T15:30:47.123026Z] [debug] sending magic and exit
[2022-03-01T15:30:47.123251Z] [debug] received magic close
[2022-03-01T15:30:47.129273Z] [debug] backend process exited: 0
[2022-03-01T15:30:47.230218Z] [debug] stopping backend process 15464
[2022-03-01T15:30:47.230282Z] [debug] done with backend process
15368: EXIT 0
[2022-03-01T15:30:47.247081Z] [info] [pid:15361] Isotovideo exit status: 0
[2022-03-01T15:30:47.274431Z] [info] [pid:15361] +++ worker notes +++
[2022-03-01T15:30:47.274633Z] [info] [pid:15361] End time: 2022-03-01 15:30:47
[2022-03-01T15:30:47.274724Z] [info] [pid:15361] Result: done
[2022-03-01T15:30:47.279493Z] [info] [pid:15604] Uploading video.ogv
[2022-03-01T15:30:47.308157Z] [info] [pid:15604] Uploading vars.json
[2022-03-01T15:30:47.329606Z] [info] [pid:15604] Uploading autoinst-log.txt
/home/squamata/project/test-results/fullstack/full-stack.d/openqa/testresults/00000/00000006-tinycore-1-flavor-i386-Build1-core@coolone/serial0.txt:
/home/squamata/project/test-results/fullstack/full-stack.d/openqa/testresults/00000/00000006-tinycore-1-flavor-i386-Build1-core@coolone/serial_terminal.txt:
/home/squamata/project/test-results/fullstack/full-stack.d/openqa/testresults/00000/00000006-tinycore-1-flavor-i386-Build1-core@coolone/shutdown-3.txt:
# Test died: Machine didn't shut down! at tinycore/tests/shutdown.pm line 9.
/home/squamata/project/test-results/fullstack/full-stack.d/openqa/testresults/00000/00000006-tinycore-1-flavor-i386-Build1-core@coolone/worker-log.txt:
[2022-03-01T15:28:52.774038Z] [debug] [pid:15361] Preparing Mojo::IOLoop::ReadWriteProcess::Session
[2022-03-01T15:28:52.774924Z] [debug] [pid:15361] Job settings:
[2022-03-01T15:28:52.775060Z] [debug] [pid:15361]
ARCH=i386
BUILD=1
CACHEDIRECTORY=/home/squamata/project/test-results/fullstack/full-stack.d/cache
CACHELIMIT=50
DISTRI=tinycore
FLAVOR=flavor
INTEGRATION_TESTS=1
ISO=Core-7.2.iso
JOBTOKEN=LSwqvyqaj4Ub2NPr
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=/home/squamata/project/test-results/fullstack/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-03-01T15:28:52.785441Z] [debug] [pid:15361] Updating status so job 6 is not considered dead.
[2022-03-01T15:28:52.785855Z] [debug] [pid:15361] REST-API call: POST http://localhost:9526/api/v1/jobs/6/status
[2022-03-01T15:28:57.830995Z] [debug] [pid:15361] Updating status so job 6 is not considered dead.
[2022-03-01T15:28:57.831584Z] [debug] [pid:15361] REST-API call: POST http://localhost:9526/api/v1/jobs/6/status
[2022-03-01T15:28:57.875212Z] [debug] [pid:15361] Linked asset "/home/squamata/project/test-results/fullstack/full-stack.d/cache/localhost/Core-7.2.iso" to "/home/squamata/project/test-results/fullstack/full-stack.d/openqa/pool/1/Core-7.2.iso"
[2022-03-01T15:28:57.875620Z] [debug] [pid:15361] Symlinked from "/home/squamata/project/test-results/fullstack/full-stack.d/openqa/share/tests/tinycore" to "/home/squamata/project/test-results/fullstack/full-stack.d/openqa/pool/1/tinycore"
[2022-03-01T15:28:57.875916Z] [info] [pid:15361] Preparing cgroup to start isotovideo
[2022-03-01T15:28:57.877013Z] [warn] [pid:15361] 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-03-01T15:28:57.877140Z] [info] [pid:15361] You can define a custom slice with OPENQA_CGROUP_SLICE or indicating the base mount with MOJO_CGROUP_FS.
[2022-03-01T15:28:57.877467Z] [info] [pid:15361] Starting isotovideo container
[2022-03-01T15:28:57.879858Z] [debug] [pid:15361] Registered process:15368
[2022-03-01T15:28:57.880192Z] [info] [pid:15368] 15368: WORKING 6
[2022-03-01T15:28:57.880336Z] [info] [pid:15361] isotovideo has been started (PID: 15368)
[2022-03-01T15:28:57.880931Z] [debug] [pid:15361] Running job 6 from http://localhost:9526: 00000006-tinycore-1-flavor-i386-Build1-core@coolone.
[2022-03-01T15:28:57.883757Z] [debug] [pid:15361] REST-API call: POST http://localhost:9526/api/v1/jobs/6/status
[2022-03-01T15:28:57.927Z] [debug] [pid:15361] Upload concluded (no current module)
[2022-03-01T15:29:07.935327Z] [debug] [pid:15361] REST-API call: POST http://localhost:9526/api/v1/jobs/6/status
[2022-03-01T15:29:08.000222Z] [debug] [pid:15361] Upload concluded (at boot)
[2022-03-01T15:29:18.002975Z] [debug] [pid:15361] REST-API call: POST http://localhost:9526/api/v1/jobs/6/status
[2022-03-01T15:29:18.118955Z] [debug] [pid:15361] Upload concluded (up to boot)
[2022-03-01T15:29:28.127365Z] [debug] [pid:15361] REST-API call: POST http://localhost:9526/api/v1/jobs/6/status
[2022-03-01T15:29:28.177081Z] [debug] [pid:15361] Upload concluded (at shutdown)
[2022-03-01T15:29:38.179154Z] [debug] [pid:15361] REST-API call: POST http://localhost:9526/api/v1/jobs/6/status
[2022-03-01T15:29:38.233324Z] [debug] [pid:15361] Upload concluded (at shutdown)
[2022-03-01T15:29:48.243182Z] [debug] [pid:15361] REST-API call: POST http://localhost:9526/api/v1/jobs/6/status
[2022-03-01T15:29:48.292938Z] [debug] [pid:15361] Upload concluded (at shutdown)
[2022-03-01T15:29:58.294199Z] [debug] [pid:15361] REST-API call: POST http://localhost:9526/api/v1/jobs/6/status
[2022-03-01T15:29:58.345140Z] [debug] [pid:15361] Upload concluded (at shutdown)
[2022-03-01T15:30:08.356844Z] [debug] [pid:15361] REST-API call: POST http://localhost:9526/api/v1/jobs/6/status
[2022-03-01T15:30:08.407880Z] [debug] [pid:15361] Upload concluded (at shutdown)
[2022-03-01T15:30:18.409652Z] [debug] [pid:15361] REST-API call: POST http://localhost:9526/api/v1/jobs/6/status
[2022-03-01T15:30:18.459101Z] [debug] [pid:15361] Upload concluded (at shutdown)
[2022-03-01T15:30:28.467263Z] [debug] [pid:15361] REST-API call: POST http://localhost:9526/api/v1/jobs/6/status
[2022-03-01T15:30:28.518042Z] [debug] [pid:15361] Upload concluded (at shutdown)
[2022-03-01T15:30:38.520452Z] [debug] [pid:15361] REST-API call: POST http://localhost:9526/api/v1/jobs/6/status
[2022-03-01T15:30:38.570768Z] [debug] [pid:15361] Upload concluded (at shutdown)
[2022-03-01T15:30:47.247470Z] [debug] [pid:15361] Stopping job 6 from http://localhost:9526: 00000006-tinycore-1-flavor-i386-Build1-core@coolone - reason: done
[2022-03-01T15:30:47.248172Z] [debug] [pid:15361] REST-API call: POST http://localhost:9526/api/v1/jobs/6/status
[2022-03-01T15:30:47.279310Z] [info] [pid:15604] Uploading video.ogv
[2022-03-01T15:30:47.279787Z] [debug] [pid:15604] Uploading artefact video.ogv
[2022-03-01T15:30:47.308080Z] [info] [pid:15604] Uploading vars.json
[2022-03-01T15:30:47.308308Z] [debug] [pid:15604] Uploading artefact vars.json
[2022-03-01T15:30:47.329525Z] [info] [pid:15604] Uploading autoinst-log.txt
[2022-03-01T15:30:47.329746Z] [debug] [pid:15604] Uploading artefact autoinst-log.txt
[2022-03-01T15:30:47.351212Z] [info] [pid:15604] Uploading worker-log.txt
[2022-03-01T15:30:47.351432Z] [debug] [pid:15604] Uploading artefact worker-log.txt
/home/squamata/project/test-results/fullstack/full-stack.d/openqa/testresults/00000/00000007-tinycore-1-flavor-i386-Build1-core@coolone/autoinst-log.txt:
[2022-03-01T15:30:56.559708Z] [info] [pid:15611] +++ setup notes +++
[2022-03-01T15:30:56.560037Z] [info] [pid:15611] Running on 1a81a2b0ff0f:1 (Linux 5.11.0-1027-aws #30~20.04.1-Ubuntu SMP Thu Jan 13 11:46:53 UTC 2022 x86_64)
[2022-03-01T15:30:56.566905Z] [debug] [pid:15611] Found ISO, caching Core-7.2.iso
[2022-03-01T15:30:56.571854Z] [info] [pid:15611] Downloading Core-7.2.iso, request #3 sent to Cache Service
[2022-03-01T15:31:01.680996Z] [info] [pid:15611] Download of Core-7.2.iso processed
[2022-03-01T15:31:01.689267Z] [debug] [pid:15619] +++ worker notes +++
[2022-03-01T15:31:03.373118Z] [debug] Current version is d410cc0dd1aa541233ea295ddfbe1d94a78c33ad [interface v25]
[2022-03-01T15:31:03.381691Z] [debug] git hash in tinycore: d410cc0dd1aa541233ea295ddfbe1d94a78c33ad
[2022-03-01T15:31:03.465660Z] [debug] scheduling boot tests/boot.pm
[2022-03-01T15:31:03.466317Z] [debug] scheduling assert_screen tests/assert_screen.pm
[2022-03-01T15:31:03.466882Z] [debug] scheduling shutdown tests/shutdown.pm
[2022-03-01T15:31:03.472697Z] [info] cmdsrv: daemon reachable under http://*:20013/gNLfIAyXupl3BtPb/
[2022-03-01T15:31:03.474666Z] [info] Listening at "http://0.0.0.0:20013"
Web application available at http://0.0.0.0:20013
[2022-03-01T15:31:03.475997Z] [debug] git hash in tinycore/needles: d410cc0dd1aa541233ea295ddfbe1d94a78c33ad
[2022-03-01T15:31:03.476104Z] [debug] init needles from tinycore/needles
[2022-03-01T15:31:03.477380Z] [debug] loaded 4 needles
[2022-03-01T15:31:03.479651Z] [debug] Blocking SIGCHLD and SIGTERM
[2022-03-01T15:31:03.666208Z] [debug] Unblocking SIGCHLD and SIGTERM
[2022-03-01T15:31:03.735625Z] [debug] Blocking SIGCHLD and SIGTERM
[2022-03-01T15:31:03.735682Z] [debug] 15619: channel_out 15, channel_in 14
[2022-03-01T15:31:03.866553Z] [debug] Unblocking SIGCHLD and SIGTERM
[2022-03-01T15:31:03.867924Z] [debug] 15712: cmdpipe 13, rsppipe 16
[2022-03-01T15:31:03.868009Z] [debug] started mgmt loop with pid 15712
[2022-03-01T15:31:04.067087Z] [debug] qemu version detected: 5.2.0
[2022-03-01T15:31:04.068241Z] [debug] running `/usr/bin/chattr +C /home/squamata/project/test-results/fullstack/full-stack.d/openqa/pool/1/raid`
[2022-03-01T15:31:04.075384Z] [debug] Fatal error in command `/usr/bin/chattr +C /home/squamata/project/test-results/fullstack/full-stack.d/openqa/pool/1/raid`: open3: exec of /usr/bin/chattr +C /home/squamata/project/test-results/fullstack/full-stack.d/openqa/pool/1/raid failed: No such file or directory at /usr/lib/perl5/vendor_perl/5.26.1/Mojo/IOLoop/ReadWriteProcess.pm line 127.
[2022-03-01T15:31:04.075468Z] [debug] Configuring storage controllers and block devices
[2022-03-01T15:31:04.076003Z] [debug] running `/usr/bin/qemu-img info --output=json /home/squamata/project/test-results/fullstack/full-stack.d/openqa/pool/1/Core-7.2.iso`
[2022-03-01T15:31:04.084877Z] [debug] Initializing block device images
[2022-03-01T15:31:04.085062Z] [debug] running `/usr/bin/qemu-img create -f qcow2 /home/squamata/project/test-results/fullstack/full-stack.d/openqa/pool/1/raid/hd0 10G`
[2022-03-01T15:31:04.098487Z] [debug] Formatting '/home/squamata/project/test-results/fullstack/full-stack.d/openqa/pool/1/raid/hd0', fmt=qcow2 cluster_size=65536 extended_l2=off compression_type=zlib size=10737418240 lazy_refcounts=off refcount_bits=16
[2022-03-01T15:31:04.098599Z] [debug] running `/usr/bin/qemu-img create -f qcow2 -F raw -b /home/squamata/project/test-results/fullstack/full-stack.d/openqa/pool/1/Core-7.2.iso /home/squamata/project/test-results/fullstack/full-stack.d/openqa/pool/1/raid/cd0-overlay0 11116544`
[2022-03-01T15:31:04.109234Z] [debug] Formatting '/home/squamata/project/test-results/fullstack/full-stack.d/openqa/pool/1/raid/cd0-overlay0', fmt=qcow2 cluster_size=65536 extended_l2=off compression_type=zlib size=11116544 backing_file=/home/squamata/project/test-results/fullstack/full-stack.d/openqa/pool/1/Core-7.2.iso backing_fmt=raw lazy_refcounts=off refcount_bits=16
[2022-03-01T15:31:04.109321Z] [debug] init_blockdev_images: Finished creating block devices
[2022-03-01T15:31:04.110322Z] [debug] starting: /usr/bin/qemu-system-i386 -only-migratable -chardev ringbuf,id=serial0,logfile=serial0,logappend=on -serial chardev:serial0 -audiodev none,id=snd0 -device intel-hda -device hda-output,audiodev=snd0 -m 1024 -netdev user,id=qanet0 -device virtio-net,netdev=qanet0,mac=52:54:00:12:34:56 -boot once=d -smp 1 -no-shutdown -vnc :91,share=force-shared -device virtio-serial -chardev pipe,id=virtio_console,path=virtio_console,logfile=virtio_console.log,logappend=on -device virtconsole,chardev=virtio_console,name=org.openqa.console.virtio_console -chardev pipe,id=virtio_console1,path=virtio_console1,logfile=virtio_console1.log,logappend=on -device virtconsole,chardev=virtio_console1,name=org.openqa.console.virtio_console1 -chardev socket,path=qmp_socket,server=on,wait=off,id=qmp_socket,logfile=qmp_socket.log,logappend=on -qmp chardev:qmp_socket -S -device virtio-scsi-pci,id=scsi0 -blockdev driver=file,node-name=hd0-file,filename=/home/squamata/project/test-results/fullstack/full-stack.d/openqa/pool/1/raid/hd0,cache.no-flush=on -blockdev driver=qcow2,node-name=hd0,file=hd0-file,cache.no-flush=on -device virtio-blk,id=hd0-device,drive=hd0,serial=hd0 -blockdev driver=file,node-name=cd0-overlay0-file,filename=/home/squamata/project/test-results/fullstack/full-stack.d/openqa/pool/1/raid/cd0-overlay0,cache.no-flush=on -blockdev driver=qcow2,node-name=cd0-overlay0,file=cd0-overlay0-file,cache.no-flush=on -device scsi-cd,id=cd0-device,drive=cd0-overlay0,serial=cd0
[2022-03-01T15:31:04.113961Z] [debug] Waiting for 0 attempts
[2022-03-01T15:31:05.114570Z] [debug] Waiting for 1 attempts
[2022-03-01T15:31:06.114930Z] [debug] Finished after 2 attempts
[2022-03-01T15:31:06.116912Z] [debug] Establishing VNC connection to localhost:5991
[2022-03-01T15:31:06.119484Z] [debug] pointer type 0 0 640 480 -257
[2022-03-01T15:31:06.119568Z] [debug] led state 0 1 1 -261
[2022-03-01T15:31:06.178770Z] [debug] Start CPU
[2022-03-01T15:31:06.179040Z] [debug] EVENT {"data":{"client":{"family":"ipv4","host":"127.0.0.1","service":"36884","websocket":false},"server":{"auth":"none","family":"ipv4","host":"0.0.0.0","service":"5991","websocket":false}},"event":"VNC_CONNECTED","timestamp":{"microseconds":117515,"seconds":1646148666}}
[2022-03-01T15:31:06.179124Z] [debug] EVENT {"data":{"client":{"family":"ipv4","host":"127.0.0.1","service":"36884","websocket":false},"server":{"auth":"none","family":"ipv4","host":"0.0.0.0","service":"5991","websocket":false}},"event":"VNC_INITIALIZED","timestamp":{"microseconds":118436,"seconds":1646148666}}
[2022-03-01T15:31:06.179315Z] [debug] EVENT {"event":"RESUME","timestamp":{"microseconds":179246,"seconds":1646148666}}
GOT GO

[2022-03-01T15:31:06.187039Z] [debug] QEMU: QEMU emulator version 5.2.0 (SUSE Linux Enterprise 15)
[2022-03-01T15:31:06.187093Z] [debug] QEMU: Copyright (c) 2003-2020 Fabrice Bellard and the QEMU Project developers
[2022-03-01T15:31:06.190319Z] [debug] Snapshots are supported
[2022-03-01T15:31:06.191124Z] [debug] ||| starting boot tests/boot.pm
[2022-03-01T15:31:06.192559Z] [debug] tests/boot.pm:9 called testapi::assert_screen
[2022-03-01T15:31:06.192807Z] [debug] <<< testapi::assert_screen(mustmatch="core", no_wait=1, timeout=15)
[2022-03-01T15:31:06.206769Z] [debug] no match: 14.9s, best candidate: boot-core (0.00)
[2022-03-01T15:31:06.307577Z] [debug] no change: 14.8s
[2022-03-01T15:31:06.314231Z] [debug] no match: 14.8s, best candidate: boot-core (0.00)
[2022-03-01T15:31:06.414930Z] [debug] no change: 14.7s
[2022-03-01T15:31:06.421470Z] [debug] no match: 14.7s, best candidate: boot-core (0.00)
[2022-03-01T15:31:06.522166Z] [debug] no change: 14.6s
[2022-03-01T15:31:06.528763Z] [debug] no match: 14.6s, best candidate: boot-core (0.00)
[2022-03-01T15:31:06.629645Z] [debug] no change: 14.5s
[2022-03-01T15:31:06.636272Z] [debug] no match: 14.5s, best candidate: boot-core (0.00)
[2022-03-01T15:31:06.811647Z] [debug] >>> testapi::_handle_found_needle: found boot-core, similarity 0.97 @ 1/74
[2022-03-01T15:31:06.812270Z] [debug] tests/boot.pm:10 called testapi::send_key
[2022-03-01T15:31:06.812388Z] [debug] <<< testapi::send_key(key="ret", do_wait=0, wait_screen_change=0)
[2022-03-01T15:31:07.081859Z] [debug] tests/boot.pm:14 called testapi::assert_screen
[2022-03-01T15:31:07.082014Z] [debug] <<< testapi::assert_screen(mustmatch="on_prompt", timeout=90)
[2022-03-01T15:31:07.742475Z] [debug] no match: 89.3s, best candidate: boot-on_prompt (0.00)
[2022-03-01T15:31:08.740165Z] [debug] no match: 88.3s, best candidate: boot-on_prompt (0.00)
[2022-03-01T15:31:09.741412Z] [debug] no match: 87.3s, best candidate: boot-on_prompt (0.00)
[2022-03-01T15:31:10.742425Z] [debug] no match: 86.3s, best candidate: boot-on_prompt (0.00)
[2022-03-01T15:31:11.786061Z] [debug] no match: 85.3s, best candidate: boot-on_prompt (0.00)
[2022-03-01T15:31:12.744722Z] [debug] no match: 84.3s, best candidate: boot-on_prompt (0.00)
[2022-03-01T15:31:13.745716Z] [debug] no match: 83.3s, best candidate: boot-on_prompt (0.00)
[2022-03-01T15:31:14.746240Z] [debug] no match: 82.3s, best candidate: boot-on_prompt (0.00)
[2022-03-01T15:31:15.820112Z] [debug] >>> testapi::_handle_found_needle: found boot-on_prompt, similarity 1.00 @ 2/64
[2022-03-01T15:31:15.823409Z] [debug] ||| finished boot tests (runtime: 9 s)
[2022-03-01T15:31:15.824465Z] [debug] ||| starting assert_screen tests/assert_screen.pm
[2022-03-01T15:31:15.825078Z] [debug] tests/assert_screen.pm:9 called testapi::assert_screen
[2022-03-01T15:31:15.825174Z] [debug] <<< testapi::assert_screen(mustmatch="on_prompt", timeout=60)
[2022-03-01T15:31:16.807246Z] [debug] >>> testapi::_handle_found_needle: found boot-on_prompt, similarity 1.00 @ 2/64
[2022-03-01T15:31:16.807395Z] [debug] tests/assert_screen.pm:10 called testapi::assert_screen
[2022-03-01T15:31:16.807498Z] [debug] <<< testapi::assert_screen(mustmatch="on_prompt", no_wait=1, timeout=30)
[2022-03-01T15:31:16.884661Z] [debug] >>> testapi::_handle_found_needle: found boot-on_prompt, similarity 1.00 @ 2/64
[2022-03-01T15:31:16.885721Z] [debug] ||| finished assert_screen tests (runtime: 1 s)
[2022-03-01T15:31:16.887024Z] [debug] ||| starting shutdown tests/shutdown.pm
[2022-03-01T15:31:16.887541Z] [debug] tests/shutdown.pm:8 called testapi::enter_cmd
[2022-03-01T15:31:16.887688Z] [debug] <<< testapi::type_string(string="sudo poweroff", max_interval=250, wait_screen_changes=0, wait_still_screen=0, timeout=30, similarity_level=47)
[2022-03-01T15:31:17.361642Z] [debug] tests/shutdown.pm:9 called testapi::assert_shutdown
[2022-03-01T15:31:17.361783Z] [debug] <<< testapi::check_shutdown(timeout=90)
[2022-03-01T15:31:17.362563Z] [debug] QEMU status is not 'shutdown', it is 'running'
[2022-03-01T15:31:18.363771Z] [debug] QEMU status is not 'shutdown', it is 'running'
[2022-03-01T15:31:19.365286Z] [debug] QEMU status is not 'shutdown', it is 'running'
[2022-03-01T15:31:20.366765Z] [debug] QEMU status is not 'shutdown', it is 'running'
[2022-03-01T15:31:21.368311Z] [debug] QEMU status is not 'shutdown', it is 'running'
[2022-03-01T15:31:22.369522Z] [debug] EVENT {"data":{"guest":true,"reason":"guest-shutdown"},"event":"SHUTDOWN","timestamp":{"microseconds":967483,"seconds":1646148681}}
[2022-03-01T15:31:22.369621Z] [debug] EVENT {"event":"STOP","timestamp":{"microseconds":967989,"seconds":1646148681}}
[2022-03-01T15:31:22.429401Z] [debug] ||| finished shutdown tests (runtime: 6 s)
[2022-03-01T15:31:22.430814Z] [debug] stopping autotest process 15642
[2022-03-01T15:31:22.435352Z] [debug] [autotest] process exited: 0
[2022-03-01T15:31:22.535829Z] [debug] done with autotest process
[2022-03-01T15:31:22.536254Z] [debug] stopping command server 15639 because test execution ended
[2022-03-01T15:31:22.536331Z] [debug] isotovideo: informing websocket clients before stopping command server: http://127.0.0.1:20013/gNLfIAyXupl3BtPb/broadcast
[2022-03-01T15:31:22.548564Z] [debug] commands process exited: 0
[2022-03-01T15:31:22.648947Z] [debug] done with command server
[2022-03-01T15:31:22.649024Z] [debug] isotovideo done
[2022-03-01T15:31:22.649876Z] [debug] backend shutdown state: 1
[2022-03-01T15:31:22.650298Z] [info] ::: OpenQA::Qemu::Proc::save_state: Saving QEMU state to qemu_state.json
[2022-03-01T15:31:23.659290Z] [debug] Passing remaining frames to the video encoder
[2022-03-01T15:31:23.683456Z] [debug] Waiting for video encoder to finalize the video
[2022-03-01T15:31:23.683540Z] [debug] The built-in video encoder (pid 15782) terminated
[2022-03-01T15:31:23.684019Z] [debug] QEMU: qemu-system-i386: terminating on signal 15 from pid 15712 (/home/squamata/os-autoinst/isotovideo: backen)
[2022-03-01T15:31:23.684812Z] [debug] sending magic and exit
[2022-03-01T15:31:23.685105Z] [debug] received magic close
[2022-03-01T15:31:23.691150Z] [debug] backend process exited: 0
[2022-03-01T15:31:23.791990Z] [debug] stopping backend process 15712
[2022-03-01T15:31:23.792059Z] [debug] done with backend process
15619: EXIT 0
[2022-03-01T15:31:23.807176Z] [info] [pid:15611] Isotovideo exit status: 0
[2022-03-01T15:31:23.835781Z] [info] [pid:15611] +++ worker notes +++
[2022-03-01T15:31:23.836046Z] [info] [pid:15611] End time: 2022-03-01 15:31:23
[2022-03-01T15:31:23.836203Z] [info] [pid:15611] Result: done
[2022-03-01T15:31:23.842042Z] [info] [pid:15840] Uploading video.ogv
[2022-03-01T15:31:23.870221Z] [info] [pid:15840] Uploading vars.json
[2022-03-01T15:31:23.894449Z] [info] [pid:15840] Uploading autoinst-log.txt
/home/squamata/project/test-results/fullstack/full-stack.d/openqa/testresults/00000/00000007-tinycore-1-flavor-i386-Build1-core@coolone/serial0.txt:
/home/squamata/project/test-results/fullstack/full-stack.d/openqa/testresults/00000/00000007-tinycore-1-flavor-i386-Build1-core@coolone/serial_terminal.txt:
/home/squamata/project/test-results/fullstack/full-stack.d/openqa/testresults/00000/00000007-tinycore-1-flavor-i386-Build1-core@coolone/worker-log.txt:
[2022-03-01T15:30:56.559163Z] [debug] [pid:15611] Preparing Mojo::IOLoop::ReadWriteProcess::Session
[2022-03-01T15:30:56.560408Z] [debug] [pid:15611] Job settings:
[2022-03-01T15:30:56.560629Z] [debug] [pid:15611]
ARCH=i386
BUILD=1
CACHEDIRECTORY=/home/squamata/project/test-results/fullstack/full-stack.d/cache
CACHELIMIT=50
DISTRI=tinycore
FLAVOR=flavor
INTEGRATION_TESTS=1
ISO=Core-7.2.iso
JOBTOKEN=gNLfIAyXupl3BtPb
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=/home/squamata/project/test-results/fullstack/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-03-01T15:30:56.572091Z] [debug] [pid:15611] Updating status so job 7 is not considered dead.
[2022-03-01T15:30:56.572680Z] [debug] [pid:15611] REST-API call: POST http://localhost:9526/api/v1/jobs/7/status
[2022-03-01T15:31:01.638429Z] [debug] [pid:15611] Updating status so job 7 is not considered dead.
[2022-03-01T15:31:01.639086Z] [debug] [pid:15611] REST-API call: POST http://localhost:9526/api/v1/jobs/7/status
[2022-03-01T15:31:01.683017Z] [debug] [pid:15611] Linked asset "/home/squamata/project/test-results/fullstack/full-stack.d/cache/localhost/Core-7.2.iso" to "/home/squamata/project/test-results/fullstack/full-stack.d/openqa/pool/1/Core-7.2.iso"
[2022-03-01T15:31:01.683454Z] [debug] [pid:15611] Symlinked from "/home/squamata/project/test-results/fullstack/full-stack.d/openqa/share/tests/tinycore" to "/home/squamata/project/test-results/fullstack/full-stack.d/openqa/pool/1/tinycore"
[2022-03-01T15:31:01.683866Z] [info] [pid:15611] Preparing cgroup to start isotovideo
[2022-03-01T15:31:01.685323Z] [warn] [pid:15611] 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-03-01T15:31:01.685499Z] [info] [pid:15611] You can define a custom slice with OPENQA_CGROUP_SLICE or indicating the base mount with MOJO_CGROUP_FS.
[2022-03-01T15:31:01.685917Z] [info] [pid:15611] Starting isotovideo container
[2022-03-01T15:31:01.688782Z] [debug] [pid:15611] Registered process:15619
[2022-03-01T15:31:01.689035Z] [info] [pid:15619] 15619: WORKING 7
[2022-03-01T15:31:01.689364Z] [info] [pid:15611] isotovideo has been started (PID: 15619)
[2022-03-01T15:31:01.690135Z] [debug] [pid:15611] Running job 7 from http://localhost:9526: 00000007-tinycore-1-flavor-i386-Build1-core@coolone.
[2022-03-01T15:31:01.693163Z] [debug] [pid:15611] REST-API call: POST http://localhost:9526/api/v1/jobs/7/status
[2022-03-01T15:31:01.735180Z] [debug] [pid:15611] Upload concluded (no current module)
[2022-03-01T15:31:11.746679Z] [debug] [pid:15611] REST-API call: POST http://localhost:9526/api/v1/jobs/7/status
[2022-03-01T15:31:11.811701Z] [debug] [pid:15611] Upload concluded (at boot)
[2022-03-01T15:31:21.813737Z] [debug] [pid:15611] REST-API call: POST http://localhost:9526/api/v1/jobs/7/status
[2022-03-01T15:31:21.913156Z] [debug] [pid:15611] Upload concluded (up to boot)
[2022-03-01T15:31:23.807647Z] [debug] [pid:15611] Stopping job 7 from http://localhost:9526: 00000007-tinycore-1-flavor-i386-Build1-core@coolone - reason: done
[2022-03-01T15:31:23.808676Z] [debug] [pid:15611] REST-API call: POST http://localhost:9526/api/v1/jobs/7/status
[2022-03-01T15:31:23.841884Z] [info] [pid:15840] Uploading video.ogv
[2022-03-01T15:31:23.842361Z] [debug] [pid:15840] Uploading artefact video.ogv
[2022-03-01T15:31:23.870130Z] [info] [pid:15840] Uploading vars.json
[2022-03-01T15:31:23.870385Z] [debug] [pid:15840] Uploading artefact vars.json
[2022-03-01T15:31:23.894340Z] [info] [pid:15840] Uploading autoinst-log.txt
[2022-03-01T15:31:23.894620Z] [debug] [pid:15840] Uploading artefact autoinst-log.txt
[2022-03-01T15:31:23.918495Z] [info] [pid:15840] Uploading worker-log.txt
[2022-03-01T15:31:23.918738Z] [debug] [pid:15840] Uploading artefact worker-log.txt
/home/squamata/project/test-results/fullstack/full-stack.d/openqa/testresults/00000/00000008-tinycore-1-flavor-i386-Build1-core@coolone/autoinst-log.txt:
[2022-03-01T15:31:25.849960Z] [info] [pid:15611] +++ setup notes +++
[2022-03-01T15:31:25.850208Z] [info] [pid:15611] Running on 1a81a2b0ff0f:1 (Linux 5.11.0-1027-aws #30~20.04.1-Ubuntu SMP Thu Jan 13 11:46:53 UTC 2022 x86_64)
[2022-03-01T15:31:25.856229Z] [debug] [pid:15611] Found HDD_1, caching non-existent.qcow2
[2022-03-01T15:31:25.863008Z] [info] [pid:15611] Downloading non-existent.qcow2, request #4 sent to Cache Service
[2022-03-01T15:31:31.016113Z] [info] [pid:15611] Download of non-existent.qcow2 processed
[2022-03-01T15:31:31.017930Z] [error] [pid:15611] Failed to download non-existent.qcow2 to /home/squamata/project/test-results/fullstack/full-stack.d/cache/localhost/non-existent.qcow2
[2022-03-01T15:31:31.042498Z] [info] [pid:15611] +++ worker notes +++
[2022-03-01T15:31:31.042680Z] [info] [pid:15611] End time: 2022-03-01 15:31:31
[2022-03-01T15:31:31.042769Z] [info] [pid:15611] Result: setup failure
[2022-03-01T15:31:31.047024Z] [info] [pid:15848] Uploading autoinst-log.txt
/home/squamata/project/test-results/fullstack/full-stack.d/openqa/testresults/00000/00000008-tinycore-1-flavor-i386-Build1-core@coolone/worker-log.txt:
[2022-03-01T15:31:25.849684Z] [debug] [pid:15611] Preparing Mojo::IOLoop::ReadWriteProcess::Session
[2022-03-01T15:31:25.850455Z] [debug] [pid:15611] Job settings:
[2022-03-01T15:31:25.850593Z] [debug] [pid:15611]
ARCH=i386
BUILD=1
CACHEDIRECTORY=/home/squamata/project/test-results/fullstack/full-stack.d/cache
CACHELIMIT=50
DISTRI=tinycore
FLAVOR=flavor
HDD_1=non-existent.qcow2
INTEGRATION_TESTS=1
ISO=Core-7.2.iso
JOBTOKEN=FyOb_mAEM1SQZfuT
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=/home/squamata/project/test-results/fullstack/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-03-01T15:31:25.863182Z] [debug] [pid:15611] Updating status so job 8 is not considered dead.
[2022-03-01T15:31:25.863547Z] [debug] [pid:15611] REST-API call: POST http://localhost:9526/api/v1/jobs/8/status
[2022-03-01T15:31:30.974364Z] [debug] [pid:15611] Updating status so job 8 is not considered dead.
[2022-03-01T15:31:30.974934Z] [debug] [pid:15611] REST-API call: POST http://localhost:9526/api/v1/jobs/8/status
[2022-03-01T15:31:31.018139Z] [error] [pid:15611] Unable to setup job 8: Failed to download non-existent.qcow2 to /home/squamata/project/test-results/fullstack/full-stack.d/cache/localhost/non-existent.qcow2
[2022-03-01T15:31:31.018329Z] [debug] [pid:15611] Stopping job 8 from http://localhost:9526: 00000008-tinycore-1-flavor-i386-Build1-core@coolone - reason: setup failure
[2022-03-01T15:31:31.018746Z] [debug] [pid:15611] REST-API call: POST http://localhost:9526/api/v1/jobs/8/status
[2022-03-01T15:31:31.046860Z] [info] [pid:15848] Uploading autoinst-log.txt
[2022-03-01T15:31:31.047365Z] [debug] [pid:15848] Uploading artefact autoinst-log.txt
[2022-03-01T15:31:31.084057Z] [info] [pid:15848] Uploading worker-log.txt
[2022-03-01T15:31:31.084312Z] [debug] [pid:15848] Uploading artefact worker-log.txt
    (1-1/1)