Project

General

Profile

full-stack-shutdown-problem.t

mkittler, 2022-03-01 15:42

 
1
# OPENQA_BASEDIR: /home/squamata/project/test-results/fullstack/full-stack.d
2
# OPENQA_CONFIG: /home/squamata/project/test-results/fullstack/full-stack.d/config
3
[INFO] using database schema "public"
4
[info] [pid:14560] setting database search path to public when registering Minion plugin
5
ok 1 - assets are prefetched
6
# Used ports: {}
7
# Starting WebSocket service. Port: 9527
8
# Bogus: 0 | No wait: 0
9
# PID of openqa-websocket: 14565
10
# Starting WebUI service. Port: 9526
11
# PID of openqa-webapi: 14566
12
[info] [pid:14566] setting database search path to public when registering Minion plugin
13
[info] Listening at "http://127.0.0.1:9527"
14
Web application available at http://127.0.0.1:9527
15
# PID of openqa-livehandler: 14643
16
ok 2 - resultdir "/home/squamata/project/test-results/fullstack/full-stack.d/openqa/testresults" exists
17
ok 3 - on main page
18
ok 4 - no one logged in
19
ok 5 - click_ok'Login clicked'
20
ok 6 - back on main page
21
ok 7 - click_ok'disable tour permanently'
22
ok 8 - click_ok'confirm dismissing tour'
23
[warn] [pid:14566] Unable to wakeup scheduler: Connection refused
24
ok 9 - click_ok'Clicked All Tests to look for scheduled job'
25
ok 10 - tests followed
26
# Wait for jQuery successful: wait before checking for scheduled job
27
[debug] [pid:14566] Unrecognized referer 'localhost'
28
[debug] [pid:14566] Unrecognized referer 'localhost'
29
ok 11 - scheduled test page
30
ok 12 - test 1 is scheduled
31
ok 13 - no unexpected js warnings after test 1 was scheduled
32
# Subtest: testhelper
33
    ok 1 - BAIL_OUT invoked
34
[debug] [pid:14566] Unrecognized referer 'localhost'
35
    # scheduled jobs: [
36
    #   {
37
    #     'cluster_jobs' => {
38
    #       '1' => {
39
    #         'chained_children' => [],
40
    #         'chained_parents' => [],
41
    #         'directly_chained_children' => [],
42
    #         'directly_chained_parents' => [],
43
    #         'is_parent_or_initial_job' => 1,
44
    #         'ok' => 0,
45
    #         'parallel_children' => [],
46
    #         'parallel_parents' => [],
47
    #         'state' => 'scheduled'
48
    #       }
49
    #     },
50
    #     'id' => 1,
51
    #     'priority' => 50,
52
    #     'priority_offset' => 0,
53
    #     'state' => 'scheduled',
54
    #     'test' => 'core',
55
    #     'worker_classes' => [
56
    #       'qemu_i386'
57
    #     ]
58
    #   }
59
    # ]
60
    # free workers: []
61
    ok 2 - fail invoked
62
    1..2
63
ok 14 - testhelper
64
ok 15 - Worker started as IPC::Run=HASH(0x557426513988)
65
ok 16 - job with worker class qemu_i386 scheduled
66
[info] [pid:14649] worker 1:
67
 - config file:           /home/squamata/project/test-results/fullstack/full-stack.d/config/workers.ini
68
 - worker hostname:       1a81a2b0ff0f
69
 - isotovideo version:    25
70
 - websocket API version: 1
71
 - web UI hosts:          http://localhost:9526
72
 - class:                 qemu_i386,qemu_x86_64
73
 - no cleanup:            no
74
 - pool directory:        /home/squamata/project/test-results/fullstack/full-stack.d/openqa/pool/1
75
[info] [pid:14649] Project dir for host http://localhost:9526 is /home/squamata/project/test-results/fullstack/full-stack.d/openqa/share
76
[info] [pid:14649] Registering with openQA http://localhost:9526
77
ok 17 - at least one free worker with class qemu_i386 registered
78
[info] [pid:14649] Establishing ws connection via ws://localhost:9526/api/v1/ws/1
79
[debug] [pid:14560] +=----------------=+
80
[debug] [pid:14560] -> Scheduling new jobs.
81
[debug] [pid:14560] 	 Free workers: 1/1
82
[debug] [pid:14560] 	 Scheduled jobs: 1
83
[debug] [pid:14560] Need to schedule 1 parallel jobs for job 1 (with priority 50)
84
[info] [pid:14649] Registered and connected via websockets with openQA host http://localhost:9526 and worker ID 1
85
[debug] [pid:14560] Assigned job '1' to worker ID '1'
86
[debug] [pid:14560] [Job#1] Prepare for being processed by worker 1
87
[debug] [pid:14565] Updating seen of worker 1 from worker_status (free)
88
[debug] [pid:14565] Started to send message to 1 for job(s) 1
89
[debug] [pid:14560] Sent job(s) '1' to worker '1'
90
[debug] [pid:14560] Scheduler took 0.09654s to perform operations and allocated 1 jobs
91
[debug] [pid:14649] Accepting job 1 from http://localhost:9526.
92
[debug] [pid:14560] Allocated: { job => 1, worker => 1 }
93
[debug] [pid:14649] Setting job 1 from http://localhost:9526 up
94
[debug] [pid:14649] Preparing Mojo::IOLoop::ReadWriteProcess::Session
95
[info] [pid:14649] +++ setup notes +++
96
[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)
97
[debug] [pid:14649] Job settings:
98
[debug] [pid:14649] 
99
    ARCH=i386
100
    BUILD=1
101
    DISTRI=tinycore
102
    FLAVOR=flavor
103
    INTEGRATION_TESTS=1
104
    ISO=Core-7.2.iso
105
    JOBTOKEN=N503ZgOJZf1SW84y
106
    LOG_LEVEL=debug
107
    MACHINE=coolone
108
    NAME=00000001-tinycore-1-flavor-i386-Build1-core@coolone
109
    OPENQA_HOSTNAME=localhost:9526
110
    OPENQA_URL=http://localhost:9526
111
    PAUSE_AT=shutdown
112
    PRJDIR=/home/squamata/project/test-results/fullstack/full-stack.d/openqa/share
113
    PUBLISH_HDD_1=core-hdd.qcow2
114
    QEMU=i386
115
    QEMUPORT=20012
116
    QEMU_NO_FDC_SET=1
117
    QEMU_NO_KVM=1
118
    QEMU_NO_TABLET=1
119
    RETRY_DELAY=5
120
    RETRY_DELAY_IF_WEBUI_BUSY=60
121
    TEST=core
122
    UEFI_PFLASH_VARS=/usr/share/qemu/ovmf-x86_64.bin
123
    VERSION=1
124
    VNC=91
125
    WORKER_CLASS=qemu_i386,qemu_x86_64
126
    WORKER_HOSTNAME=127.0.0.1
127
    WORKER_ID=1
128
    WORKER_INSTANCE=1
129
[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"
130
[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"
131
[info] [pid:14649] Preparing cgroup to start isotovideo
132
[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.
133
# Wait for jQuery successful: wait_for_result_panel: waiting for '(?^u:State: running)' (count 0 of 3240)
134
[info] [pid:14649] You can define a custom slice with OPENQA_CGROUP_SLICE or indicating the base mount with MOJO_CGROUP_FS.
135
[info] [pid:14649] Starting isotovideo container
136
[debug] [pid:14649] Registered process:14656
137
[info] [pid:14656] 14656: WORKING 1
138
[debug] [pid:14656] +++ worker notes +++
139
[info] [pid:14649] isotovideo has been started (PID: 14656)
140
[debug] [pid:14649] Running job 1 from http://localhost:9526: 00000001-tinycore-1-flavor-i386-Build1-core@coolone.
141
[debug] [pid:14649] REST-API call: POST http://localhost:9526/api/v1/jobs/1/status
142
[debug] [pid:14565] Worker 1 accepted job 1
143
[debug] [pid:14565] Updating seen of worker 1 from worker_status (working)
144
[debug] [pid:14649] Upload concluded (no current module)
145
# Wait for jQuery successful: wait_for_result_panel: waiting for '(?^u:State: running)' (count 1 of 3240)
146
# Wait for jQuery successful: wait_for_result_panel: waiting for '(?^u:State: running)' (count 2 of 3240)
147
# Wait for jQuery successful: wait_for_result_panel: waiting for '(?^u:State: running)' (count 3 of 3240)
148
# Wait for jQuery successful: wait_for_result_panel: waiting for '(?^u:State: running)' (count 4 of 3240)
149
# Wait for jQuery successful: wait_for_result_panel: waiting for '(?^u:State: running)' (count 5 of 3240)
150
[debug] [pid:14566] Unrecognized referer 'localhost'
151
[debug] [pid:14566] Unrecognized referer 'localhost'
152
[debug] [pid:14566] Unrecognized referer 'localhost'
153
[debug] [pid:14643] connecting to os-autoinst command server for job 1 at ws://127.0.0.1:20013/N503ZgOJZf1SW84y/ws
154
[debug] [pid:14566] Unrecognized referer 'localhost'
155
[debug] [pid:14566] Unrecognized referer 'localhost'
156
[debug] [pid:14566] Asking the worker 1 to start providing livestream for job 1
157
[debug] [pid:14649] Starting livelog
158
[debug] [pid:14649] REST-API call: POST http://localhost:9526/api/v1/jobs/1/status
159
[debug] [pid:14649] Upload concluded (no current module)
160
# Wait for jQuery successful: wait_for_result_panel: waiting for '(?^u:State: running)' (count 6 of 3240)
161
ok 18 - \#nav-item-for-live present
162
ok 19 - test 1 is running
163
# Subtest: wait until developer console becomes available
164
[debug] [pid:14566] Asking worker 1 to stop providing livestream for job 1
165
[debug] [pid:14649] Stopping livelog
166
    # Waiting for 'URL for os-autoinst cmd srv' to become available
167
    # waiting for worker to propagate URL for os-autoinst cmd srv
168
    # Wait for jQuery successful: developer console available
169
    ok 1 - No unexpected js warnings
170
    ok 2 - found connection opened at 112
171
    1..2
172
ok 20 - wait until developer console becomes available
173
# Subtest: pause at certain test
174
    ok 1 - No unexpected js warnings
175
[debug] [pid:14649] REST-API call: POST http://localhost:9526/api/v1/jobs/1/status
176
[debug] [pid:14649] Upload concluded (no current module)
177
    # waiting for paused, developer console contains:
178
    # status: Connecting to ws://127.0.0.1:20013/N503ZgOJZf1SW84y/ws
179
    # status: Using proxy: no
180
    # status: Connection opened
181
    # ==> {"cmd":"status"}
182
    # Wait for jQuery successful: (?^u:(\"paused\":|\"test_execution_paused\":\".*\")) remaining wait time 1075s
183
    # waiting for paused, developer console contains:
184
    # status: Connecting to ws://127.0.0.1:20013/N503ZgOJZf1SW84y/ws
185
    # status: Using proxy: no
186
    # status: Connection opened
187
    # ==> {"cmd":"status"}
188
    # <== {"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}
189
    # <== {"can_handle":{"cmd":"backend_can_handle","function":"snapshots","json_cmd_token":"uuDcaiKN"},"current_api_function":"can_handle"}
190
    # <== {"current_test_full_name":"tests-boot","set_current_test":"boot"}
191
    # <== {"check_screen":{"check":0,"mustmatch":"core","timeout":15},"current_api_function":"assert_screen"}
192
    # <== {"current_api_function":"send_key","send_key":{"cmd":"backend_send_key","json_cmd_token":"xYluZbnG","key":"ret"}}
193
    # <== {"check_screen":{"check":0,"mustmatch":"on_prompt","timeout":90},"current_api_function":"assert_screen"}
194
    # Wait for jQuery successful: (?^u:(\"paused\":|\"test_execution_paused\":\".*\")) remaining wait time 1070s
195
[debug] [pid:14649] REST-API call: POST http://localhost:9526/api/v1/jobs/1/status
196
[debug] [pid:14649] Upload concluded (at boot)
197
    # Wait for jQuery successful: (?^u:(\"paused\":|\"test_execution_paused\":\".*\")) remaining wait time 1065s
198
    ok 2 - found paused at 1451
199
    ok 3 - No unexpected js warnings
200
    ok 4 - found resume at 2286
201
    1..4
202
ok 21 - pause at certain test
203
# Subtest: schedule job
204
[debug] [pid:14566] Unrecognized referer 'localhost'
205
[debug] [pid:14566] Unrecognized referer 'localhost'
206
[debug] [pid:14566] Unrecognized referer 'localhost'
207
[debug] [pid:14566] Unrecognized referer 'localhost'
208
[debug] [pid:14643] connecting to os-autoinst command server for job 1 at ws://127.0.0.1:20013/N503ZgOJZf1SW84y/ws
209
[debug] [pid:14566] Asking the worker 1 to start providing livestream for job 1
210
[debug] [pid:14649] Starting livelog
211
[debug] [pid:14649] REST-API call: POST http://localhost:9526/api/v1/jobs/1/status
212
[debug] [pid:14566] Unrecognized referer 'localhost'
213
[debug] [pid:14566] creating f41/844/68dbb276a03240907d0e7e500d.png
214
[debug] [pid:14566] creating 68d/7ac/83452b72555f8a6b386629f91f.png
215
[debug] [pid:14880] Optimizing /home/squamata/project/test-results/fullstack/full-stack.d/openqa/pool/1/testresults/boot-2.png
216
    # Wait for jQuery successful: wait_for_result_panel: waiting for '(?^u:Result: passed)' (count 0 of 3240)
217
[debug] [pid:14880] Uploading artefact boot-2.png as 68d7ac83452b72555f8a6b386629f91f
218
[debug] [pid:14880] Optimizing /home/squamata/project/test-results/fullstack/full-stack.d/openqa/pool/1/testresults/.thumbs/boot-2.png
219
[debug] [pid:14880] Uploading artefact boot-2.png as 68d7ac83452b72555f8a6b386629f91f
220
[debug] [pid:14880] Optimizing /home/squamata/project/test-results/fullstack/full-stack.d/openqa/pool/1/testresults/boot-1.png
221
[debug] [pid:14880] Uploading artefact boot-1.png as f4184468dbb276a03240907d0e7e500d
222
[debug] [pid:14880] Optimizing /home/squamata/project/test-results/fullstack/full-stack.d/openqa/pool/1/testresults/.thumbs/boot-1.png
223
[debug] [pid:14880] Uploading artefact boot-1.png as f4184468dbb276a03240907d0e7e500d
224
[debug] [pid:14649] Upload concluded (up to boot)
225
    # Wait for jQuery successful: wait_for_result_panel: waiting for '(?^u:Result: passed)' (count 1 of 3240)
226
    # Wait for jQuery successful: wait_for_result_panel: waiting for '(?^u:Result: passed)' (count 2 of 3240)
227
[debug] [pid:14565] Updating seen of worker 1 from worker_status (working)
228
[debug] [pid:14649] REST-API call: POST http://localhost:9526/api/v1/jobs/1/status
229
[debug] [pid:14649] Upload concluded (at shutdown)
230
    # Wait for jQuery successful: wait_for_result_panel: waiting for '(?^u:Result: passed)' (count 3 of 3240)
231
    # Wait for jQuery successful: wait_for_result_panel: waiting for '(?^u:Result: passed)' (count 4 of 3240)
232
[debug] [pid:14649] REST-API call: POST http://localhost:9526/api/v1/jobs/1/status
233
[debug] [pid:14649] Upload concluded (at shutdown)
234
    # Wait for jQuery successful: wait_for_result_panel: waiting for '(?^u:Result: passed)' (count 5 of 3240)
235
    # Wait for jQuery successful: wait_for_result_panel: waiting for '(?^u:Result: passed)' (count 6 of 3240)
236
[debug] [pid:14649] REST-API call: POST http://localhost:9526/api/v1/jobs/1/status
237
[debug] [pid:14649] Upload concluded (at shutdown)
238
    # Wait for jQuery successful: wait_for_result_panel: waiting for '(?^u:Result: passed)' (count 7 of 3240)
239
    # Wait for jQuery successful: wait_for_result_panel: waiting for '(?^u:Result: passed)' (count 8 of 3240)
240
[debug] [pid:14649] REST-API call: POST http://localhost:9526/api/v1/jobs/1/status
241
[debug] [pid:14649] Upload concluded (at shutdown)
242
    # Wait for jQuery successful: wait_for_result_panel: waiting for '(?^u:Result: passed)' (count 9 of 3240)
243
[debug] [pid:14566] Unrecognized referer 'localhost'
244
[debug] [pid:14566] Unrecognized referer 'localhost'
245
[debug] looking for "f41/844/.thumbs/68dbb276a03240907d0e7e500d.png" in [
246
  "/home/squamata/project/test-results/fullstack/full-stack.d/openqa/images",
247
]
248
[debug] found bless({
249
  path => "/home/squamata/project/test-results/fullstack/full-stack.d/openqa/images/f41/844/.thumbs/68dbb276a03240907d0e7e500d.png",
250
  pid  => 14566,
251
}, "Mojo::Asset::File")
252
[debug] looking for "68d/7ac/.thumbs/83452b72555f8a6b386629f91f.png" in [
253
  "/home/squamata/project/test-results/fullstack/full-stack.d/openqa/images",
254
]
255
[debug] found bless({
256
  path => "/home/squamata/project/test-results/fullstack/full-stack.d/openqa/images/68d/7ac/.thumbs/83452b72555f8a6b386629f91f.png",
257
  pid  => 14566,
258
}, "Mojo::Asset::File")
259
    # Wait for jQuery successful: wait_for_result_panel: waiting for '(?^u:Result: passed)' (count 10 of 3240)
260
[debug] [pid:14649] REST-API call: POST http://localhost:9526/api/v1/jobs/1/status
261
[debug] [pid:14566] creating 68d/7ac/83452b72555f8a6b386629f91f.png
262
[debug] [pid:14566] creating 68d/7ac/83452b72555f8a6b386629f91f.png
263
    # Wait for jQuery successful: wait_for_result_panel: waiting for '(?^u:Result: passed)' (count 11 of 3240)
264
[debug] [pid:14566] creating f1e/d19/aa4bfd65612d1d5fc58b221bf2.png
265
[debug] [pid:14890] Optimizing /home/squamata/project/test-results/fullstack/full-stack.d/openqa/pool/1/testresults/shutdown-2.png
266
[debug] [pid:14890] Uploading artefact shutdown-2.png as f1ed19aa4bfd65612d1d5fc58b221bf2
267
[debug] [pid:14890] Optimizing /home/squamata/project/test-results/fullstack/full-stack.d/openqa/pool/1/testresults/.thumbs/shutdown-2.png
268
[debug] [pid:14890] Uploading artefact shutdown-2.png as f1ed19aa4bfd65612d1d5fc58b221bf2
269
[debug] [pid:14649] Upload concluded (up to shutdown)
270
    # Wait for jQuery successful: wait_for_result_panel: waiting for '(?^u:Result: passed)' (count 12 of 3240)
271
[info] [pid:14649] Isotovideo exit status: 0
272
[debug] [pid:14649] Stopping job 1 from http://localhost:9526: 00000001-tinycore-1-flavor-i386-Build1-core@coolone - reason: done
273
[debug] [pid:14649] REST-API call: POST http://localhost:9526/api/v1/jobs/1/status
274
[info] [pid:14649] +++ worker notes +++
275
[info] [pid:14649] End time: 2022-03-01 15:27:34
276
[info] [pid:14649] Result: done
277
[info] [pid:14899] Uploading core-hdd.qcow2
278
[info] [pid:14899] Uploading core-hdd.qcow2 using multiple chunks
279
[info] [pid:14899] core-hdd.qcow2: local upload (no chunks needed)
280
[info] [pid:14899] Uploading video.ogv
281
[debug] [pid:14899] Uploading artefact video.ogv
282
[info] [pid:14899] Uploading vars.json
283
[debug] [pid:14899] Uploading artefact vars.json
284
[info] [pid:14899] Uploading autoinst-log.txt
285
[debug] [pid:14899] Uploading artefact autoinst-log.txt
286
    # Wait for jQuery successful: wait_for_result_panel: waiting for '(?^u:Result: passed)' (count 13 of 3240)
287
[info] [pid:14899] Uploading worker-log.txt
288
[debug] [pid:14899] Uploading artefact worker-log.txt
289
[info] [pid:14899] Uploading serial0.txt
290
[debug] [pid:14899] Uploading artefact serial0.txt
291
[info] [pid:14899] Uploading video_time.vtt
292
[debug] [pid:14899] Uploading artefact video_time.vtt
293
[info] [pid:14899] Uploading serial_terminal.txt
294
[debug] [pid:14899] Uploading artefact serial_terminal.txt
295
[info] [pid:14899] Uploading virtio_console1.log
296
[debug] [pid:14899] Uploading artefact virtio_console1.log
297
[debug] [pid:14649] Considering job 1 as regularly done
298
[debug] [pid:14649] REST-API call: POST http://localhost:9526/api/v1/jobs/1/status
299
[debug] [pid:14566] creating 68d/7ac/83452b72555f8a6b386629f91f.png
300
[debug] [pid:14566] creating 68d/7ac/83452b72555f8a6b386629f91f.png
301
[debug] [pid:14566] creating f41/844/68dbb276a03240907d0e7e500d.png
302
[debug] [pid:14566] creating 68d/7ac/83452b72555f8a6b386629f91f.png
303
[debug] [pid:14566] creating f1e/d19/aa4bfd65612d1d5fc58b221bf2.png
304
[debug] [pid:14649] Upload concluded (no current module)
305
[debug] [pid:14649] REST-API call: POST http://localhost:9526/api/v1/jobs/1/set_done?worker_id=1
306
[debug] [pid:14649] Job 1 from http://localhost:9526 finished - reason: done
307
[debug] [pid:14649] Cleaning up for next job
308
    # Wait for jQuery successful: wait_for_result_panel: waiting for '(?^u:Result: passed)' (count 14 of 3240)
309
    # Wait for jQuery successful: wait_for_result_panel: waiting for '(?^u:Result: passed)' (count 15 of 3240)
310
    # Wait for jQuery successful: wait_for_result_panel: waiting for '(?^u:Result: passed)' (count 16 of 3240)
311
    # Wait for jQuery successful: wait_for_result_panel: waiting for '(?^u:Result: passed)' (count 17 of 3240)
312
    # Wait for jQuery successful: wait_for_result_panel: waiting for '(?^u:Result: passed)' (count 18 of 3240)
313
    # Wait for jQuery successful: wait_for_result_panel: waiting for '(?^u:Result: passed)' (count 19 of 3240)
314
[debug] [pid:14566] Unrecognized referer 'localhost'
315
[debug] [pid:14566] Unrecognized referer 'localhost'
316
[debug] [pid:14566] Unrecognized referer 'localhost'
317
[debug] looking for "f1e/d19/.thumbs/aa4bfd65612d1d5fc58b221bf2.png" in [
318
  "/home/squamata/project/test-results/fullstack/full-stack.d/openqa/images",
319
]
320
[debug] found bless({
321
  path => "/home/squamata/project/test-results/fullstack/full-stack.d/openqa/images/f1e/d19/.thumbs/aa4bfd65612d1d5fc58b221bf2.png",
322
  pid  => 14566,
323
}, "Mojo::Asset::File")
324
    # Wait for jQuery successful: wait_for_result_panel: waiting for '(?^u:Result: passed)' (count 20 of 3240)
325
    ok 1 - job 1 passed
326
    ok 2 - autoinst log file generated
327
    ok 3 - worker log file generated
328
    ok 4 - autoinst log uploaded
329
    ok 5 - worker log uploaded
330
    ok 6 - local upload feature used
331
    ok 7 - image of hdd uploaded
332
    ok 8 - can stat /home/squamata/project/test-results/fullstack/full-stack.d/openqa/share/factory/hdd/core-hdd.qcow2
333
    ok 9 - exported image has correct permissions (420 -> 0644)
334
    ok 10 - regular post via client script
335
    ok 11 - send JSON data via client
336
    ok 12 - group has been altered correctly
337
    1..12
338
ok 22 - schedule job
339
# Subtest: clone job that crashes
340
[debug] Restarting job 1
341
[debug] [pid:14566] Duplicating jobs: {
342
  1 => {
343
         chained_children => [],
344
         chained_parents => [],
345
         directly_chained_children => [],
346
         directly_chained_parents => [],
347
         is_parent_or_initial_job => 1,
348
         ok => 1,
349
         parallel_children => [],
350
         parallel_parents => [],
351
         state => "done",
352
       },
353
}
354
[debug] [pid:14566] Job 1 duplicated as 2
355
[warn] [pid:14566] Unable to wakeup scheduler: Connection refused
356
    ok 1 - client returned new test_url for test 2
357
[debug] [pid:14566] Unrecognized referer 'localhost'
358
    ok 2 - test 1 is restarted
359
[debug] looking for "68d/7ac/.thumbs/83452b72555f8a6b386629f91f.png" in [
360
  "/home/squamata/project/test-results/fullstack/full-stack.d/openqa/images",
361
]
362
[debug] found bless({
363
  path => "/home/squamata/project/test-results/fullstack/full-stack.d/openqa/images/68d/7ac/.thumbs/83452b72555f8a6b386629f91f.png",
364
  pid  => 14566,
365
}, "Mojo::Asset::File")
366
[debug] looking for "f41/844/.thumbs/68dbb276a03240907d0e7e500d.png" in [
367
  "/home/squamata/project/test-results/fullstack/full-stack.d/openqa/images",
368
]
369
[debug] found bless({
370
  path => "/home/squamata/project/test-results/fullstack/full-stack.d/openqa/images/f41/844/.thumbs/68dbb276a03240907d0e7e500d.png",
371
  pid  => 14566,
372
}, "Mojo::Asset::File")
373
[debug] [pid:14566] Unrecognized referer 'localhost'
374
[debug] looking for "f1e/d19/.thumbs/aa4bfd65612d1d5fc58b221bf2.png" in [
375
  "/home/squamata/project/test-results/fullstack/full-stack.d/openqa/images",
376
]
377
[debug] found bless({
378
  path => "/home/squamata/project/test-results/fullstack/full-stack.d/openqa/images/f1e/d19/.thumbs/aa4bfd65612d1d5fc58b221bf2.png",
379
  pid  => 14566,
380
}, "Mojo::Asset::File")
381
    ok 3 - click_ok'clicked link to test 2'
382
[debug] [pid:14566] Unrecognized referer 'localhost'
383
    ok 4 - job with worker class qemu_i386 scheduled
384
[debug] [pid:14566] Unrecognized referer 'localhost'
385
    ok 5 - at least one free worker with class qemu_i386 registered
386
[debug] [pid:14560] +=----------------=+
387
[debug] [pid:14560] -> Scheduling new jobs.
388
[debug] [pid:14560] 	 Free workers: 1/1
389
[debug] [pid:14560] 	 Scheduled jobs: 1
390
[debug] [pid:14560] Need to schedule 1 parallel jobs for job 2 (with priority 50)
391
[debug] [pid:14560] Assigned job '2' to worker ID '1'
392
[debug] [pid:14560] [Job#2] Prepare for being processed by worker 1
393
[debug] [pid:14565] Started to send message to 1 for job(s) 2
394
[debug] [pid:14560] Sent job(s) '2' to worker '1'
395
[debug] [pid:14560] Scheduler took 0.11342s to perform operations and allocated 1 jobs
396
[debug] [pid:14560] Allocated: { job => 2, worker => 1 }
397
[debug] [pid:14649] Accepting job 2 from http://localhost:9526.
398
[debug] [pid:14649] Setting job 2 from http://localhost:9526 up
399
[debug] [pid:14649] Preparing Mojo::IOLoop::ReadWriteProcess::Session
400
[info] [pid:14649] +++ setup notes +++
401
[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)
402
[debug] [pid:14649] Job settings:
403
[debug] [pid:14649] 
404
    ARCH=i386
405
    BUILD=1
406
    DISTRI=tinycore
407
    FLAVOR=flavor
408
    INTEGRATION_TESTS=1
409
    ISO=Core-7.2.iso
410
    JOBTOKEN=G7cORS23YXmPkIHP
411
    LOG_LEVEL=debug
412
    MACHINE=coolone
413
    NAME=00000002-tinycore-1-flavor-i386-Build1-core@coolone
414
    OPENQA_HOSTNAME=localhost:9526
415
    OPENQA_URL=http://localhost:9526
416
    PAUSE_AT=shutdown
417
    PRJDIR=/home/squamata/project/test-results/fullstack/full-stack.d/openqa/share
418
    PUBLISH_HDD_1=core-hdd.qcow2
419
    QEMU=i386
420
    QEMUPORT=20012
421
    QEMU_NO_FDC_SET=1
422
    QEMU_NO_KVM=1
423
    QEMU_NO_TABLET=1
424
    RETRY_DELAY=5
425
    RETRY_DELAY_IF_WEBUI_BUSY=60
426
    TEST=core
427
    UEFI_PFLASH_VARS=/usr/share/qemu/ovmf-x86_64.bin
428
    VERSION=1
429
    VNC=91
430
    WORKER_CLASS=qemu_i386,qemu_x86_64
431
    WORKER_HOSTNAME=127.0.0.1
432
    WORKER_ID=1
433
    WORKER_INSTANCE=1
434
[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"
435
[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"
436
[info] [pid:14649] Preparing cgroup to start isotovideo
437
[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.
438
[info] [pid:14649] You can define a custom slice with OPENQA_CGROUP_SLICE or indicating the base mount with MOJO_CGROUP_FS.
439
[info] [pid:14649] Starting isotovideo container
440
    # Wait for jQuery successful: wait_for_result_panel: waiting for '(?^u:State: running)' (count 0 of 3240)
441
[debug] [pid:14649] Registered process:14912
442
[info] [pid:14912] 14912: WORKING 2
443
[info] [pid:14649] isotovideo has been started (PID: 14912)
444
[debug] [pid:14912] +++ worker notes +++
445
[debug] [pid:14649] Running job 2 from http://localhost:9526: 00000002-tinycore-1-flavor-i386-Build1-core@coolone.
446
[debug] [pid:14649] REST-API call: POST http://localhost:9526/api/v1/jobs/2/status
447
[debug] [pid:14565] Worker 1 accepted job 2
448
[debug] [pid:14565] Updating seen of worker 1 from worker_status (working)
449
[debug] [pid:14649] Upload concluded (no current module)
450
    # Wait for jQuery successful: wait_for_result_panel: waiting for '(?^u:State: running)' (count 1 of 3240)
451
    # Wait for jQuery successful: wait_for_result_panel: waiting for '(?^u:State: running)' (count 2 of 3240)
452
    # Wait for jQuery successful: wait_for_result_panel: waiting for '(?^u:State: running)' (count 3 of 3240)
453
    # Wait for jQuery successful: wait_for_result_panel: waiting for '(?^u:State: running)' (count 4 of 3240)
454
    # Wait for jQuery successful: wait_for_result_panel: waiting for '(?^u:State: running)' (count 5 of 3240)
455
    # Wait for jQuery successful: wait_for_result_panel: waiting for '(?^u:State: running)' (count 6 of 3240)
456
    # Wait for jQuery successful: wait_for_result_panel: waiting for '(?^u:State: running)' (count 7 of 3240)
457
    # Wait for jQuery successful: wait_for_result_panel: waiting for '(?^u:State: running)' (count 8 of 3240)
458
    # Wait for jQuery successful: wait_for_result_panel: waiting for '(?^u:State: running)' (count 9 of 3240)
459
[debug] [pid:14566] Unrecognized referer 'localhost'
460
[debug] [pid:14566] Unrecognized referer 'localhost'
461
[debug] [pid:14566] Unrecognized referer 'localhost'
462
[debug] [pid:14566] Unrecognized referer 'localhost'
463
[debug] [pid:14643] connecting to os-autoinst command server for job 2 at ws://127.0.0.1:20013/G7cORS23YXmPkIHP/ws
464
[debug] [pid:14566] Unrecognized referer 'localhost'
465
[debug] [pid:14566] Asking the worker 1 to start providing livestream for job 2
466
[debug] [pid:14649] Starting livelog
467
[debug] [pid:14649] REST-API call: POST http://localhost:9526/api/v1/jobs/2/status
468
[debug] [pid:14649] Upload concluded (at boot)
469
    # Wait for jQuery successful: wait_for_result_panel: waiting for '(?^u:State: running)' (count 10 of 3240)
470
    ok 6 - \#nav-item-for-live present
471
    ok 7 - job 2 running
472
[info] [pid:14649] Received signal TERM
473
[debug] [pid:14649] Stopping job 2 from http://localhost:9526: 00000002-tinycore-1-flavor-i386-Build1-core@coolone - reason: quit
474
[debug] [pid:14649] REST-API call: POST http://localhost:9526/api/v1/jobs/2/status
475
[debug] [pid:14649] Announcing job termination (due to quit) to command server via http://localhost:20013/G7cORS23YXmPkIHP/broadcast
476
[info] [pid:14649] Isotovideo exit status: 1
477
[info] [pid:14649] +++ worker notes +++
478
[info] [pid:14649] End time: 2022-03-01 15:27:50
479
[info] [pid:14649] Result: quit
480
[debug] [pid:14649] Job 2 stopped as incomplete
481
[debug] [pid:14649] Duplicating job 2
482
[debug] [pid:14649] REST-API call: POST http://localhost:9526/api/v1/jobs/2/duplicate?dup_type_auto=1
483
[debug] Restarting job 2
484
[debug] [pid:14566] Duplicating jobs: {
485
  2 => {
486
         chained_children => [],
487
         chained_parents => [],
488
         directly_chained_children => [],
489
         directly_chained_parents => [],
490
         is_parent_or_initial_job => 1,
491
         ok => 0,
492
         parallel_children => [],
493
         parallel_parents => [],
494
         state => "uploading",
495
       },
496
}
497
[debug] [pid:14566] Job 2 duplicated as 3
498
[warn] [pid:14566] Unable to wakeup scheduler: Connection refused
499
[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.
500
	Mojo::File::slurp(Mojo::File=SCALAR(0x55b84ce4c328)) called at /home/squamata/project/script/../lib/OpenQA/Worker/Job.pm line 1098
501
	eval {...} called at /home/squamata/project/script/../lib/OpenQA/Worker/Job.pm line 1098
502
	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
503
	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
504
	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
505
	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
506
	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
507
	OpenQA::Worker::Job::__ANON__(HASH(0x55b84cdfdcf8)) called at /home/squamata/project/script/../lib/OpenQA/Worker/WebUIConnection.pm line 301
508
	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
509
	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
510
	Mojo::UserAgent::_finish(OpenQA::Client=HASH(0x55b84cd14910), "764adede50dff3234cd1a0a414df5489") called at /usr/lib/perl5/vendor_perl/5.26.1/Mojo/UserAgent.pm line 276
511
	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
512
	Mojo::UserAgent::__ANON__(Mojo::IOLoop::Stream=HASH(0x55b84ce4ff58)) called at /usr/lib/perl5/vendor_perl/5.26.1/Mojo/EventEmitter.pm line 15
513
	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
514
	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
515
	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
516
	eval {...} called at /usr/lib/perl5/vendor_perl/5.26.1/Mojo/Reactor/Poll.pm line 141
517
	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
518
	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
519
	Mojo::Reactor::Poll::start(Mojo::Reactor::Poll=HASH(0x55b84acab0d8)) called at /usr/lib/perl5/vendor_perl/5.26.1/Mojo/IOLoop.pm line 134
520
	Mojo::IOLoop::start(Mojo::IOLoop=HASH(0x55b84aa062d0)) called at /home/squamata/project/script/../lib/OpenQA/Worker.pm line 376
521
	OpenQA::Worker::exec(OpenQA::Worker=HASH(0x55b84cd05c18)) called at ./script/worker line 126
522
[debug] [pid:14649] REST-API call: POST http://localhost:9526/api/v1/jobs/2/status
523
[debug] [pid:14566] creating f41/844/68dbb276a03240907d0e7e500d.png
524
[debug] [pid:14649] Upload concluded (at boot)
525
[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
526
[debug] [pid:14566] checking take over from 1: GOOD vs assert_screen:none,shutdown:none
527
[debug] [pid:14649] Job 2 from http://localhost:9526 finished - reason: quit
528
[debug] [pid:14649] Informing http://localhost:9526 that we are going offline
529
[info] [pid:14565] Worker 1 websocket connection closed - 1006
530
    # Wait for jQuery successful: wait_for_result_panel: waiting for '(?^u:Result: incomplete)' (count 0 of 3240)
531
    # Wait for jQuery successful: wait_for_result_panel: waiting for '(?^u:Result: incomplete)' (count 1 of 3240)
532
    # Wait for jQuery successful: wait_for_result_panel: waiting for '(?^u:Result: incomplete)' (count 2 of 3240)
533
[debug] [pid:14566] Unrecognized referer 'localhost'
534
[debug] [pid:14566] Unrecognized referer 'localhost'
535
[debug] [pid:14566] Unrecognized referer 'localhost'
536
[debug] looking for "f41/844/.thumbs/68dbb276a03240907d0e7e500d.png" in [
537
  "/home/squamata/project/test-results/fullstack/full-stack.d/openqa/images",
538
]
539
[debug] found bless({
540
  path => "/home/squamata/project/test-results/fullstack/full-stack.d/openqa/images/f41/844/.thumbs/68dbb276a03240907d0e7e500d.png",
541
  pid  => 14566,
542
}, "Mojo::Asset::File")
543
    # Wait for jQuery successful: wait_for_result_panel: waiting for '(?^u:Result: incomplete)' (count 3 of 3240)
544
    ok 8 - job 2 crashed
545
    ok 9 - test 2 is restarted by killing worker
546
    1..9
547
ok 23 - clone job that crashes
548
# Subtest: cancel a scheduled job
549
[warn] [pid:14566] Unable to wakeup scheduler: Connection refused
550
    ok 1 - click_ok'Clicked All Tests'
551
    # Wait for jQuery successful: wait for All Tests displayed before looking for 3
552
[debug] [pid:14566] Unrecognized referer 'localhost'
553
    ok 2 - click_ok'clicked on 3'
554
[debug] [pid:14566] Unrecognized referer 'localhost'
555
[debug] [pid:14566] Unrecognized referer 'localhost'
556
    # Wait for jQuery successful: wait_for_result_panel: waiting for '(?^u:State: scheduled)' (count 0 of 8100)
557
    ok 3 - Job 3 was scheduled
558
    1..3
559
ok 24 - cancel a scheduled job
560
ok 25 - click_ok'Clicked All Tests to go to test 4'
561
# Wait for jQuery successful: wait for All Tests displayed before looking for 3
562
[debug] [pid:14566] Unrecognized referer 'localhost'
563
ok 26 - click_ok'clicked on 4'
564
ok 27 - scheduled test page
565
[debug] [pid:14566] Unrecognized referer 'localhost'
566
ok 28 - test 4 is scheduled
567
ok 29 - no unexpected js warnings after test 4 was scheduled
568
ok 30 - Worker started as IPC::Run=HASH(0x557426604aa8)
569
[debug] [pid:14566] Unrecognized referer 'localhost'
570
ok 31 - job with worker class qemu_i386 scheduled
571
[info] [pid:15121] worker 1:
572
 - config file:           /home/squamata/project/test-results/fullstack/full-stack.d/config/workers.ini
573
 - worker hostname:       1a81a2b0ff0f
574
 - isotovideo version:    25
575
 - websocket API version: 1
576
 - web UI hosts:          http://localhost:9526
577
 - class:                 qemu_i386,qemu_x86_64
578
 - no cleanup:            no
579
 - pool directory:        /home/squamata/project/test-results/fullstack/full-stack.d/openqa/pool/1
580
[info] [pid:15121] Project dir for host http://localhost:9526 is /home/squamata/project/test-results/fullstack/full-stack.d/openqa/share
581
[info] [pid:15121] Registering with openQA http://localhost:9526
582
[info] [pid:15121] Establishing ws connection via ws://localhost:9526/api/v1/ws/1
583
[info] [pid:15121] Registered and connected via websockets with openQA host http://localhost:9526 and worker ID 1
584
[debug] [pid:14565] Updating seen of worker 1 from worker_status (free)
585
ok 32 - at least one free worker with class qemu_i386 registered
586
[debug] [pid:14560] +=----------------=+
587
[debug] [pid:14560] -> Scheduling new jobs.
588
[debug] [pid:14560] 	 Free workers: 1/1
589
[debug] [pid:14560] 	 Scheduled jobs: 1
590
[debug] [pid:14560] Need to schedule 1 parallel jobs for job 4 (with priority 50)
591
[debug] [pid:14560] Assigned job '4' to worker ID '1'
592
[debug] [pid:14560] [Job#4] Prepare for being processed by worker 1
593
[debug] [pid:14565] Started to send message to 1 for job(s) 4
594
[debug] [pid:14560] Sent job(s) '4' to worker '1'
595
[debug] [pid:14560] Scheduler took 0.12918s to perform operations and allocated 1 jobs
596
[debug] [pid:14560] Allocated: { job => 4, worker => 1 }
597
# Subtest: incomplete job because of setup failure
598
[debug] [pid:15121] Accepting job 4 from http://localhost:9526.
599
[debug] [pid:15121] Setting job 4 from http://localhost:9526 up
600
[debug] [pid:15121] Preparing Mojo::IOLoop::ReadWriteProcess::Session
601
[info] [pid:15121] +++ setup notes +++
602
[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)
603
[debug] [pid:15121] Job settings:
604
[debug] [pid:15121] 
605
    ARCH=i386
606
    BUILD=1
607
    DISTRI=tinycore
608
    FLAVOR=flavor
609
    HDD_1=nihilist_disk.hda
610
    INTEGRATION_TESTS=1
611
    ISO=Core-7.2.iso
612
    JOBTOKEN=Hi1Jbzdefw7ROxDn
613
    LOG_LEVEL=debug
614
    MACHINE=noassets
615
    NAME=00000004-tinycore-1-flavor-i386-Build1-core@noassets
616
    OPENQA_HOSTNAME=localhost:9526
617
    OPENQA_URL=http://localhost:9526
618
    PRJDIR=/home/squamata/project/test-results/fullstack/full-stack.d/openqa/share
619
    PUBLISH_HDD_1=core-hdd.qcow2
620
    QEMU=i386
621
    QEMUPORT=20012
622
    QEMU_NO_FDC_SET=1
623
    QEMU_NO_KVM=1
624
    QEMU_NO_TABLET=1
625
    RETRY_DELAY=5
626
    RETRY_DELAY_IF_WEBUI_BUSY=60
627
    TEST=core
628
    UEFI_PFLASH_VARS=/usr/share/qemu/ovmf-x86_64.bin
629
    VERSION=1
630
    VNC=91
631
    WORKER_CLASS=qemu_i386,qemu_x86_64
632
    WORKER_HOSTNAME=127.0.0.1
633
    WORKER_ID=1
634
    WORKER_INSTANCE=1
635
[error] [pid:15121] HDD_1 handling Cannot find HDD_1 asset hdd/nihilist_disk.hda!
636
[error] [pid:15121] Unable to setup job 4: Cannot find HDD_1 asset hdd/nihilist_disk.hda!
637
[debug] [pid:15121] Stopping job 4 from http://localhost:9526: 00000004-tinycore-1-flavor-i386-Build1-core@noassets - reason: setup failure
638
[debug] [pid:15121] REST-API call: POST http://localhost:9526/api/v1/jobs/4/status
639
    # Wait for jQuery successful: wait_for_result_panel: waiting for '(?^u:Result: incomplete)' (count 0 of 3240)
640
[debug] [pid:14565] Worker 1 accepted job 4
641
[info] [pid:15121] +++ worker notes +++
642
[info] [pid:15121] End time: 2022-03-01 15:27:59
643
[info] [pid:15121] Result: setup failure
644
[info] [pid:15127] Uploading autoinst-log.txt
645
[debug] [pid:15127] Uploading artefact autoinst-log.txt
646
[info] [pid:15127] Uploading worker-log.txt
647
[debug] [pid:15127] Uploading artefact worker-log.txt
648
[debug] [pid:15121] Job 4 stopped as incomplete
649
[warn] [pid:15121] Unable to upload results of the job because no command server URL or worker ID have been set.
650
[debug] [pid:15121] Upload concluded (no current module)
651
[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
652
[debug] [pid:15121] Job 4 from http://localhost:9526 finished - reason: setup failure
653
[debug] [pid:15121] Cleaning up for next job
654
    # Wait for jQuery successful: wait_for_result_panel: waiting for '(?^u:Result: incomplete)' (count 1 of 3240)
655
    # Wait for jQuery successful: wait_for_result_panel: waiting for '(?^u:Result: incomplete)' (count 2 of 3240)
656
    # Wait for jQuery successful: wait_for_result_panel: waiting for '(?^u:Result: incomplete)' (count 3 of 3240)
657
    # Wait for jQuery successful: wait_for_result_panel: waiting for '(?^u:Result: incomplete)' (count 4 of 3240)
658
    # Wait for jQuery successful: wait_for_result_panel: waiting for '(?^u:Result: incomplete)' (count 5 of 3240)
659
[debug] [pid:14566] Unrecognized referer 'localhost'
660
[debug] [pid:14566] Unrecognized referer 'localhost'
661
    # Wait for jQuery successful: wait_for_result_panel: waiting for '(?^u:Result: incomplete)' (count 6 of 3240)
662
    ok 1 - Job 4 crashed
663
    # Waiting for 'autoinst-log.txt' to become available
664
    ok 2 - Test 4 result correct: setup failure
665
    ok 3 - Test 4 correct autoinst setup notes
666
    ok 4 - Test 4: upload of autoinst-log.txt logged
667
[info] [pid:15121] Received signal TERM
668
[debug] [pid:15121] Informing http://localhost:9526 that we are going offline
669
[info] [pid:14565] Worker 1 websocket connection closed - 1006
670
    1..4
671
ok 33 - incomplete job because of setup failure
672
ok 34 - Setting up Cache directory
673
ok 35 - Config file created
674
# Subtest: Cache tests
675
    ok 1 - cache.sqlite is not present
676
    # Starting cache minion worker
677
    # Waiting for 'cache service at http://127.0.0.1:9530' to become available
678
    # Starting worker cache service on port 9530
679
    # Waiting for 'cache service worker' to become available
680
[warn] [pid:14566] Unable to wakeup scheduler: Connection refused
681
[debug] [pid:14566] Unrecognized referer 'localhost'
682
    ok 2 - test 5 is scheduled
683
    ok 3 - Worker started as IPC::Run=HASH(0x55742670c998)
684
[debug] [pid:14566] Unrecognized referer 'localhost'
685
    ok 4 - job with worker class qemu_i386 scheduled
686
[info] [pid:15136] worker 1:
687
 - config file:           /home/squamata/project/test-results/fullstack/full-stack.d/config/workers.ini
688
 - worker hostname:       1a81a2b0ff0f
689
 - isotovideo version:    25
690
 - websocket API version: 1
691
 - web UI hosts:          http://localhost:9526
692
 - class:                 qemu_i386,qemu_x86_64
693
 - no cleanup:            no
694
 - pool directory:        /home/squamata/project/test-results/fullstack/full-stack.d/openqa/pool/1
695
[info] [pid:15136] CACHE: caching is enabled, setting up /home/squamata/project/test-results/fullstack/full-stack.d/cache/localhost
696
[info] [pid:15136] Project dir for host http://localhost:9526 is /home/squamata/project/test-results/fullstack/full-stack.d/openqa/share
697
[info] [pid:15136] Registering with openQA http://localhost:9526
698
[info] [pid:15136] Establishing ws connection via ws://localhost:9526/api/v1/ws/1
699
[info] [pid:15136] Registered and connected via websockets with openQA host http://localhost:9526 and worker ID 1
700
[debug] [pid:14565] Updating seen of worker 1 from worker_status (free)
701
    ok 5 - at least one free worker with class qemu_i386 registered
702
[debug] [pid:14560] +=----------------=+
703
[debug] [pid:14560] -> Scheduling new jobs.
704
[debug] [pid:14560] 	 Free workers: 1/1
705
[debug] [pid:14560] 	 Scheduled jobs: 1
706
[debug] [pid:14560] Need to schedule 1 parallel jobs for job 5 (with priority 50)
707
[debug] [pid:14560] Assigned job '5' to worker ID '1'
708
[debug] [pid:14560] [Job#5] Prepare for being processed by worker 1
709
[debug] [pid:14565] Started to send message to 1 for job(s) 5
710
[debug] [pid:14560] Sent job(s) '5' to worker '1'
711
[debug] [pid:14560] Scheduler took 0.10115s to perform operations and allocated 1 jobs
712
[debug] [pid:14560] Allocated: { job => 5, worker => 1 }
713
[debug] [pid:15136] Accepting job 5 from http://localhost:9526.
714
[debug] [pid:15136] Setting job 5 from http://localhost:9526 up
715
[debug] [pid:15136] Preparing Mojo::IOLoop::ReadWriteProcess::Session
716
[info] [pid:15136] +++ setup notes +++
717
[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)
718
[debug] [pid:15136] Job settings:
719
[debug] [pid:15136] 
720
    ARCH=i386
721
    BUILD=1
722
    CACHEDIRECTORY=/home/squamata/project/test-results/fullstack/full-stack.d/cache
723
    CACHELIMIT=50
724
    DISTRI=tinycore
725
    FLAVOR=flavor
726
    INTEGRATION_TESTS=1
727
    ISO=Core-7.2.iso
728
    JOBTOKEN=xBOCRMEQoRw0iLse
729
    LOCAL_UPLOAD=0
730
    LOG_LEVEL=debug
731
    MACHINE=coolone
732
    NAME=00000005-tinycore-1-flavor-i386-Build1-core@coolone
733
    OPENQA_HOSTNAME=localhost:9526
734
    OPENQA_URL=http://localhost:9526
735
    PRJDIR=/home/squamata/project/test-results/fullstack/full-stack.d/openqa/share
736
    PUBLISH_HDD_1=
737
    QEMU=i386
738
    QEMUPORT=20012
739
    QEMU_NO_FDC_SET=1
740
    QEMU_NO_KVM=1
741
    QEMU_NO_TABLET=1
742
    RETRY_DELAY=5
743
    RETRY_DELAY_IF_WEBUI_BUSY=60
744
    TEST=core
745
    UEFI_PFLASH_VARS=/usr/share/qemu/ovmf-x86_64.bin
746
    VERSION=1
747
    VNC=91
748
    WORKER_CLASS=qemu_i386,qemu_x86_64
749
    WORKER_ID=1
750
    WORKER_INSTANCE=1
751
    # Wait for jQuery successful: wait_for_result_panel: waiting for '(?^u:State: running)' (count 0 of 3240)
752
[debug] [pid:15136] Found ISO, caching Core-7.2.iso
753
[info] [pid:15136] Downloading Core-7.2.iso, request #1 sent to Cache Service
754
[debug] [pid:15136] Updating status so job 5 is not considered dead.
755
[debug] [pid:15136] REST-API call: POST http://localhost:9526/api/v1/jobs/5/status
756
[debug] [pid:14565] Worker 1 accepted job 5
757
[debug] redirect to /assets/iso/Core-7.2.iso
758
    # Wait for jQuery successful: wait_for_result_panel: waiting for '(?^u:State: running)' (count 1 of 3240)
759
    # Wait for jQuery successful: wait_for_result_panel: waiting for '(?^u:State: running)' (count 2 of 3240)
760
    # Wait for jQuery successful: wait_for_result_panel: waiting for '(?^u:State: running)' (count 3 of 3240)
761
    # Wait for jQuery successful: wait_for_result_panel: waiting for '(?^u:State: running)' (count 4 of 3240)
762
[debug] [pid:14566] Unrecognized referer 'localhost'
763
[debug] [pid:14566] Unrecognized referer 'localhost'
764
[debug] [pid:14566] Unrecognized referer 'localhost'
765
[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
766
[debug] [pid:14566] Unrecognized referer 'localhost'
767
[debug] [pid:14566] Unrecognized referer 'localhost'
768
[debug] [pid:14566] Asking the worker 1 to start providing livestream for job 5
769
    # Wait for jQuery successful: wait_for_result_panel: waiting for '(?^u:State: running)' (count 5 of 3240)
770
    ok 6 - \#nav-item-for-live present
771
    ok 7 - job 5 running
772
    # Subtest: results of test 5
773
        ok 1 - cache.sqlite file created
774
        ok 2 - Directory within cache, not present after deploy
775
        ok 3 - File within cache, not present after deploy
776
        # Waiting for 'finished download' to become available
777
[debug] [pid:15136] Updating status so job 5 is not considered dead.
778
[debug] [pid:15136] REST-API call: POST http://localhost:9526/api/v1/jobs/5/status
779
[info] [pid:15136] Download of Core-7.2.iso processed
780
[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"
781
[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"
782
[info] [pid:15136] Preparing cgroup to start isotovideo
783
[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.
784
[info] [pid:15136] You can define a custom slice with OPENQA_CGROUP_SLICE or indicating the base mount with MOJO_CGROUP_FS.
785
[info] [pid:15136] Starting isotovideo container
786
[debug] [pid:15136] Registered process:15143
787
[info] [pid:15143] 15143: WORKING 5
788
[info] [pid:15136] isotovideo has been started (PID: 15143)
789
[debug] [pid:15143] +++ worker notes +++
790
[debug] [pid:15136] Running job 5 from http://localhost:9526: 00000005-tinycore-1-flavor-i386-Build1-core@coolone.
791
[debug] [pid:15136] REST-API call: POST http://localhost:9526/api/v1/jobs/5/status
792
[debug] [pid:14565] Updating seen of worker 1 from worker_status (working)
793
[debug] [pid:15136] Upload concluded (no current module)
794
        ok 4 - iso is hardlinked to cache
795
        # Wait for jQuery successful: wait_for_result_panel: waiting for '(?^u:Result: passed)' (count 0 of 3240)
796
        # Wait for jQuery successful: wait_for_result_panel: waiting for '(?^u:Result: passed)' (count 1 of 3240)
797
        # Wait for jQuery successful: wait_for_result_panel: waiting for '(?^u:Result: passed)' (count 2 of 3240)
798
        # Wait for jQuery successful: wait_for_result_panel: waiting for '(?^u:Result: passed)' (count 3 of 3240)
799
        # Wait for jQuery successful: wait_for_result_panel: waiting for '(?^u:Result: passed)' (count 4 of 3240)
800
[debug] [pid:14566] Unrecognized referer 'localhost'
801
        # Wait for jQuery successful: wait_for_result_panel: waiting for '(?^u:Result: passed)' (count 5 of 3240)
802
        # Wait for jQuery successful: wait_for_result_panel: waiting for '(?^u:Result: passed)' (count 6 of 3240)
803
        # Wait for jQuery successful: wait_for_result_panel: waiting for '(?^u:Result: passed)' (count 7 of 3240)
804
        # Wait for jQuery successful: wait_for_result_panel: waiting for '(?^u:Result: passed)' (count 8 of 3240)
805
        # Wait for jQuery successful: wait_for_result_panel: waiting for '(?^u:Result: passed)' (count 9 of 3240)
806
        # Wait for jQuery successful: wait_for_result_panel: waiting for '(?^u:Result: passed)' (count 10 of 3240)
807
        # Wait for jQuery successful: wait_for_result_panel: waiting for '(?^u:Result: passed)' (count 11 of 3240)
808
        # Wait for jQuery successful: wait_for_result_panel: waiting for '(?^u:Result: passed)' (count 12 of 3240)
809
        # Wait for jQuery successful: wait_for_result_panel: waiting for '(?^u:Result: passed)' (count 13 of 3240)
810
        # Wait for jQuery successful: wait_for_result_panel: waiting for '(?^u:Result: passed)' (count 14 of 3240)
811
[debug] [pid:14566] Unrecognized referer 'localhost'
812
        # Wait for jQuery successful: wait_for_result_panel: waiting for '(?^u:Result: passed)' (count 15 of 3240)
813
        # Wait for jQuery successful: wait_for_result_panel: waiting for '(?^u:Result: passed)' (count 16 of 3240)
814
        # Wait for jQuery successful: wait_for_result_panel: waiting for '(?^u:Result: passed)' (count 17 of 3240)
815
        # Wait for jQuery successful: wait_for_result_panel: waiting for '(?^u:Result: passed)' (count 18 of 3240)
816
        # Wait for jQuery successful: wait_for_result_panel: waiting for '(?^u:Result: passed)' (count 19 of 3240)
817
[debug] [pid:15136] REST-API call: POST http://localhost:9526/api/v1/jobs/5/status
818
[debug] [pid:15136] Upload concluded (at boot)
819
        # Wait for jQuery successful: wait_for_result_panel: waiting for '(?^u:Result: passed)' (count 20 of 3240)
820
        # Wait for jQuery successful: wait_for_result_panel: waiting for '(?^u:Result: passed)' (count 21 of 3240)
821
        # Wait for jQuery successful: wait_for_result_panel: waiting for '(?^u:Result: passed)' (count 22 of 3240)
822
        # Wait for jQuery successful: wait_for_result_panel: waiting for '(?^u:Result: passed)' (count 23 of 3240)
823
[debug] [pid:14566] Unrecognized referer 'localhost'
824
[debug] [pid:14566] Unrecognized referer 'localhost'
825
[debug] [pid:14643] connecting to os-autoinst command server for job 5 at ws://1a81a2b0ff0f:20013/xBOCRMEQoRw0iLse/ws
826
        # Wait for jQuery successful: wait_for_result_panel: waiting for '(?^u:Result: passed)' (count 24 of 3240)
827
        # Wait for jQuery successful: wait_for_result_panel: waiting for '(?^u:Result: passed)' (count 25 of 3240)
828
        # Wait for jQuery successful: wait_for_result_panel: waiting for '(?^u:Result: passed)' (count 26 of 3240)
829
        # Wait for jQuery successful: wait_for_result_panel: waiting for '(?^u:Result: passed)' (count 27 of 3240)
830
        # Wait for jQuery successful: wait_for_result_panel: waiting for '(?^u:Result: passed)' (count 28 of 3240)
831
        # Wait for jQuery successful: wait_for_result_panel: waiting for '(?^u:Result: passed)' (count 29 of 3240)
832
        # Wait for jQuery successful: wait_for_result_panel: waiting for '(?^u:Result: passed)' (count 30 of 3240)
833
        # Wait for jQuery successful: wait_for_result_panel: waiting for '(?^u:Result: passed)' (count 31 of 3240)
834
        # Wait for jQuery successful: wait_for_result_panel: waiting for '(?^u:Result: passed)' (count 32 of 3240)
835
        # Wait for jQuery successful: wait_for_result_panel: waiting for '(?^u:Result: passed)' (count 33 of 3240)
836
[debug] [pid:14566] Unrecognized referer 'localhost'
837
        # Wait for jQuery successful: wait_for_result_panel: waiting for '(?^u:Result: passed)' (count 34 of 3240)
838
        # Wait for jQuery successful: wait_for_result_panel: waiting for '(?^u:Result: passed)' (count 35 of 3240)
839
        # Wait for jQuery successful: wait_for_result_panel: waiting for '(?^u:Result: passed)' (count 36 of 3240)
840
        # Wait for jQuery successful: wait_for_result_panel: waiting for '(?^u:Result: passed)' (count 37 of 3240)
841
        # Wait for jQuery successful: wait_for_result_panel: waiting for '(?^u:Result: passed)' (count 38 of 3240)
842
[debug] [pid:14565] Updating seen of worker 1 from worker_status (working)
843
[debug] [pid:15136] REST-API call: POST http://localhost:9526/api/v1/jobs/5/status
844
[debug] [pid:14566] creating f41/844/68dbb276a03240907d0e7e500d.png
845
[debug] [pid:14566] creating 68d/7ac/83452b72555f8a6b386629f91f.png
846
[debug] [pid:15136] Upload concluded (up to boot)
847
        # Wait for jQuery successful: wait_for_result_panel: waiting for '(?^u:Result: passed)' (count 39 of 3240)
848
        # Wait for jQuery successful: wait_for_result_panel: waiting for '(?^u:Result: passed)' (count 40 of 3240)
849
        # Wait for jQuery successful: wait_for_result_panel: waiting for '(?^u:Result: passed)' (count 41 of 3240)
850
        # Wait for jQuery successful: wait_for_result_panel: waiting for '(?^u:Result: passed)' (count 42 of 3240)
851
        # Wait for jQuery successful: wait_for_result_panel: waiting for '(?^u:Result: passed)' (count 43 of 3240)
852
[debug] [pid:14566] Unrecognized referer 'localhost'
853
[debug] [pid:14566] Unrecognized referer 'localhost'
854
[debug] looking for "f41/844/.thumbs/68dbb276a03240907d0e7e500d.png" in [
855
  "/home/squamata/project/test-results/fullstack/full-stack.d/openqa/images",
856
]
857
[debug] found bless({
858
  path => "/home/squamata/project/test-results/fullstack/full-stack.d/openqa/images/f41/844/.thumbs/68dbb276a03240907d0e7e500d.png",
859
  pid  => 14566,
860
}, "Mojo::Asset::File")
861
[debug] looking for "68d/7ac/.thumbs/83452b72555f8a6b386629f91f.png" in [
862
  "/home/squamata/project/test-results/fullstack/full-stack.d/openqa/images",
863
]
864
[debug] found bless({
865
  path => "/home/squamata/project/test-results/fullstack/full-stack.d/openqa/images/68d/7ac/.thumbs/83452b72555f8a6b386629f91f.png",
866
  pid  => 14566,
867
}, "Mojo::Asset::File")
868
[debug] [pid:14643] connecting to os-autoinst command server for job 5 at ws://1a81a2b0ff0f:20013/xBOCRMEQoRw0iLse/ws
869
        # Wait for jQuery successful: wait_for_result_panel: waiting for '(?^u:Result: passed)' (count 44 of 3240)
870
[info] [pid:15136] Isotovideo exit status: 0
871
[debug] [pid:15136] Stopping job 5 from http://localhost:9526: 00000005-tinycore-1-flavor-i386-Build1-core@coolone - reason: done
872
[debug] [pid:15136] REST-API call: POST http://localhost:9526/api/v1/jobs/5/status
873
[info] [pid:15136] +++ worker notes +++
874
[info] [pid:15136] End time: 2022-03-01 15:28:42
875
[info] [pid:15136] Result: done
876
[info] [pid:15352] Uploading video.ogv
877
[debug] [pid:15352] Uploading artefact video.ogv
878
[info] [pid:15352] Uploading vars.json
879
[debug] [pid:15352] Uploading artefact vars.json
880
[info] [pid:15352] Uploading autoinst-log.txt
881
[debug] [pid:15352] Uploading artefact autoinst-log.txt
882
[info] [pid:15352] Uploading worker-log.txt
883
[debug] [pid:15352] Uploading artefact worker-log.txt
884
[info] [pid:15352] Uploading serial0.txt
885
[debug] [pid:15352] Uploading artefact serial0.txt
886
[info] [pid:15352] Uploading video_time.vtt
887
[debug] [pid:15352] Uploading artefact video_time.vtt
888
[info] [pid:15352] Uploading serial_terminal.txt
889
[debug] [pid:15352] Uploading artefact serial_terminal.txt
890
[info] [pid:15352] Uploading virtio_console1.log
891
[debug] [pid:15352] Uploading artefact virtio_console1.log
892
[debug] [pid:15136] Considering job 5 as regularly done
893
[debug] [pid:15136] REST-API call: POST http://localhost:9526/api/v1/jobs/5/status
894
[debug] [pid:14566] creating e3b/43b/69c91fe4072dac1037f416c281.png
895
[debug] [pid:14566] creating e3b/43b/69c91fe4072dac1037f416c281.png
896
[debug] [pid:14566] creating 4ec/328/64be46d7336c00b3b3f4a5fe6d.png
897
[debug] [pid:15353] Optimizing /home/squamata/project/test-results/fullstack/full-stack.d/openqa/pool/1/testresults/shutdown-2.png
898
        # Wait for jQuery successful: wait_for_result_panel: waiting for '(?^u:Result: passed)' (count 45 of 3240)
899
[debug] [pid:15353] Uploading artefact shutdown-2.png as 4ec32864be46d7336c00b3b3f4a5fe6d
900
[debug] [pid:15353] Optimizing /home/squamata/project/test-results/fullstack/full-stack.d/openqa/pool/1/testresults/.thumbs/shutdown-2.png
901
[debug] [pid:15353] Uploading artefact shutdown-2.png as 4ec32864be46d7336c00b3b3f4a5fe6d
902
[debug] [pid:15353] Optimizing /home/squamata/project/test-results/fullstack/full-stack.d/openqa/pool/1/testresults/assert_screen-2.png
903
[debug] [pid:15353] Uploading artefact assert_screen-2.png as e3b43b69c91fe4072dac1037f416c281
904
[debug] [pid:15353] Optimizing /home/squamata/project/test-results/fullstack/full-stack.d/openqa/pool/1/testresults/.thumbs/assert_screen-2.png
905
[debug] [pid:15353] Uploading artefact assert_screen-2.png as e3b43b69c91fe4072dac1037f416c281
906
[debug] [pid:15136] Upload concluded (no current module)
907
[debug] [pid:15136] REST-API call: POST http://localhost:9526/api/v1/jobs/5/set_done?worker_id=1
908
[debug] [pid:15136] Job 5 from http://localhost:9526 finished - reason: done
909
[debug] [pid:15136] Cleaning up for next job
910
        # Wait for jQuery successful: wait_for_result_panel: waiting for '(?^u:Result: passed)' (count 46 of 3240)
911
        # Wait for jQuery successful: wait_for_result_panel: waiting for '(?^u:Result: passed)' (count 47 of 3240)
912
        # Wait for jQuery successful: wait_for_result_panel: waiting for '(?^u:Result: passed)' (count 48 of 3240)
913
        # Wait for jQuery successful: wait_for_result_panel: waiting for '(?^u:Result: passed)' (count 49 of 3240)
914
        # Wait for jQuery successful: wait_for_result_panel: waiting for '(?^u:Result: passed)' (count 50 of 3240)
915
        # Wait for jQuery successful: wait_for_result_panel: waiting for '(?^u:Result: passed)' (count 51 of 3240)
916
        # Wait for jQuery successful: wait_for_result_panel: waiting for '(?^u:Result: passed)' (count 52 of 3240)
917
[debug] [pid:14566] Unrecognized referer 'localhost'
918
[debug] [pid:14566] Unrecognized referer 'localhost'
919
[debug] [pid:14566] Unrecognized referer 'localhost'
920
[debug] looking for "e3b/43b/.thumbs/69c91fe4072dac1037f416c281.png" in [
921
  "/home/squamata/project/test-results/fullstack/full-stack.d/openqa/images",
922
]
923
[debug] found bless({
924
  path => "/home/squamata/project/test-results/fullstack/full-stack.d/openqa/images/e3b/43b/.thumbs/69c91fe4072dac1037f416c281.png",
925
  pid  => 14566,
926
}, "Mojo::Asset::File")
927
[debug] looking for "4ec/328/.thumbs/64be46d7336c00b3b3f4a5fe6d.png" in [
928
  "/home/squamata/project/test-results/fullstack/full-stack.d/openqa/images",
929
]
930
[debug] found bless({
931
  path => "/home/squamata/project/test-results/fullstack/full-stack.d/openqa/images/4ec/328/.thumbs/64be46d7336c00b3b3f4a5fe6d.png",
932
  pid  => 14566,
933
}, "Mojo::Asset::File")
934
        # Wait for jQuery successful: wait_for_result_panel: waiting for '(?^u:Result: passed)' (count 53 of 3240)
935
        ok 5 - job 5 passed
936
[info] [pid:15136] Received signal TERM
937
[debug] [pid:15136] Informing http://localhost:9526 that we are going offline
938
[info] [pid:14565] Worker 1 websocket connection closed - 1006
939
        ok 6 - Test 5 autoinst-log.txt file created
940
        ok 7 - Test 5, downloaded the right iso
941
        ok 8 - Test 5 Core-7.2.iso size is correct
942
        ok 9 - Test 5 result done
943
        ok 10 - setup notes present
944
        ok 11 - uploading of autoinst-log.txt logged
945
        ok 12 - worker log file generated
946
        ok 13 - autoinst log uploaded
947
        ok 14 - worker log uploaded
948
        ok 15 - local upload feature not used
949
        ok 16 - Core-7.2.iso is the first element
950
        ok 17 - file \#5 is the newest element
951
        1..17
952
    ok 8 - results of test 5
953
[debug] Restarting job 5
954
[debug] [pid:14566] Duplicating jobs: {
955
  5 => {
956
         chained_children => [],
957
         chained_parents => [],
958
         directly_chained_children => [],
959
         directly_chained_parents => [],
960
         is_parent_or_initial_job => 1,
961
         ok => 1,
962
         parallel_children => [],
963
         parallel_parents => [],
964
         state => "done",
965
       },
966
}
967
[debug] [pid:14566] Job 5 duplicated as 6
968
[warn] [pid:14566] Unable to wakeup scheduler: Connection refused
969
    ok 9 - client returned new test_url for test 6
970
[debug] [pid:14566] Unrecognized referer 'localhost'
971
    ok 10 - test 6 is scheduled
972
    ok 11 - Worker started as IPC::Run=HASH(0x55741bfab6f0)
973
    ok 12 - job with worker class qemu_i386 scheduled
974
[debug] [pid:14566] Unrecognized referer 'localhost'
975
[info] [pid:15361] worker 1:
976
 - config file:           /home/squamata/project/test-results/fullstack/full-stack.d/config/workers.ini
977
 - worker hostname:       1a81a2b0ff0f
978
 - isotovideo version:    25
979
 - websocket API version: 1
980
 - web UI hosts:          http://localhost:9526
981
 - class:                 qemu_i386,qemu_x86_64
982
 - no cleanup:            no
983
 - pool directory:        /home/squamata/project/test-results/fullstack/full-stack.d/openqa/pool/1
984
[info] [pid:15361] CACHE: caching is enabled, setting up /home/squamata/project/test-results/fullstack/full-stack.d/cache/localhost
985
[info] [pid:15361] Project dir for host http://localhost:9526 is /home/squamata/project/test-results/fullstack/full-stack.d/openqa/share
986
[info] [pid:15361] Registering with openQA http://localhost:9526
987
[info] [pid:15361] Establishing ws connection via ws://localhost:9526/api/v1/ws/1
988
[info] [pid:15361] Registered and connected via websockets with openQA host http://localhost:9526 and worker ID 1
989
[debug] [pid:14565] Updating seen of worker 1 from worker_status (free)
990
    ok 13 - at least one free worker with class qemu_i386 registered
991
[debug] [pid:14560] +=----------------=+
992
[debug] [pid:14560] -> Scheduling new jobs.
993
[debug] [pid:14560] 	 Free workers: 1/1
994
[debug] [pid:14560] 	 Scheduled jobs: 1
995
[debug] [pid:14560] Need to schedule 1 parallel jobs for job 6 (with priority 50)
996
[debug] [pid:14560] Assigned job '6' to worker ID '1'
997
[debug] [pid:14560] [Job#6] Prepare for being processed by worker 1
998
[debug] [pid:14565] Started to send message to 1 for job(s) 6
999
[debug] [pid:14560] Sent job(s) '6' to worker '1'
1000
[debug] [pid:14560] Scheduler took 0.08337s to perform operations and allocated 1 jobs
1001
[debug] [pid:14560] Allocated: { job => 6, worker => 1 }
1002
[debug] [pid:15361] Accepting job 6 from http://localhost:9526.
1003
    # Subtest: results of test 6
1004
[debug] [pid:15361] Setting job 6 from http://localhost:9526 up
1005
[debug] [pid:15361] Preparing Mojo::IOLoop::ReadWriteProcess::Session
1006
[info] [pid:15361] +++ setup notes +++
1007
[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)
1008
[debug] [pid:15361] Job settings:
1009
[debug] [pid:15361] 
1010
    ARCH=i386
1011
    BUILD=1
1012
    CACHEDIRECTORY=/home/squamata/project/test-results/fullstack/full-stack.d/cache
1013
    CACHELIMIT=50
1014
    DISTRI=tinycore
1015
    FLAVOR=flavor
1016
    INTEGRATION_TESTS=1
1017
    ISO=Core-7.2.iso
1018
    JOBTOKEN=LSwqvyqaj4Ub2NPr
1019
    LOCAL_UPLOAD=0
1020
    LOG_LEVEL=debug
1021
    MACHINE=coolone
1022
    NAME=00000006-tinycore-1-flavor-i386-Build1-core@coolone
1023
    OPENQA_HOSTNAME=localhost:9526
1024
    OPENQA_URL=http://localhost:9526
1025
    PRJDIR=/home/squamata/project/test-results/fullstack/full-stack.d/openqa/share
1026
    PUBLISH_HDD_1=
1027
    QEMU=i386
1028
    QEMUPORT=20012
1029
    QEMU_NO_FDC_SET=1
1030
    QEMU_NO_KVM=1
1031
    QEMU_NO_TABLET=1
1032
    RETRY_DELAY=5
1033
    RETRY_DELAY_IF_WEBUI_BUSY=60
1034
    TEST=core
1035
    UEFI_PFLASH_VARS=/usr/share/qemu/ovmf-x86_64.bin
1036
    VERSION=1
1037
    VNC=91
1038
    WORKER_CLASS=qemu_i386,qemu_x86_64
1039
    WORKER_ID=1
1040
    WORKER_INSTANCE=1
1041
        # Wait for jQuery successful: wait_for_result_panel: waiting for '(?^u:Result: passed)' (count 0 of 3240)
1042
[debug] [pid:15361] Found ISO, caching Core-7.2.iso
1043
[info] [pid:15361] Downloading Core-7.2.iso, request #2 sent to Cache Service
1044
[debug] [pid:15361] Updating status so job 6 is not considered dead.
1045
[debug] [pid:15361] REST-API call: POST http://localhost:9526/api/v1/jobs/6/status
1046
[debug] [pid:14565] Worker 1 accepted job 6
1047
[debug] redirect to /assets/iso/Core-7.2.iso
1048
        # Wait for jQuery successful: wait_for_result_panel: waiting for '(?^u:Result: passed)' (count 1 of 3240)
1049
        # Wait for jQuery successful: wait_for_result_panel: waiting for '(?^u:Result: passed)' (count 2 of 3240)
1050
        # Wait for jQuery successful: wait_for_result_panel: waiting for '(?^u:Result: passed)' (count 3 of 3240)
1051
        # Wait for jQuery successful: wait_for_result_panel: waiting for '(?^u:Result: passed)' (count 4 of 3240)
1052
        # Wait for jQuery successful: wait_for_result_panel: waiting for '(?^u:Result: passed)' (count 5 of 3240)
1053
[debug] [pid:14566] Unrecognized referer 'localhost'
1054
[debug] [pid:14566] Unrecognized referer 'localhost'
1055
[debug] [pid:14566] Unrecognized referer 'localhost'
1056
[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
1057
[debug] [pid:14566] Unrecognized referer 'localhost'
1058
[debug] [pid:14566] Unrecognized referer 'localhost'
1059
[debug] [pid:14566] Asking the worker 1 to start providing livestream for job 6
1060
        # Wait for jQuery successful: wait_for_result_panel: waiting for '(?^u:Result: passed)' (count 6 of 3240)
1061
        # Wait for jQuery successful: wait_for_result_panel: waiting for '(?^u:Result: passed)' (count 7 of 3240)
1062
        # Wait for jQuery successful: wait_for_result_panel: waiting for '(?^u:Result: passed)' (count 8 of 3240)
1063
        # Wait for jQuery successful: wait_for_result_panel: waiting for '(?^u:Result: passed)' (count 9 of 3240)
1064
[debug] [pid:15361] Updating status so job 6 is not considered dead.
1065
[debug] [pid:15361] REST-API call: POST http://localhost:9526/api/v1/jobs/6/status
1066
[info] [pid:15361] Download of Core-7.2.iso processed
1067
[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"
1068
[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"
1069
[info] [pid:15361] Preparing cgroup to start isotovideo
1070
[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.
1071
[info] [pid:15361] You can define a custom slice with OPENQA_CGROUP_SLICE or indicating the base mount with MOJO_CGROUP_FS.
1072
[info] [pid:15361] Starting isotovideo container
1073
[debug] [pid:15361] Registered process:15368
1074
[info] [pid:15368] 15368: WORKING 6
1075
[info] [pid:15361] isotovideo has been started (PID: 15368)
1076
[debug] [pid:15368] +++ worker notes +++
1077
[debug] [pid:15361] Running job 6 from http://localhost:9526: 00000006-tinycore-1-flavor-i386-Build1-core@coolone.
1078
[debug] [pid:15361] REST-API call: POST http://localhost:9526/api/v1/jobs/6/status
1079
[debug] [pid:14565] Updating seen of worker 1 from worker_status (working)
1080
[debug] [pid:15361] Upload concluded (no current module)
1081
        # Wait for jQuery successful: wait_for_result_panel: waiting for '(?^u:Result: passed)' (count 10 of 3240)
1082
        # Wait for jQuery successful: wait_for_result_panel: waiting for '(?^u:Result: passed)' (count 11 of 3240)
1083
        # Wait for jQuery successful: wait_for_result_panel: waiting for '(?^u:Result: passed)' (count 12 of 3240)
1084
        # Wait for jQuery successful: wait_for_result_panel: waiting for '(?^u:Result: passed)' (count 13 of 3240)
1085
        # Wait for jQuery successful: wait_for_result_panel: waiting for '(?^u:Result: passed)' (count 14 of 3240)
1086
[debug] [pid:14566] Unrecognized referer 'localhost'
1087
        # Wait for jQuery successful: wait_for_result_panel: waiting for '(?^u:Result: passed)' (count 15 of 3240)
1088
        # Wait for jQuery successful: wait_for_result_panel: waiting for '(?^u:Result: passed)' (count 16 of 3240)
1089
        # Wait for jQuery successful: wait_for_result_panel: waiting for '(?^u:Result: passed)' (count 17 of 3240)
1090
        # Wait for jQuery successful: wait_for_result_panel: waiting for '(?^u:Result: passed)' (count 18 of 3240)
1091
        # Wait for jQuery successful: wait_for_result_panel: waiting for '(?^u:Result: passed)' (count 19 of 3240)
1092
        # Wait for jQuery successful: wait_for_result_panel: waiting for '(?^u:Result: passed)' (count 20 of 3240)
1093
        # Wait for jQuery successful: wait_for_result_panel: waiting for '(?^u:Result: passed)' (count 21 of 3240)
1094
        # Wait for jQuery successful: wait_for_result_panel: waiting for '(?^u:Result: passed)' (count 22 of 3240)
1095
        # Wait for jQuery successful: wait_for_result_panel: waiting for '(?^u:Result: passed)' (count 23 of 3240)
1096
        # Wait for jQuery successful: wait_for_result_panel: waiting for '(?^u:Result: passed)' (count 24 of 3240)
1097
[debug] [pid:14566] Unrecognized referer 'localhost'
1098
        # Wait for jQuery successful: wait_for_result_panel: waiting for '(?^u:Result: passed)' (count 25 of 3240)
1099
        # Wait for jQuery successful: wait_for_result_panel: waiting for '(?^u:Result: passed)' (count 26 of 3240)
1100
        # Wait for jQuery successful: wait_for_result_panel: waiting for '(?^u:Result: passed)' (count 27 of 3240)
1101
        # Wait for jQuery successful: wait_for_result_panel: waiting for '(?^u:Result: passed)' (count 28 of 3240)
1102
        # Wait for jQuery successful: wait_for_result_panel: waiting for '(?^u:Result: passed)' (count 29 of 3240)
1103
[debug] [pid:15361] REST-API call: POST http://localhost:9526/api/v1/jobs/6/status
1104
[debug] [pid:15361] Upload concluded (at boot)
1105
        # Wait for jQuery successful: wait_for_result_panel: waiting for '(?^u:Result: passed)' (count 30 of 3240)
1106
        # Wait for jQuery successful: wait_for_result_panel: waiting for '(?^u:Result: passed)' (count 31 of 3240)
1107
        # Wait for jQuery successful: wait_for_result_panel: waiting for '(?^u:Result: passed)' (count 32 of 3240)
1108
        # Wait for jQuery successful: wait_for_result_panel: waiting for '(?^u:Result: passed)' (count 33 of 3240)
1109
        # Wait for jQuery successful: wait_for_result_panel: waiting for '(?^u:Result: passed)' (count 34 of 3240)
1110
[debug] [pid:14566] Unrecognized referer 'localhost'
1111
[debug] [pid:14566] Unrecognized referer 'localhost'
1112
[debug] [pid:14643] connecting to os-autoinst command server for job 6 at ws://1a81a2b0ff0f:20013/LSwqvyqaj4Ub2NPr/ws
1113
        # Wait for jQuery successful: wait_for_result_panel: waiting for '(?^u:Result: passed)' (count 35 of 3240)
1114
        # Wait for jQuery successful: wait_for_result_panel: waiting for '(?^u:Result: passed)' (count 36 of 3240)
1115
        # Wait for jQuery successful: wait_for_result_panel: waiting for '(?^u:Result: passed)' (count 37 of 3240)
1116
        # Wait for jQuery successful: wait_for_result_panel: waiting for '(?^u:Result: passed)' (count 38 of 3240)
1117
        # Wait for jQuery successful: wait_for_result_panel: waiting for '(?^u:Result: passed)' (count 39 of 3240)
1118
        # Wait for jQuery successful: wait_for_result_panel: waiting for '(?^u:Result: passed)' (count 40 of 3240)
1119
        # Wait for jQuery successful: wait_for_result_panel: waiting for '(?^u:Result: passed)' (count 41 of 3240)
1120
        # Wait for jQuery successful: wait_for_result_panel: waiting for '(?^u:Result: passed)' (count 42 of 3240)
1121
        # Wait for jQuery successful: wait_for_result_panel: waiting for '(?^u:Result: passed)' (count 43 of 3240)
1122
        # Wait for jQuery successful: wait_for_result_panel: waiting for '(?^u:Result: passed)' (count 44 of 3240)
1123
[debug] [pid:14566] Unrecognized referer 'localhost'
1124
        # Wait for jQuery successful: wait_for_result_panel: waiting for '(?^u:Result: passed)' (count 45 of 3240)
1125
        # Wait for jQuery successful: wait_for_result_panel: waiting for '(?^u:Result: passed)' (count 46 of 3240)
1126
        # Wait for jQuery successful: wait_for_result_panel: waiting for '(?^u:Result: passed)' (count 47 of 3240)
1127
        # Wait for jQuery successful: wait_for_result_panel: waiting for '(?^u:Result: passed)' (count 48 of 3240)
1128
[debug] [pid:14565] Updating seen of worker 1 from worker_status (working)
1129
[debug] [pid:15361] REST-API call: POST http://localhost:9526/api/v1/jobs/6/status
1130
        # Wait for jQuery successful: wait_for_result_panel: waiting for '(?^u:Result: passed)' (count 49 of 3240)
1131
[debug] [pid:14566] creating f41/844/68dbb276a03240907d0e7e500d.png
1132
[debug] [pid:14566] creating 68d/7ac/83452b72555f8a6b386629f91f.png
1133
[debug] [pid:15361] Upload concluded (up to boot)
1134
        # Wait for jQuery successful: wait_for_result_panel: waiting for '(?^u:Result: passed)' (count 50 of 3240)
1135
        # Wait for jQuery successful: wait_for_result_panel: waiting for '(?^u:Result: passed)' (count 51 of 3240)
1136
        # Wait for jQuery successful: wait_for_result_panel: waiting for '(?^u:Result: passed)' (count 52 of 3240)
1137
        # Wait for jQuery successful: wait_for_result_panel: waiting for '(?^u:Result: passed)' (count 53 of 3240)
1138
[debug] [pid:14566] Unrecognized referer 'localhost'
1139
[debug] [pid:14566] Unrecognized referer 'localhost'
1140
[debug] looking for "f41/844/.thumbs/68dbb276a03240907d0e7e500d.png" in [
1141
  "/home/squamata/project/test-results/fullstack/full-stack.d/openqa/images",
1142
]
1143
[debug] found bless({
1144
  path => "/home/squamata/project/test-results/fullstack/full-stack.d/openqa/images/f41/844/.thumbs/68dbb276a03240907d0e7e500d.png",
1145
  pid  => 14566,
1146
}, "Mojo::Asset::File")
1147
[debug] looking for "68d/7ac/.thumbs/83452b72555f8a6b386629f91f.png" in [
1148
  "/home/squamata/project/test-results/fullstack/full-stack.d/openqa/images",
1149
]
1150
[debug] found bless({
1151
  path => "/home/squamata/project/test-results/fullstack/full-stack.d/openqa/images/68d/7ac/.thumbs/83452b72555f8a6b386629f91f.png",
1152
  pid  => 14566,
1153
}, "Mojo::Asset::File")
1154
        # Wait for jQuery successful: wait_for_result_panel: waiting for '(?^u:Result: passed)' (count 54 of 3240)
1155
        # Wait for jQuery successful: wait_for_result_panel: waiting for '(?^u:Result: passed)' (count 55 of 3240)
1156
        # Wait for jQuery successful: wait_for_result_panel: waiting for '(?^u:Result: passed)' (count 56 of 3240)
1157
        # Wait for jQuery successful: wait_for_result_panel: waiting for '(?^u:Result: passed)' (count 57 of 3240)
1158
        # Wait for jQuery successful: wait_for_result_panel: waiting for '(?^u:Result: passed)' (count 58 of 3240)
1159
        # Wait for jQuery successful: wait_for_result_panel: waiting for '(?^u:Result: passed)' (count 59 of 3240)
1160
        # Wait for jQuery successful: wait_for_result_panel: waiting for '(?^u:Result: passed)' (count 60 of 3240)
1161
        # Wait for jQuery successful: wait_for_result_panel: waiting for '(?^u:Result: passed)' (count 61 of 3240)
1162
        # Wait for jQuery successful: wait_for_result_panel: waiting for '(?^u:Result: passed)' (count 62 of 3240)
1163
        # Wait for jQuery successful: wait_for_result_panel: waiting for '(?^u:Result: passed)' (count 63 of 3240)
1164
[debug] [pid:14566] Unrecognized referer 'localhost'
1165
        # Wait for jQuery successful: wait_for_result_panel: waiting for '(?^u:Result: passed)' (count 64 of 3240)
1166
        # Wait for jQuery successful: wait_for_result_panel: waiting for '(?^u:Result: passed)' (count 65 of 3240)
1167
        # Wait for jQuery successful: wait_for_result_panel: waiting for '(?^u:Result: passed)' (count 66 of 3240)
1168
        # Wait for jQuery successful: wait_for_result_panel: waiting for '(?^u:Result: passed)' (count 67 of 3240)
1169
        # Wait for jQuery successful: wait_for_result_panel: waiting for '(?^u:Result: passed)' (count 68 of 3240)
1170
[debug] [pid:15361] REST-API call: POST http://localhost:9526/api/v1/jobs/6/status
1171
[debug] [pid:15361] Upload concluded (at shutdown)
1172
        # Wait for jQuery successful: wait_for_result_panel: waiting for '(?^u:Result: passed)' (count 69 of 3240)
1173
        # Wait for jQuery successful: wait_for_result_panel: waiting for '(?^u:Result: passed)' (count 70 of 3240)
1174
        # Wait for jQuery successful: wait_for_result_panel: waiting for '(?^u:Result: passed)' (count 71 of 3240)
1175
        # Wait for jQuery successful: wait_for_result_panel: waiting for '(?^u:Result: passed)' (count 72 of 3240)
1176
        # Wait for jQuery successful: wait_for_result_panel: waiting for '(?^u:Result: passed)' (count 73 of 3240)
1177
[debug] [pid:14566] Unrecognized referer 'localhost'
1178
        # Wait for jQuery successful: wait_for_result_panel: waiting for '(?^u:Result: passed)' (count 74 of 3240)
1179
        # Wait for jQuery successful: wait_for_result_panel: waiting for '(?^u:Result: passed)' (count 75 of 3240)
1180
        # Wait for jQuery successful: wait_for_result_panel: waiting for '(?^u:Result: passed)' (count 76 of 3240)
1181
        # Wait for jQuery successful: wait_for_result_panel: waiting for '(?^u:Result: passed)' (count 77 of 3240)
1182
        # Wait for jQuery successful: wait_for_result_panel: waiting for '(?^u:Result: passed)' (count 78 of 3240)
1183
        # Wait for jQuery successful: wait_for_result_panel: waiting for '(?^u:Result: passed)' (count 79 of 3240)
1184
        # Wait for jQuery successful: wait_for_result_panel: waiting for '(?^u:Result: passed)' (count 80 of 3240)
1185
        # Wait for jQuery successful: wait_for_result_panel: waiting for '(?^u:Result: passed)' (count 81 of 3240)
1186
        # Wait for jQuery successful: wait_for_result_panel: waiting for '(?^u:Result: passed)' (count 82 of 3240)
1187
[debug] [pid:14566] Unrecognized referer 'localhost'
1188
        # Wait for jQuery successful: wait_for_result_panel: waiting for '(?^u:Result: passed)' (count 83 of 3240)
1189
        # Wait for jQuery successful: wait_for_result_panel: waiting for '(?^u:Result: passed)' (count 84 of 3240)
1190
        # Wait for jQuery successful: wait_for_result_panel: waiting for '(?^u:Result: passed)' (count 85 of 3240)
1191
        # Wait for jQuery successful: wait_for_result_panel: waiting for '(?^u:Result: passed)' (count 86 of 3240)
1192
        # Wait for jQuery successful: wait_for_result_panel: waiting for '(?^u:Result: passed)' (count 87 of 3240)
1193
[debug] [pid:14565] Updating seen of worker 1 from worker_status (working)
1194
[debug] [pid:15361] REST-API call: POST http://localhost:9526/api/v1/jobs/6/status
1195
[debug] [pid:15361] Upload concluded (at shutdown)
1196
        # Wait for jQuery successful: wait_for_result_panel: waiting for '(?^u:Result: passed)' (count 88 of 3240)
1197
        # Wait for jQuery successful: wait_for_result_panel: waiting for '(?^u:Result: passed)' (count 89 of 3240)
1198
        # Wait for jQuery successful: wait_for_result_panel: waiting for '(?^u:Result: passed)' (count 90 of 3240)
1199
        # Wait for jQuery successful: wait_for_result_panel: waiting for '(?^u:Result: passed)' (count 91 of 3240)
1200
        # Wait for jQuery successful: wait_for_result_panel: waiting for '(?^u:Result: passed)' (count 92 of 3240)
1201
[debug] [pid:14566] Unrecognized referer 'localhost'
1202
        # Wait for jQuery successful: wait_for_result_panel: waiting for '(?^u:Result: passed)' (count 93 of 3240)
1203
        # Wait for jQuery successful: wait_for_result_panel: waiting for '(?^u:Result: passed)' (count 94 of 3240)
1204
        # Wait for jQuery successful: wait_for_result_panel: waiting for '(?^u:Result: passed)' (count 95 of 3240)
1205
        # Wait for jQuery successful: wait_for_result_panel: waiting for '(?^u:Result: passed)' (count 96 of 3240)
1206
        # Wait for jQuery successful: wait_for_result_panel: waiting for '(?^u:Result: passed)' (count 97 of 3240)
1207
        # Wait for jQuery successful: wait_for_result_panel: waiting for '(?^u:Result: passed)' (count 98 of 3240)
1208
        # Wait for jQuery successful: wait_for_result_panel: waiting for '(?^u:Result: passed)' (count 99 of 3240)
1209
        # Wait for jQuery successful: wait_for_result_panel: waiting for '(?^u:Result: passed)' (count 100 of 3240)
1210
        # Wait for jQuery successful: wait_for_result_panel: waiting for '(?^u:Result: passed)' (count 101 of 3240)
1211
        # Wait for jQuery successful: wait_for_result_panel: waiting for '(?^u:Result: passed)' (count 102 of 3240)
1212
[debug] [pid:14566] Unrecognized referer 'localhost'
1213
        # Wait for jQuery successful: wait_for_result_panel: waiting for '(?^u:Result: passed)' (count 103 of 3240)
1214
        # Wait for jQuery successful: wait_for_result_panel: waiting for '(?^u:Result: passed)' (count 104 of 3240)
1215
        # Wait for jQuery successful: wait_for_result_panel: waiting for '(?^u:Result: passed)' (count 105 of 3240)
1216
        # Wait for jQuery successful: wait_for_result_panel: waiting for '(?^u:Result: passed)' (count 106 of 3240)
1217
        # Wait for jQuery successful: wait_for_result_panel: waiting for '(?^u:Result: passed)' (count 107 of 3240)
1218
[debug] [pid:15361] REST-API call: POST http://localhost:9526/api/v1/jobs/6/status
1219
[debug] [pid:15361] Upload concluded (at shutdown)
1220
        # Wait for jQuery successful: wait_for_result_panel: waiting for '(?^u:Result: passed)' (count 108 of 3240)
1221
        # Wait for jQuery successful: wait_for_result_panel: waiting for '(?^u:Result: passed)' (count 109 of 3240)
1222
        # Wait for jQuery successful: wait_for_result_panel: waiting for '(?^u:Result: passed)' (count 110 of 3240)
1223
        # Wait for jQuery successful: wait_for_result_panel: waiting for '(?^u:Result: passed)' (count 111 of 3240)
1224
        # Wait for jQuery successful: wait_for_result_panel: waiting for '(?^u:Result: passed)' (count 112 of 3240)
1225
[debug] [pid:14566] Unrecognized referer 'localhost'
1226
        # Wait for jQuery successful: wait_for_result_panel: waiting for '(?^u:Result: passed)' (count 113 of 3240)
1227
        # Wait for jQuery successful: wait_for_result_panel: waiting for '(?^u:Result: passed)' (count 114 of 3240)
1228
        # Wait for jQuery successful: wait_for_result_panel: waiting for '(?^u:Result: passed)' (count 115 of 3240)
1229
        # Wait for jQuery successful: wait_for_result_panel: waiting for '(?^u:Result: passed)' (count 116 of 3240)
1230
        # Wait for jQuery successful: wait_for_result_panel: waiting for '(?^u:Result: passed)' (count 117 of 3240)
1231
        # Wait for jQuery successful: wait_for_result_panel: waiting for '(?^u:Result: passed)' (count 118 of 3240)
1232
        # Wait for jQuery successful: wait_for_result_panel: waiting for '(?^u:Result: passed)' (count 119 of 3240)
1233
        # Wait for jQuery successful: wait_for_result_panel: waiting for '(?^u:Result: passed)' (count 120 of 3240)
1234
        # Wait for jQuery successful: wait_for_result_panel: waiting for '(?^u:Result: passed)' (count 121 of 3240)
1235
        # Wait for jQuery successful: wait_for_result_panel: waiting for '(?^u:Result: passed)' (count 122 of 3240)
1236
[debug] [pid:14566] Unrecognized referer 'localhost'
1237
        # Wait for jQuery successful: wait_for_result_panel: waiting for '(?^u:Result: passed)' (count 123 of 3240)
1238
        # Wait for jQuery successful: wait_for_result_panel: waiting for '(?^u:Result: passed)' (count 124 of 3240)
1239
        # Wait for jQuery successful: wait_for_result_panel: waiting for '(?^u:Result: passed)' (count 125 of 3240)
1240
        # Wait for jQuery successful: wait_for_result_panel: waiting for '(?^u:Result: passed)' (count 126 of 3240)
1241
[debug] [pid:14565] Updating seen of worker 1 from worker_status (working)
1242
        # Wait for jQuery successful: wait_for_result_panel: waiting for '(?^u:Result: passed)' (count 127 of 3240)
1243
[debug] [pid:15361] REST-API call: POST http://localhost:9526/api/v1/jobs/6/status
1244
[debug] [pid:15361] Upload concluded (at shutdown)
1245
        # Wait for jQuery successful: wait_for_result_panel: waiting for '(?^u:Result: passed)' (count 128 of 3240)
1246
        # Wait for jQuery successful: wait_for_result_panel: waiting for '(?^u:Result: passed)' (count 129 of 3240)
1247
        # Wait for jQuery successful: wait_for_result_panel: waiting for '(?^u:Result: passed)' (count 130 of 3240)
1248
        # Wait for jQuery successful: wait_for_result_panel: waiting for '(?^u:Result: passed)' (count 131 of 3240)
1249
[debug] [pid:14566] Unrecognized referer 'localhost'
1250
        # Wait for jQuery successful: wait_for_result_panel: waiting for '(?^u:Result: passed)' (count 132 of 3240)
1251
        # Wait for jQuery successful: wait_for_result_panel: waiting for '(?^u:Result: passed)' (count 133 of 3240)
1252
        # Wait for jQuery successful: wait_for_result_panel: waiting for '(?^u:Result: passed)' (count 134 of 3240)
1253
        # Wait for jQuery successful: wait_for_result_panel: waiting for '(?^u:Result: passed)' (count 135 of 3240)
1254
        # Wait for jQuery successful: wait_for_result_panel: waiting for '(?^u:Result: passed)' (count 136 of 3240)
1255
        # Wait for jQuery successful: wait_for_result_panel: waiting for '(?^u:Result: passed)' (count 137 of 3240)
1256
        # Wait for jQuery successful: wait_for_result_panel: waiting for '(?^u:Result: passed)' (count 138 of 3240)
1257
        # Wait for jQuery successful: wait_for_result_panel: waiting for '(?^u:Result: passed)' (count 139 of 3240)
1258
        # Wait for jQuery successful: wait_for_result_panel: waiting for '(?^u:Result: passed)' (count 140 of 3240)
1259
        # Wait for jQuery successful: wait_for_result_panel: waiting for '(?^u:Result: passed)' (count 141 of 3240)
1260
[debug] [pid:14566] Unrecognized referer 'localhost'
1261
        # Wait for jQuery successful: wait_for_result_panel: waiting for '(?^u:Result: passed)' (count 142 of 3240)
1262
        # Wait for jQuery successful: wait_for_result_panel: waiting for '(?^u:Result: passed)' (count 143 of 3240)
1263
        # Wait for jQuery successful: wait_for_result_panel: waiting for '(?^u:Result: passed)' (count 144 of 3240)
1264
        # Wait for jQuery successful: wait_for_result_panel: waiting for '(?^u:Result: passed)' (count 145 of 3240)
1265
        # Wait for jQuery successful: wait_for_result_panel: waiting for '(?^u:Result: passed)' (count 146 of 3240)
1266
[debug] [pid:15361] REST-API call: POST http://localhost:9526/api/v1/jobs/6/status
1267
[debug] [pid:15361] Upload concluded (at shutdown)
1268
        # Wait for jQuery successful: wait_for_result_panel: waiting for '(?^u:Result: passed)' (count 147 of 3240)
1269
        # Wait for jQuery successful: wait_for_result_panel: waiting for '(?^u:Result: passed)' (count 148 of 3240)
1270
        # Wait for jQuery successful: wait_for_result_panel: waiting for '(?^u:Result: passed)' (count 149 of 3240)
1271
        # Wait for jQuery successful: wait_for_result_panel: waiting for '(?^u:Result: passed)' (count 150 of 3240)
1272
        # Wait for jQuery successful: wait_for_result_panel: waiting for '(?^u:Result: passed)' (count 151 of 3240)
1273
[debug] [pid:14566] Unrecognized referer 'localhost'
1274
        # Wait for jQuery successful: wait_for_result_panel: waiting for '(?^u:Result: passed)' (count 152 of 3240)
1275
        # Wait for jQuery successful: wait_for_result_panel: waiting for '(?^u:Result: passed)' (count 153 of 3240)
1276
        # Wait for jQuery successful: wait_for_result_panel: waiting for '(?^u:Result: passed)' (count 154 of 3240)
1277
        # Wait for jQuery successful: wait_for_result_panel: waiting for '(?^u:Result: passed)' (count 155 of 3240)
1278
        # Wait for jQuery successful: wait_for_result_panel: waiting for '(?^u:Result: passed)' (count 156 of 3240)
1279
        # Wait for jQuery successful: wait_for_result_panel: waiting for '(?^u:Result: passed)' (count 157 of 3240)
1280
        # Wait for jQuery successful: wait_for_result_panel: waiting for '(?^u:Result: passed)' (count 158 of 3240)
1281
        # Wait for jQuery successful: wait_for_result_panel: waiting for '(?^u:Result: passed)' (count 159 of 3240)
1282
        # Wait for jQuery successful: wait_for_result_panel: waiting for '(?^u:Result: passed)' (count 160 of 3240)
1283
        # Wait for jQuery successful: wait_for_result_panel: waiting for '(?^u:Result: passed)' (count 161 of 3240)
1284
[debug] [pid:14566] Unrecognized referer 'localhost'
1285
        # Wait for jQuery successful: wait_for_result_panel: waiting for '(?^u:Result: passed)' (count 162 of 3240)
1286
        # Wait for jQuery successful: wait_for_result_panel: waiting for '(?^u:Result: passed)' (count 163 of 3240)
1287
        # Wait for jQuery successful: wait_for_result_panel: waiting for '(?^u:Result: passed)' (count 164 of 3240)
1288
        # Wait for jQuery successful: wait_for_result_panel: waiting for '(?^u:Result: passed)' (count 165 of 3240)
1289
[debug] [pid:14565] Updating seen of worker 1 from worker_status (working)
1290
        # Wait for jQuery successful: wait_for_result_panel: waiting for '(?^u:Result: passed)' (count 166 of 3240)
1291
[debug] [pid:15361] REST-API call: POST http://localhost:9526/api/v1/jobs/6/status
1292
[debug] [pid:15361] Upload concluded (at shutdown)
1293
        # Wait for jQuery successful: wait_for_result_panel: waiting for '(?^u:Result: passed)' (count 167 of 3240)
1294
        # Wait for jQuery successful: wait_for_result_panel: waiting for '(?^u:Result: passed)' (count 168 of 3240)
1295
        # Wait for jQuery successful: wait_for_result_panel: waiting for '(?^u:Result: passed)' (count 169 of 3240)
1296
        # Wait for jQuery successful: wait_for_result_panel: waiting for '(?^u:Result: passed)' (count 170 of 3240)
1297
        # Wait for jQuery successful: wait_for_result_panel: waiting for '(?^u:Result: passed)' (count 171 of 3240)
1298
[debug] [pid:14566] Unrecognized referer 'localhost'
1299
        # Wait for jQuery successful: wait_for_result_panel: waiting for '(?^u:Result: passed)' (count 172 of 3240)
1300
        # Wait for jQuery successful: wait_for_result_panel: waiting for '(?^u:Result: passed)' (count 173 of 3240)
1301
        # Wait for jQuery successful: wait_for_result_panel: waiting for '(?^u:Result: passed)' (count 174 of 3240)
1302
        # Wait for jQuery successful: wait_for_result_panel: waiting for '(?^u:Result: passed)' (count 175 of 3240)
1303
        # Wait for jQuery successful: wait_for_result_panel: waiting for '(?^u:Result: passed)' (count 176 of 3240)
1304
        # Wait for jQuery successful: wait_for_result_panel: waiting for '(?^u:Result: passed)' (count 177 of 3240)
1305
        # Wait for jQuery successful: wait_for_result_panel: waiting for '(?^u:Result: passed)' (count 178 of 3240)
1306
        # Wait for jQuery successful: wait_for_result_panel: waiting for '(?^u:Result: passed)' (count 179 of 3240)
1307
        # Wait for jQuery successful: wait_for_result_panel: waiting for '(?^u:Result: passed)' (count 180 of 3240)
1308
[debug] [pid:14566] Unrecognized referer 'localhost'
1309
        # Wait for jQuery successful: wait_for_result_panel: waiting for '(?^u:Result: passed)' (count 181 of 3240)
1310
        # Wait for jQuery successful: wait_for_result_panel: waiting for '(?^u:Result: passed)' (count 182 of 3240)
1311
        # Wait for jQuery successful: wait_for_result_panel: waiting for '(?^u:Result: passed)' (count 183 of 3240)
1312
        # Wait for jQuery successful: wait_for_result_panel: waiting for '(?^u:Result: passed)' (count 184 of 3240)
1313
        # Wait for jQuery successful: wait_for_result_panel: waiting for '(?^u:Result: passed)' (count 185 of 3240)
1314
[debug] [pid:15361] REST-API call: POST http://localhost:9526/api/v1/jobs/6/status
1315
[debug] [pid:15361] Upload concluded (at shutdown)
1316
        # Wait for jQuery successful: wait_for_result_panel: waiting for '(?^u:Result: passed)' (count 186 of 3240)
1317
        # Wait for jQuery successful: wait_for_result_panel: waiting for '(?^u:Result: passed)' (count 187 of 3240)
1318
        # Wait for jQuery successful: wait_for_result_panel: waiting for '(?^u:Result: passed)' (count 188 of 3240)
1319
        # Wait for jQuery successful: wait_for_result_panel: waiting for '(?^u:Result: passed)' (count 189 of 3240)
1320
        # Wait for jQuery successful: wait_for_result_panel: waiting for '(?^u:Result: passed)' (count 190 of 3240)
1321
[debug] [pid:14566] Unrecognized referer 'localhost'
1322
        # Wait for jQuery successful: wait_for_result_panel: waiting for '(?^u:Result: passed)' (count 191 of 3240)
1323
        # Wait for jQuery successful: wait_for_result_panel: waiting for '(?^u:Result: passed)' (count 192 of 3240)
1324
        # Wait for jQuery successful: wait_for_result_panel: waiting for '(?^u:Result: passed)' (count 193 of 3240)
1325
        # Wait for jQuery successful: wait_for_result_panel: waiting for '(?^u:Result: passed)' (count 194 of 3240)
1326
        # Wait for jQuery successful: wait_for_result_panel: waiting for '(?^u:Result: passed)' (count 195 of 3240)
1327
        # Wait for jQuery successful: wait_for_result_panel: waiting for '(?^u:Result: passed)' (count 196 of 3240)
1328
        # Wait for jQuery successful: wait_for_result_panel: waiting for '(?^u:Result: passed)' (count 197 of 3240)
1329
        # Wait for jQuery successful: wait_for_result_panel: waiting for '(?^u:Result: passed)' (count 198 of 3240)
1330
        # Wait for jQuery successful: wait_for_result_panel: waiting for '(?^u:Result: passed)' (count 199 of 3240)
1331
        # Wait for jQuery successful: wait_for_result_panel: waiting for '(?^u:Result: passed)' (count 200 of 3240)
1332
[debug] [pid:14566] Unrecognized referer 'localhost'
1333
        # Wait for jQuery successful: wait_for_result_panel: waiting for '(?^u:Result: passed)' (count 201 of 3240)
1334
        # Wait for jQuery successful: wait_for_result_panel: waiting for '(?^u:Result: passed)' (count 202 of 3240)
1335
        # Wait for jQuery successful: wait_for_result_panel: waiting for '(?^u:Result: passed)' (count 203 of 3240)
1336
        # Wait for jQuery successful: wait_for_result_panel: waiting for '(?^u:Result: passed)' (count 204 of 3240)
1337
[debug] [pid:14565] Updating seen of worker 1 from worker_status (working)
1338
        # Wait for jQuery successful: wait_for_result_panel: waiting for '(?^u:Result: passed)' (count 205 of 3240)
1339
[debug] [pid:15361] REST-API call: POST http://localhost:9526/api/v1/jobs/6/status
1340
[debug] [pid:15361] Upload concluded (at shutdown)
1341
        # Wait for jQuery successful: wait_for_result_panel: waiting for '(?^u:Result: passed)' (count 206 of 3240)
1342
        # Wait for jQuery successful: wait_for_result_panel: waiting for '(?^u:Result: passed)' (count 207 of 3240)
1343
        # Wait for jQuery successful: wait_for_result_panel: waiting for '(?^u:Result: passed)' (count 208 of 3240)
1344
        # Wait for jQuery successful: wait_for_result_panel: waiting for '(?^u:Result: passed)' (count 209 of 3240)
1345
        # Wait for jQuery successful: wait_for_result_panel: waiting for '(?^u:Result: passed)' (count 210 of 3240)
1346
[debug] [pid:14566] Unrecognized referer 'localhost'
1347
        # Wait for jQuery successful: wait_for_result_panel: waiting for '(?^u:Result: passed)' (count 211 of 3240)
1348
        # Wait for jQuery successful: wait_for_result_panel: waiting for '(?^u:Result: passed)' (count 212 of 3240)
1349
        # Wait for jQuery successful: wait_for_result_panel: waiting for '(?^u:Result: passed)' (count 213 of 3240)
1350
        # Wait for jQuery successful: wait_for_result_panel: waiting for '(?^u:Result: passed)' (count 214 of 3240)
1351
        # Wait for jQuery successful: wait_for_result_panel: waiting for '(?^u:Result: passed)' (count 215 of 3240)
1352
        # Wait for jQuery successful: wait_for_result_panel: waiting for '(?^u:Result: passed)' (count 216 of 3240)
1353
        # Wait for jQuery successful: wait_for_result_panel: waiting for '(?^u:Result: passed)' (count 217 of 3240)
1354
        # Wait for jQuery successful: wait_for_result_panel: waiting for '(?^u:Result: passed)' (count 218 of 3240)
1355
        # Wait for jQuery successful: wait_for_result_panel: waiting for '(?^u:Result: passed)' (count 219 of 3240)
1356
[debug] [pid:14566] Unrecognized referer 'localhost'
1357
        # Wait for jQuery successful: wait_for_result_panel: waiting for '(?^u:Result: passed)' (count 220 of 3240)
1358
        # Wait for jQuery successful: wait_for_result_panel: waiting for '(?^u:Result: passed)' (count 221 of 3240)
1359
[info] [pid:15361] Isotovideo exit status: 0
1360
[debug] [pid:15361] Stopping job 6 from http://localhost:9526: 00000006-tinycore-1-flavor-i386-Build1-core@coolone - reason: done
1361
[debug] [pid:15361] REST-API call: POST http://localhost:9526/api/v1/jobs/6/status
1362
[info] [pid:15361] +++ worker notes +++
1363
[info] [pid:15361] End time: 2022-03-01 15:30:47
1364
[info] [pid:15361] Result: done
1365
[info] [pid:15604] Uploading video.ogv
1366
[debug] [pid:15604] Uploading artefact video.ogv
1367
        # Wait for jQuery successful: wait_for_result_panel: waiting for '(?^u:Result: passed)' (count 222 of 3240)
1368
[info] [pid:15604] Uploading vars.json
1369
[debug] [pid:15604] Uploading artefact vars.json
1370
[info] [pid:15604] Uploading autoinst-log.txt
1371
[debug] [pid:15604] Uploading artefact autoinst-log.txt
1372
[info] [pid:15604] Uploading worker-log.txt
1373
[debug] [pid:15604] Uploading artefact worker-log.txt
1374
[info] [pid:15604] Uploading serial0.txt
1375
[debug] [pid:15604] Uploading artefact serial0.txt
1376
[info] [pid:15604] Uploading video_time.vtt
1377
[debug] [pid:15604] Uploading artefact video_time.vtt
1378
[info] [pid:15604] Uploading serial_terminal.txt
1379
[debug] [pid:15604] Uploading artefact serial_terminal.txt
1380
[info] [pid:15604] Uploading virtio_console1.log
1381
[debug] [pid:15604] Uploading artefact virtio_console1.log
1382
[debug] [pid:15361] Considering job 6 as regularly done
1383
[debug] [pid:15361] REST-API call: POST http://localhost:9526/api/v1/jobs/6/status
1384
[debug] [pid:14566] creating 68d/7ac/83452b72555f8a6b386629f91f.png
1385
[debug] [pid:14566] creating 68d/7ac/83452b72555f8a6b386629f91f.png
1386
[debug] [pid:14566] creating d95/4da/9d6d29536ba2b96c0092309cbb.png
1387
[debug] [pid:15605] Optimizing /home/squamata/project/test-results/fullstack/full-stack.d/openqa/pool/1/testresults/shutdown-2.png
1388
[debug] [pid:15605] Uploading artefact shutdown-2.png as d954da9d6d29536ba2b96c0092309cbb
1389
[debug] [pid:15605] Optimizing /home/squamata/project/test-results/fullstack/full-stack.d/openqa/pool/1/testresults/.thumbs/shutdown-2.png
1390
[debug] [pid:15605] Uploading artefact shutdown-2.png as d954da9d6d29536ba2b96c0092309cbb
1391
[debug] [pid:15605] Uploading artefact shutdown-3.txt
1392
[debug] [pid:15361] Upload concluded (no current module)
1393
[debug] [pid:15361] REST-API call: POST http://localhost:9526/api/v1/jobs/6/set_done?worker_id=1
1394
[debug] [pid:14566] checking take over from 5: GOOD vs shutdown:failed
1395
[debug] [pid:14566] checking take over from 1: GOOD vs shutdown:failed
1396
[debug] [pid:14566] ignoring job with repeated problem
1397
[debug] [pid:15361] Job 6 from http://localhost:9526 finished - reason: done
1398
[debug] [pid:15361] Cleaning up for next job
1399
        # Wait for jQuery successful: wait_for_result_panel: waiting for '(?^u:Result: passed)' (count 223 of 3240)
1400
        # Wait for jQuery successful: wait_for_result_panel: waiting for '(?^u:Result: passed)' (count 224 of 3240)
1401
        # Wait for jQuery successful: wait_for_result_panel: waiting for '(?^u:Result: passed)' (count 225 of 3240)
1402
        # Wait for jQuery successful: wait_for_result_panel: waiting for '(?^u:Result: passed)' (count 226 of 3240)
1403
        # Wait for jQuery successful: wait_for_result_panel: waiting for '(?^u:Result: passed)' (count 227 of 3240)
1404
        # Wait for jQuery successful: wait_for_result_panel: waiting for '(?^u:Result: passed)' (count 228 of 3240)
1405
        # Wait for jQuery successful: wait_for_result_panel: waiting for '(?^u:Result: passed)' (count 229 of 3240)
1406
[debug] [pid:14566] Unrecognized referer 'localhost'
1407
[debug] [pid:14566] Unrecognized referer 'localhost'
1408
[debug] [pid:14566] Unrecognized referer 'localhost'
1409
[debug] looking for "d95/4da/.thumbs/9d6d29536ba2b96c0092309cbb.png" in [
1410
  "/home/squamata/project/test-results/fullstack/full-stack.d/openqa/images",
1411
]
1412
[debug] found bless({
1413
  path => "/home/squamata/project/test-results/fullstack/full-stack.d/openqa/images/d95/4da/.thumbs/9d6d29536ba2b96c0092309cbb.png",
1414
  pid  => 14566,
1415
}, "Mojo::Asset::File")
1416
        # Wait for jQuery successful: wait_for_result_panel: waiting for '(?^u:Result: passed)' (count 230 of 3240)
1417
        ok 1 - No unexpected js warnings
1418
        not ok 2 - Expected result not found
1419
        not ok 3 - job 6 passed
1420
        # job info: {
1421
        #   'assigned_worker_id' => 1,
1422
        #   'blocked_by_id' => undef,
1423
        #   'clone_id' => undef,
1424
        #   'group_id' => undef,
1425
        #   'id' => 6,
1426
        #   'name' => 'tinycore-1-flavor-i386-Build1-core@coolone',
1427
        #   'origin_id' => 5,
1428
        #   'priority' => 50,
1429
        #   'result' => 'failed',
1430
        #   'settings' => {
1431
        #     'ARCH' => 'i386',
1432
        #     'BUILD' => '1',
1433
        #     'DISTRI' => 'tinycore',
1434
        #     'FLAVOR' => 'flavor',
1435
        #     'INTEGRATION_TESTS' => '1',
1436
        #     'ISO' => 'Core-7.2.iso',
1437
        #     'MACHINE' => 'coolone',
1438
        #     'NAME' => '00000006-tinycore-1-flavor-i386-Build1-core@coolone',
1439
        #     'PUBLISH_HDD_1' => '',
1440
        #     'QEMU' => 'i386',
1441
        #     'QEMU_NO_FDC_SET' => '1',
1442
        #     'QEMU_NO_KVM' => '1',
1443
        #     'QEMU_NO_TABLET' => '1',
1444
        #     'TEST' => 'core',
1445
        #     'UEFI_PFLASH_VARS' => '/usr/share/qemu/ovmf-x86_64.bin',
1446
        #     'VERSION' => '1',
1447
        #     'WORKER_CLASS' => 'qemu_i386'
1448
        #   },
1449
        #   'state' => 'done',
1450
        #   't_finished' => '2022-03-01T15:30:47',
1451
        #   't_started' => '2022-03-01T15:28:52',
1452
        #   'test' => 'core'
1453
        # }
1454
[info] [pid:15361] Received signal TERM
1455
[debug] [pid:15361] Informing http://localhost:9526 that we are going offline
1456
[info] [pid:14565] Worker 1 websocket connection closed - 1006
1457
        ok 4 - Test 6 autoinst-log.txt file created
1458
        ok 5 - asset 5.qcow2 removed during cache init
1459
        ok 6 - Core-7.2.iso the most recent asset again
1460
        1..6
1461
    not ok 14 - results of test 6
1462
[debug] Restarting job 6
1463
[debug] [pid:14566] Duplicating jobs: {
1464
  6 => {
1465
         chained_children => [],
1466
         chained_parents => [],
1467
         directly_chained_children => [],
1468
         directly_chained_parents => [],
1469
         is_parent_or_initial_job => 1,
1470
         ok => 0,
1471
         parallel_children => [],
1472
         parallel_parents => [],
1473
         state => "done",
1474
       },
1475
}
1476
[debug] [pid:14566] Job 6 duplicated as 7
1477
[warn] [pid:14566] Unable to wakeup scheduler: Connection refused
1478
    ok 15 - client returned new test_url for test 7
1479
[debug] [pid:14566] Unrecognized referer 'localhost'
1480
    ok 16 - test 7 is scheduled
1481
    ok 17 - Worker started as IPC::Run=HASH(0x5574267342f0)
1482
[debug] [pid:14566] Unrecognized referer 'localhost'
1483
    ok 18 - job with worker class qemu_i386 scheduled
1484
[info] [pid:15611] worker 1:
1485
 - config file:           /home/squamata/project/test-results/fullstack/full-stack.d/config/workers.ini
1486
 - worker hostname:       1a81a2b0ff0f
1487
 - isotovideo version:    25
1488
 - websocket API version: 1
1489
 - web UI hosts:          http://localhost:9526
1490
 - class:                 qemu_i386,qemu_x86_64
1491
 - no cleanup:            no
1492
 - pool directory:        /home/squamata/project/test-results/fullstack/full-stack.d/openqa/pool/1
1493
[info] [pid:15611] CACHE: caching is enabled, setting up /home/squamata/project/test-results/fullstack/full-stack.d/cache/localhost
1494
[info] [pid:15611] Project dir for host http://localhost:9526 is /home/squamata/project/test-results/fullstack/full-stack.d/openqa/share
1495
[info] [pid:15611] Registering with openQA http://localhost:9526
1496
[info] [pid:15611] Establishing ws connection via ws://localhost:9526/api/v1/ws/1
1497
[info] [pid:15611] Registered and connected via websockets with openQA host http://localhost:9526 and worker ID 1
1498
[debug] [pid:14565] Updating seen of worker 1 from worker_status (free)
1499
    ok 19 - at least one free worker with class qemu_i386 registered
1500
[debug] [pid:14560] +=----------------=+
1501
[debug] [pid:14560] -> Scheduling new jobs.
1502
[debug] [pid:14560] 	 Free workers: 1/1
1503
[debug] [pid:14560] 	 Scheduled jobs: 1
1504
[debug] [pid:14560] Need to schedule 1 parallel jobs for job 7 (with priority 50)
1505
[debug] [pid:14560] Assigned job '7' to worker ID '1'
1506
[debug] [pid:14560] [Job#7] Prepare for being processed by worker 1
1507
[debug] [pid:14565] Started to send message to 1 for job(s) 7
1508
[debug] [pid:14560] Sent job(s) '7' to worker '1'
1509
[debug] [pid:14560] Scheduler took 0.08196s to perform operations and allocated 1 jobs
1510
[debug] [pid:15611] Accepting job 7 from http://localhost:9526.
1511
[debug] [pid:14560] Allocated: { job => 7, worker => 1 }
1512
    # Subtest: results of test 7
1513
[debug] [pid:15611] Setting job 7 from http://localhost:9526 up
1514
[debug] [pid:15611] Preparing Mojo::IOLoop::ReadWriteProcess::Session
1515
[info] [pid:15611] +++ setup notes +++
1516
[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)
1517
[debug] [pid:15611] Job settings:
1518
[debug] [pid:15611] 
1519
    ARCH=i386
1520
    BUILD=1
1521
    CACHEDIRECTORY=/home/squamata/project/test-results/fullstack/full-stack.d/cache
1522
    CACHELIMIT=50
1523
    DISTRI=tinycore
1524
    FLAVOR=flavor
1525
    INTEGRATION_TESTS=1
1526
    ISO=Core-7.2.iso
1527
    JOBTOKEN=gNLfIAyXupl3BtPb
1528
    LOCAL_UPLOAD=0
1529
    LOG_LEVEL=debug
1530
    MACHINE=coolone
1531
    NAME=00000007-tinycore-1-flavor-i386-Build1-core@coolone
1532
    OPENQA_HOSTNAME=localhost:9526
1533
    OPENQA_URL=http://localhost:9526
1534
    PRJDIR=/home/squamata/project/test-results/fullstack/full-stack.d/openqa/share
1535
    PUBLISH_HDD_1=
1536
    QEMU=i386
1537
    QEMUPORT=20012
1538
    QEMU_NO_FDC_SET=1
1539
    QEMU_NO_KVM=1
1540
    QEMU_NO_TABLET=1
1541
    RETRY_DELAY=5
1542
    RETRY_DELAY_IF_WEBUI_BUSY=60
1543
    TEST=core
1544
    UEFI_PFLASH_VARS=/usr/share/qemu/ovmf-x86_64.bin
1545
    VERSION=1
1546
    VNC=91
1547
    WORKER_CLASS=qemu_i386,qemu_x86_64
1548
    WORKER_ID=1
1549
    WORKER_INSTANCE=1
1550
        # Wait for jQuery successful: wait_for_result_panel: waiting for '(?^u:Result: passed)' (count 0 of 3240)
1551
[debug] [pid:15611] Found ISO, caching Core-7.2.iso
1552
[info] [pid:15611] Downloading Core-7.2.iso, request #3 sent to Cache Service
1553
[debug] [pid:15611] Updating status so job 7 is not considered dead.
1554
[debug] [pid:15611] REST-API call: POST http://localhost:9526/api/v1/jobs/7/status
1555
[debug] [pid:14565] Worker 1 accepted job 7
1556
[debug] redirect to /assets/iso/Core-7.2.iso
1557
        # Wait for jQuery successful: wait_for_result_panel: waiting for '(?^u:Result: passed)' (count 1 of 3240)
1558
        # Wait for jQuery successful: wait_for_result_panel: waiting for '(?^u:Result: passed)' (count 2 of 3240)
1559
        # Wait for jQuery successful: wait_for_result_panel: waiting for '(?^u:Result: passed)' (count 3 of 3240)
1560
        # Wait for jQuery successful: wait_for_result_panel: waiting for '(?^u:Result: passed)' (count 4 of 3240)
1561
        # Wait for jQuery successful: wait_for_result_panel: waiting for '(?^u:Result: passed)' (count 5 of 3240)
1562
[debug] [pid:14566] Unrecognized referer 'localhost'
1563
[debug] [pid:14566] Unrecognized referer 'localhost'
1564
[debug] [pid:14566] Unrecognized referer 'localhost'
1565
[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
1566
[debug] [pid:14566] Unrecognized referer 'localhost'
1567
[debug] [pid:14566] Unrecognized referer 'localhost'
1568
[debug] [pid:14566] Asking the worker 1 to start providing livestream for job 7
1569
        # Wait for jQuery successful: wait_for_result_panel: waiting for '(?^u:Result: passed)' (count 6 of 3240)
1570
        # Wait for jQuery successful: wait_for_result_panel: waiting for '(?^u:Result: passed)' (count 7 of 3240)
1571
        # Wait for jQuery successful: wait_for_result_panel: waiting for '(?^u:Result: passed)' (count 8 of 3240)
1572
        # Wait for jQuery successful: wait_for_result_panel: waiting for '(?^u:Result: passed)' (count 9 of 3240)
1573
[debug] [pid:15611] Updating status so job 7 is not considered dead.
1574
[debug] [pid:15611] REST-API call: POST http://localhost:9526/api/v1/jobs/7/status
1575
[info] [pid:15611] Download of Core-7.2.iso processed
1576
[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"
1577
[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"
1578
[info] [pid:15611] Preparing cgroup to start isotovideo
1579
[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.
1580
[info] [pid:15611] You can define a custom slice with OPENQA_CGROUP_SLICE or indicating the base mount with MOJO_CGROUP_FS.
1581
[info] [pid:15611] Starting isotovideo container
1582
[debug] [pid:15611] Registered process:15619
1583
[info] [pid:15619] 15619: WORKING 7
1584
[debug] [pid:15619] +++ worker notes +++
1585
[info] [pid:15611] isotovideo has been started (PID: 15619)
1586
        # Wait for jQuery successful: wait_for_result_panel: waiting for '(?^u:Result: passed)' (count 10 of 3240)
1587
[debug] [pid:15611] Running job 7 from http://localhost:9526: 00000007-tinycore-1-flavor-i386-Build1-core@coolone.
1588
[debug] [pid:15611] REST-API call: POST http://localhost:9526/api/v1/jobs/7/status
1589
[debug] [pid:14565] Updating seen of worker 1 from worker_status (working)
1590
[debug] [pid:15611] Upload concluded (no current module)
1591
        # Wait for jQuery successful: wait_for_result_panel: waiting for '(?^u:Result: passed)' (count 11 of 3240)
1592
        # Wait for jQuery successful: wait_for_result_panel: waiting for '(?^u:Result: passed)' (count 12 of 3240)
1593
        # Wait for jQuery successful: wait_for_result_panel: waiting for '(?^u:Result: passed)' (count 13 of 3240)
1594
        # Wait for jQuery successful: wait_for_result_panel: waiting for '(?^u:Result: passed)' (count 14 of 3240)
1595
[debug] [pid:14566] Unrecognized referer 'localhost'
1596
        # Wait for jQuery successful: wait_for_result_panel: waiting for '(?^u:Result: passed)' (count 15 of 3240)
1597
        # Wait for jQuery successful: wait_for_result_panel: waiting for '(?^u:Result: passed)' (count 16 of 3240)
1598
        # Wait for jQuery successful: wait_for_result_panel: waiting for '(?^u:Result: passed)' (count 17 of 3240)
1599
        # Wait for jQuery successful: wait_for_result_panel: waiting for '(?^u:Result: passed)' (count 18 of 3240)
1600
        # Wait for jQuery successful: wait_for_result_panel: waiting for '(?^u:Result: passed)' (count 19 of 3240)
1601
        # Wait for jQuery successful: wait_for_result_panel: waiting for '(?^u:Result: passed)' (count 20 of 3240)
1602
        # Wait for jQuery successful: wait_for_result_panel: waiting for '(?^u:Result: passed)' (count 21 of 3240)
1603
        # Wait for jQuery successful: wait_for_result_panel: waiting for '(?^u:Result: passed)' (count 22 of 3240)
1604
        # Wait for jQuery successful: wait_for_result_panel: waiting for '(?^u:Result: passed)' (count 23 of 3240)
1605
        # Wait for jQuery successful: wait_for_result_panel: waiting for '(?^u:Result: passed)' (count 24 of 3240)
1606
[debug] [pid:14566] Unrecognized referer 'localhost'
1607
        # Wait for jQuery successful: wait_for_result_panel: waiting for '(?^u:Result: passed)' (count 25 of 3240)
1608
        # Wait for jQuery successful: wait_for_result_panel: waiting for '(?^u:Result: passed)' (count 26 of 3240)
1609
        # Wait for jQuery successful: wait_for_result_panel: waiting for '(?^u:Result: passed)' (count 27 of 3240)
1610
        # Wait for jQuery successful: wait_for_result_panel: waiting for '(?^u:Result: passed)' (count 28 of 3240)
1611
        # Wait for jQuery successful: wait_for_result_panel: waiting for '(?^u:Result: passed)' (count 29 of 3240)
1612
[debug] [pid:15611] REST-API call: POST http://localhost:9526/api/v1/jobs/7/status
1613
[debug] [pid:15611] Upload concluded (at boot)
1614
        # Wait for jQuery successful: wait_for_result_panel: waiting for '(?^u:Result: passed)' (count 30 of 3240)
1615
        # Wait for jQuery successful: wait_for_result_panel: waiting for '(?^u:Result: passed)' (count 31 of 3240)
1616
        # Wait for jQuery successful: wait_for_result_panel: waiting for '(?^u:Result: passed)' (count 32 of 3240)
1617
        # Wait for jQuery successful: wait_for_result_panel: waiting for '(?^u:Result: passed)' (count 33 of 3240)
1618
        # Wait for jQuery successful: wait_for_result_panel: waiting for '(?^u:Result: passed)' (count 34 of 3240)
1619
[debug] [pid:14566] Unrecognized referer 'localhost'
1620
[debug] [pid:14566] Unrecognized referer 'localhost'
1621
[debug] [pid:14643] connecting to os-autoinst command server for job 7 at ws://1a81a2b0ff0f:20013/gNLfIAyXupl3BtPb/ws
1622
        # Wait for jQuery successful: wait_for_result_panel: waiting for '(?^u:Result: passed)' (count 35 of 3240)
1623
        # Wait for jQuery successful: wait_for_result_panel: waiting for '(?^u:Result: passed)' (count 36 of 3240)
1624
        # Wait for jQuery successful: wait_for_result_panel: waiting for '(?^u:Result: passed)' (count 37 of 3240)
1625
        # Wait for jQuery successful: wait_for_result_panel: waiting for '(?^u:Result: passed)' (count 38 of 3240)
1626
        # Wait for jQuery successful: wait_for_result_panel: waiting for '(?^u:Result: passed)' (count 39 of 3240)
1627
        # Wait for jQuery successful: wait_for_result_panel: waiting for '(?^u:Result: passed)' (count 40 of 3240)
1628
        # Wait for jQuery successful: wait_for_result_panel: waiting for '(?^u:Result: passed)' (count 41 of 3240)
1629
        # Wait for jQuery successful: wait_for_result_panel: waiting for '(?^u:Result: passed)' (count 42 of 3240)
1630
        # Wait for jQuery successful: wait_for_result_panel: waiting for '(?^u:Result: passed)' (count 43 of 3240)
1631
[debug] [pid:14566] Unrecognized referer 'localhost'
1632
        # Wait for jQuery successful: wait_for_result_panel: waiting for '(?^u:Result: passed)' (count 44 of 3240)
1633
        # Wait for jQuery successful: wait_for_result_panel: waiting for '(?^u:Result: passed)' (count 45 of 3240)
1634
        # Wait for jQuery successful: wait_for_result_panel: waiting for '(?^u:Result: passed)' (count 46 of 3240)
1635
        # Wait for jQuery successful: wait_for_result_panel: waiting for '(?^u:Result: passed)' (count 47 of 3240)
1636
        # Wait for jQuery successful: wait_for_result_panel: waiting for '(?^u:Result: passed)' (count 48 of 3240)
1637
[debug] [pid:14565] Updating seen of worker 1 from worker_status (working)
1638
[debug] [pid:15611] REST-API call: POST http://localhost:9526/api/v1/jobs/7/status
1639
[debug] [pid:14566] creating f41/844/68dbb276a03240907d0e7e500d.png
1640
[debug] [pid:14566] creating e3b/43b/69c91fe4072dac1037f416c281.png
1641
[debug] [pid:15611] Upload concluded (up to boot)
1642
        # Wait for jQuery successful: wait_for_result_panel: waiting for '(?^u:Result: passed)' (count 49 of 3240)
1643
        # Wait for jQuery successful: wait_for_result_panel: waiting for '(?^u:Result: passed)' (count 50 of 3240)
1644
        # Wait for jQuery successful: wait_for_result_panel: waiting for '(?^u:Result: passed)' (count 51 of 3240)
1645
        # Wait for jQuery successful: wait_for_result_panel: waiting for '(?^u:Result: passed)' (count 52 of 3240)
1646
[info] [pid:15611] Isotovideo exit status: 0
1647
[debug] [pid:15611] Stopping job 7 from http://localhost:9526: 00000007-tinycore-1-flavor-i386-Build1-core@coolone - reason: done
1648
[debug] [pid:15611] REST-API call: POST http://localhost:9526/api/v1/jobs/7/status
1649
[info] [pid:15611] +++ worker notes +++
1650
[info] [pid:15611] End time: 2022-03-01 15:31:23
1651
[info] [pid:15611] Result: done
1652
[info] [pid:15840] Uploading video.ogv
1653
[debug] [pid:15840] Uploading artefact video.ogv
1654
[info] [pid:15840] Uploading vars.json
1655
[debug] [pid:15840] Uploading artefact vars.json
1656
[info] [pid:15840] Uploading autoinst-log.txt
1657
[debug] [pid:15840] Uploading artefact autoinst-log.txt
1658
[info] [pid:15840] Uploading worker-log.txt
1659
[debug] [pid:15840] Uploading artefact worker-log.txt
1660
[info] [pid:15840] Uploading serial0.txt
1661
[debug] [pid:15840] Uploading artefact serial0.txt
1662
[info] [pid:15840] Uploading video_time.vtt
1663
[debug] [pid:15840] Uploading artefact video_time.vtt
1664
        # Wait for jQuery successful: wait_for_result_panel: waiting for '(?^u:Result: passed)' (count 53 of 3240)
1665
[info] [pid:15840] Uploading serial_terminal.txt
1666
[debug] [pid:15840] Uploading artefact serial_terminal.txt
1667
[info] [pid:15840] Uploading virtio_console1.log
1668
[debug] [pid:15840] Uploading artefact virtio_console1.log
1669
[debug] [pid:15611] Considering job 7 as regularly done
1670
[debug] [pid:15611] REST-API call: POST http://localhost:9526/api/v1/jobs/7/status
1671
[debug] [pid:14566] creating e3b/43b/69c91fe4072dac1037f416c281.png
1672
[debug] [pid:14566] creating e3b/43b/69c91fe4072dac1037f416c281.png
1673
[debug] [pid:14566] creating 9a3/9ff/f3019996d3774d4fb9a634e520.png
1674
[debug] [pid:15841] Optimizing /home/squamata/project/test-results/fullstack/full-stack.d/openqa/pool/1/testresults/shutdown-2.png
1675
[debug] [pid:15841] Uploading artefact shutdown-2.png as 9a39fff3019996d3774d4fb9a634e520
1676
[debug] [pid:15841] Optimizing /home/squamata/project/test-results/fullstack/full-stack.d/openqa/pool/1/testresults/.thumbs/shutdown-2.png
1677
[debug] [pid:15841] Uploading artefact shutdown-2.png as 9a39fff3019996d3774d4fb9a634e520
1678
[debug] [pid:15611] Upload concluded (no current module)
1679
[debug] [pid:15611] REST-API call: POST http://localhost:9526/api/v1/jobs/7/set_done?worker_id=1
1680
[debug] [pid:14566] Unrecognized referer 'localhost'
1681
[debug] [pid:15611] Job 7 from http://localhost:9526 finished - reason: done
1682
[debug] [pid:15611] Cleaning up for next job
1683
[debug] [pid:14566] Unrecognized referer 'localhost'
1684
[debug] [pid:14566] Unrecognized referer 'localhost'
1685
        # Wait for jQuery successful: wait_for_result_panel: waiting for '(?^u:Result: passed)' (count 54 of 3240)
1686
[debug] looking for "e3b/43b/.thumbs/69c91fe4072dac1037f416c281.png" in [
1687
  "/home/squamata/project/test-results/fullstack/full-stack.d/openqa/images",
1688
]
1689
[debug] found bless({
1690
  path => "/home/squamata/project/test-results/fullstack/full-stack.d/openqa/images/e3b/43b/.thumbs/69c91fe4072dac1037f416c281.png",
1691
  pid  => 14566,
1692
}, "Mojo::Asset::File")
1693
        ok 1 - job 7 passed
1694
        ok 2 - Test 7 autoinst-log.txt file created
1695
        ok 3 - Test 7 has worker notes
1696
        ok 4 - setup notes present
1697
        ok 5 - uploaded autoinst-log
1698
        1..5
1699
    ok 20 - results of test 7
1700
[debug] looking for "9a3/9ff/.thumbs/f3019996d3774d4fb9a634e520.png" in [
1701
  "/home/squamata/project/test-results/fullstack/full-stack.d/openqa/images",
1702
]
1703
[debug] found bless({
1704
  path => "/home/squamata/project/test-results/fullstack/full-stack.d/openqa/images/9a3/9ff/.thumbs/f3019996d3774d4fb9a634e520.png",
1705
  pid  => 14566,
1706
}, "Mojo::Asset::File")
1707
[debug] looking for "f41/844/.thumbs/68dbb276a03240907d0e7e500d.png" in [
1708
  "/home/squamata/project/test-results/fullstack/full-stack.d/openqa/images",
1709
]
1710
[debug] found bless({
1711
  path => "/home/squamata/project/test-results/fullstack/full-stack.d/openqa/images/f41/844/.thumbs/68dbb276a03240907d0e7e500d.png",
1712
  pid  => 14566,
1713
}, "Mojo::Asset::File")
1714
[warn] [pid:14566] Unable to wakeup scheduler: Connection refused
1715
    ok 21 - job with worker class qemu_i386 scheduled
1716
    ok 22 - at least one free worker with class qemu_i386 registered
1717
[debug] [pid:14560] +=----------------=+
1718
[debug] [pid:14560] -> Scheduling new jobs.
1719
[debug] [pid:14560] 	 Free workers: 1/1
1720
[debug] [pid:14560] 	 Scheduled jobs: 1
1721
[debug] [pid:14560] Need to schedule 1 parallel jobs for job 8 (with priority 50)
1722
[debug] [pid:14560] Assigned job '8' to worker ID '1'
1723
[debug] [pid:14560] [Job#8] Prepare for being processed by worker 1
1724
[debug] [pid:14565] Started to send message to 1 for job(s) 8
1725
[debug] [pid:14560] Sent job(s) '8' to worker '1'
1726
[debug] [pid:14560] Scheduler took 0.09979s to perform operations and allocated 1 jobs
1727
[debug] [pid:14560] Allocated: { job => 8, worker => 1 }
1728
[debug] [pid:15611] Accepting job 8 from http://localhost:9526.
1729
[debug] [pid:15611] Setting job 8 from http://localhost:9526 up
1730
[debug] [pid:15611] Preparing Mojo::IOLoop::ReadWriteProcess::Session
1731
[info] [pid:15611] +++ setup notes +++
1732
[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)
1733
[debug] [pid:15611] Job settings:
1734
[debug] [pid:15611] 
1735
    ARCH=i386
1736
    BUILD=1
1737
    CACHEDIRECTORY=/home/squamata/project/test-results/fullstack/full-stack.d/cache
1738
    CACHELIMIT=50
1739
    DISTRI=tinycore
1740
    FLAVOR=flavor
1741
    HDD_1=non-existent.qcow2
1742
    INTEGRATION_TESTS=1
1743
    ISO=Core-7.2.iso
1744
    JOBTOKEN=FyOb_mAEM1SQZfuT
1745
    LOCAL_UPLOAD=0
1746
    LOG_LEVEL=debug
1747
    MACHINE=coolone
1748
    NAME=00000008-tinycore-1-flavor-i386-Build1-core@coolone
1749
    OPENQA_HOSTNAME=localhost:9526
1750
    OPENQA_URL=http://localhost:9526
1751
    PRJDIR=/home/squamata/project/test-results/fullstack/full-stack.d/openqa/share
1752
    PUBLISH_HDD_1=core-hdd.qcow2
1753
    QEMU=i386
1754
    QEMUPORT=20012
1755
    QEMU_NO_FDC_SET=1
1756
    QEMU_NO_KVM=1
1757
    QEMU_NO_TABLET=1
1758
    RETRY_DELAY=5
1759
    RETRY_DELAY_IF_WEBUI_BUSY=60
1760
    TEST=core
1761
    UEFI_PFLASH_VARS=/usr/share/qemu/ovmf-x86_64.bin
1762
    VERSION=1
1763
    VNC=91
1764
    WORKER_CLASS=qemu_i386,qemu_x86_64
1765
    WORKER_ID=1
1766
    WORKER_INSTANCE=1
1767
[debug] [pid:15611] Found HDD_1, caching non-existent.qcow2
1768
[info] [pid:15611] Downloading non-existent.qcow2, request #4 sent to Cache Service
1769
[debug] [pid:15611] Updating status so job 8 is not considered dead.
1770
[debug] [pid:15611] REST-API call: POST http://localhost:9526/api/v1/jobs/8/status
1771
[debug] [pid:14566] Unrecognized referer 'localhost'
1772
[debug] [pid:14565] Worker 1 accepted job 8
1773
[debug] [pid:14566] Unrecognized referer 'localhost'
1774
[debug] [pid:14566] Unrecognized referer 'localhost'
1775
[debug] [pid:14566] Unrecognized referer 'localhost'
1776
[debug] [pid:14566] Unrecognized referer 'localhost'
1777
[debug] redirect to /assets/hdd/non-existent.qcow2
1778
[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
1779
[debug] [pid:14566] Unrecognized referer 'localhost'
1780
[debug] [pid:14566] Asking the worker 1 to start providing livestream for job 8
1781
    # Wait for jQuery successful: wait_for_result_panel: waiting for '(?^u:Result: incomplete)' (count 0 of 3240)
1782
    # Wait for jQuery successful: wait_for_result_panel: waiting for '(?^u:Result: incomplete)' (count 1 of 3240)
1783
    # Wait for jQuery successful: wait_for_result_panel: waiting for '(?^u:Result: incomplete)' (count 2 of 3240)
1784
    # Wait for jQuery successful: wait_for_result_panel: waiting for '(?^u:Result: incomplete)' (count 3 of 3240)
1785
    # Wait for jQuery successful: wait_for_result_panel: waiting for '(?^u:Result: incomplete)' (count 4 of 3240)
1786
    # Wait for jQuery successful: wait_for_result_panel: waiting for '(?^u:Result: incomplete)' (count 5 of 3240)
1787
    # Wait for jQuery successful: wait_for_result_panel: waiting for '(?^u:Result: incomplete)' (count 6 of 3240)
1788
    # Wait for jQuery successful: wait_for_result_panel: waiting for '(?^u:Result: incomplete)' (count 7 of 3240)
1789
    # Wait for jQuery successful: wait_for_result_panel: waiting for '(?^u:Result: incomplete)' (count 8 of 3240)
1790
    # Wait for jQuery successful: wait_for_result_panel: waiting for '(?^u:Result: incomplete)' (count 9 of 3240)
1791
[debug] [pid:15611] Updating status so job 8 is not considered dead.
1792
[debug] [pid:15611] REST-API call: POST http://localhost:9526/api/v1/jobs/8/status
1793
[info] [pid:15611] Download of non-existent.qcow2 processed
1794
[error] [pid:15611] Failed to download non-existent.qcow2 to /home/squamata/project/test-results/fullstack/full-stack.d/cache/localhost/non-existent.qcow2
1795
[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
1796
[debug] [pid:15611] Stopping job 8 from http://localhost:9526: 00000008-tinycore-1-flavor-i386-Build1-core@coolone - reason: setup failure
1797
[debug] [pid:15611] REST-API call: POST http://localhost:9526/api/v1/jobs/8/status
1798
[info] [pid:15611] +++ worker notes +++
1799
[info] [pid:15611] End time: 2022-03-01 15:31:31
1800
[info] [pid:15611] Result: setup failure
1801
[info] [pid:15848] Uploading autoinst-log.txt
1802
[debug] [pid:15848] Uploading artefact autoinst-log.txt
1803
[debug] [pid:14566] Unrecognized referer 'localhost'
1804
[info] [pid:15848] Uploading worker-log.txt
1805
[debug] [pid:15848] Uploading artefact worker-log.txt
1806
[debug] [pid:14566] Unrecognized referer 'localhost'
1807
[debug] [pid:14566] Unrecognized referer 'localhost'
1808
[debug] [pid:15611] Job 8 stopped as incomplete
1809
[warn] [pid:15611] Unable to upload results of the job because no command server URL or worker ID have been set.
1810
[debug] [pid:15611] Upload concluded (no current module)
1811
[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
1812
[debug] [pid:14566] Duplicating jobs: {
1813
  8 => {
1814
         chained_children => [],
1815
         chained_parents => [],
1816
         directly_chained_children => [],
1817
         directly_chained_parents => [],
1818
         is_parent_or_initial_job => 1,
1819
         ok => 0,
1820
         parallel_children => [],
1821
         parallel_parents => [],
1822
         state => "done",
1823
       },
1824
}
1825
[debug] [pid:14566] Job 8 duplicated as 9
1826
[debug] [pid:15611] Job 8 from http://localhost:9526 finished - reason: setup failure
1827
[debug] [pid:15611] Cleaning up for next job
1828
    # Wait for jQuery successful: wait_for_result_panel: waiting for '(?^u:Result: incomplete)' (count 10 of 3240)
1829
    # Wait for jQuery successful: wait_for_result_panel: waiting for '(?^u:Result: incomplete)' (count 11 of 3240)
1830
    # Wait for jQuery successful: wait_for_result_panel: waiting for '(?^u:Result: incomplete)' (count 12 of 3240)
1831
    # Wait for jQuery successful: wait_for_result_panel: waiting for '(?^u:Result: incomplete)' (count 13 of 3240)
1832
    # Wait for jQuery successful: wait_for_result_panel: waiting for '(?^u:Result: incomplete)' (count 14 of 3240)
1833
    # Wait for jQuery successful: wait_for_result_panel: waiting for '(?^u:Result: incomplete)' (count 15 of 3240)
1834
    # Wait for jQuery successful: wait_for_result_panel: waiting for '(?^u:Result: incomplete)' (count 16 of 3240)
1835
    # Wait for jQuery successful: wait_for_result_panel: waiting for '(?^u:Result: incomplete)' (count 17 of 3240)
1836
    # Wait for jQuery successful: wait_for_result_panel: waiting for '(?^u:Result: incomplete)' (count 18 of 3240)
1837
    # Wait for jQuery successful: wait_for_result_panel: waiting for '(?^u:Result: incomplete)' (count 19 of 3240)
1838
[debug] [pid:14566] Unrecognized referer 'localhost'
1839
[debug] [pid:14566] Unrecognized referer 'localhost'
1840
[debug] [pid:14566] Unrecognized referer 'localhost'
1841
[debug] [pid:14566] Unrecognized referer 'localhost'
1842
[debug] looking for "autoinst-log.txt" in [
1843
  "/home/squamata/project/test-results/fullstack/full-stack.d/openqa/testresults/00000/00000008-tinycore-1-flavor-i386-Build1-core\@coolone",
1844
  "/home/squamata/project/test-results/fullstack/full-stack.d/openqa/testresults/00000/00000008-tinycore-1-flavor-i386-Build1-core\@coolone/ulogs",
1845
]
1846
[debug] found bless({
1847
  path => "/home/squamata/project/test-results/fullstack/full-stack.d/openqa/testresults/00000/00000008-tinycore-1-flavor-i386-Build1-core\@coolone/autoinst-log.txt",
1848
  pid  => 14566,
1849
}, "Mojo::Asset::File")
1850
    # Wait for jQuery successful: wait_for_result_panel: waiting for '(?^u:Result: incomplete)' (count 20 of 3240)
1851
    ok 23 - job 8 is incomplete
1852
    ok 24 - reason for incomplete specified
1853
    # Subtest: log shown within details tab (without page reload)
1854
        # Wait for jQuery successful: autoinst log embedded within "Details" tab
1855
        ok 1 - element for embedded logfile present
1856
        # Wait for jQuery successful: log contents loaded
1857
        ok 2 - log contents present
1858
        1..2
1859
    ok 25 - log shown within details tab (without page reload)
1860
    # Subtest: results of test 8
1861
        ok 1 - autoinst-log.txt file created
1862
        ok 2 - worker notes present
1863
        ok 3 - setup notes present
1864
        ok 4 - autoinst-log uploaded
1865
        ok 5 - failure message found in log
1866
        ok 6 - job result result
1867
        1..6
1868
    ok 26 - results of test 8
1869
[info] [pid:15611] Received signal TERM
1870
[debug] [pid:15611] Informing http://localhost:9526 that we are going offline
1871
[info] [pid:14565] Worker 1 websocket connection closed - 1006
1872
    1..26
1873
not ok 36 - Cache tests
1874
ok 37 - no (unexpected) warnings (via done_testing)
1875
1..37
1876
    # Cache minion worker stopped
1877
    # Worker cache service on port 9530 stopped
1878
/home/squamata/project/test-results/fullstack/full-stack.d/openqa/testresults/00000/00000001-tinycore-1-flavor-i386-Build1-core@coolone/autoinst-log.txt:
1879
[2022-03-01T15:27:09.229Z] [info] [pid:14649] +++ setup notes +++
1880
[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)
1881
[2022-03-01T15:27:09.237109Z] [debug] [pid:14656] +++ worker notes +++
1882
[2022-03-01T15:27:10.955510Z] [debug] Current version is d410cc0dd1aa541233ea295ddfbe1d94a78c33ad [interface v25]
1883
[2022-03-01T15:27:10.963938Z] [debug] git hash in tinycore: d410cc0dd1aa541233ea295ddfbe1d94a78c33ad
1884
[2022-03-01T15:27:11.052625Z] [debug] scheduling boot tests/boot.pm
1885
[2022-03-01T15:27:11.053369Z] [debug] scheduling assert_screen tests/assert_screen.pm
1886
[2022-03-01T15:27:11.054045Z] [debug] scheduling shutdown tests/shutdown.pm
1887
[2022-03-01T15:27:11.059789Z] [info] cmdsrv: daemon reachable under http://*:20013/N503ZgOJZf1SW84y/
1888
[2022-03-01T15:27:11.061762Z] [info] Listening at "http://0.0.0.0:20013"
1889
Web application available at http://0.0.0.0:20013
1890
[2022-03-01T15:27:11.062907Z] [debug] git hash in tinycore/needles: d410cc0dd1aa541233ea295ddfbe1d94a78c33ad
1891
[2022-03-01T15:27:11.063012Z] [debug] init needles from tinycore/needles
1892
[2022-03-01T15:27:11.064311Z] [debug] loaded 4 needles
1893
[2022-03-01T15:27:11.066999Z] [debug] Blocking SIGCHLD and SIGTERM
1894
[2022-03-01T15:27:11.266252Z] [debug] Unblocking SIGCHLD and SIGTERM
1895
[2022-03-01T15:27:11.329222Z] [debug] 14656: channel_out 15, channel_in 14
1896
[2022-03-01T15:27:11.329228Z] [debug] Blocking SIGCHLD and SIGTERM
1897
[2022-03-01T15:27:11.466319Z] [debug] Unblocking SIGCHLD and SIGTERM
1898
[2022-03-01T15:27:11.467932Z] [debug] 14735: cmdpipe 13, rsppipe 16
1899
[2022-03-01T15:27:11.468019Z] [debug] started mgmt loop with pid 14735
1900
[2022-03-01T15:27:11.665204Z] [debug] qemu version detected: 5.2.0
1901
[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`
1902
[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.
1903
  
1904
[2022-03-01T15:27:11.672679Z] [debug] Configuring storage controllers and block devices
1905
[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`
1906
[2022-03-01T15:27:11.681483Z] [debug] Initializing block device images
1907
[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`
1908
[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
1909
[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`
1910
[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
1911
[2022-03-01T15:27:11.700033Z] [debug] init_blockdev_images: Finished creating block devices
1912
[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
1913
[2022-03-01T15:27:11.703941Z] [debug] Waiting for 0 attempts
1914
[2022-03-01T15:27:12.704546Z] [debug] Waiting for 1 attempts
1915
[2022-03-01T15:27:13.704925Z] [debug] Finished after 2 attempts
1916
[2022-03-01T15:27:13.706840Z] [debug] Establishing VNC connection to localhost:5991
1917
[2022-03-01T15:27:13.709311Z] [debug] pointer type 0 0 640 480 -257
1918
[2022-03-01T15:27:13.709390Z] [debug] led state 0 1 1 -261
1919
[2022-03-01T15:27:13.768908Z] [debug] Start CPU
1920
[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}}
1921
[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}}
1922
[2022-03-01T15:27:13.769366Z] [debug] EVENT {"event":"RESUME","timestamp":{"microseconds":769273,"seconds":1646148433}}
1923
GOT GO
1924

    
1925
[2022-03-01T15:27:13.777576Z] [debug] QEMU: QEMU emulator version 5.2.0 (SUSE Linux Enterprise 15)
1926
[2022-03-01T15:27:13.777632Z] [debug] QEMU: Copyright (c) 2003-2020 Fabrice Bellard and the QEMU Project developers
1927
[2022-03-01T15:27:13.781214Z] [debug] Snapshots are supported
1928
[2022-03-01T15:27:13.782063Z] [debug] ||| starting boot tests/boot.pm
1929
[2022-03-01T15:27:13.783971Z] [debug] tests/boot.pm:9 called testapi::assert_screen
1930
[2022-03-01T15:27:13.784254Z] [debug] <<< testapi::assert_screen(mustmatch="core", no_wait=1, timeout=15)
1931
[2022-03-01T15:27:13.798123Z] [debug] no match: 14.9s, best candidate: boot-core (0.00)
1932
[2022-03-01T15:27:13.898872Z] [debug] no change: 14.8s
1933
[2022-03-01T15:27:13.905483Z] [debug] no match: 14.8s, best candidate: boot-core (0.00)
1934
[2022-03-01T15:27:14.006180Z] [debug] no change: 14.7s
1935
[2022-03-01T15:27:14.012824Z] [debug] no match: 14.7s, best candidate: boot-core (0.00)
1936
[2022-03-01T15:27:14.113611Z] [debug] no change: 14.6s
1937
[2022-03-01T15:27:14.120191Z] [debug] no match: 14.6s, best candidate: boot-core (0.00)
1938
[2022-03-01T15:27:14.220961Z] [debug] no change: 14.5s
1939
[2022-03-01T15:27:14.227566Z] [debug] no match: 14.5s, best candidate: boot-core (0.00)
1940
[2022-03-01T15:27:14.402820Z] [debug] >>> testapi::_handle_found_needle: found boot-core, similarity 0.97 @ 1/74
1941
[2022-03-01T15:27:14.403325Z] [debug] tests/boot.pm:10 called testapi::send_key
1942
[2022-03-01T15:27:14.403442Z] [debug] <<< testapi::send_key(key="ret", do_wait=0, wait_screen_change=0)
1943
[2022-03-01T15:27:14.672890Z] [debug] tests/boot.pm:14 called testapi::assert_screen
1944
[2022-03-01T15:27:14.673060Z] [debug] <<< testapi::assert_screen(mustmatch="on_prompt", timeout=90)
1945
[2022-03-01T15:27:15.334360Z] [debug] no match: 89.3s, best candidate: boot-on_prompt (0.00)
1946
[2022-03-01T15:27:16.331508Z] [debug] no match: 88.3s, best candidate: boot-on_prompt (0.00)
1947
[2022-03-01T15:27:17.331829Z] [debug] no match: 87.3s, best candidate: boot-on_prompt (0.00)
1948
[2022-03-01T15:27:18.332935Z] [debug] no match: 86.3s, best candidate: boot-on_prompt (0.00)
1949
[2022-03-01T15:27:19.374586Z] [debug] no match: 85.3s, best candidate: boot-on_prompt (0.00)
1950
[2022-03-01T15:27:20.335169Z] [debug] no match: 84.3s, best candidate: boot-on_prompt (0.00)
1951
[2022-03-01T15:27:21.335756Z] [debug] no match: 83.3s, best candidate: boot-on_prompt (0.00)
1952
[2022-03-01T15:27:22.336941Z] [debug] no match: 82.3s, best candidate: boot-on_prompt (0.00)
1953
[2022-03-01T15:27:23.337923Z] [debug] no match: 81.3s, best candidate: boot-on_prompt (0.00)
1954
[2022-03-01T15:27:24.440512Z] [debug] >>> testapi::_handle_found_needle: found boot-on_prompt, similarity 1.00 @ 2/64
1955
[2022-03-01T15:27:24.443024Z] [debug] ||| finished boot tests (runtime: 11 s)
1956
[2022-03-01T15:27:24.444214Z] [debug] ||| starting assert_screen tests/assert_screen.pm
1957
[2022-03-01T15:27:24.444847Z] [debug] tests/assert_screen.pm:9 called testapi::assert_screen
1958
[2022-03-01T15:27:24.444974Z] [debug] <<< testapi::assert_screen(mustmatch="on_prompt", timeout=60)
1959
[2022-03-01T15:27:25.399173Z] [debug] >>> testapi::_handle_found_needle: found boot-on_prompt, similarity 1.00 @ 2/64
1960
[2022-03-01T15:27:25.399322Z] [debug] tests/assert_screen.pm:10 called testapi::assert_screen
1961
[2022-03-01T15:27:25.399426Z] [debug] <<< testapi::assert_screen(mustmatch="on_prompt", timeout=30, no_wait=1)
1962
[2022-03-01T15:27:25.460511Z] [debug] >>> testapi::_handle_found_needle: found boot-on_prompt, similarity 1.00 @ 2/64
1963
[2022-03-01T15:27:25.465078Z] [debug] ||| finished assert_screen tests (runtime: 1 s)
1964
[2022-03-01T15:27:25.466026Z] [debug] ||| starting shutdown tests/shutdown.pm
1965
[2022-03-01T15:27:25.466526Z] [debug] isotovideo: pausing test execution of shutdown because we're supposed to pause at this test module
1966
[2022-03-01T15:27:25.466904Z] [debug] tests/shutdown.pm:8 called testapi::enter_cmd
1967
[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)
1968
[2022-03-01T15:27:25.467438Z] [debug] isotovideo: paused, so not passing backend_type_string to backend
1969
[2022-03-01T15:27:27.724775Z] [debug] isotovideo: test execution will be resumed
1970
[2022-03-01T15:27:27.725148Z] [debug] isotovideo: resuming, continue passing backend_type_string to backend
1971
[2022-03-01T15:27:28.200614Z] [debug] tests/shutdown.pm:9 called testapi::assert_shutdown
1972
[2022-03-01T15:27:28.200803Z] [debug] <<< testapi::check_shutdown(timeout=90)
1973
[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}}
1974
[2022-03-01T15:27:28.201662Z] [debug] QEMU status is not 'shutdown', it is 'running'
1975
[2022-03-01T15:27:29.203020Z] [debug] QEMU status is not 'shutdown', it is 'running'
1976
[2022-03-01T15:27:30.204510Z] [debug] QEMU status is not 'shutdown', it is 'running'
1977
[2022-03-01T15:27:31.205805Z] [debug] QEMU status is not 'shutdown', it is 'running'
1978
[2022-03-01T15:27:32.207209Z] [debug] QEMU status is not 'shutdown', it is 'running'
1979
[2022-03-01T15:27:33.208358Z] [debug] EVENT {"data":{"guest":true,"reason":"guest-shutdown"},"event":"SHUTDOWN","timestamp":{"microseconds":660515,"seconds":1646148452}}
1980
[2022-03-01T15:27:33.208452Z] [debug] EVENT {"event":"STOP","timestamp":{"microseconds":661035,"seconds":1646148452}}
1981
[2022-03-01T15:27:33.273069Z] [debug] ||| finished shutdown tests (runtime: 8 s)
1982
[2022-03-01T15:27:33.274843Z] [debug] stopping autotest process 14665
1983
[2022-03-01T15:27:33.278860Z] [debug] [autotest] process exited: 0
1984
[2022-03-01T15:27:33.379237Z] [debug] done with autotest process
1985
[2022-03-01T15:27:33.379616Z] [debug] stopping command server 14662 because test execution ended
1986
[2022-03-01T15:27:33.379681Z] [debug] isotovideo: informing websocket clients before stopping command server: http://127.0.0.1:20013/N503ZgOJZf1SW84y/broadcast
1987
[2022-03-01T15:27:33.392235Z] [debug] commands process exited: 0
1988
[2022-03-01T15:27:33.492591Z] [debug] done with command server
1989
[2022-03-01T15:27:33.492662Z] [debug] isotovideo done
1990
[2022-03-01T15:27:33.493477Z] [debug] backend shutdown state: 1
1991
[2022-03-01T15:27:33.494007Z] [info] ::: OpenQA::Qemu::Proc::save_state: Saving QEMU state to qemu_state.json
1992
[2022-03-01T15:27:34.502307Z] [debug] Passing remaining frames to the video encoder
1993
[2022-03-01T15:27:34.525427Z] [debug] Waiting for video encoder to finalize the video
1994
[2022-03-01T15:27:34.525526Z] [debug] The built-in video encoder (pid 14805) terminated
1995
[2022-03-01T15:27:34.526032Z] [debug] QEMU: qemu-system-i386: terminating on signal 15 from pid 14735 (/home/squamata/os-autoinst/isotovideo: backen)
1996
[2022-03-01T15:27:34.526905Z] [debug] sending magic and exit
1997
[2022-03-01T15:27:34.527141Z] [debug] received magic close
1998
[2022-03-01T15:27:34.532401Z] [debug] backend process exited: 0
1999
[2022-03-01T15:27:34.633897Z] [info] ::: backend::qemu::do_extract_assets: Extracting (?^u:^hd0$)
2000
[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`
2001
[2022-03-01T15:27:34.647756Z] [debug] running `qemu-img info --output=json assets_public/core-hdd.qcow2`
2002
[2022-03-01T15:27:34.655708Z] [debug] stopping backend process 14735
2003
[2022-03-01T15:27:34.655778Z] [debug] done with backend process
2004
14656: EXIT 0
2005
[2022-03-01T15:27:34.671886Z] [info] [pid:14649] Isotovideo exit status: 0
2006
[2022-03-01T15:27:34.697495Z] [info] [pid:14649] +++ worker notes +++
2007
[2022-03-01T15:27:34.697700Z] [info] [pid:14649] End time: 2022-03-01 15:27:34
2008
[2022-03-01T15:27:34.697791Z] [info] [pid:14649] Result: done
2009
[2022-03-01T15:27:34.700940Z] [info] [pid:14899] Uploading core-hdd.qcow2
2010
[2022-03-01T15:27:34.757915Z] [info] [pid:14899] Uploading video.ogv
2011
[2022-03-01T15:27:34.787594Z] [info] [pid:14899] Uploading vars.json
2012
[2022-03-01T15:27:34.812971Z] [info] [pid:14899] Uploading autoinst-log.txt
2013
/home/squamata/project/test-results/fullstack/full-stack.d/openqa/testresults/00000/00000001-tinycore-1-flavor-i386-Build1-core@coolone/serial0.txt:
2014
/home/squamata/project/test-results/fullstack/full-stack.d/openqa/testresults/00000/00000001-tinycore-1-flavor-i386-Build1-core@coolone/serial_terminal.txt:
2015
/home/squamata/project/test-results/fullstack/full-stack.d/openqa/testresults/00000/00000001-tinycore-1-flavor-i386-Build1-core@coolone/worker-log.txt:
2016
[2022-03-01T15:27:09.228443Z] [debug] [pid:14649] Preparing Mojo::IOLoop::ReadWriteProcess::Session
2017
[2022-03-01T15:27:09.229844Z] [debug] [pid:14649] Job settings:
2018
[2022-03-01T15:27:09.230062Z] [debug] [pid:14649] 
2019
    ARCH=i386
2020
    BUILD=1
2021
    DISTRI=tinycore
2022
    FLAVOR=flavor
2023
    INTEGRATION_TESTS=1
2024
    ISO=Core-7.2.iso
2025
    JOBTOKEN=N503ZgOJZf1SW84y
2026
    LOG_LEVEL=debug
2027
    MACHINE=coolone
2028
    NAME=00000001-tinycore-1-flavor-i386-Build1-core@coolone
2029
    OPENQA_HOSTNAME=localhost:9526
2030
    OPENQA_URL=http://localhost:9526
2031
    PAUSE_AT=shutdown
2032
    PRJDIR=/home/squamata/project/test-results/fullstack/full-stack.d/openqa/share
2033
    PUBLISH_HDD_1=core-hdd.qcow2
2034
    QEMU=i386
2035
    QEMUPORT=20012
2036
    QEMU_NO_FDC_SET=1
2037
    QEMU_NO_KVM=1
2038
    QEMU_NO_TABLET=1
2039
    RETRY_DELAY=5
2040
    RETRY_DELAY_IF_WEBUI_BUSY=60
2041
    TEST=core
2042
    UEFI_PFLASH_VARS=/usr/share/qemu/ovmf-x86_64.bin
2043
    VERSION=1
2044
    VNC=91
2045
    WORKER_CLASS=qemu_i386,qemu_x86_64
2046
    WORKER_HOSTNAME=127.0.0.1
2047
    WORKER_ID=1
2048
    WORKER_INSTANCE=1
2049
[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"
2050
[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"
2051
[2022-03-01T15:27:09.231790Z] [info] [pid:14649] Preparing cgroup to start isotovideo
2052
[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.
2053
[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.
2054
[2022-03-01T15:27:09.233802Z] [info] [pid:14649] Starting isotovideo container
2055
[2022-03-01T15:27:09.236693Z] [debug] [pid:14649] Registered process:14656
2056
[2022-03-01T15:27:09.236894Z] [info] [pid:14656] 14656: WORKING 1
2057
[2022-03-01T15:27:09.237269Z] [info] [pid:14649] isotovideo has been started (PID: 14656)
2058
[2022-03-01T15:27:09.237996Z] [debug] [pid:14649] Running job 1 from http://localhost:9526: 00000001-tinycore-1-flavor-i386-Build1-core@coolone.
2059
[2022-03-01T15:27:09.240212Z] [debug] [pid:14649] REST-API call: POST http://localhost:9526/api/v1/jobs/1/status
2060
[2022-03-01T15:27:09.295110Z] [debug] [pid:14649] Upload concluded (no current module)
2061
[2022-03-01T15:27:11.973563Z] [debug] [pid:14649] Starting livelog
2062
[2022-03-01T15:27:11.974910Z] [debug] [pid:14649] REST-API call: POST http://localhost:9526/api/v1/jobs/1/status
2063
[2022-03-01T15:27:12.020603Z] [debug] [pid:14649] Upload concluded (no current module)
2064
[2022-03-01T15:27:12.436468Z] [debug] [pid:14649] Stopping livelog
2065
[2022-03-01T15:27:13.022362Z] [debug] [pid:14649] REST-API call: POST http://localhost:9526/api/v1/jobs/1/status
2066
[2022-03-01T15:27:13.063471Z] [debug] [pid:14649] Upload concluded (no current module)
2067
[2022-03-01T15:27:23.071523Z] [debug] [pid:14649] REST-API call: POST http://localhost:9526/api/v1/jobs/1/status
2068
[2022-03-01T15:27:23.142145Z] [debug] [pid:14649] Upload concluded (at boot)
2069
[2022-03-01T15:27:28.006665Z] [debug] [pid:14649] Starting livelog
2070
[2022-03-01T15:27:28.008261Z] [debug] [pid:14649] REST-API call: POST http://localhost:9526/api/v1/jobs/1/status
2071
[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
2072
[2022-03-01T15:27:28.233452Z] [debug] [pid:14880] Uploading artefact boot-2.png as 68d7ac83452b72555f8a6b386629f91f
2073
[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
2074
[2022-03-01T15:27:28.282803Z] [debug] [pid:14880] Uploading artefact boot-2.png as 68d7ac83452b72555f8a6b386629f91f
2075
[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
2076
[2022-03-01T15:27:28.424816Z] [debug] [pid:14880] Uploading artefact boot-1.png as f4184468dbb276a03240907d0e7e500d
2077
[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
2078
[2022-03-01T15:27:28.459452Z] [debug] [pid:14880] Uploading artefact boot-1.png as f4184468dbb276a03240907d0e7e500d
2079
[2022-03-01T15:27:28.495669Z] [debug] [pid:14649] Upload concluded (up to boot)
2080
[2022-03-01T15:27:29.497358Z] [debug] [pid:14649] REST-API call: POST http://localhost:9526/api/v1/jobs/1/status
2081
[2022-03-01T15:27:29.553123Z] [debug] [pid:14649] Upload concluded (at shutdown)
2082
[2022-03-01T15:27:30.555680Z] [debug] [pid:14649] REST-API call: POST http://localhost:9526/api/v1/jobs/1/status
2083
[2022-03-01T15:27:30.620044Z] [debug] [pid:14649] Upload concluded (at shutdown)
2084
[2022-03-01T15:27:31.622858Z] [debug] [pid:14649] REST-API call: POST http://localhost:9526/api/v1/jobs/1/status
2085
[2022-03-01T15:27:31.685025Z] [debug] [pid:14649] Upload concluded (at shutdown)
2086
[2022-03-01T15:27:32.687655Z] [debug] [pid:14649] REST-API call: POST http://localhost:9526/api/v1/jobs/1/status
2087
[2022-03-01T15:27:32.743610Z] [debug] [pid:14649] Upload concluded (at shutdown)
2088
[2022-03-01T15:27:33.746664Z] [debug] [pid:14649] REST-API call: POST http://localhost:9526/api/v1/jobs/1/status
2089
[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
2090
[2022-03-01T15:27:33.971007Z] [debug] [pid:14890] Uploading artefact shutdown-2.png as f1ed19aa4bfd65612d1d5fc58b221bf2
2091
[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
2092
[2022-03-01T15:27:34.007432Z] [debug] [pid:14890] Uploading artefact shutdown-2.png as f1ed19aa4bfd65612d1d5fc58b221bf2
2093
[2022-03-01T15:27:34.039275Z] [debug] [pid:14649] Upload concluded (up to shutdown)
2094
[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
2095
[2022-03-01T15:27:34.672889Z] [debug] [pid:14649] REST-API call: POST http://localhost:9526/api/v1/jobs/1/status
2096
[2022-03-01T15:27:34.700743Z] [info] [pid:14899] Uploading core-hdd.qcow2
2097
[2022-03-01T15:27:34.701265Z] [info] [pid:14899] Uploading core-hdd.qcow2 using multiple chunks
2098
[2022-03-01T15:27:34.702306Z] [info] [pid:14899] core-hdd.qcow2: local upload (no chunks needed)
2099
[2022-03-01T15:27:34.757826Z] [info] [pid:14899] Uploading video.ogv
2100
[2022-03-01T15:27:34.758251Z] [debug] [pid:14899] Uploading artefact video.ogv
2101
[2022-03-01T15:27:34.787504Z] [info] [pid:14899] Uploading vars.json
2102
[2022-03-01T15:27:34.787754Z] [debug] [pid:14899] Uploading artefact vars.json
2103
[2022-03-01T15:27:34.812875Z] [info] [pid:14899] Uploading autoinst-log.txt
2104
[2022-03-01T15:27:34.813132Z] [debug] [pid:14899] Uploading artefact autoinst-log.txt
2105
[2022-03-01T15:27:34.838335Z] [info] [pid:14899] Uploading worker-log.txt
2106
[2022-03-01T15:27:34.838595Z] [debug] [pid:14899] Uploading artefact worker-log.txt
2107
/home/squamata/project/test-results/fullstack/full-stack.d/openqa/testresults/00000/00000004-tinycore-1-flavor-i386-Build1-core@noassets/autoinst-log.txt:
2108
[2022-03-01T15:27:59.078967Z] [info] [pid:15121] +++ setup notes +++
2109
[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)
2110
[2022-03-01T15:27:59.079944Z] [error] [pid:15121] HDD_1 handling Cannot find HDD_1 asset hdd/nihilist_disk.hda!
2111
[2022-03-01T15:27:59.104173Z] [info] [pid:15121] +++ worker notes +++
2112
[2022-03-01T15:27:59.104368Z] [info] [pid:15121] End time: 2022-03-01 15:27:59
2113
[2022-03-01T15:27:59.104457Z] [info] [pid:15121] Result: setup failure
2114
[2022-03-01T15:27:59.108536Z] [info] [pid:15127] Uploading autoinst-log.txt
2115
/home/squamata/project/test-results/fullstack/full-stack.d/openqa/testresults/00000/00000004-tinycore-1-flavor-i386-Build1-core@noassets/worker-log.txt:
2116
[2022-03-01T15:27:59.078551Z] [debug] [pid:15121] Preparing Mojo::IOLoop::ReadWriteProcess::Session
2117
[2022-03-01T15:27:59.079430Z] [debug] [pid:15121] Job settings:
2118
[2022-03-01T15:27:59.079566Z] [debug] [pid:15121] 
2119
    ARCH=i386
2120
    BUILD=1
2121
    DISTRI=tinycore
2122
    FLAVOR=flavor
2123
    HDD_1=nihilist_disk.hda
2124
    INTEGRATION_TESTS=1
2125
    ISO=Core-7.2.iso
2126
    JOBTOKEN=Hi1Jbzdefw7ROxDn
2127
    LOG_LEVEL=debug
2128
    MACHINE=noassets
2129
    NAME=00000004-tinycore-1-flavor-i386-Build1-core@noassets
2130
    OPENQA_HOSTNAME=localhost:9526
2131
    OPENQA_URL=http://localhost:9526
2132
    PRJDIR=/home/squamata/project/test-results/fullstack/full-stack.d/openqa/share
2133
    PUBLISH_HDD_1=core-hdd.qcow2
2134
    QEMU=i386
2135
    QEMUPORT=20012
2136
    QEMU_NO_FDC_SET=1
2137
    QEMU_NO_KVM=1
2138
    QEMU_NO_TABLET=1
2139
    RETRY_DELAY=5
2140
    RETRY_DELAY_IF_WEBUI_BUSY=60
2141
    TEST=core
2142
    UEFI_PFLASH_VARS=/usr/share/qemu/ovmf-x86_64.bin
2143
    VERSION=1
2144
    VNC=91
2145
    WORKER_CLASS=qemu_i386,qemu_x86_64
2146
    WORKER_HOSTNAME=127.0.0.1
2147
    WORKER_ID=1
2148
    WORKER_INSTANCE=1
2149
[2022-03-01T15:27:59.080074Z] [error] [pid:15121] Unable to setup job 4: Cannot find HDD_1 asset hdd/nihilist_disk.hda!
2150
[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
2151
[2022-03-01T15:27:59.080718Z] [debug] [pid:15121] REST-API call: POST http://localhost:9526/api/v1/jobs/4/status
2152
[2022-03-01T15:27:59.108364Z] [info] [pid:15127] Uploading autoinst-log.txt
2153
[2022-03-01T15:27:59.108827Z] [debug] [pid:15127] Uploading artefact autoinst-log.txt
2154
[2022-03-01T15:27:59.140294Z] [info] [pid:15127] Uploading worker-log.txt
2155
[2022-03-01T15:27:59.140542Z] [debug] [pid:15127] Uploading artefact worker-log.txt
2156
/home/squamata/project/test-results/fullstack/full-stack.d/openqa/testresults/00000/00000005-tinycore-1-flavor-i386-Build1-core@coolone/autoinst-log.txt:
2157
[2022-03-01T15:28:14.541361Z] [info] [pid:15136] +++ setup notes +++
2158
[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)
2159
[2022-03-01T15:28:14.547990Z] [debug] [pid:15136] Found ISO, caching Core-7.2.iso
2160
[2022-03-01T15:28:14.554353Z] [info] [pid:15136] Downloading Core-7.2.iso, request #1 sent to Cache Service
2161
[2022-03-01T15:28:19.650276Z] [info] [pid:15136] Download of Core-7.2.iso processed
2162
[2022-03-01T15:28:19.657805Z] [debug] [pid:15143] +++ worker notes +++
2163
[2022-03-01T15:28:21.433498Z] [debug] Current version is d410cc0dd1aa541233ea295ddfbe1d94a78c33ad [interface v25]
2164
[2022-03-01T15:28:21.442068Z] [debug] git hash in tinycore: d410cc0dd1aa541233ea295ddfbe1d94a78c33ad
2165
[2022-03-01T15:28:21.526219Z] [debug] scheduling boot tests/boot.pm
2166
[2022-03-01T15:28:21.526849Z] [debug] scheduling assert_screen tests/assert_screen.pm
2167
[2022-03-01T15:28:21.527407Z] [debug] scheduling shutdown tests/shutdown.pm
2168
[2022-03-01T15:28:21.533158Z] [info] cmdsrv: daemon reachable under http://*:20013/xBOCRMEQoRw0iLse/
2169
[2022-03-01T15:28:21.535100Z] [info] Listening at "http://0.0.0.0:20013"
2170
Web application available at http://0.0.0.0:20013
2171
[2022-03-01T15:28:21.536252Z] [debug] git hash in tinycore/needles: d410cc0dd1aa541233ea295ddfbe1d94a78c33ad
2172
[2022-03-01T15:28:21.536359Z] [debug] init needles from tinycore/needles
2173
[2022-03-01T15:28:21.537644Z] [debug] loaded 4 needles
2174
[2022-03-01T15:28:21.540046Z] [debug] Blocking SIGCHLD and SIGTERM
2175
[2022-03-01T15:28:21.666316Z] [debug] Unblocking SIGCHLD and SIGTERM
2176
[2022-03-01T15:28:21.736077Z] [debug] Blocking SIGCHLD and SIGTERM
2177
[2022-03-01T15:28:21.736133Z] [debug] 15143: channel_out 15, channel_in 14
2178
[2022-03-01T15:28:21.866438Z] [debug] Unblocking SIGCHLD and SIGTERM
2179
[2022-03-01T15:28:21.867795Z] [debug] 15222: cmdpipe 13, rsppipe 16
2180
[2022-03-01T15:28:21.867874Z] [debug] started mgmt loop with pid 15222
2181
[2022-03-01T15:28:22.068146Z] [debug] qemu version detected: 5.2.0
2182
[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`
2183
[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.
2184
  
2185
[2022-03-01T15:28:22.076249Z] [debug] Configuring storage controllers and block devices
2186
[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`
2187
[2022-03-01T15:28:22.085881Z] [debug] Initializing block device images
2188
[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`
2189
[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
2190
[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`
2191
[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
2192
[2022-03-01T15:28:22.108462Z] [debug] init_blockdev_images: Finished creating block devices
2193
[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
2194
[2022-03-01T15:28:22.113085Z] [debug] Waiting for 0 attempts
2195
[2022-03-01T15:28:23.113726Z] [debug] Waiting for 1 attempts
2196
[2022-03-01T15:28:24.114158Z] [debug] Finished after 2 attempts
2197
[2022-03-01T15:28:24.116020Z] [debug] Establishing VNC connection to localhost:5991
2198
[2022-03-01T15:28:24.118649Z] [debug] pointer type 0 0 640 480 -257
2199
[2022-03-01T15:28:24.118739Z] [debug] led state 0 1 1 -261
2200
[2022-03-01T15:28:24.178150Z] [debug] Start CPU
2201
[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}}
2202
[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}}
2203
[2022-03-01T15:28:24.178619Z] [debug] EVENT {"event":"RESUME","timestamp":{"microseconds":178548,"seconds":1646148504}}
2204
GOT GO
2205

    
2206
[2022-03-01T15:28:24.188394Z] [debug] QEMU: QEMU emulator version 5.2.0 (SUSE Linux Enterprise 15)
2207
[2022-03-01T15:28:24.188477Z] [debug] QEMU: Copyright (c) 2003-2020 Fabrice Bellard and the QEMU Project developers
2208
[2022-03-01T15:28:24.192206Z] [debug] Snapshots are supported
2209
[2022-03-01T15:28:24.193350Z] [debug] ||| starting boot tests/boot.pm
2210
[2022-03-01T15:28:24.195311Z] [debug] tests/boot.pm:9 called testapi::assert_screen
2211
[2022-03-01T15:28:24.195690Z] [debug] <<< testapi::assert_screen(mustmatch="core", no_wait=1, timeout=15)
2212
[2022-03-01T15:28:24.209648Z] [debug] no match: 14.9s, best candidate: boot-core (0.00)
2213
[2022-03-01T15:28:24.310484Z] [debug] no change: 14.8s
2214
[2022-03-01T15:28:24.317100Z] [debug] no match: 14.8s, best candidate: boot-core (0.00)
2215
[2022-03-01T15:28:24.417775Z] [debug] no change: 14.7s
2216
[2022-03-01T15:28:24.425345Z] [debug] no match: 14.7s, best candidate: boot-core (0.00)
2217
[2022-03-01T15:28:24.526186Z] [debug] no change: 14.6s
2218
[2022-03-01T15:28:24.533631Z] [debug] no match: 14.6s, best candidate: boot-core (0.00)
2219
[2022-03-01T15:28:24.634513Z] [debug] no change: 14.5s
2220
[2022-03-01T15:28:24.643244Z] [debug] no match: 14.5s, best candidate: boot-core (0.00)
2221
[2022-03-01T15:28:24.835218Z] [debug] >>> testapi::_handle_found_needle: found boot-core, similarity 0.97 @ 1/74
2222
[2022-03-01T15:28:24.835839Z] [debug] tests/boot.pm:10 called testapi::send_key
2223
[2022-03-01T15:28:24.835965Z] [debug] <<< testapi::send_key(key="ret", do_wait=0, wait_screen_change=0)
2224
[2022-03-01T15:28:25.105712Z] [debug] tests/boot.pm:14 called testapi::assert_screen
2225
[2022-03-01T15:28:25.105931Z] [debug] <<< testapi::assert_screen(mustmatch="on_prompt", timeout=90)
2226
[2022-03-01T15:28:25.749547Z] [debug] no match: 89.3s, best candidate: boot-on_prompt (0.00)
2227
[2022-03-01T15:28:26.746295Z] [debug] no match: 88.3s, best candidate: boot-on_prompt (0.00)
2228
[2022-03-01T15:28:27.747325Z] [debug] no match: 87.3s, best candidate: boot-on_prompt (0.00)
2229
[2022-03-01T15:28:28.747863Z] [debug] no match: 86.3s, best candidate: boot-on_prompt (0.00)
2230
[2022-03-01T15:28:29.795464Z] [debug] no match: 85.3s, best candidate: boot-on_prompt (0.00)
2231
[2022-03-01T15:28:30.750221Z] [debug] no match: 84.3s, best candidate: boot-on_prompt (0.00)
2232
[2022-03-01T15:28:31.751191Z] [debug] no match: 83.3s, best candidate: boot-on_prompt (0.00)
2233
[2022-03-01T15:28:32.751775Z] [debug] no match: 82.3s, best candidate: boot-on_prompt (0.00)
2234
[2022-03-01T15:28:33.752762Z] [debug] no match: 81.3s, best candidate: boot-on_prompt (0.00)
2235
[2022-03-01T15:28:34.855811Z] [debug] >>> testapi::_handle_found_needle: found boot-on_prompt, similarity 1.00 @ 2/64
2236
[2022-03-01T15:28:34.858212Z] [debug] ||| finished boot tests (runtime: 10 s)
2237
[2022-03-01T15:28:34.859262Z] [debug] ||| starting assert_screen tests/assert_screen.pm
2238
[2022-03-01T15:28:34.859938Z] [debug] tests/assert_screen.pm:9 called testapi::assert_screen
2239
[2022-03-01T15:28:34.860052Z] [debug] <<< testapi::assert_screen(mustmatch="on_prompt", timeout=60)
2240
[2022-03-01T15:28:35.817101Z] [debug] >>> testapi::_handle_found_needle: found boot-on_prompt, similarity 1.00 @ 2/64
2241
[2022-03-01T15:28:35.817262Z] [debug] tests/assert_screen.pm:10 called testapi::assert_screen
2242
[2022-03-01T15:28:35.817412Z] [debug] <<< testapi::assert_screen(mustmatch="on_prompt", no_wait=1, timeout=30)
2243
[2022-03-01T15:28:35.890203Z] [debug] >>> testapi::_handle_found_needle: found boot-on_prompt, similarity 1.00 @ 2/64
2244
[2022-03-01T15:28:35.891158Z] [debug] ||| finished assert_screen tests (runtime: 1 s)
2245
[2022-03-01T15:28:35.892732Z] [debug] ||| starting shutdown tests/shutdown.pm
2246
[2022-03-01T15:28:35.893420Z] [debug] tests/shutdown.pm:8 called testapi::enter_cmd
2247
[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)
2248
[2022-03-01T15:28:36.376751Z] [debug] tests/shutdown.pm:9 called testapi::assert_shutdown
2249
[2022-03-01T15:28:36.376905Z] [debug] <<< testapi::check_shutdown(timeout=90)
2250
[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}}
2251
[2022-03-01T15:28:36.377715Z] [debug] QEMU status is not 'shutdown', it is 'running'
2252
[2022-03-01T15:28:37.379157Z] [debug] QEMU status is not 'shutdown', it is 'running'
2253
[2022-03-01T15:28:38.380504Z] [debug] QEMU status is not 'shutdown', it is 'running'
2254
[2022-03-01T15:28:39.381832Z] [debug] QEMU status is not 'shutdown', it is 'running'
2255
[2022-03-01T15:28:40.383187Z] [debug] QEMU status is not 'shutdown', it is 'running'
2256
[2022-03-01T15:28:41.384245Z] [debug] EVENT {"data":{"guest":true,"reason":"guest-shutdown"},"event":"SHUTDOWN","timestamp":{"microseconds":941742,"seconds":1646148520}}
2257
[2022-03-01T15:28:41.384350Z] [debug] EVENT {"event":"STOP","timestamp":{"microseconds":942259,"seconds":1646148520}}
2258
[2022-03-01T15:28:41.445396Z] [debug] ||| finished shutdown tests (runtime: 6 s)
2259
[2022-03-01T15:28:41.447757Z] [debug] stopping autotest process 15152
2260
[2022-03-01T15:28:41.451693Z] [debug] [autotest] process exited: 0
2261
[2022-03-01T15:28:41.552082Z] [debug] done with autotest process
2262
[2022-03-01T15:28:41.552476Z] [debug] stopping command server 15149 because test execution ended
2263
[2022-03-01T15:28:41.552556Z] [debug] isotovideo: informing websocket clients before stopping command server: http://127.0.0.1:20013/xBOCRMEQoRw0iLse/broadcast
2264
[2022-03-01T15:28:41.564725Z] [debug] commands process exited: 0
2265
[2022-03-01T15:28:41.665135Z] [debug] done with command server
2266
[2022-03-01T15:28:41.665206Z] [debug] isotovideo done
2267
[2022-03-01T15:28:41.665856Z] [debug] backend shutdown state: 1
2268
[2022-03-01T15:28:41.666273Z] [info] ::: OpenQA::Qemu::Proc::save_state: Saving QEMU state to qemu_state.json
2269
[2022-03-01T15:28:42.677199Z] [debug] Passing remaining frames to the video encoder
2270
[2022-03-01T15:28:42.700950Z] [debug] Waiting for video encoder to finalize the video
2271
[2022-03-01T15:28:42.701026Z] [debug] The built-in video encoder (pid 15292) terminated
2272
[2022-03-01T15:28:42.701511Z] [debug] QEMU: qemu-system-i386: terminating on signal 15 from pid 15222 (/home/squamata/os-autoinst/isotovideo: backen)
2273
[2022-03-01T15:28:42.702392Z] [debug] sending magic and exit
2274
[2022-03-01T15:28:42.702617Z] [debug] received magic close
2275
[2022-03-01T15:28:42.707832Z] [debug] backend process exited: 0
2276
[2022-03-01T15:28:42.808798Z] [debug] stopping backend process 15222
2277
[2022-03-01T15:28:42.808871Z] [debug] done with backend process
2278
15143: EXIT 0
2279
[2022-03-01T15:28:42.823769Z] [info] [pid:15136] Isotovideo exit status: 0
2280
[2022-03-01T15:28:42.852118Z] [info] [pid:15136] +++ worker notes +++
2281
[2022-03-01T15:28:42.852329Z] [info] [pid:15136] End time: 2022-03-01 15:28:42
2282
[2022-03-01T15:28:42.852419Z] [info] [pid:15136] Result: done
2283
[2022-03-01T15:28:42.857221Z] [info] [pid:15352] Uploading video.ogv
2284
[2022-03-01T15:28:42.895433Z] [info] [pid:15352] Uploading vars.json
2285
[2022-03-01T15:28:42.923Z] [info] [pid:15352] Uploading autoinst-log.txt
2286
/home/squamata/project/test-results/fullstack/full-stack.d/openqa/testresults/00000/00000005-tinycore-1-flavor-i386-Build1-core@coolone/serial0.txt:
2287
/home/squamata/project/test-results/fullstack/full-stack.d/openqa/testresults/00000/00000005-tinycore-1-flavor-i386-Build1-core@coolone/serial_terminal.txt:
2288
/home/squamata/project/test-results/fullstack/full-stack.d/openqa/testresults/00000/00000005-tinycore-1-flavor-i386-Build1-core@coolone/worker-log.txt:
2289
[2022-03-01T15:28:14.540950Z] [debug] [pid:15136] Preparing Mojo::IOLoop::ReadWriteProcess::Session
2290
[2022-03-01T15:28:14.541825Z] [debug] [pid:15136] Job settings:
2291
[2022-03-01T15:28:14.541963Z] [debug] [pid:15136] 
2292
    ARCH=i386
2293
    BUILD=1
2294
    CACHEDIRECTORY=/home/squamata/project/test-results/fullstack/full-stack.d/cache
2295
    CACHELIMIT=50
2296
    DISTRI=tinycore
2297
    FLAVOR=flavor
2298
    INTEGRATION_TESTS=1
2299
    ISO=Core-7.2.iso
2300
    JOBTOKEN=xBOCRMEQoRw0iLse
2301
    LOCAL_UPLOAD=0
2302
    LOG_LEVEL=debug
2303
    MACHINE=coolone
2304
    NAME=00000005-tinycore-1-flavor-i386-Build1-core@coolone
2305
    OPENQA_HOSTNAME=localhost:9526
2306
    OPENQA_URL=http://localhost:9526
2307
    PRJDIR=/home/squamata/project/test-results/fullstack/full-stack.d/openqa/share
2308
    PUBLISH_HDD_1=
2309
    QEMU=i386
2310
    QEMUPORT=20012
2311
    QEMU_NO_FDC_SET=1
2312
    QEMU_NO_KVM=1
2313
    QEMU_NO_TABLET=1
2314
    RETRY_DELAY=5
2315
    RETRY_DELAY_IF_WEBUI_BUSY=60
2316
    TEST=core
2317
    UEFI_PFLASH_VARS=/usr/share/qemu/ovmf-x86_64.bin
2318
    VERSION=1
2319
    VNC=91
2320
    WORKER_CLASS=qemu_i386,qemu_x86_64
2321
    WORKER_ID=1
2322
    WORKER_INSTANCE=1
2323
[2022-03-01T15:28:14.554583Z] [debug] [pid:15136] Updating status so job 5 is not considered dead.
2324
[2022-03-01T15:28:14.555027Z] [debug] [pid:15136] REST-API call: POST http://localhost:9526/api/v1/jobs/5/status
2325
[2022-03-01T15:28:19.606335Z] [debug] [pid:15136] Updating status so job 5 is not considered dead.
2326
[2022-03-01T15:28:19.606931Z] [debug] [pid:15136] REST-API call: POST http://localhost:9526/api/v1/jobs/5/status
2327
[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"
2328
[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"
2329
[2022-03-01T15:28:19.653291Z] [info] [pid:15136] Preparing cgroup to start isotovideo
2330
[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.
2331
[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.
2332
[2022-03-01T15:28:19.654850Z] [info] [pid:15136] Starting isotovideo container
2333
[2022-03-01T15:28:19.657251Z] [debug] [pid:15136] Registered process:15143
2334
[2022-03-01T15:28:19.657572Z] [info] [pid:15143] 15143: WORKING 5
2335
[2022-03-01T15:28:19.657700Z] [info] [pid:15136] isotovideo has been started (PID: 15143)
2336
[2022-03-01T15:28:19.658332Z] [debug] [pid:15136] Running job 5 from http://localhost:9526: 00000005-tinycore-1-flavor-i386-Build1-core@coolone.
2337
[2022-03-01T15:28:19.661006Z] [debug] [pid:15136] REST-API call: POST http://localhost:9526/api/v1/jobs/5/status
2338
[2022-03-01T15:28:19.703636Z] [debug] [pid:15136] Upload concluded (no current module)
2339
[2022-03-01T15:28:29.711523Z] [debug] [pid:15136] REST-API call: POST http://localhost:9526/api/v1/jobs/5/status
2340
[2022-03-01T15:28:29.782955Z] [debug] [pid:15136] Upload concluded (at boot)
2341
[2022-03-01T15:28:39.785165Z] [debug] [pid:15136] REST-API call: POST http://localhost:9526/api/v1/jobs/5/status
2342
[2022-03-01T15:28:39.879622Z] [debug] [pid:15136] Upload concluded (up to boot)
2343
[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
2344
[2022-03-01T15:28:42.824818Z] [debug] [pid:15136] REST-API call: POST http://localhost:9526/api/v1/jobs/5/status
2345
[2022-03-01T15:28:42.857049Z] [info] [pid:15352] Uploading video.ogv
2346
[2022-03-01T15:28:42.857524Z] [debug] [pid:15352] Uploading artefact video.ogv
2347
[2022-03-01T15:28:42.895340Z] [info] [pid:15352] Uploading vars.json
2348
[2022-03-01T15:28:42.895607Z] [debug] [pid:15352] Uploading artefact vars.json
2349
[2022-03-01T15:28:42.922890Z] [info] [pid:15352] Uploading autoinst-log.txt
2350
[2022-03-01T15:28:42.923161Z] [debug] [pid:15352] Uploading artefact autoinst-log.txt
2351
[2022-03-01T15:28:42.949229Z] [info] [pid:15352] Uploading worker-log.txt
2352
[2022-03-01T15:28:42.949481Z] [debug] [pid:15352] Uploading artefact worker-log.txt
2353
/home/squamata/project/test-results/fullstack/full-stack.d/openqa/testresults/00000/00000006-tinycore-1-flavor-i386-Build1-core@coolone/autoinst-log.txt:
2354
[2022-03-01T15:28:52.774469Z] [info] [pid:15361] +++ setup notes +++
2355
[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)
2356
[2022-03-01T15:28:52.780628Z] [debug] [pid:15361] Found ISO, caching Core-7.2.iso
2357
[2022-03-01T15:28:52.785263Z] [info] [pid:15361] Downloading Core-7.2.iso, request #2 sent to Cache Service
2358
[2022-03-01T15:28:57.873152Z] [info] [pid:15361] Download of Core-7.2.iso processed
2359
[2022-03-01T15:28:57.880425Z] [debug] [pid:15368] +++ worker notes +++
2360
[2022-03-01T15:28:59.599032Z] [debug] Current version is d410cc0dd1aa541233ea295ddfbe1d94a78c33ad [interface v25]
2361
[2022-03-01T15:28:59.607329Z] [debug] git hash in tinycore: d410cc0dd1aa541233ea295ddfbe1d94a78c33ad
2362
[2022-03-01T15:28:59.694256Z] [debug] scheduling boot tests/boot.pm
2363
[2022-03-01T15:28:59.694985Z] [debug] scheduling assert_screen tests/assert_screen.pm
2364
[2022-03-01T15:28:59.695560Z] [debug] scheduling shutdown tests/shutdown.pm
2365
[2022-03-01T15:28:59.701416Z] [info] cmdsrv: daemon reachable under http://*:20013/LSwqvyqaj4Ub2NPr/
2366
[2022-03-01T15:28:59.703474Z] [info] Listening at "http://0.0.0.0:20013"
2367
Web application available at http://0.0.0.0:20013
2368
[2022-03-01T15:28:59.704838Z] [debug] git hash in tinycore/needles: d410cc0dd1aa541233ea295ddfbe1d94a78c33ad
2369
[2022-03-01T15:28:59.704959Z] [debug] init needles from tinycore/needles
2370
[2022-03-01T15:28:59.706350Z] [debug] loaded 4 needles
2371
[2022-03-01T15:28:59.709085Z] [debug] Blocking SIGCHLD and SIGTERM
2372
[2022-03-01T15:28:59.866684Z] [debug] Unblocking SIGCHLD and SIGTERM
2373
[2022-03-01T15:28:59.970030Z] [debug] Blocking SIGCHLD and SIGTERM
2374
[2022-03-01T15:28:59.970327Z] [debug] 15368: channel_out 15, channel_in 14
2375
[2022-03-01T15:29:00.165912Z] [debug] Unblocking SIGCHLD and SIGTERM
2376
[2022-03-01T15:29:00.167288Z] [debug] 15464: cmdpipe 13, rsppipe 16
2377
[2022-03-01T15:29:00.167372Z] [debug] started mgmt loop with pid 15464
2378
[2022-03-01T15:29:00.365410Z] [debug] qemu version detected: 5.2.0
2379
[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`
2380
[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.
2381
  
2382
[2022-03-01T15:29:00.373163Z] [debug] Configuring storage controllers and block devices
2383
[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`
2384
[2022-03-01T15:29:00.381734Z] [debug] Initializing block device images
2385
[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`
2386
[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
2387
[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`
2388
[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
2389
[2022-03-01T15:29:00.401220Z] [debug] init_blockdev_images: Finished creating block devices
2390
[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
2391
[2022-03-01T15:29:00.405583Z] [debug] Waiting for 0 attempts
2392
[2022-03-01T15:29:01.406221Z] [debug] Waiting for 1 attempts
2393
[2022-03-01T15:29:02.406683Z] [debug] Finished after 2 attempts
2394
[2022-03-01T15:29:02.408636Z] [debug] Establishing VNC connection to localhost:5991
2395
[2022-03-01T15:29:02.411263Z] [debug] pointer type 0 0 640 480 -257
2396
[2022-03-01T15:29:02.411344Z] [debug] led state 0 1 1 -261
2397
[2022-03-01T15:29:02.470334Z] [debug] Start CPU
2398
[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}}
2399
[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}}
2400
[2022-03-01T15:29:02.470800Z] [debug] EVENT {"event":"RESUME","timestamp":{"microseconds":470729,"seconds":1646148542}}
2401
GOT GO
2402

    
2403
[2022-03-01T15:29:02.478563Z] [debug] QEMU: QEMU emulator version 5.2.0 (SUSE Linux Enterprise 15)
2404
[2022-03-01T15:29:02.478619Z] [debug] QEMU: Copyright (c) 2003-2020 Fabrice Bellard and the QEMU Project developers
2405
[2022-03-01T15:29:02.481695Z] [debug] Snapshots are supported
2406
[2022-03-01T15:29:02.482545Z] [debug] ||| starting boot tests/boot.pm
2407
[2022-03-01T15:29:02.484051Z] [debug] tests/boot.pm:9 called testapi::assert_screen
2408
[2022-03-01T15:29:02.484320Z] [debug] <<< testapi::assert_screen(mustmatch="core", no_wait=1, timeout=15)
2409
[2022-03-01T15:29:02.498140Z] [debug] no match: 14.9s, best candidate: boot-core (0.00)
2410
[2022-03-01T15:29:02.598832Z] [debug] no change: 14.8s
2411
[2022-03-01T15:29:02.605435Z] [debug] no match: 14.8s, best candidate: boot-core (0.00)
2412
[2022-03-01T15:29:02.706253Z] [debug] no change: 14.7s
2413
[2022-03-01T15:29:02.712875Z] [debug] no match: 14.7s, best candidate: boot-core (0.00)
2414
[2022-03-01T15:29:02.813722Z] [debug] no change: 14.6s
2415
[2022-03-01T15:29:02.820322Z] [debug] no match: 14.6s, best candidate: boot-core (0.00)
2416
[2022-03-01T15:29:02.921125Z] [debug] no change: 14.5s
2417
[2022-03-01T15:29:02.927738Z] [debug] no match: 14.5s, best candidate: boot-core (0.00)
2418
[2022-03-01T15:29:03.103892Z] [debug] >>> testapi::_handle_found_needle: found boot-core, similarity 0.97 @ 1/74
2419
[2022-03-01T15:29:03.104449Z] [debug] tests/boot.pm:10 called testapi::send_key
2420
[2022-03-01T15:29:03.104574Z] [debug] <<< testapi::send_key(key="ret", do_wait=0, wait_screen_change=0)
2421
[2022-03-01T15:29:03.374065Z] [debug] tests/boot.pm:14 called testapi::assert_screen
2422
[2022-03-01T15:29:03.374262Z] [debug] <<< testapi::assert_screen(mustmatch="on_prompt", timeout=90)
2423
[2022-03-01T15:29:04.034027Z] [debug] no match: 89.3s, best candidate: boot-on_prompt (0.00)
2424
[2022-03-01T15:29:05.032285Z] [debug] no match: 88.3s, best candidate: boot-on_prompt (0.00)
2425
[2022-03-01T15:29:06.032704Z] [debug] no match: 87.3s, best candidate: boot-on_prompt (0.00)
2426
[2022-03-01T15:29:07.033867Z] [debug] no match: 86.3s, best candidate: boot-on_prompt (0.00)
2427
[2022-03-01T15:29:08.080548Z] [debug] no match: 85.3s, best candidate: boot-on_prompt (0.00)
2428
[2022-03-01T15:29:09.035698Z] [debug] no match: 84.3s, best candidate: boot-on_prompt (0.00)
2429
[2022-03-01T15:29:10.036939Z] [debug] no match: 83.3s, best candidate: boot-on_prompt (0.00)
2430
[2022-03-01T15:29:11.038223Z] [debug] no match: 82.3s, best candidate: boot-on_prompt (0.00)
2431
[2022-03-01T15:29:12.038472Z] [debug] no match: 81.3s, best candidate: boot-on_prompt (0.00)
2432
[2022-03-01T15:29:13.168239Z] [debug] >>> testapi::_handle_found_needle: found boot-on_prompt, similarity 1.00 @ 2/64
2433
[2022-03-01T15:29:13.171374Z] [debug] ||| finished boot tests (runtime: 11 s)
2434
[2022-03-01T15:29:13.172403Z] [debug] ||| starting assert_screen tests/assert_screen.pm
2435
[2022-03-01T15:29:13.173012Z] [debug] tests/assert_screen.pm:9 called testapi::assert_screen
2436
[2022-03-01T15:29:13.173116Z] [debug] <<< testapi::assert_screen(mustmatch="on_prompt", timeout=60)
2437
[2022-03-01T15:29:14.108212Z] [debug] >>> testapi::_handle_found_needle: found boot-on_prompt, similarity 1.00 @ 2/64
2438
[2022-03-01T15:29:14.108359Z] [debug] tests/assert_screen.pm:10 called testapi::assert_screen
2439
[2022-03-01T15:29:14.108466Z] [debug] <<< testapi::assert_screen(mustmatch="on_prompt", no_wait=1, timeout=30)
2440
[2022-03-01T15:29:14.180362Z] [debug] >>> testapi::_handle_found_needle: found boot-on_prompt, similarity 1.00 @ 2/64
2441
[2022-03-01T15:29:14.181608Z] [debug] ||| finished assert_screen tests (runtime: 1 s)
2442
[2022-03-01T15:29:14.183218Z] [debug] ||| starting shutdown tests/shutdown.pm
2443
[2022-03-01T15:29:14.183945Z] [debug] tests/shutdown.pm:8 called testapi::enter_cmd
2444
[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)
2445
[2022-03-01T15:29:14.665497Z] [debug] tests/shutdown.pm:9 called testapi::assert_shutdown
2446
[2022-03-01T15:29:14.665673Z] [debug] <<< testapi::check_shutdown(timeout=90)
2447
[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}}
2448
[2022-03-01T15:29:14.666595Z] [debug] QEMU status is not 'shutdown', it is 'running'
2449
[2022-03-01T15:29:15.667927Z] [debug] QEMU status is not 'shutdown', it is 'running'
2450
[2022-03-01T15:29:16.669329Z] [debug] QEMU status is not 'shutdown', it is 'running'
2451
[2022-03-01T15:29:17.670747Z] [debug] QEMU status is not 'shutdown', it is 'running'
2452
[2022-03-01T15:29:18.672189Z] [debug] QEMU status is not 'shutdown', it is 'running'
2453
[2022-03-01T15:29:19.673435Z] [debug] QEMU status is not 'shutdown', it is 'running'
2454
[2022-03-01T15:29:20.674812Z] [debug] QEMU status is not 'shutdown', it is 'running'
2455
[2022-03-01T15:29:21.676290Z] [debug] QEMU status is not 'shutdown', it is 'running'
2456
[2022-03-01T15:29:22.677811Z] [debug] QEMU status is not 'shutdown', it is 'running'
2457
[2022-03-01T15:29:23.679354Z] [debug] QEMU status is not 'shutdown', it is 'running'
2458
[2022-03-01T15:29:24.680924Z] [debug] QEMU status is not 'shutdown', it is 'running'
2459
[2022-03-01T15:29:25.682417Z] [debug] QEMU status is not 'shutdown', it is 'running'
2460
[2022-03-01T15:29:26.683758Z] [debug] QEMU status is not 'shutdown', it is 'running'
2461
[2022-03-01T15:29:27.685379Z] [debug] QEMU status is not 'shutdown', it is 'running'
2462
[2022-03-01T15:29:28.686953Z] [debug] QEMU status is not 'shutdown', it is 'running'
2463
[2022-03-01T15:29:29.688394Z] [debug] QEMU status is not 'shutdown', it is 'running'
2464
[2022-03-01T15:29:30.689899Z] [debug] QEMU status is not 'shutdown', it is 'running'
2465
[2022-03-01T15:29:31.691234Z] [debug] QEMU status is not 'shutdown', it is 'running'
2466
[2022-03-01T15:29:32.692505Z] [debug] QEMU status is not 'shutdown', it is 'running'
2467
[2022-03-01T15:29:33.693922Z] [debug] QEMU status is not 'shutdown', it is 'running'
2468
[2022-03-01T15:29:34.695268Z] [debug] QEMU status is not 'shutdown', it is 'running'
2469
[2022-03-01T15:29:35.696865Z] [debug] QEMU status is not 'shutdown', it is 'running'
2470
[2022-03-01T15:29:36.698406Z] [debug] QEMU status is not 'shutdown', it is 'running'
2471
[2022-03-01T15:29:37.699802Z] [debug] QEMU status is not 'shutdown', it is 'running'
2472
[2022-03-01T15:29:38.701217Z] [debug] QEMU status is not 'shutdown', it is 'running'
2473
[2022-03-01T15:29:39.702570Z] [debug] QEMU status is not 'shutdown', it is 'running'
2474
[2022-03-01T15:29:40.703935Z] [debug] QEMU status is not 'shutdown', it is 'running'
2475
[2022-03-01T15:29:41.705226Z] [debug] QEMU status is not 'shutdown', it is 'running'
2476
[2022-03-01T15:29:42.706634Z] [debug] QEMU status is not 'shutdown', it is 'running'
2477
[2022-03-01T15:29:43.708084Z] [debug] QEMU status is not 'shutdown', it is 'running'
2478
[2022-03-01T15:29:44.709369Z] [debug] QEMU status is not 'shutdown', it is 'running'
2479
[2022-03-01T15:29:45.710840Z] [debug] QEMU status is not 'shutdown', it is 'running'
2480
[2022-03-01T15:29:46.712151Z] [debug] QEMU status is not 'shutdown', it is 'running'
2481
[2022-03-01T15:29:47.713554Z] [debug] QEMU status is not 'shutdown', it is 'running'
2482
[2022-03-01T15:29:48.715018Z] [debug] QEMU status is not 'shutdown', it is 'running'
2483
[2022-03-01T15:29:49.716358Z] [debug] QEMU status is not 'shutdown', it is 'running'
2484
[2022-03-01T15:29:50.717843Z] [debug] QEMU status is not 'shutdown', it is 'running'
2485
[2022-03-01T15:29:51.719185Z] [debug] QEMU status is not 'shutdown', it is 'running'
2486
[2022-03-01T15:29:52.720599Z] [debug] QEMU status is not 'shutdown', it is 'running'
2487
[2022-03-01T15:29:53.721972Z] [debug] QEMU status is not 'shutdown', it is 'running'
2488
[2022-03-01T15:29:54.723283Z] [debug] QEMU status is not 'shutdown', it is 'running'
2489
[2022-03-01T15:29:55.724712Z] [debug] QEMU status is not 'shutdown', it is 'running'
2490
[2022-03-01T15:29:56.726355Z] [debug] QEMU status is not 'shutdown', it is 'running'
2491
[2022-03-01T15:29:57.727703Z] [debug] QEMU status is not 'shutdown', it is 'running'
2492
[2022-03-01T15:29:58.729247Z] [debug] QEMU status is not 'shutdown', it is 'running'
2493
[2022-03-01T15:29:59.730979Z] [debug] QEMU status is not 'shutdown', it is 'running'
2494
[2022-03-01T15:30:00.732312Z] [debug] QEMU status is not 'shutdown', it is 'running'
2495
[2022-03-01T15:30:01.733796Z] [debug] QEMU status is not 'shutdown', it is 'running'
2496
[2022-03-01T15:30:02.735325Z] [debug] QEMU status is not 'shutdown', it is 'running'
2497
[2022-03-01T15:30:03.736778Z] [debug] QEMU status is not 'shutdown', it is 'running'
2498
[2022-03-01T15:30:04.738376Z] [debug] QEMU status is not 'shutdown', it is 'running'
2499
[2022-03-01T15:30:05.739688Z] [debug] QEMU status is not 'shutdown', it is 'running'
2500
[2022-03-01T15:30:06.741215Z] [debug] QEMU status is not 'shutdown', it is 'running'
2501
[2022-03-01T15:30:07.742449Z] [debug] QEMU status is not 'shutdown', it is 'running'
2502
[2022-03-01T15:30:08.743771Z] [debug] QEMU status is not 'shutdown', it is 'running'
2503
[2022-03-01T15:30:09.745249Z] [debug] QEMU status is not 'shutdown', it is 'running'
2504
[2022-03-01T15:30:10.746801Z] [debug] QEMU status is not 'shutdown', it is 'running'
2505
[2022-03-01T15:30:11.748252Z] [debug] QEMU status is not 'shutdown', it is 'running'
2506
[2022-03-01T15:30:12.749655Z] [debug] QEMU status is not 'shutdown', it is 'running'
2507
[2022-03-01T15:30:13.751028Z] [debug] QEMU status is not 'shutdown', it is 'running'
2508
[2022-03-01T15:30:14.752368Z] [debug] QEMU status is not 'shutdown', it is 'running'
2509
[2022-03-01T15:30:15.753802Z] [debug] QEMU status is not 'shutdown', it is 'running'
2510
[2022-03-01T15:30:16.755093Z] [debug] QEMU status is not 'shutdown', it is 'running'
2511
[2022-03-01T15:30:17.756541Z] [debug] QEMU status is not 'shutdown', it is 'running'
2512
[2022-03-01T15:30:18.757861Z] [debug] QEMU status is not 'shutdown', it is 'running'
2513
[2022-03-01T15:30:19.759143Z] [debug] QEMU status is not 'shutdown', it is 'running'
2514
[2022-03-01T15:30:20.760539Z] [debug] QEMU status is not 'shutdown', it is 'running'
2515
[2022-03-01T15:30:21.761841Z] [debug] QEMU status is not 'shutdown', it is 'running'
2516
[2022-03-01T15:30:22.763168Z] [debug] QEMU status is not 'shutdown', it is 'running'
2517
[2022-03-01T15:30:23.764713Z] [debug] QEMU status is not 'shutdown', it is 'running'
2518
[2022-03-01T15:30:24.766030Z] [debug] QEMU status is not 'shutdown', it is 'running'
2519
[2022-03-01T15:30:25.767581Z] [debug] QEMU status is not 'shutdown', it is 'running'
2520
[2022-03-01T15:30:26.769298Z] [debug] QEMU status is not 'shutdown', it is 'running'
2521
[2022-03-01T15:30:27.770957Z] [debug] QEMU status is not 'shutdown', it is 'running'
2522
[2022-03-01T15:30:28.772350Z] [debug] QEMU status is not 'shutdown', it is 'running'
2523
[2022-03-01T15:30:29.774014Z] [debug] QEMU status is not 'shutdown', it is 'running'
2524
[2022-03-01T15:30:30.775643Z] [debug] QEMU status is not 'shutdown', it is 'running'
2525
[2022-03-01T15:30:31.777319Z] [debug] QEMU status is not 'shutdown', it is 'running'
2526
[2022-03-01T15:30:32.778946Z] [debug] QEMU status is not 'shutdown', it is 'running'
2527
[2022-03-01T15:30:33.780501Z] [debug] QEMU status is not 'shutdown', it is 'running'
2528
[2022-03-01T15:30:34.782025Z] [debug] QEMU status is not 'shutdown', it is 'running'
2529
[2022-03-01T15:30:35.783555Z] [debug] QEMU status is not 'shutdown', it is 'running'
2530
[2022-03-01T15:30:36.785207Z] [debug] QEMU status is not 'shutdown', it is 'running'
2531
[2022-03-01T15:30:37.786776Z] [debug] QEMU status is not 'shutdown', it is 'running'
2532
[2022-03-01T15:30:38.788311Z] [debug] QEMU status is not 'shutdown', it is 'running'
2533
[2022-03-01T15:30:39.789892Z] [debug] QEMU status is not 'shutdown', it is 'running'
2534
[2022-03-01T15:30:40.791399Z] [debug] QEMU status is not 'shutdown', it is 'running'
2535
[2022-03-01T15:30:41.792833Z] [debug] QEMU status is not 'shutdown', it is 'running'
2536
[2022-03-01T15:30:42.794338Z] [debug] QEMU status is not 'shutdown', it is 'running'
2537
[2022-03-01T15:30:43.795768Z] [debug] QEMU status is not 'shutdown', it is 'running'
2538
[2022-03-01T15:30:44.797156Z] [debug] QEMU status is not 'shutdown', it is 'running'
2539
[2022-03-01T15:30:45.863300Z] [info] ::: basetest::runtest: # Test died: Machine didn't shut down! at tinycore/tests/shutdown.pm line 9.
2540
  
2541
[2022-03-01T15:30:45.865418Z] [debug] ||| finished shutdown tests (runtime: 91 s)
2542
[2022-03-01T15:30:45.865473Z] [debug] ||| post fail hooks runtime: 0 s
2543
[2022-03-01T15:30:45.865763Z] [debug] stopping overall test execution after a fatal test failure
2544
[2022-03-01T15:30:45.866743Z] [debug] stopping autotest process 15394
2545
[2022-03-01T15:30:45.871122Z] [debug] [autotest] process exited: 0
2546
[2022-03-01T15:30:45.971535Z] [debug] done with autotest process
2547
[2022-03-01T15:30:45.971976Z] [debug] stopping command server 15391 because test execution ended
2548
[2022-03-01T15:30:45.972048Z] [debug] isotovideo: informing websocket clients before stopping command server: http://127.0.0.1:20013/LSwqvyqaj4Ub2NPr/broadcast
2549
[2022-03-01T15:30:45.985687Z] [debug] commands process exited: 0
2550
[2022-03-01T15:30:46.086046Z] [debug] done with command server
2551
[2022-03-01T15:30:46.086145Z] [debug] isotovideo done
2552
[2022-03-01T15:30:46.086886Z] [debug] QEMU status is not 'shutdown', it is 'running'
2553
[2022-03-01T15:30:46.087033Z] [debug] backend shutdown state: 
2554
[2022-03-01T15:30:46.087435Z] [info] ::: OpenQA::Qemu::Proc::save_state: Saving QEMU state to qemu_state.json
2555
[2022-03-01T15:30:47.099097Z] [debug] Passing remaining frames to the video encoder
2556
[2022-03-01T15:30:47.121523Z] [debug] Waiting for video encoder to finalize the video
2557
[2022-03-01T15:30:47.121599Z] [debug] The built-in video encoder (pid 15534) terminated
2558
[2022-03-01T15:30:47.122162Z] [debug] QEMU: qemu-system-i386: terminating on signal 15 from pid 15464 (/home/squamata/os-autoinst/isotovideo: backen)
2559
[2022-03-01T15:30:47.123026Z] [debug] sending magic and exit
2560
[2022-03-01T15:30:47.123251Z] [debug] received magic close
2561
[2022-03-01T15:30:47.129273Z] [debug] backend process exited: 0
2562
[2022-03-01T15:30:47.230218Z] [debug] stopping backend process 15464
2563
[2022-03-01T15:30:47.230282Z] [debug] done with backend process
2564
15368: EXIT 0
2565
[2022-03-01T15:30:47.247081Z] [info] [pid:15361] Isotovideo exit status: 0
2566
[2022-03-01T15:30:47.274431Z] [info] [pid:15361] +++ worker notes +++
2567
[2022-03-01T15:30:47.274633Z] [info] [pid:15361] End time: 2022-03-01 15:30:47
2568
[2022-03-01T15:30:47.274724Z] [info] [pid:15361] Result: done
2569
[2022-03-01T15:30:47.279493Z] [info] [pid:15604] Uploading video.ogv
2570
[2022-03-01T15:30:47.308157Z] [info] [pid:15604] Uploading vars.json
2571
[2022-03-01T15:30:47.329606Z] [info] [pid:15604] Uploading autoinst-log.txt
2572
/home/squamata/project/test-results/fullstack/full-stack.d/openqa/testresults/00000/00000006-tinycore-1-flavor-i386-Build1-core@coolone/serial0.txt:
2573
/home/squamata/project/test-results/fullstack/full-stack.d/openqa/testresults/00000/00000006-tinycore-1-flavor-i386-Build1-core@coolone/serial_terminal.txt:
2574
/home/squamata/project/test-results/fullstack/full-stack.d/openqa/testresults/00000/00000006-tinycore-1-flavor-i386-Build1-core@coolone/shutdown-3.txt:
2575
# Test died: Machine didn't shut down! at tinycore/tests/shutdown.pm line 9.
2576
/home/squamata/project/test-results/fullstack/full-stack.d/openqa/testresults/00000/00000006-tinycore-1-flavor-i386-Build1-core@coolone/worker-log.txt:
2577
[2022-03-01T15:28:52.774038Z] [debug] [pid:15361] Preparing Mojo::IOLoop::ReadWriteProcess::Session
2578
[2022-03-01T15:28:52.774924Z] [debug] [pid:15361] Job settings:
2579
[2022-03-01T15:28:52.775060Z] [debug] [pid:15361] 
2580
    ARCH=i386
2581
    BUILD=1
2582
    CACHEDIRECTORY=/home/squamata/project/test-results/fullstack/full-stack.d/cache
2583
    CACHELIMIT=50
2584
    DISTRI=tinycore
2585
    FLAVOR=flavor
2586
    INTEGRATION_TESTS=1
2587
    ISO=Core-7.2.iso
2588
    JOBTOKEN=LSwqvyqaj4Ub2NPr
2589
    LOCAL_UPLOAD=0
2590
    LOG_LEVEL=debug
2591
    MACHINE=coolone
2592
    NAME=00000006-tinycore-1-flavor-i386-Build1-core@coolone
2593
    OPENQA_HOSTNAME=localhost:9526
2594
    OPENQA_URL=http://localhost:9526
2595
    PRJDIR=/home/squamata/project/test-results/fullstack/full-stack.d/openqa/share
2596
    PUBLISH_HDD_1=
2597
    QEMU=i386
2598
    QEMUPORT=20012
2599
    QEMU_NO_FDC_SET=1
2600
    QEMU_NO_KVM=1
2601
    QEMU_NO_TABLET=1
2602
    RETRY_DELAY=5
2603
    RETRY_DELAY_IF_WEBUI_BUSY=60
2604
    TEST=core
2605
    UEFI_PFLASH_VARS=/usr/share/qemu/ovmf-x86_64.bin
2606
    VERSION=1
2607
    VNC=91
2608
    WORKER_CLASS=qemu_i386,qemu_x86_64
2609
    WORKER_ID=1
2610
    WORKER_INSTANCE=1
2611
[2022-03-01T15:28:52.785441Z] [debug] [pid:15361] Updating status so job 6 is not considered dead.
2612
[2022-03-01T15:28:52.785855Z] [debug] [pid:15361] REST-API call: POST http://localhost:9526/api/v1/jobs/6/status
2613
[2022-03-01T15:28:57.830995Z] [debug] [pid:15361] Updating status so job 6 is not considered dead.
2614
[2022-03-01T15:28:57.831584Z] [debug] [pid:15361] REST-API call: POST http://localhost:9526/api/v1/jobs/6/status
2615
[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"
2616
[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"
2617
[2022-03-01T15:28:57.875916Z] [info] [pid:15361] Preparing cgroup to start isotovideo
2618
[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.
2619
[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.
2620
[2022-03-01T15:28:57.877467Z] [info] [pid:15361] Starting isotovideo container
2621
[2022-03-01T15:28:57.879858Z] [debug] [pid:15361] Registered process:15368
2622
[2022-03-01T15:28:57.880192Z] [info] [pid:15368] 15368: WORKING 6
2623
[2022-03-01T15:28:57.880336Z] [info] [pid:15361] isotovideo has been started (PID: 15368)
2624
[2022-03-01T15:28:57.880931Z] [debug] [pid:15361] Running job 6 from http://localhost:9526: 00000006-tinycore-1-flavor-i386-Build1-core@coolone.
2625
[2022-03-01T15:28:57.883757Z] [debug] [pid:15361] REST-API call: POST http://localhost:9526/api/v1/jobs/6/status
2626
[2022-03-01T15:28:57.927Z] [debug] [pid:15361] Upload concluded (no current module)
2627
[2022-03-01T15:29:07.935327Z] [debug] [pid:15361] REST-API call: POST http://localhost:9526/api/v1/jobs/6/status
2628
[2022-03-01T15:29:08.000222Z] [debug] [pid:15361] Upload concluded (at boot)
2629
[2022-03-01T15:29:18.002975Z] [debug] [pid:15361] REST-API call: POST http://localhost:9526/api/v1/jobs/6/status
2630
[2022-03-01T15:29:18.118955Z] [debug] [pid:15361] Upload concluded (up to boot)
2631
[2022-03-01T15:29:28.127365Z] [debug] [pid:15361] REST-API call: POST http://localhost:9526/api/v1/jobs/6/status
2632
[2022-03-01T15:29:28.177081Z] [debug] [pid:15361] Upload concluded (at shutdown)
2633
[2022-03-01T15:29:38.179154Z] [debug] [pid:15361] REST-API call: POST http://localhost:9526/api/v1/jobs/6/status
2634
[2022-03-01T15:29:38.233324Z] [debug] [pid:15361] Upload concluded (at shutdown)
2635
[2022-03-01T15:29:48.243182Z] [debug] [pid:15361] REST-API call: POST http://localhost:9526/api/v1/jobs/6/status
2636
[2022-03-01T15:29:48.292938Z] [debug] [pid:15361] Upload concluded (at shutdown)
2637
[2022-03-01T15:29:58.294199Z] [debug] [pid:15361] REST-API call: POST http://localhost:9526/api/v1/jobs/6/status
2638
[2022-03-01T15:29:58.345140Z] [debug] [pid:15361] Upload concluded (at shutdown)
2639
[2022-03-01T15:30:08.356844Z] [debug] [pid:15361] REST-API call: POST http://localhost:9526/api/v1/jobs/6/status
2640
[2022-03-01T15:30:08.407880Z] [debug] [pid:15361] Upload concluded (at shutdown)
2641
[2022-03-01T15:30:18.409652Z] [debug] [pid:15361] REST-API call: POST http://localhost:9526/api/v1/jobs/6/status
2642
[2022-03-01T15:30:18.459101Z] [debug] [pid:15361] Upload concluded (at shutdown)
2643
[2022-03-01T15:30:28.467263Z] [debug] [pid:15361] REST-API call: POST http://localhost:9526/api/v1/jobs/6/status
2644
[2022-03-01T15:30:28.518042Z] [debug] [pid:15361] Upload concluded (at shutdown)
2645
[2022-03-01T15:30:38.520452Z] [debug] [pid:15361] REST-API call: POST http://localhost:9526/api/v1/jobs/6/status
2646
[2022-03-01T15:30:38.570768Z] [debug] [pid:15361] Upload concluded (at shutdown)
2647
[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
2648
[2022-03-01T15:30:47.248172Z] [debug] [pid:15361] REST-API call: POST http://localhost:9526/api/v1/jobs/6/status
2649
[2022-03-01T15:30:47.279310Z] [info] [pid:15604] Uploading video.ogv
2650
[2022-03-01T15:30:47.279787Z] [debug] [pid:15604] Uploading artefact video.ogv
2651
[2022-03-01T15:30:47.308080Z] [info] [pid:15604] Uploading vars.json
2652
[2022-03-01T15:30:47.308308Z] [debug] [pid:15604] Uploading artefact vars.json
2653
[2022-03-01T15:30:47.329525Z] [info] [pid:15604] Uploading autoinst-log.txt
2654
[2022-03-01T15:30:47.329746Z] [debug] [pid:15604] Uploading artefact autoinst-log.txt
2655
[2022-03-01T15:30:47.351212Z] [info] [pid:15604] Uploading worker-log.txt
2656
[2022-03-01T15:30:47.351432Z] [debug] [pid:15604] Uploading artefact worker-log.txt
2657
/home/squamata/project/test-results/fullstack/full-stack.d/openqa/testresults/00000/00000007-tinycore-1-flavor-i386-Build1-core@coolone/autoinst-log.txt:
2658
[2022-03-01T15:30:56.559708Z] [info] [pid:15611] +++ setup notes +++
2659
[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)
2660
[2022-03-01T15:30:56.566905Z] [debug] [pid:15611] Found ISO, caching Core-7.2.iso
2661
[2022-03-01T15:30:56.571854Z] [info] [pid:15611] Downloading Core-7.2.iso, request #3 sent to Cache Service
2662
[2022-03-01T15:31:01.680996Z] [info] [pid:15611] Download of Core-7.2.iso processed
2663
[2022-03-01T15:31:01.689267Z] [debug] [pid:15619] +++ worker notes +++
2664
[2022-03-01T15:31:03.373118Z] [debug] Current version is d410cc0dd1aa541233ea295ddfbe1d94a78c33ad [interface v25]
2665
[2022-03-01T15:31:03.381691Z] [debug] git hash in tinycore: d410cc0dd1aa541233ea295ddfbe1d94a78c33ad
2666
[2022-03-01T15:31:03.465660Z] [debug] scheduling boot tests/boot.pm
2667
[2022-03-01T15:31:03.466317Z] [debug] scheduling assert_screen tests/assert_screen.pm
2668
[2022-03-01T15:31:03.466882Z] [debug] scheduling shutdown tests/shutdown.pm
2669
[2022-03-01T15:31:03.472697Z] [info] cmdsrv: daemon reachable under http://*:20013/gNLfIAyXupl3BtPb/
2670
[2022-03-01T15:31:03.474666Z] [info] Listening at "http://0.0.0.0:20013"
2671
Web application available at http://0.0.0.0:20013
2672
[2022-03-01T15:31:03.475997Z] [debug] git hash in tinycore/needles: d410cc0dd1aa541233ea295ddfbe1d94a78c33ad
2673
[2022-03-01T15:31:03.476104Z] [debug] init needles from tinycore/needles
2674
[2022-03-01T15:31:03.477380Z] [debug] loaded 4 needles
2675
[2022-03-01T15:31:03.479651Z] [debug] Blocking SIGCHLD and SIGTERM
2676
[2022-03-01T15:31:03.666208Z] [debug] Unblocking SIGCHLD and SIGTERM
2677
[2022-03-01T15:31:03.735625Z] [debug] Blocking SIGCHLD and SIGTERM
2678
[2022-03-01T15:31:03.735682Z] [debug] 15619: channel_out 15, channel_in 14
2679
[2022-03-01T15:31:03.866553Z] [debug] Unblocking SIGCHLD and SIGTERM
2680
[2022-03-01T15:31:03.867924Z] [debug] 15712: cmdpipe 13, rsppipe 16
2681
[2022-03-01T15:31:03.868009Z] [debug] started mgmt loop with pid 15712
2682
[2022-03-01T15:31:04.067087Z] [debug] qemu version detected: 5.2.0
2683
[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`
2684
[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.
2685
  
2686
[2022-03-01T15:31:04.075468Z] [debug] Configuring storage controllers and block devices
2687
[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`
2688
[2022-03-01T15:31:04.084877Z] [debug] Initializing block device images
2689
[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`
2690
[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
2691
[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`
2692
[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
2693
[2022-03-01T15:31:04.109321Z] [debug] init_blockdev_images: Finished creating block devices
2694
[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
2695
[2022-03-01T15:31:04.113961Z] [debug] Waiting for 0 attempts
2696
[2022-03-01T15:31:05.114570Z] [debug] Waiting for 1 attempts
2697
[2022-03-01T15:31:06.114930Z] [debug] Finished after 2 attempts
2698
[2022-03-01T15:31:06.116912Z] [debug] Establishing VNC connection to localhost:5991
2699
[2022-03-01T15:31:06.119484Z] [debug] pointer type 0 0 640 480 -257
2700
[2022-03-01T15:31:06.119568Z] [debug] led state 0 1 1 -261
2701
[2022-03-01T15:31:06.178770Z] [debug] Start CPU
2702
[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}}
2703
[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}}
2704
[2022-03-01T15:31:06.179315Z] [debug] EVENT {"event":"RESUME","timestamp":{"microseconds":179246,"seconds":1646148666}}
2705
GOT GO
2706

    
2707
[2022-03-01T15:31:06.187039Z] [debug] QEMU: QEMU emulator version 5.2.0 (SUSE Linux Enterprise 15)
2708
[2022-03-01T15:31:06.187093Z] [debug] QEMU: Copyright (c) 2003-2020 Fabrice Bellard and the QEMU Project developers
2709
[2022-03-01T15:31:06.190319Z] [debug] Snapshots are supported
2710
[2022-03-01T15:31:06.191124Z] [debug] ||| starting boot tests/boot.pm
2711
[2022-03-01T15:31:06.192559Z] [debug] tests/boot.pm:9 called testapi::assert_screen
2712
[2022-03-01T15:31:06.192807Z] [debug] <<< testapi::assert_screen(mustmatch="core", no_wait=1, timeout=15)
2713
[2022-03-01T15:31:06.206769Z] [debug] no match: 14.9s, best candidate: boot-core (0.00)
2714
[2022-03-01T15:31:06.307577Z] [debug] no change: 14.8s
2715
[2022-03-01T15:31:06.314231Z] [debug] no match: 14.8s, best candidate: boot-core (0.00)
2716
[2022-03-01T15:31:06.414930Z] [debug] no change: 14.7s
2717
[2022-03-01T15:31:06.421470Z] [debug] no match: 14.7s, best candidate: boot-core (0.00)
2718
[2022-03-01T15:31:06.522166Z] [debug] no change: 14.6s
2719
[2022-03-01T15:31:06.528763Z] [debug] no match: 14.6s, best candidate: boot-core (0.00)
2720
[2022-03-01T15:31:06.629645Z] [debug] no change: 14.5s
2721
[2022-03-01T15:31:06.636272Z] [debug] no match: 14.5s, best candidate: boot-core (0.00)
2722
[2022-03-01T15:31:06.811647Z] [debug] >>> testapi::_handle_found_needle: found boot-core, similarity 0.97 @ 1/74
2723
[2022-03-01T15:31:06.812270Z] [debug] tests/boot.pm:10 called testapi::send_key
2724
[2022-03-01T15:31:06.812388Z] [debug] <<< testapi::send_key(key="ret", do_wait=0, wait_screen_change=0)
2725
[2022-03-01T15:31:07.081859Z] [debug] tests/boot.pm:14 called testapi::assert_screen
2726
[2022-03-01T15:31:07.082014Z] [debug] <<< testapi::assert_screen(mustmatch="on_prompt", timeout=90)
2727
[2022-03-01T15:31:07.742475Z] [debug] no match: 89.3s, best candidate: boot-on_prompt (0.00)
2728
[2022-03-01T15:31:08.740165Z] [debug] no match: 88.3s, best candidate: boot-on_prompt (0.00)
2729
[2022-03-01T15:31:09.741412Z] [debug] no match: 87.3s, best candidate: boot-on_prompt (0.00)
2730
[2022-03-01T15:31:10.742425Z] [debug] no match: 86.3s, best candidate: boot-on_prompt (0.00)
2731
[2022-03-01T15:31:11.786061Z] [debug] no match: 85.3s, best candidate: boot-on_prompt (0.00)
2732
[2022-03-01T15:31:12.744722Z] [debug] no match: 84.3s, best candidate: boot-on_prompt (0.00)
2733
[2022-03-01T15:31:13.745716Z] [debug] no match: 83.3s, best candidate: boot-on_prompt (0.00)
2734
[2022-03-01T15:31:14.746240Z] [debug] no match: 82.3s, best candidate: boot-on_prompt (0.00)
2735
[2022-03-01T15:31:15.820112Z] [debug] >>> testapi::_handle_found_needle: found boot-on_prompt, similarity 1.00 @ 2/64
2736
[2022-03-01T15:31:15.823409Z] [debug] ||| finished boot tests (runtime: 9 s)
2737
[2022-03-01T15:31:15.824465Z] [debug] ||| starting assert_screen tests/assert_screen.pm
2738
[2022-03-01T15:31:15.825078Z] [debug] tests/assert_screen.pm:9 called testapi::assert_screen
2739
[2022-03-01T15:31:15.825174Z] [debug] <<< testapi::assert_screen(mustmatch="on_prompt", timeout=60)
2740
[2022-03-01T15:31:16.807246Z] [debug] >>> testapi::_handle_found_needle: found boot-on_prompt, similarity 1.00 @ 2/64
2741
[2022-03-01T15:31:16.807395Z] [debug] tests/assert_screen.pm:10 called testapi::assert_screen
2742
[2022-03-01T15:31:16.807498Z] [debug] <<< testapi::assert_screen(mustmatch="on_prompt", no_wait=1, timeout=30)
2743
[2022-03-01T15:31:16.884661Z] [debug] >>> testapi::_handle_found_needle: found boot-on_prompt, similarity 1.00 @ 2/64
2744
[2022-03-01T15:31:16.885721Z] [debug] ||| finished assert_screen tests (runtime: 1 s)
2745
[2022-03-01T15:31:16.887024Z] [debug] ||| starting shutdown tests/shutdown.pm
2746
[2022-03-01T15:31:16.887541Z] [debug] tests/shutdown.pm:8 called testapi::enter_cmd
2747
[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)
2748
[2022-03-01T15:31:17.361642Z] [debug] tests/shutdown.pm:9 called testapi::assert_shutdown
2749
[2022-03-01T15:31:17.361783Z] [debug] <<< testapi::check_shutdown(timeout=90)
2750
[2022-03-01T15:31:17.362563Z] [debug] QEMU status is not 'shutdown', it is 'running'
2751
[2022-03-01T15:31:18.363771Z] [debug] QEMU status is not 'shutdown', it is 'running'
2752
[2022-03-01T15:31:19.365286Z] [debug] QEMU status is not 'shutdown', it is 'running'
2753
[2022-03-01T15:31:20.366765Z] [debug] QEMU status is not 'shutdown', it is 'running'
2754
[2022-03-01T15:31:21.368311Z] [debug] QEMU status is not 'shutdown', it is 'running'
2755
[2022-03-01T15:31:22.369522Z] [debug] EVENT {"data":{"guest":true,"reason":"guest-shutdown"},"event":"SHUTDOWN","timestamp":{"microseconds":967483,"seconds":1646148681}}
2756
[2022-03-01T15:31:22.369621Z] [debug] EVENT {"event":"STOP","timestamp":{"microseconds":967989,"seconds":1646148681}}
2757
[2022-03-01T15:31:22.429401Z] [debug] ||| finished shutdown tests (runtime: 6 s)
2758
[2022-03-01T15:31:22.430814Z] [debug] stopping autotest process 15642
2759
[2022-03-01T15:31:22.435352Z] [debug] [autotest] process exited: 0
2760
[2022-03-01T15:31:22.535829Z] [debug] done with autotest process
2761
[2022-03-01T15:31:22.536254Z] [debug] stopping command server 15639 because test execution ended
2762
[2022-03-01T15:31:22.536331Z] [debug] isotovideo: informing websocket clients before stopping command server: http://127.0.0.1:20013/gNLfIAyXupl3BtPb/broadcast
2763
[2022-03-01T15:31:22.548564Z] [debug] commands process exited: 0
2764
[2022-03-01T15:31:22.648947Z] [debug] done with command server
2765
[2022-03-01T15:31:22.649024Z] [debug] isotovideo done
2766
[2022-03-01T15:31:22.649876Z] [debug] backend shutdown state: 1
2767
[2022-03-01T15:31:22.650298Z] [info] ::: OpenQA::Qemu::Proc::save_state: Saving QEMU state to qemu_state.json
2768
[2022-03-01T15:31:23.659290Z] [debug] Passing remaining frames to the video encoder
2769
[2022-03-01T15:31:23.683456Z] [debug] Waiting for video encoder to finalize the video
2770
[2022-03-01T15:31:23.683540Z] [debug] The built-in video encoder (pid 15782) terminated
2771
[2022-03-01T15:31:23.684019Z] [debug] QEMU: qemu-system-i386: terminating on signal 15 from pid 15712 (/home/squamata/os-autoinst/isotovideo: backen)
2772
[2022-03-01T15:31:23.684812Z] [debug] sending magic and exit
2773
[2022-03-01T15:31:23.685105Z] [debug] received magic close
2774
[2022-03-01T15:31:23.691150Z] [debug] backend process exited: 0
2775
[2022-03-01T15:31:23.791990Z] [debug] stopping backend process 15712
2776
[2022-03-01T15:31:23.792059Z] [debug] done with backend process
2777
15619: EXIT 0
2778
[2022-03-01T15:31:23.807176Z] [info] [pid:15611] Isotovideo exit status: 0
2779
[2022-03-01T15:31:23.835781Z] [info] [pid:15611] +++ worker notes +++
2780
[2022-03-01T15:31:23.836046Z] [info] [pid:15611] End time: 2022-03-01 15:31:23
2781
[2022-03-01T15:31:23.836203Z] [info] [pid:15611] Result: done
2782
[2022-03-01T15:31:23.842042Z] [info] [pid:15840] Uploading video.ogv
2783
[2022-03-01T15:31:23.870221Z] [info] [pid:15840] Uploading vars.json
2784
[2022-03-01T15:31:23.894449Z] [info] [pid:15840] Uploading autoinst-log.txt
2785
/home/squamata/project/test-results/fullstack/full-stack.d/openqa/testresults/00000/00000007-tinycore-1-flavor-i386-Build1-core@coolone/serial0.txt:
2786
/home/squamata/project/test-results/fullstack/full-stack.d/openqa/testresults/00000/00000007-tinycore-1-flavor-i386-Build1-core@coolone/serial_terminal.txt:
2787
/home/squamata/project/test-results/fullstack/full-stack.d/openqa/testresults/00000/00000007-tinycore-1-flavor-i386-Build1-core@coolone/worker-log.txt:
2788
[2022-03-01T15:30:56.559163Z] [debug] [pid:15611] Preparing Mojo::IOLoop::ReadWriteProcess::Session
2789
[2022-03-01T15:30:56.560408Z] [debug] [pid:15611] Job settings:
2790
[2022-03-01T15:30:56.560629Z] [debug] [pid:15611] 
2791
    ARCH=i386
2792
    BUILD=1
2793
    CACHEDIRECTORY=/home/squamata/project/test-results/fullstack/full-stack.d/cache
2794
    CACHELIMIT=50
2795
    DISTRI=tinycore
2796
    FLAVOR=flavor
2797
    INTEGRATION_TESTS=1
2798
    ISO=Core-7.2.iso
2799
    JOBTOKEN=gNLfIAyXupl3BtPb
2800
    LOCAL_UPLOAD=0
2801
    LOG_LEVEL=debug
2802
    MACHINE=coolone
2803
    NAME=00000007-tinycore-1-flavor-i386-Build1-core@coolone
2804
    OPENQA_HOSTNAME=localhost:9526
2805
    OPENQA_URL=http://localhost:9526
2806
    PRJDIR=/home/squamata/project/test-results/fullstack/full-stack.d/openqa/share
2807
    PUBLISH_HDD_1=
2808
    QEMU=i386
2809
    QEMUPORT=20012
2810
    QEMU_NO_FDC_SET=1
2811
    QEMU_NO_KVM=1
2812
    QEMU_NO_TABLET=1
2813
    RETRY_DELAY=5
2814
    RETRY_DELAY_IF_WEBUI_BUSY=60
2815
    TEST=core
2816
    UEFI_PFLASH_VARS=/usr/share/qemu/ovmf-x86_64.bin
2817
    VERSION=1
2818
    VNC=91
2819
    WORKER_CLASS=qemu_i386,qemu_x86_64
2820
    WORKER_ID=1
2821
    WORKER_INSTANCE=1
2822
[2022-03-01T15:30:56.572091Z] [debug] [pid:15611] Updating status so job 7 is not considered dead.
2823
[2022-03-01T15:30:56.572680Z] [debug] [pid:15611] REST-API call: POST http://localhost:9526/api/v1/jobs/7/status
2824
[2022-03-01T15:31:01.638429Z] [debug] [pid:15611] Updating status so job 7 is not considered dead.
2825
[2022-03-01T15:31:01.639086Z] [debug] [pid:15611] REST-API call: POST http://localhost:9526/api/v1/jobs/7/status
2826
[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"
2827
[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"
2828
[2022-03-01T15:31:01.683866Z] [info] [pid:15611] Preparing cgroup to start isotovideo
2829
[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.
2830
[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.
2831
[2022-03-01T15:31:01.685917Z] [info] [pid:15611] Starting isotovideo container
2832
[2022-03-01T15:31:01.688782Z] [debug] [pid:15611] Registered process:15619
2833
[2022-03-01T15:31:01.689035Z] [info] [pid:15619] 15619: WORKING 7
2834
[2022-03-01T15:31:01.689364Z] [info] [pid:15611] isotovideo has been started (PID: 15619)
2835
[2022-03-01T15:31:01.690135Z] [debug] [pid:15611] Running job 7 from http://localhost:9526: 00000007-tinycore-1-flavor-i386-Build1-core@coolone.
2836
[2022-03-01T15:31:01.693163Z] [debug] [pid:15611] REST-API call: POST http://localhost:9526/api/v1/jobs/7/status
2837
[2022-03-01T15:31:01.735180Z] [debug] [pid:15611] Upload concluded (no current module)
2838
[2022-03-01T15:31:11.746679Z] [debug] [pid:15611] REST-API call: POST http://localhost:9526/api/v1/jobs/7/status
2839
[2022-03-01T15:31:11.811701Z] [debug] [pid:15611] Upload concluded (at boot)
2840
[2022-03-01T15:31:21.813737Z] [debug] [pid:15611] REST-API call: POST http://localhost:9526/api/v1/jobs/7/status
2841
[2022-03-01T15:31:21.913156Z] [debug] [pid:15611] Upload concluded (up to boot)
2842
[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
2843
[2022-03-01T15:31:23.808676Z] [debug] [pid:15611] REST-API call: POST http://localhost:9526/api/v1/jobs/7/status
2844
[2022-03-01T15:31:23.841884Z] [info] [pid:15840] Uploading video.ogv
2845
[2022-03-01T15:31:23.842361Z] [debug] [pid:15840] Uploading artefact video.ogv
2846
[2022-03-01T15:31:23.870130Z] [info] [pid:15840] Uploading vars.json
2847
[2022-03-01T15:31:23.870385Z] [debug] [pid:15840] Uploading artefact vars.json
2848
[2022-03-01T15:31:23.894340Z] [info] [pid:15840] Uploading autoinst-log.txt
2849
[2022-03-01T15:31:23.894620Z] [debug] [pid:15840] Uploading artefact autoinst-log.txt
2850
[2022-03-01T15:31:23.918495Z] [info] [pid:15840] Uploading worker-log.txt
2851
[2022-03-01T15:31:23.918738Z] [debug] [pid:15840] Uploading artefact worker-log.txt
2852
/home/squamata/project/test-results/fullstack/full-stack.d/openqa/testresults/00000/00000008-tinycore-1-flavor-i386-Build1-core@coolone/autoinst-log.txt:
2853
[2022-03-01T15:31:25.849960Z] [info] [pid:15611] +++ setup notes +++
2854
[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)
2855
[2022-03-01T15:31:25.856229Z] [debug] [pid:15611] Found HDD_1, caching non-existent.qcow2
2856
[2022-03-01T15:31:25.863008Z] [info] [pid:15611] Downloading non-existent.qcow2, request #4 sent to Cache Service
2857
[2022-03-01T15:31:31.016113Z] [info] [pid:15611] Download of non-existent.qcow2 processed
2858
[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
2859
[2022-03-01T15:31:31.042498Z] [info] [pid:15611] +++ worker notes +++
2860
[2022-03-01T15:31:31.042680Z] [info] [pid:15611] End time: 2022-03-01 15:31:31
2861
[2022-03-01T15:31:31.042769Z] [info] [pid:15611] Result: setup failure
2862
[2022-03-01T15:31:31.047024Z] [info] [pid:15848] Uploading autoinst-log.txt
2863
/home/squamata/project/test-results/fullstack/full-stack.d/openqa/testresults/00000/00000008-tinycore-1-flavor-i386-Build1-core@coolone/worker-log.txt:
2864
[2022-03-01T15:31:25.849684Z] [debug] [pid:15611] Preparing Mojo::IOLoop::ReadWriteProcess::Session
2865
[2022-03-01T15:31:25.850455Z] [debug] [pid:15611] Job settings:
2866
[2022-03-01T15:31:25.850593Z] [debug] [pid:15611] 
2867
    ARCH=i386
2868
    BUILD=1
2869
    CACHEDIRECTORY=/home/squamata/project/test-results/fullstack/full-stack.d/cache
2870
    CACHELIMIT=50
2871
    DISTRI=tinycore
2872
    FLAVOR=flavor
2873
    HDD_1=non-existent.qcow2
2874
    INTEGRATION_TESTS=1
2875
    ISO=Core-7.2.iso
2876
    JOBTOKEN=FyOb_mAEM1SQZfuT
2877
    LOCAL_UPLOAD=0
2878
    LOG_LEVEL=debug
2879
    MACHINE=coolone
2880
    NAME=00000008-tinycore-1-flavor-i386-Build1-core@coolone
2881
    OPENQA_HOSTNAME=localhost:9526
2882
    OPENQA_URL=http://localhost:9526
2883
    PRJDIR=/home/squamata/project/test-results/fullstack/full-stack.d/openqa/share
2884
    PUBLISH_HDD_1=core-hdd.qcow2
2885
    QEMU=i386
2886
    QEMUPORT=20012
2887
    QEMU_NO_FDC_SET=1
2888
    QEMU_NO_KVM=1
2889
    QEMU_NO_TABLET=1
2890
    RETRY_DELAY=5
2891
    RETRY_DELAY_IF_WEBUI_BUSY=60
2892
    TEST=core
2893
    UEFI_PFLASH_VARS=/usr/share/qemu/ovmf-x86_64.bin
2894
    VERSION=1
2895
    VNC=91
2896
    WORKER_CLASS=qemu_i386,qemu_x86_64
2897
    WORKER_ID=1
2898
    WORKER_INSTANCE=1
2899
[2022-03-01T15:31:25.863182Z] [debug] [pid:15611] Updating status so job 8 is not considered dead.
2900
[2022-03-01T15:31:25.863547Z] [debug] [pid:15611] REST-API call: POST http://localhost:9526/api/v1/jobs/8/status
2901
[2022-03-01T15:31:30.974364Z] [debug] [pid:15611] Updating status so job 8 is not considered dead.
2902
[2022-03-01T15:31:30.974934Z] [debug] [pid:15611] REST-API call: POST http://localhost:9526/api/v1/jobs/8/status
2903
[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
2904
[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
2905
[2022-03-01T15:31:31.018746Z] [debug] [pid:15611] REST-API call: POST http://localhost:9526/api/v1/jobs/8/status
2906
[2022-03-01T15:31:31.046860Z] [info] [pid:15848] Uploading autoinst-log.txt
2907
[2022-03-01T15:31:31.047365Z] [debug] [pid:15848] Uploading artefact autoinst-log.txt
2908
[2022-03-01T15:31:31.084057Z] [info] [pid:15848] Uploading worker-log.txt
2909
[2022-03-01T15:31:31.084312Z] [debug] [pid:15848] Uploading artefact worker-log.txt