|
+ 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
|
