Project

General

Profile

action #106912 » fullstack-shutdown-again.txt

mkittler, 2022-02-16 11:59

 
+ target=fullstack
+ export COVERAGE=1
+ COVERAGE=1
+ export COVERDB_SUFFIX=_fullstack
+ COVERDB_SUFFIX=_fullstack
+ export JUNIT_PACKAGE=openQA
+ JUNIT_PACKAGE=openQA
+ export JUNIT_NAME_MANGLE=perl
+ JUNIT_NAME_MANGLE=perl
+ export JUNIT_OUTPUT_FILE=test-results/junit/fullstack.xml
+ JUNIT_OUTPUT_FILE=test-results/junit/fullstack.xml
+ export PERL_TEST_HARNESS_DUMP_TAP=test-results
+ PERL_TEST_HARNESS_DUMP_TAP=test-results
+ export 'HARNESS=--harness TAP::Harness::JUnit --timer'
+ HARNESS='--harness TAP::Harness::JUnit --timer'
+ mkdir -p test-results/junit
+ sudo chown -R squamata test-results
+ export OPENQA_TEST_TIMEOUT_SCALE_CI=3
+ OPENQA_TEST_TIMEOUT_SCALE_CI=3
+ export EXTRA_PROVE_ARGS=-v
+ EXTRA_PROVE_ARGS=-v
+ make test-fullstack
make test-with-database RETRY=200 STABILITY_TEST=1 TIMEOUT_M=100000 FULLSTACK=1 PROVE_ARGS="$HARNESS t/full-stack.t"
make[1]: Entering directory '/home/squamata/project'
test -d /dev/shm/tpg && (pg_ctl -D /dev/shm/tpg -s status >&/dev/null || pg_ctl -D /dev/shm/tpg -s start) || ./t/test_postgresql /dev/shm/tpg
The files belonging to this database system will be owned by user "squamata".
This user must also own the server process.

The database cluster will be initialized with locale "en_US.UTF-8".
The default database encoding has accordingly been set to "UTF8".
The default text search configuration will be set to "english".

Data page checksums are disabled.

creating directory /dev/shm/tpg ... ok
creating subdirectories ... ok
selecting dynamic shared memory implementation ... posix
selecting default max_connections ... 100
selecting default shared_buffers ... 128MB
selecting default time zone ... Etc/UTC
creating configuration files ... ok
running bootstrap script ... ok
performing post-bootstrap initialization ... ok

Sync to disk skipped.
The data directory might become corrupt if the operating system crashes.

initdb: warning: enabling "trust" authentication for local connections
You can change this by editing pg_hba.conf or using the option -A, or
--auth-local and --auth-host, the next time you run initdb.

Success. You can now start the database server using:

pg_ctl -D /dev/shm/tpg -l logfile start

PostgreSQL logs will be stored in /dev/shm/tpg/log/postgresql-openqa-test.log.
waiting for server to start.... done
server started
Now export TEST_PG like:

export TEST_PG='DBI:Pg:dbname=openqa_test;host=/dev/shm/tpg'

and if you don't need it anymore, use pg_ctl -D /dev/shm/tpg stop
make test-unit-and-integration TEST_PG="DBI:Pg:dbname=openqa_test;host=/dev/shm/tpg"
make[2]: Entering directory '/home/squamata/project'
export GLOBIGNORE="";\
export DEVEL_COVER_DB_FORMAT=JSON;\
export PERL5OPT="-mJSON::PP -MDevel::Cover=-select_re,'^/lib',+ignore_re,lib/perlcritic/Perl/Critic/Policy,-coverage,statement,-db,cover_db_fullstack, -It/lib -I/home/squamata/project/t/lib -MOpenQA::Test::PatchDeparse";\
RETRY=200 HOOK=./tools/delete-coverdb-folder timeout -s SIGINT -k 5 -v $((100000 * 2 * (200 + 1) ))m tools/retry prove -l --harness TAP::Harness::JUnit --timer t/full-stack.t
[11:51:47] t/full-stack.t ..
[11:51:47] t/full-stack.t .. 1/?
[11:51:47] t/full-stack.t .. 2/?
[11:51:47] t/full-stack.t .. 7/?
[11:51:47] t/full-stack.t .. 9/?
[11:51:47] t/full-stack.t .. 12/?
[11:51:47] t/full-stack.t .. 17/?
[11:51:47] t/full-stack.t .. 18/?
[11:51:47] t/full-stack.t .. 20/?
[11:51:47] t/full-stack.t .. 21/?
[11:51:47] t/full-stack.t .. 22/?
[11:51:47] t/full-stack.t .. 23/?
[11:51:47] t/full-stack.t .. 24/?
[11:51:47] t/full-stack.t .. 26/?
[11:51:47] t/full-stack.t .. 32/?
[11:51:47] t/full-stack.t .. 33/?
[11:51:47] t/full-stack.t .. 36/?
[11:51:47] t/full-stack.t .. ok 242764 ms ( 0.33 usr 0.01 sys + 153.48 cusr 15.16 csys = 168.98 CPU)
[11:55:50]
All tests successful.
Files=1, Tests=37, 242.775 wallclock secs ( 0.34 usr 0.01 sys + 153.48 cusr 15.16 csys = 168.99 CPU)
Result: PASS
Rerun 1 of 200 …
Calling retry hook ./tools/delete-coverdb-folder
Deleting cover_db_fullstack/
[11:55:51] t/full-stack.t ..
[11:55:51] t/full-stack.t .. 1/?
[11:55:51] t/full-stack.t .. 2/?
[11:55:51] t/full-stack.t .. 9/?
[11:55:51] t/full-stack.t .. 17/?
[11:55:51] t/full-stack.t .. 18/?
[11:55:51] t/full-stack.t .. 21/?
[11:55:51] t/full-stack.t .. 22/?
[11:55:51] t/full-stack.t .. 23/?
[11:55:51] t/full-stack.t .. 24/?
[11:55:51] t/full-stack.t .. 26/?
[11:55:51] t/full-stack.t .. 32/?
[11:55:51] t/full-stack.t .. 33/?
[11:55:51] t/full-stack.t .. 36/?
[11:55:51] t/full-stack.t .. ok 233930 ms ( 0.32 usr 0.01 sys + 150.11 cusr 10.30 csys = 160.74 CPU)
[11:59:45]
All tests successful.
Files=1, Tests=37, 233.941 wallclock secs ( 0.33 usr 0.02 sys + 150.11 cusr 10.30 csys = 160.76 CPU)
Result: PASS
Rerun 2 of 200 …
Calling retry hook ./tools/delete-coverdb-folder
Deleting cover_db_fullstack/
[11:59:45] t/full-stack.t ..
[11:59:45] t/full-stack.t .. 1/?
[11:59:45] t/full-stack.t .. 2/?
[11:59:45] t/full-stack.t .. 9/?
[11:59:45] t/full-stack.t .. 11/?
[11:59:45] t/full-stack.t .. 17/?
[11:59:45] t/full-stack.t .. 18/?
[11:59:45] t/full-stack.t .. 20/?
[11:59:45] t/full-stack.t .. 21/?
[11:59:45] t/full-stack.t .. 22/?
[11:59:45] t/full-stack.t .. 23/?
[11:59:45] t/full-stack.t .. 24/?
[11:59:45] t/full-stack.t .. 26/?
[11:59:45] t/full-stack.t .. 32/?
[11:59:45] t/full-stack.t .. 33/?
[11:59:45] t/full-stack.t .. 36/?
[11:59:45] t/full-stack.t .. ok 246488 ms ( 0.36 usr 0.01 sys + 159.35 cusr 11.11 csys = 170.83 CPU)
[12:03:52]
All tests successful.
Files=1, Tests=37, 246.501 wallclock secs ( 0.37 usr 0.01 sys + 159.35 cusr 11.11 csys = 170.84 CPU)
Result: PASS
Rerun 3 of 200 …
Calling retry hook ./tools/delete-coverdb-folder
Deleting cover_db_fullstack/
[12:03:52] t/full-stack.t ..
[12:03:52] t/full-stack.t .. 1/?
[12:03:52] t/full-stack.t .. 2/?
[12:03:52] t/full-stack.t .. 9/?
[12:03:52] t/full-stack.t .. 17/?
[12:03:52] t/full-stack.t .. 18/?
[12:03:52] t/full-stack.t .. 21/?
[12:03:52] t/full-stack.t .. 22/?
[12:03:52] t/full-stack.t .. 23/?
[12:03:52] t/full-stack.t .. 24/?
[12:03:52] t/full-stack.t .. 25/?
[12:03:52] t/full-stack.t .. 32/?
[12:03:52] t/full-stack.t .. 33/?
[12:03:52] t/full-stack.t .. 36/?
[12:03:52] t/full-stack.t .. ok 240447 ms ( 0.31 usr 0.02 sys + 155.25 cusr 15.15 csys = 170.73 CPU)
[12:07:53]
All tests successful.
Files=1, Tests=37, 240.459 wallclock secs ( 0.32 usr 0.02 sys + 155.25 cusr 15.15 csys = 170.74 CPU)
Result: PASS
Rerun 4 of 200 …
Calling retry hook ./tools/delete-coverdb-folder
Deleting cover_db_fullstack/
[12:07:53] t/full-stack.t ..
[12:07:53] t/full-stack.t .. 1/?
[12:07:53] t/full-stack.t .. 2/?
[12:07:53] t/full-stack.t .. 5/?
[12:07:53] t/full-stack.t .. 9/?
[12:07:53] t/full-stack.t .. 17/?
[12:07:53] t/full-stack.t .. 18/?
[12:07:53] t/full-stack.t .. 21/?
[12:07:53] t/full-stack.t .. 22/?
[12:07:53] t/full-stack.t .. 23/?
[12:07:53] t/full-stack.t .. 24/?
[12:07:53] t/full-stack.t .. 25/?
[12:07:53] t/full-stack.t .. 32/?
[12:07:53] t/full-stack.t .. 33/?
[12:07:53] t/full-stack.t .. 36/?
[12:07:53] t/full-stack.t .. ok 236745 ms ( 0.34 usr 0.01 sys + 157.00 cusr 11.11 csys = 168.46 CPU)
[12:11:50]
All tests successful.
Files=1, Tests=37, 236.757 wallclock secs ( 0.34 usr 0.01 sys + 157.00 cusr 11.11 csys = 168.46 CPU)
Result: PASS
Rerun 5 of 200 …
Calling retry hook ./tools/delete-coverdb-folder
Deleting cover_db_fullstack/
[12:11:50] t/full-stack.t ..
[12:11:50] t/full-stack.t .. 1/?
[12:11:50] t/full-stack.t .. 2/?
[12:11:50] t/full-stack.t .. 9/?
[12:11:50] t/full-stack.t .. 17/?
[12:11:50] t/full-stack.t .. 18/?
[12:11:50] t/full-stack.t .. 20/?
[12:11:50] t/full-stack.t .. 21/?
[12:11:50] t/full-stack.t .. 22/?
[12:11:50] t/full-stack.t .. 23/?
[12:11:50] t/full-stack.t .. 24/?
[12:11:50] t/full-stack.t .. 26/?
[12:11:50] t/full-stack.t .. 32/?
[12:11:50] t/full-stack.t .. 33/?
[12:11:50] t/full-stack.t .. 36/?
[12:11:50] t/full-stack.t .. ok 239245 ms ( 0.31 usr 0.04 sys + 150.15 cusr 11.80 csys = 162.30 CPU)
[12:15:50]
All tests successful.
Files=1, Tests=37, 239.257 wallclock secs ( 0.32 usr 0.04 sys + 150.15 cusr 11.80 csys = 162.31 CPU)
Result: PASS
Rerun 6 of 200 …
Calling retry hook ./tools/delete-coverdb-folder
Deleting cover_db_fullstack/
[12:15:50] t/full-stack.t ..
[12:15:50] t/full-stack.t .. 1/?
[12:15:50] t/full-stack.t .. 2/?
[12:15:50] t/full-stack.t .. 8/?
[12:15:50] t/full-stack.t .. 9/?
[12:15:50] t/full-stack.t .. 14/?
[12:15:50] t/full-stack.t .. 17/?
[12:15:50] t/full-stack.t .. 18/?
[12:15:50] t/full-stack.t .. 20/?
[12:15:50] t/full-stack.t .. 21/?
[12:15:50] t/full-stack.t .. 22/?
[12:15:50] t/full-stack.t .. 23/?
[12:15:50] t/full-stack.t .. 24/?
[12:15:50] t/full-stack.t .. 32/?
[12:15:50] t/full-stack.t .. 33/?
[12:15:50] t/full-stack.t .. 36/?
[12:15:50] t/full-stack.t .. ok 224077 ms ( 0.29 usr 0.02 sys + 137.83 cusr 11.07 csys = 149.21 CPU)
[12:19:34]
All tests successful.
Files=1, Tests=37, 224.089 wallclock secs ( 0.30 usr 0.02 sys + 137.83 cusr 11.07 csys = 149.22 CPU)
Result: PASS
Rerun 7 of 200 …
Calling retry hook ./tools/delete-coverdb-folder
Deleting cover_db_fullstack/
[12:19:35] t/full-stack.t ..
[12:19:35] t/full-stack.t .. 1/?
[12:19:35] t/full-stack.t .. 2/?
[12:19:35] t/full-stack.t .. 5/?
[12:19:35] t/full-stack.t .. 9/?
[12:19:35] t/full-stack.t .. 11/?
[12:19:35] t/full-stack.t .. 17/?
[12:19:35] t/full-stack.t .. 18/?
[12:19:35] t/full-stack.t .. 21/?
[12:19:35] t/full-stack.t .. 22/?
[12:19:35] t/full-stack.t .. 23/?
[12:19:35] t/full-stack.t .. 24/?
[12:19:35] t/full-stack.t .. 26/?
[12:19:35] t/full-stack.t .. 32/?
[12:19:35] t/full-stack.t .. 33/?
[12:19:35] t/full-stack.t .. 36/?
[12:19:35] t/full-stack.t .. ok 229458 ms ( 0.31 usr 0.01 sys + 138.97 cusr 11.29 csys = 150.58 CPU)
[12:23:24]
All tests successful.
Files=1, Tests=37, 229.469 wallclock secs ( 0.32 usr 0.01 sys + 138.97 cusr 11.29 csys = 150.59 CPU)
Result: PASS
Rerun 8 of 200 …
Calling retry hook ./tools/delete-coverdb-folder
Deleting cover_db_fullstack/
[12:23:25] t/full-stack.t ..
[12:23:25] t/full-stack.t .. 1/?
[12:23:25] t/full-stack.t .. 2/?
[12:23:25] t/full-stack.t .. 9/?
[12:23:25] t/full-stack.t .. 17/?
[12:23:25] t/full-stack.t .. 18/?
[12:23:25] t/full-stack.t .. 21/?
[12:23:25] t/full-stack.t .. 22/?
[12:23:25] t/full-stack.t .. 23/?
[12:23:25] t/full-stack.t .. 24/?
[12:23:25] t/full-stack.t .. 25/?
[12:23:25] t/full-stack.t .. 32/?
[12:23:25] t/full-stack.t .. 33/?
[12:23:25] t/full-stack.t .. 36/?
[12:23:25] t/full-stack.t .. ok 231438 ms ( 0.33 usr 0.01 sys + 142.86 cusr 10.57 csys = 153.77 CPU)
[12:27:16]
All tests successful.
Files=1, Tests=37, 231.451 wallclock secs ( 0.34 usr 0.01 sys + 142.86 cusr 10.57 csys = 153.78 CPU)
Result: PASS
Rerun 9 of 200 …
Calling retry hook ./tools/delete-coverdb-folder
Deleting cover_db_fullstack/
[12:27:17] t/full-stack.t ..
[12:27:17] t/full-stack.t .. 1/?
[12:27:17] t/full-stack.t .. 2/?
[12:27:17] t/full-stack.t .. 9/?
[12:27:17] t/full-stack.t .. 11/?
[12:27:17] t/full-stack.t .. 17/?
[12:27:17] t/full-stack.t .. 18/?
[12:27:17] t/full-stack.t .. 20/?
[12:27:17] t/full-stack.t .. 21/?
[12:27:17] t/full-stack.t .. 22/?
[12:27:17] t/full-stack.t .. 23/?
[12:27:17] t/full-stack.t .. 24/?
[12:27:17] t/full-stack.t .. 32/?
[12:27:17] t/full-stack.t .. 33/? # stopped waiting for '(?^u:Result: passed)', result turned out to be 'failed,'
# full result panel contents:
# 2 1
# Result: failed, finished less than a minute ago (02:01 minutes)
#
# Clone of 6 (restarted already 2 times)
# Scheduled product: job has not been created by posting an ISO (but possibly the original job)
# Assigned worker: 1234cbae1a16:1

# Failed test 'Expected result not found'
# at /home/squamata/project/t/lib/OpenQA/Test/FullstackUtils.pm line 76.

# Failed test 'job 7 passed'
# at t/full-stack.t line 406.
# 0
# Looks like you failed 2 tests of 7.

# Failed test 'results of test 7'
# at t/full-stack.t line 413.
# /tmp/7v4CAal1xt/full-stack.d/openqa/testresults/00000/00000007-tinycore-1-flavor-i386-Build1-core@coolone/autoinst-log.txt:
# [2022-02-15T12:29:56.705497Z] [info] [pid:13113] +++ setup notes +++
# [2022-02-15T12:29:56.705727Z] [info] [pid:13113] Running on 1234cbae1a16:1 (Linux 5.11.0-1027-aws #30~20.04.1-Ubuntu SMP Thu Jan 13 11:46:53 UTC 2022 x86_64)
# [2022-02-15T12:29:56.713655Z] [debug] [pid:13113] Found ISO, caching Core-7.2.iso
# [2022-02-15T12:29:56.721786Z] [info] [pid:13113] Downloading Core-7.2.iso, request #3 sent to Cache Service
# [2022-02-15T12:30:01.835373Z] [info] [pid:13113] Download of Core-7.2.iso processed
# [2022-02-15T12:30:01.843674Z] [debug] [pid:13120] +++ worker notes +++
# [2022-02-15T12:30:03.814331Z] [debug] Current version is a7103b16a88ac5669f56dab460989dea6c74d9fa [interface v24]
# [2022-02-15T12:30:03.825100Z] [debug] git hash in tinycore: a7103b16a88ac5669f56dab460989dea6c74d9fa
# [2022-02-15T12:30:03.924937Z] [debug] scheduling boot tests/boot.pm
# [2022-02-15T12:30:03.925790Z] [debug] scheduling assert_screen tests/assert_screen.pm
# [2022-02-15T12:30:03.926460Z] [debug] scheduling shutdown tests/shutdown.pm
# [2022-02-15T12:30:03.933264Z] [info] cmdsrv: daemon reachable under http://*:20013/NyTrTQWMU40CyqS4/
# [2022-02-15T12:30:03.935234Z] [info] Listening at "http://0.0.0.0:20013"
# Web application available at http://0.0.0.0:20013
# [2022-02-15T12:30:03.936974Z] [debug] git hash in tinycore/needles: a7103b16a88ac5669f56dab460989dea6c74d9fa
# [2022-02-15T12:30:03.937096Z] [debug] init needles from tinycore/needles
# [2022-02-15T12:30:03.938376Z] [debug] loaded 4 needles
# [2022-02-15T12:30:03.941194Z] [debug] Blocking SIGCHLD and SIGTERM
# [2022-02-15T12:30:04.054625Z] [debug] Unblocking SIGCHLD and SIGTERM
# [2022-02-15T12:30:04.176281Z] [debug] Blocking SIGCHLD and SIGTERM
# [2022-02-15T12:30:04.176407Z] [debug] 13120: channel_out 15, channel_in 14
# [2022-02-15T12:30:04.350643Z] [debug] Unblocking SIGCHLD and SIGTERM
# [2022-02-15T12:30:04.352545Z] [debug] 13214: cmdpipe 13, rsppipe 16
# [2022-02-15T12:30:04.352660Z] [debug] started mgmt loop with pid 13214
# [2022-02-15T12:30:04.553266Z] [debug] qemu version detected: 5.2.0
# [2022-02-15T12:30:04.554868Z] [debug] running `/usr/bin/chattr +C /tmp/7v4CAal1xt/full-stack.d/openqa/pool/1/raid`
# [2022-02-15T12:30:04.563131Z] [debug] Fatal error in command `/usr/bin/chattr +C /tmp/7v4CAal1xt/full-stack.d/openqa/pool/1/raid`: open3: exec of /usr/bin/chattr +C /tmp/7v4CAal1xt/full-stack.d/openqa/pool/1/raid failed: No such file or directory at /usr/lib/perl5/vendor_perl/5.26.1/Mojo/IOLoop/ReadWriteProcess.pm line 127.
#
# [2022-02-15T12:30:04.563224Z] [debug] Configuring storage controllers and block devices
# [2022-02-15T12:30:04.563807Z] [debug] running `/usr/bin/qemu-img info --output=json /tmp/7v4CAal1xt/full-stack.d/openqa/pool/1/Core-7.2.iso`
# [2022-02-15T12:30:04.574308Z] [debug] Initializing block device images
# [2022-02-15T12:30:04.574504Z] [debug] running `/usr/bin/qemu-img create -f qcow2 /tmp/7v4CAal1xt/full-stack.d/openqa/pool/1/raid/hd0 10G`
# [2022-02-15T12:30:04.587418Z] [debug] Formatting '/tmp/7v4CAal1xt/full-stack.d/openqa/pool/1/raid/hd0', fmt=qcow2 cluster_size=65536 extended_l2=off compression_type=zlib size=10737418240 lazy_refcounts=off refcount_bits=16
# [2022-02-15T12:30:04.587553Z] [debug] running `/usr/bin/qemu-img create -f qcow2 -F raw -b /tmp/7v4CAal1xt/full-stack.d/openqa/pool/1/Core-7.2.iso /tmp/7v4CAal1xt/full-stack.d/openqa/pool/1/raid/cd0-overlay0 11116544`
# [2022-02-15T12:30:04.599179Z] [debug] Formatting '/tmp/7v4CAal1xt/full-stack.d/openqa/pool/1/raid/cd0-overlay0', fmt=qcow2 cluster_size=65536 extended_l2=off compression_type=zlib size=11116544 backing_file=/tmp/7v4CAal1xt/full-stack.d/openqa/pool/1/Core-7.2.iso backing_fmt=raw lazy_refcounts=off refcount_bits=16
# [2022-02-15T12:30:04.599271Z] [debug] init_blockdev_images: Finished creating block devices
# [2022-02-15T12:30:04.600313Z] [debug] starting: /usr/bin/qemu-system-i386 -only-migratable -chardev ringbuf,id=serial0,logfile=serial0,logappend=on -serial chardev:serial0 -audiodev none,id=snd0 -device intel-hda -device hda-output,audiodev=snd0 -m 1024 -netdev user,id=qanet0 -device virtio-net,netdev=qanet0,mac=52:54:00:12:34:56 -boot once=d -smp 1 -no-shutdown -vnc :91,share=force-shared -device virtio-serial -chardev pipe,id=virtio_console,path=virtio_console,logfile=virtio_console.log,logappend=on -device virtconsole,chardev=virtio_console,name=org.openqa.console.virtio_console -chardev pipe,id=virtio_console1,path=virtio_console1,logfile=virtio_console1.log,logappend=on -device virtconsole,chardev=virtio_console1,name=org.openqa.console.virtio_console1 -chardev socket,path=qmp_socket,server=on,wait=off,id=qmp_socket,logfile=qmp_socket.log,logappend=on -qmp chardev:qmp_socket -S -device virtio-scsi-pci,id=scsi0 -blockdev driver=file,node-name=hd0-file,filename=/tmp/7v4CAal1xt/full-stack.d/openqa/pool/1/raid/hd0,cache.no-flush=on -blockdev driver=qcow2,node-name=hd0,file=hd0-file,cache.no-flush=on -device virtio-blk,id=hd0-device,drive=hd0,serial=hd0 -blockdev driver=file,node-name=cd0-overlay0-file,filename=/tmp/7v4CAal1xt/full-stack.d/openqa/pool/1/raid/cd0-overlay0,cache.no-flush=on -blockdev driver=qcow2,node-name=cd0-overlay0,file=cd0-overlay0-file,cache.no-flush=on -device scsi-cd,id=cd0-device,drive=cd0-overlay0,serial=cd0
# [2022-02-15T12:30:04.604322Z] [debug] Waiting for 0 attempts
# [2022-02-15T12:30:05.604972Z] [debug] Waiting for 1 attempts
# [2022-02-15T12:30:06.605400Z] [debug] Finished after 2 attempts
# [2022-02-15T12:30:06.607832Z] [debug] Establishing VNC connection to localhost:5991
# [2022-02-15T12:30:06.610964Z] [debug] pointer type 0 0 640 480 -257
# [2022-02-15T12:30:06.611113Z] [debug] led state 0 1 1 -261
# [2022-02-15T12:30:06.670643Z] [debug] Start CPU
# [2022-02-15T12:30:06.670978Z] [debug] EVENT {"data":{"client":{"family":"ipv4","host":"127.0.0.1","service":"47352","websocket":false},"server":{"auth":"none","family":"ipv4","host":"0.0.0.0","service":"5991","websocket":false}},"event":"VNC_CONNECTED","timestamp":{"microseconds":608598,"seconds":1644928206}}
# [2022-02-15T12:30:06.671074Z] [debug] EVENT {"data":{"client":{"family":"ipv4","host":"127.0.0.1","service":"47352","websocket":false},"server":{"auth":"none","family":"ipv4","host":"0.0.0.0","service":"5991","websocket":false}},"event":"VNC_INITIALIZED","timestamp":{"microseconds":609563,"seconds":1644928206}}
# [2022-02-15T12:30:06.671141Z] [debug] EVENT {"event":"RESUME","timestamp":{"microseconds":671062,"seconds":1644928206}}
# GOT GO
#
# [2022-02-15T12:30:06.679085Z] [debug] QEMU: QEMU emulator version 5.2.0 (SUSE Linux Enterprise 15)
# [2022-02-15T12:30:06.679143Z] [debug] QEMU: Copyright (c) 2003-2020 Fabrice Bellard and the QEMU Project developers
# [2022-02-15T12:30:06.682545Z] [debug] Snapshots are supported
# [2022-02-15T12:30:06.683729Z] [debug] ||| starting boot tests/boot.pm
# [2022-02-15T12:30:06.685985Z] [debug] tests/boot.pm:9 called testapi::assert_screen
# [2022-02-15T12:30:06.686361Z] [debug] <<< testapi::assert_screen(mustmatch="core", timeout=15, no_wait=1)
# [2022-02-15T12:30:06.700419Z] [debug] no match: 14.9s, best candidate: boot-core (0.00)
# [2022-02-15T12:30:06.801153Z] [debug] no change: 14.8s
# [2022-02-15T12:30:06.809744Z] [debug] no match: 14.8s, best candidate: boot-core (0.00)
# [2022-02-15T12:30:06.910484Z] [debug] no change: 14.7s
# [2022-02-15T12:30:06.917192Z] [debug] no match: 14.7s, best candidate: boot-core (0.00)
# [2022-02-15T12:30:07.017933Z] [debug] no change: 14.6s
# [2022-02-15T12:30:07.024717Z] [debug] no match: 14.6s, best candidate: boot-core (0.00)
# [2022-02-15T12:30:07.125518Z] [debug] no change: 14.5s
# [2022-02-15T12:30:07.134823Z] [debug] no match: 14.5s, best candidate: boot-core (0.00)
# [2022-02-15T12:30:07.331434Z] [debug] >>> testapi::_handle_found_needle: found boot-core, similarity 0.97 @ 1/74
# [2022-02-15T12:30:07.332261Z] [debug] tests/boot.pm:10 called testapi::send_key
# [2022-02-15T12:30:07.332397Z] [debug] <<< testapi::send_key(key="ret", wait_screen_change=0, do_wait=0)
# [2022-02-15T12:30:07.602261Z] [debug] tests/boot.pm:14 called testapi::assert_screen
# [2022-02-15T12:30:07.602421Z] [debug] <<< testapi::assert_screen(mustmatch="on_prompt", timeout=90)
# [2022-02-15T12:30:08.241080Z] [debug] no match: 89.3s, best candidate: boot-on_prompt (0.00)
# [2022-02-15T12:30:09.239031Z] [debug] no match: 88.3s, best candidate: boot-on_prompt (0.00)
# [2022-02-15T12:30:10.239732Z] [debug] no match: 87.3s, best candidate: boot-on_prompt (0.00)
# [2022-02-15T12:30:11.240536Z] [debug] no match: 86.3s, best candidate: boot-on_prompt (0.00)
# [2022-02-15T12:30:12.284183Z] [debug] no match: 85.3s, best candidate: boot-on_prompt (0.00)
# [2022-02-15T12:30:13.243429Z] [debug] no match: 84.3s, best candidate: boot-on_prompt (0.00)
# [2022-02-15T12:30:14.250893Z] [debug] no match: 83.3s, best candidate: boot-on_prompt (0.00)
# [2022-02-15T12:30:15.244456Z] [debug] no match: 82.3s, best candidate: boot-on_prompt (0.00)
# [2022-02-15T12:30:16.245635Z] [debug] no match: 81.3s, best candidate: boot-on_prompt (0.00)
# [2022-02-15T12:30:17.290398Z] [debug] no match: 80.3s, best candidate: boot-on_prompt (0.00)
# [2022-02-15T12:30:18.247487Z] [debug] no match: 79.3s, best candidate: boot-on_prompt (0.00)
# [2022-02-15T12:30:19.248117Z] [debug] no match: 78.3s, best candidate: boot-on_prompt (0.00)
# [2022-02-15T12:30:20.248476Z] [debug] no match: 77.3s, best candidate: boot-on_prompt (0.00)
# [2022-02-15T12:30:21.249634Z] [debug] no match: 76.3s, best candidate: boot-on_prompt (0.00)
# [2022-02-15T12:30:22.370453Z] [debug] >>> testapi::_handle_found_needle: found boot-on_prompt, similarity 1.00 @ 2/64
# [2022-02-15T12:30:22.374020Z] [debug] ||| finished boot tests (runtime: 16 s)
# [2022-02-15T12:30:22.375138Z] [debug] ||| starting assert_screen tests/assert_screen.pm
# [2022-02-15T12:30:22.375777Z] [debug] tests/assert_screen.pm:9 called testapi::assert_screen
# [2022-02-15T12:30:22.375889Z] [debug] <<< testapi::assert_screen(mustmatch="on_prompt", timeout=60)
# [2022-02-15T12:30:23.323411Z] [debug] >>> testapi::_handle_found_needle: found boot-on_prompt, similarity 1.00 @ 2/64
# [2022-02-15T12:30:23.323585Z] [debug] tests/assert_screen.pm:10 called testapi::assert_screen
# [2022-02-15T12:30:23.323700Z] [debug] <<< testapi::assert_screen(mustmatch="on_prompt", timeout=30, no_wait=1)
# [2022-02-15T12:30:23.397251Z] [debug] >>> testapi::_handle_found_needle: found boot-on_prompt, similarity 1.00 @ 2/64
# [2022-02-15T12:30:23.398459Z] [debug] ||| finished assert_screen tests (runtime: 1 s)
# [2022-02-15T12:30:23.399556Z] [debug] ||| starting shutdown tests/shutdown.pm
# [2022-02-15T12:30:23.400299Z] [debug] tests/shutdown.pm:8 called testapi::type_string
# [2022-02-15T12:30:23.400468Z] [debug] <<< testapi::type_string(string="sudo su\n", max_interval=250, wait_screen_changes=0, wait_still_screen=0, timeout=30, similarity_level=47)
# [2022-02-15T12:30:23.671645Z] [debug] tests/shutdown.pm:9 called testapi::type_string
# [2022-02-15T12:30:23.671846Z] [debug] <<< testapi::type_string(string="poweroff\n", max_interval=250, wait_screen_changes=0, wait_still_screen=0, timeout=30, similarity_level=47)
# [2022-02-15T12:30:23.976613Z] [debug] tests/shutdown.pm:10 called testapi::assert_shutdown
# [2022-02-15T12:30:23.976768Z] [debug] <<< testapi::check_shutdown(timeout=90)
# [2022-02-15T12:30:23.977601Z] [debug] QEMU status is not 'shutdown', it is 'running'
# [2022-02-15T12:30:24.978574Z] [debug] EVENT {"data":{"path":"\/machine\/peripheral-anon\/device[2]\/virtio-backend"},"event":"NIC_RX_FILTER_CHANGED","timestamp":{"microseconds":798568,"seconds":1644928224}}
# [2022-02-15T12:30:24.978769Z] [debug] QEMU status is not 'shutdown', it is 'running'
# [2022-02-15T12:30:25.980202Z] [debug] QEMU status is not 'shutdown', it is 'running'
# [2022-02-15T12:30:26.981697Z] [debug] QEMU status is not 'shutdown', it is 'running'
# [2022-02-15T12:30:27.983129Z] [debug] QEMU status is not 'shutdown', it is 'running'
# [2022-02-15T12:30:28.984521Z] [debug] QEMU status is not 'shutdown', it is 'running'
# [2022-02-15T12:30:29.986015Z] [debug] QEMU status is not 'shutdown', it is 'running'
# [2022-02-15T12:30:30.987833Z] [debug] QEMU status is not 'shutdown', it is 'running'
# [2022-02-15T12:30:31.989409Z] [debug] QEMU status is not 'shutdown', it is 'running'
# [2022-02-15T12:30:32.990952Z] [debug] QEMU status is not 'shutdown', it is 'running'
# [2022-02-15T12:30:33.992506Z] [debug] QEMU status is not 'shutdown', it is 'running'
# [2022-02-15T12:30:34.994180Z] [debug] QEMU status is not 'shutdown', it is 'running'
# [2022-02-15T12:30:35.995702Z] [debug] QEMU status is not 'shutdown', it is 'running'
# [2022-02-15T12:30:36.997284Z] [debug] QEMU status is not 'shutdown', it is 'running'
# [2022-02-15T12:30:37.998701Z] [debug] QEMU status is not 'shutdown', it is 'running'
# [2022-02-15T12:30:39.000077Z] [debug] QEMU status is not 'shutdown', it is 'running'
# [2022-02-15T12:30:40.001426Z] [debug] QEMU status is not 'shutdown', it is 'running'
# [2022-02-15T12:30:41.002793Z] [debug] QEMU status is not 'shutdown', it is 'running'
# [2022-02-15T12:30:42.004222Z] [debug] QEMU status is not 'shutdown', it is 'running'
# [2022-02-15T12:30:43.005663Z] [debug] QEMU status is not 'shutdown', it is 'running'
# [2022-02-15T12:30:44.007088Z] [debug] QEMU status is not 'shutdown', it is 'running'
# [2022-02-15T12:30:45.009225Z] [debug] QEMU status is not 'shutdown', it is 'running'
# [2022-02-15T12:30:46.010647Z] [debug] QEMU status is not 'shutdown', it is 'running'
# [2022-02-15T12:30:47.012001Z] [debug] QEMU status is not 'shutdown', it is 'running'
# [2022-02-15T12:30:48.013345Z] [debug] QEMU status is not 'shutdown', it is 'running'
# [2022-02-15T12:30:49.014707Z] [debug] QEMU status is not 'shutdown', it is 'running'
# [2022-02-15T12:30:50.016237Z] [debug] QEMU status is not 'shutdown', it is 'running'
# [2022-02-15T12:30:51.017733Z] [debug] QEMU status is not 'shutdown', it is 'running'
# [2022-02-15T12:30:52.019127Z] [debug] QEMU status is not 'shutdown', it is 'running'
# [2022-02-15T12:30:53.020473Z] [debug] QEMU status is not 'shutdown', it is 'running'
# [2022-02-15T12:30:54.022002Z] [debug] QEMU status is not 'shutdown', it is 'running'
# [2022-02-15T12:30:55.023478Z] [debug] QEMU status is not 'shutdown', it is 'running'
# [2022-02-15T12:30:56.024798Z] [debug] QEMU status is not 'shutdown', it is 'running'
# [2022-02-15T12:30:57.026197Z] [debug] QEMU status is not 'shutdown', it is 'running'
# [2022-02-15T12:30:58.027597Z] [debug] QEMU status is not 'shutdown', it is 'running'
# [2022-02-15T12:30:59.028949Z] [debug] QEMU status is not 'shutdown', it is 'running'
# [2022-02-15T12:31:00.030382Z] [debug] QEMU status is not 'shutdown', it is 'running'
# [2022-02-15T12:31:01.031751Z] [debug] QEMU status is not 'shutdown', it is 'running'
# [2022-02-15T12:31:02.033322Z] [debug] QEMU status is not 'shutdown', it is 'running'
# [2022-02-15T12:31:03.034643Z] [debug] QEMU status is not 'shutdown', it is 'running'
# [2022-02-15T12:31:04.035983Z] [debug] QEMU status is not 'shutdown', it is 'running'
# [2022-02-15T12:31:05.037390Z] [debug] QEMU status is not 'shutdown', it is 'running'
# [2022-02-15T12:31:06.038745Z] [debug] QEMU status is not 'shutdown', it is 'running'
# [2022-02-15T12:31:07.040077Z] [debug] QEMU status is not 'shutdown', it is 'running'
# [2022-02-15T12:31:08.041514Z] [debug] QEMU status is not 'shutdown', it is 'running'
# [2022-02-15T12:31:09.042758Z] [debug] QEMU status is not 'shutdown', it is 'running'
# [2022-02-15T12:31:10.044073Z] [debug] QEMU status is not 'shutdown', it is 'running'
# [2022-02-15T12:31:11.045563Z] [debug] QEMU status is not 'shutdown', it is 'running'
# [2022-02-15T12:31:12.047049Z] [debug] QEMU status is not 'shutdown', it is 'running'
# [2022-02-15T12:31:13.048395Z] [debug] QEMU status is not 'shutdown', it is 'running'
# [2022-02-15T12:31:14.050472Z] [debug] QEMU status is not 'shutdown', it is 'running'
# [2022-02-15T12:31:15.052414Z] [debug] QEMU status is not 'shutdown', it is 'running'
# [2022-02-15T12:31:16.054248Z] [debug] QEMU status is not 'shutdown', it is 'running'
# [2022-02-15T12:31:17.056032Z] [debug] QEMU status is not 'shutdown', it is 'running'
# [2022-02-15T12:31:18.057735Z] [debug] QEMU status is not 'shutdown', it is 'running'
# [2022-02-15T12:31:19.059430Z] [debug] QEMU status is not 'shutdown', it is 'running'
# [2022-02-15T12:31:20.061007Z] [debug] QEMU status is not 'shutdown', it is 'running'
# [2022-02-15T12:31:21.062687Z] [debug] QEMU status is not 'shutdown', it is 'running'
# [2022-02-15T12:31:22.064236Z] [debug] QEMU status is not 'shutdown', it is 'running'
# [2022-02-15T12:31:23.065755Z] [debug] QEMU status is not 'shutdown', it is 'running'
# [2022-02-15T12:31:24.067307Z] [debug] QEMU status is not 'shutdown', it is 'running'
# [2022-02-15T12:31:25.068789Z] [debug] QEMU status is not 'shutdown', it is 'running'
# [2022-02-15T12:31:26.070303Z] [debug] QEMU status is not 'shutdown', it is 'running'
# [2022-02-15T12:31:27.071919Z] [debug] QEMU status is not 'shutdown', it is 'running'
# [2022-02-15T12:31:28.073276Z] [debug] QEMU status is not 'shutdown', it is 'running'
# [2022-02-15T12:31:29.074616Z] [debug] QEMU status is not 'shutdown', it is 'running'
# [2022-02-15T12:31:30.076077Z] [debug] QEMU status is not 'shutdown', it is 'running'
# [2022-02-15T12:31:31.077578Z] [debug] QEMU status is not 'shutdown', it is 'running'
# [2022-02-15T12:31:32.079056Z] [debug] QEMU status is not 'shutdown', it is 'running'
# [2022-02-15T12:31:33.080466Z] [debug] QEMU status is not 'shutdown', it is 'running'
# [2022-02-15T12:31:34.081957Z] [debug] QEMU status is not 'shutdown', it is 'running'
# [2022-02-15T12:31:35.083433Z] [debug] QEMU status is not 'shutdown', it is 'running'
# [2022-02-15T12:31:36.084782Z] [debug] QEMU status is not 'shutdown', it is 'running'
# [2022-02-15T12:31:37.086272Z] [debug] QEMU status is not 'shutdown', it is 'running'
# [2022-02-15T12:31:38.087737Z] [debug] QEMU status is not 'shutdown', it is 'running'
# [2022-02-15T12:31:39.089124Z] [debug] QEMU status is not 'shutdown', it is 'running'
# [2022-02-15T12:31:40.090500Z] [debug] QEMU status is not 'shutdown', it is 'running'
# [2022-02-15T12:31:41.091951Z] [debug] QEMU status is not 'shutdown', it is 'running'
# [2022-02-15T12:31:42.093492Z] [debug] QEMU status is not 'shutdown', it is 'running'
# [2022-02-15T12:31:43.094993Z] [debug] QEMU status is not 'shutdown', it is 'running'
# [2022-02-15T12:31:44.096513Z] [debug] QEMU status is not 'shutdown', it is 'running'
# [2022-02-15T12:31:45.098016Z] [debug] QEMU status is not 'shutdown', it is 'running'
# [2022-02-15T12:31:46.099536Z] [debug] QEMU status is not 'shutdown', it is 'running'
# [2022-02-15T12:31:47.101013Z] [debug] QEMU status is not 'shutdown', it is 'running'
# [2022-02-15T12:31:48.102416Z] [debug] QEMU status is not 'shutdown', it is 'running'
# [2022-02-15T12:31:49.103731Z] [debug] QEMU status is not 'shutdown', it is 'running'
# [2022-02-15T12:31:50.105142Z] [debug] QEMU status is not 'shutdown', it is 'running'
# [2022-02-15T12:31:51.106659Z] [debug] QEMU status is not 'shutdown', it is 'running'
# [2022-02-15T12:31:52.108181Z] [debug] QEMU status is not 'shutdown', it is 'running'
# [2022-02-15T12:31:53.109628Z] [debug] QEMU status is not 'shutdown', it is 'running'
# [2022-02-15T12:31:54.110983Z] [debug] QEMU status is not 'shutdown', it is 'running'
# [2022-02-15T12:31:55.174986Z] [info] ::: basetest::runtest: # Test died: Machine didn't shut down! at tinycore/tests/shutdown.pm line 10.
#
# [2022-02-15T12:31:55.177594Z] [debug] ||| finished shutdown tests (runtime: 92 s)
# [2022-02-15T12:31:55.177662Z] [debug] ||| post fail hooks runtime: 0 s
# [2022-02-15T12:31:55.177961Z] [debug] stopping overall test execution after a fatal test failure
# [2022-02-15T12:31:55.178722Z] [debug] stopping autotest process 13144
# [2022-02-15T12:31:55.184647Z] [debug] [autotest] process exited: 0
# [2022-02-15T12:31:55.285073Z] [debug] done with autotest process
# [2022-02-15T12:31:55.285743Z] [debug] stopping command server 13141 because test execution ended
# [2022-02-15T12:31:55.285851Z] [debug] isotovideo: informing websocket clients before stopping command server: http://127.0.0.1:20013/NyTrTQWMU40CyqS4/broadcast
# [2022-02-15T12:31:55.301550Z] [debug] commands process exited: 0
# [2022-02-15T12:31:55.401915Z] [debug] done with command server
# [2022-02-15T12:31:55.401993Z] [debug] isotovideo done
# [2022-02-15T12:31:55.402737Z] [debug] QEMU status is not 'shutdown', it is 'running'
# [2022-02-15T12:31:55.402887Z] [debug] backend shutdown state:
# [2022-02-15T12:31:55.403295Z] [info] ::: OpenQA::Qemu::Proc::save_state: Saving QEMU state to qemu_state.json
# [2022-02-15T12:31:56.414550Z] [debug] Passing remaining frames to the video encoder
# [2022-02-15T12:31:56.437922Z] [debug] Waiting for video encoder to finalize the video
# [2022-02-15T12:31:56.437993Z] [debug] The built-in video encoder (pid 13284) terminated
# [2022-02-15T12:31:56.438524Z] [debug] QEMU: qemu-system-i386: terminating on signal 15 from pid 13214 (/home/squamata/os-autoinst/isotovideo: backen)
# [2022-02-15T12:31:56.439473Z] [debug] sending magic and exit
# [2022-02-15T12:31:56.439705Z] [debug] received magic close
# [2022-02-15T12:31:56.449547Z] [debug] backend process exited: 0
# [2022-02-15T12:31:56.550455Z] [debug] stopping backend process 13214
# [2022-02-15T12:31:56.550526Z] [debug] done with backend process
# 13120: EXIT 0
# [2022-02-15T12:31:56.566874Z] [info] [pid:13113] Isotovideo exit status: 0
# [2022-02-15T12:31:56.599551Z] [info] [pid:13113] +++ worker notes +++
# [2022-02-15T12:31:56.599759Z] [info] [pid:13113] End time: 2022-02-15 12:31:56
# [2022-02-15T12:31:56.599852Z] [info] [pid:13113] Result: done
# [2022-02-15T12:31:56.604907Z] [info] [pid:13355] Uploading video.ogv
# [2022-02-15T12:31:56.650212Z] [info] [pid:13355] Uploading vars.json
# [2022-02-15T12:31:56.691318Z] [info] [pid:13355] Uploading autoinst-log.txt
# /tmp/7v4CAal1xt/full-stack.d/openqa/testresults/00000/00000007-tinycore-1-flavor-i386-Build1-core@coolone/worker-log.txt:
# [2022-02-15T12:29:56.705078Z] [debug] [pid:13113] Preparing Mojo::IOLoop::ReadWriteProcess::Session
# [2022-02-15T12:29:56.706055Z] [debug] [pid:13113] Job settings:
# [2022-02-15T12:29:56.706195Z] [debug] [pid:13113]
# ARCH=i386
# BUILD=1
# CACHEDIRECTORY=/tmp/7v4CAal1xt/full-stack.d/cache
# CACHELIMIT=50
# DISTRI=tinycore
# FLAVOR=flavor
# INTEGRATION_TESTS=1
# ISO=Core-7.2.iso
# JOBTOKEN=NyTrTQWMU40CyqS4
# LOCAL_UPLOAD=0
# LOG_LEVEL=debug
# MACHINE=coolone
# NAME=00000007-tinycore-1-flavor-i386-Build1-core@coolone
# OPENQA_HOSTNAME=localhost:9526
# OPENQA_URL=http://localhost:9526
# PRJDIR=/tmp/7v4CAal1xt/full-stack.d/openqa/share
# PUBLISH_HDD_1=
# QEMU=i386
# QEMUPORT=20012
# QEMU_NO_FDC_SET=1
# QEMU_NO_KVM=1
# QEMU_NO_TABLET=1
# RETRY_DELAY=5
# RETRY_DELAY_IF_WEBUI_BUSY=60
# TEST=core
# UEFI_PFLASH_VARS=/usr/share/qemu/ovmf-x86_64.bin
# VERSION=1
# VNC=91
# WORKER_CLASS=qemu_i386,qemu_x86_64
# WORKER_ID=1
# WORKER_INSTANCE=1
# [2022-02-15T12:29:56.722035Z] [debug] [pid:13113] Updating status so job 7 is not considered dead.
# [2022-02-15T12:29:56.722504Z] [debug] [pid:13113] REST-API call: POST http://localhost:9526/api/v1/jobs/7/status
# [2022-02-15T12:30:01.783136Z] [debug] [pid:13113] Updating status so job 7 is not considered dead.
# [2022-02-15T12:30:01.783729Z] [debug] [pid:13113] REST-API call: POST http://localhost:9526/api/v1/jobs/7/status
# [2022-02-15T12:30:01.837831Z] [debug] [pid:13113] Linked asset "/tmp/7v4CAal1xt/full-stack.d/cache/localhost/Core-7.2.iso" to "/tmp/7v4CAal1xt/full-stack.d/openqa/pool/1/Core-7.2.iso"
# [2022-02-15T12:30:01.838278Z] [debug] [pid:13113] Symlinked from "/tmp/7v4CAal1xt/full-stack.d/openqa/share/tests/tinycore" to "/tmp/7v4CAal1xt/full-stack.d/openqa/pool/1/tinycore"
# [2022-02-15T12:30:01.838660Z] [info] [pid:13113] Preparing cgroup to start isotovideo
# [2022-02-15T12:30:01.839867Z] [warn] [pid:13113] Disabling cgroup usage because cgroup creation failed: mkdir /sys/fs/cgroup/systemd/docker: Permission denied at /usr/lib/perl5/vendor_perl/5.26.1/Mojo/File.pm line 84.
# [2022-02-15T12:30:01.840004Z] [info] [pid:13113] You can define a custom slice with OPENQA_CGROUP_SLICE or indicating the base mount with MOJO_CGROUP_FS.
# [2022-02-15T12:30:01.840324Z] [info] [pid:13113] Starting isotovideo container
# [2022-02-15T12:30:01.843130Z] [debug] [pid:13113] Registered process:13120
# [2022-02-15T12:30:01.843427Z] [info] [pid:13120] 13120: WORKING 7
# [2022-02-15T12:30:01.843640Z] [info] [pid:13113] isotovideo has been started (PID: 13120)
# [2022-02-15T12:30:01.844241Z] [debug] [pid:13113] Running job 7 from http://localhost:9526: 00000007-tinycore-1-flavor-i386-Build1-core@coolone.
# [2022-02-15T12:30:01.846921Z] [debug] [pid:13113] REST-API call: POST http://localhost:9526/api/v1/jobs/7/status
# [2022-02-15T12:30:01.903865Z] [debug] [pid:13113] Upload concluded (no current module)
# [2022-02-15T12:30:11.912144Z] [debug] [pid:13113] REST-API call: POST http://localhost:9526/api/v1/jobs/7/status
# [2022-02-15T12:30:11.986649Z] [debug] [pid:13113] Upload concluded (at boot)
# [2022-02-15T12:30:21.987764Z] [debug] [pid:13113] REST-API call: POST http://localhost:9526/api/v1/jobs/7/status
# [2022-02-15T12:30:22.050710Z] [debug] [pid:13113] Upload concluded (at boot)
# [2022-02-15T12:30:32.060439Z] [debug] [pid:13113] REST-API call: POST http://localhost:9526/api/v1/jobs/7/status
# [2022-02-15T12:30:32.208212Z] [debug] [pid:13113] Upload concluded (up to boot)
# [2022-02-15T12:30:42.210057Z] [debug] [pid:13113] REST-API call: POST http://localhost:9526/api/v1/jobs/7/status
# [2022-02-15T12:30:42.292589Z] [debug] [pid:13113] Upload concluded (at shutdown)
# [2022-02-15T12:30:52.304006Z] [debug] [pid:13113] REST-API call: POST http://localhost:9526/api/v1/jobs/7/status
# [2022-02-15T12:30:52.364354Z] [debug] [pid:13113] Upload concluded (at shutdown)
# [2022-02-15T12:31:02.366920Z] [debug] [pid:13113] REST-API call: POST http://localhost:9526/api/v1/jobs/7/status
# [2022-02-15T12:31:02.460213Z] [debug] [pid:13113] Upload concluded (at shutdown)
# [2022-02-15T12:31:12.469946Z] [debug] [pid:13113] REST-API call: POST http://localhost:9526/api/v1/jobs/7/status
# [2022-02-15T12:31:12.549781Z] [debug] [pid:13113] Upload concluded (at shutdown)
# [2022-02-15T12:31:22.552354Z] [debug] [pid:13113] REST-API call: POST http://localhost:9526/api/v1/jobs/7/status
# [2022-02-15T12:31:22.665269Z] [debug] [pid:13113] Upload concluded (at shutdown)
# [2022-02-15T12:31:32.676352Z] [debug] [pid:13113] REST-API call: POST http://localhost:9526/api/v1/jobs/7/status
# [2022-02-15T12:31:32.760474Z] [debug] [pid:13113] Upload concluded (at shutdown)
# [2022-02-15T12:31:42.762642Z] [debug] [pid:13113] REST-API call: POST http://localhost:9526/api/v1/jobs/7/status
# [2022-02-15T12:31:42.823082Z] [debug] [pid:13113] Upload concluded (at shutdown)
# [2022-02-15T12:31:52.832799Z] [debug] [pid:13113] REST-API call: POST http://localhost:9526/api/v1/jobs/7/status
# [2022-02-15T12:31:52.897949Z] [debug] [pid:13113] Upload concluded (at shutdown)
# [2022-02-15T12:31:56.567214Z] [debug] [pid:13113] Stopping job 7 from http://localhost:9526: 00000007-tinycore-1-flavor-i386-Build1-core@coolone - reason: done
# [2022-02-15T12:31:56.567929Z] [debug] [pid:13113] REST-API call: POST http://localhost:9526/api/v1/jobs/7/status
# [2022-02-15T12:31:56.604711Z] [info] [pid:13355] Uploading video.ogv
# [2022-02-15T12:31:56.605221Z] [debug] [pid:13355] Uploading artefact video.ogv
# [2022-02-15T12:31:56.650105Z] [info] [pid:13355] Uploading vars.json
# [2022-02-15T12:31:56.650397Z] [debug] [pid:13355] Uploading artefact vars.json
# [2022-02-15T12:31:56.691175Z] [info] [pid:13355] Uploading autoinst-log.txt
# [2022-02-15T12:31:56.691552Z] [debug] [pid:13355] Uploading artefact autoinst-log.txt
# [2022-02-15T12:31:56.731236Z] [info] [pid:13355] Uploading worker-log.txt
# [2022-02-15T12:31:56.731530Z] [debug] [pid:13355] Uploading artefact worker-log.txt
# Looks like you failed 1 test of 26.

[12:27:17] t/full-stack.t .. 36/?
# Failed test 'Cache tests'
# at t/full-stack.t line 442.
# Looks like you failed 1 test of 37.

[12:27:17] t/full-stack.t .. Dubious, test returned 1 (wstat 256, 0x100)
Failed 1/37 subtests
[12:32:44]

Test Summary Report
-------------------
t/full-stack.t (Wstat: 256 Tests: 37 Failed: 1)
Failed test: 36
Non-zero exit status: 1
Files=1, Tests=37, 327.046 wallclock secs ( 0.43 usr 0.01 sys + 161.62 cusr 16.30 csys = 178.36 CPU)
Result: FAIL
make[2]: *** [Makefile:197: test-unit-and-integration] Error 1
make[2]: Leaving directory '/home/squamata/project'
make[1]: *** [Makefile:192: test-with-database] Error 2
make[1]: Leaving directory '/home/squamata/project'
make: *** [Makefile:181: test-fullstack] Error 2

Exited with code exit status 2
(1-1/12)