· 6 years ago · Nov 12, 2019, 12:16 PM
1[debug] [3b65b641] POST "/api/v1/jobs/2/duplicate"
2[debug] [3b65b641] Routing to controller "OpenQA::WebAPI::Controller::API::V1" and action "auth_operator"
3[debug] API key from client: *1234567890ABCDEF*
4[debug] Key is for user 'Demo'
5[debug] API auth by user: Demo, operator: 1
6[debug] [3b65b641] Routing to controller "OpenQA::WebAPI::Controller::API::V1::Job" and action "duplicate"
7[debug] [pid:8128] Jobs to duplicate {
8 2 => {
9 chained_children => [],
10 chained_parents => [],
11 directly_chained_children => [],
12 directly_chained_parents => [],
13 parallel_children => [],
14 parallel_parents => [],
15 },
16}
17[debug] [pid:8127] Received from worker "1" worker_status message "---
18current_webui_host: http://localhost:60651
19job:
20 URL: http://localhost:20013/NYUSwTvoXn2BIQQN
21 assets:
22 iso:
23 - Core-7.2.iso
24 assigned_worker_id: 1
25 blocked_by_id: ~
26 clone_id: ~
27 group: New job group
28 group_id: 1
29 id: 2
30 name: tinycore-1-flavor-i386-Build1-core@coolone
31 origin_id: 1
32 priority: 50
33 result: none
34 settings:
35 ARCH: i386
36 BUILD: '1'
37 CDMODEL: ide-cd
38 DISTRI: tinycore
39 FLAVOR: flavor
40 HDDMODEL: ide-drive
41 INTEGRATION_TESTS: '1'
42 ISO: Core-7.2.iso
43 JOBTOKEN: NYUSwTvoXn2BIQQN
44 LOG_LEVEL: debug
45 MACHINE: coolone
46 NAME: 00000002-tinycore-1-flavor-i386-Build1-core@coolone
47 OPENQA_HOSTNAME: localhost:60651
48 PUBLISH_HDD_1: core-hdd.qcow2
49 QEMU: i386
50 QEMUPORT: 20012
51 QEMU_NO_FDC_SET: '1'
52 QEMU_NO_KVM: '1'
53 QEMU_NO_TABLET: '1'
54 RETRY_DELAY: 5
55 RETRY_DELAY_IF_WEBUI_BUSY: 60
56 TEST: core
57 UEFI_PFLASH_VARS: /usr/share/qemu/ovmf-x86_64.bin
58 VERSION: '1'
59 VNC: '91'
60 WORKER_CLASS: qemu_i386,qemu_x86_64
61 WORKER_HOSTNAME: 127.0.0.1
62 state: scheduled
63 t_finished: ~
64 t_started: ~
65 test: core
66status: working
67type: worker_status
68"
69[debug] [pid:8127] Updating worker seen from worker_status
70[debug] [pid:8127] Found job 2 in DB from worker_status update sent by worker 1
71[debug] [pid:8127] Received request has job id: 2
72[debug] [pid:8127] Worker 1 for job 2 has token NYUSwTvoXn2BIQQN
73[debug] [pid:8127] Received request has token: NYUSwTvoXn2BIQQN
74[debug] [pid:8127] Sent population to worker: { population => 1, type => "info" }
75[error] [pid:8127] Unable to inform scheduler that worker 1 reported back (connection error: Connection refused)
76[error] [pid:8127] response was:
77[debug] [pid:8128] new job 3
78[debug] [3b65b641] 200 OK (0.097457s, 10.261/s)
79[warn] [pid:8203] Can't open /tmp/VDZMlESezv/t/full-stack.d/openqa/pool/1/testresults/result-shutdown.json for result upload - likely isotovideo could not be started or failed early. Error message: No such file or directory
80[debug] [pid:8203] REST-API call: POST http://localhost:60651/api/v1/jobs/2/status
81[debug] [ea88ddc2] POST "/api/v1/jobs/2/status"
82[debug] [ea88ddc2] Routing to controller "OpenQA::WebAPI::Controller::API::V1" and action "auth_operator"
83[debug] API key from client: *1234567890ABCDEF*
84[debug] Key is for user 'Demo'
85[debug] API auth by user: Demo, operator: 1
86[debug] [ea88ddc2] Routing to controller "OpenQA::WebAPI::Controller::API::V1::Job" and action "update_status"
87[debug] [ea88ddc2] 200 OK (0.038517s, 25.963/s)
88[debug] [pid:8203] REST-API call: POST http://localhost:60651/api/v1/jobs/2/set_done?result=incomplete
89[debug] [dd8a106e] POST "/api/v1/jobs/2/set_done"
90[debug] [dd8a106e] Routing to controller "OpenQA::WebAPI::Controller::API::V1" and action "auth_operator"
91[debug] API key from client: *1234567890ABCDEF*
92[debug] Key is for user 'Demo'
93[debug] API auth by user: Demo, operator: 1
94[debug] [dd8a106e] Routing to controller "OpenQA::WebAPI::Controller::API::V1::Job" and action "done"
95[debug] [dd8a106e] 200 OK (0.039404s, 25.378/s)
96[debug] [pid:8203] Job 2 from http://localhost:60651 finished - reason: quit
97[debug] [b27c4eb6] 200 OK (8.760551s, 0.114/s)
98[debug] [fa762ba9] GET "/tests/2/status"
99[debug] [fa762ba9] Routing to controller "OpenQA::WebAPI::Controller::Test" and action "referer_check"
100[debug] [pid:8128] Unrecognized referer 'localhost'
101[debug] [fa762ba9] Routing to controller "OpenQA::WebAPI::Controller::Running" and action "status"
102[debug] [fa762ba9] 200 OK (0.010159s, 98.435/s)
103[info] [pid:8127] Worker 1 websocket connection closed - 1006
104ok 31 - WORKER is done
105# reloading manually (test 2 crashed)
106[debug] [14de0d96] GET "/tests/2"
107[debug] [14de0d96] Routing to controller "OpenQA::WebAPI::Controller::Test" and action "referer_check"
108[debug] [pid:8128] Unrecognized referer 'localhost'
109[debug] [14de0d96] Routing to controller "OpenQA::WebAPI::Controller::Test" and action "show"
110[debug] [pid:8128] reading /tmp/VDZMlESezv/t/full-stack.d/openqa/testresults/00000/00000002-tinycore-1-flavor-i386-Build1-core@coolone/details-boot.json
111[debug] [pid:8128] reading /tmp/VDZMlESezv/t/full-stack.d/openqa/testresults/00000/00000002-tinycore-1-flavor-i386-Build1-core@coolone/details-shutdown.json
112[debug] [14de0d96] Rendering cached template "test/result.html.ep"
113[debug] [14de0d96] Rendering cached template "layouts/info.html.ep"
114[debug] [14de0d96] Rendering cached template "test/infopanel.html.ep"
115[debug] [14de0d96] Rendering cached template "test/details.html.ep"
116[debug] [14de0d96] Rendering cached template "test/module_table.html.ep"
117[debug] [14de0d96] Rendering cached template "test/downloads.html.ep"
118[debug] [14de0d96] Rendering cached template "test/settings.html.ep"
119[debug] [14de0d96] Rendering cached template "test/comments.html.ep"
120[debug] [14de0d96] Rendering cached template "comments/comment_row.html.ep"
121[debug] [14de0d96] Rendering cached template "comments/add_comment_form_groups.html.ep"
122[debug] [14de0d96] Rendering cached template "test/job_next_previous.html.ep"
123[debug] [14de0d96] Rendering cached template "layouts/bootstrap.html.ep"
124[debug] [14de0d96] Rendering cached template "layouts/navbar.html.ep"
125[debug] [14de0d96] Template "branding/openSUSE/links_footer_left.html.ep" not found
126[debug] [14de0d96] Template "branding/plain/links_footer_left.html.ep" not found
127[debug] [14de0d96] Template "branding/openSUSE/links_footer_right.html.ep" not found
128[debug] [14de0d96] Template "branding/plain/links_footer_right.html.ep" not found
129[debug] [14de0d96] 200 OK (0.118614s, 8.431/s)
130[debug] [pid:8128] Asking the worker to stop providing livestream
131[debug] [334b925e] POST "/api/send_msg"
132[debug] [334b925e] Routing to controller "OpenQA::Shared::Controller::Auth" and action "check"
133[debug] [334b925e] Routing to controller "OpenQA::WebSockets::Controller::API" and action "send_msg"
134[debug] [pid:8127] Unable to send command "livelog_stop" to worker 1: worker not connected
135[debug] [334b925e] 200 OK (0.001553s, 643.915/s)
136ok 32 - test 2 crashed
137ok 33 - test 2 is restarted by killing worker
138[debug] [f27e7de3] POST "/api/v1/jobs"
139[debug] [f27e7de3] Routing to controller "OpenQA::WebAPI::Controller::API::V1" and action "auth_operator"
140[debug] API key from client: *1234567890ABCDEF*
141[debug] Key is for user 'Demo'
142[debug] API auth by user: Demo, operator: 1
143[debug] [f27e7de3] Routing to controller "OpenQA::WebAPI::Controller::API::V1::Job" and action "create"
144[debug] [f27e7de3] 200 OK (0.060653s, 16.487/s)
145# Subtest: cancel a scheduled job
146[debug] [60a46022] GET "/tests"
147[debug] [60a46022] Routing to controller "OpenQA::WebAPI::Controller::Test" and action "list"
148[debug] [60a46022] Rendering cached template "test/list.html.ep"
149[debug] [60a46022] Rendering cached template "layouts/bootstrap.html.ep"
150[debug] [60a46022] Rendering cached template "layouts/navbar.html.ep"
151[debug] [60a46022] Template "branding/openSUSE/links_footer_left.html.ep" not found
152[debug] [60a46022] Template "branding/plain/links_footer_left.html.ep" not found
153[debug] [60a46022] Template "branding/openSUSE/links_footer_right.html.ep" not found
154[debug] [60a46022] Template "branding/plain/links_footer_right.html.ep" not found
155[debug] [60a46022] 200 OK (0.01733s, 57.703/s)
156 ok 1 - click_ok'All tests clicked'
157[debug] [a8703c40] GET "/tests/list_running_ajax"
158[debug] [a8703c40] Routing to controller "OpenQA::WebAPI::Controller::Test" and action "list_running_ajax"
159[debug] [a8703c40] 200 OK (0.013052s, 76.617/s)
160[debug] [a0e55a6c] GET "/tests/list_ajax"
161[debug] [a0e55a6c] Routing to controller "OpenQA::WebAPI::Controller::Test" and action "list_ajax"
162[debug] [a0e55a6c] 200 OK (0.033496s, 29.854/s)
163[debug] [58750dcc] GET "/tests/list_scheduled_ajax"
164[debug] [58750dcc] Routing to controller "OpenQA::WebAPI::Controller::Test" and action "list_scheduled_ajax"
165[debug] [58750dcc] 200 OK (0.006472s, 154.512/s)
166[debug] [eccb9385] GET "/tests/3"
167[debug] [eccb9385] Routing to controller "OpenQA::WebAPI::Controller::Test" and action "referer_check"
168[debug] [pid:8128] Unrecognized referer 'localhost'
169[debug] [eccb9385] Routing to controller "OpenQA::WebAPI::Controller::Test" and action "show"
170[debug] [eccb9385] Rendering cached template "test/result.html.ep"
171[debug] [eccb9385] Rendering cached template "layouts/info.html.ep"
172[debug] [eccb9385] Rendering cached template "test/infopanel.html.ep"
173[debug] [eccb9385] Rendering cached template "test/details.html.ep"
174[debug] [eccb9385] Rendering cached template "test/downloads.html.ep"
175[debug] [eccb9385] Rendering cached template "test/settings.html.ep"
176[debug] [eccb9385] Rendering cached template "test/comments.html.ep"
177[debug] [eccb9385] Rendering cached template "comments/comment_row.html.ep"
178[debug] [eccb9385] Rendering cached template "comments/add_comment_form_groups.html.ep"
179[debug] [eccb9385] Rendering cached template "test/job_next_previous.html.ep"
180[debug] [eccb9385] Rendering cached template "layouts/bootstrap.html.ep"
181[debug] [eccb9385] Rendering cached template "layouts/navbar.html.ep"
182[debug] [eccb9385] Template "branding/openSUSE/links_footer_left.html.ep" not found
183[debug] [eccb9385] Template "branding/plain/links_footer_left.html.ep" not found
184[debug] [eccb9385] Template "branding/openSUSE/links_footer_right.html.ep" not found
185[debug] [eccb9385] Template "branding/plain/links_footer_right.html.ep" not found
186[debug] [eccb9385] 200 OK (0.07172s, 13.943/s)
187 ok 2 - click_ok'clicked on 3'
188 ok 3 - Test 3 is scheduled
189 1..3
190ok 34 - cancel a scheduled job
191[debug] [7807ccdb] POST "/api/v1/jobs/3/cancel"
192[debug] [7807ccdb] Routing to controller "OpenQA::WebAPI::Controller::API::V1" and action "auth_operator"
193[debug] API auth by user: Demo, operator: 1
194[debug] [7807ccdb] Routing to controller "OpenQA::WebAPI::Controller::API::V1::Job" and action "cancel"
195[debug] [7807ccdb] 200 OK (0.028222s, 35.433/s)
196[debug] [72c17bf5] GET "/tests"
197[debug] [72c17bf5] Routing to controller "OpenQA::WebAPI::Controller::Test" and action "list"
198[debug] [72c17bf5] Rendering cached template "test/list.html.ep"
199[debug] [72c17bf5] Rendering cached template "layouts/bootstrap.html.ep"
200[debug] [72c17bf5] Rendering cached template "layouts/navbar.html.ep"
201[debug] [72c17bf5] Template "branding/openSUSE/links_footer_left.html.ep" not found
202[debug] [72c17bf5] Template "branding/plain/links_footer_left.html.ep" not found
203[debug] [72c17bf5] Template "branding/openSUSE/links_footer_right.html.ep" not found
204[debug] [72c17bf5] Template "branding/plain/links_footer_right.html.ep" not found
205[debug] [72c17bf5] 200 OK (0.024154s, 41.401/s)
206ok 35 - click_ok''
207[debug] [ea39a680] GET "/tests/list_running_ajax"
208[debug] [ea39a680] Routing to controller "OpenQA::WebAPI::Controller::Test" and action "list_running_ajax"
209[debug] [ea39a680] 200 OK (0.011319s, 88.347/s)
210[debug] [8597d292] GET "/tests/list_scheduled_ajax"
211[debug] [8597d292] Routing to controller "OpenQA::WebAPI::Controller::Test" and action "list_scheduled_ajax"
212[debug] [8597d292] 200 OK (0.004825s, 207.254/s)
213[debug] [ef3ee5f0] GET "/tests/list_ajax"
214[debug] [ef3ee5f0] Routing to controller "OpenQA::WebAPI::Controller::Test" and action "list_ajax"
215[debug] [ef3ee5f0] 200 OK (0.029501s, 33.897/s)
216[debug] [c5562fc4] GET "/tests/4"
217[debug] [c5562fc4] Routing to controller "OpenQA::WebAPI::Controller::Test" and action "referer_check"
218[debug] [pid:8128] Unrecognized referer 'localhost'
219[debug] [c5562fc4] Routing to controller "OpenQA::WebAPI::Controller::Test" and action "show"
220[debug] [c5562fc4] Rendering cached template "test/result.html.ep"
221[debug] [c5562fc4] Rendering cached template "layouts/info.html.ep"
222[debug] [c5562fc4] Rendering cached template "test/infopanel.html.ep"
223[debug] [c5562fc4] Rendering cached template "test/details.html.ep"
224[debug] [c5562fc4] Rendering cached template "test/downloads.html.ep"
225[debug] [c5562fc4] Rendering cached template "test/settings.html.ep"
226[debug] [c5562fc4] Rendering cached template "test/comments.html.ep"
227[debug] [c5562fc4] Rendering cached template "comments/comment_row.html.ep"
228[debug] [c5562fc4] Rendering cached template "comments/add_comment_form_groups.html.ep"
229[debug] [c5562fc4] Rendering cached template "test/job_next_previous.html.ep"
230[debug] [c5562fc4] Rendering cached template "layouts/bootstrap.html.ep"
231[debug] [c5562fc4] Rendering cached template "layouts/navbar.html.ep"
232[debug] [c5562fc4] Template "branding/openSUSE/links_footer_left.html.ep" not found
233[debug] [c5562fc4] Template "branding/plain/links_footer_left.html.ep" not found
234[debug] [c5562fc4] Template "branding/openSUSE/links_footer_right.html.ep" not found
235[debug] [c5562fc4] Template "branding/plain/links_footer_right.html.ep" not found
236[debug] [c5562fc4] 200 OK (0.110571s, 9.044/s)
237ok 36 - click_ok''
238ok 37 - scheduled test page
239ok 38 - test 4 is scheduled
240ok 39 - Worker started as 8546
241[info] [pid:8546] worker 1:
242 - config file: /tmp/VDZMlESezv/t/full-stack.d/config/workers.ini
243 - worker hostname: ac31197ebdb5
244 - isotovideo version: 18
245 - websocket API version: 1
246 - web UI hosts: http://localhost:60651
247 - class: qemu_i386,qemu_x86_64
248 - no cleanup: no
249 - pool directory: /tmp/VDZMlESezv/t/full-stack.d/openqa/pool/1
250[info] [pid:8546] Project dir for host http://localhost:60651 is /tmp/VDZMlESezv/t/full-stack.d/openqa/share
251[info] [pid:8546] Registering with openQA http://localhost:60651
252[debug] [2e0c6872] POST "/api/v1/workers"
253[debug] [2e0c6872] Routing to controller "OpenQA::WebAPI::Controller::API::V1" and action "auth_operator"
254[debug] API key from client: *1234567890ABCDEF*
255[debug] Key is for user 'Demo'
256[debug] API auth by user: Demo, operator: 1
257[debug] [2e0c6872] Routing to controller "OpenQA::WebAPI::Controller::API::V1::Worker" and action "create"
258[debug] [2e0c6872] 200 OK (0.039745s, 25.160/s)
259[info] [pid:8546] Establishing ws connection via ws://localhost:60651/api/v1/ws/1
260[debug] [c1bc89e0] GET "/api/v1/ws/1"
261[debug] [c1bc89e0] Routing to a callback
262[debug] [c1bc89e0] 302 Found (0.000643s, 1555.210/s)
263[debug] [f67f1f9b] GET "/ws/1"
264[debug] [f67f1f9b] Routing to controller "OpenQA::Shared::Controller::Auth" and action "check"
265[debug] [f67f1f9b] Routing to controller "OpenQA::WebSockets::Controller::Worker" and action "ws"
266[debug] [f67f1f9b] 101 Switching Protocols (0.001822s, 548.847/s)
267[info] [pid:8546] Registered and connected via websockets with openQA host http://localhost:60651 and worker ID 1
268[debug] [pid:8127] Received from worker "1" worker_status message "---
269status: free
270type: worker_status
271"
272[debug] [pid:8127] Updating worker seen from worker_status
273[debug] [pid:8127] Sent population to worker: { population => 1, type => "info" }
274[debug] [pid:8119] +=----------------=+
275[debug] [pid:8119] -> Scheduling new jobs.
276[debug] [pid:8119] Free workers: 1/1
277[debug] [pid:8119] Scheduled jobs: 1
278[debug] [pid:8119] need to schedule 1 jobs for 4(50)
279[debug] [pid:8119] [Job#4] Prepare for being processed by worker 1
280[debug] [f9a05de1] POST "/api/send_job"
281[debug] [f9a05de1] Routing to controller "OpenQA::Shared::Controller::Auth" and action "check"
282[debug] [f9a05de1] Routing to controller "OpenQA::WebSockets::Controller::API" and action "send_job"
283[debug] [pid:8127] Started to send message to 1 for job 4
284[debug] [f9a05de1] 200 OK (0.001602s, 624.220/s)
285[debug] [pid:8119] Sent job(s) '4' to worker '1'
286[debug] [pid:8119] Job '4' has worker '1' assigned
287[debug] [pid:8119] Scheduler took 0.10445s to perform operations and allocated 1 jobs
288[debug] [pid:8119] Allocated: { job => 4, worker => 1 }
289[debug] [pid:8546] Accepting job 4 from http://localhost:60651.
290[debug] [pid:8546] Setting job 4 from http://localhost:60651 up
291[debug] [pid:8546] Preparing Mojo::IOLoop::ReadWriteProcess::Session
292[info] [pid:8546] +++ setup notes +++
293[info] [pid:8546] Start time: 2019-11-12 12:12:08
294[info] [pid:8546] Running on ac31197ebdb5:1 (Linux 4.15.0-1043-aws #45-Ubuntu SMP Mon Jun 24 14:07:03 UTC 2019 x86_64)
295[debug] [pid:8546] Job settings:
296[debug] [pid:8546]
297 ARCH=i386
298 BUILD=1
299 CDMODEL=ide-cd
300 DISTRI=tinycore
301 FLAVOR=flavor
302 HDDMODEL=ide-drive
303 HDD_1=nihilist_disk.hda
304 INTEGRATION_TESTS=1
305 ISO=Core-7.2.iso
306 JOBTOKEN=qUTGULQyqzrHve8M
307 LOG_LEVEL=debug
308 MACHINE=noassets
309 NAME=00000004-tinycore-1-flavor-i386-Build1-core@noassets
310 OPENQA_HOSTNAME=localhost:60651
311 OPENQA_URL=http://localhost:60651
312 PRJDIR=/tmp/VDZMlESezv/t/full-stack.d/openqa/share
313 PUBLISH_HDD_1=core-hdd.qcow2
314 QEMU=i386
315 QEMUPORT=20012
316 QEMU_NO_FDC_SET=1
317 QEMU_NO_KVM=1
318 QEMU_NO_TABLET=1
319 RETRY_DELAY=5
320 RETRY_DELAY_IF_WEBUI_BUSY=60
321 TEST=core
322 UEFI_PFLASH_VARS=/usr/share/qemu/ovmf-x86_64.bin
323 VERSION=1
324 VNC=91
325 WORKER_CLASS=qemu_i386,qemu_x86_64
326 WORKER_HOSTNAME=127.0.0.1
327 WORKER_ID=1
328 WORKER_INSTANCE=1
329[error] [pid:8546] HDD_1 handling Cannot find HDD_1 asset hdd/nihilist_disk.hda!
330[error] [pid:8546] Unable to setup job 4: Cannot find HDD_1 asset hdd/nihilist_disk.hda!
331[debug] [pid:8546] Stopping job 4 from http://localhost:60651: 00000004-tinycore-1-flavor-i386-Build1-core@noassets - reason: setup failure
332[debug] [pid:8546] REST-API call: POST http://localhost:60651/api/v1/jobs/4/status
333[debug] [pid:8127] Worker 1 accepted job 4
334[debug] [5745d23e] POST "/api/v1/jobs/4/status"
335[debug] [5745d23e] Routing to controller "OpenQA::WebAPI::Controller::API::V1" and action "auth_operator"
336[debug] API key from client: *1234567890ABCDEF*
337[debug] Key is for user 'Demo'
338[debug] API auth by user: Demo, operator: 1
339[debug] [5745d23e] Routing to controller "OpenQA::WebAPI::Controller::API::V1::Job" and action "update_status"
340[debug] [5745d23e] 200 OK (0.016478s, 60.687/s)
341[info] [pid:8546] +++ worker notes +++
342[info] [pid:8546] End time: 2019-11-12 12:12:08
343[info] [pid:8546] Result: setup failure
344[info] [pid:8552] Uploading autoinst-log.txt
345[debug] [65b07470] POST "/api/v1/jobs/4/artefact"
346[debug] [65b07470] Routing to controller "OpenQA::WebAPI::Controller::API::V1" and action "auth_operator"
347[debug] API key from client: *1234567890ABCDEF*
348[debug] Key is for user 'Demo'
349[debug] API auth by user: Demo, operator: 1
350[debug] [65b07470] Routing to controller "OpenQA::WebAPI::Controller::API::V1::Job" and action "create_artefact"
351[debug] [pid:8128] moved to /tmp/VDZMlESezv/t/full-stack.d/openqa/testresults/00000/00000004-tinycore-1-flavor-i386-Build1-core@noassets autoinst-log.txt
352[debug] [65b07470] 200 OK (0.016927s, 59.077/s)
353[info] [pid:8552] Uploading worker-log.txt
354[debug] [e242a373] POST "/api/v1/jobs/4/artefact"
355[debug] [e242a373] Routing to controller "OpenQA::WebAPI::Controller::API::V1" and action "auth_operator"
356[debug] API key from client: *1234567890ABCDEF*
357[debug] Key is for user 'Demo'
358[debug] API auth by user: Demo, operator: 1
359[debug] [e242a373] Routing to controller "OpenQA::WebAPI::Controller::API::V1::Job" and action "create_artefact"
360[debug] [pid:8128] moved to /tmp/VDZMlESezv/t/full-stack.d/openqa/testresults/00000/00000004-tinycore-1-flavor-i386-Build1-core@noassets worker-log.txt
361[debug] [e242a373] 200 OK (0.013495s, 74.102/s)
362[debug] [pid:8546] Job 4 stopped as incomplete
363[warn] [pid:8546] Unable to upload results of the job because no command server URL or worker ID have been set.
364[debug] [pid:8546] REST-API call: POST http://localhost:60651/api/v1/jobs/4/set_done?result=incomplete
365[debug] [951a3b77] POST "/api/v1/jobs/4/set_done"
366[debug] [951a3b77] Routing to controller "OpenQA::WebAPI::Controller::API::V1" and action "auth_operator"
367[debug] API key from client: *1234567890ABCDEF*
368[debug] Key is for user 'Demo'
369[debug] API auth by user: Demo, operator: 1
370[debug] [951a3b77] Routing to controller "OpenQA::WebAPI::Controller::API::V1::Job" and action "done"
371[debug] [951a3b77] 200 OK (0.035516s, 28.156/s)
372[debug] [pid:8546] Job 4 from http://localhost:60651 finished - reason: setup failure
373[debug] [pid:8546] Cleaning up for next job
374[warn] [pid:8546] Ignoring WS message from http://localhost:60651 with type livelog_stop and job ID 2 (currently not executing a job):
375{ jobid => 2, type => "livelog_stop" }
376[debug] [24c3eb1b] GET "/tests/4/status"
377[debug] [24c3eb1b] Routing to controller "OpenQA::WebAPI::Controller::Test" and action "referer_check"
378[debug] [pid:8128] Unrecognized referer 'localhost'
379[debug] [24c3eb1b] Routing to controller "OpenQA::WebAPI::Controller::Running" and action "status"
380[debug] [24c3eb1b] 200 OK (0.007877s, 126.952/s)
381[debug] [3f5a3bbe] GET "/tests/4"
382[debug] [3f5a3bbe] Routing to controller "OpenQA::WebAPI::Controller::Test" and action "referer_check"
383[debug] [pid:8128] Unrecognized referer 'localhost'
384[debug] [3f5a3bbe] Routing to controller "OpenQA::WebAPI::Controller::Test" and action "show"
385[debug] [3f5a3bbe] Rendering cached template "test/result.html.ep"
386[debug] [3f5a3bbe] Rendering cached template "layouts/info.html.ep"
387[debug] [3f5a3bbe] Rendering cached template "test/infopanel.html.ep"
388[debug] [3f5a3bbe] Rendering cached template "test/details.html.ep"
389[debug] [3f5a3bbe] Rendering cached template "test/downloads.html.ep"
390[debug] [3f5a3bbe] Rendering cached template "test/settings.html.ep"
391[debug] [3f5a3bbe] Rendering cached template "test/comments.html.ep"
392[debug] [3f5a3bbe] Rendering cached template "comments/comment_row.html.ep"
393[debug] [3f5a3bbe] Rendering cached template "comments/add_comment_form_groups.html.ep"
394[debug] [3f5a3bbe] Rendering cached template "test/job_next_previous.html.ep"
395[debug] [3f5a3bbe] Rendering cached template "layouts/bootstrap.html.ep"
396[debug] [3f5a3bbe] Rendering cached template "layouts/navbar.html.ep"
397[debug] [3f5a3bbe] Template "branding/openSUSE/links_footer_left.html.ep" not found
398[debug] [3f5a3bbe] Template "branding/plain/links_footer_left.html.ep" not found
399[debug] [3f5a3bbe] Template "branding/openSUSE/links_footer_right.html.ep" not found
400[debug] [3f5a3bbe] Template "branding/plain/links_footer_right.html.ep" not found
401[debug] [3f5a3bbe] 200 OK (0.078371s, 12.760/s)
402ok 40 - Test 4 crashed as expected
403ok 41 - Test 4 autoinst-log.txt file created
404ok 42 - Test 4 result correct: setup failure
405ok 43 - Test 4 correct autoinst setup notes
406ok 44 - Test 4: upload of autoinst-log.txt logged
407[info] [pid:8546] Quit due to signal TERM
408[info] [pid:8127] Worker 1 websocket connection closed - 1006
409ok 45 - WORKER is done
410ok 46 - Setting up Cache directory
411ok 47 - Config file created.
412# Subtest: Cache tests
413 ok 1 - cache.sqlite is not present
414[info] [pid:8561] OpenQA::CacheService::Model::Cache: loading database from /tmp/VDZMlESezv/t/full-stack.d/cache/cache.sqlite
415[info] [pid:8561] Creating cache directory tree for /tmp/VDZMlESezv/t/full-stack.d/cache
416[debug] [pid:8561] CACHE: Health: Real size: 0, Configured limit: 53687091200
417[info] [pid:8561] OpenQA::CacheService::Model::Cache: Initialized with localhost at /tmp/VDZMlESezv/t/full-stack.d/cache, current size is 0
418<7>[8561] [d] Starting cache service: t/full-stack.t minion worker -j 5
419<6>[8561] [i] Worker 8561 started
420<6>[8561] [i] Worker 8561 stopped
421[info] [pid:8563] OpenQA::CacheService::Model::Cache: loading database from /tmp/VDZMlESezv/t/full-stack.d/cache/cache.sqlite
422[info] [pid:8562] OpenQA::CacheService::Model::Cache: loading database from /tmp/VDZMlESezv/t/full-stack.d/cache/cache.sqlite
423[debug] [pid:8563] CACHE: Health: Real size: 0, Configured limit: 53687091200
424[info] [pid:8563] OpenQA::CacheService::Model::Cache: Initialized with localhost at /tmp/VDZMlESezv/t/full-stack.d/cache, current size is 0
425[debug] [pid:8562] CACHE: Health: Real size: 0, Configured limit: 53687091200
426[info] [pid:8562] OpenQA::CacheService::Model::Cache: Initialized with localhost at /tmp/VDZMlESezv/t/full-stack.d/cache, current size is 0
427<7>[8563] [d] Starting cache service: t/full-stack.t daemon -l http://*:7844
428<7>[8562] [d] Starting cache service: t/full-stack.t minion worker -j 5
429<6>[8562] [i] Worker 8562 started
430[info] [pid:8564] OpenQA::CacheService::Model::Cache: loading database from /tmp/VDZMlESezv/t/full-stack.d/cache/cache.sqlite
431[debug] [pid:8564] CACHE: Health: Real size: 0, Configured limit: 53687091200
432[info] [pid:8564] OpenQA::CacheService::Model::Cache: Initialized with localhost at /tmp/VDZMlESezv/t/full-stack.d/cache, current size is 0
433<7>[8564] [d] Starting cache service: t/full-stack.t daemon -l http://*:7844
434 # Waiting for cache service to be available
435<7>[8564] [d] [bd45bd4f] GET "/info"
436<7>[8564] [d] [bd45bd4f] Routing to controller "OpenQA::CacheService::Controller::API" and action "info"
437<7>[8564] [d] [bd45bd4f] 200 OK (0.004424s, 226.040/s)
438<7>[8564] [d] [3bd0bb46] GET "/info"
439<7>[8564] [d] [3bd0bb46] Routing to controller "OpenQA::CacheService::Controller::API" and action "info"
440<7>[8564] [d] [3bd0bb46] 200 OK (0.000887s, 1127.396/s)
441[debug] [73dda28d] POST "/api/v1/jobs/3/restart"
442[debug] [73dda28d] Routing to controller "OpenQA::WebAPI::Controller::API::V1" and action "auth_operator"
443[debug] API key from client: *1234567890ABCDEF*
444[debug] Key is for user 'Demo'
445[debug] API auth by user: Demo, operator: 1
446[debug] [73dda28d] Routing to controller "OpenQA::WebAPI::Controller::API::V1::Job" and action "restart"
447[debug] Restarting job 3
448[debug] [pid:8128] Jobs to duplicate {
449 3 => {
450 chained_children => [],
451 chained_parents => [],
452 directly_chained_children => [],
453 directly_chained_parents => [],
454 parallel_children => [],
455 parallel_parents => [],
456 },
457}
458[debug] [pid:8128] new job 5
459[debug] [73dda28d] 200 OK (0.100732s, 9.927/s)
460 ok 2 - client returned new test_url
461[debug] [2389c746] GET "/tests/5"
462[debug] [2389c746] Routing to controller "OpenQA::WebAPI::Controller::Test" and action "referer_check"
463[debug] [2389c746] Routing to controller "OpenQA::WebAPI::Controller::Test" and action "show"
464[debug] [2389c746] Rendering cached template "test/result.html.ep"
465[debug] [2389c746] Rendering cached template "layouts/info.html.ep"
466[debug] [2389c746] Rendering cached template "test/infopanel.html.ep"
467[debug] [2389c746] Rendering cached template "test/details.html.ep"
468[debug] [2389c746] Rendering cached template "test/downloads.html.ep"
469[debug] [2389c746] Rendering cached template "test/settings.html.ep"
470[debug] [2389c746] Rendering cached template "test/comments.html.ep"
471[debug] [2389c746] Rendering cached template "comments/comment_row.html.ep"
472[debug] [2389c746] Rendering cached template "comments/add_comment_form_groups.html.ep"
473[debug] [2389c746] Rendering cached template "test/job_next_previous.html.ep"
474[debug] [2389c746] Rendering cached template "layouts/bootstrap.html.ep"
475[debug] [2389c746] Rendering cached template "layouts/navbar.html.ep"
476[debug] [2389c746] Template "branding/openSUSE/links_footer_left.html.ep" not found
477[debug] [2389c746] Template "branding/plain/links_footer_left.html.ep" not found
478[debug] [2389c746] Template "branding/openSUSE/links_footer_right.html.ep" not found
479[debug] [2389c746] Template "branding/plain/links_footer_right.html.ep" not found
480[debug] [2389c746] 200 OK (0.068731s, 14.549/s)
481 ok 3 - test 5 is scheduled
482 ok 4 - Worker started as 8567
483[info] [pid:8567] worker 1:
484 - config file: /tmp/VDZMlESezv/t/full-stack.d/config/workers.ini
485 - worker hostname: ac31197ebdb5
486 - isotovideo version: 18
487 - websocket API version: 1
488 - web UI hosts: http://localhost:60651
489 - class: qemu_i386,qemu_x86_64
490 - no cleanup: no
491 - pool directory: /tmp/VDZMlESezv/t/full-stack.d/openqa/pool/1
492<7>[8564] [d] [6000761d] GET "/info"
493<7>[8564] [d] [6000761d] Routing to controller "OpenQA::CacheService::Controller::API" and action "info"
494<7>[8564] [d] [6000761d] 200 OK (0.000939s, 1064.963/s)
495[info] [pid:8567] CACHE: caching is enabled, setting up /tmp/VDZMlESezv/t/full-stack.d/cache/localhost
496[info] [pid:8567] Project dir for host http://localhost:60651 is /tmp/VDZMlESezv/t/full-stack.d/openqa/share
497[info] [pid:8567] Registering with openQA http://localhost:60651
498[debug] [65253e17] POST "/api/v1/workers"
499[debug] [65253e17] Routing to controller "OpenQA::WebAPI::Controller::API::V1" and action "auth_operator"
500[debug] API key from client: *1234567890ABCDEF*
501[debug] Key is for user 'Demo'
502[debug] API auth by user: Demo, operator: 1
503[debug] [65253e17] Routing to controller "OpenQA::WebAPI::Controller::API::V1::Worker" and action "create"
504[debug] [65253e17] 200 OK (0.040802s, 24.509/s)
505[info] [pid:8567] Establishing ws connection via ws://localhost:60651/api/v1/ws/1
506[debug] [7304dbf1] GET "/api/v1/ws/1"
507[debug] [7304dbf1] Routing to a callback
508[debug] [7304dbf1] 302 Found (0.000654s, 1529.052/s)
509[debug] [5d949319] GET "/ws/1"
510[debug] [5d949319] Routing to controller "OpenQA::Shared::Controller::Auth" and action "check"
511[debug] [5d949319] Routing to controller "OpenQA::WebSockets::Controller::Worker" and action "ws"
512[debug] [5d949319] 101 Switching Protocols (0.00152s, 657.895/s)
513<7>[8564] [d] [c2725f60] GET "/info"
514<7>[8564] [d] [c2725f60] Routing to controller "OpenQA::CacheService::Controller::API" and action "info"
515<7>[8564] [d] [c2725f60] 200 OK (0.000976s, 1024.590/s)
516[info] [pid:8567] Registered and connected via websockets with openQA host http://localhost:60651 and worker ID 1
517[debug] [pid:8127] Received from worker "1" worker_status message "---
518status: free
519type: worker_status
520"
521[debug] [pid:8127] Updating worker seen from worker_status
522[debug] [pid:8127] Sent population to worker: { population => 1, type => "info" }
523[debug] [pid:8119] +=----------------=+
524[debug] [pid:8119] -> Scheduling new jobs.
525[debug] [pid:8119] Free workers: 1/1
526[debug] [pid:8119] Scheduled jobs: 1
527[debug] [pid:8119] need to schedule 1 jobs for 5(50)
528[debug] [pid:8119] [Job#5] Prepare for being processed by worker 1
529[debug] [a80401e4] POST "/api/send_job"
530[debug] [a80401e4] Routing to controller "OpenQA::Shared::Controller::Auth" and action "check"
531[debug] [a80401e4] Routing to controller "OpenQA::WebSockets::Controller::API" and action "send_job"
532[debug] [pid:8127] Started to send message to 1 for job 5
533[debug] [a80401e4] 200 OK (0.001733s, 577.034/s)
534[debug] [pid:8119] Sent job(s) '5' to worker '1'
535[debug] [pid:8567] Accepting job 5 from http://localhost:60651.
536[debug] [pid:8567] Setting job 5 from http://localhost:60651 up
537[debug] [pid:8567] Preparing Mojo::IOLoop::ReadWriteProcess::Session
538[info] [pid:8567] +++ setup notes +++
539[info] [pid:8567] Start time: 2019-11-12 12:12:36
540[info] [pid:8567] Running on ac31197ebdb5:1 (Linux 4.15.0-1043-aws #45-Ubuntu SMP Mon Jun 24 14:07:03 UTC 2019 x86_64)
541[debug] [pid:8567] Job settings:
542[debug] [pid:8567]
543 ARCH=i386
544 BUILD=1
545 CACHEDIRECTORY=/tmp/VDZMlESezv/t/full-stack.d/cache
546 CACHELIMIT=50
547 CDMODEL=ide-cd
548 DISTRI=tinycore
549 FLAVOR=flavor
550 HDDMODEL=ide-drive
551 INTEGRATION_TESTS=1
552 ISO=Core-7.2.iso
553 JOBTOKEN=uJM94m5G_G9Mttri
554 LOG_LEVEL=debug
555 MACHINE=coolone
556 NAME=00000005-tinycore-1-flavor-i386-Build1-core@coolone
557 OPENQA_HOSTNAME=localhost:60651
558 OPENQA_URL=http://localhost:60651
559 PRJDIR=/tmp/VDZMlESezv/t/full-stack.d/openqa/share
560 PUBLISH_HDD_1=core-hdd.qcow2
561 QEMU=i386
562 QEMUPORT=20012
563 QEMU_NO_FDC_SET=1
564 QEMU_NO_KVM=1
565 QEMU_NO_TABLET=1
566 RETRY_DELAY=5
567 RETRY_DELAY_IF_WEBUI_BUSY=60
568 TEST=core
569 UEFI_PFLASH_VARS=/usr/share/qemu/ovmf-x86_64.bin
570 VERSION=1
571 VNC=91
572 WORKER_CLASS=qemu_i386,qemu_x86_64
573 WORKER_ID=1
574 WORKER_INSTANCE=1
575[debug] [pid:8567] Found ISO, caching Core-7.2.iso
576<7>[8564] [d] [18d66c72] GET "/info"
577<7>[8564] [d] [18d66c72] Routing to controller "OpenQA::CacheService::Controller::API" and action "info"
578<7>[8564] [d] [18d66c72] 200 OK (0.000965s, 1036.269/s)
579[debug] [pid:8119] Job '5' has worker '1' assigned
580[debug] [pid:8119] Scheduler took 0.07994s to perform operations and allocated 1 jobs
581[debug] [pid:8119] Allocated: { job => 5, worker => 1 }
582<7>[8564] [d] [2ba6c568] POST "/enqueue"
583<7>[8564] [d] [2ba6c568] Routing to controller "OpenQA::CacheService::Controller::API" and action "enqueue"
584<7>[8564] [d] Requested [cache_asset] Args: 5 iso Core-7.2.iso http://localhost:60651 Lock: Core-7.2.iso.http://localhost:60651
585<7>[8564] [d] [2ba6c568] 200 OK (0.001577s, 634.115/s)
586[debug] [pid:8567] Downloading Core-7.2.iso, request sent to Cache Service (1)
587<7>[8564] [d] [334b925e] GET "/status/1"
588<7>[8564] [d] [334b925e] Routing to controller "OpenQA::CacheService::Controller::API" and action "status"
589<7>[8564] [d] [334b925e] 200 OK (0.002067s, 483.793/s)
590<7>[8562] [d] Process 8573 is performing job "1" with task "cache_asset"
591[info] [pid:8573] OpenQA::CacheService::Model::Cache: loading database from /tmp/VDZMlESezv/t/full-stack.d/cache/cache.sqlite
592[debug] [pid:8573] CACHE: Health: Real size: 0, Configured limit: 53687091200
593[info] [pid:8573] OpenQA::CacheService::Model::Cache: Initialized with localhost at /tmp/VDZMlESezv/t/full-stack.d/cache, current size is 0
594<7>[8573] [d] [Job #1] Download: Core-7.2.iso
595[debug] [46f2fd6e] GET "/tests/5/asset/iso/Core-7.2.iso"
596[debug] [46f2fd6e] Routing to controller "OpenQA::WebAPI::Controller::Test" and action "referer_check"
597[debug] [46f2fd6e] Routing to controller "OpenQA::WebAPI::Controller::File" and action "test_asset"
598[debug] redirect to /assets/iso/Core-7.2.iso
599[debug] [46f2fd6e] 302 Found (0.014413s, 69.382/s)
600[debug] [55a5197c] GET "/assets/iso/Core-7.2.iso"
601[debug] [55a5197c] Routing to controller "OpenQA::WebAPI::Controller::File" and action "download_asset"
602[debug] [55a5197c] 200 OK (0.00151s, 662.252/s)
603<7>[8573] [d] [Job #1] Finished
604[debug] [pid:8567] Updating status so job 5 is not considered dead.
605[debug] [pid:8567] REST-API call: POST http://localhost:60651/api/v1/jobs/5/status
606[debug] [c7da8639] POST "/api/v1/jobs/5/status"
607[debug] [c7da8639] Routing to controller "OpenQA::WebAPI::Controller::API::V1" and action "auth_operator"
608[debug] API key from client: *1234567890ABCDEF*
609[debug] Key is for user 'Demo'
610[debug] API auth by user: Demo, operator: 1
611[debug] [c7da8639] Routing to controller "OpenQA::WebAPI::Controller::API::V1::Job" and action "update_status"
612[debug] [c7da8639] 200 OK (0.037062s, 26.982/s)
613<7>[8564] [d] [f67f1f9b] GET "/status/1"
614<7>[8564] [d] [f67f1f9b] Routing to controller "OpenQA::CacheService::Controller::API" and action "status"
615<7>[8564] [d] [f67f1f9b] 200 OK (0.001645s, 607.903/s)
616[debug] [98b9fb03] GET "/tests/5/status"
617[debug] [98b9fb03] Routing to controller "OpenQA::WebAPI::Controller::Test" and action "referer_check"
618[debug] [pid:8128] Unrecognized referer 'localhost'
619[debug] [98b9fb03] Routing to controller "OpenQA::WebAPI::Controller::Running" and action "status"
620[debug] [98b9fb03] 200 OK (0.014828s, 67.440/s)
621[debug] [e7d42022] GET "/tests/5"
622[debug] [e7d42022] Routing to controller "OpenQA::WebAPI::Controller::Test" and action "referer_check"
623[debug] [pid:8128] Unrecognized referer 'localhost'
624[debug] [e7d42022] Routing to controller "OpenQA::WebAPI::Controller::Test" and action "show"
625[debug] [e7d42022] Rendering cached template "test/result.html.ep"
626[debug] [e7d42022] Rendering cached template "layouts/info.html.ep"
627[debug] [e7d42022] Rendering cached template "test/infopanel.html.ep"
628[debug] [e7d42022] Rendering cached template "test/details.html.ep"
629[debug] [e7d42022] Rendering cached template "test/live.html.ep"
630[debug] [e7d42022] Rendering cached template "test/module_select.html.ep"
631[debug] [e7d42022] Rendering cached template "test/downloads.html.ep"
632[debug] [e7d42022] Rendering cached template "test/settings.html.ep"
633[debug] [e7d42022] Rendering cached template "test/comments.html.ep"
634[debug] [e7d42022] Rendering cached template "comments/comment_row.html.ep"
635[debug] [e7d42022] Rendering cached template "comments/add_comment_form_groups.html.ep"
636[debug] [e7d42022] Rendering cached template "test/job_next_previous.html.ep"
637[debug] [e7d42022] Rendering cached template "layouts/bootstrap.html.ep"
638[debug] [e7d42022] Rendering cached template "layouts/navbar.html.ep"
639[debug] [e7d42022] Template "branding/openSUSE/links_footer_left.html.ep" not found
640[debug] [e7d42022] Template "branding/plain/links_footer_left.html.ep" not found
641[debug] [e7d42022] Template "branding/openSUSE/links_footer_right.html.ep" not found
642[debug] [e7d42022] Template "branding/plain/links_footer_right.html.ep" not found
643[debug] [e7d42022] 200 OK (0.119988s, 8.334/s)
644[debug] [9c74365c] GET "/tests/5/status"
645[debug] [9c74365c] Routing to controller "OpenQA::WebAPI::Controller::Test" and action "referer_check"
646[debug] [pid:8128] Unrecognized referer 'localhost'
647[debug] [9c74365c] Routing to controller "OpenQA::WebAPI::Controller::Running" and action "status"
648[debug] [9c74365c] 200 OK (0.011258s, 88.826/s)
649 ok 5 - job is running
650[debug] [6000761d] GET "/liveviewhandler/tests/5/developer/ws-proxy/status"
651[debug] [6000761d] Routing to controller "OpenQA::WebAPI::Controller::Test" and action "referer_check"
652[debug] [6000761d] Routing to controller "OpenQA::WebAPI::Controller::LiveViewHandler" and action "proxy_status"
653 ok 6 - cache.sqlite file created
654 ok 7 - Directory within cache, not present after deploy
655 ok 8 - File within cache, not present after deploy
656[2019-11-12T12:12:36.0677 UTC] [info] [pid:8567] +++ setup notes +++
657[2019-11-12T12:12:36.0678 UTC] [info] [pid:8567] Start time: 2019-11-12 12:12:36
658[2019-11-12T12:12:36.0678 UTC] [info] [pid:8567] Running on ac31197ebdb5:1 (Linux 4.15.0-1043-aws #45-Ubuntu SMP Mon Jun 24 14:07:03 UTC 2019 x86_64)
659[2019-11-12T12:12:36.0689 UTC] [debug] [pid:8567] Downloading Core-7.2.iso, request sent to Cache Service (1)
660[2019-11-12T12:12:36.0677 UTC] [debug] [pid:8567] Preparing Mojo::IOLoop::ReadWriteProcess::Session
661[2019-11-12T12:12:36.0678 UTC] [debug] [pid:8567] Job settings:
662[2019-11-12T12:12:36.0678 UTC] [debug] [pid:8567]
663 ARCH=i386
664 BUILD=1
665 CACHEDIRECTORY=/tmp/VDZMlESezv/t/full-stack.d/cache
666 CACHELIMIT=50
667 CDMODEL=ide-cd
668 DISTRI=tinycore
669 FLAVOR=flavor
670 HDDMODEL=ide-drive
671 INTEGRATION_TESTS=1
672 ISO=Core-7.2.iso
673 JOBTOKEN=uJM94m5G_G9Mttri
674 LOG_LEVEL=debug
675 MACHINE=coolone
676 NAME=00000005-tinycore-1-flavor-i386-Build1-core@coolone
677 OPENQA_HOSTNAME=localhost:60651
678 OPENQA_URL=http://localhost:60651
679 PRJDIR=/tmp/VDZMlESezv/t/full-stack.d/openqa/share
680 PUBLISH_HDD_1=core-hdd.qcow2
681 QEMU=i386
682 QEMUPORT=20012
683 QEMU_NO_FDC_SET=1
684 QEMU_NO_KVM=1
685 QEMU_NO_TABLET=1
686 RETRY_DELAY=5
687 RETRY_DELAY_IF_WEBUI_BUSY=60
688 TEST=core
689 UEFI_PFLASH_VARS=/usr/share/qemu/ovmf-x86_64.bin
690 VERSION=1
691 VNC=91
692 WORKER_CLASS=qemu_i386,qemu_x86_64
693 WORKER_ID=1
694 WORKER_INSTANCE=1
695[2019-11-12T12:12:36.0678 UTC] [debug] [pid:8567] Found ISO, caching Core-7.2.iso
696[2019-11-12T12:12:41.0695 UTC] [debug] [pid:8567] Updating status so job 5 is not considered dead.
697[2019-11-12T12:12:41.0695 UTC] [debug] [pid:8567] REST-API call: POST http://localhost:60651/api/v1/jobs/5/status
698 1..8
699ok 48 - Cache tests
700Can't readlink('/tmp/VDZMlESezv/t/full-stack.d/openqa/pool/1/Core-7.2.iso'): No such file or directory at t/full-stack.t line 363
701[debug] [6a02a994] GET "/tests/5/streaming"
702[debug] [6a02a994] Routing to controller "OpenQA::WebAPI::Controller::Test" and action "referer_check"
703[debug] [pid:8128] Unrecognized referer 'localhost'
704[debug] [6a02a994] Routing to controller "OpenQA::WebAPI::Controller::Running" and action "streaming"
705[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
706[debug] [6000761d] 101 Switching Protocols (0.016419s, 60.905/s)
707[debug] [pid:8128] Asking the worker to start providing livestream
708[debug] [366948da] POST "/api/send_msg"
709[debug] [366948da] Routing to controller "OpenQA::Shared::Controller::Auth" and action "check"
710[debug] [366948da] Routing to controller "OpenQA::WebSockets::Controller::API" and action "send_msg"
711[debug] [366948da] 200 OK (0.002249s, 444.642/s)
712[debug] [pid:8128] Asking the worker to stop providing livestream
713[debug] [66fe17a1] POST "/api/send_msg"
714[debug] [66fe17a1] Routing to controller "OpenQA::Shared::Controller::Auth" and action "check"
715[debug] [66fe17a1] Routing to controller "OpenQA::WebSockets::Controller::API" and action "send_msg"
716[debug] [66fe17a1] 200 OK (0.001902s, 525.762/s)
717[info] [pid:8567] Quit due to signal TERM
718[debug] [pid:8567] Stopping job 5 from http://localhost:60651: 00000005-tinycore-1-flavor-i386-Build1-core@coolone - reason: quit
719[debug] [pid:8567] REST-API call: POST http://localhost:60651/api/v1/jobs/5/status
720[error] [pid:8567] REST-API error (POST http://localhost:60651/api/v1/jobs/5/status): Connection error: Connection refused (remaining tries: 2)
721[debug] [pid:8127] Worker 1 accepted job 5
722[error] [pid:8567] REST-API error (POST http://localhost:60651/api/v1/jobs/5/status): Connection error: Connection refused (remaining tries: 1)