- {"dt": "2024-07-07T08:36:46.825663", "lvl": "info", "msg": "lava-dispatcher, installed at version: 2023.10"}
- {"dt": "2024-07-07T08:36:46.827158", "lvl": "info", "msg": "start: 0 validate"}
- {"dt": "2024-07-07T08:36:46.828227", "lvl": "info", "msg": "Start time: 2024-07-07 08:36:46.828169+00:00 (UTC)"}
- {"dt": "2024-07-07T08:36:46.829486", "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-07-07T08:36:48.373619", "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-07-07T08:36:50.359286", "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-07-07T08:36:50.910518", "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-07-07T08:36:51.977010", "lvl": "info", "msg": "validate duration: 5.15"}
- {"dt": "2024-07-07T08:36:51.977897", "lvl": "results", "msg": {"case": "validate", "definition": "lava", "result": "pass"}}
- {"dt": "2024-07-07T08:36:51.979036", "lvl": "info", "msg": "start: 1 tftp-deploy (timeout 00:10:00) [common]"}
- {"dt": "2024-07-07T08:36:51.979851", "lvl": "debug", "msg": "start: 1.1 download-retry (timeout 00:10:00) [common]"}
- {"dt": "2024-07-07T08:36:51.980672", "lvl": "debug", "msg": "start: 1.1.1 http-download (timeout 00:10:00) [common]"}
- {"dt": "2024-07-07T08:36:51.981697", "lvl": "debug", "msg": "Not decompressing ramdisk as can be used compressed."}
- {"dt": "2024-07-07T08:36:51.982498", "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-07-07T08:36:51.983061", "lvl": "debug", "msg": "saving as /var/lib/lava/dispatcher/tmp/35313/tftp-deploy-b9hrn41v/ramdisk/rootfs.cpio.gz"}
- {"dt": "2024-07-07T08:36:51.983575", "lvl": "debug", "msg": "total size: 7844224 (7\u202FMB)"}
- {"dt": "2024-07-07T08:36:52.597934", "lvl": "debug", "msg": "progress   0\u202F% (0\u202FMB)"}
- {"dt": "2024-07-07T08:36:52.656356", "lvl": "debug", "msg": "progress   5\u202F% (0\u202FMB)"}
- {"dt": "2024-07-07T08:36:52.706031", "lvl": "debug", "msg": "progress  10\u202F% (0\u202FMB)"}
- {"dt": "2024-07-07T08:36:52.755155", "lvl": "debug", "msg": "progress  15\u202F% (1\u202FMB)"}
- {"dt": "2024-07-07T08:36:52.798877", "lvl": "debug", "msg": "progress  20\u202F% (1\u202FMB)"}
- {"dt": "2024-07-07T08:36:52.836517", "lvl": "debug", "msg": "progress  25\u202F% (1\u202FMB)"}
- {"dt": "2024-07-07T08:36:52.868478", "lvl": "debug", "msg": "progress  30\u202F% (2\u202FMB)"}
- {"dt": "2024-07-07T08:36:52.900656", "lvl": "debug", "msg": "progress  35\u202F% (2\u202FMB)"}
- {"dt": "2024-07-07T08:36:52.929332", "lvl": "debug", "msg": "progress  40\u202F% (3\u202FMB)"}
- {"dt": "2024-07-07T08:36:52.954682", "lvl": "debug", "msg": "progress  45\u202F% (3\u202FMB)"}
- {"dt": "2024-07-07T08:36:52.981917", "lvl": "debug", "msg": "progress  50\u202F% (3\u202FMB)"}
- {"dt": "2024-07-07T08:36:53.008177", "lvl": "debug", "msg": "progress  55\u202F% (4\u202FMB)"}
- {"dt": "2024-07-07T08:36:53.033362", "lvl": "debug", "msg": "progress  60\u202F% (4\u202FMB)"}
- {"dt": "2024-07-07T08:36:53.056218", "lvl": "debug", "msg": "progress  65\u202F% (4\u202FMB)"}
- {"dt": "2024-07-07T08:36:53.081229", "lvl": "debug", "msg": "progress  70\u202F% (5\u202FMB)"}
- {"dt": "2024-07-07T08:36:53.104107", "lvl": "debug", "msg": "progress  75\u202F% (5\u202FMB)"}
- {"dt": "2024-07-07T08:36:53.127084", "lvl": "debug", "msg": "progress  80\u202F% (6\u202FMB)"}
- {"dt": "2024-07-07T08:36:53.151148", "lvl": "debug", "msg": "progress  85\u202F% (6\u202FMB)"}
- {"dt": "2024-07-07T08:36:53.172669", "lvl": "debug", "msg": "progress  90\u202F% (6\u202FMB)"}
- {"dt": "2024-07-07T08:36:53.190342", "lvl": "debug", "msg": "progress  95\u202F% (7\u202FMB)"}
- {"dt": "2024-07-07T08:36:53.207495", "lvl": "debug", "msg": "progress 100\u202F% (7\u202FMB)"}
- {"dt": "2024-07-07T08:36:53.208906", "lvl": "info", "msg": "7\u202FMB downloaded in 1.23\u202Fs (6.11\u202FMB/s)"}
- {"dt": "2024-07-07T08:36:53.209983", "lvl": "debug", "msg": "end: 1.1.1 http-download (duration 00:00:01) [common]"}
- {"dt": "2024-07-07T08:36:53.210600", "lvl": "results", "msg": {"case": "http-download", "definition": "lava", "duration": "1.23", "extra": {"label": "ramdisk", "md5sum": "4bbb32813cb05021df34cefcbb385507", "sha256sum": "5a9577755f4c03de73672a1f7d73d1fefcc1af9c766e4815d716d23495f74ed8", "sha512sum": "b435cc3fbbdc57e455d0c13d9dcec3969dcf4e26cee57fa102df8b82e1a4e9b739f026cc19905db282fd50a3187a6e143709e111a847d8c8ff9d38fba0434aa8", "size": ! "7844224"}, "level": "1.1.1", "namespace": "common", "result": "pass"}}
- {"dt": "2024-07-07T08:36:53.211922", "lvl": "debug", "msg": "end: 1.1 download-retry (duration 00:00:01) [common]"}
- {"dt": "2024-07-07T08:36:53.212642", "lvl": "debug", "msg": "start: 1.2 download-retry (timeout 00:09:59) [common]"}
- {"dt": "2024-07-07T08:36:53.213277", "lvl": "debug", "msg": "start: 1.2.1 http-download (timeout 00:09:59) [common]"}
- {"dt": "2024-07-07T08:36:53.214255", "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-07-07T08:36:53.214842", "lvl": "debug", "msg": "saving as /var/lib/lava/dispatcher/tmp/35313/tftp-deploy-b9hrn41v/kernel/Image"}
- {"dt": "2024-07-07T08:36:53.215308", "lvl": "debug", "msg": "total size: 19845120 (18\u202FMB)"}
- {"dt": "2024-07-07T08:36:53.215768", "lvl": "debug", "msg": "No compression specified"}
- {"dt": "2024-07-07T08:36:54.753360", "lvl": "debug", "msg": "progress   0\u202F% (0\u202FMB)"}
- {"dt": "2024-07-07T08:36:54.840818", "lvl": "debug", "msg": "progress   5\u202F% (0\u202FMB)"}
- {"dt": "2024-07-07T08:36:54.905718", "lvl": "debug", "msg": "progress  10\u202F% (1\u202FMB)"}
- {"dt": "2024-07-07T08:36:54.994895", "lvl": "debug", "msg": "progress  15\u202F% (2\u202FMB)"}
- {"dt": "2024-07-07T08:36:55.087865", "lvl": "debug", "msg": "progress  20\u202F% (3\u202FMB)"}
- {"dt": "2024-07-07T08:36:55.178453", "lvl": "debug", "msg": "progress  25\u202F% (4\u202FMB)"}
- {"dt": "2024-07-07T08:36:55.265371", "lvl": "debug", "msg": "progress  30\u202F% (5\u202FMB)"}
- {"dt": "2024-07-07T08:36:55.354215", "lvl": "debug", "msg": "progress  35\u202F% (6\u202FMB)"}
- {"dt": "2024-07-07T08:36:55.447680", "lvl": "debug", "msg": "progress  40\u202F% (7\u202FMB)"}
- {"dt": "2024-07-07T08:36:55.538822", "lvl": "debug", "msg": "progress  45\u202F% (8\u202FMB)"}
- {"dt": "2024-07-07T08:36:55.615407", "lvl": "debug", "msg": "progress  50\u202F% (9\u202FMB)"}
- {"dt": "2024-07-07T08:36:55.682629", "lvl": "debug", "msg": "progress  55\u202F% (10\u202FMB)"}
- {"dt": "2024-07-07T08:36:55.749697", "lvl": "debug", "msg": "progress  60\u202F% (11\u202FMB)"}
- {"dt": "2024-07-07T08:36:55.819983", "lvl": "debug", "msg": "progress  65\u202F% (12\u202FMB)"}
- {"dt": "2024-07-07T08:36:55.890569", "lvl": "debug", "msg": "progress  70\u202F% (13\u202FMB)"}
- {"dt": "2024-07-07T08:36:55.960472", "lvl": "debug", "msg": "progress  75\u202F% (14\u202FMB)"}
- {"dt": "2024-07-07T08:36:56.010012", "lvl": "debug", "msg": "progress  80\u202F% (15\u202FMB)"}
- {"dt": "2024-07-07T08:36:56.060748", "lvl": "debug", "msg": "progress  85\u202F% (16\u202FMB)"}
- {"dt": "2024-07-07T08:36:56.112005", "lvl": "debug", "msg": "progress  90\u202F% (17\u202FMB)"}
- {"dt": "2024-07-07T08:36:56.161505", "lvl": "debug", "msg": "progress  95\u202F% (18\u202FMB)"}
- {"dt": "2024-07-07T08:36:56.207039", "lvl": "debug", "msg": "progress 100\u202F% (18\u202FMB)"}
- {"dt": "2024-07-07T08:36:56.208923", "lvl": "info", "msg": "18\u202FMB downloaded in 2.99\u202Fs (6.32\u202FMB/s)"}
- {"dt": "2024-07-07T08:36:56.210240", "lvl": "debug", "msg": "end: 1.2.1 http-download (duration 00:00:03) [common]"}
- {"dt": "2024-07-07T08:36:56.211110", "lvl": "results", "msg": {"case": "http-download", "definition": "lava", "duration": "3.00", "extra": {"label": "kernel", "md5sum": "bc353ea01eab589bb4cd6918b0d126de", "sha256sum": "8a98e42d83b971b3f17b23f2fded633f8d3c97ef956efe6ee5d6edd727f87ee1", "sha512sum": "4cad13e71faae976b6b963587c809e948943cb1a76d6655667aac8f154e7068fccb3b3a1191ff00b29dd63f0e46a7b939ed0c46d4edda16d7e9efa5acf87b65b", "size": ! "19845120"}, "level": "1.2.1", "namespace": "common", "result": "pass"}}
- {"dt": "2024-07-07T08:36:56.212830", "lvl": "debug", "msg": "end: 1.2 download-retry (duration 00:00:03) [common]"}
- {"dt": "2024-07-07T08:36:56.213837", "lvl": "debug", "msg": "start: 1.3 download-retry (timeout 00:09:56) [common]"}
- {"dt": "2024-07-07T08:36:56.214775", "lvl": "debug", "msg": "start: 1.3.1 http-download (timeout 00:09:56) [common]"}
- {"dt": "2024-07-07T08:36:56.215989", "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-07-07T08:36:56.216904", "lvl": "debug", "msg": "saving as /var/lib/lava/dispatcher/tmp/35313/tftp-deploy-b9hrn41v/dtb/hifive-unmatched-a00.dtb"}
- {"dt": "2024-07-07T08:36:56.217661", "lvl": "debug", "msg": "total size: 10707 (0\u202FMB)"}
- {"dt": "2024-07-07T08:36:56.218409", "lvl": "debug", "msg": "No compression specified"}
- {"dt": "2024-07-07T08:36:56.416137", "lvl": "debug", "msg": "progress 100\u202F% (0\u202FMB)"}
- {"dt": "2024-07-07T08:36:56.417437", "lvl": "info", "msg": "0\u202FMB downloaded in 0.20\u202Fs (0.05\u202FMB/s)"}
- {"dt": "2024-07-07T08:36:56.418447", "lvl": "debug", "msg": "end: 1.3.1 http-download (duration 00:00:00) [common]"}
- {"dt": "2024-07-07T08:36:56.419025", "lvl": "results", "msg": {"case": "http-download", "definition": "lava", "duration": "0.20", "extra": {"label": "dtb", "md5sum": "6e4ede97cac7e574ba154868ae6bd490", "sha256sum": "bfd83286eab97548a6663437655c0c6805a361a06c726c439b8d9655be38d15b", "sha512sum": "429c70a390d17dc993647232bfa0333fdf25e66e87f05676252174f698e925e876ddf6b1e722bfdedaf8fd299f71a19b2c8c383eade9bf4df01262d0773fd702", "size": ! "10707"}, "level": "1.3.1", "namespace": "common", "result": "pass"}}
- {"dt": "2024-07-07T08:36:56.420412", "lvl": "debug", "msg": "end: 1.3 download-retry (duration 00:00:00) [common]"}
- {"dt": "2024-07-07T08:36:56.421105", "lvl": "debug", "msg": "start: 1.4 download-retry (timeout 00:09:56) [common]"}
- {"dt": "2024-07-07T08:36:56.421725", "lvl": "debug", "msg": "start: 1.4.1 http-download (timeout 00:09:56) [common]"}
- {"dt": "2024-07-07T08:36:56.422656", "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-07-07T08:36:56.423212", "lvl": "debug", "msg": "saving as /var/lib/lava/dispatcher/tmp/35313/tftp-deploy-b9hrn41v/modules/modules.tar"}
- {"dt": "2024-07-07T08:36:56.423661", "lvl": "debug", "msg": "total size: 3892756 (3\u202FMB)"}
- {"dt": "2024-07-07T08:36:56.424122", "lvl": "info", "msg": "Using unxz to decompress xz"}
- {"dt": "2024-07-07T08:36:56.873088", "lvl": "debug", "msg": "progress   0\u202F% (0\u202FMB)"}
- {"dt": "2024-07-07T08:36:56.899459", "lvl": "debug", "msg": "progress   5\u202F% (0\u202FMB)"}
- {"dt": "2024-07-07T08:36:56.948537", "lvl": "debug", "msg": "progress  10\u202F% (0\u202FMB)"}
- {"dt": "2024-07-07T08:36:56.999030", "lvl": "debug", "msg": "progress  15\u202F% (0\u202FMB)"}
- {"dt": "2024-07-07T08:36:57.035515", "lvl": "debug", "msg": "progress  20\u202F% (0\u202FMB)"}
- {"dt": "2024-07-07T08:36:57.080158", "lvl": "debug", "msg": "progress  25\u202F% (0\u202FMB)"}
- {"dt": "2024-07-07T08:36:57.137267", "lvl": "debug", "msg": "progress  30\u202F% (1\u202FMB)"}
- {"dt": "2024-07-07T08:36:57.184054", "lvl": "debug", "msg": "progress  35\u202F% (1\u202FMB)"}
- {"dt": "2024-07-07T08:36:57.228414", "lvl": "debug", "msg": "progress  40\u202F% (1\u202FMB)"}
- {"dt": "2024-07-07T08:36:57.264615", "lvl": "debug", "msg": "progress  45\u202F% (1\u202FMB)"}
- {"dt": "2024-07-07T08:36:57.318539", "lvl": "debug", "msg": "progress  50\u202F% (1\u202FMB)"}
- {"dt": "2024-07-07T08:36:57.380894", "lvl": "debug", "msg": "progress  55\u202F% (2\u202FMB)"}
- {"dt": "2024-07-07T08:36:57.453858", "lvl": "debug", "msg": "progress  60\u202F% (2\u202FMB)"}
- {"dt": "2024-07-07T08:36:57.508175", "lvl": "debug", "msg": "progress  65\u202F% (2\u202FMB)"}
- {"dt": "2024-07-07T08:36:57.564426", "lvl": "debug", "msg": "progress  70\u202F% (2\u202FMB)"}
- {"dt": "2024-07-07T08:36:57.613204", "lvl": "debug", "msg": "progress  75\u202F% (2\u202FMB)"}
- {"dt": "2024-07-07T08:36:57.675937", "lvl": "debug", "msg": "progress  80\u202F% (3\u202FMB)"}
- {"dt": "2024-07-07T08:36:57.734086", "lvl": "debug", "msg": "progress  85\u202F% (3\u202FMB)"}
- {"dt": "2024-07-07T08:36:57.804816", "lvl": "debug", "msg": "progress  90\u202F% (3\u202FMB)"}
- {"dt": "2024-07-07T08:36:57.865985", "lvl": "debug", "msg": "progress  95\u202F% (3\u202FMB)"}
- {"dt": "2024-07-07T08:36:57.923801", "lvl": "debug", "msg": "progress 100\u202F% (3\u202FMB)"}
- {"dt": "2024-07-07T08:36:57.953152", "lvl": "info", "msg": "3\u202FMB downloaded in 1.53\u202Fs (2.43\u202FMB/s)"}
- {"dt": "2024-07-07T08:36:57.954237", "lvl": "debug", "msg": "end: 1.4.1 http-download (duration 00:00:02) [common]"}
- {"dt": "2024-07-07T08:36:57.954824", "lvl": "results", "msg": {"case": "http-download", "definition": "lava", "duration": "1.53", "extra": {"label": "modules", "md5sum": "bd526ab1d1394350f02fce39169fd3ed", "sha256sum": "3adbbae160cc6e797e09f2ec6df9c6c848d48f6451e75131e278b4f8dc96bb3b", "sha512sum": "94ab1014e55f1dc62ed235004bd221efcacdbad3af4ff6cb191ec3007be7588b46db84f73d3a3f0da7d101fa96ae93c4dc51fe8a49d2b43b50fcf42e95b38c7f", "size": ! "3892756"}, "level": "1.4.1", "namespace": "common", "result": "pass"}}
- {"dt": "2024-07-07T08:36:57.956145", "lvl": "debug", "msg": "end: 1.4 download-retry (duration 00:00:02) [common]"}
- {"dt": "2024-07-07T08:36:57.957708", "lvl": "debug", "msg": "start: 1.5 prepare-tftp-overlay (timeout 00:09:54) [common]"}
- {"dt": "2024-07-07T08:36:57.958662", "lvl": "debug", "msg": "start: 1.5.1 extract-nfsrootfs (timeout 00:09:54) [common]"}
- {"dt": "2024-07-07T08:36:57.959560", "lvl": "debug", "msg": "end: 1.5.1 extract-nfsrootfs (duration 00:00:00) [common]"}
- {"dt": "2024-07-07T08:36:57.960459", "lvl": "debug", "msg": "start: 1.5.2 lava-overlay (timeout 00:09:54) [common]"}
- {"dt": "2024-07-07T08:36:57.962528", "lvl": "debug", "msg": "[common] Preparing overlay tarball in /var/lib/lava/dispatcher/tmp/35313/lava-overlay-3ufcabdo"}
- {"dt": "2024-07-07T08:36:57.963929", "lvl": "debug", "msg": "makedir: /var/lib/lava/dispatcher/tmp/35313/lava-overlay-3ufcabdo/lava-35313/bin"}
- {"dt": "2024-07-07T08:36:57.965201", "lvl": "debug", "msg": "makedir: /var/lib/lava/dispatcher/tmp/35313/lava-overlay-3ufcabdo/lava-35313/tests"}
- {"dt": "2024-07-07T08:36:57.966518", "lvl": "debug", "msg": "makedir: /var/lib/lava/dispatcher/tmp/35313/lava-overlay-3ufcabdo/lava-35313/results"}
- {"dt": "2024-07-07T08:36:57.967598", "lvl": "debug", "msg": "Creating /var/lib/lava/dispatcher/tmp/35313/lava-overlay-3ufcabdo/lava-35313/bin/lava-add-keys"}
- {"dt": "2024-07-07T08:36:57.969362", "lvl": "debug", "msg": "Creating /var/lib/lava/dispatcher/tmp/35313/lava-overlay-3ufcabdo/lava-35313/bin/lava-add-sources"}
- {"dt": "2024-07-07T08:36:57.970843", "lvl": "debug", "msg": "Creating /var/lib/lava/dispatcher/tmp/35313/lava-overlay-3ufcabdo/lava-35313/bin/lava-background-process-start"}
- {"dt": "2024-07-07T08:36:57.972421", "lvl": "debug", "msg": "Creating /var/lib/lava/dispatcher/tmp/35313/lava-overlay-3ufcabdo/lava-35313/bin/lava-background-process-stop"}
- {"dt": "2024-07-07T08:36:57.974172", "lvl": "debug", "msg": "Creating /var/lib/lava/dispatcher/tmp/35313/lava-overlay-3ufcabdo/lava-35313/bin/lava-common-functions"}
- {"dt": "2024-07-07T08:36:57.975658", "lvl": "debug", "msg": "Creating /var/lib/lava/dispatcher/tmp/35313/lava-overlay-3ufcabdo/lava-35313/bin/lava-echo-ipv4"}
- {"dt": "2024-07-07T08:36:57.977193", "lvl": "debug", "msg": "Creating /var/lib/lava/dispatcher/tmp/35313/lava-overlay-3ufcabdo/lava-35313/bin/lava-install-packages"}
- {"dt": "2024-07-07T08:36:57.979055", "lvl": "debug", "msg": "Creating /var/lib/lava/dispatcher/tmp/35313/lava-overlay-3ufcabdo/lava-35313/bin/lava-installed-packages"}
- {"dt": "2024-07-07T08:36:57.980809", "lvl": "debug", "msg": "Creating /var/lib/lava/dispatcher/tmp/35313/lava-overlay-3ufcabdo/lava-35313/bin/lava-os-build"}
- {"dt": "2024-07-07T08:36:57.982291", "lvl": "debug", "msg": "Creating /var/lib/lava/dispatcher/tmp/35313/lava-overlay-3ufcabdo/lava-35313/bin/lava-probe-channel"}
- {"dt": "2024-07-07T08:36:57.983961", "lvl": "debug", "msg": "Creating /var/lib/lava/dispatcher/tmp/35313/lava-overlay-3ufcabdo/lava-35313/bin/lava-probe-ip"}
- {"dt": "2024-07-07T08:36:57.985466", "lvl": "debug", "msg": "Creating /var/lib/lava/dispatcher/tmp/35313/lava-overlay-3ufcabdo/lava-35313/bin/lava-target-ip"}
- {"dt": "2024-07-07T08:36:57.987053", "lvl": "debug", "msg": "Creating /var/lib/lava/dispatcher/tmp/35313/lava-overlay-3ufcabdo/lava-35313/bin/lava-target-mac"}
- {"dt": "2024-07-07T08:36:57.988705", "lvl": "debug", "msg": "Creating /var/lib/lava/dispatcher/tmp/35313/lava-overlay-3ufcabdo/lava-35313/bin/lava-target-storage"}
- {"dt": "2024-07-07T08:36:57.990689", "lvl": "debug", "msg": "Creating /var/lib/lava/dispatcher/tmp/35313/lava-overlay-3ufcabdo/lava-35313/bin/lava-test-case"}
- {"dt": "2024-07-07T08:36:57.992201", "lvl": "debug", "msg": "Creating /var/lib/lava/dispatcher/tmp/35313/lava-overlay-3ufcabdo/lava-35313/bin/lava-test-event"}
- {"dt": "2024-07-07T08:36:57.993728", "lvl": "debug", "msg": "Creating /var/lib/lava/dispatcher/tmp/35313/lava-overlay-3ufcabdo/lava-35313/bin/lava-test-feedback"}
- {"dt": "2024-07-07T08:36:57.995368", "lvl": "debug", "msg": "Creating /var/lib/lava/dispatcher/tmp/35313/lava-overlay-3ufcabdo/lava-35313/bin/lava-test-raise"}
- {"dt": "2024-07-07T08:36:57.996884", "lvl": "debug", "msg": "Creating /var/lib/lava/dispatcher/tmp/35313/lava-overlay-3ufcabdo/lava-35313/bin/lava-test-reference"}
- {"dt": "2024-07-07T08:36:57.998750", "lvl": "debug", "msg": "Creating /var/lib/lava/dispatcher/tmp/35313/lava-overlay-3ufcabdo/lava-35313/bin/lava-test-runner"}
- {"dt": "2024-07-07T08:36:58.000206", "lvl": "debug", "msg": "Creating /var/lib/lava/dispatcher/tmp/35313/lava-overlay-3ufcabdo/lava-35313/bin/lava-test-set"}
- {"dt": "2024-07-07T08:36:58.001949", "lvl": "debug", "msg": "Creating /var/lib/lava/dispatcher/tmp/35313/lava-overlay-3ufcabdo/lava-35313/bin/lava-test-shell"}
- {"dt": "2024-07-07T08:36:58.003511", "lvl": "debug", "msg": "Updating /var/lib/lava/dispatcher/tmp/35313/lava-overlay-3ufcabdo/lava-35313/bin/lava-install-packages (oe)"}
- {"dt": "2024-07-07T08:36:58.005236", "lvl": "debug", "msg": "Updating /var/lib/lava/dispatcher/tmp/35313/lava-overlay-3ufcabdo/lava-35313/bin/lava-installed-packages (oe)"}
- {"dt": "2024-07-07T08:36:58.006771", "lvl": "debug", "msg": "Creating /var/lib/lava/dispatcher/tmp/35313/lava-overlay-3ufcabdo/lava-35313/environment"}
- {"dt": "2024-07-07T08:36:58.008575", "lvl": "debug", "msg": "LAVA metadata"}
- {"dt": "2024-07-07T08:36:58.009538", "lvl": "debug", "msg": "- LAVA_JOB_ID=35313"}
- {"dt": "2024-07-07T08:36:58.010313", "lvl": "debug", "msg": "- LAVA_DISPATCHER_IP=192.168.66.1"}
- {"dt": "2024-07-07T08:36:58.011329", "lvl": "debug", "msg": "start: 1.5.2.1 ssh-authorize (timeout 00:09:54) [common]"}
- {"dt": "2024-07-07T08:36:58.017165", "lvl": "debug", "msg": "end: 1.5.2.1 ssh-authorize (duration 00:00:00) [common]"}
- {"dt": "2024-07-07T08:36:58.018260", "lvl": "debug", "msg": "start: 1.5.2.2 lava-vland-overlay (timeout 00:09:54) [common]"}
- {"dt": "2024-07-07T08:36:58.019319", "lvl": "debug", "msg": "skipped lava-vland-overlay"}
- {"dt": "2024-07-07T08:36:58.020257", "lvl": "debug", "msg": "end: 1.5.2.2 lava-vland-overlay (duration 00:00:00) [common]"}
- {"dt": "2024-07-07T08:36:58.021323", "lvl": "debug", "msg": "start: 1.5.2.3 lava-multinode-overlay (timeout 00:09:54) [common]"}
- {"dt": "2024-07-07T08:36:58.022066", "lvl": "debug", "msg": "skipped lava-multinode-overlay"}
- {"dt": "2024-07-07T08:36:58.022886", "lvl": "debug", "msg": "end: 1.5.2.3 lava-multinode-overlay (duration 00:00:00) [common]"}
- {"dt": "2024-07-07T08:36:58.023880", "lvl": "debug", "msg": "start: 1.5.2.4 test-definition (timeout 00:09:54) [common]"}
- {"dt": "2024-07-07T08:36:58.025159", "lvl": "info", "msg": "Loading test definitions"}
- {"dt": "2024-07-07T08:36:58.026564", "lvl": "debug", "msg": "start: 1.5.2.4.1 inline-repo-action (timeout 00:09:54) [common]"}
- {"dt": "2024-07-07T08:36:58.027464", "lvl": "debug", "msg": "Using /lava-35313 at stage 0"}
- {"dt": "2024-07-07T08:36:58.030516", "lvl": "debug", "msg": "uuid=35313_1.5.2.4.1 testdef=None"}
- {"dt": "2024-07-07T08:36:58.031530", "lvl": "debug", "msg": "end: 1.5.2.4.1 inline-repo-action (duration 00:00:00) [common]"}
- {"dt": "2024-07-07T08:36:58.032504", "lvl": "debug", "msg": "start: 1.5.2.4.2 test-overlay (timeout 00:09:54) [common]"}
- {"dt": "2024-07-07T08:36:58.037089", "lvl": "debug", "msg": "end: 1.5.2.4.2 test-overlay (duration 00:00:00) [common]"}
- {"dt": "2024-07-07T08:36:58.037940", "lvl": "results", "msg": {"case": "test-overlay", "definition": "lava", "duration": "0.00", "extra": {"from": "inline", "name": "dmesg", "path": "inline/dmesg.yaml", "uuid": "35313_1.5.2.4.1"}, "level": "1.5.2.4.2", "namespace": "common", "result": "pass"}}
- {"dt": "2024-07-07T08:36:58.039523", "lvl": "debug", "msg": "start: 1.5.2.4.3 test-install-overlay (timeout 00:09:54) [common]"}
- {"dt": "2024-07-07T08:36:58.045710", "lvl": "debug", "msg": "end: 1.5.2.4.3 test-install-overlay (duration 00:00:00) [common]"}
- {"dt": "2024-07-07T08:36:58.046595", "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": "35313_1.5.2.4.1", "uuid": "35313_1.5.2.4.1"}, "level": "1.5.2.4.3", "namespace": "common", "result": "pass"}}
- {"dt": "2024-07-07T08:36:58.048247", "lvl": "debug", "msg": "start: 1.5.2.4.4 test-runscript-overlay (timeout 00:09:54) [common]"}
- {"dt": "2024-07-07T08:36:58.055379", "lvl": "debug", "msg": "runner path: /var/lib/lava/dispatcher/tmp/35313/lava-overlay-3ufcabdo/lava-35313/0/tests/0_dmesg test_uuid 35313_1.5.2.4.1"}
- {"dt": "2024-07-07T08:36:58.057168", "lvl": "debug", "msg": "end: 1.5.2.4.4 test-runscript-overlay (duration 00:00:00) [common]"}
- {"dt": "2024-07-07T08:36:58.058081", "lvl": "results", "msg": {"case": "test-runscript-overlay", "definition": "lava", "duration": "0.01", "extra": {"filename": "/var/lib/lava/dispatcher/tmp/35313/lava-overlay-3ufcabdo/lava-35313/0/tests/0_dmesg/run.sh", "from": "inline", "name": "dmesg", "path": "inline/dmesg.yaml", "uuid": "35313_1.5.2.4.1"}, "level": "1.5.2.4.4", "namespace": "common", "result": "pass"}}
- {"dt": "2024-07-07T08:36:58.059704", "lvl": "debug", "msg": "start: 1.5.2.4.5 inline-repo-action (timeout 00:09:54) [common]"}
- {"dt": "2024-07-07T08:36:58.060559", "lvl": "debug", "msg": "Using /lava-35313 at stage 1"}
- {"dt": "2024-07-07T08:36:58.063366", "lvl": "debug", "msg": "uuid=35313_1.5.2.4.5 testdef=None"}
- {"dt": "2024-07-07T08:36:58.064476", "lvl": "debug", "msg": "end: 1.5.2.4.5 inline-repo-action (duration 00:00:00) [common]"}
- {"dt": "2024-07-07T08:36:58.065480", "lvl": "debug", "msg": "start: 1.5.2.4.6 test-overlay (timeout 00:09:54) [common]"}
- {"dt": "2024-07-07T08:36:58.069958", "lvl": "debug", "msg": "end: 1.5.2.4.6 test-overlay (duration 00:00:00) [common]"}
- {"dt": "2024-07-07T08:36:58.071229", "lvl": "results", "msg": {"case": "test-overlay", "definition": "lava", "duration": "0.00", "extra": {"from": "inline", "name": "bootrr", "path": "inline/bootrr.yaml", "uuid": "35313_1.5.2.4.5"}, "level": "1.5.2.4.6", "namespace": "common", "result": "pass"}}
- {"dt": "2024-07-07T08:36:58.073193", "lvl": "debug", "msg": "start: 1.5.2.4.7 test-install-overlay (timeout 00:09:54) [common]"}
- {"dt": "2024-07-07T08:36:58.079723", "lvl": "debug", "msg": "end: 1.5.2.4.7 test-install-overlay (duration 00:00:00) [common]"}
- {"dt": "2024-07-07T08:36:58.080642", "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": "35313_1.5.2.4.5", "uuid": "35313_1.5.2.4.5"}, "level": "1.5.2.4.7", "namespace": "common", "result": "pass"}}
- {"dt": "2024-07-07T08:36:58.082808", "lvl": "debug", "msg": "start: 1.5.2.4.8 test-runscript-overlay (timeout 00:09:54) [common]"}
- {"dt": "2024-07-07T08:36:58.089322", "lvl": "debug", "msg": "runner path: /var/lib/lava/dispatcher/tmp/35313/lava-overlay-3ufcabdo/lava-35313/1/tests/1_bootrr test_uuid 35313_1.5.2.4.5"}
- {"dt": "2024-07-07T08:36:58.090991", "lvl": "debug", "msg": "end: 1.5.2.4.8 test-runscript-overlay (duration 00:00:00) [common]"}
- {"dt": "2024-07-07T08:36:58.091868", "lvl": "results", "msg": {"case": "test-runscript-overlay", "definition": "lava", "duration": "0.01", "extra": {"filename": "/var/lib/lava/dispatcher/tmp/35313/lava-overlay-3ufcabdo/lava-35313/1/tests/1_bootrr/run.sh", "from": "inline", "name": "bootrr", "path": "inline/bootrr.yaml", "uuid": "35313_1.5.2.4.5"}, "level": "1.5.2.4.8", "namespace": "common", "result": "pass"}}
- {"dt": "2024-07-07T08:36:58.093356", "lvl": "info", "msg": "Creating lava-test-runner.conf files"}
- {"dt": "2024-07-07T08:36:58.094089", "lvl": "debug", "msg": "Using lava-test-runner path: /var/lib/lava/dispatcher/tmp/35313/lava-overlay-3ufcabdo/lava-35313/0 for stage 0"}
- {"dt": "2024-07-07T08:36:58.095095", "lvl": "debug", "msg": "- 0_dmesg"}
- {"dt": "2024-07-07T08:36:58.096025", "lvl": "debug", "msg": "Using lava-test-runner path: /var/lib/lava/dispatcher/tmp/35313/lava-overlay-3ufcabdo/lava-35313/1 for stage 1"}
- {"dt": "2024-07-07T08:36:58.097164", "lvl": "debug", "msg": "- 1_bootrr"}
- {"dt": "2024-07-07T08:36:58.098619", "lvl": "debug", "msg": "end: 1.5.2.4 test-definition (duration 00:00:00) [common]"}
- {"dt": "2024-07-07T08:36:58.099693", "lvl": "debug", "msg": "start: 1.5.2.5 compress-overlay (timeout 00:09:54) [common]"}
- {"dt": "2024-07-07T08:36:58.161060", "lvl": "debug", "msg": "end: 1.5.2.5 compress-overlay (duration 00:00:00) [common]"}
- {"dt": "2024-07-07T08:36:58.162157", "lvl": "debug", "msg": "start: 1.5.2.6 persistent-nfs-overlay (timeout 00:09:54) [common]"}
- {"dt": "2024-07-07T08:36:58.163059", "lvl": "debug", "msg": "end: 1.5.2.6 persistent-nfs-overlay (duration 00:00:00) [common]"}
- {"dt": "2024-07-07T08:36:58.163979", "lvl": "debug", "msg": "end: 1.5.2 lava-overlay (duration 00:00:00) [common]"}
- {"dt": "2024-07-07T08:36:58.164984", "lvl": "debug", "msg": "start: 1.5.3 extract-overlay-ramdisk (timeout 00:09:54) [common]"}
- {"dt": "2024-07-07T08:37:00.010087", "lvl": "debug", "msg": "end: 1.5.3 extract-overlay-ramdisk (duration 00:00:02) [common]"}
- {"dt": "2024-07-07T08:37:00.010894", "lvl": "debug", "msg": "start: 1.5.4 extract-modules (timeout 00:09:52) [common]"}
- {"dt": "2024-07-07T08:37:00.011436", "lvl": "info", "msg": "extracting modules file /var/lib/lava/dispatcher/tmp/35313/tftp-deploy-b9hrn41v/modules/modules.tar to /var/lib/lava/dispatcher/tmp/35313/extract-overlay-ramdisk-4k20r3x2/ramdisk"}
- {"dt": "2024-07-07T08:37:00.432964", "lvl": "debug", "msg": "end: 1.5.4 extract-modules (duration 00:00:00) [common]"}
- {"dt": "2024-07-07T08:37:00.433766", "lvl": "debug", "msg": "start: 1.5.5 apply-overlay-tftp (timeout 00:09:52) [common]"}
- {"dt": "2024-07-07T08:37:00.434302", "lvl": "info", "msg": "[common] Applying overlay /var/lib/lava/dispatcher/tmp/35313/compress-overlay-u7_cf9xc/overlay-1.5.2.5.tar.gz to ramdisk"}
- {"dt": "2024-07-07T08:37:00.434732", "lvl": "debug", "msg": "[common] Applying overlay /var/lib/lava/dispatcher/tmp/35313/compress-overlay-u7_cf9xc/overlay-1.5.2.5.tar.gz to directory /var/lib/lava/dispatcher/tmp/35313/extract-overlay-ramdisk-4k20r3x2/ramdisk"}
- {"dt": "2024-07-07T08:37:00.516817", "lvl": "debug", "msg": "end: 1.5.5 apply-overlay-tftp (duration 00:00:00) [common]"}
- {"dt": "2024-07-07T08:37:00.517612", "lvl": "debug", "msg": "start: 1.5.6 prepare-kernel (timeout 00:09:51) [common]"}
- {"dt": "2024-07-07T08:37:00.518179", "lvl": "debug", "msg": "start: 1.5.6.1 uboot-prepare-kernel (timeout 00:09:51) [common]"}
- {"dt": "2024-07-07T08:37:00.518775", "lvl": "debug", "msg": "end: 1.5.6.1 uboot-prepare-kernel (duration 00:00:00) [common]"}
- {"dt": "2024-07-07T08:37:00.519316", "lvl": "debug", "msg": "end: 1.5.6 prepare-kernel (duration 00:00:00) [common]"}
- {"dt": "2024-07-07T08:37:00.519855", "lvl": "debug", "msg": "start: 1.5.7 configure-preseed-file (timeout 00:09:51) [common]"}
- {"dt": "2024-07-07T08:37:00.520484", "lvl": "debug", "msg": "end: 1.5.7 configure-preseed-file (duration 00:00:00) [common]"}
- {"dt": "2024-07-07T08:37:00.521324", "lvl": "debug", "msg": "start: 1.5.8 compress-ramdisk (timeout 00:09:51) [common]"}
- {"dt": "2024-07-07T08:37:00.522022", "lvl": "info", "msg": "Building ramdisk /var/lib/lava/dispatcher/tmp/35313/extract-overlay-ramdisk-4k20r3x2/ramdisk.cpio containing /var/lib/lava/dispatcher/tmp/35313/extract-overlay-ramdisk-4k20r3x2/ramdisk"}
- {"dt": "2024-07-07T08:37:03.378415", "lvl": "debug", "msg": ">> 86851 blocks\n"}
- {"dt": "2024-07-07T08:37:09.888881", "lvl": "debug", "msg": "Adding RAMdisk u-boot header."}
- {"dt": "2024-07-07T08:37:09.889850", "lvl": "debug", "msg": "mkimage -A riscv -T ramdisk -C none -d /var/lib/lava/dispatcher/tmp/35313/extract-overlay-ramdisk-4k20r3x2/ramdisk.cpio.gz /var/lib/lava/dispatcher/tmp/35313/extract-overlay-ramdisk-4k20r3x2/ramdisk.cpio.gz.uboot"}
- {"dt": "2024-07-07T08:37:10.098063", "lvl": "debug", "msg": "output: Image Name:   "}
- {"dt": "2024-07-07T08:37:10.098705", "lvl": "debug", "msg": "output: Created:      Sun Jul  7 08:37:09 2024"}
- {"dt": "2024-07-07T08:37:10.099105", "lvl": "debug", "msg": "output: Image Type:   RISC-V Linux RAMDisk Image (uncompressed)"}
- {"dt": "2024-07-07T08:37:10.099489", "lvl": "debug", "msg": "output: Data Size:    13643990 Bytes = 13324.21 KiB = 13.01 MiB"}
- {"dt": "2024-07-07T08:37:10.100426", "lvl": "debug", "msg": "output: Load Address: 00000000"}
- {"dt": "2024-07-07T08:37:10.100991", "lvl": "debug", "msg": "output: Entry Point:  00000000"}
- {"dt": "2024-07-07T08:37:10.101503", "lvl": "debug", "msg": "output: "}
- {"dt": "2024-07-07T08:37:10.102285", "lvl": "debug", "msg": "rename /var/lib/lava/dispatcher/tmp/35313/extract-overlay-ramdisk-4k20r3x2/ramdisk.cpio.gz.uboot to /var/lib/lava/dispatcher/tmp/35313/tftp-deploy-b9hrn41v/ramdisk/ramdisk.cpio.gz.uboot"}
- {"dt": "2024-07-07T08:37:10.103087", "lvl": "debug", "msg": "end: 1.5.8 compress-ramdisk (duration 00:00:10) [common]"}
- {"dt": "2024-07-07T08:37:10.103755", "lvl": "debug", "msg": "end: 1.5 prepare-tftp-overlay (duration 00:00:12) [common]"}
- {"dt": "2024-07-07T08:37:10.104434", "lvl": "debug", "msg": "start: 1.6 lxc-create-udev-rule-action (timeout 00:09:42) [common]"}
- {"dt": "2024-07-07T08:37:10.105219", "lvl": "debug", "msg": "No LXC device requested"}
- {"dt": "2024-07-07T08:37:10.106031", "lvl": "debug", "msg": "end: 1.6 lxc-create-udev-rule-action (duration 00:00:00) [common]"}
- {"dt": "2024-07-07T08:37:10.106644", "lvl": "debug", "msg": "start: 1.7 deploy-device-env (timeout 00:09:42) [common]"}
- {"dt": "2024-07-07T08:37:10.107225", "lvl": "debug", "msg": "end: 1.7 deploy-device-env (duration 00:00:00) [common]"}
- {"dt": "2024-07-07T08:37:10.107699", "lvl": "debug", "msg": "Checking files for TFTP limit of 4294967296 bytes."}
- {"dt": "2024-07-07T08:37:10.110735", "lvl": "info", "msg": "end: 1 tftp-deploy (duration 00:00:18) [common]"}
- {"dt": "2024-07-07T08:37:10.111477", "lvl": "info", "msg": "start: 2 uboot-action (timeout 00:05:00) [common]"}
- {"dt": "2024-07-07T08:37:10.112165", "lvl": "debug", "msg": "start: 2.1 uboot-from-media (timeout 00:05:00) [common]"}
- {"dt": "2024-07-07T08:37:10.112883", "lvl": "debug", "msg": "end: 2.1 uboot-from-media (duration 00:00:00) [common]"}
- {"dt": "2024-07-07T08:37:10.113509", "lvl": "debug", "msg": "start: 2.2 bootloader-overlay (timeout 00:05:00) [common]"}
- {"dt": "2024-07-07T08:37:10.114336", "lvl": "debug", "msg": "substitutions:"}
- {"dt": "2024-07-07T08:37:10.114849", "lvl": "debug", "msg": "- {BOOTX}: booti 0x80200000 0x83500000 0x83000000"}
- {"dt": "2024-07-07T08:37:10.115303", "lvl": "debug", "msg": "- {DTB_ADDR}: 0x83000000"}
- {"dt": "2024-07-07T08:37:10.115792", "lvl": "debug", "msg": "- {DTB}: 35313/tftp-deploy-b9hrn41v/dtb/hifive-unmatched-a00.dtb"}
- {"dt": "2024-07-07T08:37:10.116236", "lvl": "debug", "msg": "- {INITRD}: 35313/tftp-deploy-b9hrn41v/ramdisk/ramdisk.cpio.gz.uboot"}
- {"dt": "2024-07-07T08:37:10.116743", "lvl": "debug", "msg": "- {KERNEL_ADDR}: 0x80200000"}
- {"dt": "2024-07-07T08:37:10.117187", "lvl": "debug", "msg": "- {KERNEL}: 35313/tftp-deploy-b9hrn41v/kernel/Image"}
- {"dt": "2024-07-07T08:37:10.117620", "lvl": "debug", "msg": "- {LAVA_MAC}: None"}
- {"dt": "2024-07-07T08:37:10.118061", "lvl": "debug", "msg": "- {PRESEED_CONFIG}: None"}
- {"dt": "2024-07-07T08:37:10.118494", "lvl": "debug", "msg": "- {PRESEED_LOCAL}: None"}
- {"dt": "2024-07-07T08:37:10.118916", "lvl": "debug", "msg": "- {RAMDISK_ADDR}: 0x83500000"}
- {"dt": "2024-07-07T08:37:10.119335", "lvl": "debug", "msg": "- {RAMDISK}: 35313/tftp-deploy-b9hrn41v/ramdisk/ramdisk.cpio.gz.uboot"}
- {"dt": "2024-07-07T08:37:10.119761", "lvl": "debug", "msg": "- {ROOT_PART}: None"}
- {"dt": "2024-07-07T08:37:10.120182", "lvl": "debug", "msg": "- {ROOT}: None"}
- {"dt": "2024-07-07T08:37:10.120719", "lvl": "debug", "msg": "- {SERVER_IP}: 192.168.66.1"}
- {"dt": "2024-07-07T08:37:10.121170", "lvl": "debug", "msg": "- {TEE_ADDR}: 0x83000000"}
- {"dt": "2024-07-07T08:37:10.121600", "lvl": "debug", "msg": "- {TEE}: None"}
- {"dt": "2024-07-07T08:37:10.122028", "lvl": "info", "msg": "Parsed boot commands:"}
- {"dt": "2024-07-07T08:37:10.122441", "lvl": "info", "msg": "- setenv autoload no"}
- {"dt": "2024-07-07T08:37:10.122860", "lvl": "info", "msg": "- setenv initrd_high 0xffffffffffffffff"}
- {"dt": "2024-07-07T08:37:10.123280", "lvl": "info", "msg": "- setenv fdt_high 0xffffffffffffffff"}
- {"dt": "2024-07-07T08:37:10.123700", "lvl": "info", "msg": "- dhcp"}
- {"dt": "2024-07-07T08:37:10.124114", "lvl": "info", "msg": "- setenv serverip 192.168.66.1"}
- {"dt": "2024-07-07T08:37:10.124575", "lvl": "info", "msg": "- tftp 0x80200000 35313/tftp-deploy-b9hrn41v/kernel/Image"}
- {"dt": "2024-07-07T08:37:10.125011", "lvl": "info", "msg": "- tftp 0x83500000 35313/tftp-deploy-b9hrn41v/ramdisk/ramdisk.cpio.gz.uboot"}
- {"dt": "2024-07-07T08:37:10.125437", "lvl": "info", "msg": "- setenv initrd_size ${filesize}"}
- {"dt": "2024-07-07T08:37:10.125860", "lvl": "info", "msg": "- tftp 0x83000000 35313/tftp-deploy-b9hrn41v/dtb/hifive-unmatched-a00.dtb"}
- {"dt": "2024-07-07T08:37:10.126282", "lvl": "info", "msg": "- setenv bootargs '115200 root=/dev/ram0 console_msg_format=syslog earlycon deferred_probe_timeout=60 ip=dhcp'"}
- {"dt": "2024-07-07T08:37:10.126712", "lvl": "info", "msg": "- booti 0x80200000 0x83500000 0x83000000"}
- {"dt": "2024-07-07T08:37:10.127326", "lvl": "debug", "msg": "end: 2.2 bootloader-overlay (duration 00:00:00) [common]"}
- {"dt": "2024-07-07T08:37:10.127832", "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-07-07T08:37:10.129177", "lvl": "debug", "msg": "start: 2.3 connect-device (timeout 00:05:00) [common]"}
- {"dt": "2024-07-07T08:37:10.129698", "lvl": "info", "msg": "[common] connect-device Connecting to device using 'telnet 127.0.0.1 63006'"}
- {"dt": "2024-07-07T08:37:14.726886", "lvl": "debug", "msg": "Setting prompt string to ['lava-test: # ']"}
- {"dt": "2024-07-07T08:37:14.729740", "lvl": "debug", "msg": "end: 2.3 connect-device (duration 00:00:05) [common]"}
- {"dt": "2024-07-07T08:37:14.731056", "lvl": "debug", "msg": "start: 2.4 uboot-commands (timeout 00:04:55) [common]"}
- {"dt": "2024-07-07T08:37:14.733850", "lvl": "debug", "msg": "start: 2.4.1 reset-device (timeout 00:04:55) [common]"}
- {"dt": "2024-07-07T08:37:14.734660", "lvl": "debug", "msg": "start: 2.4.1.1 pdu-reboot (timeout 00:04:55) [common]"}
- {"dt": "2024-07-07T08:37:14.735811", "lvl": "debug", "msg": "Calling: 'upower.sh' '--atx' 'reset' '1'"}
- {"dt": "2024-07-07T08:37:19.806953", "lvl": "debug", "msg": ">> Accessing Gembird #0 USB device 016\r"}
- {"dt": "2024-07-07T08:37:19.809261", "lvl": "debug", "msg": ">> Switched outlet 1 off\r"}
- {"dt": "2024-07-07T08:37:23.530655", "lvl": "debug", "msg": ">> Accessing Gembird #0 USB device 016\r"}
- {"dt": "2024-07-07T08:37:23.531975", "lvl": "debug", "msg": ">> Switched outlet 1 on\r"}
- {"dt": "2024-07-07T08:37:25.671671", "lvl": "debug", "msg": ">> FTDI RELAY: power on\r"}
- {"dt": "2024-07-07T08:37:27.672141", "lvl": "debug", "msg": ">> FTDI RELAY: power off\r"}
- {"dt": "2024-07-07T08:37:27.701504", "lvl": "debug", "msg": "Returned 0 in 12 seconds"}
- {"dt": "2024-07-07T08:37:27.803797", "lvl": "debug", "msg": "end: 2.4.1.1 pdu-reboot (duration 00:00:13) [common]"}
- {"dt": "2024-07-07T08:37:27.804938", "lvl": "results", "msg": {"case": "pdu-reboot", "definition": "lava", "duration": "13.07", "extra": {"status": "success"}, "level": "2.4.1.1", "namespace": "common", "result": "pass"}}
- {"dt": "2024-07-07T08:37:27.806919", "lvl": "debug", "msg": "end: 2.4.1 reset-device (duration 00:00:13) [common]"}
- {"dt": "2024-07-07T08:37:27.808080", "lvl": "debug", "msg": "start: 2.4.2 bootloader-interrupt (timeout 00:04:42) [common]"}
- {"dt": "2024-07-07T08:37:27.809083", "lvl": "debug", "msg": "Setting prompt string to ['Hit any key to stop autoboot']"}
- {"dt": "2024-07-07T08:37:27.809795", "lvl": "debug", "msg": "bootloader-interrupt: Wait for prompt ['Hit any key to stop autoboot'] (timeout 00:05:00)"}
- {"dt": "2024-07-07T08:37:27.811682", "lvl": "target", "msg": "Trying 127.0.0.1..."}
- {"dt": "2024-07-07T08:37:27.812394", "lvl": "target", "msg": "Connected to 127.0.0.1."}
- {"dt": "2024-07-07T08:37:27.813021", "lvl": "target", "msg": "Escape character is '^]'."}
- {"dt": "2024-07-07T08:37:36.062473", "lvl": "target", "msg": ""}
- {"dt": "2024-07-07T08:37:36.078200", "lvl": "target", "msg": "U-Boot SPL 2023.07.02 (Jul 11 2023 - 15:20:44 +0000)"}
- {"dt": "2024-07-07T08:37:36.206039", "lvl": "target", "msg": "Trying to boot from MMC1"}
- {"dt": "2024-07-07T08:37:36.940088", "lvl": "target", "msg": ""}
- {"dt": "2024-07-07T08:37:36.940954", "lvl": "target", "msg": ""}
- {"dt": "2024-07-07T08:37:36.941626", "lvl": "target", "msg": "U-Boot 2023.07.02 (Jul 11 2023 - 15:20:44 +0000)"}
- {"dt": "2024-07-07T08:37:36.942255", "lvl": "target", "msg": ""}
- {"dt": "2024-07-07T08:37:36.944140", "lvl": "target", "msg": "CPU:   rv64imafdc"}
- {"dt": "2024-07-07T08:37:36.957739", "lvl": "target", "msg": "Model: SiFive HiFive Unmatched A00"}
- {"dt": "2024-07-07T08:37:36.958514", "lvl": "target", "msg": "DRAM:  16 GiB"}
- {"dt": "2024-07-07T08:37:37.005864", "lvl": "target", "msg": "Core:  28 devices, 19 uclasses, devicetree: separate"}
- {"dt": "2024-07-07T08:37:37.019668", "lvl": "target", "msg": "MMC:   spi@10050000:mmc@0: 0"}
- {"dt": "2024-07-07T08:37:37.022242", "lvl": "target", "msg": "Loading Environment from SPIFlash... SF: Detected is25wp256 with page size 256 Bytes, erase size 4 KiB, total 32 MiB"}
- {"dt": "2024-07-07T08:37:37.054204", "lvl": "target", "msg": "*** Warning - bad CRC, using default environment"}
- {"dt": "2024-07-07T08:37:37.055202", "lvl": "target", "msg": ""}
- {"dt": "2024-07-07T08:37:37.067730", "lvl": "target", "msg": "EEPROM: SiFive PCB EEPROM format v1"}
- {"dt": "2024-07-07T08:37:37.069473", "lvl": "target", "msg": "Product ID: 0002 (HiFive Unmatched)"}
- {"dt": "2024-07-07T08:37:37.070617", "lvl": "target", "msg": "PCB revision: 3"}
- {"dt": "2024-07-07T08:37:37.071566", "lvl": "target", "msg": "BOM revision: B"}
- {"dt": "2024-07-07T08:37:37.072572", "lvl": "target", "msg": "BOM variant: 0"}
- {"dt": "2024-07-07T08:37:37.083593", "lvl": "target", "msg": "Serial number: SF105SZ212500053"}
- {"dt": "2024-07-07T08:37:37.084752", "lvl": "target", "msg": "Ethernet MAC address: 70:b3:d5:92:fa:8d"}
- {"dt": "2024-07-07T08:37:37.085821", "lvl": "target", "msg": "CRC: 6508cedc"}
- {"dt": "2024-07-07T08:37:37.086678", "lvl": "target", "msg": "In:    serial@10010000"}
- {"dt": "2024-07-07T08:37:37.087428", "lvl": "target", "msg": "Out:   serial@10010000"}
- {"dt": "2024-07-07T08:37:37.088566", "lvl": "target", "msg": "Err:   serial@10010000"}
- {"dt": "2024-07-07T08:37:37.089385", "lvl": "target", "msg": "Model: SiFive HiFive Unmatched A00"}
- {"dt": "2024-07-07T08:37:37.099964", "lvl": "target", "msg": "Net:   eth0: ethernet@10090000"}
- {"dt": "2024-07-07T08:37:37.100662", "lvl": "target", "msg": "Working FDT set to ff72f7f0"}
- {"dt": "2024-07-07T08:37:37.102516", "lvl": "input", "msg": "\n"}
- {"dt": "2024-07-07T08:37:37.153429", "lvl": "target", "msg": "Hit any key to stop autoboot:  2 "}
- {"dt": "2024-07-07T08:37:37.155031", "lvl": "debug", "msg": "end: 2.4.2 bootloader-interrupt (duration 00:00:09) [common]"}
- {"dt": "2024-07-07T08:37:37.156414", "lvl": "debug", "msg": "start: 2.4.3 bootloader-commands (timeout 00:04:33) [common]"}
- {"dt": "2024-07-07T08:37:37.157361", "lvl": "debug", "msg": "Setting prompt string to ['=>']"}
- {"dt": "2024-07-07T08:37:37.158199", "lvl": "debug", "msg": "bootloader-commands: Wait for prompt ['=>'] (timeout 00:04:33)"}
- {"dt": "2024-07-07T08:37:37.182096", "lvl": "target", "msg": "\b\b\b 0 "}
- {"dt": "2024-07-07T08:37:37.184576", "lvl": "debug", "msg": "Setting prompt string to ['=>', '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": "2024-07-07T08:37:37.186012", "lvl": "input", "msg": "setenv autoload no\n"}
- {"dt": "2024-07-07T08:37:37.288161", "lvl": "target", "msg": "=> setenv autoload no"}
- {"dt": "2024-07-07T08:37:37.289675", "lvl": "debug", "msg": "bootloader-commands: Wait for prompt ['=>', '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:33)"}
- {"dt": "2024-07-07T08:37:37.299118", "lvl": "target", "msg": "setenv autoload no"}
- {"dt": "2024-07-07T08:37:37.300242", "lvl": "input", "msg": "setenv initrd_high 0xffffffffffffffff\n"}
- {"dt": "2024-07-07T08:37:37.401293", "lvl": "target", "msg": "=> setenv initrd_high 0xffffffffffffffff"}
- {"dt": "2024-07-07T08:37:37.402345", "lvl": "debug", "msg": "bootloader-commands: Wait for prompt ['=>', '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:33)"}
- {"dt": "2024-07-07T08:37:37.406430", "lvl": "target", "msg": "setenv initrd_high 0xffffffffffffffff"}
- {"dt": "2024-07-07T08:37:37.422285", "lvl": "input", "msg": "setenv fdt_high 0xffffffffffffffff\n"}
- {"dt": "2024-07-07T08:37:37.523486", "lvl": "target", "msg": "=> setenv fdt_high 0xffffffffffffffff"}
- {"dt": "2024-07-07T08:37:37.525018", "lvl": "debug", "msg": "bootloader-commands: Wait for prompt ['=>', '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:33)"}
- {"dt": "2024-07-07T08:37:37.534240", "lvl": "target", "msg": "setenv fdt_high 0xffffffffffffffff"}
- {"dt": "2024-07-07T08:37:37.535296", "lvl": "input", "msg": "dhcp\n"}
- {"dt": "2024-07-07T08:37:37.636517", "lvl": "target", "msg": "=> dhcp"}
- {"dt": "2024-07-07T08:37:37.637885", "lvl": "debug", "msg": "bootloader-commands: Wait for prompt ['=>', '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:32)"}
- {"dt": "2024-07-07T08:37:37.646043", "lvl": "target", "msg": "dhcp"}
- {"dt": "2024-07-07T08:37:37.646764", "lvl": "target", "msg": "ethernet@10090000: PHY present at 0"}
- {"dt": "2024-07-07T08:37:37.662135", "lvl": "target", "msg": "ethernet@10090000: Starting autonegotiation..."}
- {"dt": "2024-07-07T08:37:40.235699", "lvl": "target", "msg": "ethernet@10090000: Autonegotiation complete"}
- {"dt": "2024-07-07T08:37:40.239681", "lvl": "target", "msg": "ethernet@10090000: link up, 100Mbps full-duplex (lpa: 0xcde1)"}
- {"dt": "2024-07-07T08:37:40.253631", "lvl": "target", "msg": "BOOTP broadcast 1"}
- {"dt": "2024-07-07T08:37:40.493956", "lvl": "target", "msg": "BOOTP broadcast 2"}
- {"dt": "2024-07-07T08:37:41.006464", "lvl": "target", "msg": "BOOTP broadcast 3"}
- {"dt": "2024-07-07T08:37:41.278035", "lvl": "target", "msg": "DHCP client bound to address 192.168.66.244 (1031 ms)"}
- {"dt": "2024-07-07T08:37:41.279356", "lvl": "input", "msg": "setenv serverip 192.168.66.1\n"}
- {"dt": "2024-07-07T08:37:41.380746", "lvl": "target", "msg": "=> setenv serverip 192.168.66.1"}
- {"dt": "2024-07-07T08:37:41.383326", "lvl": "debug", "msg": "bootloader-commands: Wait for prompt ['=>', '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:29)"}
- {"dt": "2024-07-07T08:37:41.390539", "lvl": "target", "msg": "setenv serverip 192.168.66.1"}
- {"dt": "2024-07-07T08:37:41.392862", "lvl": "input", "msg": "tftp 0x80200000 35313/tftp-deploy-b9hrn41v/kernel/Image\n"}
- {"dt": "2024-07-07T08:37:41.493979", "lvl": "target", "msg": "=> tftp 0x80200000 35313/tftp-deploy-b9hrn41v/kernel/Image"}
- {"dt": "2024-07-07T08:37:41.496297", "lvl": "debug", "msg": "bootloader-commands: Wait for prompt ['=>', '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:29)"}
- {"dt": "2024-07-07T08:37:41.502528", "lvl": "target", "msg": "tftp 0x80200000 35313/tftp-deploy-b9hrn41v/kernel/Image"}
- {"dt": "2024-07-07T08:37:41.515484", "lvl": "target", "msg": "ethernet@10090000: PHY present at 0"}
- {"dt": "2024-07-07T08:37:41.518804", "lvl": "target", "msg": "ethernet@10090000: Starting autonegotiation..."}
- {"dt": "2024-07-07T08:37:43.774746", "lvl": "target", "msg": "ethernet@10090000: Autonegotiation complete"}
- {"dt": "2024-07-07T08:37:43.787806", "lvl": "target", "msg": "ethernet@10090000: link up, 100Mbps full-duplex (lpa: 0xcde1)"}
- {"dt": "2024-07-07T08:37:43.789566", "lvl": "target", "msg": "Using ethernet@10090000 device"}
- {"dt": "2024-07-07T08:37:43.791719", "lvl": "target", "msg": "TFTP from server 192.168.66.1; our IP address is 192.168.66.244"}
- {"dt": "2024-07-07T08:37:43.805496", "lvl": "target", "msg": "Filename '35313/tftp-deploy-b9hrn41v/kernel/Image'."}
- {"dt": "2024-07-07T08:37:43.806494", "lvl": "target", "msg": "Load address: 0x80200000"}
- {"dt": "2024-07-07T08:37:44.366845", "lvl": "target", "msg": "Loading: *\b#################################################################"}
- {"dt": "2024-07-07T08:37:44.926571", "lvl": "target", "msg": "\t #################################################################"}
- {"dt": "2024-07-07T08:37:45.485983", "lvl": "target", "msg": "\t #################################################################"}
- {"dt": "2024-07-07T08:37:46.013733", "lvl": "target", "msg": "\t #################################################################"}
- {"dt": "2024-07-07T08:37:46.541321", "lvl": "target", "msg": "\t #################################################################"}
- {"dt": "2024-07-07T08:37:47.086166", "lvl": "target", "msg": "\t #################################################################"}
- {"dt": "2024-07-07T08:37:47.614035", "lvl": "target", "msg": "\t #################################################################"}
- {"dt": "2024-07-07T08:37:48.141823", "lvl": "target", "msg": "\t #################################################################"}
- {"dt": "2024-07-07T08:37:48.669554", "lvl": "target", "msg": "\t #################################################################"}
- {"dt": "2024-07-07T08:37:49.197352", "lvl": "target", "msg": "\t #################################################################"}
- {"dt": "2024-07-07T08:37:49.758013", "lvl": "target", "msg": "\t #################################################################"}
- {"dt": "2024-07-07T08:37:50.317783", "lvl": "target", "msg": "\t #################################################################"}
- {"dt": "2024-07-07T08:37:50.877514", "lvl": "target", "msg": "\t #################################################################"}
- {"dt": "2024-07-07T08:37:51.438682", "lvl": "target", "msg": "\t #################################################################"}
- {"dt": "2024-07-07T08:37:52.029524", "lvl": "target", "msg": "\t #################################################################"}
- {"dt": "2024-07-07T08:37:52.621512", "lvl": "target", "msg": "\t #################################################################"}
- {"dt": "2024-07-07T08:37:53.214280", "lvl": "target", "msg": "\t #################################################################"}
- {"dt": "2024-07-07T08:37:53.776595", "lvl": "target", "msg": "\t #################################################################"}
- {"dt": "2024-07-07T08:37:54.317306", "lvl": "target", "msg": "\t #################################################################"}
- {"dt": "2024-07-07T08:37:54.909550", "lvl": "target", "msg": "\t #################################################################"}
- {"dt": "2024-07-07T08:37:55.355291", "lvl": "target", "msg": "\t ####################################################"}
- {"dt": "2024-07-07T08:37:55.357068", "lvl": "target", "msg": "\t 1.6 MiB/s"}
- {"dt": "2024-07-07T08:37:55.359204", "lvl": "target", "msg": "done"}
- {"dt": "2024-07-07T08:37:55.361407", "lvl": "target", "msg": "Bytes transferred = 19845120 (12ed000 hex)"}
- {"dt": "2024-07-07T08:37:55.362450", "lvl": "input", "msg": "tftp 0x83500000 35313/tftp-deploy-b9hrn41v/ramdisk/ramdisk.cpio.gz.uboot\n"}
- {"dt": "2024-07-07T08:37:55.463856", "lvl": "target", "msg": "=>tftp 0x83500000 35313/tftp-deploy-b9hrn41v/ramdisk/ramdisk.cpio.gz.uboot"}
- {"dt": "2024-07-07T08:37:55.466608", "lvl": "debug", "msg": "bootloader-commands: Wait for prompt ['=>', '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:15)"}
- {"dt": "2024-07-07T08:37:55.483332", "lvl": "target", "msg": " tftp 0x83500000 35313/tftp-deploy-b9hrn41v/ramdisk/ramdisk.cpio.gz.uboot"}
- {"dt": "2024-07-07T08:37:55.484916", "lvl": "target", "msg": "ethernet@10090000: PHY present at 0"}
- {"dt": "2024-07-07T08:37:55.525027", "lvl": "target", "msg": "ethernet@10090000: Starting autonegotiation..."}
- {"dt": "2024-07-07T08:37:57.677451", "lvl": "target", "msg": "ethernet@10090000: Autonegotiation complete"}
- {"dt": "2024-07-07T08:37:57.691230", "lvl": "target", "msg": "ethernet@10090000: link up, 100Mbps full-duplex (lpa: 0xcde1)"}
- {"dt": "2024-07-07T08:37:57.694587", "lvl": "target", "msg": "Using ethernet@10090000 device"}
- {"dt": "2024-07-07T08:37:57.707276", "lvl": "target", "msg": "TFTP from server 192.168.66.1; our IP address is 192.168.66.244"}
- {"dt": "2024-07-07T08:37:57.708779", "lvl": "target", "msg": "Filename '35313/tftp-deploy-b9hrn41v/ramdisk/ramdisk.cpio.gz.uboot'."}
- {"dt": "2024-07-07T08:37:57.710726", "lvl": "target", "msg": "Load address: 0x83500000"}
- {"dt": "2024-07-07T08:37:58.317175", "lvl": "target", "msg": "Loading: *\b#################################################################"}
- {"dt": "2024-07-07T08:37:58.941364", "lvl": "target", "msg": "\t #################################################################"}
- {"dt": "2024-07-07T08:37:59.533399", "lvl": "target", "msg": "\t #################################################################"}
- {"dt": "2024-07-07T08:38:00.110071", "lvl": "target", "msg": "\t #################################################################"}
- {"dt": "2024-07-07T08:38:00.701319", "lvl": "target", "msg": "\t #################################################################"}
- {"dt": "2024-07-07T08:38:01.261594", "lvl": "target", "msg": "\t #################################################################"}
- {"dt": "2024-07-07T08:38:01.836752", "lvl": "target", "msg": "\t #################################################################"}
- {"dt": "2024-07-07T08:38:02.381681", "lvl": "target", "msg": "\t #################################################################"}
- {"dt": "2024-07-07T08:38:02.893770", "lvl": "target", "msg": "\t #################################################################"}
- {"dt": "2024-07-07T08:38:03.440841", "lvl": "target", "msg": "\t #################################################################"}
- {"dt": "2024-07-07T08:38:03.967716", "lvl": "target", "msg": "\t #################################################################"}
- {"dt": "2024-07-07T08:38:04.477766", "lvl": "target", "msg": "\t #################################################################"}
- {"dt": "2024-07-07T08:38:05.020836", "lvl": "target", "msg": "\t #################################################################"}
- {"dt": "2024-07-07T08:38:05.565722", "lvl": "target", "msg": "\t #################################################################"}
- {"dt": "2024-07-07T08:38:05.738815", "lvl": "target", "msg": "\t ####################"}
- {"dt": "2024-07-07T08:38:05.740196", "lvl": "target", "msg": "\t 1.6 MiB/s"}
- {"dt": "2024-07-07T08:38:05.741486", "lvl": "target", "msg": "done"}
- {"dt": "2024-07-07T08:38:05.743310", "lvl": "target", "msg": "Bytes transferred = 13644054 (d03116 hex)"}
- {"dt": "2024-07-07T08:38:05.746051", "lvl": "input", "msg": "setenv initrd_size ${filesize}\n"}
- {"dt": "2024-07-07T08:38:05.847789", "lvl": "target", "msg": "=> setenv initrd_size ${filesize}"}
- {"dt": "2024-07-07T08:38:05.848895", "lvl": "debug", "msg": "bootloader-commands: Wait for prompt ['=>', '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:04)"}
- {"dt": "2024-07-07T08:38:05.869719", "lvl": "target", "msg": "setenv initrd_size ${filesize}"}
- {"dt": "2024-07-07T08:38:05.870811", "lvl": "input", "msg": "tftp 0x83000000 35313/tftp-deploy-b9hrn41v/dtb/hifive-unmatched-a00.dtb\n"}
- {"dt": "2024-07-07T08:38:05.972183", "lvl": "target", "msg": "=> tftp 0x83000000 35313/tftp-deploy-b9hrn41v/dtb/hifive-unmatched-a00.dtb"}
- {"dt": "2024-07-07T08:38:05.973701", "lvl": "debug", "msg": "bootloader-commands: Wait for prompt ['=>', '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:04)"}
- {"dt": "2024-07-07T08:38:05.981683", "lvl": "target", "msg": "tftp 0x83000000 35313/tftp-deploy-b9hrn41v/dtb/hifive-unmatched-a00.dtb"}
- {"dt": "2024-07-07T08:38:05.982639", "lvl": "target", "msg": "ethernet@10090000: PHY present at 0"}
- {"dt": "2024-07-07T08:38:05.997680", "lvl": "target", "msg": "ethernet@10090000: Starting autonegotiation..."}
- {"dt": "2024-07-07T08:38:08.109103", "lvl": "target", "msg": "ethernet@10090000: Autonegotiation complete"}
- {"dt": "2024-07-07T08:38:08.123515", "lvl": "target", "msg": "ethernet@10090000: link up, 100Mbps full-duplex (lpa: 0xcde1)"}
- {"dt": "2024-07-07T08:38:08.126798", "lvl": "target", "msg": "Using ethernet@10090000 device"}
- {"dt": "2024-07-07T08:38:08.138486", "lvl": "target", "msg": "TFTP from server 192.168.66.1; our IP address is 192.168.66.244"}
- {"dt": "2024-07-07T08:38:08.142134", "lvl": "target", "msg": "Filename '35313/tftp-deploy-b9hrn41v/dtb/hifive-unmatched-a00.dtb'."}
- {"dt": "2024-07-07T08:38:08.143646", "lvl": "target", "msg": "Load address: 0x83000000"}
- {"dt": "2024-07-07T08:38:08.154787", "lvl": "target", "msg": "Loading: *\b#"}
- {"dt": "2024-07-07T08:38:08.155979", "lvl": "target", "msg": "\t 950.2 KiB/s"}
- {"dt": "2024-07-07T08:38:08.157174", "lvl": "target", "msg": "done"}
- {"dt": "2024-07-07T08:38:08.158289", "lvl": "target", "msg": "Bytes transferred = 10707 (29d3 hex)"}
- {"dt": "2024-07-07T08:38:08.159917", "lvl": "input", "msg": "setenv bootargs '115200 root=/dev/ram0 console_msg_format=syslog earlycon deferred_probe_timeout=60 ip=dhcp'\n"}
- {"dt": "2024-07-07T08:38:08.261779", "lvl": "target", "msg": "=>setenv bootargs '115200 root=/dev/ram0 console_msg_format=syslog earlycon deferred_probe_timeout=60 ip=dhcp'"}
- {"dt": "2024-07-07T08:38:08.263858", "lvl": "debug", "msg": "bootloader-commands: Wait for prompt ['=>', '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:02)"}
- {"dt": "2024-07-07T08:38:08.268671", "lvl": "target", "msg": " setenv bootargs '115200 root=/dev/ram0 console_msg_format=syslog earlycon deferred_probe_timeout=60 ip=dhcp'"}
- {"dt": "2024-07-07T08:38:08.269526", "lvl": "input", "msg": "booti 0x80200000 0x83500000 0x83000000\n"}
- {"dt": "2024-07-07T08:38:08.370408", "lvl": "target", "msg": "=> booti 0x80200000 0x83500000 0x83000000"}
- {"dt": "2024-07-07T08:38:08.372628", "lvl": "debug", "msg": "Setting prompt string to ['Starting kernel', '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": "2024-07-07T08:38:08.373886", "lvl": "debug", "msg": "bootloader-commands: Wait for prompt ['Starting kernel', '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:02)"}
- {"dt": "2024-07-07T08:38:08.380906", "lvl": "target", "msg": "booti 0x80200000 0x83500000 0x83000000"}
- {"dt": "2024-07-07T08:38:08.394530", "lvl": "target", "msg": "## Loading init Ramdisk from Legacy Image at 83500000 ..."}
- {"dt": "2024-07-07T08:38:08.395334", "lvl": "target", "msg": "   Image Name:   "}
- {"dt": "2024-07-07T08:38:08.396663", "lvl": "target", "msg": "   Image Type:   RISC-V Linux RAMDisk Image (uncompressed)"}
- {"dt": "2024-07-07T08:38:08.397793", "lvl": "target", "msg": "   Data Size:    13643990 Bytes = 13 MiB"}
- {"dt": "2024-07-07T08:38:08.398891", "lvl": "target", "msg": "   Load Address: 00000000"}
- {"dt": "2024-07-07T08:38:08.399950", "lvl": "target", "msg": "   Entry Point:  00000000"}
- {"dt": "2024-07-07T08:38:08.524920", "lvl": "target", "msg": "   Verifying Checksum ... OK"}
- {"dt": "2024-07-07T08:38:08.539242", "lvl": "target", "msg": "## Flattened Device Tree blob at 83000000"}
- {"dt": "2024-07-07T08:38:08.540826", "lvl": "target", "msg": "   Booting using the fdt blob at 0x83000000"}
- {"dt": "2024-07-07T08:38:08.542295", "lvl": "target", "msg": "Working FDT set to 83000000"}
- {"dt": "2024-07-07T08:38:08.544842", "lvl": "target", "msg": "   Using Device Tree in place at 0000000083000000, end 00000000830059d2"}
- {"dt": "2024-07-07T08:38:08.546475", "lvl": "target", "msg": "Working FDT set to 83000000"}
- {"dt": "2024-07-07T08:38:08.555470", "lvl": "target", "msg": ""}
- {"dt": "2024-07-07T08:38:08.556087", "lvl": "target", "msg": "Starting kernel ..."}
- {"dt": "2024-07-07T08:38:08.556721", "lvl": "target", "msg": ""}
- {"dt": "2024-07-07T08:38:08.558135", "lvl": "debug", "msg": "end: 2.4.3 bootloader-commands (duration 00:00:31) [common]"}
- {"dt": "2024-07-07T08:38:08.559523", "lvl": "debug", "msg": "start: 2.4.4 auto-login-action (timeout 00:04:02) [common]"}
- {"dt": "2024-07-07T08:38:08.560762", "lvl": "debug", "msg": "Setting prompt string to ['Linux version [0-9]']"}
- {"dt": "2024-07-07T08:38:08.561488", "lvl": "debug", "msg": "Setting prompt string to ['Linux version [0-9]', '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": "2024-07-07T08:38:08.562201", "lvl": "debug", "msg": "auto-login-action: Wait for prompt ['Linux version [0-9]', '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:05:00)"}
- {"dt": "2024-07-07T08:38:08.563954", "lvl": "debug", "msg": "start: 2.4.4.1 login-action (timeout 00:04:02) [common]"}
- {"dt": "2024-07-07T08:38:08.564893", "lvl": "warning", "msg": "The string '/ #' does not look like a typical prompt and could match status messages instead. Please check the job log files and use a prompt string which matches the actual prompt string more closely."}
- {"dt": "2024-07-07T08:38:08.565620", "lvl": "debug", "msg": "Setting prompt string to []"}
- {"dt": "2024-07-07T08:38:08.566392", "lvl": "debug", "msg": "Setting prompt string to ['-\\\\[ cut here \\\\]', 'Unhandled fault', 'BUG: KCSAN:', 'BUG: KASAN:', 'BUG: KFENCE:', 'Oops(?: -|:)', 'WARNING:', '(kernel BUG at|BUG:)', 'invalid opcode:', 'Kernel panic - not syncing']"}
- {"dt": "2024-07-07T08:38:08.567119", "lvl": "debug", "msg": "Using line separator: #'\\n'#"}
- {"dt": "2024-07-07T08:38:08.567767", "lvl": "debug", "msg": "No login prompt set."}
- {"dt": "2024-07-07T08:38:08.568507", "lvl": "info", "msg": "Parsing kernel messages"}
- {"dt": "2024-07-07T08:38:08.569160", "lvl": "debug", "msg": ["-\\[ cut here \\]", "Unhandled fault", "BUG: KCSAN:", "BUG: KASAN:", "BUG: KFENCE:", "Oops(?: -|:)", "WARNING:", "(kernel BUG at|BUG:)", "invalid opcode:", "Kernel panic - not syncing", "/ #", "Login timed out", "Login incorrect"]}
- {"dt": "2024-07-07T08:38:08.570481", "lvl": "debug", "msg": "[login-action] Waiting for messages, (timeout 00:04:02)"}
- {"dt": "2024-07-07T08:38:08.574345", "lvl": "target", "msg": "[    0.000000] Linux version 6.1.54 (KernelCI@build-j50728-riscv-gcc-10-defconfig-75n2g) (riscv64-linux-gnu-gcc (Debian 10.2.1-6) 10.2.1 20210110, GNU ld (GNU Binutils for Debian) 2.35.2) #1 SMP Tue Sep 19 13:51:25 UTC 2023"}
- {"dt": "2024-07-07T08:38:08.575077", "lvl": "target", "msg": "[    0.000000] OF: fdt: Ignoring memory range 0x80000000 - 0x80200000"}
- {"dt": "2024-07-07T08:38:08.586613", "lvl": "target", "msg": "[    0.000000] Machine model: SiFive HiFive Unmatched A00"}
- {"dt": "2024-07-07T08:38:08.587944", "lvl": "target", "msg": "[    0.000000] earlycon: sifive0 at MMIO 0x0000000010010000 (options '')"}
- {"dt": "2024-07-07T08:38:08.589982", "lvl": "target", "msg": "[    0.000000] printk: bootconsole [sifive0] enabled"}
- {"dt": "2024-07-07T08:38:08.602694", "lvl": "target", "msg": "[    0.000000] efi: UEFI not found."}
- {"dt": "2024-07-07T08:38:08.603524", "lvl": "target", "msg": "[    0.000000] Zone ranges:"}
- {"dt": "2024-07-07T08:38:08.604826", "lvl": "target", "msg": "[    0.000000]   DMA32    [mem 0x0000000080200000-0x00000000ffffffff]"}
- {"dt": "2024-07-07T08:38:08.618555", "lvl": "target", "msg": "[    0.000000]   Normal   [mem 0x0000000100000000-0x000000047fffffff]"}
- {"dt": "2024-07-07T08:38:08.619834", "lvl": "target", "msg": "[    0.000000] Movable zone start for each node"}
- {"dt": "2024-07-07T08:38:08.620688", "lvl": "target", "msg": "[    0.000000] Early memory node ranges"}
- {"dt": "2024-07-07T08:38:08.634588", "lvl": "target", "msg": "[    0.000000]   node   0: [mem 0x0000000080200000-0x000000047fffffff]"}
- {"dt": "2024-07-07T08:38:08.638066", "lvl": "target", "msg": "[    0.000000] Initmem setup node 0 [mem 0x0000000080200000-0x000000047fffffff]"}
- {"dt": "2024-07-07T08:38:10.603113", "lvl": "target", "msg": "[    0.000000] SBI specification v1.0 detected"}
- {"dt": "2024-07-07T08:38:10.604967", "lvl": "target", "msg": "[    0.000000] SBI implementation ID=0x1 Version=0x10002"}
- {"dt": "2024-07-07T08:38:10.608623", "lvl": "target", "msg": "[    0.000000] SBI TIME extension detected"}
- {"dt": "2024-07-07T08:38:10.618541", "lvl": "target", "msg": "[    0.000000] SBI IPI extension detected"}
- {"dt": "2024-07-07T08:38:10.619094", "lvl": "target", "msg": "[    0.000000] SBI RFENCE extension detected"}
- {"dt": "2024-07-07T08:38:10.619921", "lvl": "target", "msg": "[    0.000000] SBI SRST extension detected"}
- {"dt": "2024-07-07T08:38:10.622227", "lvl": "target", "msg": "[    0.000000] SBI HSM extension detected"}
- {"dt": "2024-07-07T08:38:10.634604", "lvl": "target", "msg": "[    0.000000] CPU with hartid=0 is not available"}
- {"dt": "2024-07-07T08:38:10.635614", "lvl": "target", "msg": "[    0.000000] CPU with hartid=0 is not available"}
- {"dt": "2024-07-07T08:38:10.637171", "lvl": "target", "msg": "[    0.000000] CPU with hartid=0 is not available"}
- {"dt": "2024-07-07T08:38:10.638713", "lvl": "target", "msg": "[    0.000000] riscv: base ISA extensions acdfim"}
- {"dt": "2024-07-07T08:38:10.650583", "lvl": "target", "msg": "[    0.000000] riscv: ELF capabilities acdfim"}
- {"dt": "2024-07-07T08:38:10.652148", "lvl": "target", "msg": "[    0.000000] percpu: Embedded 18 pages/cpu s34744 r8192 d30792 u73728"}
- {"dt": "2024-07-07T08:38:10.654287", "lvl": "target", "msg": "[    0.000000] Built 1 zonelists, mobility grouping on.  Total pages: 4128264"}
- {"dt": "2024-07-07T08:38:10.667247", "lvl": "target", "msg": "[    0.000000] Kernel command line: 115200 root=/dev/ram0 console_msg_format=syslog earlycon deferred_probe_timeout=60 ip=dhcp"}
- {"dt": "2024-07-07T08:38:10.684907", "lvl": "target", "msg": "<5>[    0.000000] Unknown kernel command line parameters \\\"115200\\\", will be passed to user space."}
- {"dt": "2024-07-07T08:38:10.750225", "lvl": "target", "msg": "<6>[    0.000000] Dentry cache hash table entries: 2097152 (order: 12, 16777216 bytes, linear)"}
- {"dt": "2024-07-07T08:38:10.779785", "lvl": "target", "msg": "<6>[    0.000000] Inode-cache hash table entries: 1048576 (order: 11, 8388608 bytes, linear)"}
- {"dt": "2024-07-07T08:38:10.794860", "lvl": "target", "msg": "<6>[    0.000000] mem auto-init: stack:off, heap alloc:off, heap free:off"}
- {"dt": "2024-07-07T08:38:10.798168", "lvl": "target", "msg": "<6>[    0.000000] software IO TLB: area num 4."}
- {"dt": "2024-07-07T08:38:11.278327", "lvl": "target", "msg": "<6>[    0.000000] software IO TLB: mapped [mem 0x00000000fbfff000-0x00000000fffff000] (64MB)"}
- {"dt": "2024-07-07T08:38:12.410841", "lvl": "target", "msg": "<5>[    0.000000] Virtual kernel memory layout:"}
- {"dt": "2024-07-07T08:38:12.427685", "lvl": "target", "msg": "<5>[    0.000000]       fixmap : 0xffffffc6fea00000 - 0xffffffc6ff000000   (6144 kB)"}
- {"dt": "2024-07-07T08:38:12.430589", "lvl": "target", "msg": "<5>[    0.000000]       pci io : 0xffffffc6ff000000 - 0xffffffc700000000   (  16 MB)"}
- {"dt": "2024-07-07T08:38:12.442649", "lvl": "target", "msg": "<5>[    0.000000]      vmemmap : 0xffffffc700000000 - 0xffffffc800000000   (4096 MB)"}
- {"dt": "2024-07-07T08:38:12.446338", "lvl": "target", "msg": "<5>[    0.000000]      vmalloc : 0xffffffc800000000 - 0xffffffd800000000   (  64 GB)"}
- {"dt": "2024-07-07T08:38:12.458533", "lvl": "target", "msg": "<5>[    0.000000]      modules : 0xffffffff01361000 - 0xffffffff80000000   (2028 MB)"}
- {"dt": "2024-07-07T08:38:12.462230", "lvl": "target", "msg": "<5>[    0.000000]       lowmem : 0xffffffd800000000 - 0xffffffdbffe00000   (  15 GB)"}
- {"dt": "2024-07-07T08:38:12.474539", "lvl": "target", "msg": "<5>[    0.000000]       kernel : 0xffffffff80000000 - 0xffffffffffffffff   (2047 MB)"}
- {"dt": "2024-07-07T08:38:12.490639", "lvl": "target", "msg": "<6>[    0.000000] Memory: 16387892K/16775168K available (7456K kernel code, 4927K rwdata, 4096K rodata, 2164K init, 461K bss, 387276K reserved, 0K cma-reserved)"}
- {"dt": "2024-07-07T08:38:12.492841", "lvl": "target", "msg": "<6>[    0.000000] SLUB: HWalign=64, Order=0-3, MinObjects=0, CPUs=4, Nodes=1"}
- {"dt": "2024-07-07T08:38:12.494230", "lvl": "target", "msg": "<6>[    0.000000] rcu: Hierarchical RCU implementation."}
- {"dt": "2024-07-07T08:38:12.506614", "lvl": "target", "msg": "<6>[    0.000000] rcu: \tRCU restricting CPUs from NR_CPUS=64 to nr_cpu_ids=4."}
- {"dt": "2024-07-07T08:38:12.508424", "lvl": "target", "msg": "<6>[    0.000000] rcu: \tRCU debug extended QS entry/exit."}
- {"dt": "2024-07-07T08:38:12.510181", "lvl": "target", "msg": "<6>[    0.000000] \tTracing variant of Tasks RCU enabled."}
- {"dt": "2024-07-07T08:38:12.523426", "lvl": "target", "msg": "<6>[    0.000000] rcu: RCU calculated value of scheduler-enlistment delay is 25 jiffies."}
- {"dt": "2024-07-07T08:38:12.526280", "lvl": "target", "msg": "<6>[    0.000000] rcu: Adjusting geometry for rcu_fanout_leaf=16, nr_cpu_ids=4"}
- {"dt": "2024-07-07T08:38:12.538670", "lvl": "target", "msg": "<6>[    0.000000] NR_IRQS: 64, nr_irqs: 64, preallocated irqs: 0"}
- {"dt": "2024-07-07T08:38:12.540827", "lvl": "target", "msg": "<6>[    0.000000] CPU with hartid=0 is not available"}
- {"dt": "2024-07-07T08:38:12.542931", "lvl": "target", "msg": "<4>[    0.000000] riscv-intc: unable to find hart id for /cpus/cpu@0/interrupt-controller"}
- {"dt": "2024-07-07T08:38:12.554669", "lvl": "target", "msg": "<6>[    0.000000] riscv-intc: 64 local interrupts mapped"}
- {"dt": "2024-07-07T08:38:12.558254", "lvl": "target", "msg": "<6>[    0.000000] plic: interrupt-controller@c000000: mapped 69 interrupts with 4 handlers for 9 contexts."}
- {"dt": "2024-07-07T08:38:12.570659", "lvl": "target", "msg": "<6>[    0.000000] rcu: srcu_init: Setting srcu_struct sizes based on contention."}
- {"dt": "2024-07-07T08:38:12.574280", "lvl": "target", "msg": "<6>[    0.000000] riscv-timer: riscv_timer_init_dt: Registering clocksource cpuid [0] hartid [2]"}
- {"dt": "2024-07-07T08:38:12.587536", "lvl": "target", "msg": "<6>[    0.000000] clocksource: riscv_clocksource: mask: 0xffffffffffffffff max_cycles: 0x1d854df40, max_idle_ns: 3526361616960 ns"}
- {"dt": "2024-07-07T08:38:12.602698", "lvl": "target", "msg": "<6>[    0.000003] sched_clock: 64 bits at 1000kHz, resolution 1000ns, wraps every 2199023255500ns"}
- {"dt": "2024-07-07T08:38:12.605184", "lvl": "target", "msg": "<6>[    0.008823] Console: colour dummy device 80x25"}
- {"dt": "2024-07-07T08:38:12.606448", "lvl": "target", "msg": "<6>[    0.013316] printk: console [tty0] enabled"}
- {"dt": "2024-07-07T08:38:12.607892", "lvl": "target", "msg": "<6>[    0.017630] printk: bootconsole [sifive0] disabled"}
- {"dt": "2024-07-07T08:38:13.195431", "lvl": "target", "msg": "<5>[    0.000000] Linux version 6.1.54 (KernelCI@build-j50728-riscv-gcc-10-defconfig-75n2g) (riscv64-linux-gnu-gcc (Debian 10.2.1-6) 10.2.1 20210110, GNU ld (GNU Binutils for Debian) 2.35.2) #1 SMP Tue Sep 19 13:51:25 UTC 2023"}
- {"dt": "2024-07-07T08:38:13.198099", "lvl": "target", "msg": "<4>[    0.000000] OF: fdt: Ignoring memory range 0x80000000 - 0x80200000"}
- {"dt": "2024-07-07T08:38:13.210587", "lvl": "target", "msg": "<6>[    0.000000] Machine model: SiFive HiFive Unmatched A00"}
- {"dt": "2024-07-07T08:38:13.212947", "lvl": "target", "msg": "<6>[    0.000000] earlycon: sifive0 at MMIO 0x0000000010010000 (options '')"}
- {"dt": "2024-07-07T08:38:13.214262", "lvl": "target", "msg": "<6>[    0.000000] printk: bootconsole [sifive0] enabled"}
- {"dt": "2024-07-07T08:38:13.226543", "lvl": "target", "msg": "<6>[    0.000000] efi: UEFI not found."}
- {"dt": "2024-07-07T08:38:13.227485", "lvl": "target", "msg": "<6>[    0.000000] Zone ranges:"}
- {"dt": "2024-07-07T08:38:13.229348", "lvl": "target", "msg": "<6>[    0.000000]   DMA32    [mem 0x0000000080200000-0x00000000ffffffff]"}
- {"dt": "2024-07-07T08:38:13.242506", "lvl": "target", "msg": "<6>[    0.000000]   Normal   [mem 0x0000000100000000-0x000000047fffffff]"}
- {"dt": "2024-07-07T08:38:13.243583", "lvl": "target", "msg": "<6>[    0.000000] Movable zone start for each node"}
- {"dt": "2024-07-07T08:38:13.245857", "lvl": "target", "msg": "<6>[    0.000000] Early memory node ranges"}
- {"dt": "2024-07-07T08:38:13.247095", "lvl": "target", "msg": "<6>[    0.000000]   node   0: [mem 0x0000000080200000-0x000000047fffffff]"}
- {"dt": "2024-07-07T08:38:13.259338", "lvl": "target", "msg": "<6>[    0.000000] Initmem setup node 0 [mem 0x0000000080200000-0x000000047fffffff]"}
- {"dt": "2024-07-07T08:38:13.262190", "lvl": "target", "msg": "<6>[    0.000000] SBI specification v1.0 detected"}
- {"dt": "2024-07-07T08:38:13.274624", "lvl": "target", "msg": "<6>[    0.000000] SBI implementation ID=0x1 Version=0x10002"}
- {"dt": "2024-07-07T08:38:13.275605", "lvl": "target", "msg": "<6>[    0.000000] SBI TIME extension detected"}
- {"dt": "2024-07-07T08:38:13.277694", "lvl": "target", "msg": "<6>[    0.000000] SBI IPI extension detected"}
- {"dt": "2024-07-07T08:38:13.278846", "lvl": "target", "msg": "<6>[    0.000000] SBI RFENCE extension detected"}
- {"dt": "2024-07-07T08:38:13.290634", "lvl": "target", "msg": "<6>[    0.000000] SBI SRST extension detected"}
- {"dt": "2024-07-07T08:38:13.291450", "lvl": "target", "msg": "<6>[    0.000000] SBI HSM extension detected"}
- {"dt": "2024-07-07T08:38:13.293171", "lvl": "target", "msg": "<6>[    0.000000] CPU with hartid=0 is not available"}
- {"dt": "2024-07-07T08:38:13.294212", "lvl": "target", "msg": "<6>[    0.000000] CPU with hartid=0 is not available"}
- {"dt": "2024-07-07T08:38:13.306638", "lvl": "target", "msg": "<6>[    0.000000] CPU with hartid=0 is not available"}
- {"dt": "2024-07-07T08:38:13.308805", "lvl": "target", "msg": "<6>[    0.000000] riscv: base ISA extensions acdfim"}
- {"dt": "2024-07-07T08:38:13.310989", "lvl": "target", "msg": "<6>[    0.000000] riscv: ELF capabilities acdfim"}
- {"dt": "2024-07-07T08:38:13.322628", "lvl": "target", "msg": "<6>[    0.000000] percpu: Embedded 18 pages/cpu s34744 r8192 d30792 u73728"}
- {"dt": "2024-07-07T08:38:13.324502", "lvl": "target", "msg": "<6>[    0.000000] Built 1 zonelists, mobility grouping on.  Total pages: 4128264"}
- {"dt": "2024-07-07T08:38:13.338613", "lvl": "target", "msg": "<5>[    0.000000] Kernel command line: 115200 root=/dev/ram0 console_msg_format=syslog earlycon deferred_probe_timeout=60 ip=dhcp"}
- {"dt": "2024-07-07T08:38:13.342307", "lvl": "target", "msg": "<5>[    0.000000] Unknown kernel command line parameters \\\"115200\\\", will be passed to user space."}
- {"dt": "2024-07-07T08:38:13.355688", "lvl": "target", "msg": "<6>[    0.000000] Dentry cache hash table entries: 2097152 (order: 12, 16777216 bytes, linear)"}
- {"dt": "2024-07-07T08:38:13.358251", "lvl": "target", "msg": "<6>[    0.000000] Inode-cache hash table entries: 1048576 (order: 11, 8388608 bytes, linear)"}
- {"dt": "2024-07-07T08:38:13.370666", "lvl": "target", "msg": "<6>[    0.000000] mem auto-init: stack:off, heap alloc:off, heap free:off"}
- {"dt": "2024-07-07T08:38:13.373016", "lvl": "target", "msg": "<6>[    0.000000] software IO TLB: area num 4."}
- {"dt": "2024-07-07T08:38:13.386629", "lvl": "target", "msg": "<6>[    0.000000] software IO TLB: mapped [mem 0x00000000fbfff000-0x00000000fffff000] (64MB)"}
- {"dt": "2024-07-07T08:38:13.388840", "lvl": "target", "msg": "<5>[    0.000000] Virtual kernel memory layout:"}
- {"dt": "2024-07-07T08:38:13.391289", "lvl": "target", "msg": "<5>[    0.000000]       fixmap : 0xffffffc6fea00000 - 0xffffffc6ff000000   (6144 kB)"}
- {"dt": "2024-07-07T08:38:13.402650", "lvl": "target", "msg": "<5>[    0.000000]       pci io : 0xffffffc6ff000000 - 0xffffffc700000000   (  16 MB)"}
- {"dt": "2024-07-07T08:38:13.406223", "lvl": "target", "msg": "<5>[    0.000000]      vmemmap : 0xffffffc700000000 - 0xffffffc800000000   (4096 MB)"}
- {"dt": "2024-07-07T08:38:13.418740", "lvl": "target", "msg": "<5>[    0.000000]      vmalloc : 0xffffffc800000000 - 0xffffffd800000000   (  64 GB)"}
- {"dt": "2024-07-07T08:38:13.421125", "lvl": "target", "msg": "<5>[    0.000000]      modules : 0xffffffff01361000 - 0xffffffff80000000   (2028 MB)"}
- {"dt": "2024-07-07T08:38:13.434649", "lvl": "target", "msg": "<5>[    0.000000]       lowmem : 0xffffffd800000000 - 0xffffffdbffe00000   (  15 GB)"}
- {"dt": "2024-07-07T08:38:13.437247", "lvl": "target", "msg": "<5>[    0.000000]       kernel : 0xffffffff80000000 - 0xffffffffffffffff   (2047 MB)"}
- {"dt": "2024-07-07T08:38:13.451867", "lvl": "target", "msg": "<6>[    0.000000] Memory: 16387892K/16775168K available (7456K kernel code, 4927K rwdata, 4096K rodata, 2164K init, 461K bss, 387276K reserved, 0K cma-reserved)"}
- {"dt": "2024-07-07T08:38:13.454317", "lvl": "target", "msg": "<6>[    0.000000] SLUB: HWalign=64, Order=0-3, MinObjects=0, CPUs=4, Nodes=1"}
- {"dt": "2024-07-07T08:38:13.466618", "lvl": "target", "msg": "<6>[    0.000000] rcu: Hierarchical RCU implementation."}
- {"dt": "2024-07-07T08:38:13.468808", "lvl": "target", "msg": "<6>[    0.000000] rcu: \tRCU restricting CPUs from NR_CPUS=64 to nr_cpu_ids=4."}
- {"dt": "2024-07-07T08:38:13.470989", "lvl": "target", "msg": "<6>[    0.000000] rcu: \tRCU debug extended QS entry/exit."}
- {"dt": "2024-07-07T08:38:13.482581", "lvl": "target", "msg": "<6>[    0.000000] \tTracing variant of Tasks RCU enabled."}
- {"dt": "2024-07-07T08:38:13.486181", "lvl": "target", "msg": "<6>[    0.000000] rcu: RCU calculated value of scheduler-enlistment delay is 25 jiffies."}
- {"dt": "2024-07-07T08:38:13.498613", "lvl": "target", "msg": "<6>[    0.000000] rcu: Adjusting geometry for rcu_fanout_leaf=16, nr_cpu_ids=4"}
- {"dt": "2024-07-07T08:38:13.501129", "lvl": "target", "msg": "<6>[    0.000000] NR_IRQS: 64, nr_irqs: 64, preallocated irqs: 0"}
- {"dt": "2024-07-07T08:38:13.502280", "lvl": "target", "msg": "<6>[    0.000000] CPU with hartid=0 is not available"}
- {"dt": "2024-07-07T08:38:13.515876", "lvl": "target", "msg": "<4>[    0.000000] riscv-intc: unable to find hart id for /cpus/cpu@0/interrupt-controller"}
- {"dt": "2024-07-07T08:38:13.516864", "lvl": "target", "msg": "<6>[    0.000000] riscv-intc: 64 local interrupts mapped"}
- {"dt": "2024-07-07T08:38:13.530622", "lvl": "target", "msg": "<6>[    0.000000] plic: interrupt-controller@c000000: mapped 69 interrupts with 4 handlers for 9 contexts."}
- {"dt": "2024-07-07T08:38:13.534493", "lvl": "target", "msg": "<6>[    0.000000] rcu: srcu_init: Setting srcu_struct sizes based on contention."}
- {"dt": "2024-07-07T08:38:13.546617", "lvl": "target", "msg": "<6>[    0.000000] riscv-timer: riscv_timer_init_dt: Registering clocksource cpuid [0] hartid [2]"}
- {"dt": "2024-07-07T08:38:13.550178", "lvl": "target", "msg": "<6>[    0.000000] clocksource: riscv_clocksource: mask: 0xffffffffffffffff max_cycles: 0x1d854df40, max_idle_ns: 3526361616960 ns"}
- {"dt": "2024-07-07T08:38:13.563777", "lvl": "target", "msg": "<6>[    0.000003] sched_clock: 64 bits at 1000kHz, resolution 1000ns, wraps every 2199023255500ns"}
- {"dt": "2024-07-07T08:38:13.566406", "lvl": "target", "msg": "<6>[    0.008823] Console: colour dummy device 80x25"}
- {"dt": "2024-07-07T08:38:13.578611", "lvl": "target", "msg": "<6>[    0.013316] printk: console [tty0] enabled"}
- {"dt": "2024-07-07T08:38:13.580899", "lvl": "target", "msg": "<6>[    0.017630] printk: bootconsole [sifive0] disabled"}
- {"dt": "2024-07-07T08:38:13.594611", "lvl": "target", "msg": "<6>[    0.022726] Calibrating delay loop (skipped), value calculated using timer frequency.. 2.00 BogoMIPS (lpj=4000)"}
- {"dt": "2024-07-07T08:38:13.595590", "lvl": "target", "msg": "<6>[    0.022751] pid_max: default: 32768 minimum: 301"}
- {"dt": "2024-07-07T08:38:13.597900", "lvl": "target", "msg": "<6>[    0.022869] LSM: Security Framework initializing"}
- {"dt": "2024-07-07T08:38:13.610652", "lvl": "target", "msg": "<6>[    0.023631] Mount-cache hash table entries: 32768 (order: 6, 262144 bytes, linear)"}
- {"dt": "2024-07-07T08:38:13.613102", "lvl": "target", "msg": "<6>[    0.024322] Mountpoint-cache hash table entries: 32768 (order: 6, 262144 bytes, linear)"}
- {"dt": "2024-07-07T08:38:13.626456", "lvl": "target", "msg": "<6>[    0.026128] CPU node for /cpus/cpu@0 exist but the possible cpu range is :0-3"}
- {"dt": "2024-07-07T08:38:13.627833", "lvl": "target", "msg": "<6>[    0.027530] cblist_init_generic: Setting adjustable number of callback queues."}
- {"dt": "2024-07-07T08:38:13.630024", "lvl": "target", "msg": "<6>[    0.027547] cblist_init_generic: Setting shift to 2 and lim to 1."}
- {"dt": "2024-07-07T08:38:13.642626", "lvl": "target", "msg": "<6>[    0.027708] riscv: ELF compat mode unsupported"}
- {"dt": "2024-07-07T08:38:13.644012", "lvl": "target", "msg": "<6>[    0.027716] ASID allocator disabled (0 bits)"}
- {"dt": "2024-07-07T08:38:13.646173", "lvl": "target", "msg": "<6>[    0.027901] rcu: Hierarchical SRCU implementation."}
- {"dt": "2024-07-07T08:38:13.658190", "lvl": "target", "msg": "<6>[    0.027915] rcu: \tMax phase no-delay instances is 1000."}
- {"dt": "2024-07-07T08:38:13.660191", "lvl": "target", "msg": "<6>[    0.028283] EFI services will not be available."}
- {"dt": "2024-07-07T08:38:13.662210", "lvl": "target", "msg": "<6>[    0.028984] smp: Bringing up secondary CPUs ..."}
- {"dt": "2024-07-07T08:38:13.674835", "lvl": "target", "msg": "<6>[    0.032055] smp: Brought up 1 node, 4 CPUs"}
- {"dt": "2024-07-07T08:38:13.675558", "lvl": "target", "msg": "<6>[    0.036193] devtmpfs: initialized"}
- {"dt": "2024-07-07T08:38:13.678380", "lvl": "target", "msg": "<6>[    0.039030] clocksource: jiffies: mask: 0xffffffff max_cycles: 0xffffffff, max_idle_ns: 7645041785100000 ns"}
- {"dt": "2024-07-07T08:38:13.690756", "lvl": "target", "msg": "<6>[    0.039074] futex hash table entries: 1024 (order: 4, 65536 bytes, linear)"}
- {"dt": "2024-07-07T08:38:13.693498", "lvl": "target", "msg": "<6>[    0.039473] pinctrl core: initialized pinctrl subsystem"}
- {"dt": "2024-07-07T08:38:13.706671", "lvl": "target", "msg": "<6>[    0.040487] NET: Registered PF_NETLINK/PF_ROUTE protocol family"}
- {"dt": "2024-07-07T08:38:13.709033", "lvl": "target", "msg": "<6>[    0.040688] audit: initializing netlink subsys (disabled)"}
- {"dt": "2024-07-07T08:38:13.711348", "lvl": "target", "msg": "<5>[    0.040951] audit: type=2000 audit(0.028:1): state=initialized audit_enabled=0 res=1"}
- {"dt": "2024-07-07T08:38:13.722616", "lvl": "target", "msg": "<6>[    0.041288] cpuidle: using governor menu"}
- {"dt": "2024-07-07T08:38:13.724656", "lvl": "target", "msg": "<6>[    0.052290] HugeTLB: registered 2.00 MiB page size, pre-allocated 0 pages"}
- {"dt": "2024-07-07T08:38:13.738697", "lvl": "target", "msg": "<6>[    0.052319] HugeTLB: 0 KiB vmemmap can be freed for a 2.00 MiB page"}
- {"dt": "2024-07-07T08:38:13.739756", "lvl": "target", "msg": "<6>[    0.053046] iommu: Default domain type: Translated "}
- {"dt": "2024-07-07T08:38:13.742213", "lvl": "target", "msg": "<6>[    0.053066] iommu: DMA domain TLB invalidation policy: strict mode "}
- {"dt": "2024-07-07T08:38:13.743230", "lvl": "target", "msg": "<5>[    0.053420] SCSI subsystem initialized"}
- {"dt": "2024-07-07T08:38:13.755692", "lvl": "target", "msg": "<6>[    0.053842] usbcore: registered new interface driver usbfs"}
- {"dt": "2024-07-07T08:38:13.758195", "lvl": "target", "msg": "<6>[    0.053894] usbcore: registered new interface driver hub"}
- {"dt": "2024-07-07T08:38:13.770617", "lvl": "target", "msg": "<6>[    0.053947] usbcore: registered new device driver usb"}
- {"dt": "2024-07-07T08:38:13.771579", "lvl": "target", "msg": "<6>[    0.055000] vgaarb: loaded"}
- {"dt": "2024-07-07T08:38:13.773801", "lvl": "target", "msg": "<6>[    0.055161] clocksource: Switched to clocksource riscv_clocksource"}
- {"dt": "2024-07-07T08:38:13.774850", "lvl": "target", "msg": "<6>[    0.064478] NET: Registered PF_INET protocol family"}
- {"dt": "2024-07-07T08:38:13.787784", "lvl": "target", "msg": "<6>[    0.071673] IP idents hash table entries: 262144 (order: 9, 2097152 bytes, linear)"}
- {"dt": "2024-07-07T08:38:13.790222", "lvl": "target", "msg": "<6>[    0.092798] tcp_listen_portaddr_hash hash table entries: 8192 (order: 6, 262144 bytes, linear)"}
- {"dt": "2024-07-07T08:38:13.803968", "lvl": "target", "msg": "<6>[    0.093838] Table-perturb hash table entries: 65536 (order: 6, 262144 bytes, linear)"}
- {"dt": "2024-07-07T08:38:13.818625", "lvl": "target", "msg": "<6>[    0.093927] TCP established hash table entries: 131072 (order: 8, 1048576 bytes, linear)"}
- {"dt": "2024-07-07T08:38:13.821408", "lvl": "target", "msg": "<6>[    0.098588] TCP bind hash table entries: 65536 (order: 10, 4194304 bytes, linear)"}
- {"dt": "2024-07-07T08:38:13.822690", "lvl": "target", "msg": "<6>[    0.116274] TCP: Hash tables configured (established 131072 bind 65536)"}
- {"dt": "2024-07-07T08:38:13.834788", "lvl": "target", "msg": "<6>[    0.117060] UDP hash table entries: 8192 (order: 7, 786432 bytes, linear)"}
- {"dt": "2024-07-07T08:38:13.838033", "lvl": "target", "msg": "<6>[    0.120309] UDP-Lite hash table entries: 8192 (order: 7, 786432 bytes, linear)"}
- {"dt": "2024-07-07T08:38:13.851123", "lvl": "target", "msg": "<6>[    0.123841] NET: Registered PF_UNIX/PF_LOCAL protocol family"}
- {"dt": "2024-07-07T08:38:13.852947", "lvl": "target", "msg": "<6>[    0.125018] RPC: Registered named UNIX socket transport module."}
- {"dt": "2024-07-07T08:38:13.855596", "lvl": "target", "msg": "<6>[    0.125043] RPC: Registered udp transport module."}
- {"dt": "2024-07-07T08:38:13.866627", "lvl": "target", "msg": "<6>[    0.125056] RPC: Registered tcp transport module."}
- {"dt": "2024-07-07T08:38:13.868501", "lvl": "target", "msg": "<6>[    0.125068] RPC: Registered tcp NFSv4.1 backchannel transport module."}
- {"dt": "2024-07-07T08:38:13.871462", "lvl": "target", "msg": "<6>[    0.125090] PCI: CLS 0 bytes, default 64"}
- {"dt": "2024-07-07T08:38:13.882753", "lvl": "target", "msg": "<6>[    0.125698] Unpacking initramfs..."}
- {"dt": "2024-07-07T08:38:13.885186", "lvl": "target", "msg": "<6>[    0.144531] workingset: timestamp_bits=46 max_order=22 bucket_order=0"}
- {"dt": "2024-07-07T08:38:13.887021", "lvl": "target", "msg": "<5>[    0.153840] NFS: Registering the id_resolver key type"}
- {"dt": "2024-07-07T08:38:13.898707", "lvl": "target", "msg": "<5>[    0.153927] Key type id_resolver registered"}
- {"dt": "2024-07-07T08:38:13.900822", "lvl": "target", "msg": "<5>[    0.153943] Key type id_legacy registered"}
- {"dt": "2024-07-07T08:38:13.903081", "lvl": "target", "msg": "<6>[    0.154037] nfs4filelayout_init: NFSv4 File Layout Driver Registering..."}
- {"dt": "2024-07-07T08:38:13.914658", "lvl": "target", "msg": "<6>[    0.154056] nfs4flexfilelayout_init: NFSv4 Flexfile Layout Driver Registering..."}
- {"dt": "2024-07-07T08:38:13.916914", "lvl": "target", "msg": "<6>[    0.154333] 9p: Installing v9fs 9p2000 file system support"}
- {"dt": "2024-07-07T08:38:13.919055", "lvl": "target", "msg": "<6>[    0.154833] NET: Registered PF_ALG protocol family"}
- {"dt": "2024-07-07T08:38:13.931614", "lvl": "target", "msg": "<6>[    0.154918] Block layer SCSI generic (bsg) driver version 0.4 loaded (major 250)"}
- {"dt": "2024-07-07T08:38:13.933892", "lvl": "target", "msg": "<6>[    0.154945] io scheduler mq-deadline registered"}
- {"dt": "2024-07-07T08:38:13.946078", "lvl": "target", "msg": "<6>[    0.154961] io scheduler kyber registered"}
- {"dt": "2024-07-07T08:38:13.948272", "lvl": "target", "msg": "<6>[    0.178960] fu740-pcie e00000000.pcie: host bridge /soc/pcie@e00000000 ranges:"}
- {"dt": "2024-07-07T08:38:13.962032", "lvl": "target", "msg": "<6>[    0.179092] fu740-pcie e00000000.pcie:       IO 0x0060080000..0x006008ffff -> 0x0060080000"}
- {"dt": "2024-07-07T08:38:13.963024", "lvl": "target", "msg": "<6>[    0.179211] fu740-pcie e00000000.pcie:      MEM 0x0060090000..0x007fffffff -> 0x0060090000"}
- {"dt": "2024-07-07T08:38:13.978538", "lvl": "target", "msg": "<6>[    0.179244] fu740-pcie e00000000.pcie:      MEM 0x2000000000..0x3fffffffff -> 0x2000000000"}
- {"dt": "2024-07-07T08:38:13.981867", "lvl": "target", "msg": "<6>[    0.288310] fu740-pcie e00000000.pcie: iATU unroll: enabled"}
- {"dt": "2024-07-07T08:38:13.983395", "lvl": "target", "msg": "<6>[    0.288372] fu740-pcie e00000000.pcie: iATU regions: 8 ob, 8 ib, align 4K, limit 4096G"}
- {"dt": "2024-07-07T08:38:13.994438", "lvl": "target", "msg": "<6>[    0.388481] fu740-pcie e00000000.pcie: PCIe Gen.1 x8 link up"}
- {"dt": "2024-07-07T08:38:13.998605", "lvl": "target", "msg": "<6>[    0.488598] fu740-pcie e00000000.pcie: PCIe Gen.3 x8 link up"}
- {"dt": "2024-07-07T08:38:14.010817", "lvl": "target", "msg": "<6>[    0.488664] fu740-pcie e00000000.pcie: PCIe Gen.3 x8 link up"}
- {"dt": "2024-07-07T08:38:14.013229", "lvl": "target", "msg": "<6>[    0.488903] fu740-pcie e00000000.pcie: PCI host bridge to bus 0000:00"}
- {"dt": "2024-07-07T08:38:14.014358", "lvl": "target", "msg": "<6>[    0.488934] pci_bus 0000:00: root bus resource [bus 00-ff]"}
- {"dt": "2024-07-07T08:38:14.027530", "lvl": "target", "msg": "<6>[    0.488958] pci_bus 0000:00: root bus resource [io  0x0000-0xffff] (bus address [0x60080000-0x6008ffff])"}
- {"dt": "2024-07-07T08:38:14.030639", "lvl": "target", "msg": "<6>[    0.488980] pci_bus 0000:00: root bus resource [mem 0x60090000-0x7fffffff]"}
- {"dt": "2024-07-07T08:38:14.044160", "lvl": "target", "msg": "<6>[    0.488997] pci_bus 0000:00: root bus resource [mem 0x2000000000-0x3fffffffff pref]"}
- {"dt": "2024-07-07T08:38:14.047893", "lvl": "target", "msg": "<6>[    0.489054] pci 0000:00:00.0: [f15e:0000] type 01 class 0x060400"}
- {"dt": "2024-07-07T08:38:14.058688", "lvl": "target", "msg": "<6>[    0.489082] pci 0000:00:00.0: reg 0x10: [mem 0x00000000-0x000fffff]"}
- {"dt": "2024-07-07T08:38:14.061171", "lvl": "target", "msg": "<6>[    0.489105] pci 0000:00:00.0: reg 0x38: [mem 0x00000000-0x0000ffff pref]"}
- {"dt": "2024-07-07T08:38:14.062234", "lvl": "target", "msg": "<6>[    0.489185] pci 0000:00:00.0: supports D1"}
- {"dt": "2024-07-07T08:38:14.074192", "lvl": "target", "msg": "<6>[    0.489201] pci 0000:00:00.0: PME# supported from D0 D1 D3hot"}
- {"dt": "2024-07-07T08:38:14.076124", "lvl": "target", "msg": "<6>[    0.490059] pci 0000:01:00.0: [1b21:2824] type 01 class 0x060400"}
- {"dt": "2024-07-07T08:38:14.078399", "lvl": "target", "msg": "<6>[    0.490157] pci 0000:01:00.0: enabling Extended Tags"}
- {"dt": "2024-07-07T08:38:14.091998", "lvl": "target", "msg": "<6>[    0.490305] pci 0000:01:00.0: PME# supported from D0 D3hot D3cold"}
- {"dt": "2024-07-07T08:38:14.095288", "lvl": "target", "msg": "<6>[    0.499259] pci 0000:01:00.0: bridge configuration invalid ([bus 00-00]), reconfiguring"}
- {"dt": "2024-07-07T08:38:14.106564", "lvl": "target", "msg": "<6>[    0.499503] pci 0000:02:00.0: [1b21:2824] type 01 class 0x060400"}
- {"dt": "2024-07-07T08:38:14.107210", "lvl": "target", "msg": "<6>[    0.499600] pci 0000:02:00.0: enabling Extended Tags"}
- {"dt": "2024-07-07T08:38:14.122521", "lvl": "target", "msg": "<6>[    0.499758] pci 0000:02:00.0: PME# supported from D0 D3hot D3cold"}
- {"dt": "2024-07-07T08:38:14.125731", "lvl": "target", "msg": "<6>[    0.500135] pci 0000:02:02.0: [1b21:2824] type 01 class 0x060400"}
- {"dt": "2024-07-07T08:38:14.127148", "lvl": "target", "msg": "<6>[    0.500231] pci 0000:02:02.0: enabling Extended Tags"}
- {"dt": "2024-07-07T08:38:14.139293", "lvl": "target", "msg": "<6>[    0.500375] pci 0000:02:02.0: PME# supported from D0 D3hot D3cold"}
- {"dt": "2024-07-07T08:38:14.140748", "lvl": "target", "msg": "<6>[    0.500667] pci 0000:02:03.0: [1b21:2824] type 01 class 0x060400"}
- {"dt": "2024-07-07T08:38:14.142140", "lvl": "target", "msg": "<6>[    0.500761] pci 0000:02:03.0: enabling Extended Tags"}
- {"dt": "2024-07-07T08:38:14.154276", "lvl": "target", "msg": "<6>[    0.500904] pci 0000:02:03.0: PME# supported from D0 D3hot D3cold"}
- {"dt": "2024-07-07T08:38:14.155757", "lvl": "target", "msg": "<6>[    0.501214] pci 0000:02:04.0: [1b21:2824] type 01 class 0x060400"}
- {"dt": "2024-07-07T08:38:14.157658", "lvl": "target", "msg": "<6>[    0.501312] pci 0000:02:04.0: enabling Extended Tags"}
- {"dt": "2024-07-07T08:38:14.170409", "lvl": "target", "msg": "<6>[    0.501459] pci 0000:02:04.0: PME# supported from D0 D3hot D3cold"}
- {"dt": "2024-07-07T08:38:14.173909", "lvl": "target", "msg": "<6>[    0.501824] pci 0000:02:08.0: [1b21:2824] type 01 class 0x060400"}
- {"dt": "2024-07-07T08:38:14.186472", "lvl": "target", "msg": "<6>[    0.501919] pci 0000:02:08.0: enabling Extended Tags"}
- {"dt": "2024-07-07T08:38:14.188717", "lvl": "target", "msg": "<6>[    0.502065] pci 0000:02:08.0: PME# supported from D0 D3hot D3cold"}
- {"dt": "2024-07-07T08:38:14.190489", "lvl": "target", "msg": "<6>[    0.502740] pci 0000:02:00.0: bridge configuration invalid ([bus 00-00]), reconfiguring"}
- {"dt": "2024-07-07T08:38:14.203780", "lvl": "target", "msg": "<6>[    0.502776] pci 0000:02:02.0: bridge configuration invalid ([bus 00-00]), reconfiguring"}
- {"dt": "2024-07-07T08:38:14.218648", "lvl": "target", "msg": "<6>[    0.502805] pci 0000:02:03.0: bridge configuration invalid ([bus 00-00]), reconfiguring"}
- {"dt": "2024-07-07T08:38:14.223131", "lvl": "target", "msg": "<6>[    0.502834] pci 0000:02:04.0: bridge configuration invalid ([bus 00-00]), reconfiguring"}
- {"dt": "2024-07-07T08:38:14.234496", "lvl": "target", "msg": "<6>[    0.502861] pci 0000:02:08.0: bridge configuration invalid ([bus 00-00]), reconfiguring"}
- {"dt": "2024-07-07T08:38:14.236617", "lvl": "target", "msg": "<6>[    0.503049] pci_bus 0000:03: busn_res: [bus 03-ff] end is updated to 03"}
- {"dt": "2024-07-07T08:38:14.238197", "lvl": "target", "msg": "<6>[    0.503266] pci 0000:04:00.0: [1b21:1142] type 00 class 0x0c0330"}
- {"dt": "2024-07-07T08:38:14.250612", "lvl": "target", "msg": "<6>[    0.503329] pci 0000:04:00.0: reg 0x10: [mem 0x00000000-0x00007fff 64bit]"}
- {"dt": "2024-07-07T08:38:14.253759", "lvl": "target", "msg": "<6>[    0.503557] pci 0000:04:00.0: PME# supported from D3cold"}
- {"dt": "2024-07-07T08:38:14.266562", "lvl": "target", "msg": "<6>[    0.515246] pci_bus 0000:04: busn_res: [bus 04-ff] end is updated to 04"}
- {"dt": "2024-07-07T08:38:14.268709", "lvl": "target", "msg": "<6>[    0.515523] pci_bus 0000:05: busn_res: [bus 05-ff] end is updated to 05"}
- {"dt": "2024-07-07T08:38:14.270683", "lvl": "target", "msg": "<6>[    0.515697] pci_bus 0000:06: busn_res: [bus 06-ff] end is updated to 06"}
- {"dt": "2024-07-07T08:38:14.282400", "lvl": "target", "msg": "<6>[    0.515920] pci 0000:07:00.0: [1002:6779] type 00 class 0x030000"}
- {"dt": "2024-07-07T08:38:14.286206", "lvl": "target", "msg": "<6>[    0.515982] pci 0000:07:00.0: reg 0x10: [mem 0x00000000-0x0fffffff 64bit pref]"}
- {"dt": "2024-07-07T08:38:14.298621", "lvl": "target", "msg": "<6>[    0.516026] pci 0000:07:00.0: reg 0x18: [mem 0x00000000-0x0001ffff 64bit]"}
- {"dt": "2024-07-07T08:38:14.302195", "lvl": "target", "msg": "<6>[    0.516056] pci 0000:07:00.0: reg 0x20: initial BAR value 0x00000000 invalid"}
- {"dt": "2024-07-07T08:38:14.314488", "lvl": "target", "msg": "<6>[    0.516074] pci 0000:07:00.0: reg 0x20: [io  size 0x0100]"}
- {"dt": "2024-07-07T08:38:14.316583", "lvl": "target", "msg": "<6>[    0.516115] pci 0000:07:00.0: reg 0x30: [mem 0x00000000-0x0001ffff pref]"}
- {"dt": "2024-07-07T08:38:14.318286", "lvl": "target", "msg": "<6>[    0.516148] pci 0000:07:00.0: enabling Extended Tags"}
- {"dt": "2024-07-07T08:38:14.330809", "lvl": "target", "msg": "<6>[    0.516295] pci 0000:07:00.0: supports D1 D2"}
- {"dt": "2024-07-07T08:38:14.346888", "lvl": "target", "msg": "<6>[    0.516359] pci 0000:07:00.0: 16.000 Gb/s available PCIe bandwidth, limited by 2.5 GT/s PCIe x8 link at 0000:02:08.0 (capable of 32.000 Gb/s with 2.5 GT/s PCIe x16 link)"}
- {"dt": "2024-07-07T08:38:14.348677", "lvl": "target", "msg": "<6>[    0.516565] pci 0000:07:00.0: vgaarb: setting as boot VGA device"}
- {"dt": "2024-07-07T08:38:14.350931", "lvl": "target", "msg": "<6>[    0.516584] pci 0000:07:00.0: vgaarb: bridge control possible"}
- {"dt": "2024-07-07T08:38:14.362540", "lvl": "target", "msg": "<6>[    0.516600] pci 0000:07:00.0: vgaarb: VGA device added: decodes=io+mem,owns=none,locks=none"}
- {"dt": "2024-07-07T08:38:14.365926", "lvl": "target", "msg": "<6>[    0.516695] pci 0000:07:00.1: [1002:aa98] type 00 class 0x040300"}
- {"dt": "2024-07-07T08:38:14.378421", "lvl": "target", "msg": "<6>[    0.516752] pci 0000:07:00.1: reg 0x10: [mem 0x00000000-0x00003fff 64bit]"}
- {"dt": "2024-07-07T08:38:14.379482", "lvl": "target", "msg": "<6>[    0.516847] pci 0000:07:00.1: enabling Extended Tags"}
- {"dt": "2024-07-07T08:38:14.381984", "lvl": "target", "msg": "<6>[    0.516979] pci 0000:07:00.1: supports D1 D2"}
- {"dt": "2024-07-07T08:38:14.394496", "lvl": "target", "msg": "<6>[    0.527264] pci_bus 0000:07: busn_res: [bus 07-ff] end is updated to 07"}
- {"dt": "2024-07-07T08:38:14.395521", "lvl": "target", "msg": "<6>[    0.527318] pci_bus 0000:02: busn_res: [bus 02-ff] end is updated to 07"}
- {"dt": "2024-07-07T08:38:14.410433", "lvl": "target", "msg": "<6>[    0.527343] pci_bus 0000:01: busn_res: [bus 01-ff] end is updated to 07"}
- {"dt": "2024-07-07T08:38:14.411489", "lvl": "target", "msg": "<6>[    0.527416] pci 0000:00:00.0: BAR 9: assigned [mem 0x2000000000-0x200fffffff 64bit pref]"}
- {"dt": "2024-07-07T08:38:14.426542", "lvl": "target", "msg": "<6>[    0.527440] pci 0000:00:00.0: BAR 0: assigned [mem 0x60100000-0x601fffff]"}
- {"dt": "2024-07-07T08:38:14.429176", "lvl": "target", "msg": "<6>[    0.527460] pci 0000:00:00.0: BAR 8: assigned [mem 0x60200000-0x603fffff]"}
- {"dt": "2024-07-07T08:38:14.430340", "lvl": "target", "msg": "<6>[    0.527478] pci 0000:00:00.0: BAR 6: assigned [mem 0x60090000-0x6009ffff pref]"}
- {"dt": "2024-07-07T08:38:14.442463", "lvl": "target", "msg": "<6>[    0.527499] pci 0000:00:00.0: BAR 7: assigned [io  0x1000-0x1fff]"}
- {"dt": "2024-07-07T08:38:14.446040", "lvl": "target", "msg": "<6>[    0.527522] pci 0000:01:00.0: BAR 9: assigned [mem 0x2000000000-0x200fffffff 64bit pref]"}
- {"dt": "2024-07-07T08:38:14.458526", "lvl": "target", "msg": "<6>[    0.527543] pci 0000:01:00.0: BAR 8: assigned [mem 0x60200000-0x603fffff]"}
- {"dt": "2024-07-07T08:38:14.461150", "lvl": "target", "msg": "<6>[    0.527561] pci 0000:01:00.0: BAR 7: assigned [io  0x1000-0x1fff]"}
- {"dt": "2024-07-07T08:38:14.474501", "lvl": "target", "msg": "<6>[    0.527583] pci 0000:02:08.0: BAR 9: assigned [mem 0x2000000000-0x200fffffff 64bit pref]"}
- {"dt": "2024-07-07T08:38:14.476869", "lvl": "target", "msg": "<6>[    0.527605] pci 0000:02:02.0: BAR 8: assigned [mem 0x60200000-0x602fffff]"}
- {"dt": "2024-07-07T08:38:14.490434", "lvl": "target", "msg": "<6>[    0.527622] pci 0000:02:08.0: BAR 8: assigned [mem 0x60300000-0x603fffff]"}
- {"dt": "2024-07-07T08:38:14.491674", "lvl": "target", "msg": "<6>[    0.527639] pci 0000:02:08.0: BAR 7: assigned [io  0x1000-0x1fff]"}
- {"dt": "2024-07-07T08:38:14.494431", "lvl": "target", "msg": "<6>[    0.527658] pci 0000:02:00.0: PCI bridge to [bus 03]"}
- {"dt": "2024-07-07T08:38:14.506571", "lvl": "target", "msg": "<6>[    0.527694] pci 0000:04:00.0: BAR 0: assigned [mem 0x60200000-0x60207fff 64bit]"}
- {"dt": "2024-07-07T08:38:14.508959", "lvl": "target", "msg": "<6>[    0.527735] pci 0000:02:02.0: PCI bridge to [bus 04]"}
- {"dt": "2024-07-07T08:38:14.522315", "lvl": "target", "msg": "<6>[    0.527755] pci 0000:02:02.0:   bridge window [mem 0x60200000-0x602fffff]"}
- {"dt": "2024-07-07T08:38:14.524508", "lvl": "target", "msg": "<6>[    0.527783] pci 0000:02:03.0: PCI bridge to [bus 05]"}
- {"dt": "2024-07-07T08:38:14.527141", "lvl": "target", "msg": "<6>[    0.527814] pci 0000:02:04.0: PCI bridge to [bus 06]"}
- {"dt": "2024-07-07T08:38:14.538465", "lvl": "target", "msg": "<6>[    0.527849] pci 0000:07:00.0: BAR 0: assigned [mem 0x2000000000-0x200fffffff 64bit pref]"}
- {"dt": "2024-07-07T08:38:14.540650", "lvl": "target", "msg": "<6>[    0.527888] pci 0000:07:00.0: BAR 2: assigned [mem 0x60300000-0x6031ffff 64bit]"}
- {"dt": "2024-07-07T08:38:14.554290", "lvl": "target", "msg": "<6>[    0.527927] pci 0000:07:00.0: BAR 6: assigned [mem 0x60320000-0x6033ffff pref]"}
- {"dt": "2024-07-07T08:38:14.556526", "lvl": "target", "msg": "<6>[    0.527948] pci 0000:07:00.1: BAR 0: assigned [mem 0x60340000-0x60343fff 64bit]"}
- {"dt": "2024-07-07T08:38:14.570409", "lvl": "target", "msg": "<6>[    0.527985] pci 0000:07:00.0: BAR 4: assigned [io  0x1000-0x10ff]"}
- {"dt": "2024-07-07T08:38:14.572693", "lvl": "target", "msg": "<6>[    0.528009] pci 0000:02:08.0: PCI bridge to [bus 07]"}
- {"dt": "2024-07-07T08:38:14.574953", "lvl": "target", "msg": "<6>[    0.528025] pci 0000:02:08.0:   bridge window [io  0x1000-0x1fff]"}
- {"dt": "2024-07-07T08:38:14.586387", "lvl": "target", "msg": "<6>[    0.528046] pci 0000:02:08.0:   bridge window [mem 0x60300000-0x603fffff]"}
- {"dt": "2024-07-07T08:38:14.590750", "lvl": "target", "msg": "<6>[    0.528065] pci 0000:02:08.0:   bridge window [mem 0x2000000000-0x200fffffff 64bit pref]"}
- {"dt": "2024-07-07T08:38:14.602427", "lvl": "target", "msg": "<6>[    0.528091] pci 0000:01:00.0: PCI bridge to [bus 02-07]"}
- {"dt": "2024-07-07T08:38:14.603919", "lvl": "target", "msg": "<6>[    0.528108] pci 0000:01:00.0:   bridge window [io  0x1000-0x1fff]"}
- {"dt": "2024-07-07T08:38:14.605764", "lvl": "target", "msg": "<6>[    0.528128] pci 0000:01:00.0:   bridge window [mem 0x60200000-0x603fffff]"}
- {"dt": "2024-07-07T08:38:14.619846", "lvl": "target", "msg": "<6>[    0.528148] pci 0000:01:00.0:   bridge window [mem 0x2000000000-0x200fffffff 64bit pref]"}
- {"dt": "2024-07-07T08:38:14.622992", "lvl": "target", "msg": "<6>[    0.528174] pci 0000:00:00.0: PCI bridge to [bus 01-07]"}
- {"dt": "2024-07-07T08:38:14.634453", "lvl": "target", "msg": "<6>[    0.528190] pci 0000:00:00.0:   bridge window [io  0x1000-0x1fff]"}
- {"dt": "2024-07-07T08:38:14.635360", "lvl": "target", "msg": "<6>[    0.528206] pci 0000:00:00.0:   bridge window [mem 0x60200000-0x603fffff]"}
- {"dt": "2024-07-07T08:38:14.650564", "lvl": "target", "msg": "<6>[    0.528222] pci 0000:00:00.0:   bridge window [mem 0x2000000000-0x200fffffff 64bit pref]"}
- {"dt": "2024-07-07T08:38:14.653341", "lvl": "target", "msg": "<6>[    0.528687] pcieport 0000:00:00.0: PME: Signaling with IRQ 21"}
- {"dt": "2024-07-07T08:38:14.654485", "lvl": "target", "msg": "<6>[    0.528845] pcieport 0000:01:00.0: enabling device (0000 -> 0003)"}
- {"dt": "2024-07-07T08:38:14.666443", "lvl": "target", "msg": "<6>[    0.529416] pcieport 0000:02:02.0: enabling device (0000 -> 0002)"}
- {"dt": "2024-07-07T08:38:14.668782", "lvl": "target", "msg": "<6>[    0.530429] pcieport 0000:02:08.0: enabling device (0000 -> 0003)"}
- {"dt": "2024-07-07T08:38:14.682461", "lvl": "target", "msg": "<6>[    0.530808] pci 0000:04:00.0: enabling device (0000 -> 0002)"}
- {"dt": "2024-07-07T08:38:14.683687", "lvl": "target", "msg": "<6>[    0.530992] pci 0000:07:00.1: D0 power state depends on 0000:07:00.0"}
- {"dt": "2024-07-07T08:38:14.686544", "lvl": "target", "msg": "<6>[    0.585320] Serial: 8250/16550 driver, 4 ports, IRQ sharing disabled"}
- {"dt": "2024-07-07T08:38:14.700418", "lvl": "target", "msg": "<6>[    0.586892] 10010000.serial: ttySIF0 at MMIO 0x10010000 (irq = 29, base_baud = 8125000) is a SiFive UART v0"}
- {"dt": "2024-07-07T08:38:14.702646", "lvl": "target", "msg": "<6>[    0.977433] Freeing initrd memory: 13320K"}
- {"dt": "2024-07-07T08:38:14.714347", "lvl": "target", "msg": "<6>[    0.980029] printk: console [ttySIF0] enabled"}
- {"dt": "2024-07-07T08:38:14.717614", "lvl": "target", "msg": "<6>[    2.121292] 10011000.serial: ttySIF1 at MMIO 0x10011000 (irq = 30, base_baud = 8125000) is a SiFive UART v0"}
- {"dt": "2024-07-07T08:38:14.730337", "lvl": "target", "msg": "<6>[    2.141350] loop: module loaded"}
- {"dt": "2024-07-07T08:38:14.733756", "lvl": "target", "msg": "<6>[    2.144828] sifive_spi 10040000.spi: mapped; irq=31, cs=1"}
- {"dt": "2024-07-07T08:38:14.746518", "lvl": "target", "msg": "<6>[    2.150475] sifive_spi 10050000.spi: mapped; irq=32, cs=1"}
- {"dt": "2024-07-07T08:38:14.750385", "lvl": "target", "msg": "<6>[    2.157316] macb 10090000.ethernet: Registered clk switch 'sifive-gemgxl-mgmt'"}
- {"dt": "2024-07-07T08:38:14.778690", "lvl": "target", "msg": "<6>[    2.176249] macb 10090000.ethernet eth0: Cadence GEM rev 0x10070109 at 0x10090000 irq 33 (70:b3:d5:92:fa:8d)"}
- {"dt": "2024-07-07T08:38:14.779826", "lvl": "target", "msg": "<6>[    2.185742] e1000e: Intel(R) PRO/1000 Network Driver"}
- {"dt": "2024-07-07T08:38:14.782320", "lvl": "target", "msg": "<6>[    2.190803] e1000e: Copyright(c) 1999 - 2015 Intel Corporation."}
- {"dt": "2024-07-07T08:38:14.794487", "lvl": "target", "msg": "<6>[    2.197538] xhci_hcd 0000:04:00.0: xHCI Host Controller"}
- {"dt": "2024-07-07T08:38:14.797971", "lvl": "target", "msg": "<6>[    2.202464] xhci_hcd 0000:04:00.0: new USB bus registered, assigned bus number 1"}
- {"dt": "2024-07-07T08:38:14.942029", "lvl": "target", "msg": "<6>[    2.350811] xhci_hcd 0000:04:00.0: hcc params 0x0200e080 hci version 0x100 quirks 0x0000000010800410"}
- {"dt": "2024-07-07T08:38:14.954520", "lvl": "target", "msg": "<6>[    2.360251] xhci_hcd 0000:04:00.0: xHCI Host Controller"}
- {"dt": "2024-07-07T08:38:14.957890", "lvl": "target", "msg": "<6>[    2.364992] xhci_hcd 0000:04:00.0: new USB bus registered, assigned bus number 2"}
- {"dt": "2024-07-07T08:38:14.970375", "lvl": "target", "msg": "<6>[    2.372636] xhci_hcd 0000:04:00.0: Host supports USB 3.0 SuperSpeed"}
- {"dt": "2024-07-07T08:38:14.971593", "lvl": "target", "msg": "<6>[    2.380637] hub 1-0:1.0: USB hub found"}
- {"dt": "2024-07-07T08:38:14.974277", "lvl": "target", "msg": "<6>[    2.383931] hub 1-0:1.0: 2 ports detected"}
- {"dt": "2024-07-07T08:38:14.986515", "lvl": "target", "msg": "<6>[    2.388573] usb usb2: We don't know the algorithms for LPM for this host, disabling LPM."}
- {"dt": "2024-07-07T08:38:14.988896", "lvl": "target", "msg": "<6>[    2.396981] hub 2-0:1.0: USB hub found"}
- {"dt": "2024-07-07T08:38:14.990799", "lvl": "target", "msg": "<6>[    2.400512] hub 2-0:1.0: 2 ports detected"}
- {"dt": "2024-07-07T08:38:15.002347", "lvl": "target", "msg": "<6>[    2.405490] usbcore: registered new interface driver uas"}
- {"dt": "2024-07-07T08:38:15.003470", "lvl": "target", "msg": "<6>[    2.410405] usbcore: registered new interface driver usb-storage"}
- {"dt": "2024-07-07T08:38:15.005950", "lvl": "target", "msg": "<6>[    2.416738] mousedev: PS/2 mouse device common for all mice"}
- {"dt": "2024-07-07T08:38:15.018421", "lvl": "target", "msg": "<6>[    2.422888] sdhci: Secure Digital Host Controller Interface driver"}
- {"dt": "2024-07-07T08:38:15.021679", "lvl": "target", "msg": "<6>[    2.428810] sdhci: Copyright(c) Pierre Ossman"}
- {"dt": "2024-07-07T08:38:15.050689", "lvl": "target", "msg": "<6>[    2.459141] mmc_spi spi1.0: SD/MMC host mmc0, no DMA, no WP, no poweroff"}
- {"dt": "2024-07-07T08:38:15.054166", "lvl": "target", "msg": "<6>[    2.465419] sdhci-pltfm: SDHCI platform and OF driver helper"}
- {"dt": "2024-07-07T08:38:15.066798", "lvl": "target", "msg": "<6>[    2.471460] usbcore: registered new interface driver usbhid"}
- {"dt": "2024-07-07T08:38:15.068459", "lvl": "target", "msg": "<6>[    2.477094] usbhid: USB HID core driver"}
- {"dt": "2024-07-07T08:38:15.071911", "lvl": "target", "msg": "<6>[    2.481302] riscv-pmu-sbi: SBI PMU extension is available"}
- {"dt": "2024-07-07T08:38:15.082381", "lvl": "target", "msg": "<6>[    2.486855] riscv-pmu-sbi: 16 firmware and 4 hardware counters"}
- {"dt": "2024-07-07T08:38:15.086010", "lvl": "target", "msg": "<6>[    2.492899] riscv-pmu-sbi: Perf sampling/filtering is not supported as sscof extension is not available"}
- {"dt": "2024-07-07T08:38:15.098419", "lvl": "target", "msg": "<6>[    2.503597] NET: Registered PF_INET6 protocol family"}
- {"dt": "2024-07-07T08:38:15.100779", "lvl": "target", "msg": "<6>[    2.509647] Segment Routing with IPv6"}
- {"dt": "2024-07-07T08:38:15.103022", "lvl": "target", "msg": "<6>[    2.512877] In-situ OAM (IOAM) with IPv6"}
- {"dt": "2024-07-07T08:38:15.114455", "lvl": "target", "msg": "<6>[    2.517064] sit: IPv6, IPv4 and MPLS over IPv4 tunneling driver"}
- {"dt": "2024-07-07T08:38:15.115697", "lvl": "target", "msg": "<6>[    2.523790] NET: Registered PF_PACKET protocol family"}
- {"dt": "2024-07-07T08:38:15.118533", "lvl": "target", "msg": "<6>[    2.528665] 9pnet: Installing 9P2000 support"}
- {"dt": "2024-07-07T08:38:15.130471", "lvl": "target", "msg": "<5>[    2.533033] Key type dns_resolver registered"}
- {"dt": "2024-07-07T08:38:15.146572", "lvl": "target", "msg": "<6>[    2.543282] debug_vm_pgtable: [debug_vm_pgtable         ]: Validating architecture page table helpers"}
- {"dt": "2024-07-07T08:38:15.149988", "lvl": "target", "msg": "<4>[    2.559954] mmc0: host does not support reading read-only switch, assuming write-enable"}
- {"dt": "2024-07-07T08:38:15.162454", "lvl": "target", "msg": "<6>[    2.567488] mmc0: new SDHC card on SPI"}
- {"dt": "2024-07-07T08:38:15.165790", "lvl": "target", "msg": "<6>[    2.572905] mmcblk0: mmc0:0000 SDC   7.47 GiB "}
- {"dt": "2024-07-07T08:38:15.210257", "lvl": "target", "msg": "<4>[    2.610547] GPT:Primary header thinks Alt. header is not at the end of the disk."}
- {"dt": "2024-07-07T08:38:15.213058", "lvl": "target", "msg": "<4>[    2.617464] GPT:13918241 != 15661055"}
- {"dt": "2024-07-07T08:38:15.214561", "lvl": "target", "msg": "<4>[    2.621268] GPT:Alternate GPT header not at the end of the disk."}
- {"dt": "2024-07-07T08:38:15.215803", "lvl": "target", "msg": "<4>[    2.627521] GPT:13918241 != 15661055"}
- {"dt": "2024-07-07T08:38:15.226581", "lvl": "target", "msg": "<4>[    2.631341] GPT: Use GNU Parted to correct GPT errors."}
- {"dt": "2024-07-07T08:38:15.229663", "lvl": "target", "msg": "<6>[    2.636761]  mmcblk0: p1 p2 p3 p4"}
- {"dt": "2024-07-07T08:38:15.245422", "lvl": "target", "msg": "<6>[    2.655175] usb 1-2: new high-speed USB device number 2 using xhci_hcd"}
- {"dt": "2024-07-07T08:38:15.290454", "lvl": "target", "msg": "<6>[    2.686979] macb 10090000.ethernet eth0: PHY [10090000.ethernet-ffffffff:00] driver [Microsemi VSC8541 SyncE] (irq=POLL)"}
- {"dt": "2024-07-07T08:38:15.294003", "lvl": "target", "msg": "<6>[    2.697372] macb 10090000.ethernet eth0: configuring for phy/gmii link mode"}
- {"dt": "2024-07-07T08:38:15.498716", "lvl": "target", "msg": "<6>[    2.902396] hub 1-2:1.0: USB hub found"}
- {"dt": "2024-07-07T08:38:15.502462", "lvl": "target", "msg": "<6>[    2.905837] hub 1-2:1.0: 4 ports detected"}
- {"dt": "2024-07-07T08:38:15.596276", "lvl": "target", "msg": "<6>[    2.994614] usb 2-2: new SuperSpeed USB device number 2 using xhci_hcd"}
- {"dt": "2024-07-07T08:38:15.690665", "lvl": "target", "msg": "<6>[    3.096377] hub 2-2:1.0: USB hub found"}
- {"dt": "2024-07-07T08:38:15.695036", "lvl": "target", "msg": "<6>[    3.100345] hub 2-2:1.0: 4 ports detected"}
- {"dt": "2024-07-07T08:38:18.362964", "lvl": "target", "msg": "<6>[    5.768903] macb 10090000.ethernet eth0: Link is Up - 100Mbps/Full - flow control tx"}
- {"dt": "2024-07-07T08:38:18.368536", "lvl": "target", "msg": "<6>[    5.776197] IPv6: ADDRCONF(NETDEV_CHANGE): eth0: link becomes ready"}
- {"dt": "2024-07-07T08:38:18.410155", "lvl": "target", "msg": "<5>[    5.799195] Sending DHCP requests ., OK"}
- {"dt": "2024-07-07T08:38:18.413689", "lvl": "target", "msg": "<6>[    5.818526] IP-Config: Got DHCP answer from 192.168.66.1, my address is 192.168.66.244"}
- {"dt": "2024-07-07T08:38:18.414846", "lvl": "target", "msg": "<6>[    5.826683] IP-Config: Complete:"}
- {"dt": "2024-07-07T08:38:18.426402", "lvl": "target", "msg": "<6>[    5.830138]      device=eth0, hwaddr=70:b3:d5:92:fa:8d, ipaddr=192.168.66.244, mask=255.255.255.0, gw=192.168.66.1"}
- {"dt": "2024-07-07T08:38:18.429706", "lvl": "target", "msg": "<6>[    5.840742]      host=192.168.66.244, domain=, nis-domain=(none)"}
- {"dt": "2024-07-07T08:38:18.445476", "lvl": "target", "msg": "<6>[    5.846989]      bootserver=0.0.0.0, rootserver=0.0.0.0, rootpath="}
- {"dt": "2024-07-07T08:38:18.446570", "lvl": "target", "msg": "<6>[    5.846996]      nameserver0=10.1.1.1"}
- {"dt": "2024-07-07T08:38:18.460933", "lvl": "target", "msg": "<6>[    5.865816] Freeing unused kernel image (initmem) memory: 2164K"}
- {"dt": "2024-07-07T08:38:18.476678", "lvl": "target", "msg": "<6>[    5.879235] Run /init as init process"}
- {"dt": "2024-07-07T08:38:18.508732", "lvl": "target", "msg": "Starting syslogd: OK"}
- {"dt": "2024-07-07T08:38:18.524779", "lvl": "target", "msg": "Starting klogd: OK"}
- {"dt": "2024-07-07T08:38:18.540774", "lvl": "target", "msg": "Running sysctl: OK"}
- {"dt": "2024-07-07T08:38:18.556634", "lvl": "target", "msg": "Populating /dev using udev: <30>[    5.958112] udevd[97]: starting version 3.2.9"}
- {"dt": "2024-07-07T08:38:22.586480", "lvl": "target", "msg": "<5>[    9.995170] random: crng init done"}
- {"dt": "2024-07-07T08:38:22.601751", "lvl": "target", "msg": "<27>[   10.004049] udevd[97]: specified user 'tss' unknown"}
- {"dt": "2024-07-07T08:38:22.605012", "lvl": "target", "msg": "<27>[   10.008602] udevd[97]: specified group 'tss' unknown"}
- {"dt": "2024-07-07T08:38:22.605625", "lvl": "target", "msg": "<30>[   10.015991] udevd[99]: starting eudev-3.2.9"}
- {"dt": "2024-07-07T08:38:26.521830", "lvl": "target", "msg": "<6>[   13.928180] [drm] radeon kernel modesetting enabled."}
- {"dt": "2024-07-07T08:38:26.525124", "lvl": "target", "msg": "<6>[   13.933231] radeon 0000:07:00.0: enabling device (0000 -> 0003)"}
- {"dt": "2024-07-07T08:38:26.540826", "lvl": "target", "msg": "<6>[   13.939764] [drm] initializing kernel modesetting (CAICOS 0x1002:0x6779 0x1002:0x0000 0x00)."}
- {"dt": "2024-07-07T08:38:26.761791", "lvl": "target", "msg": "<6>[   14.169175] ATOM BIOS: C26401"}
- {"dt": "2024-07-07T08:38:26.765034", "lvl": "target", "msg": "<6>[   14.171832] [drm] GPU not posted. posting now..."}
- {"dt": "2024-07-07T08:38:26.777826", "lvl": "target", "msg": "<6>[   14.182040] radeon 0000:07:00.0: VRAM: 2048M 0x0000000000000000 - 0x000000007FFFFFFF (2048M used)"}
- {"dt": "2024-07-07T08:38:26.781101", "lvl": "target", "msg": "<6>[   14.190425] radeon 0000:07:00.0: GTT: 1024M 0x0000000080000000 - 0x00000000BFFFFFFF"}
- {"dt": "2024-07-07T08:38:26.793797", "lvl": "target", "msg": "<6>[   14.198329] [drm] Detected VRAM RAM=2048M, BAR=256M"}
- {"dt": "2024-07-07T08:38:26.794409", "lvl": "target", "msg": "<6>[   14.203442] [drm] RAM width 64bits DDR"}
- {"dt": "2024-07-07T08:38:26.797066", "lvl": "target", "msg": "<6>[   14.207569] [drm] radeon: 2048M of VRAM memory ready"}
- {"dt": "2024-07-07T08:38:26.809812", "lvl": "target", "msg": "<6>[   14.212657] [drm] radeon: 1024M of GTT memory ready."}
- {"dt": "2024-07-07T08:38:26.810625", "lvl": "target", "msg": "<6>[   14.217951] [drm] Loading CAICOS Microcode"}
- {"dt": "2024-07-07T08:38:26.825717", "lvl": "target", "msg": "<4>[   14.222278] radeon 0000:07:00.0: Direct firmware load for radeon/CAICOS_pfp.bin failed with error -2"}
- {"dt": "2024-07-07T08:38:26.826543", "lvl": "target", "msg": "<3>[   14.231600] ni_cp: Failed to load firmware \\\"radeon/CAICOS_pfp.bin\\\""}
- {"dt": "2024-07-07T08:38:26.841713", "lvl": "target", "msg": "<3>[   14.238014] [drm:evergreen_init [radeon]] *ERROR* Failed to load firmware!"}
- {"dt": "2024-07-07T08:38:26.842529", "lvl": "target", "msg": "<3>[   14.248690] radeon 0000:07:00.0: Fatal error during GPU init"}
- {"dt": "2024-07-07T08:38:26.845022", "lvl": "target", "msg": "<6>[   14.254592] [drm] radeon: finishing device."}
- {"dt": "2024-07-07T08:38:26.857727", "lvl": "target", "msg": "<6>[   14.266205] [drm] radeon: ttm finalized"}
- {"dt": "2024-07-07T08:38:26.861031", "lvl": "target", "msg": "<4>[   14.270183] radeon: probe of 0000:07:00.0 failed with error -2"}
- {"dt": "2024-07-07T08:38:26.876811", "lvl": "target", "msg": "done"}
- {"dt": "2024-07-07T08:38:26.877619", "lvl": "target", "msg": "Saving random seed: OK"}
- {"dt": "2024-07-07T08:38:26.908660", "lvl": "target", "msg": "Starting network: ip: RTNETLINK answers: File exists"}
- {"dt": "2024-07-07T08:38:26.909476", "lvl": "target", "msg": "FAIL"}
- {"dt": "2024-07-07T08:38:26.940657", "lvl": "target", "msg": "Starting dropbear sshd: OK"}
- {"dt": "2024-07-07T08:38:26.956793", "lvl": "target", "msg": "/bin/sh: can't access tty; job control turned off"}
- {"dt": "2024-07-07T08:38:26.958418", "lvl": "debug", "msg": "Matched prompt #10: / #"}
- {"dt": "2024-07-07T08:38:26.959209", "lvl": "results", "msg": {"case": "kernel-messages", "definition": "lava", "duration": "18.39", "extra": {"extra": []}, "level": "2.4.4.1", "namespace": "common", "result": "pass"}}
- {"dt": "2024-07-07T08:38:26.960295", "lvl": "debug", "msg": "Setting prompt string to ['/ #']"}
- {"dt": "2024-07-07T08:38:26.961135", "lvl": "debug", "msg": "end: 2.4.4.1 login-action (duration 00:00:18) [common]"}
- {"dt": "2024-07-07T08:38:26.961801", "lvl": "results", "msg": {"case": "login-action", "definition": "lava", "duration": "18.40", "extra": {"success": "No kernel warnings or errors detected."}, "level": "2.4.4.1", "namespace": "common", "result": "pass"}}
- {"dt": "2024-07-07T08:38:26.962964", "lvl": "debug", "msg": "end: 2.4.4 auto-login-action (duration 00:00:18) [common]"}
- {"dt": "2024-07-07T08:38:26.963763", "lvl": "debug", "msg": "start: 2.4.5 expect-shell-connection (timeout 00:03:43) [common]"}
- {"dt": "2024-07-07T08:38:26.964473", "lvl": "debug", "msg": "Setting prompt string to ['/ #']"}
- {"dt": "2024-07-07T08:38:26.965110", "lvl": "debug", "msg": "Forcing a shell prompt, looking for ['/ #']"}
- {"dt": "2024-07-07T08:38:26.965694", "lvl": "input", "msg": "\n"}
- {"dt": "2024-07-07T08:38:27.016368", "lvl": "target", "msg": "/ # "}
- {"dt": "2024-07-07T08:38:27.017554", "lvl": "debug", "msg": "expect-shell-connection: Wait for prompt ['/ #'] (timeout 00:05:00)"}
- {"dt": "2024-07-07T08:38:27.018438", "lvl": "debug", "msg": "Waiting using forced prompt support (timeout 00:02:30)"}
- {"dt": "2024-07-07T08:38:27.036807", "lvl": "target", "msg": ""}
- {"dt": "2024-07-07T08:38:27.038028", "lvl": "debug", "msg": "end: 2.4.5 expect-shell-connection (duration 00:00:00) [common]"}
- {"dt": "2024-07-07T08:38:27.038892", "lvl": "debug", "msg": "start: 2.4.6 export-device-env (timeout 00:03:43) [common]"}
- {"dt": "2024-07-07T08:38:27.039718", "lvl": "debug", "msg": "end: 2.4.6 export-device-env (duration 00:00:00) [common]"}
- {"dt": "2024-07-07T08:38:27.041087", "lvl": "debug", "msg": "end: 2.4 uboot-commands (duration 00:01:12) [common]"}
- {"dt": "2024-07-07T08:38:27.043101", "lvl": "info", "msg": "end: 2 uboot-action (duration 00:01:17) [common]"}
- {"dt": "2024-07-07T08:38:27.045027", "lvl": "info", "msg": "start: 3 lava-test-retry (timeout 00:01:00) [common]"}
- {"dt": "2024-07-07T08:38:27.046860", "lvl": "debug", "msg": "start: 3.1 lava-test-shell (timeout 00:01:00) [common]"}
- {"dt": "2024-07-07T08:38:27.048444", "lvl": "debug", "msg": "Using namespace: common"}
- {"dt": "2024-07-07T08:38:27.049913", "lvl": "input", "msg": "#\n"}
- {"dt": "2024-07-07T08:38:27.151650", "lvl": "target", "msg": "/ # #"}
- {"dt": "2024-07-07T08:38:27.153517", "lvl": "debug", "msg": "lava-test-shell: Wait for prompt ['/ #'] (timeout 00:01:00)"}
- {"dt": "2024-07-07T08:38:27.164719", "lvl": "target", "msg": "#"}
- {"dt": "2024-07-07T08:38:27.166225", "lvl": "debug", "msg": "Using /lava-35313"}
- {"dt": "2024-07-07T08:38:27.167234", "lvl": "input", "msg": "export SHELL=/bin/sh\n"}
- {"dt": "2024-07-07T08:38:27.268633", "lvl": "target", "msg": "/ # export SHELL=/bin/sh"}
- {"dt": "2024-07-07T08:38:27.276100", "lvl": "target", "msg": "export SHELL=/bin/sh"}
- {"dt": "2024-07-07T08:38:27.278137", "lvl": "input", "msg": ". /lava-35313/environment\n"}
- {"dt": "2024-07-07T08:38:27.379941", "lvl": "target", "msg": "/ # . /lava-35313/environment"}
- {"dt": "2024-07-07T08:38:27.388050", "lvl": "target", "msg": ". /lava-35313/environment"}
- {"dt": "2024-07-07T08:38:27.390209", "lvl": "input", "msg": "/lava-35313/bin/lava-test-runner /lava-35313/0\n"}
- {"dt": "2024-07-07T08:38:27.492046", "lvl": "target", "msg": "/ # /lava-35313/bin/lava-test-runner /lava-35313/0"}
- {"dt": "2024-07-07T08:38:27.493646", "lvl": "info", "msg": "Test shell timeout: 10s (minimum of the action and connection timeout)"}
- {"dt": "2024-07-07T08:38:27.500078", "lvl": "target", "msg": "/lava-35313/bin/lava-test-runner /lava-35313/0"}
- {"dt": "2024-07-07T08:38:27.529902", "lvl": "target", "msg": "+ export 'TESTRUN_ID=0_dmesg'"}
- {"dt": "2024-07-07T08:38:27.545906", "lvl": "target", "msg": "+ cd /lava-<8>[   14.948306] <LAVA_SIGNAL_STARTRUN 0_dmesg 35313_1.5.2.4.1>"}
- {"dt": "2024-07-07T08:38:27.547413", "lvl": "target", "msg": "35313/0/tests/0_dmesg"}
- {"dt": "2024-07-07T08:38:27.549380", "lvl": "debug", "msg": "Received signal: <STARTRUN> 0_dmesg 35313_1.5.2.4.1"}
- {"dt": "2024-07-07T08:38:27.550887", "lvl": "info", "msg": "Starting test lava.0_dmesg (35313_1.5.2.4.1)"}
- {"dt": "2024-07-07T08:38:27.552564", "lvl": "info", "msg": "Skipping test definition patterns."}
- {"dt": "2024-07-07T08:38:27.554535", "lvl": "target", "msg": "+ cat uuid"}
- {"dt": "2024-07-07T08:38:27.555914", "lvl": "target", "msg": "+ UUID=35313_1.5.2.4.1"}
- {"dt": "2024-07-07T08:38:27.556699", "lvl": "target", "msg": "+ set +x"}
- {"dt": "2024-07-07T08:38:27.557091", "lvl": "target", "msg": "+ KERNELCI_LAVA=y /bin/sh /opt/kernelci/dmesg.sh"}
- {"dt": "2024-07-07T08:38:27.580677", "lvl": "target", "msg": "<8>[   14.975770] <LAVA_SIGNAL_TESTCASE TEST_CASE_ID=crit RESULT=pass UNITS=lines MEASUREMENT=0>"}
- {"dt": "2024-07-07T08:38:27.581781", "lvl": "debug", "msg": "Received signal: <TESTCASE> TEST_CASE_ID=crit RESULT=pass UNITS=lines MEASUREMENT=0"}
- {"dt": "2024-07-07T08:38:27.582821", "lvl": "results", "msg": {"case": "crit", "definition": "0_dmesg", "endtc": ! "930", "measurement": ! "0.0", "result": "pass", "starttc": ! "930", "units": "lines"}}
- {"dt": "2024-07-07T08:38:27.597083", "lvl": "target", "msg": "<8>[   15.002212] <LAVA_SIGNAL_TESTCASE TEST_CASE_ID=alert RESULT=pass UNITS=lines MEASUREMENT=0>"}
- {"dt": "2024-07-07T08:38:27.598510", "lvl": "debug", "msg": "Received signal: <TESTCASE> TEST_CASE_ID=alert RESULT=pass UNITS=lines MEASUREMENT=0"}
- {"dt": "2024-07-07T08:38:27.599689", "lvl": "results", "msg": {"case": "alert", "definition": "0_dmesg", "endtc": ! "933", "measurement": ! "0.0", "result": "pass", "starttc": ! "933", "units": "lines"}}
- {"dt": "2024-07-07T08:38:27.625975", "lvl": "target", "msg": "<8>[   15.028494] <LAVA_SIGNAL_TESTCASE TEST_CASE_ID=emerg RESULT=pass UNITS=lines MEASUREMENT=0>"}
- {"dt": "2024-07-07T08:38:27.627772", "lvl": "debug", "msg": "Received signal: <TESTCASE> TEST_CASE_ID=emerg RESULT=pass UNITS=lines MEASUREMENT=0"}
- {"dt": "2024-07-07T08:38:27.629239", "lvl": "results", "msg": {"case": "emerg", "definition": "0_dmesg", "endtc": ! "936", "measurement": ! "0.0", "result": "pass", "starttc": ! "936", "units": "lines"}}
- {"dt": "2024-07-07T08:38:27.632074", "lvl": "target", "msg": "+ set +x"}
- {"dt": "2024-07-07T08:38:27.633368", "lvl": "target", "msg": "<8>[   15.037441] <LAVA_SIGNAL_ENDRUN 0_dmesg 35313_1.5.2.4.1>"}
- {"dt": "2024-07-07T08:38:27.634502", "lvl": "target", "msg": "<LAVA_TEST_RUNNER EXIT>"}
- {"dt": "2024-07-07T08:38:27.635944", "lvl": "debug", "msg": "Received signal: <ENDRUN> 0_dmesg 35313_1.5.2.4.1"}
- {"dt": "2024-07-07T08:38:27.636497", "lvl": "info", "msg": "Ending use of test pattern."}
- {"dt": "2024-07-07T08:38:27.636910", "lvl": "info", "msg": "Ending test lava.0_dmesg (35313_1.5.2.4.1), duration 0.09"}
- {"dt": "2024-07-07T08:38:27.637469", "lvl": "results", "msg": {"case": "0_dmesg", "definition": "lava", "duration": "0.09", "namespace": "common", "path": "inline/dmesg.yaml", "repository": {"metadata": {"description": "baseline test plan", "environment": ["lava-test-shell"], "format": "Lava-Test Test Definition 1.0", "name": "baseline", "os": ["debian"], "scope": ["functional"]}, "run": {"steps": ["KERNELCI_LAVA=y /bin/sh /opt/kernelci/dmesg.sh"]}}, "result": "pass", "revision": "unspecified", "uuid": "35313_1.5.2.4.1"}}
- {"dt": "2024-07-07T08:38:27.639044", "lvl": "info", "msg": "ok: lava_test_shell seems to have completed"}
- {"dt": "2024-07-07T08:38:27.639726", "lvl": "debug", "msg": "alert: pass\ncrit: pass\nemerg: pass\n"}
- {"dt": "2024-07-07T08:38:27.640267", "lvl": "debug", "msg": "end: 3.1 lava-test-shell (duration 00:00:01) [common]"}
- {"dt": "2024-07-07T08:38:27.640872", "lvl": "info", "msg": "end: 3 lava-test-retry (duration 00:00:01) [common]"}
- {"dt": "2024-07-07T08:38:27.641434", "lvl": "info", "msg": "start: 4 lava-test-retry (timeout 00:01:00) [common]"}
- {"dt": "2024-07-07T08:38:27.641993", "lvl": "debug", "msg": "start: 4.1 lava-test-shell (timeout 00:01:00) [common]"}
- {"dt": "2024-07-07T08:38:27.642425", "lvl": "debug", "msg": "Using namespace: common"}
- {"dt": "2024-07-07T08:38:27.642853", "lvl": "input", "msg": "#\n"}
- {"dt": "2024-07-07T08:38:27.743621", "lvl": "target", "msg": "/ # #"}
- {"dt": "2024-07-07T08:38:27.745350", "lvl": "debug", "msg": "lava-test-shell: Wait for prompt ['/ #'] (timeout 00:01:00)"}
- {"dt": "2024-07-07T08:38:27.746909", "lvl": "debug", "msg": "Using /lava-35313"}
- {"dt": "2024-07-07T08:38:27.748061", "lvl": "input", "msg": "export SHELL=/bin/sh\n"}
- {"dt": "2024-07-07T08:38:27.849755", "lvl": "target", "msg": "export SHELL=/bin/sh"}
- {"dt": "2024-07-07T08:38:27.852044", "lvl": "target", "msg": "#"}
- {"dt": "2024-07-07T08:38:27.854023", "lvl": "input", "msg": ". /lava-35313/environment\n"}
- {"dt": "2024-07-07T08:38:27.955837", "lvl": "target", "msg": "/ # export SHELL=/bin/sh. /lava-35313/environment"}
- {"dt": "2024-07-07T08:38:27.958096", "lvl": "target", "msg": ""}
- {"dt": "2024-07-07T08:38:27.959974", "lvl": "input", "msg": "/lava-35313/bin/lava-test-runner /lava-35313/1\n"}
- {"dt": "2024-07-07T08:38:28.061323", "lvl": "target", "msg": "/ # . /lava-35313/environment/lava-35313/bin/lava-test-runner /lava-35313/1"}
- {"dt": "2024-07-07T08:38:28.063070", "lvl": "info", "msg": "Test shell timeout: 10s (minimum of the action and connection timeout)"}
- {"dt": "2024-07-07T08:38:28.065068", "lvl": "target", "msg": ""}
- {"dt": "2024-07-07T08:38:28.076028", "lvl": "target", "msg": "/ # /lava-35313/bin/lava-test-runner /lava-35313/1"}
- {"dt": "2024-07-07T08:38:28.117046", "lvl": "target", "msg": "+ export 'TESTRUN_ID=1_bootrr'"}
- {"dt": "2024-07-07T08:38:28.118279", "lvl": "target", "msg": "+ cd /lava<8>[   15.517755] <LAVA_SIGNAL_STARTRUN 1_bootrr 35313_1.5.2.4.5>"}
- {"dt": "2024-07-07T08:38:28.119289", "lvl": "target", "msg": "-35313/1/tests/1_bootrr"}
- {"dt": "2024-07-07T08:38:28.120284", "lvl": "target", "msg": "+ cat uuid"}
- {"dt": "2024-07-07T08:38:28.121549", "lvl": "debug", "msg": "Received signal: <STARTRUN> 1_bootrr 35313_1.5.2.4.5"}
- {"dt": "2024-07-07T08:38:28.122509", "lvl": "info", "msg": "Starting test lava.1_bootrr (35313_1.5.2.4.5)"}
- {"dt": "2024-07-07T08:38:28.123476", "lvl": "info", "msg": "Skipping test definition patterns."}
- {"dt": "2024-07-07T08:38:28.124727", "lvl": "target", "msg": "+ UUID=35313_1.5.2.4.5"}
- {"dt": "2024-07-07T08:38:28.125691", "lvl": "target", "msg": "+ set +x"}
- {"dt": "2024-07-07T08:38:28.126681", "lvl": "target", "msg": "+ export 'PATH=/opt/bootrr/libexec/bootrr/helpers:/lava-35313/1/../bin:/sbin:/usr/sbin:/bin:/usr/bin'"}
- {"dt": "2024-07-07T08:38:28.127508", "lvl": "target", "msg": "+ cd /opt/bootrr/libexec/bootrr"}
- {"dt": "2024-07-07T08:38:28.137696", "lvl": "target", "msg": "+ sh helpers/bootrr-auto"}
- {"dt": "2024-07-07T08:38:28.138305", "lvl": "target", "msg": "/lava-35313/1/../bin/lava-test-case"}
- {"dt": "2024-07-07T08:38:28.139007", "lvl": "debug", "msg": "Received signal: <TESTCASE> TEST_CASE_ID=deferred-probe-empty RESULT=pass"}
- {"dt": "2024-07-07T08:38:28.139509", "lvl": "results", "msg": {"case": "deferred-probe-empty", "definition": "1_bootrr", "endtc": ! "980", "result": "pass", "starttc": ! "980"}}
- {"dt": "2024-07-07T08:38:28.140991", "lvl": "target", "msg": "<8>[   15.549602] <LAVA_SIGNAL_TESTCASE TEST_CASE_ID=deferred-probe-empty RESULT=pass>"}
- {"dt": "2024-07-07T08:38:28.155974", "lvl": "target", "msg": "/lava-35313/1/../bin/lava-test-case"}
- {"dt": "2024-07-07T08:38:28.173174", "lvl": "target", "msg": "<8>[   15.574993] <LAVA_SIGNAL_TESTCASE TEST_CASE_ID=all-cpus-are-online RESULT=pass>"}
- {"dt": "2024-07-07T08:38:28.174246", "lvl": "target", "msg": "/lava-35313/1/../bin/lava-test-case"}
- {"dt": "2024-07-07T08:38:28.175475", "lvl": "debug", "msg": "Received signal: <TESTCASE> TEST_CASE_ID=all-cpus-are-online RESULT=pass"}
- {"dt": "2024-07-07T08:38:28.176521", "lvl": "results", "msg": {"case": "all-cpus-are-online", "definition": "1_bootrr", "endtc": ! "986", "result": "pass", "starttc": ! "986"}}
- {"dt": "2024-07-07T08:38:28.189045", "lvl": "target", "msg": "<8>[   15.591347] <LAVA_SIGNAL_TESTCASE TEST_CASE_ID=tpm-chip-is-online RESULT=skip>"}
- {"dt": "2024-07-07T08:38:28.189921", "lvl": "target", "msg": "+ set +x"}
- {"dt": "2024-07-07T08:38:28.190910", "lvl": "debug", "msg": "Received signal: <TESTCASE> TEST_CASE_ID=tpm-chip-is-online RESULT=skip"}
- {"dt": "2024-07-07T08:38:28.191670", "lvl": "results", "msg": {"case": "tpm-chip-is-online", "definition": "1_bootrr", "endtc": ! "990", "result": "skip", "starttc": ! "990"}}
- {"dt": "2024-07-07T08:38:28.201842", "lvl": "target", "msg": "<8>[   15.606047] <LAVA_SIGNAL_ENDRUN 1_bootrr 35313_1.5.2.4.5>"}
- {"dt": "2024-07-07T08:38:28.202954", "lvl": "debug", "msg": "Received signal: <ENDRUN> 1_bootrr 35313_1.5.2.4.5"}
- {"dt": "2024-07-07T08:38:28.203641", "lvl": "info", "msg": "Ending use of test pattern."}
- {"dt": "2024-07-07T08:38:28.204230", "lvl": "info", "msg": "Ending test lava.1_bootrr (35313_1.5.2.4.5), duration 0.08"}
- {"dt": "2024-07-07T08:38:28.205203", "lvl": "results", "msg": {"case": "1_bootrr", "definition": "lava", "duration": "0.08", "namespace": "common", "path": "inline/bootrr.yaml", "repository": {"metadata": {"description": "baseline test plan", "environment": ["lava-test-shell"], "format": "Lava-Test Test Definition 1.0", "name": "baseline", "os": ["debian"], "scope": ["functional"]}, "run": {"steps": ["export PATH=/opt/bootrr/libexec/bootrr/helpers:$PATH", "cd /opt/bootrr/libexec/bootrr && sh helpers/bootrr-auto"]}}, "result": "pass", "revision": "unspecified", "uuid": "35313_1.5.2.4.5"}}
- {"dt": "2024-07-07T08:38:28.207753", "lvl": "target", "msg": "<LAVA_TEST_RUNNER EXIT>"}
- {"dt": "2024-07-07T08:38:28.208725", "lvl": "info", "msg": "ok: lava_test_shell seems to have completed"}
- {"dt": "2024-07-07T08:38:28.209531", "lvl": "debug", "msg": "all-cpus-are-online: pass\ndeferred-probe-empty: pass\ntpm-chip-is-online: skip\n"}
- {"dt": "2024-07-07T08:38:28.210150", "lvl": "debug", "msg": "end: 4.1 lava-test-shell (duration 00:00:01) [common]"}
- {"dt": "2024-07-07T08:38:28.210756", "lvl": "info", "msg": "end: 4 lava-test-retry (duration 00:00:01) [common]"}
- {"dt": "2024-07-07T08:38:28.211398", "lvl": "info", "msg": "start: 5 finalize (timeout 00:08:24) [common]"}
- {"dt": "2024-07-07T08:38:28.212060", "lvl": "debug", "msg": "start: 5.1 power-off (timeout 00:00:30) [common]"}
- {"dt": "2024-07-07T08:38:28.212943", "lvl": "debug", "msg": "Calling: 'upower.sh' '--atx' 'off' '1'"}
- {"dt": "2024-07-07T08:38:32.059226", "lvl": "debug", "msg": ">> Accessing Gembird #0 USB device 016\r"}
- {"dt": "2024-07-07T08:38:32.064204", "lvl": "debug", "msg": ">> Switched outlet 1 off\r"}
- {"dt": "2024-07-07T08:38:32.070913", "lvl": "debug", "msg": "Returned 0 in 3 seconds"}
- {"dt": "2024-07-07T08:38:32.174148", "lvl": "debug", "msg": "end: 5.1 power-off (duration 00:00:04) [common]"}
- {"dt": "2024-07-07T08:38:32.176283", "lvl": "results", "msg": {"case": "power-off", "definition": "lava", "duration": "3.96", "extra": {"status": "success"}, "level": "5.1", "namespace": "common", "result": "pass"}}
- {"dt": "2024-07-07T08:38:32.180452", "lvl": "debug", "msg": "start: 5.2 read-feedback (timeout 00:08:20) [common]"}
- {"dt": "2024-07-07T08:38:32.184715", "lvl": "debug", "msg": "Listened to connection for namespace 'common' for up to 1s"}
- {"dt": "2024-07-07T08:38:33.184147", "lvl": "info", "msg": "Finalising connection for namespace 'common'"}
- {"dt": "2024-07-07T08:38:33.186474", "lvl": "info", "msg": "Disconnecting from shell: Finalise"}
- {"dt": "2024-07-07T08:38:33.188387", "lvl": "target", "msg": "/ # "}
- {"dt": "2024-07-07T08:38:33.291162", "lvl": "debug", "msg": "end: 5.2 read-feedback (duration 00:00:01) [common]"}
- {"dt": "2024-07-07T08:38:33.293292", "lvl": "info", "msg": "end: 5 finalize (duration 00:00:05) [common]"}
- {"dt": "2024-07-07T08:38:33.295445", "lvl": "info", "msg": "Cleaning after the job"}
- {"dt": "2024-07-07T08:38:33.297053", "lvl": "debug", "msg": "Cleaning up download directory: /var/lib/lava/dispatcher/tmp/35313/tftp-deploy-b9hrn41v/ramdisk"}
- {"dt": "2024-07-07T08:38:33.306797", "lvl": "debug", "msg": "Cleaning up download directory: /var/lib/lava/dispatcher/tmp/35313/tftp-deploy-b9hrn41v/kernel"}
- {"dt": "2024-07-07T08:38:33.314753", "lvl": "debug", "msg": "Cleaning up download directory: /var/lib/lava/dispatcher/tmp/35313/tftp-deploy-b9hrn41v/dtb"}
- {"dt": "2024-07-07T08:38:33.316112", "lvl": "debug", "msg": "Cleaning up download directory: /var/lib/lava/dispatcher/tmp/35313/tftp-deploy-b9hrn41v/modules"}
- {"dt": "2024-07-07T08:38:33.324367", "lvl": "info", "msg": "Override tmp directory removed at /var/lib/lava/dispatcher/tmp/35313"}
- {"dt": "2024-07-07T08:38:33.461556", "lvl": "info", "msg": "Root tmp directory removed at /var/lib/lava/dispatcher/tmp/35313"}
- {"dt": "2024-07-07T08:38:33.462485", "lvl": "info", "msg": "Job finished correctly"}
- {"dt": "2024-07-07T08:38:33.463047", "lvl": "results", "msg": {"case": "job", "definition": "lava", "result": "pass"}}
