- {"dt": "2023-11-03T19:43:37.422707", "lvl": "info", "msg": "lava-dispatcher, installed at version: 2023.01"}
- {"dt": "2023-11-03T19:43:37.423965", "lvl": "info", "msg": "start: 0 validate"}
- {"dt": "2023-11-03T19:43:37.425038", "lvl": "info", "msg": "Start time: 2023-11-03 19:43:37.424983+00:00 (UTC)"}
- {"dt": "2023-11-03T19:43:37.426106", "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-03T19:43:39.197621", "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-03T19:43:41.291091", "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-03T19:43:41.858198", "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-03T19:43:42.904175", "lvl": "info", "msg": "validate duration: 5.48"}
- {"dt": "2023-11-03T19:43:42.905009", "lvl": "results", "msg": {"case": "validate", "definition": "lava", "result": "pass"}}
- {"dt": "2023-11-03T19:43:42.906009", "lvl": "info", "msg": "start: 1 tftp-deploy (timeout 00:10:00) [common]"}
- {"dt": "2023-11-03T19:43:42.906841", "lvl": "debug", "msg": "start: 1.1 download-retry (timeout 00:10:00) [common]"}
- {"dt": "2023-11-03T19:43:42.907551", "lvl": "debug", "msg": "start: 1.1.1 http-download (timeout 00:10:00) [common]"}
- {"dt": "2023-11-03T19:43:42.908550", "lvl": "debug", "msg": "Not decompressing ramdisk as can be used compressed."}
- {"dt": "2023-11-03T19:43:42.909402", "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-03T19:43:42.909935", "lvl": "debug", "msg": "saving as /var/lib/lava/dispatcher/tmp/33256/tftp-deploy-46j4jbol/ramdisk/rootfs.cpio.gz"}
- {"dt": "2023-11-03T19:43:42.910389", "lvl": "debug", "msg": "total size: 4192947 (3MB)"}
- {"dt": "2023-11-03T19:43:43.226140", "lvl": "debug", "msg": "progress   0% (0MB)"}
- {"dt": "2023-11-03T19:43:43.253361", "lvl": "debug", "msg": "progress   5% (0MB)"}
- {"dt": "2023-11-03T19:43:43.266261", "lvl": "debug", "msg": "progress  10% (0MB)"}
- {"dt": "2023-11-03T19:43:43.278915", "lvl": "debug", "msg": "progress  15% (0MB)"}
- {"dt": "2023-11-03T19:43:43.290808", "lvl": "debug", "msg": "progress  20% (0MB)"}
- {"dt": "2023-11-03T19:43:43.301650", "lvl": "debug", "msg": "progress  25% (1MB)"}
- {"dt": "2023-11-03T19:43:43.314070", "lvl": "debug", "msg": "progress  30% (1MB)"}
- {"dt": "2023-11-03T19:43:43.325223", "lvl": "debug", "msg": "progress  35% (1MB)"}
- {"dt": "2023-11-03T19:43:43.337527", "lvl": "debug", "msg": "progress  40% (1MB)"}
- {"dt": "2023-11-03T19:43:43.348657", "lvl": "debug", "msg": "progress  45% (1MB)"}
- {"dt": "2023-11-03T19:43:43.360449", "lvl": "debug", "msg": "progress  50% (2MB)"}
- {"dt": "2023-11-03T19:43:43.373490", "lvl": "debug", "msg": "progress  55% (2MB)"}
- {"dt": "2023-11-03T19:43:43.383854", "lvl": "debug", "msg": "progress  60% (2MB)"}
- {"dt": "2023-11-03T19:43:43.394605", "lvl": "debug", "msg": "progress  65% (2MB)"}
- {"dt": "2023-11-03T19:43:43.404037", "lvl": "debug", "msg": "progress  70% (2MB)"}
- {"dt": "2023-11-03T19:43:43.413304", "lvl": "debug", "msg": "progress  75% (3MB)"}
- {"dt": "2023-11-03T19:43:43.424009", "lvl": "debug", "msg": "progress  80% (3MB)"}
- {"dt": "2023-11-03T19:43:43.433289", "lvl": "debug", "msg": "progress  85% (3MB)"}
- {"dt": "2023-11-03T19:43:43.444277", "lvl": "debug", "msg": "progress  90% (3MB)"}
- {"dt": "2023-11-03T19:43:43.453562", "lvl": "debug", "msg": "progress  95% (3MB)"}
- {"dt": "2023-11-03T19:43:43.462860", "lvl": "debug", "msg": "progress 100% (3MB)"}
- {"dt": "2023-11-03T19:43:43.464877", "lvl": "info", "msg": "3MB downloaded in 0.55s (7.21MB/s)"}
- {"dt": "2023-11-03T19:43:43.466088", "lvl": "debug", "msg": "end: 1.1.1 http-download (duration 00:00:01) [common]"}
- {"dt": "2023-11-03T19:43:43.466789", "lvl": "results", "msg": {"case": "http-download", "definition": "lava", "duration": "0.56", "extra": {"label": "ramdisk", "md5sum": "dc99d8359b36a4a5fd569a984bb84bdf", "sha256sum": "cc73f153f47870c8ec995a00a0ad2aec3f05b6d22fc90b37a61f5066faa1b684", "sha512sum": "8fc07bd282f59a659b6417e8faca6c464be64927ab091cb2a9908805d12a680377bb58c5e52a1ed4d877b6f68783c02335e94ecf2764f5198816d2afd293923a", "size": ! "4192947"}, "level": "1.1.1", "namespace": "common", "result": "pass"}}
- {"dt": "2023-11-03T19:43:43.468333", "lvl": "debug", "msg": "end: 1.1 download-retry (duration 00:00:01) [common]"}
- {"dt": "2023-11-03T19:43:43.469175", "lvl": "debug", "msg": "start: 1.2 download-retry (timeout 00:09:59) [common]"}
- {"dt": "2023-11-03T19:43:43.469970", "lvl": "debug", "msg": "start: 1.2.1 http-download (timeout 00:09:59) [common]"}
- {"dt": "2023-11-03T19:43:43.471098", "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-03T19:43:43.471849", "lvl": "debug", "msg": "saving as /var/lib/lava/dispatcher/tmp/33256/tftp-deploy-46j4jbol/kernel/Image"}
- {"dt": "2023-11-03T19:43:43.472546", "lvl": "debug", "msg": "total size: 27247104 (25MB)"}
- {"dt": "2023-11-03T19:43:43.473197", "lvl": "debug", "msg": "No compression specified"}
- {"dt": "2023-11-03T19:43:45.647789", "lvl": "debug", "msg": "progress   0% (0MB)"}
- {"dt": "2023-11-03T19:43:45.737922", "lvl": "debug", "msg": "progress   5% (1MB)"}
- {"dt": "2023-11-03T19:43:45.805445", "lvl": "debug", "msg": "progress  10% (2MB)"}
- {"dt": "2023-11-03T19:43:45.871503", "lvl": "debug", "msg": "progress  15% (3MB)"}
- {"dt": "2023-11-03T19:43:45.939848", "lvl": "debug", "msg": "progress  20% (5MB)"}
- {"dt": "2023-11-03T19:43:46.004661", "lvl": "debug", "msg": "progress  25% (6MB)"}
- {"dt": "2023-11-03T19:43:46.073175", "lvl": "debug", "msg": "progress  30% (7MB)"}
- {"dt": "2023-11-03T19:43:46.140889", "lvl": "debug", "msg": "progress  35% (9MB)"}
- {"dt": "2023-11-03T19:43:46.205220", "lvl": "debug", "msg": "progress  40% (10MB)"}
- {"dt": "2023-11-03T19:43:46.272708", "lvl": "debug", "msg": "progress  45% (11MB)"}
- {"dt": "2023-11-03T19:43:46.338794", "lvl": "debug", "msg": "progress  50% (13MB)"}
- {"dt": "2023-11-03T19:43:46.406213", "lvl": "debug", "msg": "progress  55% (14MB)"}
- {"dt": "2023-11-03T19:43:46.471152", "lvl": "debug", "msg": "progress  60% (15MB)"}
- {"dt": "2023-11-03T19:43:46.538911", "lvl": "debug", "msg": "progress  65% (16MB)"}
- {"dt": "2023-11-03T19:43:46.604976", "lvl": "debug", "msg": "progress  70% (18MB)"}
- {"dt": "2023-11-03T19:43:46.668430", "lvl": "debug", "msg": "progress  75% (19MB)"}
- {"dt": "2023-11-03T19:43:46.735221", "lvl": "debug", "msg": "progress  80% (20MB)"}
- {"dt": "2023-11-03T19:43:46.800010", "lvl": "debug", "msg": "progress  85% (22MB)"}
- {"dt": "2023-11-03T19:43:46.865918", "lvl": "debug", "msg": "progress  90% (23MB)"}
- {"dt": "2023-11-03T19:43:46.929538", "lvl": "debug", "msg": "progress  95% (24MB)"}
- {"dt": "2023-11-03T19:43:46.990839", "lvl": "debug", "msg": "progress 100% (25MB)"}
- {"dt": "2023-11-03T19:43:46.992476", "lvl": "info", "msg": "25MB downloaded in 3.52s (7.38MB/s)"}
- {"dt": "2023-11-03T19:43:46.993660", "lvl": "debug", "msg": "end: 1.2.1 http-download (duration 00:00:04) [common]"}
- {"dt": "2023-11-03T19:43:46.994345", "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-03T19:43:46.995860", "lvl": "debug", "msg": "end: 1.2 download-retry (duration 00:00:04) [common]"}
- {"dt": "2023-11-03T19:43:46.996733", "lvl": "debug", "msg": "start: 1.3 download-retry (timeout 00:09:56) [common]"}
- {"dt": "2023-11-03T19:43:46.997528", "lvl": "debug", "msg": "start: 1.3.1 http-download (timeout 00:09:56) [common]"}
- {"dt": "2023-11-03T19:43:46.998612", "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-03T19:43:46.999309", "lvl": "debug", "msg": "saving as /var/lib/lava/dispatcher/tmp/33256/tftp-deploy-46j4jbol/dtb/bcm2711-rpi-4-b.dtb"}
- {"dt": "2023-11-03T19:43:46.999879", "lvl": "debug", "msg": "total size: 22210 (0MB)"}
- {"dt": "2023-11-03T19:43:47.000496", "lvl": "debug", "msg": "No compression specified"}
- {"dt": "2023-11-03T19:43:47.587713", "lvl": "debug", "msg": "progress 100% (0MB)"}
- {"dt": "2023-11-03T19:43:47.590245", "lvl": "info", "msg": "0MB downloaded in 0.59s (0.04MB/s)"}
- {"dt": "2023-11-03T19:43:47.591999", "lvl": "debug", "msg": "end: 1.3.1 http-download (duration 00:00:01) [common]"}
- {"dt": "2023-11-03T19:43:47.593128", "lvl": "results", "msg": {"case": "http-download", "definition": "lava", "duration": "0.59", "extra": {"label": "dtb", "md5sum": "35e07c8c1178357e2ca07c7c96d27eb2", "sha256sum": "afaf477d22603c52e823a22f64edf96f8a5ff2899f37159fe03a087a8cef7afd", "sha512sum": "f8b5cd80677a91eabd047d7d044b1e1880560f578b31b1beec8d700e455804d74ed10ece7f61b8870189da08c83d121b0f140ae6b7d1752cbdaba48b0dea3cab", "size": ! "22210"}, "level": "1.3.1", "namespace": "common", "result": "pass"}}
- {"dt": "2023-11-03T19:43:47.595668", "lvl": "debug", "msg": "end: 1.3 download-retry (duration 00:00:01) [common]"}
- {"dt": "2023-11-03T19:43:47.597000", "lvl": "debug", "msg": "start: 1.4 download-retry (timeout 00:09:55) [common]"}
- {"dt": "2023-11-03T19:43:47.598217", "lvl": "debug", "msg": "start: 1.4.1 http-download (timeout 00:09:55) [common]"}
- {"dt": "2023-11-03T19:43:47.599882", "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-03T19:43:47.600872", "lvl": "debug", "msg": "saving as /var/lib/lava/dispatcher/tmp/33256/tftp-deploy-46j4jbol/modules/modules.tar"}
- {"dt": "2023-11-03T19:43:47.601448", "lvl": "debug", "msg": "total size: 6392588 (6MB)"}
- {"dt": "2023-11-03T19:43:47.602006", "lvl": "info", "msg": "Using unxz to decompress xz"}
- {"dt": "2023-11-03T19:43:48.700631", "lvl": "debug", "msg": "progress   0% (0MB)"}
- {"dt": "2023-11-03T19:43:48.759582", "lvl": "debug", "msg": "progress   5% (0MB)"}
- {"dt": "2023-11-03T19:43:48.827278", "lvl": "debug", "msg": "progress  10% (0MB)"}
- {"dt": "2023-11-03T19:43:48.893092", "lvl": "debug", "msg": "progress  15% (0MB)"}
- {"dt": "2023-11-03T19:43:48.976241", "lvl": "debug", "msg": "progress  20% (1MB)"}
- {"dt": "2023-11-03T19:43:49.045182", "lvl": "debug", "msg": "progress  25% (1MB)"}
- {"dt": "2023-11-03T19:43:49.119444", "lvl": "debug", "msg": "progress  30% (1MB)"}
- {"dt": "2023-11-03T19:43:49.194419", "lvl": "debug", "msg": "progress  35% (2MB)"}
- {"dt": "2023-11-03T19:43:49.266190", "lvl": "debug", "msg": "progress  40% (2MB)"}
- {"dt": "2023-11-03T19:43:49.329125", "lvl": "debug", "msg": "progress  45% (2MB)"}
- {"dt": "2023-11-03T19:43:49.400314", "lvl": "debug", "msg": "progress  50% (3MB)"}
- {"dt": "2023-11-03T19:43:49.479188", "lvl": "debug", "msg": "progress  55% (3MB)"}
- {"dt": "2023-11-03T19:43:49.555324", "lvl": "debug", "msg": "progress  60% (3MB)"}
- {"dt": "2023-11-03T19:43:49.621614", "lvl": "debug", "msg": "progress  65% (3MB)"}
- {"dt": "2023-11-03T19:43:49.691834", "lvl": "debug", "msg": "progress  70% (4MB)"}
- {"dt": "2023-11-03T19:43:49.763307", "lvl": "debug", "msg": "progress  75% (4MB)"}
- {"dt": "2023-11-03T19:43:49.831250", "lvl": "debug", "msg": "progress  80% (4MB)"}
- {"dt": "2023-11-03T19:43:49.890488", "lvl": "debug", "msg": "progress  85% (5MB)"}
- {"dt": "2023-11-03T19:43:49.965405", "lvl": "debug", "msg": "progress  90% (5MB)"}
- {"dt": "2023-11-03T19:43:50.035697", "lvl": "debug", "msg": "progress  95% (5MB)"}
- {"dt": "2023-11-03T19:43:50.101874", "lvl": "debug", "msg": "progress 100% (6MB)"}
- {"dt": "2023-11-03T19:43:50.121093", "lvl": "info", "msg": "6MB downloaded in 2.52s (2.42MB/s)"}
- {"dt": "2023-11-03T19:43:50.123787", "lvl": "debug", "msg": "end: 1.4.1 http-download (duration 00:00:03) [common]"}
- {"dt": "2023-11-03T19:43:50.125043", "lvl": "results", "msg": {"case": "http-download", "definition": "lava", "duration": "2.53", "extra": {"label": "modules", "md5sum": "0724e49cc73f2f495ae13aa5497b2bec", "sha256sum": "1dd2900e982fee1c2772266b84169ee4ebbb2f5410d241faff08c4642b1616a8", "sha512sum": "897029f872c5b8d5e70944a473d61ea0441f43dd2eaefc1c68a44d11330a77629738f741db40957f5c97c5b7072f48c67373fc47794abfda6e35af8893df9785", "size": ! "6392588"}, "level": "1.4.1", "namespace": "common", "result": "pass"}}
- {"dt": "2023-11-03T19:43:50.128601", "lvl": "debug", "msg": "end: 1.4 download-retry (duration 00:00:03) [common]"}
- {"dt": "2023-11-03T19:43:50.130207", "lvl": "debug", "msg": "start: 1.5 prepare-tftp-overlay (timeout 00:09:53) [common]"}
- {"dt": "2023-11-03T19:43:50.131862", "lvl": "debug", "msg": "start: 1.5.1 extract-nfsrootfs (timeout 00:09:53) [common]"}
- {"dt": "2023-11-03T19:43:50.133250", "lvl": "debug", "msg": "end: 1.5.1 extract-nfsrootfs (duration 00:00:00) [common]"}
- {"dt": "2023-11-03T19:43:50.134927", "lvl": "debug", "msg": "start: 1.5.2 lava-overlay (timeout 00:09:53) [common]"}
- {"dt": "2023-11-03T19:43:50.136302", "lvl": "info", "msg": "[common] skipped lava-overlay - no test action."}
- {"dt": "2023-11-03T19:43:50.137077", "lvl": "debug", "msg": "end: 1.5.2 lava-overlay (duration 00:00:00) [common]"}
- {"dt": "2023-11-03T19:43:50.137732", "lvl": "debug", "msg": "start: 1.5.3 extract-overlay-ramdisk (timeout 00:09:53) [common]"}
- {"dt": "2023-11-03T19:43:51.109640", "lvl": "debug", "msg": "end: 1.5.3 extract-overlay-ramdisk (duration 00:00:01) [common]"}
- {"dt": "2023-11-03T19:43:51.113046", "lvl": "debug", "msg": "start: 1.5.4 extract-modules (timeout 00:09:52) [common]"}
- {"dt": "2023-11-03T19:43:51.114324", "lvl": "info", "msg": "extracting modules file /var/lib/lava/dispatcher/tmp/33256/tftp-deploy-46j4jbol/modules/modules.tar to /var/lib/lava/dispatcher/tmp/33256/extract-overlay-ramdisk-vd233iuu/ramdisk"}
- {"dt": "2023-11-03T19:43:52.497219", "lvl": "debug", "msg": "end: 1.5.4 extract-modules (duration 00:00:01) [common]"}
- {"dt": "2023-11-03T19:43:52.498200", "lvl": "debug", "msg": "start: 1.5.5 apply-overlay-tftp (timeout 00:09:50) [common]"}
- {"dt": "2023-11-03T19:43:52.498977", "lvl": "debug", "msg": "end: 1.5.5 apply-overlay-tftp (duration 00:00:00) [common]"}
- {"dt": "2023-11-03T19:43:52.499664", "lvl": "debug", "msg": "start: 1.5.6 prepare-kernel (timeout 00:09:50) [common]"}
- {"dt": "2023-11-03T19:43:52.500357", "lvl": "debug", "msg": "start: 1.5.6.1 uboot-prepare-kernel (timeout 00:09:50) [common]"}
- {"dt": "2023-11-03T19:43:52.501102", "lvl": "debug", "msg": "end: 1.5.6.1 uboot-prepare-kernel (duration 00:00:00) [common]"}
- {"dt": "2023-11-03T19:43:52.501729", "lvl": "debug", "msg": "end: 1.5.6 prepare-kernel (duration 00:00:00) [common]"}
- {"dt": "2023-11-03T19:43:52.502344", "lvl": "debug", "msg": "start: 1.5.7 configure-preseed-file (timeout 00:09:50) [common]"}
- {"dt": "2023-11-03T19:43:52.502940", "lvl": "debug", "msg": "end: 1.5.7 configure-preseed-file (duration 00:00:00) [common]"}
- {"dt": "2023-11-03T19:43:52.503552", "lvl": "debug", "msg": "start: 1.5.8 compress-ramdisk (timeout 00:09:50) [common]"}
- {"dt": "2023-11-03T19:43:52.504138", "lvl": "info", "msg": "Building ramdisk /var/lib/lava/dispatcher/tmp/33256/extract-overlay-ramdisk-vd233iuu/ramdisk.cpio containing /var/lib/lava/dispatcher/tmp/33256/extract-overlay-ramdisk-vd233iuu/ramdisk"}
- {"dt": "2023-11-03T19:43:54.871753", "lvl": "debug", "msg": ">> 90939 blocks\n"}
- {"dt": "2023-11-03T19:44:00.826673", "lvl": "debug", "msg": "Adding RAMdisk u-boot header."}
- {"dt": "2023-11-03T19:44:00.828523", "lvl": "debug", "msg": "mkimage -A arm64 -T ramdisk -C none -d /var/lib/lava/dispatcher/tmp/33256/extract-overlay-ramdisk-vd233iuu/ramdisk.cpio.gz /var/lib/lava/dispatcher/tmp/33256/extract-overlay-ramdisk-vd233iuu/ramdisk.cpio.gz.uboot"}
- {"dt": "2023-11-03T19:44:00.987283", "lvl": "debug", "msg": "output: Image Name:   "}
- {"dt": "2023-11-03T19:44:00.990649", "lvl": "debug", "msg": "output: Created:      Fri Nov  3 19:44:00 2023"}
- {"dt": "2023-11-03T19:44:00.991793", "lvl": "debug", "msg": "output: Image Type:   AArch64 Linux RAMDisk Image (uncompressed)"}
- {"dt": "2023-11-03T19:44:00.992787", "lvl": "debug", "msg": "output: Data Size:    13781071 Bytes = 13458.08 KiB = 13.14 MiB"}
- {"dt": "2023-11-03T19:44:00.993860", "lvl": "debug", "msg": "output: Load Address: 00000000"}
- {"dt": "2023-11-03T19:44:00.994940", "lvl": "debug", "msg": "output: Entry Point:  00000000"}
- {"dt": "2023-11-03T19:44:00.995986", "lvl": "debug", "msg": "output: "}
- {"dt": "2023-11-03T19:44:00.997746", "lvl": "debug", "msg": "rename /var/lib/lava/dispatcher/tmp/33256/extract-overlay-ramdisk-vd233iuu/ramdisk.cpio.gz.uboot to /var/lib/lava/dispatcher/tmp/33256/tftp-deploy-46j4jbol/ramdisk/ramdisk.cpio.gz.uboot"}
- {"dt": "2023-11-03T19:44:01.000477", "lvl": "debug", "msg": "end: 1.5.8 compress-ramdisk (duration 00:00:08) [common]"}
- {"dt": "2023-11-03T19:44:01.001458", "lvl": "debug", "msg": "end: 1.5 prepare-tftp-overlay (duration 00:00:11) [common]"}
- {"dt": "2023-11-03T19:44:01.002208", "lvl": "debug", "msg": "start: 1.6 lxc-create-udev-rule-action (timeout 00:09:42) [common]"}
- {"dt": "2023-11-03T19:44:01.002795", "lvl": "debug", "msg": "No LXC device requested"}
- {"dt": "2023-11-03T19:44:01.003397", "lvl": "debug", "msg": "end: 1.6 lxc-create-udev-rule-action (duration 00:00:00) [common]"}
- {"dt": "2023-11-03T19:44:01.003903", "lvl": "debug", "msg": "Checking files for TFTP limit of 4294967296 bytes."}
- {"dt": "2023-11-03T19:44:01.007561", "lvl": "info", "msg": "end: 1 tftp-deploy (duration 00:00:18) [common]"}
- {"dt": "2023-11-03T19:44:01.008514", "lvl": "info", "msg": "start: 2 uboot-action (timeout 00:05:00) [common]"}
- {"dt": "2023-11-03T19:44:01.009307", "lvl": "debug", "msg": "start: 2.1 uboot-from-media (timeout 00:05:00) [common]"}
- {"dt": "2023-11-03T19:44:01.009935", "lvl": "debug", "msg": "end: 2.1 uboot-from-media (duration 00:00:00) [common]"}
- {"dt": "2023-11-03T19:44:01.010568", "lvl": "debug", "msg": "start: 2.2 bootloader-overlay (timeout 00:05:00) [common]"}
- {"dt": "2023-11-03T19:44:01.012133", "lvl": "debug", "msg": "substitutions:"}
- {"dt": "2023-11-03T19:44:01.012869", "lvl": "debug", "msg": "- {BOOTX}: booti 0x00080000 0x02700000 0x02400000"}
- {"dt": "2023-11-03T19:44:01.013334", "lvl": "debug", "msg": "- {DTB_ADDR}: 0x02400000"}
- {"dt": "2023-11-03T19:44:01.013758", "lvl": "debug", "msg": "- {DTB}: 33256/tftp-deploy-46j4jbol/dtb/bcm2711-rpi-4-b.dtb"}
- {"dt": "2023-11-03T19:44:01.014182", "lvl": "debug", "msg": "- {INITRD}: 33256/tftp-deploy-46j4jbol/ramdisk/ramdisk.cpio.gz.uboot"}
- {"dt": "2023-11-03T19:44:01.014601", "lvl": "debug", "msg": "- {KERNEL_ADDR}: 0x00080000"}
- {"dt": "2023-11-03T19:44:01.015015", "lvl": "debug", "msg": "- {KERNEL}: 33256/tftp-deploy-46j4jbol/kernel/Image"}
- {"dt": "2023-11-03T19:44:01.015432", "lvl": "debug", "msg": "- {LAVA_MAC}: None"}
- {"dt": "2023-11-03T19:44:01.015847", "lvl": "debug", "msg": "- {PRESEED_CONFIG}: None"}
- {"dt": "2023-11-03T19:44:01.016313", "lvl": "debug", "msg": "- {PRESEED_LOCAL}: None"}
- {"dt": "2023-11-03T19:44:01.016757", "lvl": "debug", "msg": "- {RAMDISK_ADDR}: 0x02700000"}
- {"dt": "2023-11-03T19:44:01.017174", "lvl": "debug", "msg": "- {RAMDISK}: 33256/tftp-deploy-46j4jbol/ramdisk/ramdisk.cpio.gz.uboot"}
- {"dt": "2023-11-03T19:44:01.017593", "lvl": "debug", "msg": "- {ROOT_PART}: None"}
- {"dt": "2023-11-03T19:44:01.018015", "lvl": "debug", "msg": "- {ROOT}: None"}
- {"dt": "2023-11-03T19:44:01.018432", "lvl": "debug", "msg": "- {SERVER_IP}: 172.21.0.2"}
- {"dt": "2023-11-03T19:44:01.018846", "lvl": "debug", "msg": "- {TEE_ADDR}: 0x83000000"}
- {"dt": "2023-11-03T19:44:01.019269", "lvl": "debug", "msg": "- {TEE}: None"}
- {"dt": "2023-11-03T19:44:01.019712", "lvl": "info", "msg": "Parsed boot commands:"}
- {"dt": "2023-11-03T19:44:01.020124", "lvl": "info", "msg": "- setenv autoload no"}
- {"dt": "2023-11-03T19:44:01.020599", "lvl": "info", "msg": "- setenv initrd_high 0xffffffff"}
- {"dt": "2023-11-03T19:44:01.021038", "lvl": "info", "msg": "- setenv fdt_high 0xffffffff"}
- {"dt": "2023-11-03T19:44:01.021458", "lvl": "info", "msg": "- dhcp"}
- {"dt": "2023-11-03T19:44:01.021880", "lvl": "info", "msg": "- setenv serverip 172.21.0.2"}
- {"dt": "2023-11-03T19:44:01.022294", "lvl": "info", "msg": "- tftp 0x00080000 33256/tftp-deploy-46j4jbol/kernel/Image"}
- {"dt": "2023-11-03T19:44:01.022711", "lvl": "info", "msg": "- tftp 0x02700000 33256/tftp-deploy-46j4jbol/ramdisk/ramdisk.cpio.gz.uboot"}
- {"dt": "2023-11-03T19:44:01.023148", "lvl": "info", "msg": "- setenv initrd_size ${filesize}"}
- {"dt": "2023-11-03T19:44:01.023569", "lvl": "info", "msg": "- tftp 0x02400000 33256/tftp-deploy-46j4jbol/dtb/bcm2711-rpi-4-b.dtb"}
- {"dt": "2023-11-03T19:44:01.023980", "lvl": "info", "msg": "- setenv bootargs 'console=ttyS1,115200n8 root=/dev/ram0 console_msg_format=syslog ip=dhcp'"}
- {"dt": "2023-11-03T19:44:01.024461", "lvl": "info", "msg": "- fdt addr 0x02400000; fdt boardsetup; fdt resize; fdt set audio status okay; booti 0x00080000 0x02700000 0x02400000"}
- {"dt": "2023-11-03T19:44:01.025078", "lvl": "debug", "msg": "end: 2.2 bootloader-overlay (duration 00:00:00) [common]"}
- {"dt": "2023-11-03T19:44:01.025616", "lvl": "results", "msg": {"case": "bootloader-overlay", "definition": "lava", "duration": "0.01", "extra": {"dtb_addr": "0x02400000", "kernel_addr": "0x00080000", "ramdisk_addr": "0x02700000", "tee_addr": "0x83000000"}, "level": "2.2", "namespace": "common", "result": "pass"}}
- {"dt": "2023-11-03T19:44:01.026942", "lvl": "debug", "msg": "start: 2.3 connect-device (timeout 00:05:00) [common]"}
- {"dt": "2023-11-03T19:44:01.027523", "lvl": "info", "msg": "[common] connect-device Connecting to device using 'telnet 127.0.0.1 63003'"}
- {"dt": "2023-11-03T19:44:04.277755", "lvl": "debug", "msg": "Setting prompt string to ['lava-test: # ']"}
- {"dt": "2023-11-03T19:44:04.281862", "lvl": "debug", "msg": "end: 2.3 connect-device (duration 00:00:03) [common]"}
- {"dt": "2023-11-03T19:44:04.282888", "lvl": "debug", "msg": "start: 2.4 uboot-commands (timeout 00:04:57) [common]"}
- {"dt": "2023-11-03T19:44:04.283752", "lvl": "debug", "msg": "start: 2.4.1 reset-device (timeout 00:04:57) [common]"}
- {"dt": "2023-11-03T19:44:04.284699", "lvl": "debug", "msg": "start: 2.4.1.1 pdu-reboot (timeout 00:04:57) [common]"}
- {"dt": "2023-11-03T19:44:04.286190", "lvl": "debug", "msg": "Calling: 'nice' '/usr/local/bin/acme-cli' '-s' '192.168.66.2' 'reset' '7'"}
- {"dt": "2023-11-03T19:44:08.034534", "lvl": "debug", "msg": ">> Success\r"}
- {"dt": "2023-11-03T19:44:09.102070", "lvl": "debug", "msg": ">> Success\r"}
- {"dt": "2023-11-03T19:44:09.136594", "lvl": "debug", "msg": "Returned 0 in 4 seconds"}
- {"dt": "2023-11-03T19:44:09.238888", "lvl": "debug", "msg": "end: 2.4.1.1 pdu-reboot (duration 00:00:05) [common]"}
- {"dt": "2023-11-03T19:44:09.239756", "lvl": "results", "msg": {"case": "pdu-reboot", "definition": "lava", "duration": "4.95", "extra": {"status": "success"}, "level": "2.4.1.1", "namespace": "common", "result": "pass"}}
- {"dt": "2023-11-03T19:44:09.241101", "lvl": "debug", "msg": "end: 2.4.1 reset-device (duration 00:00:05) [common]"}
- {"dt": "2023-11-03T19:44:09.241857", "lvl": "debug", "msg": "start: 2.4.2 bootloader-interrupt (timeout 00:04:52) [common]"}
- {"dt": "2023-11-03T19:44:09.242515", "lvl": "debug", "msg": "Setting prompt string to ['Hit any key to stop autoboot']"}
- {"dt": "2023-11-03T19:44:09.243044", "lvl": "debug", "msg": "bootloader-interrupt: Wait for prompt ['Hit any key to stop autoboot'] (timeout 00:05:00)"}
- {"dt": "2023-11-03T19:44:09.244940", "lvl": "target", "msg": "Trying 127.0.0.1..."}
- {"dt": "2023-11-03T19:44:09.245652", "lvl": "target", "msg": "Connected to 127.0.0.1."}
- {"dt": "2023-11-03T19:44:09.246112", "lvl": "target", "msg": "Escape character is '^]'."}
- {"dt": "2023-11-03T19:44:15.726701", "lvl": "target", "msg": "\0"}
- {"dt": "2023-11-03T19:44:15.727457", "lvl": "target", "msg": ""}
- {"dt": "2023-11-03T19:44:15.730100", "lvl": "target", "msg": "U-Boot 2020.07-00717-gfee68b98fe-dirty (Jul 17 2020 - 09:59:08 +0200)"}
- {"dt": "2023-11-03T19:44:15.730802", "lvl": "target", "msg": ""}
- {"dt": "2023-11-03T19:44:15.873447", "lvl": "target", "msg": "DRAM:  3.9 GiB"}
- {"dt": "2023-11-03T19:44:15.905538", "lvl": "target", "msg": "RPI 4 Model B (0xc03111)"}
- {"dt": "2023-11-03T19:44:15.944485", "lvl": "target", "msg": "MMC:   emmc2@7e340000: 0, mmcnr@7e300000: 1"}
- {"dt": "2023-11-03T19:44:16.008578", "lvl": "target", "msg": "Loading Environment from FAT... *** Warning - bad CRC, using default environment"}
- {"dt": "2023-11-03T19:44:16.010378", "lvl": "target", "msg": ""}
- {"dt": "2023-11-03T19:44:16.035784", "lvl": "target", "msg": "In:    serial"}
- {"dt": "2023-11-03T19:44:16.037427", "lvl": "target", "msg": "Out:   serial"}
- {"dt": "2023-11-03T19:44:16.038802", "lvl": "target", "msg": "Err:   serial"}
- {"dt": "2023-11-03T19:44:16.040805", "lvl": "target", "msg": "Net:   eth0: genet@7d580000"}
- {"dt": "2023-11-03T19:44:16.042278", "lvl": "target", "msg": "starting USB..."}
- {"dt": "2023-11-03T19:44:16.043588", "lvl": "target", "msg": "No working controllers found"}
- {"dt": "2023-11-03T19:44:16.045483", "lvl": "input", "msg": "c"}
- {"dt": "2023-11-03T19:44:16.046548", "lvl": "debug", "msg": "end: 2.4.2 bootloader-interrupt (duration 00:00:07) [common]"}
- {"dt": "2023-11-03T19:44:16.047497", "lvl": "debug", "msg": "start: 2.4.3 bootloader-commands (timeout 00:04:45) [common]"}
- {"dt": "2023-11-03T19:44:16.048275", "lvl": "debug", "msg": "Setting prompt string to ['U-Boot>']"}
- {"dt": "2023-11-03T19:44:16.049026", "lvl": "debug", "msg": "bootloader-commands: Wait for prompt ['U-Boot>'] (timeout 00:04:45)"}
- {"dt": "2023-11-03T19:44:16.069880", "lvl": "target", "msg": "Hit any key to stop autoboot:  2 \x03\b\b\b 0 "}
- {"dt": "2023-11-03T19:44:16.071547", "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-03T19:44:16.072598", "lvl": "input", "msg": "setenv autoload no\n"}
- {"dt": "2023-11-03T19:44:16.174400", "lvl": "target", "msg": "U-Boot> setenv autoload no"}
- {"dt": "2023-11-03T19:44:16.176283", "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-03T19:44:16.184518", "lvl": "target", "msg": "setenv autoload no"}
- {"dt": "2023-11-03T19:44:16.185779", "lvl": "input", "msg": "setenv initrd_high 0xffffffff\n"}
- {"dt": "2023-11-03T19:44:16.287448", "lvl": "target", "msg": "U-Boot> setenv initrd_high 0xffffffff"}
- {"dt": "2023-11-03T19:44:16.289386", "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-03T19:44:16.294132", "lvl": "target", "msg": "setenv initrd_high 0xffffffff"}
- {"dt": "2023-11-03T19:44:16.310217", "lvl": "input", "msg": "setenv fdt_high 0xffffffff\n"}
- {"dt": "2023-11-03T19:44:16.412372", "lvl": "target", "msg": "U-Boot> setenv fdt_high 0xffffffff"}
- {"dt": "2023-11-03T19:44:16.414398", "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-03T19:44:16.422512", "lvl": "target", "msg": "setenv fdt_high 0xffffffff"}
- {"dt": "2023-11-03T19:44:16.423534", "lvl": "input", "msg": "dhcp\n"}
- {"dt": "2023-11-03T19:44:16.524954", "lvl": "target", "msg": "U-Boot> dhcp"}
- {"dt": "2023-11-03T19:44:16.526951", "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-03T19:44:16.533969", "lvl": "target", "msg": "dhcp"}
- {"dt": "2023-11-03T19:44:19.749052", "lvl": "target", "msg": "genet@7d580000 Waiting for PHY auto negotiation to complete....... done"}
- {"dt": "2023-11-03T19:44:19.750800", "lvl": "target", "msg": "BOOTP broadcast 1"}
- {"dt": "2023-11-03T19:44:20.004808", "lvl": "target", "msg": "BOOTP broadcast 2"}
- {"dt": "2023-11-03T19:44:20.499738", "lvl": "target", "msg": "BOOTP broadcast 3"}
- {"dt": "2023-11-03T19:44:21.507186", "lvl": "target", "msg": "BOOTP broadcast 4"}
- {"dt": "2023-11-03T19:44:21.539790", "lvl": "target", "msg": "DHCP client bound to address 192.168.66.241 (1798 ms)"}
- {"dt": "2023-11-03T19:44:21.556261", "lvl": "input", "msg": "setenv serverip 172.21.0.2\n"}
- {"dt": "2023-11-03T19:44:21.658936", "lvl": "target", "msg": "U-Boot> setenv serverip 172.21.0.2"}
- {"dt": "2023-11-03T19:44:21.660995", "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-03T19:44:21.667615", "lvl": "target", "msg": "setenv serverip 172.21.0.2"}
- {"dt": "2023-11-03T19:44:21.669749", "lvl": "input", "msg": "tftp 0x00080000 33256/tftp-deploy-46j4jbol/kernel/Image\n"}
- {"dt": "2023-11-03T19:44:21.771088", "lvl": "target", "msg": "U-Boot> tftp 0x00080000 33256/tftp-deploy-46j4jbol/kernel/Image"}
- {"dt": "2023-11-03T19:44:21.772279", "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-03T19:44:21.779169", "lvl": "target", "msg": "tftp 0x00080000 33256/tftp-deploy-46j4jbol/kernel/Image"}
- {"dt": "2023-11-03T19:44:21.780471", "lvl": "target", "msg": "Using genet@7d580000 device"}
- {"dt": "2023-11-03T19:44:21.803697", "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-03T19:44:21.806997", "lvl": "target", "msg": "Filename '33256/tftp-deploy-46j4jbol/kernel/Image'."}
- {"dt": "2023-11-03T19:44:21.808816", "lvl": "target", "msg": "Load address: 0x80000"}
- {"dt": "2023-11-03T19:45:16.820029", "lvl": "target", "msg": "Loading: *\bT T T T T T T T T T "}
- {"dt": "2023-11-03T19:45:16.821189", "lvl": "target", "msg": "Retry count exceeded; starting again"}
- {"dt": "2023-11-03T19:45:16.822800", "lvl": "exception", "msg": "matched a bootloader error message: 'Retry count exceeded' (4)"}
- {"dt": "2023-11-03T19:45:16.823935", "lvl": "debug", "msg": "end: 2.4.3 bootloader-commands (duration 00:01:01) [common]"}
- {"dt": "2023-11-03T19:45:16.825005", "lvl": "results", "msg": {"case": "bootloader-commands", "definition": "lava", "duration": "60.78", "extra": {"fail": "matched a bootloader error message: 'Retry count exceeded' (4)"}, "level": "2.4.3", "namespace": "common", "result": "fail"}}
- {"dt": "2023-11-03T19:45:16.826445", "lvl": "exception", "msg": "matched a bootloader error message: 'Retry count exceeded' (4)"}
- {"dt": "2023-11-03T19:45:16.827343", "lvl": "debug", "msg": "end: 2.4 uboot-commands (duration 00:01:13) [common]"}
- {"dt": "2023-11-03T19:45:16.828383", "lvl": "results", "msg": {"case": "uboot-commands", "definition": "lava", "duration": "72.54", "extra": {"fail": "matched a bootloader error message: 'Retry count exceeded' (4)"}, "level": "2.4", "namespace": "common", "result": "fail"}}
- {"dt": "2023-11-03T19:45:16.829804", "lvl": "error", "msg": "uboot-action failed: 1 of 1 attempts. 'matched a bootloader error message: 'Retry count exceeded' (4)'"}
- {"dt": "2023-11-03T19:45:16.830636", "lvl": "exception", "msg": "matched a bootloader error message: 'Retry count exceeded' (4)"}
- {"dt": "2023-11-03T19:45:16.831303", "lvl": "info", "msg": "end: 2 uboot-action (duration 00:01:16) [common]"}
- {"dt": "2023-11-03T19:45:16.831930", "lvl": "results", "msg": {"case": "uboot-action", "definition": "lava", "duration": "75.82", "extra": {"fail": "matched a bootloader error message: 'Retry count exceeded' (4)"}, "level": "2", "namespace": "common", "result": "fail"}}
- {"dt": "2023-11-03T19:45:16.833387", "lvl": "info", "msg": "Cleaning after the job"}
- {"dt": "2023-11-03T19:45:16.834332", "lvl": "debug", "msg": "Cleaning up download directory: /var/lib/lava/dispatcher/tmp/33256/tftp-deploy-46j4jbol/ramdisk"}
- {"dt": "2023-11-03T19:45:16.840543", "lvl": "debug", "msg": "Cleaning up download directory: /var/lib/lava/dispatcher/tmp/33256/tftp-deploy-46j4jbol/kernel"}
- {"dt": "2023-11-03T19:45:16.841811", "lvl": "debug", "msg": "Cleaning up download directory: /var/lib/lava/dispatcher/tmp/33256/tftp-deploy-46j4jbol/dtb"}
- {"dt": "2023-11-03T19:45:16.843027", "lvl": "debug", "msg": "Cleaning up download directory: /var/lib/lava/dispatcher/tmp/33256/tftp-deploy-46j4jbol/modules"}
- {"dt": "2023-11-03T19:45:16.854773", "lvl": "debug", "msg": "start: 3.1 power-off (timeout 00:00:30) [common]"}
- {"dt": "2023-11-03T19:45:16.855888", "lvl": "debug", "msg": "Calling: 'nice' '/usr/local/bin/acme-cli' '-s' '192.168.66.2' 'switch_off' '7'"}
- {"dt": "2023-11-03T19:45:20.474275", "lvl": "debug", "msg": ">> Success\r"}
- {"dt": "2023-11-03T19:45:20.514882", "lvl": "debug", "msg": "Returned 0 in 3 seconds"}
- {"dt": "2023-11-03T19:45:20.618069", "lvl": "debug", "msg": "end: 3.1 power-off (duration 00:00:04) [common]"}
- {"dt": "2023-11-03T19:45:20.619682", "lvl": "results", "msg": {"case": "power-off", "definition": "lava", "duration": "3.76", "extra": {"status": "success"}, "level": "3.1", "namespace": "common", "result": "pass"}}
- {"dt": "2023-11-03T19:45:20.622581", "lvl": "debug", "msg": "start: 3.2 read-feedback (timeout 00:09:56) [common]"}
- {"dt": "2023-11-03T19:45:20.625401", "lvl": "debug", "msg": "Listened to connection for namespace 'common' for up to 1s"}
- {"dt": "2023-11-03T19:45:21.628580", "lvl": "info", "msg": "Finalising connection for namespace 'common'"}
- {"dt": "2023-11-03T19:45:21.629589", "lvl": "info", "msg": "Disconnecting from shell: Finalise"}
- {"dt": "2023-11-03T19:45:21.630253", "lvl": "target", "msg": "U-Boot> "}
- {"dt": "2023-11-03T19:45:21.732793", "lvl": "debug", "msg": "end: 3.2 read-feedback (duration 00:00:01) [common]"}
- {"dt": "2023-11-03T19:45:21.733757", "lvl": "info", "msg": "Override tmp directory removed at /var/lib/lava/dispatcher/tmp/33256"}
- {"dt": "2023-11-03T19:45:21.942995", "lvl": "info", "msg": "Root tmp directory removed at /var/lib/lava/dispatcher/tmp/33256"}
- {"dt": "2023-11-03T19:45:21.944121", "lvl": "error", "msg": "InfrastructureError: The Infrastructure is not working correctly. Please report this error to LAVA admins."}
- {"dt": "2023-11-03T19:45:21.945296", "lvl": "results", "msg": {"case": "job", "definition": "lava", "error_msg": "matched a bootloader error message: 'Retry count exceeded' (4)", "error_type": "Infrastructure", "result": "fail"}}
