- {"dt": "2024-08-31T08:56:34.833328", "lvl": "info", "msg": "lava-dispatcher, installed at version: 2023.10"}
- {"dt": "2024-08-31T08:56:34.834837", "lvl": "info", "msg": "start: 0 validate"}
- {"dt": "2024-08-31T08:56:34.835962", "lvl": "info", "msg": "Start time: 2024-08-31 08:56:34.835907+00:00 (UTC)"}
- {"dt": "2024-08-31T08:56:34.837193", "lvl": "debug", "msg": "Validating that https://github.com/montjoie/lava-healthchecks-binary/blob/master/images/rootfs/buildroot/buildroot-baseline/20230623.0/riscv/rootfs.cpio.gz?raw=true exists"}
- {"dt": "2024-08-31T08:56:36.462419", "lvl": "debug", "msg": "Validating that https://github.com/montjoie/lava-healthchecks-binary/blob/master/stable/linux-6.1.y/v6.1.54/riscv/defconfig/gcc-10/kernel/Image?raw=true exists"}
- {"dt": "2024-08-31T08:56:38.594346", "lvl": "debug", "msg": "Validating that https://github.com/montjoie/lava-healthchecks-binary/blob/master/stable/linux-6.1.y/v6.1.54/riscv/defconfig/gcc-10/dtbs/sifive/hifive-unmatched-a00.dtb?raw=true exists"}
- {"dt": "2024-08-31T08:56:39.290451", "lvl": "debug", "msg": "Validating that https://github.com/montjoie/lava-healthchecks-binary/blob/master/stable/linux-6.1.y/v6.1.54/riscv/defconfig/gcc-10/modules.tar.xz?raw=true exists"}
- {"dt": "2024-08-31T08:56:40.391187", "lvl": "info", "msg": "validate duration: 5.56"}
- {"dt": "2024-08-31T08:56:40.392065", "lvl": "results", "msg": {"case": "validate", "definition": "lava", "result": "pass"}}
- {"dt": "2024-08-31T08:56:40.393163", "lvl": "info", "msg": "start: 1 tftp-deploy (timeout 00:10:00) [common]"}
- {"dt": "2024-08-31T08:56:40.393975", "lvl": "debug", "msg": "start: 1.1 download-retry (timeout 00:10:00) [common]"}
- {"dt": "2024-08-31T08:56:40.394751", "lvl": "debug", "msg": "start: 1.1.1 http-download (timeout 00:10:00) [common]"}
- {"dt": "2024-08-31T08:56:40.395847", "lvl": "debug", "msg": "Not decompressing ramdisk as can be used compressed."}
- {"dt": "2024-08-31T08:56:40.396655", "lvl": "info", "msg": "downloading https://github.com/montjoie/lava-healthchecks-binary/blob/master/images/rootfs/buildroot/buildroot-baseline/20230623.0/riscv/rootfs.cpio.gz?raw=true"}
- {"dt": "2024-08-31T08:56:40.397216", "lvl": "debug", "msg": "saving as /var/lib/lava/dispatcher/tmp/36204/tftp-deploy-3pnphz2a/ramdisk/rootfs.cpio.gz"}
- {"dt": "2024-08-31T08:56:40.397794", "lvl": "debug", "msg": "total size: 7844224 (7\u202FMB)"}
- {"dt": "2024-08-31T08:56:40.896385", "lvl": "debug", "msg": "progress   0\u202F% (0\u202FMB)"}
- {"dt": "2024-08-31T08:56:41.113087", "lvl": "debug", "msg": "progress   5\u202F% (0\u202FMB)"}
- {"dt": "2024-08-31T08:56:41.280918", "lvl": "debug", "msg": "progress  10\u202F% (0\u202FMB)"}
- {"dt": "2024-08-31T08:56:41.408916", "lvl": "debug", "msg": "progress  15\u202F% (1\u202FMB)"}
- {"dt": "2024-08-31T08:56:41.527869", "lvl": "debug", "msg": "progress  20\u202F% (1\u202FMB)"}
- {"dt": "2024-08-31T08:56:41.640251", "lvl": "debug", "msg": "progress  25\u202F% (1\u202FMB)"}
- {"dt": "2024-08-31T08:56:41.742846", "lvl": "debug", "msg": "progress  30\u202F% (2\u202FMB)"}
- {"dt": "2024-08-31T08:56:41.839546", "lvl": "debug", "msg": "progress  35\u202F% (2\u202FMB)"}
- {"dt": "2024-08-31T08:56:41.931743", "lvl": "debug", "msg": "progress  40\u202F% (3\u202FMB)"}
- {"dt": "2024-08-31T08:56:42.022272", "lvl": "debug", "msg": "progress  45\u202F% (3\u202FMB)"}
- {"dt": "2024-08-31T08:56:42.139405", "lvl": "debug", "msg": "progress  50\u202F% (3\u202FMB)"}
- {"dt": "2024-08-31T08:56:42.225043", "lvl": "debug", "msg": "progress  55\u202F% (4\u202FMB)"}
- {"dt": "2024-08-31T08:56:42.304078", "lvl": "debug", "msg": "progress  60\u202F% (4\u202FMB)"}
- {"dt": "2024-08-31T08:56:42.403227", "lvl": "debug", "msg": "progress  65\u202F% (4\u202FMB)"}
- {"dt": "2024-08-31T08:56:42.494600", "lvl": "debug", "msg": "progress  70\u202F% (5\u202FMB)"}
- {"dt": "2024-08-31T08:56:42.571772", "lvl": "debug", "msg": "progress  75\u202F% (5\u202FMB)"}
- {"dt": "2024-08-31T08:56:42.655916", "lvl": "debug", "msg": "progress  80\u202F% (6\u202FMB)"}
- {"dt": "2024-08-31T08:56:42.785982", "lvl": "debug", "msg": "progress  85\u202F% (6\u202FMB)"}
- {"dt": "2024-08-31T08:56:42.883763", "lvl": "debug", "msg": "progress  90\u202F% (6\u202FMB)"}
- {"dt": "2024-08-31T08:56:42.958437", "lvl": "debug", "msg": "progress  95\u202F% (7\u202FMB)"}
- {"dt": "2024-08-31T08:56:43.036307", "lvl": "debug", "msg": "progress 100\u202F% (7\u202FMB)"}
- {"dt": "2024-08-31T08:56:43.037717", "lvl": "info", "msg": "7\u202FMB downloaded in 2.64\u202Fs (2.83\u202FMB/s)"}
- {"dt": "2024-08-31T08:56:43.038858", "lvl": "debug", "msg": "end: 1.1.1 http-download (duration 00:00:03) [common]"}
- {"dt": "2024-08-31T08:56:43.039567", "lvl": "results", "msg": {"case": "http-download", "definition": "lava", "duration": "2.64", "extra": {"label": "ramdisk", "md5sum": "4bbb32813cb05021df34cefcbb385507", "sha256sum": "5a9577755f4c03de73672a1f7d73d1fefcc1af9c766e4815d716d23495f74ed8", "sha512sum": "b435cc3fbbdc57e455d0c13d9dcec3969dcf4e26cee57fa102df8b82e1a4e9b739f026cc19905db282fd50a3187a6e143709e111a847d8c8ff9d38fba0434aa8", "size": ! "7844224"}, "level": "1.1.1", "namespace": "common", "result": "pass"}}
- {"dt": "2024-08-31T08:56:43.040990", "lvl": "debug", "msg": "end: 1.1 download-retry (duration 00:00:03) [common]"}
- {"dt": "2024-08-31T08:56:43.041791", "lvl": "debug", "msg": "start: 1.2 download-retry (timeout 00:09:57) [common]"}
- {"dt": "2024-08-31T08:56:43.042473", "lvl": "debug", "msg": "start: 1.2.1 http-download (timeout 00:09:57) [common]"}
- {"dt": "2024-08-31T08:56:43.043592", "lvl": "info", "msg": "downloading https://github.com/montjoie/lava-healthchecks-binary/blob/master/stable/linux-6.1.y/v6.1.54/riscv/defconfig/gcc-10/kernel/Image?raw=true"}
- {"dt": "2024-08-31T08:56:43.044226", "lvl": "debug", "msg": "saving as /var/lib/lava/dispatcher/tmp/36204/tftp-deploy-3pnphz2a/kernel/Image"}
- {"dt": "2024-08-31T08:56:43.046224", "lvl": "debug", "msg": "total size: 19845120 (18\u202FMB)"}
- {"dt": "2024-08-31T08:56:43.048206", "lvl": "debug", "msg": "No compression specified"}
- {"dt": "2024-08-31T08:56:44.207907", "lvl": "debug", "msg": "progress   0\u202F% (0\u202FMB)"}
- {"dt": "2024-08-31T08:56:44.360832", "lvl": "debug", "msg": "progress   5\u202F% (0\u202FMB)"}
- {"dt": "2024-08-31T08:56:44.504662", "lvl": "debug", "msg": "progress  10\u202F% (1\u202FMB)"}
- {"dt": "2024-08-31T08:56:44.644308", "lvl": "debug", "msg": "progress  15\u202F% (2\u202FMB)"}
- {"dt": "2024-08-31T08:56:44.779537", "lvl": "debug", "msg": "progress  20\u202F% (3\u202FMB)"}
- {"dt": "2024-08-31T08:56:44.909666", "lvl": "debug", "msg": "progress  25\u202F% (4\u202FMB)"}
- {"dt": "2024-08-31T08:56:45.039367", "lvl": "debug", "msg": "progress  30\u202F% (5\u202FMB)"}
- {"dt": "2024-08-31T08:56:45.159146", "lvl": "debug", "msg": "progress  35\u202F% (6\u202FMB)"}
- {"dt": "2024-08-31T08:56:45.278859", "lvl": "debug", "msg": "progress  40\u202F% (7\u202FMB)"}
- {"dt": "2024-08-31T08:56:45.392590", "lvl": "debug", "msg": "progress  45\u202F% (8\u202FMB)"}
- {"dt": "2024-08-31T08:56:45.507869", "lvl": "debug", "msg": "progress  50\u202F% (9\u202FMB)"}
- {"dt": "2024-08-31T08:56:45.620603", "lvl": "debug", "msg": "progress  55\u202F% (10\u202FMB)"}
- {"dt": "2024-08-31T08:56:45.731392", "lvl": "debug", "msg": "progress  60\u202F% (11\u202FMB)"}
- {"dt": "2024-08-31T08:56:45.845905", "lvl": "debug", "msg": "progress  65\u202F% (12\u202FMB)"}
- {"dt": "2024-08-31T08:56:45.960506", "lvl": "debug", "msg": "progress  70\u202F% (13\u202FMB)"}
- {"dt": "2024-08-31T08:56:46.083404", "lvl": "debug", "msg": "progress  75\u202F% (14\u202FMB)"}
- {"dt": "2024-08-31T08:56:46.184973", "lvl": "debug", "msg": "progress  80\u202F% (15\u202FMB)"}
- {"dt": "2024-08-31T08:56:46.283831", "lvl": "debug", "msg": "progress  85\u202F% (16\u202FMB)"}
- {"dt": "2024-08-31T08:56:46.391132", "lvl": "debug", "msg": "progress  90\u202F% (17\u202FMB)"}
- {"dt": "2024-08-31T08:56:46.491935", "lvl": "debug", "msg": "progress  95\u202F% (18\u202FMB)"}
- {"dt": "2024-08-31T08:56:46.589209", "lvl": "debug", "msg": "progress 100\u202F% (18\u202FMB)"}
- {"dt": "2024-08-31T08:56:46.590813", "lvl": "info", "msg": "18\u202FMB downloaded in 3.54\u202Fs (5.34\u202FMB/s)"}
- {"dt": "2024-08-31T08:56:46.591979", "lvl": "debug", "msg": "end: 1.2.1 http-download (duration 00:00:04) [common]"}
- {"dt": "2024-08-31T08:56:46.592702", "lvl": "results", "msg": {"case": "http-download", "definition": "lava", "duration": "3.55", "extra": {"label": "kernel", "md5sum": "bc353ea01eab589bb4cd6918b0d126de", "sha256sum": "8a98e42d83b971b3f17b23f2fded633f8d3c97ef956efe6ee5d6edd727f87ee1", "sha512sum": "4cad13e71faae976b6b963587c809e948943cb1a76d6655667aac8f154e7068fccb3b3a1191ff00b29dd63f0e46a7b939ed0c46d4edda16d7e9efa5acf87b65b", "size": ! "19845120"}, "level": "1.2.1", "namespace": "common", "result": "pass"}}
- {"dt": "2024-08-31T08:56:46.594112", "lvl": "debug", "msg": "end: 1.2 download-retry (duration 00:00:04) [common]"}
- {"dt": "2024-08-31T08:56:46.596551", "lvl": "debug", "msg": "start: 1.3 download-retry (timeout 00:09:54) [common]"}
- {"dt": "2024-08-31T08:56:46.597422", "lvl": "debug", "msg": "start: 1.3.1 http-download (timeout 00:09:54) [common]"}
- {"dt": "2024-08-31T08:56:46.598469", "lvl": "info", "msg": "downloading https://github.com/montjoie/lava-healthchecks-binary/blob/master/stable/linux-6.1.y/v6.1.54/riscv/defconfig/gcc-10/dtbs/sifive/hifive-unmatched-a00.dtb?raw=true"}
- {"dt": "2024-08-31T08:56:46.599150", "lvl": "debug", "msg": "saving as /var/lib/lava/dispatcher/tmp/36204/tftp-deploy-3pnphz2a/dtb/hifive-unmatched-a00.dtb"}
- {"dt": "2024-08-31T08:56:46.599695", "lvl": "debug", "msg": "total size: 10707 (0\u202FMB)"}
- {"dt": "2024-08-31T08:56:46.600229", "lvl": "debug", "msg": "No compression specified"}
- {"dt": "2024-08-31T08:56:47.081295", "lvl": "debug", "msg": "progress 100\u202F% (0\u202FMB)"}
- {"dt": "2024-08-31T08:56:47.082685", "lvl": "info", "msg": "0\u202FMB downloaded in 0.48\u202Fs (0.02\u202FMB/s)"}
- {"dt": "2024-08-31T08:56:47.084019", "lvl": "debug", "msg": "end: 1.3.1 http-download (duration 00:00:00) [common]"}
- {"dt": "2024-08-31T08:56:47.084671", "lvl": "results", "msg": {"case": "http-download", "definition": "lava", "duration": "0.49", "extra": {"label": "dtb", "md5sum": "6e4ede97cac7e574ba154868ae6bd490", "sha256sum": "bfd83286eab97548a6663437655c0c6805a361a06c726c439b8d9655be38d15b", "sha512sum": "429c70a390d17dc993647232bfa0333fdf25e66e87f05676252174f698e925e876ddf6b1e722bfdedaf8fd299f71a19b2c8c383eade9bf4df01262d0773fd702", "size": ! "10707"}, "level": "1.3.1", "namespace": "common", "result": "pass"}}
- {"dt": "2024-08-31T08:56:47.086078", "lvl": "debug", "msg": "end: 1.3 download-retry (duration 00:00:00) [common]"}
- {"dt": "2024-08-31T08:56:47.086836", "lvl": "debug", "msg": "start: 1.4 download-retry (timeout 00:09:53) [common]"}
- {"dt": "2024-08-31T08:56:47.087582", "lvl": "debug", "msg": "start: 1.4.1 http-download (timeout 00:09:53) [common]"}
- {"dt": "2024-08-31T08:56:47.088649", "lvl": "info", "msg": "downloading https://github.com/montjoie/lava-healthchecks-binary/blob/master/stable/linux-6.1.y/v6.1.54/riscv/defconfig/gcc-10/modules.tar.xz?raw=true"}
- {"dt": "2024-08-31T08:56:47.089302", "lvl": "debug", "msg": "saving as /var/lib/lava/dispatcher/tmp/36204/tftp-deploy-3pnphz2a/modules/modules.tar"}
- {"dt": "2024-08-31T08:56:47.089809", "lvl": "debug", "msg": "total size: 3892756 (3\u202FMB)"}
- {"dt": "2024-08-31T08:56:47.090366", "lvl": "info", "msg": "Using unxz to decompress xz"}
- {"dt": "2024-08-31T08:56:47.625178", "lvl": "debug", "msg": "progress   0\u202F% (0\u202FMB)"}
- {"dt": "2024-08-31T08:56:47.658585", "lvl": "debug", "msg": "progress   5\u202F% (0\u202FMB)"}
- {"dt": "2024-08-31T08:56:47.726030", "lvl": "debug", "msg": "progress  10\u202F% (0\u202FMB)"}
- {"dt": "2024-08-31T08:56:47.791415", "lvl": "debug", "msg": "progress  15\u202F% (0\u202FMB)"}
- {"dt": "2024-08-31T08:56:47.880958", "lvl": "debug", "msg": "progress  20\u202F% (0\u202FMB)"}
- {"dt": "2024-08-31T08:56:48.024244", "lvl": "debug", "msg": "progress  25\u202F% (0\u202FMB)"}
- {"dt": "2024-08-31T08:56:48.161706", "lvl": "debug", "msg": "progress  30\u202F% (1\u202FMB)"}
- {"dt": "2024-08-31T08:56:48.272304", "lvl": "debug", "msg": "progress  35\u202F% (1\u202FMB)"}
- {"dt": "2024-08-31T08:56:48.405771", "lvl": "debug", "msg": "progress  40\u202F% (1\u202FMB)"}
- {"dt": "2024-08-31T08:56:48.481438", "lvl": "debug", "msg": "progress  45\u202F% (1\u202FMB)"}
- {"dt": "2024-08-31T08:56:48.555963", "lvl": "debug", "msg": "progress  50\u202F% (1\u202FMB)"}
- {"dt": "2024-08-31T08:56:48.639107", "lvl": "debug", "msg": "progress  55\u202F% (2\u202FMB)"}
- {"dt": "2024-08-31T08:56:48.734826", "lvl": "debug", "msg": "progress  60\u202F% (2\u202FMB)"}
- {"dt": "2024-08-31T08:56:48.810080", "lvl": "debug", "msg": "progress  65\u202F% (2\u202FMB)"}
- {"dt": "2024-08-31T08:56:48.885243", "lvl": "debug", "msg": "progress  70\u202F% (2\u202FMB)"}
- {"dt": "2024-08-31T08:56:48.948263", "lvl": "debug", "msg": "progress  75\u202F% (2\u202FMB)"}
- {"dt": "2024-08-31T08:56:49.021074", "lvl": "debug", "msg": "progress  80\u202F% (3\u202FMB)"}
- {"dt": "2024-08-31T08:56:49.090383", "lvl": "debug", "msg": "progress  85\u202F% (3\u202FMB)"}
- {"dt": "2024-08-31T08:56:49.171243", "lvl": "debug", "msg": "progress  90\u202F% (3\u202FMB)"}
- {"dt": "2024-08-31T08:56:49.240837", "lvl": "debug", "msg": "progress  95\u202F% (3\u202FMB)"}
- {"dt": "2024-08-31T08:56:49.309189", "lvl": "debug", "msg": "progress 100\u202F% (3\u202FMB)"}
- {"dt": "2024-08-31T08:56:49.349886", "lvl": "info", "msg": "3\u202FMB downloaded in 2.26\u202Fs (1.64\u202FMB/s)"}
- {"dt": "2024-08-31T08:56:49.351480", "lvl": "debug", "msg": "end: 1.4.1 http-download (duration 00:00:02) [common]"}
- {"dt": "2024-08-31T08:56:49.352418", "lvl": "results", "msg": {"case": "http-download", "definition": "lava", "duration": "2.26", "extra": {"label": "modules", "md5sum": "bd526ab1d1394350f02fce39169fd3ed", "sha256sum": "3adbbae160cc6e797e09f2ec6df9c6c848d48f6451e75131e278b4f8dc96bb3b", "sha512sum": "94ab1014e55f1dc62ed235004bd221efcacdbad3af4ff6cb191ec3007be7588b46db84f73d3a3f0da7d101fa96ae93c4dc51fe8a49d2b43b50fcf42e95b38c7f", "size": ! "3892756"}, "level": "1.4.1", "namespace": "common", "result": "pass"}}
- {"dt": "2024-08-31T08:56:49.354458", "lvl": "debug", "msg": "end: 1.4 download-retry (duration 00:00:02) [common]"}
- {"dt": "2024-08-31T08:56:49.355679", "lvl": "debug", "msg": "start: 1.5 prepare-tftp-overlay (timeout 00:09:51) [common]"}
- {"dt": "2024-08-31T08:56:49.356756", "lvl": "debug", "msg": "start: 1.5.1 extract-nfsrootfs (timeout 00:09:51) [common]"}
- {"dt": "2024-08-31T08:56:49.357810", "lvl": "debug", "msg": "end: 1.5.1 extract-nfsrootfs (duration 00:00:00) [common]"}
- {"dt": "2024-08-31T08:56:49.358879", "lvl": "debug", "msg": "start: 1.5.2 lava-overlay (timeout 00:09:51) [common]"}
- {"dt": "2024-08-31T08:56:49.360804", "lvl": "debug", "msg": "[common] Preparing overlay tarball in /var/lib/lava/dispatcher/tmp/36204/lava-overlay-3prkydl1"}
- {"dt": "2024-08-31T08:56:49.362478", "lvl": "debug", "msg": "makedir: /var/lib/lava/dispatcher/tmp/36204/lava-overlay-3prkydl1/lava-36204/bin"}
- {"dt": "2024-08-31T08:56:49.363960", "lvl": "debug", "msg": "makedir: /var/lib/lava/dispatcher/tmp/36204/lava-overlay-3prkydl1/lava-36204/tests"}
- {"dt": "2024-08-31T08:56:49.365428", "lvl": "debug", "msg": "makedir: /var/lib/lava/dispatcher/tmp/36204/lava-overlay-3prkydl1/lava-36204/results"}
- {"dt": "2024-08-31T08:56:49.366740", "lvl": "debug", "msg": "Creating /var/lib/lava/dispatcher/tmp/36204/lava-overlay-3prkydl1/lava-36204/bin/lava-add-keys"}
- {"dt": "2024-08-31T08:56:49.368708", "lvl": "debug", "msg": "Creating /var/lib/lava/dispatcher/tmp/36204/lava-overlay-3prkydl1/lava-36204/bin/lava-add-sources"}
- {"dt": "2024-08-31T08:56:49.370608", "lvl": "debug", "msg": "Creating /var/lib/lava/dispatcher/tmp/36204/lava-overlay-3prkydl1/lava-36204/bin/lava-background-process-start"}
- {"dt": "2024-08-31T08:56:49.372529", "lvl": "debug", "msg": "Creating /var/lib/lava/dispatcher/tmp/36204/lava-overlay-3prkydl1/lava-36204/bin/lava-background-process-stop"}
- {"dt": "2024-08-31T08:56:49.374742", "lvl": "debug", "msg": "Creating /var/lib/lava/dispatcher/tmp/36204/lava-overlay-3prkydl1/lava-36204/bin/lava-common-functions"}
- {"dt": "2024-08-31T08:56:49.376716", "lvl": "debug", "msg": "Creating /var/lib/lava/dispatcher/tmp/36204/lava-overlay-3prkydl1/lava-36204/bin/lava-echo-ipv4"}
- {"dt": "2024-08-31T08:56:49.378613", "lvl": "debug", "msg": "Creating /var/lib/lava/dispatcher/tmp/36204/lava-overlay-3prkydl1/lava-36204/bin/lava-install-packages"}
- {"dt": "2024-08-31T08:56:49.380587", "lvl": "debug", "msg": "Creating /var/lib/lava/dispatcher/tmp/36204/lava-overlay-3prkydl1/lava-36204/bin/lava-installed-packages"}
- {"dt": "2024-08-31T08:56:49.382478", "lvl": "debug", "msg": "Creating /var/lib/lava/dispatcher/tmp/36204/lava-overlay-3prkydl1/lava-36204/bin/lava-os-build"}
- {"dt": "2024-08-31T08:56:49.384424", "lvl": "debug", "msg": "Creating /var/lib/lava/dispatcher/tmp/36204/lava-overlay-3prkydl1/lava-36204/bin/lava-probe-channel"}
- {"dt": "2024-08-31T08:56:49.386324", "lvl": "debug", "msg": "Creating /var/lib/lava/dispatcher/tmp/36204/lava-overlay-3prkydl1/lava-36204/bin/lava-probe-ip"}
- {"dt": "2024-08-31T08:56:49.388293", "lvl": "debug", "msg": "Creating /var/lib/lava/dispatcher/tmp/36204/lava-overlay-3prkydl1/lava-36204/bin/lava-target-ip"}
- {"dt": "2024-08-31T08:56:49.390176", "lvl": "debug", "msg": "Creating /var/lib/lava/dispatcher/tmp/36204/lava-overlay-3prkydl1/lava-36204/bin/lava-target-mac"}
- {"dt": "2024-08-31T08:56:49.392186", "lvl": "debug", "msg": "Creating /var/lib/lava/dispatcher/tmp/36204/lava-overlay-3prkydl1/lava-36204/bin/lava-target-storage"}
- {"dt": "2024-08-31T08:56:49.394185", "lvl": "debug", "msg": "Creating /var/lib/lava/dispatcher/tmp/36204/lava-overlay-3prkydl1/lava-36204/bin/lava-test-case"}
- {"dt": "2024-08-31T08:56:49.396232", "lvl": "debug", "msg": "Creating /var/lib/lava/dispatcher/tmp/36204/lava-overlay-3prkydl1/lava-36204/bin/lava-test-event"}
- {"dt": "2024-08-31T08:56:49.398133", "lvl": "debug", "msg": "Creating /var/lib/lava/dispatcher/tmp/36204/lava-overlay-3prkydl1/lava-36204/bin/lava-test-feedback"}
- {"dt": "2024-08-31T08:56:49.400055", "lvl": "debug", "msg": "Creating /var/lib/lava/dispatcher/tmp/36204/lava-overlay-3prkydl1/lava-36204/bin/lava-test-raise"}
- {"dt": "2024-08-31T08:56:49.401980", "lvl": "debug", "msg": "Creating /var/lib/lava/dispatcher/tmp/36204/lava-overlay-3prkydl1/lava-36204/bin/lava-test-reference"}
- {"dt": "2024-08-31T08:56:49.404068", "lvl": "debug", "msg": "Creating /var/lib/lava/dispatcher/tmp/36204/lava-overlay-3prkydl1/lava-36204/bin/lava-test-runner"}
- {"dt": "2024-08-31T08:56:49.405923", "lvl": "debug", "msg": "Creating /var/lib/lava/dispatcher/tmp/36204/lava-overlay-3prkydl1/lava-36204/bin/lava-test-set"}
- {"dt": "2024-08-31T08:56:49.408201", "lvl": "debug", "msg": "Creating /var/lib/lava/dispatcher/tmp/36204/lava-overlay-3prkydl1/lava-36204/bin/lava-test-shell"}
- {"dt": "2024-08-31T08:56:49.410482", "lvl": "debug", "msg": "Updating /var/lib/lava/dispatcher/tmp/36204/lava-overlay-3prkydl1/lava-36204/bin/lava-install-packages (oe)"}
- {"dt": "2024-08-31T08:56:49.412834", "lvl": "debug", "msg": "Updating /var/lib/lava/dispatcher/tmp/36204/lava-overlay-3prkydl1/lava-36204/bin/lava-installed-packages (oe)"}
- {"dt": "2024-08-31T08:56:49.415158", "lvl": "debug", "msg": "Creating /var/lib/lava/dispatcher/tmp/36204/lava-overlay-3prkydl1/lava-36204/environment"}
- {"dt": "2024-08-31T08:56:49.416679", "lvl": "debug", "msg": "LAVA metadata"}
- {"dt": "2024-08-31T08:56:49.417627", "lvl": "debug", "msg": "- LAVA_JOB_ID=36204"}
- {"dt": "2024-08-31T08:56:49.418507", "lvl": "debug", "msg": "- LAVA_DISPATCHER_IP=192.168.66.1"}
- {"dt": "2024-08-31T08:56:49.420015", "lvl": "debug", "msg": "start: 1.5.2.1 ssh-authorize (timeout 00:09:51) [common]"}
- {"dt": "2024-08-31T08:56:49.423664", "lvl": "debug", "msg": "end: 1.5.2.1 ssh-authorize (duration 00:00:00) [common]"}
- {"dt": "2024-08-31T08:56:49.424736", "lvl": "debug", "msg": "start: 1.5.2.2 lava-vland-overlay (timeout 00:09:51) [common]"}
- {"dt": "2024-08-31T08:56:49.425608", "lvl": "debug", "msg": "skipped lava-vland-overlay"}
- {"dt": "2024-08-31T08:56:49.426588", "lvl": "debug", "msg": "end: 1.5.2.2 lava-vland-overlay (duration 00:00:00) [common]"}
- {"dt": "2024-08-31T08:56:49.427765", "lvl": "debug", "msg": "start: 1.5.2.3 lava-multinode-overlay (timeout 00:09:51) [common]"}
- {"dt": "2024-08-31T08:56:49.428538", "lvl": "debug", "msg": "skipped lava-multinode-overlay"}
- {"dt": "2024-08-31T08:56:49.429515", "lvl": "debug", "msg": "end: 1.5.2.3 lava-multinode-overlay (duration 00:00:00) [common]"}
- {"dt": "2024-08-31T08:56:49.430602", "lvl": "debug", "msg": "start: 1.5.2.4 test-definition (timeout 00:09:51) [common]"}
- {"dt": "2024-08-31T08:56:49.431556", "lvl": "info", "msg": "Loading test definitions"}
- {"dt": "2024-08-31T08:56:49.432665", "lvl": "debug", "msg": "start: 1.5.2.4.1 inline-repo-action (timeout 00:09:51) [common]"}
- {"dt": "2024-08-31T08:56:49.433557", "lvl": "debug", "msg": "Using /lava-36204 at stage 0"}
- {"dt": "2024-08-31T08:56:49.437390", "lvl": "debug", "msg": "uuid=36204_1.5.2.4.1 testdef=None"}
- {"dt": "2024-08-31T08:56:49.438444", "lvl": "debug", "msg": "end: 1.5.2.4.1 inline-repo-action (duration 00:00:00) [common]"}
- {"dt": "2024-08-31T08:56:49.439518", "lvl": "debug", "msg": "start: 1.5.2.4.2 test-overlay (timeout 00:09:51) [common]"}
- {"dt": "2024-08-31T08:56:49.445605", "lvl": "debug", "msg": "end: 1.5.2.4.2 test-overlay (duration 00:00:00) [common]"}
- {"dt": "2024-08-31T08:56:49.446462", "lvl": "results", "msg": {"case": "test-overlay", "definition": "lava", "duration": "0.01", "extra": {"from": "inline", "name": "dmesg", "path": "inline/dmesg.yaml", "uuid": "36204_1.5.2.4.1"}, "level": "1.5.2.4.2", "namespace": "common", "result": "pass"}}
- {"dt": "2024-08-31T08:56:49.448414", "lvl": "debug", "msg": "start: 1.5.2.4.3 test-install-overlay (timeout 00:09:51) [common]"}
- {"dt": "2024-08-31T08:56:49.456591", "lvl": "debug", "msg": "end: 1.5.2.4.3 test-install-overlay (duration 00:00:00) [common]"}
- {"dt": "2024-08-31T08:56:49.457523", "lvl": "results", "msg": {"case": "test-install-overlay", "definition": "lava", "duration": "0.01", "extra": {"from": "inline", "name": "dmesg", "path": "inline/dmesg.yaml", "skipped test-install-overlay": "36204_1.5.2.4.1", "uuid": "36204_1.5.2.4.1"}, "level": "1.5.2.4.3", "namespace": "common", "result": "pass"}}
- {"dt": "2024-08-31T08:56:49.459487", "lvl": "debug", "msg": "start: 1.5.2.4.4 test-runscript-overlay (timeout 00:09:51) [common]"}
- {"dt": "2024-08-31T08:56:49.467402", "lvl": "debug", "msg": "runner path: /var/lib/lava/dispatcher/tmp/36204/lava-overlay-3prkydl1/lava-36204/0/tests/0_dmesg test_uuid 36204_1.5.2.4.1"}
- {"dt": "2024-08-31T08:56:49.469436", "lvl": "debug", "msg": "end: 1.5.2.4.4 test-runscript-overlay (duration 00:00:00) [common]"}
- {"dt": "2024-08-31T08:56:49.470333", "lvl": "results", "msg": {"case": "test-runscript-overlay", "definition": "lava", "duration": "0.01", "extra": {"filename": "/var/lib/lava/dispatcher/tmp/36204/lava-overlay-3prkydl1/lava-36204/0/tests/0_dmesg/run.sh", "from": "inline", "name": "dmesg", "path": "inline/dmesg.yaml", "uuid": "36204_1.5.2.4.1"}, "level": "1.5.2.4.4", "namespace": "common", "result": "pass"}}
- {"dt": "2024-08-31T08:56:49.472168", "lvl": "debug", "msg": "start: 1.5.2.4.5 inline-repo-action (timeout 00:09:51) [common]"}
- {"dt": "2024-08-31T08:56:49.473087", "lvl": "debug", "msg": "Using /lava-36204 at stage 1"}
- {"dt": "2024-08-31T08:56:49.476881", "lvl": "debug", "msg": "uuid=36204_1.5.2.4.5 testdef=None"}
- {"dt": "2024-08-31T08:56:49.477930", "lvl": "debug", "msg": "end: 1.5.2.4.5 inline-repo-action (duration 00:00:00) [common]"}
- {"dt": "2024-08-31T08:56:49.479014", "lvl": "debug", "msg": "start: 1.5.2.4.6 test-overlay (timeout 00:09:51) [common]"}
- {"dt": "2024-08-31T08:56:49.485077", "lvl": "debug", "msg": "end: 1.5.2.4.6 test-overlay (duration 00:00:00) [common]"}
- {"dt": "2024-08-31T08:56:49.485913", "lvl": "results", "msg": {"case": "test-overlay", "definition": "lava", "duration": "0.01", "extra": {"from": "inline", "name": "bootrr", "path": "inline/bootrr.yaml", "uuid": "36204_1.5.2.4.5"}, "level": "1.5.2.4.6", "namespace": "common", "result": "pass"}}
- {"dt": "2024-08-31T08:56:49.487774", "lvl": "debug", "msg": "start: 1.5.2.4.7 test-install-overlay (timeout 00:09:51) [common]"}
- {"dt": "2024-08-31T08:56:49.496018", "lvl": "debug", "msg": "end: 1.5.2.4.7 test-install-overlay (duration 00:00:00) [common]"}
- {"dt": "2024-08-31T08:56:49.496923", "lvl": "results", "msg": {"case": "test-install-overlay", "definition": "lava", "duration": "0.01", "extra": {"from": "inline", "name": "bootrr", "path": "inline/bootrr.yaml", "skipped test-install-overlay": "36204_1.5.2.4.5", "uuid": "36204_1.5.2.4.5"}, "level": "1.5.2.4.7", "namespace": "common", "result": "pass"}}
- {"dt": "2024-08-31T08:56:49.499044", "lvl": "debug", "msg": "start: 1.5.2.4.8 test-runscript-overlay (timeout 00:09:51) [common]"}
- {"dt": "2024-08-31T08:56:49.514296", "lvl": "debug", "msg": "runner path: /var/lib/lava/dispatcher/tmp/36204/lava-overlay-3prkydl1/lava-36204/1/tests/1_bootrr test_uuid 36204_1.5.2.4.5"}
- {"dt": "2024-08-31T08:56:49.515872", "lvl": "debug", "msg": "end: 1.5.2.4.8 test-runscript-overlay (duration 00:00:00) [common]"}
- {"dt": "2024-08-31T08:56:49.516579", "lvl": "results", "msg": {"case": "test-runscript-overlay", "definition": "lava", "duration": "0.02", "extra": {"filename": "/var/lib/lava/dispatcher/tmp/36204/lava-overlay-3prkydl1/lava-36204/1/tests/1_bootrr/run.sh", "from": "inline", "name": "bootrr", "path": "inline/bootrr.yaml", "uuid": "36204_1.5.2.4.5"}, "level": "1.5.2.4.8", "namespace": "common", "result": "pass"}}
- {"dt": "2024-08-31T08:56:49.517852", "lvl": "info", "msg": "Creating lava-test-runner.conf files"}
- {"dt": "2024-08-31T08:56:49.518449", "lvl": "debug", "msg": "Using lava-test-runner path: /var/lib/lava/dispatcher/tmp/36204/lava-overlay-3prkydl1/lava-36204/0 for stage 0"}
- {"dt": "2024-08-31T08:56:49.519446", "lvl": "debug", "msg": "- 0_dmesg"}
- {"dt": "2024-08-31T08:56:49.520310", "lvl": "debug", "msg": "Using lava-test-runner path: /var/lib/lava/dispatcher/tmp/36204/lava-overlay-3prkydl1/lava-36204/1 for stage 1"}
- {"dt": "2024-08-31T08:56:49.521349", "lvl": "debug", "msg": "- 1_bootrr"}
- {"dt": "2024-08-31T08:56:49.522376", "lvl": "debug", "msg": "end: 1.5.2.4 test-definition (duration 00:00:00) [common]"}
- {"dt": "2024-08-31T08:56:49.523273", "lvl": "debug", "msg": "start: 1.5.2.5 compress-overlay (timeout 00:09:51) [common]"}
- {"dt": "2024-08-31T08:56:49.589002", "lvl": "debug", "msg": "end: 1.5.2.5 compress-overlay (duration 00:00:00) [common]"}
- {"dt": "2024-08-31T08:56:49.589957", "lvl": "debug", "msg": "start: 1.5.2.6 persistent-nfs-overlay (timeout 00:09:51) [common]"}
- {"dt": "2024-08-31T08:56:49.590792", "lvl": "debug", "msg": "end: 1.5.2.6 persistent-nfs-overlay (duration 00:00:00) [common]"}
- {"dt": "2024-08-31T08:56:49.591688", "lvl": "debug", "msg": "end: 1.5.2 lava-overlay (duration 00:00:00) [common]"}
- {"dt": "2024-08-31T08:56:49.592532", "lvl": "debug", "msg": "start: 1.5.3 extract-overlay-ramdisk (timeout 00:09:51) [common]"}
- {"dt": "2024-08-31T08:56:52.182823", "lvl": "debug", "msg": "end: 1.5.3 extract-overlay-ramdisk (duration 00:00:03) [common]"}
- {"dt": "2024-08-31T08:56:52.183748", "lvl": "debug", "msg": "start: 1.5.4 extract-modules (timeout 00:09:48) [common]"}
- {"dt": "2024-08-31T08:56:52.184470", "lvl": "info", "msg": "extracting modules file /var/lib/lava/dispatcher/tmp/36204/tftp-deploy-3pnphz2a/modules/modules.tar to /var/lib/lava/dispatcher/tmp/36204/extract-overlay-ramdisk-hytg3pt1/ramdisk"}
- {"dt": "2024-08-31T08:56:53.268435", "lvl": "debug", "msg": "end: 1.5.4 extract-modules (duration 00:00:01) [common]"}
- {"dt": "2024-08-31T08:56:53.273137", "lvl": "debug", "msg": "start: 1.5.5 apply-overlay-tftp (timeout 00:09:47) [common]"}
- {"dt": "2024-08-31T08:56:53.277005", "lvl": "info", "msg": "[common] Applying overlay /var/lib/lava/dispatcher/tmp/36204/compress-overlay-nqx28c6_/overlay-1.5.2.5.tar.gz to ramdisk"}
- {"dt": "2024-08-31T08:56:53.280342", "lvl": "debug", "msg": "[common] Applying overlay /var/lib/lava/dispatcher/tmp/36204/compress-overlay-nqx28c6_/overlay-1.5.2.5.tar.gz to directory /var/lib/lava/dispatcher/tmp/36204/extract-overlay-ramdisk-hytg3pt1/ramdisk"}
- {"dt": "2024-08-31T08:56:53.585380", "lvl": "debug", "msg": "end: 1.5.5 apply-overlay-tftp (duration 00:00:00) [common]"}
- {"dt": "2024-08-31T08:56:53.590165", "lvl": "debug", "msg": "start: 1.5.6 prepare-kernel (timeout 00:09:47) [common]"}
- {"dt": "2024-08-31T08:56:53.594645", "lvl": "debug", "msg": "start: 1.5.6.1 uboot-prepare-kernel (timeout 00:09:47) [common]"}
- {"dt": "2024-08-31T08:56:53.598794", "lvl": "debug", "msg": "end: 1.5.6.1 uboot-prepare-kernel (duration 00:00:00) [common]"}
- {"dt": "2024-08-31T08:56:53.603370", "lvl": "debug", "msg": "end: 1.5.6 prepare-kernel (duration 00:00:00) [common]"}
- {"dt": "2024-08-31T08:56:53.607319", "lvl": "debug", "msg": "start: 1.5.7 configure-preseed-file (timeout 00:09:47) [common]"}
- {"dt": "2024-08-31T08:56:53.611843", "lvl": "debug", "msg": "end: 1.5.7 configure-preseed-file (duration 00:00:00) [common]"}
- {"dt": "2024-08-31T08:56:53.615968", "lvl": "debug", "msg": "start: 1.5.8 compress-ramdisk (timeout 00:09:47) [common]"}
- {"dt": "2024-08-31T08:56:53.619060", "lvl": "info", "msg": "Building ramdisk /var/lib/lava/dispatcher/tmp/36204/extract-overlay-ramdisk-hytg3pt1/ramdisk.cpio containing /var/lib/lava/dispatcher/tmp/36204/extract-overlay-ramdisk-hytg3pt1/ramdisk"}
- {"dt": "2024-08-31T08:56:56.416712", "lvl": "debug", "msg": ">> 86851 blocks\n"}
- {"dt": "2024-08-31T08:57:01.946559", "lvl": "debug", "msg": "Adding RAMdisk u-boot header."}
- {"dt": "2024-08-31T08:57:01.947414", "lvl": "debug", "msg": "mkimage -A riscv -T ramdisk -C none -d /var/lib/lava/dispatcher/tmp/36204/extract-overlay-ramdisk-hytg3pt1/ramdisk.cpio.gz /var/lib/lava/dispatcher/tmp/36204/extract-overlay-ramdisk-hytg3pt1/ramdisk.cpio.gz.uboot"}
- {"dt": "2024-08-31T08:57:02.140755", "lvl": "debug", "msg": "output: Image Name:   "}
- {"dt": "2024-08-31T08:57:02.141437", "lvl": "debug", "msg": "output: Created:      Sat Aug 31 08:57:01 2024"}
- {"dt": "2024-08-31T08:57:02.141848", "lvl": "debug", "msg": "output: Image Type:   RISC-V Linux RAMDisk Image (uncompressed)"}
- {"dt": "2024-08-31T08:57:02.142240", "lvl": "debug", "msg": "output: Data Size:    13644227 Bytes = 13324.44 KiB = 13.01 MiB"}
- {"dt": "2024-08-31T08:57:02.142627", "lvl": "debug", "msg": "output: Load Address: 00000000"}
- {"dt": "2024-08-31T08:57:02.147215", "lvl": "debug", "msg": "output: Entry Point:  00000000"}
- {"dt": "2024-08-31T08:57:02.147875", "lvl": "debug", "msg": "output: "}
- {"dt": "2024-08-31T08:57:02.148630", "lvl": "debug", "msg": "rename /var/lib/lava/dispatcher/tmp/36204/extract-overlay-ramdisk-hytg3pt1/ramdisk.cpio.gz.uboot to /var/lib/lava/dispatcher/tmp/36204/tftp-deploy-3pnphz2a/ramdisk/ramdisk.cpio.gz.uboot"}
- {"dt": "2024-08-31T08:57:02.149464", "lvl": "debug", "msg": "end: 1.5.8 compress-ramdisk (duration 00:00:09) [common]"}
- {"dt": "2024-08-31T08:57:02.150189", "lvl": "debug", "msg": "end: 1.5 prepare-tftp-overlay (duration 00:00:13) [common]"}
- {"dt": "2024-08-31T08:57:02.153835", "lvl": "debug", "msg": "start: 1.6 lxc-create-udev-rule-action (timeout 00:09:38) [common]"}
- {"dt": "2024-08-31T08:57:02.154617", "lvl": "debug", "msg": "No LXC device requested"}
- {"dt": "2024-08-31T08:57:02.155390", "lvl": "debug", "msg": "end: 1.6 lxc-create-udev-rule-action (duration 00:00:00) [common]"}
- {"dt": "2024-08-31T08:57:02.156074", "lvl": "debug", "msg": "start: 1.7 deploy-device-env (timeout 00:09:38) [common]"}
- {"dt": "2024-08-31T08:57:02.156696", "lvl": "debug", "msg": "end: 1.7 deploy-device-env (duration 00:00:00) [common]"}
- {"dt": "2024-08-31T08:57:02.157190", "lvl": "debug", "msg": "Checking files for TFTP limit of 4294967296 bytes."}
- {"dt": "2024-08-31T08:57:02.160376", "lvl": "info", "msg": "end: 1 tftp-deploy (duration 00:00:22) [common]"}
- {"dt": "2024-08-31T08:57:02.162665", "lvl": "info", "msg": "start: 2 uboot-action (timeout 00:05:00) [common]"}
- {"dt": "2024-08-31T08:57:02.163532", "lvl": "debug", "msg": "start: 2.1 uboot-from-media (timeout 00:05:00) [common]"}
- {"dt": "2024-08-31T08:57:02.164091", "lvl": "debug", "msg": "end: 2.1 uboot-from-media (duration 00:00:00) [common]"}
- {"dt": "2024-08-31T08:57:02.164627", "lvl": "debug", "msg": "start: 2.2 bootloader-overlay (timeout 00:05:00) [common]"}
- {"dt": "2024-08-31T08:57:02.165407", "lvl": "debug", "msg": "substitutions:"}
- {"dt": "2024-08-31T08:57:02.165878", "lvl": "debug", "msg": "- {BOOTX}: booti 0x80200000 0x83500000 0x83000000"}
- {"dt": "2024-08-31T08:57:02.166289", "lvl": "debug", "msg": "- {DTB_ADDR}: 0x83000000"}
- {"dt": "2024-08-31T08:57:02.166688", "lvl": "debug", "msg": "- {DTB}: 36204/tftp-deploy-3pnphz2a/dtb/hifive-unmatched-a00.dtb"}
- {"dt": "2024-08-31T08:57:02.167134", "lvl": "debug", "msg": "- {INITRD}: 36204/tftp-deploy-3pnphz2a/ramdisk/ramdisk.cpio.gz.uboot"}
- {"dt": "2024-08-31T08:57:02.167535", "lvl": "debug", "msg": "- {KERNEL_ADDR}: 0x80200000"}
- {"dt": "2024-08-31T08:57:02.167926", "lvl": "debug", "msg": "- {KERNEL}: 36204/tftp-deploy-3pnphz2a/kernel/Image"}
- {"dt": "2024-08-31T08:57:02.168318", "lvl": "debug", "msg": "- {LAVA_MAC}: None"}
- {"dt": "2024-08-31T08:57:02.168720", "lvl": "debug", "msg": "- {PRESEED_CONFIG}: None"}
- {"dt": "2024-08-31T08:57:02.169107", "lvl": "debug", "msg": "- {PRESEED_LOCAL}: None"}
- {"dt": "2024-08-31T08:57:02.169491", "lvl": "debug", "msg": "- {RAMDISK_ADDR}: 0x83500000"}
- {"dt": "2024-08-31T08:57:02.169872", "lvl": "debug", "msg": "- {RAMDISK}: 36204/tftp-deploy-3pnphz2a/ramdisk/ramdisk.cpio.gz.uboot"}
- {"dt": "2024-08-31T08:57:02.170259", "lvl": "debug", "msg": "- {ROOT_PART}: None"}
- {"dt": "2024-08-31T08:57:02.170646", "lvl": "debug", "msg": "- {ROOT}: None"}
- {"dt": "2024-08-31T08:57:02.171101", "lvl": "debug", "msg": "- {SERVER_IP}: 192.168.66.1"}
- {"dt": "2024-08-31T08:57:02.171507", "lvl": "debug", "msg": "- {TEE_ADDR}: 0x83000000"}
- {"dt": "2024-08-31T08:57:02.171895", "lvl": "debug", "msg": "- {TEE}: None"}
- {"dt": "2024-08-31T08:57:02.172280", "lvl": "info", "msg": "Parsed boot commands:"}
- {"dt": "2024-08-31T08:57:02.172657", "lvl": "info", "msg": "- setenv autoload no"}
- {"dt": "2024-08-31T08:57:02.173043", "lvl": "info", "msg": "- setenv initrd_high 0xffffffffffffffff"}
- {"dt": "2024-08-31T08:57:02.173432", "lvl": "info", "msg": "- setenv fdt_high 0xffffffffffffffff"}
- {"dt": "2024-08-31T08:57:02.173820", "lvl": "info", "msg": "- dhcp"}
- {"dt": "2024-08-31T08:57:02.174212", "lvl": "info", "msg": "- setenv serverip 192.168.66.1"}
- {"dt": "2024-08-31T08:57:02.174597", "lvl": "info", "msg": "- tftp 0x80200000 36204/tftp-deploy-3pnphz2a/kernel/Image"}
- {"dt": "2024-08-31T08:57:02.175011", "lvl": "info", "msg": "- tftp 0x83500000 36204/tftp-deploy-3pnphz2a/ramdisk/ramdisk.cpio.gz.uboot"}
- {"dt": "2024-08-31T08:57:02.175408", "lvl": "info", "msg": "- setenv initrd_size ${filesize}"}
- {"dt": "2024-08-31T08:57:02.175800", "lvl": "info", "msg": "- tftp 0x83000000 36204/tftp-deploy-3pnphz2a/dtb/hifive-unmatched-a00.dtb"}
- {"dt": "2024-08-31T08:57:02.176194", "lvl": "info", "msg": "- setenv bootargs '115200 root=/dev/ram0 console_msg_format=syslog earlycon deferred_probe_timeout=60 ip=dhcp'"}
- {"dt": "2024-08-31T08:57:02.176590", "lvl": "info", "msg": "- booti 0x80200000 0x83500000 0x83000000"}
- {"dt": "2024-08-31T08:57:02.177128", "lvl": "debug", "msg": "end: 2.2 bootloader-overlay (duration 00:00:00) [common]"}
- {"dt": "2024-08-31T08:57:02.177569", "lvl": "results", "msg": {"case": "bootloader-overlay", "definition": "lava", "duration": "0.01", "extra": {"dtb_addr": "0x83000000", "kernel_addr": "0x80200000", "ramdisk_addr": "0x83500000", "tee_addr": "0x83000000"}, "level": "2.2", "namespace": "common", "result": "pass"}}
- {"dt": "2024-08-31T08:57:02.178740", "lvl": "debug", "msg": "start: 2.3 connect-device (timeout 00:05:00) [common]"}
- {"dt": "2024-08-31T08:57:02.179254", "lvl": "info", "msg": "[common] connect-device Connecting to device using 'telnet 127.0.0.1 63006'"}
- {"dt": "2024-08-31T08:57:07.013636", "lvl": "debug", "msg": "Setting prompt string to ['lava-test: # ']"}
- {"dt": "2024-08-31T08:57:07.016109", "lvl": "debug", "msg": "end: 2.3 connect-device (duration 00:00:05) [common]"}
- {"dt": "2024-08-31T08:57:07.017389", "lvl": "debug", "msg": "start: 2.4 uboot-commands (timeout 00:04:55) [common]"}
- {"dt": "2024-08-31T08:57:07.019478", "lvl": "debug", "msg": "start: 2.4.1 reset-device (timeout 00:04:55) [common]"}
- {"dt": "2024-08-31T08:57:07.021258", "lvl": "debug", "msg": "start: 2.4.1.1 pdu-reboot (timeout 00:04:55) [common]"}
- {"dt": "2024-08-31T08:57:07.022736", "lvl": "debug", "msg": "Calling: 'upower.sh' '--atx' 'reset' '1'"}
- {"dt": "2024-08-31T08:57:11.076298", "lvl": "debug", "msg": ">> Accessing Gembird #0 USB device 016\r"}
- {"dt": "2024-08-31T08:57:11.079110", "lvl": "debug", "msg": ">> Switched outlet 1 off\r"}
- {"dt": "2024-08-31T08:57:14.794743", "lvl": "debug", "msg": ">> Accessing Gembird #0 USB device 016\r"}
- {"dt": "2024-08-31T08:57:14.799317", "lvl": "debug", "msg": ">> Switched outlet 1 on\r"}
- {"dt": "2024-08-31T08:57:16.933343", "lvl": "debug", "msg": ">> FTDI RELAY: power on\r"}
- {"dt": "2024-08-31T08:57:18.933706", "lvl": "debug", "msg": ">> FTDI RELAY: power off\r"}
- {"dt": "2024-08-31T08:57:18.970692", "lvl": "debug", "msg": "Returned 0 in 11 seconds"}
- {"dt": "2024-08-31T08:57:19.072988", "lvl": "debug", "msg": "end: 2.4.1.1 pdu-reboot (duration 00:00:12) [common]"}
- {"dt": "2024-08-31T08:57:19.074070", "lvl": "results", "msg": {"case": "pdu-reboot", "definition": "lava", "duration": "12.05", "extra": {"status": "success"}, "level": "2.4.1.1", "namespace": "common", "result": "pass"}}
- {"dt": "2024-08-31T08:57:19.076270", "lvl": "debug", "msg": "end: 2.4.1 reset-device (duration 00:00:12) [common]"}
- {"dt": "2024-08-31T08:57:19.077855", "lvl": "debug", "msg": "start: 2.4.2 bootloader-interrupt (timeout 00:04:43) [common]"}
- {"dt": "2024-08-31T08:57:19.079267", "lvl": "debug", "msg": "Setting prompt string to ['Hit any key to stop autoboot']"}
- {"dt": "2024-08-31T08:57:19.079985", "lvl": "debug", "msg": "bootloader-interrupt: Wait for prompt ['Hit any key to stop autoboot'] (timeout 00:05:00)"}
- {"dt": "2024-08-31T08:57:19.081590", "lvl": "target", "msg": "Trying 127.0.0.1..."}
- {"dt": "2024-08-31T08:57:19.082469", "lvl": "target", "msg": "Connected to 127.0.0.1."}
- {"dt": "2024-08-31T08:57:19.083111", "lvl": "target", "msg": "Escape character is '^]'."}
- {"dt": "2024-08-31T09:02:02.078760", "lvl": "exception", "msg": "bootloader-interrupt timed out after 283 seconds"}
- {"dt": "2024-08-31T09:02:02.080893", "lvl": "debug", "msg": "end: 2.4.2 bootloader-interrupt (duration 00:04:43) [common]"}
- {"dt": "2024-08-31T09:02:02.082535", "lvl": "results", "msg": {"case": "bootloader-interrupt", "definition": "lava", "duration": "283.00", "extra": {"fail": "bootloader-interrupt timed out after 283 seconds"}, "level": "2.4.2", "namespace": "common", "result": "fail"}}
- {"dt": "2024-08-31T09:02:02.086011", "lvl": "exception", "msg": "bootloader-interrupt timed out after 283 seconds"}
- {"dt": "2024-08-31T09:02:02.087900", "lvl": "debug", "msg": "end: 2.4 uboot-commands (duration 00:04:55) [common]"}
- {"dt": "2024-08-31T09:02:02.089854", "lvl": "results", "msg": {"case": "uboot-commands", "definition": "lava", "duration": "295.07", "extra": {"fail": "bootloader-interrupt timed out after 283 seconds"}, "level": "2.4", "namespace": "common", "result": "fail"}}
- {"dt": "2024-08-31T09:02:02.092020", "lvl": "error", "msg": "uboot-action failed: 1 of 1 attempts. 'bootloader-interrupt timed out after 283 seconds'"}
- {"dt": "2024-08-31T09:02:02.093195", "lvl": "exception", "msg": "bootloader-interrupt timed out after 283 seconds"}
- {"dt": "2024-08-31T09:02:02.093998", "lvl": "info", "msg": "end: 2 uboot-action (duration 00:05:00) [common]"}
- {"dt": "2024-08-31T09:02:02.094549", "lvl": "results", "msg": {"case": "uboot-action", "definition": "lava", "duration": "299.93", "extra": {"fail": "bootloader-interrupt timed out after 283 seconds"}, "level": "2", "namespace": "common", "result": "fail"}}
- {"dt": "2024-08-31T09:02:02.095779", "lvl": "info", "msg": "Cleaning after the job"}
- {"dt": "2024-08-31T09:02:02.096411", "lvl": "debug", "msg": "Cleaning up download directory: /var/lib/lava/dispatcher/tmp/36204/tftp-deploy-3pnphz2a/ramdisk"}
- {"dt": "2024-08-31T09:02:02.101803", "lvl": "debug", "msg": "Cleaning up download directory: /var/lib/lava/dispatcher/tmp/36204/tftp-deploy-3pnphz2a/kernel"}
- {"dt": "2024-08-31T09:02:02.109459", "lvl": "debug", "msg": "Cleaning up download directory: /var/lib/lava/dispatcher/tmp/36204/tftp-deploy-3pnphz2a/dtb"}
- {"dt": "2024-08-31T09:02:02.110705", "lvl": "debug", "msg": "Cleaning up download directory: /var/lib/lava/dispatcher/tmp/36204/tftp-deploy-3pnphz2a/modules"}
- {"dt": "2024-08-31T09:02:02.118825", "lvl": "debug", "msg": "start: 5.1 power-off (timeout 00:00:30) [common]"}
- {"dt": "2024-08-31T09:02:02.119837", "lvl": "debug", "msg": "Calling: 'upower.sh' '--atx' 'off' '1'"}
- {"dt": "2024-08-31T09:02:05.849081", "lvl": "debug", "msg": ">> Accessing Gembird #0 USB device 016\r"}
- {"dt": "2024-08-31T09:02:05.854046", "lvl": "debug", "msg": ">> Switched outlet 1 off\r"}
- {"dt": "2024-08-31T09:02:05.860695", "lvl": "debug", "msg": "Returned 0 in 3 seconds"}
- {"dt": "2024-08-31T09:02:05.963219", "lvl": "debug", "msg": "end: 5.1 power-off (duration 00:00:04) [common]"}
- {"dt": "2024-08-31T09:02:05.965221", "lvl": "results", "msg": {"case": "power-off", "definition": "lava", "duration": "3.84", "extra": {"status": "success"}, "level": "5.1", "namespace": "common", "result": "pass"}}
- {"dt": "2024-08-31T09:02:05.969265", "lvl": "debug", "msg": "start: 5.2 read-feedback (timeout 00:09:56) [common]"}
- {"dt": "2024-08-31T09:02:05.973803", "lvl": "debug", "msg": "Listened to connection for namespace 'common' for up to 1s"}
- {"dt": "2024-08-31T09:02:06.973010", "lvl": "info", "msg": "Finalising connection for namespace 'common'"}
- {"dt": "2024-08-31T09:02:06.975252", "lvl": "info", "msg": "Disconnecting from shell: Finalise"}
- {"dt": "2024-08-31T09:02:07.079272", "lvl": "debug", "msg": "end: 5.2 read-feedback (duration 00:00:01) [common]"}
- {"dt": "2024-08-31T09:02:07.081315", "lvl": "info", "msg": "Override tmp directory removed at /var/lib/lava/dispatcher/tmp/36204"}
- {"dt": "2024-08-31T09:02:07.222535", "lvl": "info", "msg": "Root tmp directory removed at /var/lib/lava/dispatcher/tmp/36204"}
- {"dt": "2024-08-31T09:02:07.223741", "lvl": "error", "msg": "InfrastructureError: The Infrastructure is not working correctly. Please report this error to LAVA admins."}
- {"dt": "2024-08-31T09:02:07.224260", "lvl": "results", "msg": {"case": "job", "definition": "lava", "error_msg": "bootloader-interrupt timed out after 283 seconds", "error_type": "Infrastructure", "result": "fail"}}
