- {"dt": "2022-08-22T09:06:44.481366", "lvl": "info", "msg": "lava-dispatcher, installed at version: 2022.06"}
- {"dt": "2022-08-22T09:06:44.481592", "lvl": "info", "msg": "start: 0 validate"}
- {"dt": "2022-08-22T09:06:44.481768", "lvl": "info", "msg": "Start time: 2022-08-22 09:06:44.481758+00:00 (UTC)"}
- {"dt": "2022-08-22T09:06:44.481964", "lvl": "debug", "msg": "Validating that https://artifactory.softwaretools.com/artifactory/9v3.7z exists"}
- {"dt": "2022-08-22T09:06:45.611426", "lvl": "warning", "msg": "WARNING: Using boot commands supplied in the job definition, NOT the LAVA device configuration"}
- {"dt": "2022-08-22T09:06:45.612385", "lvl": "info", "msg": "validate duration: 1.13"}
- {"dt": "2022-08-22T09:06:45.612602", "lvl": "results", "msg": {"case": "validate", "definition": "lava", "result": "pass"}}
- {"dt": "2022-08-22T09:06:45.612933", "lvl": "info", "msg": "start: 1 deploy-flasher-retry (timeout 00:10:00) [common]"}
- {"dt": "2022-08-22T09:06:45.613170", "lvl": "debug", "msg": "start: 1.1 deploy-flasher (timeout 00:10:00) [common]"}
- {"dt": "2022-08-22T09:06:45.613391", "lvl": "debug", "msg": "start: 1.1.1 download-retry (timeout 00:05:00) [common]"}
- {"dt": "2022-08-22T09:06:45.613608", "lvl": "debug", "msg": "start: 1.1.1.1 http-download (timeout 00:05:00) [common]"}
- {"dt": "2022-08-22T09:06:45.613928", "lvl": "info", "msg": "downloading https://artifactory.softwaretools.artifactory/9v3.7z"}
- {"dt": "2022-08-22T09:06:45.614105", "lvl": "debug", "msg": "saving as /var/lib/lava/dispatcher/tmp/466/deploy-flasher-p2k8tvri/package/mfgtools-9v3.7z"}
- {"dt": "2022-08-22T09:06:45.614263", "lvl": "debug", "msg": "total size: 495420408 (472MB)"}
- {"dt": "2022-08-22T09:06:45.614420", "lvl": "debug", "msg": "No compression specified"}
- {"dt": "2022-08-22T09:06:46.976077", "lvl": "debug", "msg": "progress   0% (0MB)"}
- {"dt": "2022-08-22T09:06:51.768407", "lvl": "debug", "msg": "progress   5% (23MB)"}
- {"dt": "2022-08-22T09:06:55.153605", "lvl": "debug", "msg": "progress  10% (47MB)"}
- {"dt": "2022-08-22T09:06:58.250845", "lvl": "debug", "msg": "progress  15% (70MB)"}
- {"dt": "2022-08-22T09:07:01.492551", "lvl": "debug", "msg": "progress  20% (94MB)"}
- {"dt": "2022-08-22T09:07:04.522488", "lvl": "debug", "msg": "progress  25% (118MB)"}
- {"dt": "2022-08-22T09:07:07.387287", "lvl": "debug", "msg": "progress  30% (141MB)"}
- {"dt": "2022-08-22T09:07:09.758578", "lvl": "debug", "msg": "progress  35% (165MB)"}
- {"dt": "2022-08-22T09:07:11.776765", "lvl": "debug", "msg": "progress  40% (189MB)"}
- {"dt": "2022-08-22T09:07:13.615094", "lvl": "debug", "msg": "progress  45% (212MB)"}
- {"dt": "2022-08-22T09:07:15.621909", "lvl": "debug", "msg": "progress  50% (236MB)"}
- {"dt": "2022-08-22T09:07:20.208624", "lvl": "debug", "msg": "progress  55% (259MB)"}
- {"dt": "2022-08-22T09:07:24.544387", "lvl": "debug", "msg": "progress  60% (283MB)"}
- {"dt": "2022-08-22T09:07:28.736592", "lvl": "debug", "msg": "progress  65% (307MB)"}
- {"dt": "2022-08-22T09:07:32.630198", "lvl": "debug", "msg": "progress  70% (330MB)"}
- {"dt": "2022-08-22T09:07:35.815500", "lvl": "debug", "msg": "progress  75% (354MB)"}
- {"dt": "2022-08-22T09:07:38.202140", "lvl": "debug", "msg": "progress  80% (378MB)"}
- {"dt": "2022-08-22T09:07:40.171704", "lvl": "debug", "msg": "progress  85% (401MB)"}
- {"dt": "2022-08-22T09:07:42.053629", "lvl": "debug", "msg": "progress  90% (425MB)"}
- {"dt": "2022-08-22T09:07:43.927770", "lvl": "debug", "msg": "progress  95% (448MB)"}
- {"dt": "2022-08-22T09:07:45.797904", "lvl": "debug", "msg": "progress 100% (472MB)"}
- {"dt": "2022-08-22T09:07:45.798845", "lvl": "info", "msg": "472MB downloaded in 60.18s (7.85MB/s)"}
- {"dt": "2022-08-22T09:07:45.799231", "lvl": "debug", "msg": "end: 1.1.1.1 http-download (duration 00:01:00) [common]"}
- {"dt": "2022-08-22T09:07:45.799350", "lvl": "results", "msg": {"case": "http-download", "definition": "lava", "duration": "60.19", "extra": {"label": "package", "md5sum": "2c9650d5aaa2bbc99e72f36ee91b40c2", "sha256sum": "ad028fe0a70f410ab8cb0e066221bf702b2fdbdb40c9c12da08180172dc37ba5", "sha512sum": "0529ea078b2e58c7fbd47f1719160f209cd84ef68ff5a2c9786af1b10fd60ebb39a0713e79e0fda3feb5e5e3539630c38df0a10ea28f0d29b7976d085ce27ce0", "size": ! "495420408"}, "level": "1.1.1.1", "namespace": "common", "result": "pass"}}
- {"dt": "2022-08-22T09:07:45.799579", "lvl": "debug", "msg": "end: 1.1.1 download-retry (duration 00:01:00) [common]"}
- {"dt": "2022-08-22T09:07:45.799863", "lvl": "debug", "msg": "Calling: 'nice' 'flash' 'pk_raspi-unit1' '{package}'"}
- {"dt": "2022-08-22T09:07:45.809654", "lvl": "debug", "msg": ">> /var/lib/lava/dispatcher/tmp/466/deploy-flasher-p2k8tvri /var/lib/lava/dispatcher/tmp/466/deploy-flasher-p2k8tvri\r"}
- {"dt": "2022-08-22T09:07:45.811510", "lvl": "debug", "msg": ">> \r"}
- {"dt": "2022-08-22T09:07:45.811674", "lvl": "debug", "msg": ">> 7-Zip [64] 16.02 : Copyright (c) 1999-2016 Igor Pavlov : 2016-05-21\r"}
- {"dt": "2022-08-22T09:07:45.811955", "lvl": "debug", "msg": ">> p7zip Version 16.02 (locale=C.UTF-8,Utf16=on,HugeFiles=on,64 bits,8 CPUs Intel(R) Core(TM) i5-8265U CPU @ 1.60GHz (806EB),ASM,AES-NI)\r"}
- {"dt": "2022-08-22T09:07:45.812045", "lvl": "debug", "msg": ">> \r"}
- {"dt": "2022-08-22T09:07:45.812121", "lvl": "debug", "msg": ">> Scanning the drive for archives:\r"}
- {"dt": "2022-08-22T09:07:45.812195", "lvl": "debug", "msg": ">>   0M Scan\b\b\b\b\b\b\b\b\b         \b\b\b\b\b\b\b\b\b\r"}
- {"dt": "2022-08-22T09:07:45.812266", "lvl": "debug", "msg": ">> ERROR: No more files\r"}
- {"dt": "2022-08-22T09:07:45.812366", "lvl": "debug", "msg": ">> {package}\r"}
- {"dt": "2022-08-22T09:07:45.812434", "lvl": "debug", "msg": ">> \r"}
- {"dt": "2022-08-22T09:07:45.812712", "lvl": "debug", "msg": ">> \r"}
- {"dt": "2022-08-22T09:07:45.812790", "lvl": "debug", "msg": ">> \r"}
- {"dt": "2022-08-22T09:07:45.812860", "lvl": "debug", "msg": ">> System ERROR:\r"}
- {"dt": "2022-08-22T09:07:45.812929", "lvl": "debug", "msg": ">> Unknown error -2147024872\r"}
- {"dt": "2022-08-22T09:07:45.813221", "lvl": "debug", "msg": "Returned 2 in 0 seconds"}
- {"dt": "2022-08-22T09:07:45.813306", "lvl": "error", "msg": "Unable to run 'nice' '['flash', 'pk_raspi-unit1', '{package}']'"}
- {"dt": "2022-08-22T09:07:45.813411", "lvl": "exception", "msg": "Unable to flash the device"}
- {"dt": "2022-08-22T09:07:45.813503", "lvl": "debug", "msg": "end: 1.1 deploy-flasher (duration 00:01:00) [common]"}
- {"dt": "2022-08-22T09:07:45.813603", "lvl": "results", "msg": {"case": "deploy-flasher", "definition": "lava", "duration": "60.20", "extra": {"fail": "Unable to flash the device"}, "level": "1.1", "namespace": "common", "result": "fail"}}
- {"dt": "2022-08-22T09:07:45.813762", "lvl": "error", "msg": "deploy-flasher-retry failed: 1 of 1 attempts. 'Unable to flash the device'"}
- {"dt": "2022-08-22T09:07:45.813864", "lvl": "debug", "msg": "Cleaning up download directory: /var/lib/lava/dispatcher/tmp/466/deploy-flasher-p2k8tvri/package"}
- {"dt": "2022-08-22T09:07:45.854633", "lvl": "exception", "msg": "Unable to flash the device"}
- {"dt": "2022-08-22T09:07:45.854822", "lvl": "info", "msg": "end: 1 deploy-flasher-retry (duration 00:01:00) [common]"}
- {"dt": "2022-08-22T09:07:45.854963", "lvl": "results", "msg": {"case": "deploy-flasher-retry", "definition": "lava", "duration": "60.24", "extra": {"fail": "Unable to flash the device"}, "level": "1", "namespace": "common", "result": "fail"}}
- {"dt": "2022-08-22T09:07:45.855154", "lvl": "info", "msg": "Cleaning after the job"}
- {"dt": "2022-08-22T09:07:45.855403", "lvl": "debug", "msg": "start: 4.1 power-off (timeout 00:00:10) [common]"}
- {"dt": "2022-08-22T09:07:45.855597", "lvl": "debug", "msg": "Calling: 'nice' 'relay' 'pk_raspi-unit1' 'off'"}
- {"dt": "2022-08-22T09:07:45.859785", "lvl": "debug", "msg": ">> \e[32m*** RELAY 1 off!**** \e[0m\r"}
- {"dt": "2022-08-22T09:07:46.936053", "lvl": "debug", "msg": "Returned 0 in 1 seconds"}
- {"dt": "2022-08-22T09:07:47.038353", "lvl": "debug", "msg": "end: 4.1 power-off (duration 00:00:01) [common]"}
- {"dt": "2022-08-22T09:07:47.039261", "lvl": "results", "msg": {"case": "power-off", "definition": "lava", "duration": "1.18", "extra": {"status": "success"}, "level": "4.1", "namespace": "common", "result": "pass"}}
- {"dt": "2022-08-22T09:07:47.040507", "lvl": "debug", "msg": "start: 4.2 read-feedback (timeout 00:09:59) [common]"}
- {"dt": "2022-08-22T09:07:47.041138", "lvl": "debug", "msg": "No connection for namespace common"}
- {"dt": "2022-08-22T09:07:47.041852", "lvl": "debug", "msg": "end: 4.2 read-feedback (duration 00:00:00) [common]"}
- {"dt": "2022-08-22T09:07:47.042494", "lvl": "info", "msg": "Root tmp directory removed at /var/lib/lava/dispatcher/tmp/466"}
- {"dt": "2022-08-22T09:07:47.043494", "lvl": "error", "msg": "JobError: Your job cannot terminate cleanly."}
- {"dt": "2022-08-22T09:07:47.043688", "lvl": "results", "msg": {"case": "job", "definition": "lava", "error_msg": "Unable to flash the device", "error_type": "Job", "result": "fail"}}