- {"dt": "2023-11-04T08:05:43.358052", "lvl": "info", "msg": "lava-dispatcher, installed at version: 2023.01"}
- {"dt": "2023-11-04T08:05:43.359402", "lvl": "info", "msg": "start: 0 validate"}
- {"dt": "2023-11-04T08:05:43.360508", "lvl": "info", "msg": "Start time: 2023-11-04 08:05:43.360449+00:00 (UTC)"}
- {"dt": "2023-11-04T08:05:43.361606", "lvl": "debug", "msg": "Validating that https://github.com/montjoie/lava-healthchecks-binary/blob/master/images/rootfs/buildroot/kci-2019.02-11-g17e793fa4728/arm64/base/rootfs.cpio.gz?raw=true exists"}
- {"dt": "2023-11-04T08:05:45.159416", "lvl": "debug", "msg": "Validating that https://github.com/montjoie/lava-healthchecks-binary/blob/master/stable/linux-5.6.y/v5.6.12/arm64/defconfig/gcc-8/Image?raw=true exists"}
- {"dt": "2023-11-04T08:05:47.809125", "lvl": "debug", "msg": "Validating that https://github.com/montjoie/lava-healthchecks-binary/blob/master/stable/linux-5.6.y/v5.6.12/arm64/defconfig/gcc-8/dtbs/broadcom/bcm2711-rpi-4-b.dtb?raw=true exists"}
- {"dt": "2023-11-04T08:05:48.471876", "lvl": "debug", "msg": "Validating that https://github.com/montjoie/lava-healthchecks-binary/blob/master/stable/linux-5.6.y/v5.6.12/arm64/defconfig/gcc-8/modules.tar.xz?raw=true exists"}
- {"dt": "2023-11-04T08:05:50.086476", "lvl": "info", "msg": "validate duration: 6.73"}
- {"dt": "2023-11-04T08:05:50.087247", "lvl": "results", "msg": {"case": "validate", "definition": "lava", "result": "pass"}}
- {"dt": "2023-11-04T08:05:50.088287", "lvl": "info", "msg": "start: 1 tftp-deploy (timeout 00:10:00) [common]"}
- {"dt": "2023-11-04T08:05:50.089099", "lvl": "debug", "msg": "start: 1.1 download-retry (timeout 00:10:00) [common]"}
- {"dt": "2023-11-04T08:05:50.089803", "lvl": "debug", "msg": "start: 1.1.1 http-download (timeout 00:10:00) [common]"}
- {"dt": "2023-11-04T08:05:50.090692", "lvl": "debug", "msg": "Not decompressing ramdisk as can be used compressed."}
- {"dt": "2023-11-04T08:05:50.091469", "lvl": "info", "msg": "downloading https://github.com/montjoie/lava-healthchecks-binary/blob/master/images/rootfs/buildroot/kci-2019.02-11-g17e793fa4728/arm64/base/rootfs.cpio.gz?raw=true"}
- {"dt": "2023-11-04T08:05:50.091987", "lvl": "debug", "msg": "saving as /var/lib/lava/dispatcher/tmp/33268/tftp-deploy-zp4yljir/ramdisk/rootfs.cpio.gz"}
- {"dt": "2023-11-04T08:05:50.092495", "lvl": "debug", "msg": "total size: 4192947 (3MB)"}
- {"dt": "2023-11-04T08:05:51.090743", "lvl": "debug", "msg": "progress   0% (0MB)"}
- {"dt": "2023-11-04T08:05:51.126393", "lvl": "debug", "msg": "progress   5% (0MB)"}
- {"dt": "2023-11-04T08:05:51.144398", "lvl": "debug", "msg": "progress  10% (0MB)"}
- {"dt": "2023-11-04T08:05:51.159695", "lvl": "debug", "msg": "progress  15% (0MB)"}
- {"dt": "2023-11-04T08:05:51.174180", "lvl": "debug", "msg": "progress  20% (0MB)"}
- {"dt": "2023-11-04T08:05:51.186993", "lvl": "debug", "msg": "progress  25% (1MB)"}
- {"dt": "2023-11-04T08:05:51.201019", "lvl": "debug", "msg": "progress  30% (1MB)"}
- {"dt": "2023-11-04T08:05:51.212917", "lvl": "debug", "msg": "progress  35% (1MB)"}
- {"dt": "2023-11-04T08:05:51.226150", "lvl": "debug", "msg": "progress  40% (1MB)"}
- {"dt": "2023-11-04T08:05:51.238261", "lvl": "debug", "msg": "progress  45% (1MB)"}
- {"dt": "2023-11-04T08:05:51.250300", "lvl": "debug", "msg": "progress  50% (2MB)"}
- {"dt": "2023-11-04T08:05:51.264101", "lvl": "debug", "msg": "progress  55% (2MB)"}
- {"dt": "2023-11-04T08:05:51.276632", "lvl": "debug", "msg": "progress  60% (2MB)"}
- {"dt": "2023-11-04T08:05:51.291203", "lvl": "debug", "msg": "progress  65% (2MB)"}
- {"dt": "2023-11-04T08:05:51.304838", "lvl": "debug", "msg": "progress  70% (2MB)"}
- {"dt": "2023-11-04T08:05:51.317688", "lvl": "debug", "msg": "progress  75% (3MB)"}
- {"dt": "2023-11-04T08:05:51.329773", "lvl": "debug", "msg": "progress  80% (3MB)"}
- {"dt": "2023-11-04T08:05:51.339887", "lvl": "debug", "msg": "progress  85% (3MB)"}
- {"dt": "2023-11-04T08:05:51.350958", "lvl": "debug", "msg": "progress  90% (3MB)"}
- {"dt": "2023-11-04T08:05:51.360310", "lvl": "debug", "msg": "progress  95% (3MB)"}
- {"dt": "2023-11-04T08:05:51.369596", "lvl": "debug", "msg": "progress 100% (3MB)"}
- {"dt": "2023-11-04T08:05:51.371562", "lvl": "info", "msg": "3MB downloaded in 1.28s (3.13MB/s)"}
- {"dt": "2023-11-04T08:05:51.372849", "lvl": "debug", "msg": "end: 1.1.1 http-download (duration 00:00:01) [common]"}
- {"dt": "2023-11-04T08:05:51.373552", "lvl": "results", "msg": {"case": "http-download", "definition": "lava", "duration": "1.28", "extra": {"label": "ramdisk", "md5sum": "dc99d8359b36a4a5fd569a984bb84bdf", "sha256sum": "cc73f153f47870c8ec995a00a0ad2aec3f05b6d22fc90b37a61f5066faa1b684", "sha512sum": "8fc07bd282f59a659b6417e8faca6c464be64927ab091cb2a9908805d12a680377bb58c5e52a1ed4d877b6f68783c02335e94ecf2764f5198816d2afd293923a", "size": ! "4192947"}, "level": "1.1.1", "namespace": "common", "result": "pass"}}
- {"dt": "2023-11-04T08:05:51.375050", "lvl": "debug", "msg": "end: 1.1 download-retry (duration 00:00:01) [common]"}
- {"dt": "2023-11-04T08:05:51.375854", "lvl": "debug", "msg": "start: 1.2 download-retry (timeout 00:09:59) [common]"}
- {"dt": "2023-11-04T08:05:51.376698", "lvl": "debug", "msg": "start: 1.2.1 http-download (timeout 00:09:59) [common]"}
- {"dt": "2023-11-04T08:05:51.377785", "lvl": "info", "msg": "downloading https://github.com/montjoie/lava-healthchecks-binary/blob/master/stable/linux-5.6.y/v5.6.12/arm64/defconfig/gcc-8/Image?raw=true"}
- {"dt": "2023-11-04T08:05:51.378479", "lvl": "debug", "msg": "saving as /var/lib/lava/dispatcher/tmp/33268/tftp-deploy-zp4yljir/kernel/Image"}
- {"dt": "2023-11-04T08:05:51.379045", "lvl": "debug", "msg": "total size: 27247104 (25MB)"}
- {"dt": "2023-11-04T08:05:51.379597", "lvl": "debug", "msg": "No compression specified"}
- {"dt": "2023-11-04T08:05:53.366433", "lvl": "debug", "msg": "progress   0% (0MB)"}
- {"dt": "2023-11-04T08:05:53.446377", "lvl": "debug", "msg": "progress   5% (1MB)"}
- {"dt": "2023-11-04T08:05:53.523895", "lvl": "debug", "msg": "progress  10% (2MB)"}
- {"dt": "2023-11-04T08:05:53.603434", "lvl": "debug", "msg": "progress  15% (3MB)"}
- {"dt": "2023-11-04T08:05:53.681586", "lvl": "debug", "msg": "progress  20% (5MB)"}
- {"dt": "2023-11-04T08:05:53.758494", "lvl": "debug", "msg": "progress  25% (6MB)"}
- {"dt": "2023-11-04T08:05:53.836558", "lvl": "debug", "msg": "progress  30% (7MB)"}
- {"dt": "2023-11-04T08:05:53.912091", "lvl": "debug", "msg": "progress  35% (9MB)"}
- {"dt": "2023-11-04T08:05:53.984138", "lvl": "debug", "msg": "progress  40% (10MB)"}
- {"dt": "2023-11-04T08:05:54.064356", "lvl": "debug", "msg": "progress  45% (11MB)"}
- {"dt": "2023-11-04T08:05:54.139216", "lvl": "debug", "msg": "progress  50% (13MB)"}
- {"dt": "2023-11-04T08:05:54.215371", "lvl": "debug", "msg": "progress  55% (14MB)"}
- {"dt": "2023-11-04T08:05:54.292300", "lvl": "debug", "msg": "progress  60% (15MB)"}
- {"dt": "2023-11-04T08:05:54.368864", "lvl": "debug", "msg": "progress  65% (16MB)"}
- {"dt": "2023-11-04T08:05:54.446763", "lvl": "debug", "msg": "progress  70% (18MB)"}
- {"dt": "2023-11-04T08:05:54.523461", "lvl": "debug", "msg": "progress  75% (19MB)"}
- {"dt": "2023-11-04T08:05:54.601873", "lvl": "debug", "msg": "progress  80% (20MB)"}
- {"dt": "2023-11-04T08:05:54.676515", "lvl": "debug", "msg": "progress  85% (22MB)"}
- {"dt": "2023-11-04T08:05:54.753660", "lvl": "debug", "msg": "progress  90% (23MB)"}
- {"dt": "2023-11-04T08:05:54.829600", "lvl": "debug", "msg": "progress  95% (24MB)"}
- {"dt": "2023-11-04T08:05:54.894533", "lvl": "debug", "msg": "progress 100% (25MB)"}
- {"dt": "2023-11-04T08:05:54.896109", "lvl": "info", "msg": "25MB downloaded in 3.52s (7.39MB/s)"}
- {"dt": "2023-11-04T08:05:54.897333", "lvl": "debug", "msg": "end: 1.2.1 http-download (duration 00:00:04) [common]"}
- {"dt": "2023-11-04T08:05:54.898019", "lvl": "results", "msg": {"case": "http-download", "definition": "lava", "duration": "3.52", "extra": {"label": "kernel", "md5sum": "72d29fea218746b728a438f8a5b06fcd", "sha256sum": "038284bca9e8e0d7a7f18c35684550365ede71fa430f977f893544ddbbc358c3", "sha512sum": "1677e3adf0de7906c97fbce4dcdde51fcf68b4fd7131c17fdbbd7e9d573686d2adb5fe65a35184ecbffd2bde054d852ec80dafe5699e26491c46bcf588e8208e", "size": ! "27247104"}, "level": "1.2.1", "namespace": "common", "result": "pass"}}
- {"dt": "2023-11-04T08:05:54.899516", "lvl": "debug", "msg": "end: 1.2 download-retry (duration 00:00:04) [common]"}
- {"dt": "2023-11-04T08:05:54.900347", "lvl": "debug", "msg": "start: 1.3 download-retry (timeout 00:09:55) [common]"}
- {"dt": "2023-11-04T08:05:54.901147", "lvl": "debug", "msg": "start: 1.3.1 http-download (timeout 00:09:55) [common]"}
- {"dt": "2023-11-04T08:05:54.902228", "lvl": "info", "msg": "downloading https://github.com/montjoie/lava-healthchecks-binary/blob/master/stable/linux-5.6.y/v5.6.12/arm64/defconfig/gcc-8/dtbs/broadcom/bcm2711-rpi-4-b.dtb?raw=true"}
- {"dt": "2023-11-04T08:05:54.902928", "lvl": "debug", "msg": "saving as /var/lib/lava/dispatcher/tmp/33268/tftp-deploy-zp4yljir/dtb/bcm2711-rpi-4-b.dtb"}
- {"dt": "2023-11-04T08:05:54.903752", "lvl": "debug", "msg": "total size: 22210 (0MB)"}
- {"dt": "2023-11-04T08:05:54.904474", "lvl": "debug", "msg": "No compression specified"}
- {"dt": "2023-11-04T08:05:55.409931", "lvl": "debug", "msg": "progress 100% (0MB)"}
- {"dt": "2023-11-04T08:05:55.413356", "lvl": "info", "msg": "0MB downloaded in 0.51s (0.04MB/s)"}
- {"dt": "2023-11-04T08:05:55.414479", "lvl": "debug", "msg": "end: 1.3.1 http-download (duration 00:00:01) [common]"}
- {"dt": "2023-11-04T08:05:55.415161", "lvl": "results", "msg": {"case": "http-download", "definition": "lava", "duration": "0.51", "extra": {"label": "dtb", "md5sum": "35e07c8c1178357e2ca07c7c96d27eb2", "sha256sum": "afaf477d22603c52e823a22f64edf96f8a5ff2899f37159fe03a087a8cef7afd", "sha512sum": "f8b5cd80677a91eabd047d7d044b1e1880560f578b31b1beec8d700e455804d74ed10ece7f61b8870189da08c83d121b0f140ae6b7d1752cbdaba48b0dea3cab", "size": ! "22210"}, "level": "1.3.1", "namespace": "common", "result": "pass"}}
- {"dt": "2023-11-04T08:05:55.416709", "lvl": "debug", "msg": "end: 1.3 download-retry (duration 00:00:01) [common]"}
- {"dt": "2023-11-04T08:05:55.417414", "lvl": "debug", "msg": "start: 1.4 download-retry (timeout 00:09:55) [common]"}
- {"dt": "2023-11-04T08:05:55.418045", "lvl": "debug", "msg": "start: 1.4.1 http-download (timeout 00:09:55) [common]"}
- {"dt": "2023-11-04T08:05:55.419013", "lvl": "info", "msg": "downloading https://github.com/montjoie/lava-healthchecks-binary/blob/master/stable/linux-5.6.y/v5.6.12/arm64/defconfig/gcc-8/modules.tar.xz?raw=true"}
- {"dt": "2023-11-04T08:05:55.419631", "lvl": "debug", "msg": "saving as /var/lib/lava/dispatcher/tmp/33268/tftp-deploy-zp4yljir/modules/modules.tar"}
- {"dt": "2023-11-04T08:05:55.420104", "lvl": "debug", "msg": "total size: 6392588 (6MB)"}
- {"dt": "2023-11-04T08:05:55.420633", "lvl": "info", "msg": "Using unxz to decompress xz"}
- {"dt": "2023-11-04T08:05:56.627561", "lvl": "debug", "msg": "progress   0% (0MB)"}
- {"dt": "2023-11-04T08:05:56.681935", "lvl": "debug", "msg": "progress   5% (0MB)"}
- {"dt": "2023-11-04T08:05:56.749902", "lvl": "debug", "msg": "progress  10% (0MB)"}
- {"dt": "2023-11-04T08:05:56.814902", "lvl": "debug", "msg": "progress  15% (0MB)"}
- {"dt": "2023-11-04T08:05:56.899369", "lvl": "debug", "msg": "progress  20% (1MB)"}
- {"dt": "2023-11-04T08:05:56.968772", "lvl": "debug", "msg": "progress  25% (1MB)"}
- {"dt": "2023-11-04T08:05:57.042939", "lvl": "debug", "msg": "progress  30% (1MB)"}
- {"dt": "2023-11-04T08:05:57.118374", "lvl": "debug", "msg": "progress  35% (2MB)"}
- {"dt": "2023-11-04T08:05:57.190223", "lvl": "debug", "msg": "progress  40% (2MB)"}
- {"dt": "2023-11-04T08:05:57.252732", "lvl": "debug", "msg": "progress  45% (2MB)"}
- {"dt": "2023-11-04T08:05:57.326379", "lvl": "debug", "msg": "progress  50% (3MB)"}
- {"dt": "2023-11-04T08:05:57.405368", "lvl": "debug", "msg": "progress  55% (3MB)"}
- {"dt": "2023-11-04T08:05:57.481320", "lvl": "debug", "msg": "progress  60% (3MB)"}
- {"dt": "2023-11-04T08:05:57.550337", "lvl": "debug", "msg": "progress  65% (3MB)"}
- {"dt": "2023-11-04T08:05:57.620643", "lvl": "debug", "msg": "progress  70% (4MB)"}
- {"dt": "2023-11-04T08:05:57.692474", "lvl": "debug", "msg": "progress  75% (4MB)"}
- {"dt": "2023-11-04T08:05:57.764877", "lvl": "debug", "msg": "progress  80% (4MB)"}
- {"dt": "2023-11-04T08:05:57.828474", "lvl": "debug", "msg": "progress  85% (5MB)"}
- {"dt": "2023-11-04T08:05:57.905217", "lvl": "debug", "msg": "progress  90% (5MB)"}
- {"dt": "2023-11-04T08:05:57.976895", "lvl": "debug", "msg": "progress  95% (5MB)"}
- {"dt": "2023-11-04T08:05:58.044300", "lvl": "debug", "msg": "progress 100% (6MB)"}
- {"dt": "2023-11-04T08:05:58.063919", "lvl": "info", "msg": "6MB downloaded in 2.64s (2.31MB/s)"}
- {"dt": "2023-11-04T08:05:58.068657", "lvl": "debug", "msg": "end: 1.4.1 http-download (duration 00:00:03) [common]"}
- {"dt": "2023-11-04T08:05:58.070766", "lvl": "results", "msg": {"case": "http-download", "definition": "lava", "duration": "2.65", "extra": {"label": "modules", "md5sum": "0724e49cc73f2f495ae13aa5497b2bec", "sha256sum": "1dd2900e982fee1c2772266b84169ee4ebbb2f5410d241faff08c4642b1616a8", "sha512sum": "897029f872c5b8d5e70944a473d61ea0441f43dd2eaefc1c68a44d11330a77629738f741db40957f5c97c5b7072f48c67373fc47794abfda6e35af8893df9785", "size": ! "6392588"}, "level": "1.4.1", "namespace": "common", "result": "pass"}}
- {"dt": "2023-11-04T08:05:58.073439", "lvl": "debug", "msg": "end: 1.4 download-retry (duration 00:00:03) [common]"}
- {"dt": "2023-11-04T08:05:58.074162", "lvl": "debug", "msg": "start: 1.5 prepare-tftp-overlay (timeout 00:09:52) [common]"}
- {"dt": "2023-11-04T08:05:58.074848", "lvl": "debug", "msg": "start: 1.5.1 extract-nfsrootfs (timeout 00:09:52) [common]"}
- {"dt": "2023-11-04T08:05:58.075466", "lvl": "debug", "msg": "end: 1.5.1 extract-nfsrootfs (duration 00:00:00) [common]"}
- {"dt": "2023-11-04T08:05:58.076113", "lvl": "debug", "msg": "start: 1.5.2 lava-overlay (timeout 00:09:52) [common]"}
- {"dt": "2023-11-04T08:05:58.076757", "lvl": "info", "msg": "[common] skipped lava-overlay - no test action."}
- {"dt": "2023-11-04T08:05:58.077386", "lvl": "debug", "msg": "end: 1.5.2 lava-overlay (duration 00:00:00) [common]"}
- {"dt": "2023-11-04T08:05:58.078029", "lvl": "debug", "msg": "start: 1.5.3 extract-overlay-ramdisk (timeout 00:09:52) [common]"}
- {"dt": "2023-11-04T08:05:59.038516", "lvl": "debug", "msg": "end: 1.5.3 extract-overlay-ramdisk (duration 00:00:01) [common]"}
- {"dt": "2023-11-04T08:05:59.041844", "lvl": "debug", "msg": "start: 1.5.4 extract-modules (timeout 00:09:51) [common]"}
- {"dt": "2023-11-04T08:05:59.042937", "lvl": "info", "msg": "extracting modules file /var/lib/lava/dispatcher/tmp/33268/tftp-deploy-zp4yljir/modules/modules.tar to /var/lib/lava/dispatcher/tmp/33268/extract-overlay-ramdisk-jfgj_q9g/ramdisk"}
- {"dt": "2023-11-04T08:06:00.419944", "lvl": "debug", "msg": "end: 1.5.4 extract-modules (duration 00:00:01) [common]"}
- {"dt": "2023-11-04T08:06:00.421026", "lvl": "debug", "msg": "start: 1.5.5 apply-overlay-tftp (timeout 00:09:50) [common]"}
- {"dt": "2023-11-04T08:06:00.421965", "lvl": "debug", "msg": "end: 1.5.5 apply-overlay-tftp (duration 00:00:00) [common]"}
- {"dt": "2023-11-04T08:06:00.422716", "lvl": "debug", "msg": "start: 1.5.6 prepare-kernel (timeout 00:09:50) [common]"}
- {"dt": "2023-11-04T08:06:00.423377", "lvl": "debug", "msg": "start: 1.5.6.1 uboot-prepare-kernel (timeout 00:09:50) [common]"}
- {"dt": "2023-11-04T08:06:00.424069", "lvl": "debug", "msg": "end: 1.5.6.1 uboot-prepare-kernel (duration 00:00:00) [common]"}
- {"dt": "2023-11-04T08:06:00.424815", "lvl": "debug", "msg": "end: 1.5.6 prepare-kernel (duration 00:00:00) [common]"}
- {"dt": "2023-11-04T08:06:00.425433", "lvl": "debug", "msg": "start: 1.5.7 configure-preseed-file (timeout 00:09:50) [common]"}
- {"dt": "2023-11-04T08:06:00.426042", "lvl": "debug", "msg": "end: 1.5.7 configure-preseed-file (duration 00:00:00) [common]"}
- {"dt": "2023-11-04T08:06:00.426664", "lvl": "debug", "msg": "start: 1.5.8 compress-ramdisk (timeout 00:09:50) [common]"}
- {"dt": "2023-11-04T08:06:00.427202", "lvl": "info", "msg": "Building ramdisk /var/lib/lava/dispatcher/tmp/33268/extract-overlay-ramdisk-jfgj_q9g/ramdisk.cpio containing /var/lib/lava/dispatcher/tmp/33268/extract-overlay-ramdisk-jfgj_q9g/ramdisk"}
- {"dt": "2023-11-04T08:06:02.796737", "lvl": "debug", "msg": ">> 90939 blocks\n"}
- {"dt": "2023-11-04T08:06:08.735724", "lvl": "debug", "msg": "Adding RAMdisk u-boot header."}
- {"dt": "2023-11-04T08:06:08.738957", "lvl": "debug", "msg": "mkimage -A arm64 -T ramdisk -C none -d /var/lib/lava/dispatcher/tmp/33268/extract-overlay-ramdisk-jfgj_q9g/ramdisk.cpio.gz /var/lib/lava/dispatcher/tmp/33268/extract-overlay-ramdisk-jfgj_q9g/ramdisk.cpio.gz.uboot"}
- {"dt": "2023-11-04T08:06:08.890995", "lvl": "debug", "msg": "output: Image Name:   "}
- {"dt": "2023-11-04T08:06:08.893045", "lvl": "debug", "msg": "output: Created:      Sat Nov  4 08:06:08 2023"}
- {"dt": "2023-11-04T08:06:08.893914", "lvl": "debug", "msg": "output: Image Type:   AArch64 Linux RAMDisk Image (uncompressed)"}
- {"dt": "2023-11-04T08:06:08.894790", "lvl": "debug", "msg": "output: Data Size:    13780961 Bytes = 13457.97 KiB = 13.14 MiB"}
- {"dt": "2023-11-04T08:06:08.895613", "lvl": "debug", "msg": "output: Load Address: 00000000"}
- {"dt": "2023-11-04T08:06:08.896296", "lvl": "debug", "msg": "output: Entry Point:  00000000"}
- {"dt": "2023-11-04T08:06:08.897103", "lvl": "debug", "msg": "output: "}
- {"dt": "2023-11-04T08:06:08.898409", "lvl": "debug", "msg": "rename /var/lib/lava/dispatcher/tmp/33268/extract-overlay-ramdisk-jfgj_q9g/ramdisk.cpio.gz.uboot to /var/lib/lava/dispatcher/tmp/33268/tftp-deploy-zp4yljir/ramdisk/ramdisk.cpio.gz.uboot"}
- {"dt": "2023-11-04T08:06:08.900146", "lvl": "debug", "msg": "end: 1.5.8 compress-ramdisk (duration 00:00:08) [common]"}
- {"dt": "2023-11-04T08:06:08.901524", "lvl": "debug", "msg": "end: 1.5 prepare-tftp-overlay (duration 00:00:11) [common]"}
- {"dt": "2023-11-04T08:06:08.902752", "lvl": "debug", "msg": "start: 1.6 lxc-create-udev-rule-action (timeout 00:09:41) [common]"}
- {"dt": "2023-11-04T08:06:08.903727", "lvl": "debug", "msg": "No LXC device requested"}
- {"dt": "2023-11-04T08:06:08.904726", "lvl": "debug", "msg": "end: 1.6 lxc-create-udev-rule-action (duration 00:00:00) [common]"}
- {"dt": "2023-11-04T08:06:08.905373", "lvl": "debug", "msg": "Checking files for TFTP limit of 4294967296 bytes."}
- {"dt": "2023-11-04T08:06:08.909151", "lvl": "info", "msg": "end: 1 tftp-deploy (duration 00:00:19) [common]"}
- {"dt": "2023-11-04T08:06:08.910083", "lvl": "info", "msg": "start: 2 uboot-action (timeout 00:05:00) [common]"}
- {"dt": "2023-11-04T08:06:08.910964", "lvl": "debug", "msg": "start: 2.1 uboot-from-media (timeout 00:05:00) [common]"}
- {"dt": "2023-11-04T08:06:08.911744", "lvl": "debug", "msg": "end: 2.1 uboot-from-media (duration 00:00:00) [common]"}
- {"dt": "2023-11-04T08:06:08.912646", "lvl": "debug", "msg": "start: 2.2 bootloader-overlay (timeout 00:05:00) [common]"}
- {"dt": "2023-11-04T08:06:08.914418", "lvl": "debug", "msg": "substitutions:"}
- {"dt": "2023-11-04T08:06:08.915148", "lvl": "debug", "msg": "- {BOOTX}: booti 0x00080000 0x02700000 0x02400000"}
- {"dt": "2023-11-04T08:06:08.915735", "lvl": "debug", "msg": "- {DTB_ADDR}: 0x02400000"}
- {"dt": "2023-11-04T08:06:08.916369", "lvl": "debug", "msg": "- {DTB}: 33268/tftp-deploy-zp4yljir/dtb/bcm2711-rpi-4-b.dtb"}
- {"dt": "2023-11-04T08:06:08.916942", "lvl": "debug", "msg": "- {INITRD}: 33268/tftp-deploy-zp4yljir/ramdisk/ramdisk.cpio.gz.uboot"}
- {"dt": "2023-11-04T08:06:08.917480", "lvl": "debug", "msg": "- {KERNEL_ADDR}: 0x00080000"}
- {"dt": "2023-11-04T08:06:08.918006", "lvl": "debug", "msg": "- {KERNEL}: 33268/tftp-deploy-zp4yljir/kernel/Image"}
- {"dt": "2023-11-04T08:06:08.918519", "lvl": "debug", "msg": "- {LAVA_MAC}: None"}
- {"dt": "2023-11-04T08:06:08.919034", "lvl": "debug", "msg": "- {PRESEED_CONFIG}: None"}
- {"dt": "2023-11-04T08:06:08.919545", "lvl": "debug", "msg": "- {PRESEED_LOCAL}: None"}
- {"dt": "2023-11-04T08:06:08.920052", "lvl": "debug", "msg": "- {RAMDISK_ADDR}: 0x02700000"}
- {"dt": "2023-11-04T08:06:08.920627", "lvl": "debug", "msg": "- {RAMDISK}: 33268/tftp-deploy-zp4yljir/ramdisk/ramdisk.cpio.gz.uboot"}
- {"dt": "2023-11-04T08:06:08.921159", "lvl": "debug", "msg": "- {ROOT_PART}: None"}
- {"dt": "2023-11-04T08:06:08.921673", "lvl": "debug", "msg": "- {ROOT}: None"}
- {"dt": "2023-11-04T08:06:08.922187", "lvl": "debug", "msg": "- {SERVER_IP}: 172.21.0.2"}
- {"dt": "2023-11-04T08:06:08.922698", "lvl": "debug", "msg": "- {TEE_ADDR}: 0x83000000"}
- {"dt": "2023-11-04T08:06:08.923208", "lvl": "debug", "msg": "- {TEE}: None"}
- {"dt": "2023-11-04T08:06:08.923716", "lvl": "info", "msg": "Parsed boot commands:"}
- {"dt": "2023-11-04T08:06:08.924252", "lvl": "info", "msg": "- setenv autoload no"}
- {"dt": "2023-11-04T08:06:08.924800", "lvl": "info", "msg": "- setenv initrd_high 0xffffffff"}
- {"dt": "2023-11-04T08:06:08.925321", "lvl": "info", "msg": "- setenv fdt_high 0xffffffff"}
- {"dt": "2023-11-04T08:06:08.925835", "lvl": "info", "msg": "- dhcp"}
- {"dt": "2023-11-04T08:06:08.926339", "lvl": "info", "msg": "- setenv serverip 172.21.0.2"}
- {"dt": "2023-11-04T08:06:08.926850", "lvl": "info", "msg": "- tftp 0x00080000 33268/tftp-deploy-zp4yljir/kernel/Image"}
- {"dt": "2023-11-04T08:06:08.927359", "lvl": "info", "msg": "- tftp 0x02700000 33268/tftp-deploy-zp4yljir/ramdisk/ramdisk.cpio.gz.uboot"}
- {"dt": "2023-11-04T08:06:08.927888", "lvl": "info", "msg": "- setenv initrd_size ${filesize}"}
- {"dt": "2023-11-04T08:06:08.928461", "lvl": "info", "msg": "- tftp 0x02400000 33268/tftp-deploy-zp4yljir/dtb/bcm2711-rpi-4-b.dtb"}
- {"dt": "2023-11-04T08:06:08.928988", "lvl": "info", "msg": "- setenv bootargs 'console=ttyS1,115200n8 root=/dev/ram0 console_msg_format=syslog ip=dhcp'"}
- {"dt": "2023-11-04T08:06:08.929510", "lvl": "info", "msg": "- fdt addr 0x02400000; fdt boardsetup; fdt resize; fdt set audio status okay; booti 0x00080000 0x02700000 0x02400000"}
- {"dt": "2023-11-04T08:06:08.930222", "lvl": "debug", "msg": "end: 2.2 bootloader-overlay (duration 00:00:00) [common]"}
- {"dt": "2023-11-04T08:06:08.930886", "lvl": "results", "msg": {"case": "bootloader-overlay", "definition": "lava", "duration": "0.02", "extra": {"dtb_addr": "0x02400000", "kernel_addr": "0x00080000", "ramdisk_addr": "0x02700000", "tee_addr": "0x83000000"}, "level": "2.2", "namespace": "common", "result": "pass"}}
- {"dt": "2023-11-04T08:06:08.932452", "lvl": "debug", "msg": "start: 2.3 connect-device (timeout 00:05:00) [common]"}
- {"dt": "2023-11-04T08:06:08.933175", "lvl": "info", "msg": "[common] connect-device Connecting to device using 'telnet 127.0.0.1 63003'"}
- {"dt": "2023-11-04T08:06:12.171285", "lvl": "debug", "msg": "Setting prompt string to ['lava-test: # ']"}
- {"dt": "2023-11-04T08:06:12.173554", "lvl": "debug", "msg": "end: 2.3 connect-device (duration 00:00:03) [common]"}
- {"dt": "2023-11-04T08:06:12.174642", "lvl": "debug", "msg": "start: 2.4 uboot-commands (timeout 00:04:57) [common]"}
- {"dt": "2023-11-04T08:06:12.176051", "lvl": "debug", "msg": "start: 2.4.1 reset-device (timeout 00:04:57) [common]"}
- {"dt": "2023-11-04T08:06:12.177967", "lvl": "debug", "msg": "start: 2.4.1.1 pdu-reboot (timeout 00:04:57) [common]"}
- {"dt": "2023-11-04T08:06:12.179584", "lvl": "debug", "msg": "Calling: 'nice' '/usr/local/bin/acme-cli' '-s' '192.168.66.2' 'reset' '7'"}
- {"dt": "2023-11-04T08:06:16.267386", "lvl": "debug", "msg": ">> Success\r"}
- {"dt": "2023-11-04T08:06:17.340580", "lvl": "debug", "msg": ">> Success\r"}
- {"dt": "2023-11-04T08:06:17.373795", "lvl": "debug", "msg": "Returned 0 in 5 seconds"}
- {"dt": "2023-11-04T08:06:17.476384", "lvl": "debug", "msg": "end: 2.4.1.1 pdu-reboot (duration 00:00:05) [common]"}
- {"dt": "2023-11-04T08:06:17.477697", "lvl": "results", "msg": {"case": "pdu-reboot", "definition": "lava", "duration": "5.30", "extra": {"status": "success"}, "level": "2.4.1.1", "namespace": "common", "result": "pass"}}
- {"dt": "2023-11-04T08:06:17.479937", "lvl": "debug", "msg": "end: 2.4.1 reset-device (duration 00:00:05) [common]"}
- {"dt": "2023-11-04T08:06:17.481179", "lvl": "debug", "msg": "start: 2.4.2 bootloader-interrupt (timeout 00:04:51) [common]"}
- {"dt": "2023-11-04T08:06:17.481969", "lvl": "debug", "msg": "Setting prompt string to ['Hit any key to stop autoboot']"}
- {"dt": "2023-11-04T08:06:17.482616", "lvl": "debug", "msg": "bootloader-interrupt: Wait for prompt ['Hit any key to stop autoboot'] (timeout 00:05:00)"}
- {"dt": "2023-11-04T08:06:17.484761", "lvl": "target", "msg": "Trying 127.0.0.1..."}
- {"dt": "2023-11-04T08:06:17.485513", "lvl": "target", "msg": "Connected to 127.0.0.1."}
- {"dt": "2023-11-04T08:06:17.486103", "lvl": "target", "msg": "Escape character is '^]'."}
- {"dt": "2023-11-04T08:06:23.955913", "lvl": "target", "msg": "\0"}
- {"dt": "2023-11-04T08:06:23.957500", "lvl": "target", "msg": ""}
- {"dt": "2023-11-04T08:06:23.959567", "lvl": "target", "msg": "U-Boot 2020.07-00717-gfee68b98fe-dirty (Jul 17 2020 - 09:59:08 +0200)"}
- {"dt": "2023-11-04T08:06:23.961368", "lvl": "target", "msg": ""}
- {"dt": "2023-11-04T08:06:24.102548", "lvl": "target", "msg": "DRAM:  3.9 GiB"}
- {"dt": "2023-11-04T08:06:24.134127", "lvl": "target", "msg": "RPI 4 Model B (0xc03111)"}
- {"dt": "2023-11-04T08:06:24.170801", "lvl": "target", "msg": "MMC:   emmc2@7e340000: 0, mmcnr@7e300000: 1"}
- {"dt": "2023-11-04T08:06:24.237784", "lvl": "target", "msg": "Loading Environment from FAT... *** Warning - bad CRC, using default environment"}
- {"dt": "2023-11-04T08:06:24.239439", "lvl": "target", "msg": ""}
- {"dt": "2023-11-04T08:06:24.264977", "lvl": "target", "msg": "In:    serial"}
- {"dt": "2023-11-04T08:06:24.265962", "lvl": "target", "msg": "Out:   serial"}
- {"dt": "2023-11-04T08:06:24.266715", "lvl": "target", "msg": "Err:   serial"}
- {"dt": "2023-11-04T08:06:24.267422", "lvl": "target", "msg": "Net:   eth0: genet@7d580000"}
- {"dt": "2023-11-04T08:06:24.268050", "lvl": "target", "msg": "starting USB..."}
- {"dt": "2023-11-04T08:06:24.268916", "lvl": "target", "msg": "No working controllers found"}
- {"dt": "2023-11-04T08:06:24.270466", "lvl": "input", "msg": "c"}
- {"dt": "2023-11-04T08:06:24.271842", "lvl": "debug", "msg": "end: 2.4.2 bootloader-interrupt (duration 00:00:07) [common]"}
- {"dt": "2023-11-04T08:06:24.272915", "lvl": "debug", "msg": "start: 2.4.3 bootloader-commands (timeout 00:04:45) [common]"}
- {"dt": "2023-11-04T08:06:24.273736", "lvl": "debug", "msg": "Setting prompt string to ['U-Boot>']"}
- {"dt": "2023-11-04T08:06:24.274535", "lvl": "debug", "msg": "bootloader-commands: Wait for prompt ['U-Boot>'] (timeout 00:04:45)"}
- {"dt": "2023-11-04T08:06:24.300710", "lvl": "target", "msg": "Hit any key to stop autoboot:  2 \x03\b\b\b 0 "}
- {"dt": "2023-11-04T08:06:24.302969", "lvl": "debug", "msg": "Setting prompt string to ['U-Boot>', 'Resetting CPU', 'Must RESET board to recover', 'TIMEOUT', 'Retry count exceeded', 'Retry time exceeded; starting again', 'ERROR: The remote end did not respond in time.', 'File not found', 'Bad Linux ARM64 Image magic!', 'Wrong Ramdisk Image Format', 'Ramdisk image is corrupt or invalid', 'ERROR: Failed to allocate', 'TFTP error: trying to overwrite reserved memory', 'Bad Linux RISCV Image magic!', 'Wrong Image Format for boot', 'ERROR: Did not find a cmdline Flattened Device Tree', 'ERROR: RD image overlaps OS image']"}
- {"dt": "2023-11-04T08:06:24.303685", "lvl": "input", "msg": "setenv autoload no\n"}
- {"dt": "2023-11-04T08:06:24.405256", "lvl": "target", "msg": "U-Boot> setenv autoload no"}
- {"dt": "2023-11-04T08:06:24.406243", "lvl": "debug", "msg": "bootloader-commands: Wait for prompt ['U-Boot>', 'Resetting CPU', 'Must RESET board to recover', 'TIMEOUT', 'Retry count exceeded', 'Retry time exceeded; starting again', 'ERROR: The remote end did not respond in time.', 'File not found', 'Bad Linux ARM64 Image magic!', 'Wrong Ramdisk Image Format', 'Ramdisk image is corrupt or invalid', 'ERROR: Failed to allocate', 'TFTP error: trying to overwrite reserved memory', 'Bad Linux RISCV Image magic!', 'Wrong Image Format for boot', 'ERROR: Did not find a cmdline Flattened Device Tree', 'ERROR: RD image overlaps OS image'] (timeout 00:04:45)"}
- {"dt": "2023-11-04T08:06:24.418159", "lvl": "target", "msg": "setenv autoload no"}
- {"dt": "2023-11-04T08:06:24.419603", "lvl": "input", "msg": "setenv initrd_high 0xffffffff\n"}
- {"dt": "2023-11-04T08:06:24.521643", "lvl": "target", "msg": "U-Boot> setenv initrd_high 0xffffffff"}
- {"dt": "2023-11-04T08:06:24.523609", "lvl": "debug", "msg": "bootloader-commands: Wait for prompt ['U-Boot>', 'Resetting CPU', 'Must RESET board to recover', 'TIMEOUT', 'Retry count exceeded', 'Retry time exceeded; starting again', 'ERROR: The remote end did not respond in time.', 'File not found', 'Bad Linux ARM64 Image magic!', 'Wrong Ramdisk Image Format', 'Ramdisk image is corrupt or invalid', 'ERROR: Failed to allocate', 'TFTP error: trying to overwrite reserved memory', 'Bad Linux RISCV Image magic!', 'Wrong Image Format for boot', 'ERROR: Did not find a cmdline Flattened Device Tree', 'ERROR: RD image overlaps OS image'] (timeout 00:04:44)"}
- {"dt": "2023-11-04T08:06:24.539964", "lvl": "target", "msg": "setenv initrd_high 0xffffffff"}
- {"dt": "2023-11-04T08:06:24.541238", "lvl": "input", "msg": "setenv fdt_high 0xffffffff\n"}
- {"dt": "2023-11-04T08:06:24.642855", "lvl": "target", "msg": "U-Boot> setenv fdt_high 0xffffffff"}
- {"dt": "2023-11-04T08:06:24.644529", "lvl": "debug", "msg": "bootloader-commands: Wait for prompt ['U-Boot>', 'Resetting CPU', 'Must RESET board to recover', 'TIMEOUT', 'Retry count exceeded', 'Retry time exceeded; starting again', 'ERROR: The remote end did not respond in time.', 'File not found', 'Bad Linux ARM64 Image magic!', 'Wrong Ramdisk Image Format', 'Ramdisk image is corrupt or invalid', 'ERROR: Failed to allocate', 'TFTP error: trying to overwrite reserved memory', 'Bad Linux RISCV Image magic!', 'Wrong Image Format for boot', 'ERROR: Did not find a cmdline Flattened Device Tree', 'ERROR: RD image overlaps OS image'] (timeout 00:04:44)"}
- {"dt": "2023-11-04T08:06:24.651244", "lvl": "target", "msg": "setenv fdt_high 0xffffffff"}
- {"dt": "2023-11-04T08:06:24.653122", "lvl": "input", "msg": "dhcp\n"}
- {"dt": "2023-11-04T08:06:24.755402", "lvl": "target", "msg": "U-Boot> dhcp"}
- {"dt": "2023-11-04T08:06:24.756592", "lvl": "debug", "msg": "bootloader-commands: Wait for prompt ['U-Boot>', 'Resetting CPU', 'Must RESET board to recover', 'TIMEOUT', 'Retry count exceeded', 'Retry time exceeded; starting again', 'ERROR: The remote end did not respond in time.', 'File not found', 'Bad Linux ARM64 Image magic!', 'Wrong Ramdisk Image Format', 'Ramdisk image is corrupt or invalid', 'ERROR: Failed to allocate', 'TFTP error: trying to overwrite reserved memory', 'Bad Linux RISCV Image magic!', 'Wrong Image Format for boot', 'ERROR: Did not find a cmdline Flattened Device Tree', 'ERROR: RD image overlaps OS image'] (timeout 00:04:44)"}
- {"dt": "2023-11-04T08:06:24.762871", "lvl": "target", "msg": "dhcp"}
- {"dt": "2023-11-04T08:06:27.929023", "lvl": "target", "msg": "genet@7d580000 Waiting for PHY auto negotiation to complete....... done"}
- {"dt": "2023-11-04T08:06:27.929739", "lvl": "target", "msg": "BOOTP broadcast 1"}
- {"dt": "2023-11-04T08:06:28.184674", "lvl": "target", "msg": "BOOTP broadcast 2"}
- {"dt": "2023-11-04T08:06:28.680456", "lvl": "target", "msg": "BOOTP broadcast 3"}
- {"dt": "2023-11-04T08:06:29.687515", "lvl": "target", "msg": "BOOTP broadcast 4"}
- {"dt": "2023-11-04T08:06:29.730461", "lvl": "target", "msg": "DHCP client bound to address 192.168.66.241 (1794 ms)"}
- {"dt": "2023-11-04T08:06:29.731569", "lvl": "input", "msg": "setenv serverip 172.21.0.2\n"}
- {"dt": "2023-11-04T08:06:29.833675", "lvl": "target", "msg": "U-Boot> setenv serverip 172.21.0.2"}
- {"dt": "2023-11-04T08:06:29.834926", "lvl": "debug", "msg": "bootloader-commands: Wait for prompt ['U-Boot>', 'Resetting CPU', 'Must RESET board to recover', 'TIMEOUT', 'Retry count exceeded', 'Retry time exceeded; starting again', 'ERROR: The remote end did not respond in time.', 'File not found', 'Bad Linux ARM64 Image magic!', 'Wrong Ramdisk Image Format', 'Ramdisk image is corrupt or invalid', 'ERROR: Failed to allocate', 'TFTP error: trying to overwrite reserved memory', 'Bad Linux RISCV Image magic!', 'Wrong Image Format for boot', 'ERROR: Did not find a cmdline Flattened Device Tree', 'ERROR: RD image overlaps OS image'] (timeout 00:04:39)"}
- {"dt": "2023-11-04T08:06:29.841658", "lvl": "target", "msg": "setenv serverip 172.21.0.2"}
- {"dt": "2023-11-04T08:06:29.843207", "lvl": "input", "msg": "tftp 0x00080000 33268/tftp-deploy-zp4yljir/kernel/Image\n"}
- {"dt": "2023-11-04T08:06:29.945183", "lvl": "target", "msg": "U-Boot> tftp 0x00080000 33268/tftp-deploy-zp4yljir/kernel/Image"}
- {"dt": "2023-11-04T08:06:29.947204", "lvl": "debug", "msg": "bootloader-commands: Wait for prompt ['U-Boot>', 'Resetting CPU', 'Must RESET board to recover', 'TIMEOUT', 'Retry count exceeded', 'Retry time exceeded; starting again', 'ERROR: The remote end did not respond in time.', 'File not found', 'Bad Linux ARM64 Image magic!', 'Wrong Ramdisk Image Format', 'Ramdisk image is corrupt or invalid', 'ERROR: Failed to allocate', 'TFTP error: trying to overwrite reserved memory', 'Bad Linux RISCV Image magic!', 'Wrong Image Format for boot', 'ERROR: Did not find a cmdline Flattened Device Tree', 'ERROR: RD image overlaps OS image'] (timeout 00:04:39)"}
- {"dt": "2023-11-04T08:06:29.953573", "lvl": "target", "msg": "tftp 0x00080000 33268/tftp-deploy-zp4yljir/kernel/Image"}
- {"dt": "2023-11-04T08:06:29.983406", "lvl": "target", "msg": "Using genet@7d580000 device"}
- {"dt": "2023-11-04T08:06:29.985578", "lvl": "target", "msg": "TFTP from server 172.21.0.2; our IP address is 192.168.66.241; sending through gateway 192.168.66.1"}
- {"dt": "2023-11-04T08:06:29.987377", "lvl": "target", "msg": "Filename '33268/tftp-deploy-zp4yljir/kernel/Image'."}
- {"dt": "2023-11-04T08:06:29.989234", "lvl": "target", "msg": "Load address: 0x80000"}
- {"dt": "2023-11-04T08:07:24.981845", "lvl": "target", "msg": "Loading: *\bT T T T T T T T T T "}
- {"dt": "2023-11-04T08:07:24.983192", "lvl": "exception", "msg": "matched a bootloader error message: 'Retry count exceeded' (4)"}
- {"dt": "2023-11-04T08:07:24.983999", "lvl": "debug", "msg": "end: 2.4.3 bootloader-commands (duration 00:01:01) [common]"}
- {"dt": "2023-11-04T08:07:24.984799", "lvl": "results", "msg": {"case": "bootloader-commands", "definition": "lava", "duration": "60.71", "extra": {"fail": "matched a bootloader error message: 'Retry count exceeded' (4)"}, "level": "2.4.3", "namespace": "common", "result": "fail"}}
- {"dt": "2023-11-04T08:07:24.986042", "lvl": "exception", "msg": "matched a bootloader error message: 'Retry count exceeded' (4)"}
- {"dt": "2023-11-04T08:07:24.986794", "lvl": "debug", "msg": "end: 2.4 uboot-commands (duration 00:01:13) [common]"}
- {"dt": "2023-11-04T08:07:24.987629", "lvl": "results", "msg": {"case": "uboot-commands", "definition": "lava", "duration": "72.81", "extra": {"fail": "matched a bootloader error message: 'Retry count exceeded' (4)"}, "level": "2.4", "namespace": "common", "result": "fail"}}
- {"dt": "2023-11-04T08:07:24.988894", "lvl": "error", "msg": "uboot-action failed: 1 of 1 attempts. 'matched a bootloader error message: 'Retry count exceeded' (4)'"}
- {"dt": "2023-11-04T08:07:24.989726", "lvl": "exception", "msg": "matched a bootloader error message: 'Retry count exceeded' (4)"}
- {"dt": "2023-11-04T08:07:24.990450", "lvl": "info", "msg": "end: 2 uboot-action (duration 00:01:16) [common]"}
- {"dt": "2023-11-04T08:07:24.991156", "lvl": "results", "msg": {"case": "uboot-action", "definition": "lava", "duration": "76.08", "extra": {"fail": "matched a bootloader error message: 'Retry count exceeded' (4)"}, "level": "2", "namespace": "common", "result": "fail"}}
- {"dt": "2023-11-04T08:07:24.992807", "lvl": "info", "msg": "Cleaning after the job"}
- {"dt": "2023-11-04T08:07:24.993710", "lvl": "debug", "msg": "Cleaning up download directory: /var/lib/lava/dispatcher/tmp/33268/tftp-deploy-zp4yljir/ramdisk"}
- {"dt": "2023-11-04T08:07:25.001520", "lvl": "debug", "msg": "Cleaning up download directory: /var/lib/lava/dispatcher/tmp/33268/tftp-deploy-zp4yljir/kernel"}
- {"dt": "2023-11-04T08:07:25.002744", "lvl": "debug", "msg": "Cleaning up download directory: /var/lib/lava/dispatcher/tmp/33268/tftp-deploy-zp4yljir/dtb"}
- {"dt": "2023-11-04T08:07:25.003942", "lvl": "debug", "msg": "Cleaning up download directory: /var/lib/lava/dispatcher/tmp/33268/tftp-deploy-zp4yljir/modules"}
- {"dt": "2023-11-04T08:07:25.015572", "lvl": "debug", "msg": "start: 3.1 power-off (timeout 00:00:30) [common]"}
- {"dt": "2023-11-04T08:07:25.016746", "lvl": "debug", "msg": "Calling: 'nice' '/usr/local/bin/acme-cli' '-s' '192.168.66.2' 'switch_off' '7'"}
- {"dt": "2023-11-04T08:07:28.475384", "lvl": "debug", "msg": ">> Success\r"}
- {"dt": "2023-11-04T08:07:28.511838", "lvl": "debug", "msg": "Returned 0 in 3 seconds"}
- {"dt": "2023-11-04T08:07:28.616002", "lvl": "debug", "msg": "end: 3.1 power-off (duration 00:00:04) [common]"}
- {"dt": "2023-11-04T08:07:28.618147", "lvl": "results", "msg": {"case": "power-off", "definition": "lava", "duration": "3.60", "extra": {"status": "success"}, "level": "3.1", "namespace": "common", "result": "pass"}}
- {"dt": "2023-11-04T08:07:28.622658", "lvl": "debug", "msg": "start: 3.2 read-feedback (timeout 00:09:56) [common]"}
- {"dt": "2023-11-04T08:07:28.627961", "lvl": "debug", "msg": "Listened to connection for namespace 'common' for up to 1s"}
- {"dt": "2023-11-04T08:07:28.629336", "lvl": "feedback", "msg": "Retry count exceeded; starting again", "ns": "common"}
- {"dt": "2023-11-04T08:07:28.630278", "lvl": "debug", "msg": "Listened to connection for namespace 'common' for up to 1s"}
- {"dt": "2023-11-04T08:07:29.628549", "lvl": "info", "msg": "Finalising connection for namespace 'common'"}
- {"dt": "2023-11-04T08:07:29.629487", "lvl": "info", "msg": "Disconnecting from shell: Finalise"}
- {"dt": "2023-11-04T08:07:29.630250", "lvl": "target", "msg": "U-Boot> \uFFFD"}
- {"dt": "2023-11-04T08:07:29.732889", "lvl": "debug", "msg": "end: 3.2 read-feedback (duration 00:00:01) [common]"}
- {"dt": "2023-11-04T08:07:29.735008", "lvl": "info", "msg": "Override tmp directory removed at /var/lib/lava/dispatcher/tmp/33268"}
- {"dt": "2023-11-04T08:07:29.943214", "lvl": "info", "msg": "Root tmp directory removed at /var/lib/lava/dispatcher/tmp/33268"}
- {"dt": "2023-11-04T08:07:29.944760", "lvl": "error", "msg": "InfrastructureError: The Infrastructure is not working correctly. Please report this error to LAVA admins."}
- {"dt": "2023-11-04T08:07:29.945515", "lvl": "results", "msg": {"case": "job", "definition": "lava", "error_msg": "matched a bootloader error message: 'Retry count exceeded' (4)", "error_type": "Infrastructure", "result": "fail"}}
