- {"dt": "2023-12-18T13:14:31.406425", "lvl": "info", "msg": "lava-dispatcher, installed at version: 2023.01"}
- {"dt": "2023-12-18T13:14:31.407752", "lvl": "info", "msg": "start: 0 validate"}
- {"dt": "2023-12-18T13:14:31.408740", "lvl": "info", "msg": "Start time: 2023-12-18 13:14:31.408683+00:00 (UTC)"}
- {"dt": "2023-12-18T13:14:31.409848", "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": "2023-12-18T13:14:32.722196", "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": "2023-12-18T13:14:34.349149", "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": "2023-12-18T13:14:34.993164", "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": "2023-12-18T13:14:36.132947", "lvl": "info", "msg": "validate duration: 4.72"}
- {"dt": "2023-12-18T13:14:36.133724", "lvl": "results", "msg": {"case": "validate", "definition": "lava", "result": "pass"}}
- {"dt": "2023-12-18T13:14:36.134832", "lvl": "info", "msg": "start: 1 tftp-deploy (timeout 00:10:00) [common]"}
- {"dt": "2023-12-18T13:14:36.135768", "lvl": "debug", "msg": "start: 1.1 download-retry (timeout 00:10:00) [common]"}
- {"dt": "2023-12-18T13:14:36.136562", "lvl": "debug", "msg": "start: 1.1.1 http-download (timeout 00:10:00) [common]"}
- {"dt": "2023-12-18T13:14:36.137595", "lvl": "debug", "msg": "Not decompressing ramdisk as can be used compressed."}
- {"dt": "2023-12-18T13:14:36.138449", "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": "2023-12-18T13:14:36.139072", "lvl": "debug", "msg": "saving as /var/lib/lava/dispatcher/tmp/34405/tftp-deploy-h2kejrfm/ramdisk/rootfs.cpio.gz"}
- {"dt": "2023-12-18T13:14:36.139695", "lvl": "debug", "msg": "total size: 7844224 (7MB)"}
- {"dt": "2023-12-18T13:14:37.259722", "lvl": "debug", "msg": "progress   0% (0MB)"}
- {"dt": "2023-12-18T13:14:37.304683", "lvl": "debug", "msg": "progress   5% (0MB)"}
- {"dt": "2023-12-18T13:14:37.323214", "lvl": "debug", "msg": "progress  10% (0MB)"}
- {"dt": "2023-12-18T13:14:37.342903", "lvl": "debug", "msg": "progress  15% (1MB)"}
- {"dt": "2023-12-18T13:14:37.362404", "lvl": "debug", "msg": "progress  20% (1MB)"}
- {"dt": "2023-12-18T13:14:37.382405", "lvl": "debug", "msg": "progress  25% (1MB)"}
- {"dt": "2023-12-18T13:14:37.401544", "lvl": "debug", "msg": "progress  30% (2MB)"}
- {"dt": "2023-12-18T13:14:37.419738", "lvl": "debug", "msg": "progress  35% (2MB)"}
- {"dt": "2023-12-18T13:14:37.438460", "lvl": "debug", "msg": "progress  40% (3MB)"}
- {"dt": "2023-12-18T13:14:37.457270", "lvl": "debug", "msg": "progress  45% (3MB)"}
- {"dt": "2023-12-18T13:14:37.475816", "lvl": "debug", "msg": "progress  50% (3MB)"}
- {"dt": "2023-12-18T13:14:37.495271", "lvl": "debug", "msg": "progress  55% (4MB)"}
- {"dt": "2023-12-18T13:14:37.513677", "lvl": "debug", "msg": "progress  60% (4MB)"}
- {"dt": "2023-12-18T13:14:37.532618", "lvl": "debug", "msg": "progress  65% (4MB)"}
- {"dt": "2023-12-18T13:14:37.551686", "lvl": "debug", "msg": "progress  70% (5MB)"}
- {"dt": "2023-12-18T13:14:37.569488", "lvl": "debug", "msg": "progress  75% (5MB)"}
- {"dt": "2023-12-18T13:14:37.587400", "lvl": "debug", "msg": "progress  80% (6MB)"}
- {"dt": "2023-12-18T13:14:37.604792", "lvl": "debug", "msg": "progress  85% (6MB)"}
- {"dt": "2023-12-18T13:14:37.622375", "lvl": "debug", "msg": "progress  90% (6MB)"}
- {"dt": "2023-12-18T13:14:37.639776", "lvl": "debug", "msg": "progress  95% (7MB)"}
- {"dt": "2023-12-18T13:14:37.657118", "lvl": "debug", "msg": "progress 100% (7MB)"}
- {"dt": "2023-12-18T13:14:37.658512", "lvl": "info", "msg": "7MB downloaded in 1.52s (4.93MB/s)"}
- {"dt": "2023-12-18T13:14:37.659637", "lvl": "debug", "msg": "end: 1.1.1 http-download (duration 00:00:02) [common]"}
- {"dt": "2023-12-18T13:14:37.660259", "lvl": "results", "msg": {"case": "http-download", "definition": "lava", "duration": "1.52", "extra": {"label": "ramdisk", "md5sum": "4bbb32813cb05021df34cefcbb385507", "sha256sum": "5a9577755f4c03de73672a1f7d73d1fefcc1af9c766e4815d716d23495f74ed8", "sha512sum": "b435cc3fbbdc57e455d0c13d9dcec3969dcf4e26cee57fa102df8b82e1a4e9b739f026cc19905db282fd50a3187a6e143709e111a847d8c8ff9d38fba0434aa8", "size": ! "7844224"}, "level": "1.1.1", "namespace": "common", "result": "pass"}}
- {"dt": "2023-12-18T13:14:37.661572", "lvl": "debug", "msg": "end: 1.1 download-retry (duration 00:00:02) [common]"}
- {"dt": "2023-12-18T13:14:37.662190", "lvl": "debug", "msg": "start: 1.2 download-retry (timeout 00:09:58) [common]"}
- {"dt": "2023-12-18T13:14:37.662790", "lvl": "debug", "msg": "start: 1.2.1 http-download (timeout 00:09:58) [common]"}
- {"dt": "2023-12-18T13:14:37.663783", "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": "2023-12-18T13:14:37.664397", "lvl": "debug", "msg": "saving as /var/lib/lava/dispatcher/tmp/34405/tftp-deploy-h2kejrfm/kernel/Image"}
- {"dt": "2023-12-18T13:14:37.664853", "lvl": "debug", "msg": "total size: 19845120 (18MB)"}
- {"dt": "2023-12-18T13:14:37.665289", "lvl": "debug", "msg": "No compression specified"}
- {"dt": "2023-12-18T13:14:38.733184", "lvl": "debug", "msg": "progress   0% (0MB)"}
- {"dt": "2023-12-18T13:14:38.779889", "lvl": "debug", "msg": "progress   5% (0MB)"}
- {"dt": "2023-12-18T13:14:38.823233", "lvl": "debug", "msg": "progress  10% (1MB)"}
- {"dt": "2023-12-18T13:14:38.867292", "lvl": "debug", "msg": "progress  15% (2MB)"}
- {"dt": "2023-12-18T13:14:38.912454", "lvl": "debug", "msg": "progress  20% (3MB)"}
- {"dt": "2023-12-18T13:14:38.956396", "lvl": "debug", "msg": "progress  25% (4MB)"}
- {"dt": "2023-12-18T13:14:39.001004", "lvl": "debug", "msg": "progress  30% (5MB)"}
- {"dt": "2023-12-18T13:14:39.045447", "lvl": "debug", "msg": "progress  35% (6MB)"}
- {"dt": "2023-12-18T13:14:39.091427", "lvl": "debug", "msg": "progress  40% (7MB)"}
- {"dt": "2023-12-18T13:14:39.135766", "lvl": "debug", "msg": "progress  45% (8MB)"}
- {"dt": "2023-12-18T13:14:39.179324", "lvl": "debug", "msg": "progress  50% (9MB)"}
- {"dt": "2023-12-18T13:14:39.225935", "lvl": "debug", "msg": "progress  55% (10MB)"}
- {"dt": "2023-12-18T13:14:39.271526", "lvl": "debug", "msg": "progress  60% (11MB)"}
- {"dt": "2023-12-18T13:14:39.316868", "lvl": "debug", "msg": "progress  65% (12MB)"}
- {"dt": "2023-12-18T13:14:39.361485", "lvl": "debug", "msg": "progress  70% (13MB)"}
- {"dt": "2023-12-18T13:14:39.408129", "lvl": "debug", "msg": "progress  75% (14MB)"}
- {"dt": "2023-12-18T13:14:39.453476", "lvl": "debug", "msg": "progress  80% (15MB)"}
- {"dt": "2023-12-18T13:14:39.498582", "lvl": "debug", "msg": "progress  85% (16MB)"}
- {"dt": "2023-12-18T13:14:39.545739", "lvl": "debug", "msg": "progress  90% (17MB)"}
- {"dt": "2023-12-18T13:14:39.588204", "lvl": "debug", "msg": "progress  95% (18MB)"}
- {"dt": "2023-12-18T13:14:39.630157", "lvl": "debug", "msg": "progress 100% (18MB)"}
- {"dt": "2023-12-18T13:14:39.631859", "lvl": "info", "msg": "18MB downloaded in 1.97s (9.62MB/s)"}
- {"dt": "2023-12-18T13:14:39.633013", "lvl": "debug", "msg": "end: 1.2.1 http-download (duration 00:00:02) [common]"}
- {"dt": "2023-12-18T13:14:39.633689", "lvl": "results", "msg": {"case": "http-download", "definition": "lava", "duration": "1.97", "extra": {"label": "kernel", "md5sum": "bc353ea01eab589bb4cd6918b0d126de", "sha256sum": "8a98e42d83b971b3f17b23f2fded633f8d3c97ef956efe6ee5d6edd727f87ee1", "sha512sum": "4cad13e71faae976b6b963587c809e948943cb1a76d6655667aac8f154e7068fccb3b3a1191ff00b29dd63f0e46a7b939ed0c46d4edda16d7e9efa5acf87b65b", "size": ! "19845120"}, "level": "1.2.1", "namespace": "common", "result": "pass"}}
- {"dt": "2023-12-18T13:14:39.635204", "lvl": "debug", "msg": "end: 1.2 download-retry (duration 00:00:02) [common]"}
- {"dt": "2023-12-18T13:14:39.636065", "lvl": "debug", "msg": "start: 1.3 download-retry (timeout 00:09:56) [common]"}
- {"dt": "2023-12-18T13:14:39.636851", "lvl": "debug", "msg": "start: 1.3.1 http-download (timeout 00:09:56) [common]"}
- {"dt": "2023-12-18T13:14:39.637918", "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": "2023-12-18T13:14:39.638598", "lvl": "debug", "msg": "saving as /var/lib/lava/dispatcher/tmp/34405/tftp-deploy-h2kejrfm/dtb/hifive-unmatched-a00.dtb"}
- {"dt": "2023-12-18T13:14:39.639205", "lvl": "debug", "msg": "total size: 10707 (0MB)"}
- {"dt": "2023-12-18T13:14:39.639791", "lvl": "debug", "msg": "No compression specified"}
- {"dt": "2023-12-18T13:14:40.113288", "lvl": "debug", "msg": "progress 100% (0MB)"}
- {"dt": "2023-12-18T13:14:40.117159", "lvl": "info", "msg": "0MB downloaded in 0.48s (0.02MB/s)"}
- {"dt": "2023-12-18T13:14:40.119934", "lvl": "debug", "msg": "end: 1.3.1 http-download (duration 00:00:00) [common]"}
- {"dt": "2023-12-18T13:14:40.120622", "lvl": "results", "msg": {"case": "http-download", "definition": "lava", "duration": "0.48", "extra": {"label": "dtb", "md5sum": "6e4ede97cac7e574ba154868ae6bd490", "sha256sum": "bfd83286eab97548a6663437655c0c6805a361a06c726c439b8d9655be38d15b", "sha512sum": "429c70a390d17dc993647232bfa0333fdf25e66e87f05676252174f698e925e876ddf6b1e722bfdedaf8fd299f71a19b2c8c383eade9bf4df01262d0773fd702", "size": ! "10707"}, "level": "1.3.1", "namespace": "common", "result": "pass"}}
- {"dt": "2023-12-18T13:14:40.122086", "lvl": "debug", "msg": "end: 1.3 download-retry (duration 00:00:00) [common]"}
- {"dt": "2023-12-18T13:14:40.122865", "lvl": "debug", "msg": "start: 1.4 download-retry (timeout 00:09:56) [common]"}
- {"dt": "2023-12-18T13:14:40.123696", "lvl": "debug", "msg": "start: 1.4.1 http-download (timeout 00:09:56) [common]"}
- {"dt": "2023-12-18T13:14:40.124784", "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": "2023-12-18T13:14:40.125460", "lvl": "debug", "msg": "saving as /var/lib/lava/dispatcher/tmp/34405/tftp-deploy-h2kejrfm/modules/modules.tar"}
- {"dt": "2023-12-18T13:14:40.126016", "lvl": "debug", "msg": "total size: 3892756 (3MB)"}
- {"dt": "2023-12-18T13:14:40.126564", "lvl": "info", "msg": "Using unxz to decompress xz"}
- {"dt": "2023-12-18T13:14:41.149522", "lvl": "debug", "msg": "progress   0% (0MB)"}
- {"dt": "2023-12-18T13:14:41.175922", "lvl": "debug", "msg": "progress   5% (0MB)"}
- {"dt": "2023-12-18T13:14:41.215469", "lvl": "debug", "msg": "progress  10% (0MB)"}
- {"dt": "2023-12-18T13:14:41.257588", "lvl": "debug", "msg": "progress  15% (0MB)"}
- {"dt": "2023-12-18T13:14:41.292420", "lvl": "debug", "msg": "progress  20% (0MB)"}
- {"dt": "2023-12-18T13:14:41.338462", "lvl": "debug", "msg": "progress  25% (0MB)"}
- {"dt": "2023-12-18T13:14:41.395231", "lvl": "debug", "msg": "progress  30% (1MB)"}
- {"dt": "2023-12-18T13:14:41.442419", "lvl": "debug", "msg": "progress  35% (1MB)"}
- {"dt": "2023-12-18T13:14:41.486807", "lvl": "debug", "msg": "progress  40% (1MB)"}
- {"dt": "2023-12-18T13:14:41.523783", "lvl": "debug", "msg": "progress  45% (1MB)"}
- {"dt": "2023-12-18T13:14:41.566013", "lvl": "debug", "msg": "progress  50% (1MB)"}
- {"dt": "2023-12-18T13:14:41.615688", "lvl": "debug", "msg": "progress  55% (2MB)"}
- {"dt": "2023-12-18T13:14:41.677128", "lvl": "debug", "msg": "progress  60% (2MB)"}
- {"dt": "2023-12-18T13:14:41.720106", "lvl": "debug", "msg": "progress  65% (2MB)"}
- {"dt": "2023-12-18T13:14:41.764167", "lvl": "debug", "msg": "progress  70% (2MB)"}
- {"dt": "2023-12-18T13:14:41.800410", "lvl": "debug", "msg": "progress  75% (2MB)"}
- {"dt": "2023-12-18T13:14:41.846901", "lvl": "debug", "msg": "progress  80% (3MB)"}
- {"dt": "2023-12-18T13:14:41.893445", "lvl": "debug", "msg": "progress  85% (3MB)"}
- {"dt": "2023-12-18T13:14:41.947500", "lvl": "debug", "msg": "progress  90% (3MB)"}
- {"dt": "2023-12-18T13:14:41.991742", "lvl": "debug", "msg": "progress  95% (3MB)"}
- {"dt": "2023-12-18T13:14:42.035347", "lvl": "debug", "msg": "progress 100% (3MB)"}
- {"dt": "2023-12-18T13:14:42.060416", "lvl": "info", "msg": "3MB downloaded in 1.93s (1.92MB/s)"}
- {"dt": "2023-12-18T13:14:42.063224", "lvl": "debug", "msg": "end: 1.4.1 http-download (duration 00:00:02) [common]"}
- {"dt": "2023-12-18T13:14:42.064240", "lvl": "results", "msg": {"case": "http-download", "definition": "lava", "duration": "1.94", "extra": {"label": "modules", "md5sum": "bd526ab1d1394350f02fce39169fd3ed", "sha256sum": "3adbbae160cc6e797e09f2ec6df9c6c848d48f6451e75131e278b4f8dc96bb3b", "sha512sum": "94ab1014e55f1dc62ed235004bd221efcacdbad3af4ff6cb191ec3007be7588b46db84f73d3a3f0da7d101fa96ae93c4dc51fe8a49d2b43b50fcf42e95b38c7f", "size": ! "3892756"}, "level": "1.4.1", "namespace": "common", "result": "pass"}}
- {"dt": "2023-12-18T13:14:42.066704", "lvl": "debug", "msg": "end: 1.4 download-retry (duration 00:00:02) [common]"}
- {"dt": "2023-12-18T13:14:42.067896", "lvl": "debug", "msg": "start: 1.5 prepare-tftp-overlay (timeout 00:09:54) [common]"}
- {"dt": "2023-12-18T13:14:42.069066", "lvl": "debug", "msg": "start: 1.5.1 extract-nfsrootfs (timeout 00:09:54) [common]"}
- {"dt": "2023-12-18T13:14:42.070096", "lvl": "debug", "msg": "end: 1.5.1 extract-nfsrootfs (duration 00:00:00) [common]"}
- {"dt": "2023-12-18T13:14:42.071259", "lvl": "debug", "msg": "start: 1.5.2 lava-overlay (timeout 00:09:54) [common]"}
- {"dt": "2023-12-18T13:14:42.072812", "lvl": "debug", "msg": "[common] Preparing overlay tarball in /var/lib/lava/dispatcher/tmp/34405/lava-overlay-2toou5i7"}
- {"dt": "2023-12-18T13:14:42.073968", "lvl": "debug", "msg": "makedir: /var/lib/lava/dispatcher/tmp/34405/lava-overlay-2toou5i7/lava-34405/bin"}
- {"dt": "2023-12-18T13:14:42.074947", "lvl": "debug", "msg": "makedir: /var/lib/lava/dispatcher/tmp/34405/lava-overlay-2toou5i7/lava-34405/tests"}
- {"dt": "2023-12-18T13:14:42.075917", "lvl": "debug", "msg": "makedir: /var/lib/lava/dispatcher/tmp/34405/lava-overlay-2toou5i7/lava-34405/results"}
- {"dt": "2023-12-18T13:14:42.076832", "lvl": "debug", "msg": "Creating /var/lib/lava/dispatcher/tmp/34405/lava-overlay-2toou5i7/lava-34405/bin/lava-add-keys"}
- {"dt": "2023-12-18T13:14:42.078080", "lvl": "debug", "msg": "Creating /var/lib/lava/dispatcher/tmp/34405/lava-overlay-2toou5i7/lava-34405/bin/lava-add-sources"}
- {"dt": "2023-12-18T13:14:42.079398", "lvl": "debug", "msg": "Creating /var/lib/lava/dispatcher/tmp/34405/lava-overlay-2toou5i7/lava-34405/bin/lava-background-process-start"}
- {"dt": "2023-12-18T13:14:42.080639", "lvl": "debug", "msg": "Creating /var/lib/lava/dispatcher/tmp/34405/lava-overlay-2toou5i7/lava-34405/bin/lava-background-process-stop"}
- {"dt": "2023-12-18T13:14:42.081824", "lvl": "debug", "msg": "Creating /var/lib/lava/dispatcher/tmp/34405/lava-overlay-2toou5i7/lava-34405/bin/lava-common-functions"}
- {"dt": "2023-12-18T13:14:42.083010", "lvl": "debug", "msg": "Creating /var/lib/lava/dispatcher/tmp/34405/lava-overlay-2toou5i7/lava-34405/bin/lava-echo-ipv4"}
- {"dt": "2023-12-18T13:14:42.084278", "lvl": "debug", "msg": "Creating /var/lib/lava/dispatcher/tmp/34405/lava-overlay-2toou5i7/lava-34405/bin/lava-install-packages"}
- {"dt": "2023-12-18T13:14:42.085478", "lvl": "debug", "msg": "Creating /var/lib/lava/dispatcher/tmp/34405/lava-overlay-2toou5i7/lava-34405/bin/lava-installed-packages"}
- {"dt": "2023-12-18T13:14:42.086677", "lvl": "debug", "msg": "Creating /var/lib/lava/dispatcher/tmp/34405/lava-overlay-2toou5i7/lava-34405/bin/lava-os-build"}
- {"dt": "2023-12-18T13:14:42.087946", "lvl": "debug", "msg": "Creating /var/lib/lava/dispatcher/tmp/34405/lava-overlay-2toou5i7/lava-34405/bin/lava-probe-channel"}
- {"dt": "2023-12-18T13:14:42.089157", "lvl": "debug", "msg": "Creating /var/lib/lava/dispatcher/tmp/34405/lava-overlay-2toou5i7/lava-34405/bin/lava-probe-ip"}
- {"dt": "2023-12-18T13:14:42.090339", "lvl": "debug", "msg": "Creating /var/lib/lava/dispatcher/tmp/34405/lava-overlay-2toou5i7/lava-34405/bin/lava-target-ip"}
- {"dt": "2023-12-18T13:14:42.091614", "lvl": "debug", "msg": "Creating /var/lib/lava/dispatcher/tmp/34405/lava-overlay-2toou5i7/lava-34405/bin/lava-target-mac"}
- {"dt": "2023-12-18T13:14:42.092830", "lvl": "debug", "msg": "Creating /var/lib/lava/dispatcher/tmp/34405/lava-overlay-2toou5i7/lava-34405/bin/lava-target-storage"}
- {"dt": "2023-12-18T13:14:42.094049", "lvl": "debug", "msg": "Creating /var/lib/lava/dispatcher/tmp/34405/lava-overlay-2toou5i7/lava-34405/bin/lava-test-case"}
- {"dt": "2023-12-18T13:14:42.095270", "lvl": "debug", "msg": "Creating /var/lib/lava/dispatcher/tmp/34405/lava-overlay-2toou5i7/lava-34405/bin/lava-test-event"}
- {"dt": "2023-12-18T13:14:42.096482", "lvl": "debug", "msg": "Creating /var/lib/lava/dispatcher/tmp/34405/lava-overlay-2toou5i7/lava-34405/bin/lava-test-feedback"}
- {"dt": "2023-12-18T13:14:42.097663", "lvl": "debug", "msg": "Creating /var/lib/lava/dispatcher/tmp/34405/lava-overlay-2toou5i7/lava-34405/bin/lava-test-raise"}
- {"dt": "2023-12-18T13:14:42.098875", "lvl": "debug", "msg": "Creating /var/lib/lava/dispatcher/tmp/34405/lava-overlay-2toou5i7/lava-34405/bin/lava-test-reference"}
- {"dt": "2023-12-18T13:14:42.100159", "lvl": "debug", "msg": "Creating /var/lib/lava/dispatcher/tmp/34405/lava-overlay-2toou5i7/lava-34405/bin/lava-test-runner"}
- {"dt": "2023-12-18T13:14:42.101339", "lvl": "debug", "msg": "Creating /var/lib/lava/dispatcher/tmp/34405/lava-overlay-2toou5i7/lava-34405/bin/lava-test-set"}
- {"dt": "2023-12-18T13:14:42.102527", "lvl": "debug", "msg": "Creating /var/lib/lava/dispatcher/tmp/34405/lava-overlay-2toou5i7/lava-34405/bin/lava-test-shell"}
- {"dt": "2023-12-18T13:14:42.103827", "lvl": "debug", "msg": "Updating /var/lib/lava/dispatcher/tmp/34405/lava-overlay-2toou5i7/lava-34405/bin/lava-install-packages (oe)"}
- {"dt": "2023-12-18T13:14:42.105251", "lvl": "debug", "msg": "Updating /var/lib/lava/dispatcher/tmp/34405/lava-overlay-2toou5i7/lava-34405/bin/lava-installed-packages (oe)"}
- {"dt": "2023-12-18T13:14:42.106505", "lvl": "debug", "msg": "Creating /var/lib/lava/dispatcher/tmp/34405/lava-overlay-2toou5i7/lava-34405/environment"}
- {"dt": "2023-12-18T13:14:42.107643", "lvl": "debug", "msg": "LAVA metadata"}
- {"dt": "2023-12-18T13:14:42.108289", "lvl": "debug", "msg": "- LAVA_JOB_ID=34405"}
- {"dt": "2023-12-18T13:14:42.108784", "lvl": "debug", "msg": "- LAVA_DISPATCHER_IP=192.168.66.1"}
- {"dt": "2023-12-18T13:14:42.109617", "lvl": "debug", "msg": "start: 1.5.2.1 ssh-authorize (timeout 00:09:54) [common]"}
- {"dt": "2023-12-18T13:14:42.111896", "lvl": "debug", "msg": "end: 1.5.2.1 ssh-authorize (duration 00:00:00) [common]"}
- {"dt": "2023-12-18T13:14:42.112748", "lvl": "debug", "msg": "start: 1.5.2.2 lava-vland-overlay (timeout 00:09:54) [common]"}
- {"dt": "2023-12-18T13:14:42.113270", "lvl": "debug", "msg": "skipped lava-vland-overlay"}
- {"dt": "2023-12-18T13:14:42.113828", "lvl": "debug", "msg": "end: 1.5.2.2 lava-vland-overlay (duration 00:00:00) [common]"}
- {"dt": "2023-12-18T13:14:42.114466", "lvl": "debug", "msg": "start: 1.5.2.3 lava-multinode-overlay (timeout 00:09:54) [common]"}
- {"dt": "2023-12-18T13:14:42.114963", "lvl": "debug", "msg": "skipped lava-multinode-overlay"}
- {"dt": "2023-12-18T13:14:42.115587", "lvl": "debug", "msg": "end: 1.5.2.3 lava-multinode-overlay (duration 00:00:00) [common]"}
- {"dt": "2023-12-18T13:14:42.116212", "lvl": "debug", "msg": "start: 1.5.2.4 test-definition (timeout 00:09:54) [common]"}
- {"dt": "2023-12-18T13:14:42.116832", "lvl": "info", "msg": "Loading test definitions"}
- {"dt": "2023-12-18T13:14:42.117602", "lvl": "debug", "msg": "start: 1.5.2.4.1 inline-repo-action (timeout 00:09:54) [common]"}
- {"dt": "2023-12-18T13:14:42.118247", "lvl": "debug", "msg": "Using /lava-34405 at stage 0"}
- {"dt": "2023-12-18T13:14:42.121103", "lvl": "debug", "msg": "uuid=34405_1.5.2.4.1 testdef=None"}
- {"dt": "2023-12-18T13:14:42.121929", "lvl": "debug", "msg": "end: 1.5.2.4.1 inline-repo-action (duration 00:00:00) [common]"}
- {"dt": "2023-12-18T13:14:42.122633", "lvl": "debug", "msg": "start: 1.5.2.4.2 test-overlay (timeout 00:09:54) [common]"}
- {"dt": "2023-12-18T13:14:42.127325", "lvl": "debug", "msg": "end: 1.5.2.4.2 test-overlay (duration 00:00:00) [common]"}
- {"dt": "2023-12-18T13:14:42.127980", "lvl": "results", "msg": {"case": "test-overlay", "definition": "lava", "duration": "0.00", "extra": {"from": "inline", "name": "dmesg", "path": "inline/dmesg.yaml", "uuid": "34405_1.5.2.4.1"}, "level": "1.5.2.4.2", "namespace": "common", "result": "pass"}}
- {"dt": "2023-12-18T13:14:42.129317", "lvl": "debug", "msg": "start: 1.5.2.4.3 test-install-overlay (timeout 00:09:54) [common]"}
- {"dt": "2023-12-18T13:14:42.135471", "lvl": "debug", "msg": "end: 1.5.2.4.3 test-install-overlay (duration 00:00:00) [common]"}
- {"dt": "2023-12-18T13:14:42.136154", "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": "34405_1.5.2.4.1", "uuid": "34405_1.5.2.4.1"}, "level": "1.5.2.4.3", "namespace": "common", "result": "pass"}}
- {"dt": "2023-12-18T13:14:42.137521", "lvl": "debug", "msg": "start: 1.5.2.4.4 test-runscript-overlay (timeout 00:09:54) [common]"}
- {"dt": "2023-12-18T13:14:42.143528", "lvl": "debug", "msg": "runner path: /var/lib/lava/dispatcher/tmp/34405/lava-overlay-2toou5i7/lava-34405/0/tests/0_dmesg test_uuid 34405_1.5.2.4.1"}
- {"dt": "2023-12-18T13:14:42.144995", "lvl": "debug", "msg": "end: 1.5.2.4.4 test-runscript-overlay (duration 00:00:00) [common]"}
- {"dt": "2023-12-18T13:14:42.145688", "lvl": "results", "msg": {"case": "test-runscript-overlay", "definition": "lava", "duration": "0.01", "extra": {"filename": "/var/lib/lava/dispatcher/tmp/34405/lava-overlay-2toou5i7/lava-34405/0/tests/0_dmesg/run.sh", "from": "inline", "name": "dmesg", "path": "inline/dmesg.yaml", "uuid": "34405_1.5.2.4.1"}, "level": "1.5.2.4.4", "namespace": "common", "result": "pass"}}
- {"dt": "2023-12-18T13:14:42.147042", "lvl": "debug", "msg": "start: 1.5.2.4.5 inline-repo-action (timeout 00:09:54) [common]"}
- {"dt": "2023-12-18T13:14:42.147668", "lvl": "debug", "msg": "Using /lava-34405 at stage 1"}
- {"dt": "2023-12-18T13:14:42.150337", "lvl": "debug", "msg": "uuid=34405_1.5.2.4.5 testdef=None"}
- {"dt": "2023-12-18T13:14:42.151130", "lvl": "debug", "msg": "end: 1.5.2.4.5 inline-repo-action (duration 00:00:00) [common]"}
- {"dt": "2023-12-18T13:14:42.151860", "lvl": "debug", "msg": "start: 1.5.2.4.6 test-overlay (timeout 00:09:54) [common]"}
- {"dt": "2023-12-18T13:14:42.157049", "lvl": "debug", "msg": "end: 1.5.2.4.6 test-overlay (duration 00:00:00) [common]"}
- {"dt": "2023-12-18T13:14:42.157696", "lvl": "results", "msg": {"case": "test-overlay", "definition": "lava", "duration": "0.01", "extra": {"from": "inline", "name": "bootrr", "path": "inline/bootrr.yaml", "uuid": "34405_1.5.2.4.5"}, "level": "1.5.2.4.6", "namespace": "common", "result": "pass"}}
- {"dt": "2023-12-18T13:14:42.159021", "lvl": "debug", "msg": "start: 1.5.2.4.7 test-install-overlay (timeout 00:09:54) [common]"}
- {"dt": "2023-12-18T13:14:42.165221", "lvl": "debug", "msg": "end: 1.5.2.4.7 test-install-overlay (duration 00:00:00) [common]"}
- {"dt": "2023-12-18T13:14:42.165898", "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": "34405_1.5.2.4.5", "uuid": "34405_1.5.2.4.5"}, "level": "1.5.2.4.7", "namespace": "common", "result": "pass"}}
- {"dt": "2023-12-18T13:14:42.167303", "lvl": "debug", "msg": "start: 1.5.2.4.8 test-runscript-overlay (timeout 00:09:54) [common]"}
- {"dt": "2023-12-18T13:14:42.173317", "lvl": "debug", "msg": "runner path: /var/lib/lava/dispatcher/tmp/34405/lava-overlay-2toou5i7/lava-34405/1/tests/1_bootrr test_uuid 34405_1.5.2.4.5"}
- {"dt": "2023-12-18T13:14:42.174714", "lvl": "debug", "msg": "end: 1.5.2.4.8 test-runscript-overlay (duration 00:00:00) [common]"}
- {"dt": "2023-12-18T13:14:42.175452", "lvl": "results", "msg": {"case": "test-runscript-overlay", "definition": "lava", "duration": "0.01", "extra": {"filename": "/var/lib/lava/dispatcher/tmp/34405/lava-overlay-2toou5i7/lava-34405/1/tests/1_bootrr/run.sh", "from": "inline", "name": "bootrr", "path": "inline/bootrr.yaml", "uuid": "34405_1.5.2.4.5"}, "level": "1.5.2.4.8", "namespace": "common", "result": "pass"}}
- {"dt": "2023-12-18T13:14:42.176650", "lvl": "info", "msg": "Creating lava-test-runner.conf files"}
- {"dt": "2023-12-18T13:14:42.177122", "lvl": "debug", "msg": "Using lava-test-runner path: /var/lib/lava/dispatcher/tmp/34405/lava-overlay-2toou5i7/lava-34405/0 for stage 0"}
- {"dt": "2023-12-18T13:14:42.177920", "lvl": "debug", "msg": "- 0_dmesg"}
- {"dt": "2023-12-18T13:14:42.178650", "lvl": "debug", "msg": "Using lava-test-runner path: /var/lib/lava/dispatcher/tmp/34405/lava-overlay-2toou5i7/lava-34405/1 for stage 1"}
- {"dt": "2023-12-18T13:14:42.179551", "lvl": "debug", "msg": "- 1_bootrr"}
- {"dt": "2023-12-18T13:14:42.180441", "lvl": "debug", "msg": "end: 1.5.2.4 test-definition (duration 00:00:00) [common]"}
- {"dt": "2023-12-18T13:14:42.181163", "lvl": "debug", "msg": "start: 1.5.2.5 compress-overlay (timeout 00:09:54) [common]"}
- {"dt": "2023-12-18T13:14:42.240130", "lvl": "debug", "msg": "end: 1.5.2.5 compress-overlay (duration 00:00:00) [common]"}
- {"dt": "2023-12-18T13:14:42.241026", "lvl": "debug", "msg": "start: 1.5.2.6 persistent-nfs-overlay (timeout 00:09:54) [common]"}
- {"dt": "2023-12-18T13:14:42.241671", "lvl": "debug", "msg": "end: 1.5.2.6 persistent-nfs-overlay (duration 00:00:00) [common]"}
- {"dt": "2023-12-18T13:14:42.242294", "lvl": "debug", "msg": "end: 1.5.2 lava-overlay (duration 00:00:00) [common]"}
- {"dt": "2023-12-18T13:14:42.242917", "lvl": "debug", "msg": "start: 1.5.3 extract-overlay-ramdisk (timeout 00:09:54) [common]"}
- {"dt": "2023-12-18T13:14:43.838819", "lvl": "debug", "msg": "end: 1.5.3 extract-overlay-ramdisk (duration 00:00:02) [common]"}
- {"dt": "2023-12-18T13:14:43.842869", "lvl": "debug", "msg": "start: 1.5.4 extract-modules (timeout 00:09:52) [common]"}
- {"dt": "2023-12-18T13:14:43.844246", "lvl": "info", "msg": "extracting modules file /var/lib/lava/dispatcher/tmp/34405/tftp-deploy-h2kejrfm/modules/modules.tar to /var/lib/lava/dispatcher/tmp/34405/extract-overlay-ramdisk-qqlfeonr/ramdisk"}
- {"dt": "2023-12-18T13:14:44.232789", "lvl": "debug", "msg": "end: 1.5.4 extract-modules (duration 00:00:00) [common]"}
- {"dt": "2023-12-18T13:14:44.233743", "lvl": "debug", "msg": "start: 1.5.5 apply-overlay-tftp (timeout 00:09:52) [common]"}
- {"dt": "2023-12-18T13:14:44.234380", "lvl": "info", "msg": "[common] Applying overlay /var/lib/lava/dispatcher/tmp/34405/compress-overlay-xufrso0v/overlay-1.5.2.5.tar.gz to ramdisk"}
- {"dt": "2023-12-18T13:14:44.234889", "lvl": "debug", "msg": "[common] Applying overlay /var/lib/lava/dispatcher/tmp/34405/compress-overlay-xufrso0v/overlay-1.5.2.5.tar.gz to directory /var/lib/lava/dispatcher/tmp/34405/extract-overlay-ramdisk-qqlfeonr/ramdisk"}
- {"dt": "2023-12-18T13:14:44.312515", "lvl": "debug", "msg": "end: 1.5.5 apply-overlay-tftp (duration 00:00:00) [common]"}
- {"dt": "2023-12-18T13:14:44.313422", "lvl": "debug", "msg": "start: 1.5.6 prepare-kernel (timeout 00:09:52) [common]"}
- {"dt": "2023-12-18T13:14:44.314109", "lvl": "debug", "msg": "start: 1.5.6.1 uboot-prepare-kernel (timeout 00:09:52) [common]"}
- {"dt": "2023-12-18T13:14:44.314790", "lvl": "debug", "msg": "end: 1.5.6.1 uboot-prepare-kernel (duration 00:00:00) [common]"}
- {"dt": "2023-12-18T13:14:44.315490", "lvl": "debug", "msg": "end: 1.5.6 prepare-kernel (duration 00:00:00) [common]"}
- {"dt": "2023-12-18T13:14:44.316136", "lvl": "debug", "msg": "start: 1.5.7 configure-preseed-file (timeout 00:09:52) [common]"}
- {"dt": "2023-12-18T13:14:44.316759", "lvl": "debug", "msg": "end: 1.5.7 configure-preseed-file (duration 00:00:00) [common]"}
- {"dt": "2023-12-18T13:14:44.317393", "lvl": "debug", "msg": "start: 1.5.8 compress-ramdisk (timeout 00:09:52) [common]"}
- {"dt": "2023-12-18T13:14:44.317944", "lvl": "info", "msg": "Building ramdisk /var/lib/lava/dispatcher/tmp/34405/extract-overlay-ramdisk-qqlfeonr/ramdisk.cpio containing /var/lib/lava/dispatcher/tmp/34405/extract-overlay-ramdisk-qqlfeonr/ramdisk"}
- {"dt": "2023-12-18T13:14:46.505248", "lvl": "debug", "msg": ">> 86851 blocks\n"}
- {"dt": "2023-12-18T13:14:51.878174", "lvl": "debug", "msg": "Adding RAMdisk u-boot header."}
- {"dt": "2023-12-18T13:14:51.880640", "lvl": "debug", "msg": "mkimage -A riscv -T ramdisk -C none -d /var/lib/lava/dispatcher/tmp/34405/extract-overlay-ramdisk-qqlfeonr/ramdisk.cpio.gz /var/lib/lava/dispatcher/tmp/34405/extract-overlay-ramdisk-qqlfeonr/ramdisk.cpio.gz.uboot"}
- {"dt": "2023-12-18T13:14:52.034600", "lvl": "debug", "msg": "output: Image Name:   "}
- {"dt": "2023-12-18T13:14:52.039050", "lvl": "debug", "msg": "output: Created:      Mon Dec 18 13:14:51 2023"}
- {"dt": "2023-12-18T13:14:52.040357", "lvl": "debug", "msg": "output: Image Type:   RISC-V Linux RAMDisk Image (uncompressed)"}
- {"dt": "2023-12-18T13:14:52.041653", "lvl": "debug", "msg": "output: Data Size:    13643996 Bytes = 13324.21 KiB = 13.01 MiB"}
- {"dt": "2023-12-18T13:14:52.042925", "lvl": "debug", "msg": "output: Load Address: 00000000"}
- {"dt": "2023-12-18T13:14:52.044262", "lvl": "debug", "msg": "output: Entry Point:  00000000"}
- {"dt": "2023-12-18T13:14:52.045536", "lvl": "debug", "msg": "output: "}
- {"dt": "2023-12-18T13:14:52.047467", "lvl": "debug", "msg": "rename /var/lib/lava/dispatcher/tmp/34405/extract-overlay-ramdisk-qqlfeonr/ramdisk.cpio.gz.uboot to /var/lib/lava/dispatcher/tmp/34405/tftp-deploy-h2kejrfm/ramdisk/ramdisk.cpio.gz.uboot"}
- {"dt": "2023-12-18T13:14:52.048855", "lvl": "debug", "msg": "end: 1.5.8 compress-ramdisk (duration 00:00:08) [common]"}
- {"dt": "2023-12-18T13:14:52.049843", "lvl": "debug", "msg": "end: 1.5 prepare-tftp-overlay (duration 00:00:10) [common]"}
- {"dt": "2023-12-18T13:14:52.050731", "lvl": "debug", "msg": "start: 1.6 lxc-create-udev-rule-action (timeout 00:09:44) [common]"}
- {"dt": "2023-12-18T13:14:52.051492", "lvl": "debug", "msg": "No LXC device requested"}
- {"dt": "2023-12-18T13:14:52.052283", "lvl": "debug", "msg": "end: 1.6 lxc-create-udev-rule-action (duration 00:00:00) [common]"}
- {"dt": "2023-12-18T13:14:52.053095", "lvl": "debug", "msg": "start: 1.7 deploy-device-env (timeout 00:09:44) [common]"}
- {"dt": "2023-12-18T13:14:52.053869", "lvl": "debug", "msg": "end: 1.7 deploy-device-env (duration 00:00:00) [common]"}
- {"dt": "2023-12-18T13:14:52.054514", "lvl": "debug", "msg": "Checking files for TFTP limit of 4294967296 bytes."}
- {"dt": "2023-12-18T13:14:52.058290", "lvl": "info", "msg": "end: 1 tftp-deploy (duration 00:00:16) [common]"}
- {"dt": "2023-12-18T13:14:52.059324", "lvl": "info", "msg": "start: 2 uboot-action (timeout 00:05:00) [common]"}
- {"dt": "2023-12-18T13:14:52.060240", "lvl": "debug", "msg": "start: 2.1 uboot-from-media (timeout 00:05:00) [common]"}
- {"dt": "2023-12-18T13:14:52.061018", "lvl": "debug", "msg": "end: 2.1 uboot-from-media (duration 00:00:00) [common]"}
- {"dt": "2023-12-18T13:14:52.061850", "lvl": "debug", "msg": "start: 2.2 bootloader-overlay (timeout 00:05:00) [common]"}
- {"dt": "2023-12-18T13:14:52.062945", "lvl": "debug", "msg": "substitutions:"}
- {"dt": "2023-12-18T13:14:52.065466", "lvl": "debug", "msg": "- {BOOTX}: booti 0x80200000 0x83500000 0x83000000"}
- {"dt": "2023-12-18T13:14:52.066100", "lvl": "debug", "msg": "- {DTB_ADDR}: 0x83000000"}
- {"dt": "2023-12-18T13:14:52.066659", "lvl": "debug", "msg": "- {DTB}: 34405/tftp-deploy-h2kejrfm/dtb/hifive-unmatched-a00.dtb"}
- {"dt": "2023-12-18T13:14:52.067252", "lvl": "debug", "msg": "- {INITRD}: 34405/tftp-deploy-h2kejrfm/ramdisk/ramdisk.cpio.gz.uboot"}
- {"dt": "2023-12-18T13:14:52.067826", "lvl": "debug", "msg": "- {KERNEL_ADDR}: 0x80200000"}
- {"dt": "2023-12-18T13:14:52.068363", "lvl": "debug", "msg": "- {KERNEL}: 34405/tftp-deploy-h2kejrfm/kernel/Image"}
- {"dt": "2023-12-18T13:14:52.068894", "lvl": "debug", "msg": "- {LAVA_MAC}: None"}
- {"dt": "2023-12-18T13:14:52.069414", "lvl": "debug", "msg": "- {PRESEED_CONFIG}: None"}
- {"dt": "2023-12-18T13:14:52.069930", "lvl": "debug", "msg": "- {PRESEED_LOCAL}: None"}
- {"dt": "2023-12-18T13:14:52.070444", "lvl": "debug", "msg": "- {RAMDISK_ADDR}: 0x83500000"}
- {"dt": "2023-12-18T13:14:52.070962", "lvl": "debug", "msg": "- {RAMDISK}: 34405/tftp-deploy-h2kejrfm/ramdisk/ramdisk.cpio.gz.uboot"}
- {"dt": "2023-12-18T13:14:52.071538", "lvl": "debug", "msg": "- {ROOT_PART}: None"}
- {"dt": "2023-12-18T13:14:52.072082", "lvl": "debug", "msg": "- {ROOT}: None"}
- {"dt": "2023-12-18T13:14:52.072606", "lvl": "debug", "msg": "- {SERVER_IP}: 192.168.66.1"}
- {"dt": "2023-12-18T13:14:52.073126", "lvl": "debug", "msg": "- {TEE_ADDR}: 0x83000000"}
- {"dt": "2023-12-18T13:14:52.073645", "lvl": "debug", "msg": "- {TEE}: None"}
- {"dt": "2023-12-18T13:14:52.074172", "lvl": "info", "msg": "Parsed boot commands:"}
- {"dt": "2023-12-18T13:14:52.074686", "lvl": "info", "msg": "- setenv autoload no"}
- {"dt": "2023-12-18T13:14:52.075244", "lvl": "info", "msg": "- setenv initrd_high 0xffffffffffffffff"}
- {"dt": "2023-12-18T13:14:52.075796", "lvl": "info", "msg": "- setenv fdt_high 0xffffffffffffffff"}
- {"dt": "2023-12-18T13:14:52.076331", "lvl": "info", "msg": "- dhcp"}
- {"dt": "2023-12-18T13:14:52.076854", "lvl": "info", "msg": "- setenv serverip 192.168.66.1"}
- {"dt": "2023-12-18T13:14:52.077374", "lvl": "info", "msg": "- tftp 0x80200000 34405/tftp-deploy-h2kejrfm/kernel/Image"}
- {"dt": "2023-12-18T13:14:52.077887", "lvl": "info", "msg": "- tftp 0x83500000 34405/tftp-deploy-h2kejrfm/ramdisk/ramdisk.cpio.gz.uboot"}
- {"dt": "2023-12-18T13:14:52.078436", "lvl": "info", "msg": "- setenv initrd_size ${filesize}"}
- {"dt": "2023-12-18T13:14:52.078962", "lvl": "info", "msg": "- tftp 0x83000000 34405/tftp-deploy-h2kejrfm/dtb/hifive-unmatched-a00.dtb"}
- {"dt": "2023-12-18T13:14:52.079564", "lvl": "info", "msg": "- setenv bootargs '115200 root=/dev/ram0 console_msg_format=syslog earlycon deferred_probe_timeout=60 ip=dhcp'"}
- {"dt": "2023-12-18T13:14:52.080137", "lvl": "info", "msg": "- booti 0x80200000 0x83500000 0x83000000"}
- {"dt": "2023-12-18T13:14:52.080836", "lvl": "debug", "msg": "end: 2.2 bootloader-overlay (duration 00:00:00) [common]"}
- {"dt": "2023-12-18T13:14:52.081501", "lvl": "results", "msg": {"case": "bootloader-overlay", "definition": "lava", "duration": "0.02", "extra": {"dtb_addr": "0x83000000", "kernel_addr": "0x80200000", "ramdisk_addr": "0x83500000", "tee_addr": "0x83000000"}, "level": "2.2", "namespace": "common", "result": "pass"}}
- {"dt": "2023-12-18T13:14:52.082958", "lvl": "debug", "msg": "start: 2.3 connect-device (timeout 00:05:00) [common]"}
- {"dt": "2023-12-18T13:14:52.083705", "lvl": "info", "msg": "[common] connect-device Connecting to device using 'telnet 127.0.0.1 63006'"}
- {"dt": "2023-12-18T13:14:55.215699", "lvl": "debug", "msg": "Setting prompt string to ['lava-test: # ']"}
- {"dt": "2023-12-18T13:14:55.217998", "lvl": "debug", "msg": "end: 2.3 connect-device (duration 00:00:03) [common]"}
- {"dt": "2023-12-18T13:14:55.219067", "lvl": "debug", "msg": "start: 2.4 uboot-commands (timeout 00:04:57) [common]"}
- {"dt": "2023-12-18T13:14:55.220338", "lvl": "debug", "msg": "start: 2.4.1 reset-device (timeout 00:04:57) [common]"}
- {"dt": "2023-12-18T13:14:55.221726", "lvl": "debug", "msg": "start: 2.4.1.1 pdu-reboot (timeout 00:04:57) [common]"}
- {"dt": "2023-12-18T13:14:55.223273", "lvl": "debug", "msg": "Calling: 'nice' 'upower.sh' '--atx' 'reset' '1'"}
- {"dt": "2023-12-18T13:14:59.094128", "lvl": "debug", "msg": ">> Accessing Gembird #0 USB device 015\r"}
- {"dt": "2023-12-18T13:14:59.099646", "lvl": "debug", "msg": ">> Switched outlet 1 off\r"}
- {"dt": "2023-12-18T13:15:02.306560", "lvl": "debug", "msg": ">> Accessing Gembird #0 USB device 015\r"}
- {"dt": "2023-12-18T13:15:02.308949", "lvl": "debug", "msg": ">> Switched outlet 1 on\r"}
- {"dt": "2023-12-18T13:15:04.451681", "lvl": "debug", "msg": ">> FTDI RELAY: power on\r"}
- {"dt": "2023-12-18T13:15:06.459665", "lvl": "debug", "msg": ">> FTDI RELAY: power off\r"}
- {"dt": "2023-12-18T13:15:06.496072", "lvl": "debug", "msg": "Returned 0 in 11 seconds"}
- {"dt": "2023-12-18T13:15:06.598542", "lvl": "debug", "msg": "end: 2.4.1.1 pdu-reboot (duration 00:00:11) [common]"}
- {"dt": "2023-12-18T13:15:06.599533", "lvl": "results", "msg": {"case": "pdu-reboot", "definition": "lava", "duration": "11.38", "extra": {"status": "success"}, "level": "2.4.1.1", "namespace": "common", "result": "pass"}}
- {"dt": "2023-12-18T13:15:06.601042", "lvl": "debug", "msg": "end: 2.4.1 reset-device (duration 00:00:11) [common]"}
- {"dt": "2023-12-18T13:15:06.602071", "lvl": "debug", "msg": "start: 2.4.2 bootloader-interrupt (timeout 00:04:45) [common]"}
- {"dt": "2023-12-18T13:15:06.602900", "lvl": "debug", "msg": "Setting prompt string to ['Hit any key to stop autoboot']"}
- {"dt": "2023-12-18T13:15:06.604205", "lvl": "debug", "msg": "bootloader-interrupt: Wait for prompt ['Hit any key to stop autoboot'] (timeout 00:05:00)"}
- {"dt": "2023-12-18T13:15:06.607634", "lvl": "target", "msg": "Trying 127.0.0.1..."}
- {"dt": "2023-12-18T13:15:06.608494", "lvl": "target", "msg": "Connected to 127.0.0.1."}
- {"dt": "2023-12-18T13:15:06.609283", "lvl": "target", "msg": "Escape character is '^]'."}
- {"dt": "2023-12-18T13:15:14.726377", "lvl": "target", "msg": "\uFFFD"}
- {"dt": "2023-12-18T13:15:14.741801", "lvl": "target", "msg": "U-Boot SPL 2023.07.02 (Jul 11 2023 - 15:20:44 +0000)"}
- {"dt": "2023-12-18T13:15:14.870292", "lvl": "target", "msg": "Trying to boot from MMC1"}
- {"dt": "2023-12-18T13:15:15.603728", "lvl": "target", "msg": ""}
- {"dt": "2023-12-18T13:15:15.604544", "lvl": "target", "msg": ""}
- {"dt": "2023-12-18T13:15:15.605251", "lvl": "target", "msg": "U-Boot 2023.07.02 (Jul 11 2023 - 15:20:44 +0000)"}
- {"dt": "2023-12-18T13:15:15.605950", "lvl": "target", "msg": ""}
- {"dt": "2023-12-18T13:15:15.607376", "lvl": "target", "msg": "CPU:   rv64imafdc"}
- {"dt": "2023-12-18T13:15:15.621792", "lvl": "target", "msg": "Model: SiFive HiFive Unmatched A00"}
- {"dt": "2023-12-18T13:15:15.622845", "lvl": "target", "msg": "DRAM:  16 GiB"}
- {"dt": "2023-12-18T13:15:15.670171", "lvl": "target", "msg": "Core:  28 devices, 19 uclasses, devicetree: separate"}
- {"dt": "2023-12-18T13:15:15.683942", "lvl": "target", "msg": "MMC:   spi@10050000:mmc@0: 0"}
- {"dt": "2023-12-18T13:15:15.687370", "lvl": "target", "msg": "Loading Environment from SPIFlash... SF: Detected is25wp256 with page size 256 Bytes, erase size 4 KiB, total 32 MiB"}
- {"dt": "2023-12-18T13:15:15.717970", "lvl": "target", "msg": "*** Warning - bad CRC, using default environment"}
- {"dt": "2023-12-18T13:15:15.719293", "lvl": "target", "msg": ""}
- {"dt": "2023-12-18T13:15:15.731953", "lvl": "target", "msg": "EEPROM: SiFive PCB EEPROM format v1"}
- {"dt": "2023-12-18T13:15:15.733895", "lvl": "target", "msg": "Product ID: 0002 (HiFive Unmatched)"}
- {"dt": "2023-12-18T13:15:15.735114", "lvl": "target", "msg": "PCB revision: 3"}
- {"dt": "2023-12-18T13:15:15.736338", "lvl": "target", "msg": "BOM revision: B"}
- {"dt": "2023-12-18T13:15:15.737443", "lvl": "target", "msg": "BOM variant: 0"}
- {"dt": "2023-12-18T13:15:15.747585", "lvl": "target", "msg": "Serial number: SF105SZ212500053"}
- {"dt": "2023-12-18T13:15:15.748323", "lvl": "target", "msg": "Ethernet MAC address: 70:b3:d5:92:fa:8d"}
- {"dt": "2023-12-18T13:15:15.748963", "lvl": "target", "msg": "CRC: 6508cedc"}
- {"dt": "2023-12-18T13:15:15.749583", "lvl": "target", "msg": "In:    serial@10010000"}
- {"dt": "2023-12-18T13:15:15.750185", "lvl": "target", "msg": "Out:   serial@10010000"}
- {"dt": "2023-12-18T13:15:15.751522", "lvl": "target", "msg": "Err:   serial@10010000"}
- {"dt": "2023-12-18T13:15:15.752334", "lvl": "target", "msg": "Model: SiFive HiFive Unmatched A00"}
- {"dt": "2023-12-18T13:15:15.763500", "lvl": "target", "msg": "Net:   eth0: ethernet@10090000"}
- {"dt": "2023-12-18T13:15:15.764378", "lvl": "target", "msg": "Working FDT set to ff72f7f0"}
- {"dt": "2023-12-18T13:15:15.767265", "lvl": "input", "msg": "\n"}
- {"dt": "2023-12-18T13:15:15.818883", "lvl": "target", "msg": "Hit any key to stop autoboot:  2 "}
- {"dt": "2023-12-18T13:15:15.821238", "lvl": "debug", "msg": "end: 2.4.2 bootloader-interrupt (duration 00:00:09) [common]"}
- {"dt": "2023-12-18T13:15:15.823394", "lvl": "debug", "msg": "start: 2.4.3 bootloader-commands (timeout 00:04:36) [common]"}
- {"dt": "2023-12-18T13:15:15.825201", "lvl": "debug", "msg": "Setting prompt string to ['=>']"}
- {"dt": "2023-12-18T13:15:15.827000", "lvl": "debug", "msg": "bootloader-commands: Wait for prompt ['=>'] (timeout 00:04:36)"}
- {"dt": "2023-12-18T13:15:15.847416", "lvl": "target", "msg": "\b\b\b 0 "}
- {"dt": "2023-12-18T13:15:15.848767", "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": "2023-12-18T13:15:15.849497", "lvl": "input", "msg": "setenv autoload no\n"}
- {"dt": "2023-12-18T13:15:15.951216", "lvl": "target", "msg": "=> setenv autoload no"}
- {"dt": "2023-12-18T13:15:15.952550", "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:36)"}
- {"dt": "2023-12-18T13:15:15.973976", "lvl": "target", "msg": "setenv autoload no"}
- {"dt": "2023-12-18T13:15:15.975662", "lvl": "input", "msg": "setenv initrd_high 0xffffffffffffffff\n"}
- {"dt": "2023-12-18T13:15:16.077865", "lvl": "target", "msg": "=> setenv initrd_high 0xffffffffffffffff"}
- {"dt": "2023-12-18T13:15:16.079742", "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:36)"}
- {"dt": "2023-12-18T13:15:16.086180", "lvl": "target", "msg": "setenv initrd_high 0xffffffffffffffff"}
- {"dt": "2023-12-18T13:15:16.087598", "lvl": "input", "msg": "setenv fdt_high 0xffffffffffffffff\n"}
- {"dt": "2023-12-18T13:15:16.189797", "lvl": "target", "msg": "=> setenv fdt_high 0xffffffffffffffff"}
- {"dt": "2023-12-18T13:15:16.191985", "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:36)"}
- {"dt": "2023-12-18T13:15:16.198226", "lvl": "target", "msg": "setenv fdt_high 0xffffffffffffffff"}
- {"dt": "2023-12-18T13:15:16.199870", "lvl": "input", "msg": "dhcp\n"}
- {"dt": "2023-12-18T13:15:16.301782", "lvl": "target", "msg": "=> dhcp"}
- {"dt": "2023-12-18T13:15:16.303196", "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:36)"}
- {"dt": "2023-12-18T13:15:16.310096", "lvl": "target", "msg": "dhcp"}
- {"dt": "2023-12-18T13:15:16.326021", "lvl": "target", "msg": "ethernet@10090000: PHY present at 0"}
- {"dt": "2023-12-18T13:15:16.327321", "lvl": "target", "msg": "ethernet@10090000: Starting autonegotiation..."}
- {"dt": "2023-12-18T13:15:18.611383", "lvl": "target", "msg": "ethernet@10090000: Autonegotiation complete"}
- {"dt": "2023-12-18T13:15:18.629733", "lvl": "target", "msg": "ethernet@10090000: link up, 100Mbps full-duplex (lpa: 0xcde1)"}
- {"dt": "2023-12-18T13:15:18.630691", "lvl": "target", "msg": "BOOTP broadcast 1"}
- {"dt": "2023-12-18T13:15:18.870018", "lvl": "target", "msg": "BOOTP broadcast 2"}
- {"dt": "2023-12-18T13:15:19.381869", "lvl": "target", "msg": "BOOTP broadcast 3"}
- {"dt": "2023-12-18T13:15:19.669863", "lvl": "target", "msg": "DHCP client bound to address 192.168.66.244 (1041 ms)"}
- {"dt": "2023-12-18T13:15:19.671213", "lvl": "input", "msg": "setenv serverip 192.168.66.1\n"}
- {"dt": "2023-12-18T13:15:19.773118", "lvl": "target", "msg": "=> setenv serverip 192.168.66.1"}
- {"dt": "2023-12-18T13:15:19.774437", "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": "2023-12-18T13:15:19.781681", "lvl": "target", "msg": "setenv serverip 192.168.66.1"}
- {"dt": "2023-12-18T13:15:19.782777", "lvl": "input", "msg": "tftp 0x80200000 34405/tftp-deploy-h2kejrfm/kernel/Image\n"}
- {"dt": "2023-12-18T13:15:19.884638", "lvl": "target", "msg": "=> tftp 0x80200000 34405/tftp-deploy-h2kejrfm/kernel/Image"}
- {"dt": "2023-12-18T13:15:19.886050", "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": "2023-12-18T13:15:19.893982", "lvl": "target", "msg": "tftp 0x80200000 34405/tftp-deploy-h2kejrfm/kernel/Image"}
- {"dt": "2023-12-18T13:15:19.895795", "lvl": "target", "msg": "ethernet@10090000: PHY present at 0"}
- {"dt": "2023-12-18T13:15:19.909837", "lvl": "target", "msg": "ethernet@10090000: Starting autonegotiation..."}
- {"dt": "2023-12-18T13:15:22.278018", "lvl": "target", "msg": "ethernet@10090000: Autonegotiation complete"}
- {"dt": "2023-12-18T13:15:22.291398", "lvl": "target", "msg": "ethernet@10090000: link up, 100Mbps full-duplex (lpa: 0xcde1)"}
- {"dt": "2023-12-18T13:15:22.294892", "lvl": "target", "msg": "Using ethernet@10090000 device"}
- {"dt": "2023-12-18T13:15:22.307818", "lvl": "target", "msg": "TFTP from server 192.168.66.1; our IP address is 192.168.66.244"}
- {"dt": "2023-12-18T13:15:22.308985", "lvl": "target", "msg": "Filename '34405/tftp-deploy-h2kejrfm/kernel/Image'."}
- {"dt": "2023-12-18T13:15:22.311234", "lvl": "target", "msg": "Load address: 0x80200000"}
- {"dt": "2023-12-18T13:15:22.869692", "lvl": "target", "msg": "Loading: *\b#################################################################"}
- {"dt": "2023-12-18T13:15:23.429400", "lvl": "target", "msg": "\t #################################################################"}
- {"dt": "2023-12-18T13:15:24.005502", "lvl": "target", "msg": "\t #################################################################"}
- {"dt": "2023-12-18T13:15:24.565636", "lvl": "target", "msg": "\t #################################################################"}
- {"dt": "2023-12-18T13:15:25.141549", "lvl": "target", "msg": "\t #################################################################"}
- {"dt": "2023-12-18T13:15:25.717591", "lvl": "target", "msg": "\t #################################################################"}
- {"dt": "2023-12-18T13:15:26.293519", "lvl": "target", "msg": "\t #################################################################"}
- {"dt": "2023-12-18T13:15:26.869449", "lvl": "target", "msg": "\t #################################################################"}
- {"dt": "2023-12-18T13:15:27.445425", "lvl": "target", "msg": "\t #################################################################"}
- {"dt": "2023-12-18T13:15:28.021774", "lvl": "target", "msg": "\t #################################################################"}
- {"dt": "2023-12-18T13:15:28.597539", "lvl": "target", "msg": "\t #################################################################"}
- {"dt": "2023-12-18T13:15:29.157698", "lvl": "target", "msg": "\t #################################################################"}
- {"dt": "2023-12-18T13:15:29.733434", "lvl": "target", "msg": "\t #################################################################"}
- {"dt": "2023-12-18T13:15:30.309603", "lvl": "target", "msg": "\t #################################################################"}
- {"dt": "2023-12-18T13:15:30.885356", "lvl": "target", "msg": "\t #################################################################"}
- {"dt": "2023-12-18T13:15:31.445469", "lvl": "target", "msg": "\t #################################################################"}
- {"dt": "2023-12-18T13:15:32.021229", "lvl": "target", "msg": "\t #################################################################"}
- {"dt": "2023-12-18T13:15:32.598350", "lvl": "target", "msg": "\t #################################################################"}
- {"dt": "2023-12-18T13:15:33.157398", "lvl": "target", "msg": "\t #################################################################"}
- {"dt": "2023-12-18T13:15:33.733493", "lvl": "target", "msg": "\t #################################################################"}
- {"dt": "2023-12-18T13:15:34.195091", "lvl": "target", "msg": "\t ####################################################"}
- {"dt": "2023-12-18T13:15:34.197131", "lvl": "target", "msg": "\t 1.6 MiB/s"}
- {"dt": "2023-12-18T13:15:34.198857", "lvl": "target", "msg": "done"}
- {"dt": "2023-12-18T13:15:34.201586", "lvl": "target", "msg": "Bytes transferred = 19845120 (12ed000 hex)"}
- {"dt": "2023-12-18T13:15:34.204121", "lvl": "input", "msg": "tftp 0x83500000 34405/tftp-deploy-h2kejrfm/ramdisk/ramdisk.cpio.gz.uboot\n"}
- {"dt": "2023-12-18T13:15:34.305824", "lvl": "target", "msg": "=> tftp 0x83500000 34405/tftp-deploy-h2kejrfm/ramdisk/ramdisk.cpio.gz.uboot"}
- {"dt": "2023-12-18T13:15:34.307112", "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:18)"}
- {"dt": "2023-12-18T13:15:34.322869", "lvl": "target", "msg": "tftp 0x83500000 34405/tftp-deploy-h2kejrfm/ramdisk/ramdisk.cpio.gz.uboot"}
- {"dt": "2023-12-18T13:15:34.324003", "lvl": "target", "msg": "ethernet@10090000: PHY present at 0"}
- {"dt": "2023-12-18T13:15:34.326573", "lvl": "target", "msg": "ethernet@10090000: Starting autonegotiation..."}
- {"dt": "2023-12-18T13:15:36.405238", "lvl": "target", "msg": "ethernet@10090000: Autonegotiation complete"}
- {"dt": "2023-12-18T13:15:36.418967", "lvl": "target", "msg": "ethernet@10090000: link up, 100Mbps full-duplex (lpa: 0xcde1)"}
- {"dt": "2023-12-18T13:15:36.420930", "lvl": "target", "msg": "Using ethernet@10090000 device"}
- {"dt": "2023-12-18T13:15:36.423513", "lvl": "target", "msg": "TFTP from server 192.168.66.1; our IP address is 192.168.66.244"}
- {"dt": "2023-12-18T13:15:36.434967", "lvl": "target", "msg": "Filename '34405/tftp-deploy-h2kejrfm/ramdisk/ramdisk.cpio.gz.uboot'."}
- {"dt": "2023-12-18T13:15:36.438409", "lvl": "target", "msg": "Load address: 0x83500000"}
- {"dt": "2023-12-18T13:15:37.013093", "lvl": "target", "msg": "Loading: *\b#################################################################"}
- {"dt": "2023-12-18T13:15:37.589824", "lvl": "target", "msg": "\t #################################################################"}
- {"dt": "2023-12-18T13:15:38.165243", "lvl": "target", "msg": "\t #################################################################"}
- {"dt": "2023-12-18T13:15:38.740815", "lvl": "target", "msg": "\t #################################################################"}
- {"dt": "2023-12-18T13:15:39.316817", "lvl": "target", "msg": "\t #################################################################"}
- {"dt": "2023-12-18T13:15:39.876772", "lvl": "target", "msg": "\t #################################################################"}
- {"dt": "2023-12-18T13:15:40.453027", "lvl": "target", "msg": "\t #################################################################"}
- {"dt": "2023-12-18T13:15:41.013117", "lvl": "target", "msg": "\t #################################################################"}
- {"dt": "2023-12-18T13:15:41.572754", "lvl": "target", "msg": "\t #################################################################"}
- {"dt": "2023-12-18T13:15:42.133085", "lvl": "target", "msg": "\t #################################################################"}
- {"dt": "2023-12-18T13:15:42.709129", "lvl": "target", "msg": "\t #################################################################"}
- {"dt": "2023-12-18T13:15:43.284725", "lvl": "target", "msg": "\t #################################################################"}
- {"dt": "2023-12-18T13:15:43.844653", "lvl": "target", "msg": "\t #################################################################"}
- {"dt": "2023-12-18T13:15:44.420879", "lvl": "target", "msg": "\t #################################################################"}
- {"dt": "2023-12-18T13:15:44.594574", "lvl": "target", "msg": "\t ####################"}
- {"dt": "2023-12-18T13:15:44.596147", "lvl": "target", "msg": "\t 1.6 MiB/s"}
- {"dt": "2023-12-18T13:15:44.597462", "lvl": "target", "msg": "done"}
- {"dt": "2023-12-18T13:15:44.599450", "lvl": "target", "msg": "Bytes transferred = 13644060 (d0311c hex)"}
- {"dt": "2023-12-18T13:15:44.601158", "lvl": "input", "msg": "setenv initrd_size ${filesize}\n"}
- {"dt": "2023-12-18T13:15:44.703093", "lvl": "target", "msg": "=> setenv initrd_size ${filesize}"}
- {"dt": "2023-12-18T13:15:44.705438", "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:07)"}
- {"dt": "2023-12-18T13:15:44.725023", "lvl": "target", "msg": "setenv initrd_size ${filesize}"}
- {"dt": "2023-12-18T13:15:44.727444", "lvl": "input", "msg": "tftp 0x83000000 34405/tftp-deploy-h2kejrfm/dtb/hifive-unmatched-a00.dtb\n"}
- {"dt": "2023-12-18T13:15:44.829742", "lvl": "target", "msg": "=> tftp 0x83000000 34405/tftp-deploy-h2kejrfm/dtb/hifive-unmatched-a00.dtb"}
- {"dt": "2023-12-18T13:15:44.832031", "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:07)"}
- {"dt": "2023-12-18T13:15:44.836865", "lvl": "target", "msg": "tftp 0x83000000 34405/tftp-deploy-h2kejrfm/dtb/hifive-unmatched-a00.dtb"}
- {"dt": "2023-12-18T13:15:44.850338", "lvl": "target", "msg": "ethernet@10090000: PHY present at 0"}
- {"dt": "2023-12-18T13:15:44.853915", "lvl": "target", "msg": "ethernet@10090000: Starting autonegotiation..."}
- {"dt": "2023-12-18T13:15:47.109053", "lvl": "target", "msg": "ethernet@10090000: Autonegotiation complete"}
- {"dt": "2023-12-18T13:15:47.122546", "lvl": "target", "msg": "ethernet@10090000: link up, 100Mbps full-duplex (lpa: 0xcde1)"}
- {"dt": "2023-12-18T13:15:47.125253", "lvl": "target", "msg": "Using ethernet@10090000 device"}
- {"dt": "2023-12-18T13:15:47.127440", "lvl": "target", "msg": "TFTP from server 192.168.66.1; our IP address is 192.168.66.244"}
- {"dt": "2023-12-18T13:15:47.138641", "lvl": "target", "msg": "Filename '34405/tftp-deploy-h2kejrfm/dtb/hifive-unmatched-a00.dtb'."}
- {"dt": "2023-12-18T13:15:47.142676", "lvl": "target", "msg": "Load address: 0x83000000"}
- {"dt": "2023-12-18T13:15:47.154500", "lvl": "target", "msg": "Loading: *\b#"}
- {"dt": "2023-12-18T13:15:47.155623", "lvl": "target", "msg": "\t 746.1 KiB/s"}
- {"dt": "2023-12-18T13:15:47.156849", "lvl": "target", "msg": "done"}
- {"dt": "2023-12-18T13:15:47.158058", "lvl": "target", "msg": "Bytes transferred = 10707 (29d3 hex)"}
- {"dt": "2023-12-18T13:15:47.159839", "lvl": "input", "msg": "setenv bootargs '115200 root=/dev/ram0 console_msg_format=syslog earlycon deferred_probe_timeout=60 ip=dhcp'\n"}
- {"dt": "2023-12-18T13:15:47.262071", "lvl": "target", "msg": "=> setenv bootargs '115200 root=/dev/ram0 console_msg_format=syslog earlycon deferred_probe_timeout=60 ip=dhcp'"}
- {"dt": "2023-12-18T13:15:47.264360", "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:05)"}
- {"dt": "2023-12-18T13:15:47.268755", "lvl": "target", "msg": "setenv bootargs '115200 root=/dev/ram0 console_msg_format=syslog earlycon deferred_probe_timeout=60 ip=dhcp'"}
- {"dt": "2023-12-18T13:15:47.271291", "lvl": "input", "msg": "booti 0x80200000 0x83500000 0x83000000\n"}
- {"dt": "2023-12-18T13:15:47.374060", "lvl": "target", "msg": "=> booti 0x80200000 0x83500000 0x83000000"}
- {"dt": "2023-12-18T13:15:47.374930", "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": "2023-12-18T13:15:47.375674", "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:05)"}
- {"dt": "2023-12-18T13:15:47.380836", "lvl": "target", "msg": "booti 0x80200000 0x83500000 0x83000000"}
- {"dt": "2023-12-18T13:15:47.394500", "lvl": "target", "msg": "## Loading init Ramdisk from Legacy Image at 83500000 ..."}
- {"dt": "2023-12-18T13:15:47.396117", "lvl": "target", "msg": "   Image Name:   "}
- {"dt": "2023-12-18T13:15:47.398256", "lvl": "target", "msg": "   Image Type:   RISC-V Linux RAMDisk Image (uncompressed)"}
- {"dt": "2023-12-18T13:15:47.400206", "lvl": "target", "msg": "   Data Size:    13643996 Bytes = 13 MiB"}
- {"dt": "2023-12-18T13:15:47.412901", "lvl": "target", "msg": "   Load Address: 00000000"}
- {"dt": "2023-12-18T13:15:47.414548", "lvl": "target", "msg": "   Entry Point:  00000000"}
- {"dt": "2023-12-18T13:15:47.524901", "lvl": "target", "msg": "   Verifying Checksum ... OK"}
- {"dt": "2023-12-18T13:15:47.538509", "lvl": "target", "msg": "## Flattened Device Tree blob at 83000000"}
- {"dt": "2023-12-18T13:15:47.541077", "lvl": "target", "msg": "   Booting using the fdt blob at 0x83000000"}
- {"dt": "2023-12-18T13:15:47.542639", "lvl": "target", "msg": "Working FDT set to 83000000"}
- {"dt": "2023-12-18T13:15:47.544543", "lvl": "target", "msg": "   Using Device Tree in place at 0000000083000000, end 00000000830059d2"}
- {"dt": "2023-12-18T13:15:47.554533", "lvl": "target", "msg": "Working FDT set to 83000000"}
- {"dt": "2023-12-18T13:15:47.555954", "lvl": "target", "msg": ""}
- {"dt": "2023-12-18T13:15:47.556733", "lvl": "target", "msg": "Starting kernel ..."}
- {"dt": "2023-12-18T13:15:47.557482", "lvl": "target", "msg": ""}
- {"dt": "2023-12-18T13:15:47.558860", "lvl": "debug", "msg": "end: 2.4.3 bootloader-commands (duration 00:00:32) [common]"}
- {"dt": "2023-12-18T13:15:47.560034", "lvl": "debug", "msg": "start: 2.4.4 auto-login-action (timeout 00:04:04) [common]"}
- {"dt": "2023-12-18T13:15:47.560986", "lvl": "debug", "msg": "Setting prompt string to ['Linux version [0-9]']"}
- {"dt": "2023-12-18T13:15:47.561930", "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": "2023-12-18T13:15:47.562882", "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": "2023-12-18T13:15:47.565690", "lvl": "debug", "msg": "start: 2.4.4.1 login-action (timeout 00:04:04) [common]"}
- {"dt": "2023-12-18T13:15:47.566665", "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": "2023-12-18T13:15:47.567673", "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": "2023-12-18T13:15:47.568328", "lvl": "debug", "msg": "Using line separator: #'\\n'#"}
- {"dt": "2023-12-18T13:15:47.568895", "lvl": "debug", "msg": "No login prompt set."}
- {"dt": "2023-12-18T13:15:47.569469", "lvl": "info", "msg": "Parsing kernel messages"}
- {"dt": "2023-12-18T13:15:47.570018", "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": "2023-12-18T13:15:47.571008", "lvl": "debug", "msg": "[login-action] Waiting for messages, (timeout 00:04:04)"}
- {"dt": "2023-12-18T13:15:47.575117", "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": "2023-12-18T13:15:47.586375", "lvl": "target", "msg": "[    0.000000] OF: fdt: Ignoring memory range 0x80000000 - 0x80200000"}
- {"dt": "2023-12-18T13:15:47.587472", "lvl": "target", "msg": "[    0.000000] Machine model: SiFive HiFive Unmatched A00"}
- {"dt": "2023-12-18T13:15:47.590337", "lvl": "target", "msg": "[    0.000000] earlycon: sifive0 at MMIO 0x0000000010010000 (options '')"}
- {"dt": "2023-12-18T13:15:47.602401", "lvl": "target", "msg": "[    0.000000] printk: bootconsole [sifive0] enabled"}
- {"dt": "2023-12-18T13:15:47.603389", "lvl": "target", "msg": "[    0.000000] efi: UEFI not found."}
- {"dt": "2023-12-18T13:15:47.604913", "lvl": "target", "msg": "[    0.000000] Zone ranges:"}
- {"dt": "2023-12-18T13:15:47.618380", "lvl": "target", "msg": "[    0.000000]   DMA32    [mem 0x0000000080200000-0x00000000ffffffff]"}
- {"dt": "2023-12-18T13:15:47.620036", "lvl": "target", "msg": "[    0.000000]   Normal   [mem 0x0000000100000000-0x000000047fffffff]"}
- {"dt": "2023-12-18T13:15:47.621077", "lvl": "target", "msg": "[    0.000000] Movable zone start for each node"}
- {"dt": "2023-12-18T13:15:47.622412", "lvl": "target", "msg": "[    0.000000] Early memory node ranges"}
- {"dt": "2023-12-18T13:15:47.634475", "lvl": "target", "msg": "[    0.000000]   node   0: [mem 0x0000000080200000-0x000000047fffffff]"}
- {"dt": "2023-12-18T13:15:47.638459", "lvl": "target", "msg": "[    0.000000] Initmem setup node 0 [mem 0x0000000080200000-0x000000047fffffff]"}
- {"dt": "2023-12-18T13:15:49.602617", "lvl": "target", "msg": "[    0.000000] SBI specification v1.0 detected"}
- {"dt": "2023-12-18T13:15:49.607086", "lvl": "target", "msg": "[    0.000000] SBI implementation ID=0x1 Version=0x10002"}
- {"dt": "2023-12-18T13:15:49.609016", "lvl": "target", "msg": "[    0.000000] SBI TIME extension detected"}
- {"dt": "2023-12-18T13:15:49.617996", "lvl": "target", "msg": "[    0.000000] SBI IPI extension detected"}
- {"dt": "2023-12-18T13:15:49.619225", "lvl": "target", "msg": "[    0.000000] SBI RFENCE extension detected"}
- {"dt": "2023-12-18T13:15:49.621510", "lvl": "target", "msg": "[    0.000000] SBI SRST extension detected"}
- {"dt": "2023-12-18T13:15:49.622274", "lvl": "target", "msg": "[    0.000000] SBI HSM extension detected"}
- {"dt": "2023-12-18T13:15:49.634345", "lvl": "target", "msg": "[    0.000000] CPU with hartid=0 is not available"}
- {"dt": "2023-12-18T13:15:49.636096", "lvl": "target", "msg": "[    0.000000] CPU with hartid=0 is not available"}
- {"dt": "2023-12-18T13:15:49.638056", "lvl": "target", "msg": "[    0.000000] CPU with hartid=0 is not available"}
- {"dt": "2023-12-18T13:15:49.650486", "lvl": "target", "msg": "[    0.000000] riscv: base ISA extensions acdfim"}
- {"dt": "2023-12-18T13:15:49.651928", "lvl": "target", "msg": "[    0.000000] riscv: ELF capabilities acdfim"}
- {"dt": "2023-12-18T13:15:49.654229", "lvl": "target", "msg": "[    0.000000] percpu: Embedded 18 pages/cpu s34744 r8192 d30792 u73728"}
- {"dt": "2023-12-18T13:15:49.666431", "lvl": "target", "msg": "[    0.000000] Built 1 zonelists, mobility grouping on.  Total pages: 4128264"}
- {"dt": "2023-12-18T13:15:49.670479", "lvl": "target", "msg": "[    0.000000] Kernel command line: 115200 root=/dev/ram0 console_msg_format=syslog earlycon deferred_probe_timeout=60 ip=dhcp"}
- {"dt": "2023-12-18T13:15:49.686151", "lvl": "target", "msg": "<5>[    0.000000] Unknown kernel command line parameters \\\"115200\\\", will be passed to user space."}
- {"dt": "2023-12-18T13:15:49.750232", "lvl": "target", "msg": "<6>[    0.000000] Dentry cache hash table entries: 2097152 (order: 12, 16777216 bytes, linear)"}
- {"dt": "2023-12-18T13:15:49.782207", "lvl": "target", "msg": "<6>[    0.000000] Inode-cache hash table entries: 1048576 (order: 11, 8388608 bytes, linear)"}
- {"dt": "2023-12-18T13:15:49.798036", "lvl": "target", "msg": "<6>[    0.000000] mem auto-init: stack:off, heap alloc:off, heap free:off"}
- {"dt": "2023-12-18T13:15:49.799118", "lvl": "target", "msg": "<6>[    0.000000] software IO TLB: area num 4."}
- {"dt": "2023-12-18T13:15:50.292779", "lvl": "target", "msg": "<6>[    0.000000] software IO TLB: mapped [mem 0x00000000fbfff000-0x00000000fffff000] (64MB)"}
- {"dt": "2023-12-18T13:15:51.426564", "lvl": "target", "msg": "<5>[    0.000000] Virtual kernel memory layout:"}
- {"dt": "2023-12-18T13:15:51.429746", "lvl": "target", "msg": "<5>[    0.000000]       fixmap : 0xffffffc6fea00000 - 0xffffffc6ff000000   (6144 kB)"}
- {"dt": "2023-12-18T13:15:51.442694", "lvl": "target", "msg": "<5>[    0.000000]       pci io : 0xffffffc6ff000000 - 0xffffffc700000000   (  16 MB)"}
- {"dt": "2023-12-18T13:15:51.445388", "lvl": "target", "msg": "<5>[    0.000000]      vmemmap : 0xffffffc700000000 - 0xffffffc800000000   (4096 MB)"}
- {"dt": "2023-12-18T13:15:51.446768", "lvl": "target", "msg": "<5>[    0.000000]      vmalloc : 0xffffffc800000000 - 0xffffffd800000000   (  64 GB)"}
- {"dt": "2023-12-18T13:15:51.458844", "lvl": "target", "msg": "<5>[    0.000000]      modules : 0xffffffff01361000 - 0xffffffff80000000   (2028 MB)"}
- {"dt": "2023-12-18T13:15:51.461850", "lvl": "target", "msg": "<5>[    0.000000]       lowmem : 0xffffffd800000000 - 0xffffffdbffe00000   (  15 GB)"}
- {"dt": "2023-12-18T13:15:51.475222", "lvl": "target", "msg": "<5>[    0.000000]       kernel : 0xffffffff80000000 - 0xffffffffffffffff   (2047 MB)"}
- {"dt": "2023-12-18T13:15:51.490230", "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": "2023-12-18T13:15:51.492882", "lvl": "target", "msg": "<6>[    0.000000] SLUB: HWalign=64, Order=0-3, MinObjects=0, CPUs=4, Nodes=1"}
- {"dt": "2023-12-18T13:15:51.494601", "lvl": "target", "msg": "<6>[    0.000000] rcu: Hierarchical RCU implementation."}
- {"dt": "2023-12-18T13:15:51.507064", "lvl": "target", "msg": "<6>[    0.000000] rcu: \tRCU restricting CPUs from NR_CPUS=64 to nr_cpu_ids=4."}
- {"dt": "2023-12-18T13:15:51.510414", "lvl": "target", "msg": "<6>[    0.000000] rcu: \tRCU debug extended QS entry/exit."}
- {"dt": "2023-12-18T13:15:51.522401", "lvl": "target", "msg": "<6>[    0.000000] \tTracing variant of Tasks RCU enabled."}
- {"dt": "2023-12-18T13:15:51.524795", "lvl": "target", "msg": "<6>[    0.000000] rcu: RCU calculated value of scheduler-enlistment delay is 25 jiffies."}
- {"dt": "2023-12-18T13:15:51.526290", "lvl": "target", "msg": "<6>[    0.000000] rcu: Adjusting geometry for rcu_fanout_leaf=16, nr_cpu_ids=4"}
- {"dt": "2023-12-18T13:15:51.538412", "lvl": "target", "msg": "<6>[    0.000000] NR_IRQS: 64, nr_irqs: 64, preallocated irqs: 0"}
- {"dt": "2023-12-18T13:15:51.541213", "lvl": "target", "msg": "<6>[    0.000000] CPU with hartid=0 is not available"}
- {"dt": "2023-12-18T13:15:51.554508", "lvl": "target", "msg": "<4>[    0.000000] riscv-intc: unable to find hart id for /cpus/cpu@0/interrupt-controller"}
- {"dt": "2023-12-18T13:15:51.557185", "lvl": "target", "msg": "<6>[    0.000000] riscv-intc: 64 local interrupts mapped"}
- {"dt": "2023-12-18T13:15:51.570424", "lvl": "target", "msg": "<6>[    0.000000] plic: interrupt-controller@c000000: mapped 69 interrupts with 4 handlers for 9 contexts."}
- {"dt": "2023-12-18T13:15:51.572770", "lvl": "target", "msg": "<6>[    0.000000] rcu: srcu_init: Setting srcu_struct sizes based on contention."}
- {"dt": "2023-12-18T13:15:51.574182", "lvl": "target", "msg": "<6>[    0.000000] riscv-timer: riscv_timer_init_dt: Registering clocksource cpuid [0] hartid [2]"}
- {"dt": "2023-12-18T13:15:51.589773", "lvl": "target", "msg": "<6>[    0.000000] clocksource: riscv_clocksource: mask: 0xffffffffffffffff max_cycles: 0x1d854df40, max_idle_ns: 3526361616960 ns"}
- {"dt": "2023-12-18T13:15:51.602289", "lvl": "target", "msg": "<6>[    0.000003] sched_clock: 64 bits at 1000kHz, resolution 1000ns, wraps every 2199023255500ns"}
- {"dt": "2023-12-18T13:15:51.605049", "lvl": "target", "msg": "<6>[    0.008823] Console: colour dummy device 80x25"}
- {"dt": "2023-12-18T13:15:51.606724", "lvl": "target", "msg": "<6>[    0.013317] printk: console [tty0] enabled"}
- {"dt": "2023-12-18T13:15:51.620498", "lvl": "target", "msg": "<6>[    0.017630] printk: bootconsole [sifive0] disabled"}
- {"dt": "2023-12-18T13:15:52.195848", "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": "2023-12-18T13:15:52.200143", "lvl": "target", "msg": "<4>[    0.000000] OF: fdt: Ignoring memory range 0x80000000 - 0x80200000"}
- {"dt": "2023-12-18T13:15:52.209905", "lvl": "target", "msg": "<6>[    0.000000] Machine model: SiFive HiFive Unmatched A00"}
- {"dt": "2023-12-18T13:15:52.213658", "lvl": "target", "msg": "<6>[    0.000000] earlycon: sifive0 at MMIO 0x0000000010010000 (options '')"}
- {"dt": "2023-12-18T13:15:52.226200", "lvl": "target", "msg": "<6>[    0.000000] printk: bootconsole [sifive0] enabled"}
- {"dt": "2023-12-18T13:15:52.227674", "lvl": "target", "msg": "<6>[    0.000000] efi: UEFI not found."}
- {"dt": "2023-12-18T13:15:52.230005", "lvl": "target", "msg": "<6>[    0.000000] Zone ranges:"}
- {"dt": "2023-12-18T13:15:52.231402", "lvl": "target", "msg": "<6>[    0.000000]   DMA32    [mem 0x0000000080200000-0x00000000ffffffff]"}
- {"dt": "2023-12-18T13:15:52.242180", "lvl": "target", "msg": "<6>[    0.000000]   Normal   [mem 0x0000000100000000-0x000000047fffffff]"}
- {"dt": "2023-12-18T13:15:52.243961", "lvl": "target", "msg": "<6>[    0.000000] Movable zone start for each node"}
- {"dt": "2023-12-18T13:15:52.245830", "lvl": "target", "msg": "<6>[    0.000000] Early memory node ranges"}
- {"dt": "2023-12-18T13:15:52.258165", "lvl": "target", "msg": "<6>[    0.000000]   node   0: [mem 0x0000000080200000-0x000000047fffffff]"}
- {"dt": "2023-12-18T13:15:52.260274", "lvl": "target", "msg": "<6>[    0.000000] Initmem setup node 0 [mem 0x0000000080200000-0x000000047fffffff]"}
- {"dt": "2023-12-18T13:15:52.262580", "lvl": "target", "msg": "<6>[    0.000000] SBI specification v1.0 detected"}
- {"dt": "2023-12-18T13:15:52.274220", "lvl": "target", "msg": "<6>[    0.000000] SBI implementation ID=0x1 Version=0x10002"}
- {"dt": "2023-12-18T13:15:52.276482", "lvl": "target", "msg": "<6>[    0.000000] SBI TIME extension detected"}
- {"dt": "2023-12-18T13:15:52.277644", "lvl": "target", "msg": "<6>[    0.000000] SBI IPI extension detected"}
- {"dt": "2023-12-18T13:15:52.278560", "lvl": "target", "msg": "<6>[    0.000000] SBI RFENCE extension detected"}
- {"dt": "2023-12-18T13:15:52.290381", "lvl": "target", "msg": "<6>[    0.000000] SBI SRST extension detected"}
- {"dt": "2023-12-18T13:15:52.292783", "lvl": "target", "msg": "<6>[    0.000000] SBI HSM extension detected"}
- {"dt": "2023-12-18T13:15:52.294136", "lvl": "target", "msg": "<6>[    0.000000] CPU with hartid=0 is not available"}
- {"dt": "2023-12-18T13:15:52.306377", "lvl": "target", "msg": "<6>[    0.000000] CPU with hartid=0 is not available"}
- {"dt": "2023-12-18T13:15:52.309286", "lvl": "target", "msg": "<6>[    0.000000] CPU with hartid=0 is not available"}
- {"dt": "2023-12-18T13:15:52.310742", "lvl": "target", "msg": "<6>[    0.000000] riscv: base ISA extensions acdfim"}
- {"dt": "2023-12-18T13:15:52.312074", "lvl": "target", "msg": "<6>[    0.000000] riscv: ELF capabilities acdfim"}
- {"dt": "2023-12-18T13:15:52.322537", "lvl": "target", "msg": "<6>[    0.000000] percpu: Embedded 18 pages/cpu s34744 r8192 d30792 u73728"}
- {"dt": "2023-12-18T13:15:52.327521", "lvl": "target", "msg": "<6>[    0.000000] Built 1 zonelists, mobility grouping on.  Total pages: 4128264"}
- {"dt": "2023-12-18T13:15:52.338838", "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": "2023-12-18T13:15:52.353945", "lvl": "target", "msg": "<5>[    0.000000] Unknown kernel command line parameters \\\"115200\\\", will be passed to user space."}
- {"dt": "2023-12-18T13:15:52.355765", "lvl": "target", "msg": "<6>[    0.000000] Dentry cache hash table entries: 2097152 (order: 12, 16777216 bytes, linear)"}
- {"dt": "2023-12-18T13:15:52.370221", "lvl": "target", "msg": "<6>[    0.000000] Inode-cache hash table entries: 1048576 (order: 11, 8388608 bytes, linear)"}
- {"dt": "2023-12-18T13:15:52.372882", "lvl": "target", "msg": "<6>[    0.000000] mem auto-init: stack:off, heap alloc:off, heap free:off"}
- {"dt": "2023-12-18T13:15:52.374476", "lvl": "target", "msg": "<6>[    0.000000] software IO TLB: area num 4."}
- {"dt": "2023-12-18T13:15:52.386295", "lvl": "target", "msg": "<6>[    0.000000] software IO TLB: mapped [mem 0x00000000fbfff000-0x00000000fffff000] (64MB)"}
- {"dt": "2023-12-18T13:15:52.388064", "lvl": "target", "msg": "<5>[    0.000000] Virtual kernel memory layout:"}
- {"dt": "2023-12-18T13:15:52.390075", "lvl": "target", "msg": "<5>[    0.000000]       fixmap : 0xffffffc6fea00000 - 0xffffffc6ff000000   (6144 kB)"}
- {"dt": "2023-12-18T13:15:52.403129", "lvl": "target", "msg": "<5>[    0.000000]       pci io : 0xffffffc6ff000000 - 0xffffffc700000000   (  16 MB)"}
- {"dt": "2023-12-18T13:15:52.406176", "lvl": "target", "msg": "<5>[    0.000000]      vmemmap : 0xffffffc700000000 - 0xffffffc800000000   (4096 MB)"}
- {"dt": "2023-12-18T13:15:52.419255", "lvl": "target", "msg": "<5>[    0.000000]      vmalloc : 0xffffffc800000000 - 0xffffffd800000000   (  64 GB)"}
- {"dt": "2023-12-18T13:15:52.422256", "lvl": "target", "msg": "<5>[    0.000000]      modules : 0xffffffff01361000 - 0xffffffff80000000   (2028 MB)"}
- {"dt": "2023-12-18T13:15:52.434393", "lvl": "target", "msg": "<5>[    0.000000]       lowmem : 0xffffffd800000000 - 0xffffffdbffe00000   (  15 GB)"}
- {"dt": "2023-12-18T13:15:52.438246", "lvl": "target", "msg": "<5>[    0.000000]       kernel : 0xffffffff80000000 - 0xffffffffffffffff   (2047 MB)"}
- {"dt": "2023-12-18T13:15:52.451205", "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": "2023-12-18T13:15:52.466285", "lvl": "target", "msg": "<6>[    0.000000] SLUB: HWalign=64, Order=0-3, MinObjects=0, CPUs=4, Nodes=1"}
- {"dt": "2023-12-18T13:15:52.468974", "lvl": "target", "msg": "<6>[    0.000000] rcu: Hierarchical RCU implementation."}
- {"dt": "2023-12-18T13:15:52.470596", "lvl": "target", "msg": "<6>[    0.000000] rcu: \tRCU restricting CPUs from NR_CPUS=64 to nr_cpu_ids=4."}
- {"dt": "2023-12-18T13:15:52.482287", "lvl": "target", "msg": "<6>[    0.000000] rcu: \tRCU debug extended QS entry/exit."}
- {"dt": "2023-12-18T13:15:52.484106", "lvl": "target", "msg": "<6>[    0.000000] \tTracing variant of Tasks RCU enabled."}
- {"dt": "2023-12-18T13:15:52.486145", "lvl": "target", "msg": "<6>[    0.000000] rcu: RCU calculated value of scheduler-enlistment delay is 25 jiffies."}
- {"dt": "2023-12-18T13:15:52.499047", "lvl": "target", "msg": "<6>[    0.000000] rcu: Adjusting geometry for rcu_fanout_leaf=16, nr_cpu_ids=4"}
- {"dt": "2023-12-18T13:15:52.502204", "lvl": "target", "msg": "<6>[    0.000000] NR_IRQS: 64, nr_irqs: 64, preallocated irqs: 0"}
- {"dt": "2023-12-18T13:15:52.514292", "lvl": "target", "msg": "<6>[    0.000000] CPU with hartid=0 is not available"}
- {"dt": "2023-12-18T13:15:52.516490", "lvl": "target", "msg": "<4>[    0.000000] riscv-intc: unable to find hart id for /cpus/cpu@0/interrupt-controller"}
- {"dt": "2023-12-18T13:15:52.518646", "lvl": "target", "msg": "<6>[    0.000000] riscv-intc: 64 local interrupts mapped"}
- {"dt": "2023-12-18T13:15:52.530986", "lvl": "target", "msg": "<6>[    0.000000] plic: interrupt-controller@c000000: mapped 69 interrupts with 4 handlers for 9 contexts."}
- {"dt": "2023-12-18T13:15:52.534150", "lvl": "target", "msg": "<6>[    0.000000] rcu: srcu_init: Setting srcu_struct sizes based on contention."}
- {"dt": "2023-12-18T13:15:52.547202", "lvl": "target", "msg": "<6>[    0.000000] riscv-timer: riscv_timer_init_dt: Registering clocksource cpuid [0] hartid [2]"}
- {"dt": "2023-12-18T13:15:52.562279", "lvl": "target", "msg": "<6>[    0.000000] clocksource: riscv_clocksource: mask: 0xffffffffffffffff max_cycles: 0x1d854df40, max_idle_ns: 3526361616960 ns"}
- {"dt": "2023-12-18T13:15:52.564978", "lvl": "target", "msg": "<6>[    0.000003] sched_clock: 64 bits at 1000kHz, resolution 1000ns, wraps every 2199023255500ns"}
- {"dt": "2023-12-18T13:15:52.566605", "lvl": "target", "msg": "<6>[    0.008823] Console: colour dummy device 80x25"}
- {"dt": "2023-12-18T13:15:52.578349", "lvl": "target", "msg": "<6>[    0.013317] printk: console [tty0] enabled"}
- {"dt": "2023-12-18T13:15:52.580154", "lvl": "target", "msg": "<6>[    0.017630] printk: bootconsole [sifive0] disabled"}
- {"dt": "2023-12-18T13:15:52.594225", "lvl": "target", "msg": "<6>[    0.022727] Calibrating delay loop (skipped), value calculated using timer frequency.. 2.00 BogoMIPS (lpj=4000)"}
- {"dt": "2023-12-18T13:15:52.596438", "lvl": "target", "msg": "<6>[    0.022752] pid_max: default: 32768 minimum: 301"}
- {"dt": "2023-12-18T13:15:52.598618", "lvl": "target", "msg": "<6>[    0.022868] LSM: Security Framework initializing"}
- {"dt": "2023-12-18T13:15:52.610254", "lvl": "target", "msg": "<6>[    0.023626] Mount-cache hash table entries: 32768 (order: 6, 262144 bytes, linear)"}
- {"dt": "2023-12-18T13:15:52.614212", "lvl": "target", "msg": "<6>[    0.024318] Mountpoint-cache hash table entries: 32768 (order: 6, 262144 bytes, linear)"}
- {"dt": "2023-12-18T13:15:52.626274", "lvl": "target", "msg": "<6>[    0.026136] CPU node for /cpus/cpu@0 exist but the possible cpu range is :0-3"}
- {"dt": "2023-12-18T13:15:52.630216", "lvl": "target", "msg": "<6>[    0.027526] cblist_init_generic: Setting adjustable number of callback queues."}
- {"dt": "2023-12-18T13:15:52.642261", "lvl": "target", "msg": "<6>[    0.027545] cblist_init_generic: Setting shift to 2 and lim to 1."}
- {"dt": "2023-12-18T13:15:52.644482", "lvl": "target", "msg": "<6>[    0.027706] riscv: ELF compat mode unsupported"}
- {"dt": "2023-12-18T13:15:52.645680", "lvl": "target", "msg": "<6>[    0.027715] ASID allocator disabled (0 bits)"}
- {"dt": "2023-12-18T13:15:52.646964", "lvl": "target", "msg": "<6>[    0.027902] rcu: Hierarchical SRCU implementation."}
- {"dt": "2023-12-18T13:15:52.658216", "lvl": "target", "msg": "<6>[    0.027916] rcu: \tMax phase no-delay instances is 1000."}
- {"dt": "2023-12-18T13:15:52.660044", "lvl": "target", "msg": "<6>[    0.028279] EFI services will not be available."}
- {"dt": "2023-12-18T13:15:52.662101", "lvl": "target", "msg": "<6>[    0.028981] smp: Bringing up secondary CPUs ..."}
- {"dt": "2023-12-18T13:15:52.674271", "lvl": "target", "msg": "<6>[    0.032044] smp: Brought up 1 node, 4 CPUs"}
- {"dt": "2023-12-18T13:15:52.676366", "lvl": "target", "msg": "<6>[    0.036181] devtmpfs: initialized"}
- {"dt": "2023-12-18T13:15:52.690324", "lvl": "target", "msg": "<6>[    0.039019] clocksource: jiffies: mask: 0xffffffff max_cycles: 0xffffffff, max_idle_ns: 7645041785100000 ns"}
- {"dt": "2023-12-18T13:15:52.692531", "lvl": "target", "msg": "<6>[    0.039063] futex hash table entries: 1024 (order: 4, 65536 bytes, linear)"}
- {"dt": "2023-12-18T13:15:52.694739", "lvl": "target", "msg": "<6>[    0.039458] pinctrl core: initialized pinctrl subsystem"}
- {"dt": "2023-12-18T13:15:52.706309", "lvl": "target", "msg": "<6>[    0.040479] NET: Registered PF_NETLINK/PF_ROUTE protocol family"}
- {"dt": "2023-12-18T13:15:52.708001", "lvl": "target", "msg": "<6>[    0.040678] audit: initializing netlink subsys (disabled)"}
- {"dt": "2023-12-18T13:15:52.722280", "lvl": "target", "msg": "<5>[    0.040939] audit: type=2000 audit(0.028:1): state=initialized audit_enabled=0 res=1"}
- {"dt": "2023-12-18T13:15:52.723640", "lvl": "target", "msg": "<6>[    0.041278] cpuidle: using governor menu"}
- {"dt": "2023-12-18T13:15:52.726885", "lvl": "target", "msg": "<6>[    0.052263] HugeTLB: registered 2.00 MiB page size, pre-allocated 0 pages"}
- {"dt": "2023-12-18T13:15:52.738348", "lvl": "target", "msg": "<6>[    0.052291] HugeTLB: 0 KiB vmemmap can be freed for a 2.00 MiB page"}
- {"dt": "2023-12-18T13:15:52.740241", "lvl": "target", "msg": "<6>[    0.053028] iommu: Default domain type: Translated "}
- {"dt": "2023-12-18T13:15:52.742085", "lvl": "target", "msg": "<6>[    0.053047] iommu: DMA domain TLB invalidation policy: strict mode "}
- {"dt": "2023-12-18T13:15:52.754274", "lvl": "target", "msg": "<5>[    0.053405] SCSI subsystem initialized"}
- {"dt": "2023-12-18T13:15:52.756347", "lvl": "target", "msg": "<6>[    0.053826] usbcore: registered new interface driver usbfs"}
- {"dt": "2023-12-18T13:15:52.758359", "lvl": "target", "msg": "<6>[    0.053879] usbcore: registered new interface driver hub"}
- {"dt": "2023-12-18T13:15:52.770244", "lvl": "target", "msg": "<6>[    0.053931] usbcore: registered new device driver usb"}
- {"dt": "2023-12-18T13:15:52.772321", "lvl": "target", "msg": "<6>[    0.054984] vgaarb: loaded"}
- {"dt": "2023-12-18T13:15:52.774329", "lvl": "target", "msg": "<6>[    0.055147] clocksource: Switched to clocksource riscv_clocksource"}
- {"dt": "2023-12-18T13:15:52.786261", "lvl": "target", "msg": "<6>[    0.064472] NET: Registered PF_INET protocol family"}
- {"dt": "2023-12-18T13:15:52.788089", "lvl": "target", "msg": "<6>[    0.071653] IP idents hash table entries: 262144 (order: 9, 2097152 bytes, linear)"}
- {"dt": "2023-12-18T13:15:52.802247", "lvl": "target", "msg": "<6>[    0.092793] tcp_listen_portaddr_hash hash table entries: 8192 (order: 6, 262144 bytes, linear)"}
- {"dt": "2023-12-18T13:15:52.804688", "lvl": "target", "msg": "<6>[    0.093834] Table-perturb hash table entries: 65536 (order: 6, 262144 bytes, linear)"}
- {"dt": "2023-12-18T13:15:52.818827", "lvl": "target", "msg": "<6>[    0.093922] TCP established hash table entries: 131072 (order: 8, 1048576 bytes, linear)"}
- {"dt": "2023-12-18T13:15:52.821295", "lvl": "target", "msg": "<6>[    0.098579] TCP bind hash table entries: 65536 (order: 10, 4194304 bytes, linear)"}
- {"dt": "2023-12-18T13:15:52.834379", "lvl": "target", "msg": "<6>[    0.116304] TCP: Hash tables configured (established 131072 bind 65536)"}
- {"dt": "2023-12-18T13:15:52.836789", "lvl": "target", "msg": "<6>[    0.117092] UDP hash table entries: 8192 (order: 7, 786432 bytes, linear)"}
- {"dt": "2023-12-18T13:15:52.838270", "lvl": "target", "msg": "<6>[    0.120353] UDP-Lite hash table entries: 8192 (order: 7, 786432 bytes, linear)"}
- {"dt": "2023-12-18T13:15:52.851099", "lvl": "target", "msg": "<6>[    0.123880] NET: Registered PF_UNIX/PF_LOCAL protocol family"}
- {"dt": "2023-12-18T13:15:52.854247", "lvl": "target", "msg": "<6>[    0.125044] RPC: Registered named UNIX socket transport module."}
- {"dt": "2023-12-18T13:15:52.866277", "lvl": "target", "msg": "<6>[    0.125069] RPC: Registered udp transport module."}
- {"dt": "2023-12-18T13:15:52.868480", "lvl": "target", "msg": "<6>[    0.125082] RPC: Registered tcp transport module."}
- {"dt": "2023-12-18T13:15:52.870663", "lvl": "target", "msg": "<6>[    0.125093] RPC: Registered tcp NFSv4.1 backchannel transport module."}
- {"dt": "2023-12-18T13:15:52.882276", "lvl": "target", "msg": "<6>[    0.125116] PCI: CLS 0 bytes, default 64"}
- {"dt": "2023-12-18T13:15:52.883381", "lvl": "target", "msg": "<6>[    0.125712] Unpacking initramfs..."}
- {"dt": "2023-12-18T13:15:52.885175", "lvl": "target", "msg": "<6>[    0.144523] workingset: timestamp_bits=46 max_order=22 bucket_order=0"}
- {"dt": "2023-12-18T13:15:52.898258", "lvl": "target", "msg": "<5>[    0.153781] NFS: Registering the id_resolver key type"}
- {"dt": "2023-12-18T13:15:52.899521", "lvl": "target", "msg": "<5>[    0.153932] Key type id_resolver registered"}
- {"dt": "2023-12-18T13:15:52.901583", "lvl": "target", "msg": "<5>[    0.153948] Key type id_legacy registered"}
- {"dt": "2023-12-18T13:15:52.902916", "lvl": "target", "msg": "<6>[    0.154045] nfs4filelayout_init: NFSv4 File Layout Driver Registering..."}
- {"dt": "2023-12-18T13:15:52.914978", "lvl": "target", "msg": "<6>[    0.154066] nfs4flexfilelayout_init: NFSv4 Flexfile Layout Driver Registering..."}
- {"dt": "2023-12-18T13:15:52.918092", "lvl": "target", "msg": "<6>[    0.154336] 9p: Installing v9fs 9p2000 file system support"}
- {"dt": "2023-12-18T13:15:52.930221", "lvl": "target", "msg": "<6>[    0.154839] NET: Registered PF_ALG protocol family"}
- {"dt": "2023-12-18T13:15:52.932455", "lvl": "target", "msg": "<6>[    0.154921] Block layer SCSI generic (bsg) driver version 0.4 loaded (major 250)"}
- {"dt": "2023-12-18T13:15:52.934646", "lvl": "target", "msg": "<6>[    0.154949] io scheduler mq-deadline registered"}
- {"dt": "2023-12-18T13:15:52.946230", "lvl": "target", "msg": "<6>[    0.154965] io scheduler kyber registered"}
- {"dt": "2023-12-18T13:15:52.948161", "lvl": "target", "msg": "<6>[    0.179294] fu740-pcie e00000000.pcie: host bridge /soc/pcie@e00000000 ranges:"}
- {"dt": "2023-12-18T13:15:52.962710", "lvl": "target", "msg": "<6>[    0.179425] fu740-pcie e00000000.pcie:       IO 0x0060080000..0x006008ffff -> 0x0060080000"}
- {"dt": "2023-12-18T13:15:52.965960", "lvl": "target", "msg": "<6>[    0.179475] fu740-pcie e00000000.pcie:      MEM 0x0060090000..0x007fffffff -> 0x0060090000"}
- {"dt": "2023-12-18T13:15:52.978117", "lvl": "target", "msg": "<6>[    0.179506] fu740-pcie e00000000.pcie:      MEM 0x2000000000..0x3fffffffff -> 0x2000000000"}
- {"dt": "2023-12-18T13:15:52.980368", "lvl": "target", "msg": "<6>[    0.288289] fu740-pcie e00000000.pcie: iATU unroll: enabled"}
- {"dt": "2023-12-18T13:15:52.994156", "lvl": "target", "msg": "<6>[    0.288349] fu740-pcie e00000000.pcie: iATU regions: 8 ob, 8 ib, align 4K, limit 4096G"}
- {"dt": "2023-12-18T13:15:52.996599", "lvl": "target", "msg": "<6>[    0.388459] fu740-pcie e00000000.pcie: PCIe Gen.1 x8 link up"}
- {"dt": "2023-12-18T13:15:52.998073", "lvl": "target", "msg": "<6>[    0.488569] fu740-pcie e00000000.pcie: PCIe Gen.3 x8 link up"}
- {"dt": "2023-12-18T13:15:53.010248", "lvl": "target", "msg": "<6>[    0.488635] fu740-pcie e00000000.pcie: PCIe Gen.3 x8 link up"}
- {"dt": "2023-12-18T13:15:53.012344", "lvl": "target", "msg": "<6>[    0.488875] fu740-pcie e00000000.pcie: PCI host bridge to bus 0000:00"}
- {"dt": "2023-12-18T13:15:53.026239", "lvl": "target", "msg": "<6>[    0.488905] pci_bus 0000:00: root bus resource [bus 00-ff]"}
- {"dt": "2023-12-18T13:15:53.028626", "lvl": "target", "msg": "<6>[    0.488928] pci_bus 0000:00: root bus resource [io  0x0000-0xffff] (bus address [0x60080000-0x6008ffff])"}
- {"dt": "2023-12-18T13:15:53.042228", "lvl": "target", "msg": "<6>[    0.488950] pci_bus 0000:00: root bus resource [mem 0x60090000-0x7fffffff]"}
- {"dt": "2023-12-18T13:15:53.044634", "lvl": "target", "msg": "<6>[    0.488967] pci_bus 0000:00: root bus resource [mem 0x2000000000-0x3fffffffff pref]"}
- {"dt": "2023-12-18T13:15:53.046118", "lvl": "target", "msg": "<6>[    0.489025] pci 0000:00:00.0: [f15e:0000] type 01 class 0x060400"}
- {"dt": "2023-12-18T13:15:53.058237", "lvl": "target", "msg": "<6>[    0.489055] pci 0000:00:00.0: reg 0x10: [mem 0x00000000-0x000fffff]"}
- {"dt": "2023-12-18T13:15:53.062152", "lvl": "target", "msg": "<6>[    0.489078] pci 0000:00:00.0: reg 0x38: [mem 0x00000000-0x0000ffff pref]"}
- {"dt": "2023-12-18T13:15:53.074300", "lvl": "target", "msg": "<6>[    0.489158] pci 0000:00:00.0: supports D1"}
- {"dt": "2023-12-18T13:15:53.076725", "lvl": "target", "msg": "<6>[    0.489173] pci 0000:00:00.0: PME# supported from D0 D1 D3hot"}
- {"dt": "2023-12-18T13:15:53.078209", "lvl": "target", "msg": "<6>[    0.490028] pci 0000:01:00.0: [1b21:2824] type 01 class 0x060400"}
- {"dt": "2023-12-18T13:15:53.090221", "lvl": "target", "msg": "<6>[    0.490125] pci 0000:01:00.0: enabling Extended Tags"}
- {"dt": "2023-12-18T13:15:53.092265", "lvl": "target", "msg": "<6>[    0.490273] pci 0000:01:00.0: PME# supported from D0 D3hot D3cold"}
- {"dt": "2023-12-18T13:15:53.106243", "lvl": "target", "msg": "<6>[    0.499251] pci 0000:01:00.0: bridge configuration invalid ([bus 00-00]), reconfiguring"}
- {"dt": "2023-12-18T13:15:53.108640", "lvl": "target", "msg": "<6>[    0.499494] pci 0000:02:00.0: [1b21:2824] type 01 class 0x060400"}
- {"dt": "2023-12-18T13:15:53.110142", "lvl": "target", "msg": "<6>[    0.499593] pci 0000:02:00.0: enabling Extended Tags"}
- {"dt": "2023-12-18T13:15:53.122214", "lvl": "target", "msg": "<6>[    0.499750] pci 0000:02:00.0: PME# supported from D0 D3hot D3cold"}
- {"dt": "2023-12-18T13:15:53.124293", "lvl": "target", "msg": "<6>[    0.500127] pci 0000:02:02.0: [1b21:2824] type 01 class 0x060400"}
- {"dt": "2023-12-18T13:15:53.126287", "lvl": "target", "msg": "<6>[    0.500223] pci 0000:02:02.0: enabling Extended Tags"}
- {"dt": "2023-12-18T13:15:53.138185", "lvl": "target", "msg": "<6>[    0.500368] pci 0000:02:02.0: PME# supported from D0 D3hot D3cold"}
- {"dt": "2023-12-18T13:15:53.140233", "lvl": "target", "msg": "<6>[    0.500659] pci 0000:02:03.0: [1b21:2824] type 01 class 0x060400"}
- {"dt": "2023-12-18T13:15:53.142211", "lvl": "target", "msg": "<6>[    0.500755] pci 0000:02:03.0: enabling Extended Tags"}
- {"dt": "2023-12-18T13:15:53.155262", "lvl": "target", "msg": "<6>[    0.500899] pci 0000:02:03.0: PME# supported from D0 D3hot D3cold"}
- {"dt": "2023-12-18T13:15:53.158919", "lvl": "target", "msg": "<6>[    0.501211] pci 0000:02:04.0: [1b21:2824] type 01 class 0x060400"}
- {"dt": "2023-12-18T13:15:53.170364", "lvl": "target", "msg": "<6>[    0.501306] pci 0000:02:04.0: enabling Extended Tags"}
- {"dt": "2023-12-18T13:15:53.172765", "lvl": "target", "msg": "<6>[    0.501450] pci 0000:02:04.0: PME# supported from D0 D3hot D3cold"}
- {"dt": "2023-12-18T13:15:53.174257", "lvl": "target", "msg": "<6>[    0.501813] pci 0000:02:08.0: [1b21:2824] type 01 class 0x060400"}
- {"dt": "2023-12-18T13:15:53.186220", "lvl": "target", "msg": "<6>[    0.501908] pci 0000:02:08.0: enabling Extended Tags"}
- {"dt": "2023-12-18T13:15:53.188145", "lvl": "target", "msg": "<6>[    0.502054] pci 0000:02:08.0: PME# supported from D0 D3hot D3cold"}
- {"dt": "2023-12-18T13:15:53.202200", "lvl": "target", "msg": "<6>[    0.502732] pci 0000:02:00.0: bridge configuration invalid ([bus 00-00]), reconfiguring"}
- {"dt": "2023-12-18T13:15:53.204630", "lvl": "target", "msg": "<6>[    0.502767] pci 0000:02:02.0: bridge configuration invalid ([bus 00-00]), reconfiguring"}
- {"dt": "2023-12-18T13:15:53.218209", "lvl": "target", "msg": "<6>[    0.502796] pci 0000:02:03.0: bridge configuration invalid ([bus 00-00]), reconfiguring"}
- {"dt": "2023-12-18T13:15:53.220604", "lvl": "target", "msg": "<6>[    0.502825] pci 0000:02:04.0: bridge configuration invalid ([bus 00-00]), reconfiguring"}
- {"dt": "2023-12-18T13:15:53.234220", "lvl": "target", "msg": "<6>[    0.502853] pci 0000:02:08.0: bridge configuration invalid ([bus 00-00]), reconfiguring"}
- {"dt": "2023-12-18T13:15:53.236629", "lvl": "target", "msg": "<6>[    0.503039] pci_bus 0000:03: busn_res: [bus 03-ff] end is updated to 03"}
- {"dt": "2023-12-18T13:15:53.250205", "lvl": "target", "msg": "<6>[    0.503255] pci 0000:04:00.0: [1b21:1142] type 00 class 0x0c0330"}
- {"dt": "2023-12-18T13:15:53.252627", "lvl": "target", "msg": "<6>[    0.503320] pci 0000:04:00.0: reg 0x10: [mem 0x00000000-0x00007fff 64bit]"}
- {"dt": "2023-12-18T13:15:53.254101", "lvl": "target", "msg": "<6>[    0.503547] pci 0000:04:00.0: PME# supported from D3cold"}
- {"dt": "2023-12-18T13:15:53.266223", "lvl": "target", "msg": "<6>[    0.515240] pci_bus 0000:04: busn_res: [bus 04-ff] end is updated to 04"}
- {"dt": "2023-12-18T13:15:53.268264", "lvl": "target", "msg": "<6>[    0.515511] pci_bus 0000:05: busn_res: [bus 05-ff] end is updated to 05"}
- {"dt": "2023-12-18T13:15:53.282221", "lvl": "target", "msg": "<6>[    0.515685] pci_bus 0000:06: busn_res: [bus 06-ff] end is updated to 06"}
- {"dt": "2023-12-18T13:15:53.284628", "lvl": "target", "msg": "<6>[    0.515909] pci 0000:07:00.0: [1002:6779] type 00 class 0x030000"}
- {"dt": "2023-12-18T13:15:53.286120", "lvl": "target", "msg": "<6>[    0.515969] pci 0000:07:00.0: reg 0x10: [mem 0x00000000-0x0fffffff 64bit pref]"}
- {"dt": "2023-12-18T13:15:53.298997", "lvl": "target", "msg": "<6>[    0.516014] pci 0000:07:00.0: reg 0x18: [mem 0x00000000-0x0001ffff 64bit]"}
- {"dt": "2023-12-18T13:15:53.302062", "lvl": "target", "msg": "<6>[    0.516043] pci 0000:07:00.0: reg 0x20: initial BAR value 0x00000000 invalid"}
- {"dt": "2023-12-18T13:15:53.314210", "lvl": "target", "msg": "<6>[    0.516061] pci 0000:07:00.0: reg 0x20: [io  size 0x0100]"}
- {"dt": "2023-12-18T13:15:53.316640", "lvl": "target", "msg": "<6>[    0.516102] pci 0000:07:00.0: reg 0x30: [mem 0x00000000-0x0001ffff pref]"}
- {"dt": "2023-12-18T13:15:53.318130", "lvl": "target", "msg": "<6>[    0.516135] pci 0000:07:00.0: enabling Extended Tags"}
- {"dt": "2023-12-18T13:15:53.330247", "lvl": "target", "msg": "<6>[    0.516283] pci 0000:07:00.0: supports D1 D2"}
- {"dt": "2023-12-18T13:15:53.346257", "lvl": "target", "msg": "<6>[    0.516349] 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": "2023-12-18T13:15:53.348798", "lvl": "target", "msg": "<6>[    0.516558] pci 0000:07:00.0: vgaarb: setting as boot VGA device"}
- {"dt": "2023-12-18T13:15:53.351365", "lvl": "target", "msg": "<6>[    0.516577] pci 0000:07:00.0: vgaarb: bridge control possible"}
- {"dt": "2023-12-18T13:15:53.362970", "lvl": "target", "msg": "<6>[    0.516592] pci 0000:07:00.0: vgaarb: VGA device added: decodes=io+mem,owns=none,locks=none"}
- {"dt": "2023-12-18T13:15:53.366011", "lvl": "target", "msg": "<6>[    0.516686] pci 0000:07:00.1: [1002:aa98] type 00 class 0x040300"}
- {"dt": "2023-12-18T13:15:53.378037", "lvl": "target", "msg": "<6>[    0.516744] pci 0000:07:00.1: reg 0x10: [mem 0x00000000-0x00003fff 64bit]"}
- {"dt": "2023-12-18T13:15:53.380234", "lvl": "target", "msg": "<6>[    0.516838] pci 0000:07:00.1: enabling Extended Tags"}
- {"dt": "2023-12-18T13:15:53.382418", "lvl": "target", "msg": "<6>[    0.516986] pci 0000:07:00.1: supports D1 D2"}
- {"dt": "2023-12-18T13:15:53.394778", "lvl": "target", "msg": "<6>[    0.527246] pci_bus 0000:07: busn_res: [bus 07-ff] end is updated to 07"}
- {"dt": "2023-12-18T13:15:53.397817", "lvl": "target", "msg": "<6>[    0.527297] pci_bus 0000:02: busn_res: [bus 02-ff] end is updated to 07"}
- {"dt": "2023-12-18T13:15:53.410237", "lvl": "target", "msg": "<6>[    0.527322] pci_bus 0000:01: busn_res: [bus 01-ff] end is updated to 07"}
- {"dt": "2023-12-18T13:15:53.414201", "lvl": "target", "msg": "<6>[    0.527395] pci 0000:00:00.0: BAR 9: assigned [mem 0x2000000000-0x200fffffff 64bit pref]"}
- {"dt": "2023-12-18T13:15:53.426244", "lvl": "target", "msg": "<6>[    0.527420] pci 0000:00:00.0: BAR 0: assigned [mem 0x60100000-0x601fffff]"}
- {"dt": "2023-12-18T13:15:53.428290", "lvl": "target", "msg": "<6>[    0.527439] pci 0000:00:00.0: BAR 8: assigned [mem 0x60200000-0x603fffff]"}
- {"dt": "2023-12-18T13:15:53.442238", "lvl": "target", "msg": "<6>[    0.527457] pci 0000:00:00.0: BAR 6: assigned [mem 0x60090000-0x6009ffff pref]"}
- {"dt": "2023-12-18T13:15:53.444644", "lvl": "target", "msg": "<6>[    0.527478] pci 0000:00:00.0: BAR 7: assigned [io  0x1000-0x1fff]"}
- {"dt": "2023-12-18T13:15:53.458229", "lvl": "target", "msg": "<6>[    0.527501] pci 0000:01:00.0: BAR 9: assigned [mem 0x2000000000-0x200fffffff 64bit pref]"}
- {"dt": "2023-12-18T13:15:53.460614", "lvl": "target", "msg": "<6>[    0.527522] pci 0000:01:00.0: BAR 8: assigned [mem 0x60200000-0x603fffff]"}
- {"dt": "2023-12-18T13:15:53.462232", "lvl": "target", "msg": "<6>[    0.527539] pci 0000:01:00.0: BAR 7: assigned [io  0x1000-0x1fff]"}
- {"dt": "2023-12-18T13:15:53.474985", "lvl": "target", "msg": "<6>[    0.527561] pci 0000:02:08.0: BAR 9: assigned [mem 0x2000000000-0x200fffffff 64bit pref]"}
- {"dt": "2023-12-18T13:15:53.478037", "lvl": "target", "msg": "<6>[    0.527583] pci 0000:02:02.0: BAR 8: assigned [mem 0x60200000-0x602fffff]"}
- {"dt": "2023-12-18T13:15:53.490234", "lvl": "target", "msg": "<6>[    0.527601] pci 0000:02:08.0: BAR 8: assigned [mem 0x60300000-0x603fffff]"}
- {"dt": "2023-12-18T13:15:53.492665", "lvl": "target", "msg": "<6>[    0.527617] pci 0000:02:08.0: BAR 7: assigned [io  0x1000-0x1fff]"}
- {"dt": "2023-12-18T13:15:53.494139", "lvl": "target", "msg": "<6>[    0.527635] pci 0000:02:00.0: PCI bridge to [bus 03]"}
- {"dt": "2023-12-18T13:15:53.507003", "lvl": "target", "msg": "<6>[    0.527674] pci 0000:04:00.0: BAR 0: assigned [mem 0x60200000-0x60207fff 64bit]"}
- {"dt": "2023-12-18T13:15:53.510155", "lvl": "target", "msg": "<6>[    0.527714] pci 0000:02:02.0: PCI bridge to [bus 04]"}
- {"dt": "2023-12-18T13:15:53.522276", "lvl": "target", "msg": "<6>[    0.527734] pci 0000:02:02.0:   bridge window [mem 0x60200000-0x602fffff]"}
- {"dt": "2023-12-18T13:15:53.524679", "lvl": "target", "msg": "<6>[    0.527762] pci 0000:02:03.0: PCI bridge to [bus 05]"}
- {"dt": "2023-12-18T13:15:53.526161", "lvl": "target", "msg": "<6>[    0.527793] pci 0000:02:04.0: PCI bridge to [bus 06]"}
- {"dt": "2023-12-18T13:15:53.538992", "lvl": "target", "msg": "<6>[    0.527829] pci 0000:07:00.0: BAR 0: assigned [mem 0x2000000000-0x200fffffff 64bit pref]"}
- {"dt": "2023-12-18T13:15:53.542233", "lvl": "target", "msg": "<6>[    0.527869] pci 0000:07:00.0: BAR 2: assigned [mem 0x60300000-0x6031ffff 64bit]"}
- {"dt": "2023-12-18T13:15:53.554232", "lvl": "target", "msg": "<6>[    0.527907] pci 0000:07:00.0: BAR 6: assigned [mem 0x60320000-0x6033ffff pref]"}
- {"dt": "2023-12-18T13:15:53.558181", "lvl": "target", "msg": "<6>[    0.527928] pci 0000:07:00.1: BAR 0: assigned [mem 0x60340000-0x60343fff 64bit]"}
- {"dt": "2023-12-18T13:15:53.570230", "lvl": "target", "msg": "<6>[    0.527966] pci 0000:07:00.0: BAR 4: assigned [io  0x1000-0x10ff]"}
- {"dt": "2023-12-18T13:15:53.572281", "lvl": "target", "msg": "<6>[    0.527989] pci 0000:02:08.0: PCI bridge to [bus 07]"}
- {"dt": "2023-12-18T13:15:53.574263", "lvl": "target", "msg": "<6>[    0.528006] pci 0000:02:08.0:   bridge window [io  0x1000-0x1fff]"}
- {"dt": "2023-12-18T13:15:53.586242", "lvl": "target", "msg": "<6>[    0.528026] pci 0000:02:08.0:   bridge window [mem 0x60300000-0x603fffff]"}
- {"dt": "2023-12-18T13:15:53.590114", "lvl": "target", "msg": "<6>[    0.528046] pci 0000:02:08.0:   bridge window [mem 0x2000000000-0x200fffffff 64bit pref]"}
- {"dt": "2023-12-18T13:15:53.602237", "lvl": "target", "msg": "<6>[    0.528072] pci 0000:01:00.0: PCI bridge to [bus 02-07]"}
- {"dt": "2023-12-18T13:15:53.604650", "lvl": "target", "msg": "<6>[    0.528089] pci 0000:01:00.0:   bridge window [io  0x1000-0x1fff]"}
- {"dt": "2023-12-18T13:15:53.618218", "lvl": "target", "msg": "<6>[    0.528109] pci 0000:01:00.0:   bridge window [mem 0x60200000-0x603fffff]"}
- {"dt": "2023-12-18T13:15:53.620628", "lvl": "target", "msg": "<6>[    0.528128] pci 0000:01:00.0:   bridge window [mem 0x2000000000-0x200fffffff 64bit pref]"}
- {"dt": "2023-12-18T13:15:53.622168", "lvl": "target", "msg": "<6>[    0.528155] pci 0000:00:00.0: PCI bridge to [bus 01-07]"}
- {"dt": "2023-12-18T13:15:53.634181", "lvl": "target", "msg": "<6>[    0.528170] pci 0000:00:00.0:   bridge window [io  0x1000-0x1fff]"}
- {"dt": "2023-12-18T13:15:53.638045", "lvl": "target", "msg": "<6>[    0.528186] pci 0000:00:00.0:   bridge window [mem 0x60200000-0x603fffff]"}
- {"dt": "2023-12-18T13:15:53.650225", "lvl": "target", "msg": "<6>[    0.528202] pci 0000:00:00.0:   bridge window [mem 0x2000000000-0x200fffffff 64bit pref]"}
- {"dt": "2023-12-18T13:15:53.652779", "lvl": "target", "msg": "<6>[    0.528686] pcieport 0000:00:00.0: PME: Signaling with IRQ 21"}
- {"dt": "2023-12-18T13:15:53.666175", "lvl": "target", "msg": "<6>[    0.528845] pcieport 0000:01:00.0: enabling device (0000 -> 0003)"}
- {"dt": "2023-12-18T13:15:53.668608", "lvl": "target", "msg": "<6>[    0.529426] pcieport 0000:02:02.0: enabling device (0000 -> 0002)"}
- {"dt": "2023-12-18T13:15:53.670102", "lvl": "target", "msg": "<6>[    0.530438] pcieport 0000:02:08.0: enabling device (0000 -> 0003)"}
- {"dt": "2023-12-18T13:15:53.682192", "lvl": "target", "msg": "<6>[    0.530819] pci 0000:04:00.0: enabling device (0000 -> 0002)"}
- {"dt": "2023-12-18T13:15:53.684484", "lvl": "target", "msg": "<6>[    0.531005] pci 0000:07:00.1: D0 power state depends on 0000:07:00.0"}
- {"dt": "2023-12-18T13:15:53.698116", "lvl": "target", "msg": "<6>[    0.584987] Serial: 8250/16550 driver, 4 ports, IRQ sharing disabled"}
- {"dt": "2023-12-18T13:15:53.700342", "lvl": "target", "msg": "<6>[    0.586521] 10010000.serial: ttySIF0 at MMIO 0x10010000 (irq = 29, base_baud = 8125000) is a SiFive UART v0"}
- {"dt": "2023-12-18T13:15:53.702733", "lvl": "target", "msg": "<6>[    0.980970] Freeing initrd memory: 13320K"}
- {"dt": "2023-12-18T13:15:53.714151", "lvl": "target", "msg": "<6>[    0.983981] printk: console [ttySIF0] enabled"}
- {"dt": "2023-12-18T13:15:53.718066", "lvl": "target", "msg": "<6>[    2.120727] 10011000.serial: ttySIF1 at MMIO 0x10011000 (irq = 30, base_baud = 8125000) is a SiFive UART v0"}
- {"dt": "2023-12-18T13:15:53.730207", "lvl": "target", "msg": "<6>[    2.140983] loop: module loaded"}
- {"dt": "2023-12-18T13:15:53.746155", "lvl": "target", "msg": "<6>[    2.144389] sifive_spi 10040000.spi: mapped; irq=31, cs=1"}
- {"dt": "2023-12-18T13:15:53.748929", "lvl": "target", "msg": "<6>[    2.150060] sifive_spi 10050000.spi: mapped; irq=32, cs=1"}
- {"dt": "2023-12-18T13:15:53.750812", "lvl": "target", "msg": "<6>[    2.156942] macb 10090000.ethernet: Registered clk switch 'sifive-gemgxl-mgmt'"}
- {"dt": "2023-12-18T13:15:53.778079", "lvl": "target", "msg": "<6>[    2.175562] macb 10090000.ethernet eth0: Cadence GEM rev 0x10070109 at 0x10090000 irq 33 (70:b3:d5:92:fa:8d)"}
- {"dt": "2023-12-18T13:15:53.780114", "lvl": "target", "msg": "<6>[    2.185051] e1000e: Intel(R) PRO/1000 Network Driver"}
- {"dt": "2023-12-18T13:15:53.782515", "lvl": "target", "msg": "<6>[    2.190114] e1000e: Copyright(c) 1999 - 2015 Intel Corporation."}
- {"dt": "2023-12-18T13:15:53.794166", "lvl": "target", "msg": "<6>[    2.196853] xhci_hcd 0000:04:00.0: xHCI Host Controller"}
- {"dt": "2023-12-18T13:15:53.798037", "lvl": "target", "msg": "<6>[    2.201774] xhci_hcd 0000:04:00.0: new USB bus registered, assigned bus number 1"}
- {"dt": "2023-12-18T13:15:53.954206", "lvl": "target", "msg": "<6>[    2.350090] xhci_hcd 0000:04:00.0: hcc params 0x0200e080 hci version 0x100 quirks 0x0000000010800410"}
- {"dt": "2023-12-18T13:15:53.957523", "lvl": "target", "msg": "<6>[    2.359589] xhci_hcd 0000:04:00.0: xHCI Host Controller"}
- {"dt": "2023-12-18T13:15:53.959786", "lvl": "target", "msg": "<6>[    2.364328] xhci_hcd 0000:04:00.0: new USB bus registered, assigned bus number 2"}
- {"dt": "2023-12-18T13:15:53.971549", "lvl": "target", "msg": "<6>[    2.371972] xhci_hcd 0000:04:00.0: Host supports USB 3.0 SuperSpeed"}
- {"dt": "2023-12-18T13:15:53.972365", "lvl": "target", "msg": "<6>[    2.380019] hub 1-0:1.0: USB hub found"}
- {"dt": "2023-12-18T13:15:53.974093", "lvl": "target", "msg": "<6>[    2.383320] hub 1-0:1.0: 2 ports detected"}
- {"dt": "2023-12-18T13:15:53.986893", "lvl": "target", "msg": "<6>[    2.387977] usb usb2: We don't know the algorithms for LPM for this host, disabling LPM."}
- {"dt": "2023-12-18T13:15:53.990110", "lvl": "target", "msg": "<6>[    2.396415] hub 2-0:1.0: USB hub found"}
- {"dt": "2023-12-18T13:15:53.991287", "lvl": "target", "msg": "<6>[    2.399903] hub 2-0:1.0: 2 ports detected"}
- {"dt": "2023-12-18T13:15:54.002704", "lvl": "target", "msg": "<6>[    2.404905] usbcore: registered new interface driver uas"}
- {"dt": "2023-12-18T13:15:54.006196", "lvl": "target", "msg": "<6>[    2.409820] usbcore: registered new interface driver usb-storage"}
- {"dt": "2023-12-18T13:15:54.018187", "lvl": "target", "msg": "<6>[    2.416152] mousedev: PS/2 mouse device common for all mice"}
- {"dt": "2023-12-18T13:15:54.020456", "lvl": "target", "msg": "<6>[    2.422317] sdhci: Secure Digital Host Controller Interface driver"}
- {"dt": "2023-12-18T13:15:54.022062", "lvl": "target", "msg": "<6>[    2.428226] sdhci: Copyright(c) Pierre Ossman"}
- {"dt": "2023-12-18T13:15:54.053808", "lvl": "target", "msg": "<6>[    2.458523] mmc_spi spi1.0: SD/MMC host mmc0, no DMA, no WP, no poweroff"}
- {"dt": "2023-12-18T13:15:54.066279", "lvl": "target", "msg": "<6>[    2.464797] sdhci-pltfm: SDHCI platform and OF driver helper"}
- {"dt": "2023-12-18T13:15:54.069094", "lvl": "target", "msg": "<6>[    2.470823] usbcore: registered new interface driver usbhid"}
- {"dt": "2023-12-18T13:15:54.070747", "lvl": "target", "msg": "<6>[    2.476457] usbhid: USB HID core driver"}
- {"dt": "2023-12-18T13:15:54.082344", "lvl": "target", "msg": "<6>[    2.480647] riscv-pmu-sbi: SBI PMU extension is available"}
- {"dt": "2023-12-18T13:15:54.084549", "lvl": "target", "msg": "<6>[    2.486204] riscv-pmu-sbi: 16 firmware and 4 hardware counters"}
- {"dt": "2023-12-18T13:15:54.098129", "lvl": "target", "msg": "<6>[    2.492261] riscv-pmu-sbi: Perf sampling/filtering is not supported as sscof extension is not available"}
- {"dt": "2023-12-18T13:15:54.100339", "lvl": "target", "msg": "<6>[    2.502926] NET: Registered PF_INET6 protocol family"}
- {"dt": "2023-12-18T13:15:54.101522", "lvl": "target", "msg": "<6>[    2.509193] Segment Routing with IPv6"}
- {"dt": "2023-12-18T13:15:54.102786", "lvl": "target", "msg": "<6>[    2.512424] In-situ OAM (IOAM) with IPv6"}
- {"dt": "2023-12-18T13:15:54.115076", "lvl": "target", "msg": "<6>[    2.516609] sit: IPv6, IPv4 and MPLS over IPv4 tunneling driver"}
- {"dt": "2023-12-18T13:15:54.118044", "lvl": "target", "msg": "<6>[    2.523314] NET: Registered PF_PACKET protocol family"}
- {"dt": "2023-12-18T13:15:54.119083", "lvl": "target", "msg": "<6>[    2.528183] 9pnet: Installing 9P2000 support"}
- {"dt": "2023-12-18T13:15:54.130101", "lvl": "target", "msg": "<5>[    2.532575] Key type dns_resolver registered"}
- {"dt": "2023-12-18T13:15:54.148419", "lvl": "target", "msg": "<6>[    2.541614] debug_vm_pgtable: [debug_vm_pgtable         ]: Validating architecture page table helpers"}
- {"dt": "2023-12-18T13:15:54.179363", "lvl": "target", "msg": "<4>[    2.578878] mmc0: host does not support reading read-only switch, assuming write-enable"}
- {"dt": "2023-12-18T13:15:54.181319", "lvl": "target", "msg": "<6>[    2.586414] mmc0: new SDHC card on SPI"}
- {"dt": "2023-12-18T13:15:54.183473", "lvl": "target", "msg": "<6>[    2.591859] mmcblk0: mmc0:0000 SDC   7.47 GiB "}
- {"dt": "2023-12-18T13:15:54.227684", "lvl": "target", "msg": "<4>[    2.629588] GPT:Primary header thinks Alt. header is not at the end of the disk."}
- {"dt": "2023-12-18T13:15:54.231253", "lvl": "target", "msg": "<4>[    2.636506] GPT:13918241 != 15661055"}
- {"dt": "2023-12-18T13:15:54.242098", "lvl": "target", "msg": "<4>[    2.640309] GPT:Alternate GPT header not at the end of the disk."}
- {"dt": "2023-12-18T13:15:54.243713", "lvl": "target", "msg": "<4>[    2.646583] GPT:13918241 != 15661055"}
- {"dt": "2023-12-18T13:15:54.244547", "lvl": "target", "msg": "<4>[    2.650385] GPT: Use GNU Parted to correct GPT errors."}
- {"dt": "2023-12-18T13:15:54.246084", "lvl": "target", "msg": "<6>[    2.655811]  mmcblk0: p1 p2 p3 p4"}
- {"dt": "2023-12-18T13:15:54.277866", "lvl": "target", "msg": "<6>[    2.679161] usb 1-2: new high-speed USB device number 2 using xhci_hcd"}
- {"dt": "2023-12-18T13:15:54.290973", "lvl": "target", "msg": "<6>[    2.690926] macb 10090000.ethernet eth0: PHY [10090000.ethernet-ffffffff:00] driver [Microsemi VSC8541 SyncE] (irq=POLL)"}
- {"dt": "2023-12-18T13:15:54.294086", "lvl": "target", "msg": "<6>[    2.701318] macb 10090000.ethernet eth0: configuring for phy/gmii link mode"}
- {"dt": "2023-12-18T13:15:54.514493", "lvl": "target", "msg": "<6>[    2.926375] hub 1-2:1.0: USB hub found"}
- {"dt": "2023-12-18T13:15:54.532907", "lvl": "target", "msg": "<6>[    2.929813] hub 1-2:1.0: 4 ports detected"}
- {"dt": "2023-12-18T13:15:54.613854", "lvl": "target", "msg": "<6>[    3.018597] usb 2-2: new SuperSpeed USB device number 2 using xhci_hcd"}
- {"dt": "2023-12-18T13:15:54.708622", "lvl": "target", "msg": "<6>[    3.120219] hub 2-2:1.0: USB hub found"}
- {"dt": "2023-12-18T13:15:54.724559", "lvl": "target", "msg": "<6>[    3.124169] hub 2-2:1.0: 4 ports detected"}
- {"dt": "2023-12-18T13:15:57.363869", "lvl": "target", "msg": "<6>[    5.768938] macb 10090000.ethernet eth0: Link is Up - 100Mbps/Full - flow control tx"}
- {"dt": "2023-12-18T13:15:57.380776", "lvl": "target", "msg": "<6>[    5.776220] IPv6: ADDRCONF(NETDEV_CHANGE): eth0: link becomes ready"}
- {"dt": "2023-12-18T13:15:57.410321", "lvl": "target", "msg": "<5>[    5.799151] Sending DHCP requests ., OK"}
- {"dt": "2023-12-18T13:15:57.414320", "lvl": "target", "msg": "<6>[    5.818508] IP-Config: Got DHCP answer from 192.168.66.1, my address is 192.168.66.244"}
- {"dt": "2023-12-18T13:15:57.426148", "lvl": "target", "msg": "<6>[    5.826663] IP-Config: Complete:"}
- {"dt": "2023-12-18T13:15:57.430169", "lvl": "target", "msg": "<6>[    5.830121]      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": "2023-12-18T13:15:57.441996", "lvl": "target", "msg": "<6>[    5.840721]      host=192.168.66.244, domain=, nis-domain=(none)"}
- {"dt": "2023-12-18T13:15:57.443966", "lvl": "target", "msg": "<6>[    5.846968]      bootserver=0.0.0.0, rootserver=0.0.0.0, rootpath="}
- {"dt": "2023-12-18T13:15:57.446159", "lvl": "target", "msg": "<6>[    5.846975]      nameserver0=10.1.1.1"}
- {"dt": "2023-12-18T13:15:57.461727", "lvl": "target", "msg": "<6>[    5.865929] Freeing unused kernel image (initmem) memory: 2164K"}
- {"dt": "2023-12-18T13:15:57.476496", "lvl": "target", "msg": "<6>[    5.879217] Run /init as init process"}
- {"dt": "2023-12-18T13:15:57.524476", "lvl": "target", "msg": "Starting syslogd: OK"}
- {"dt": "2023-12-18T13:15:57.526395", "lvl": "target", "msg": "Starting klogd: OK"}
- {"dt": "2023-12-18T13:15:57.540732", "lvl": "target", "msg": "Running sysctl: OK"}
- {"dt": "2023-12-18T13:15:57.556730", "lvl": "target", "msg": "Populating /dev using udev: <30>[    5.958022] udevd[97]: starting version 3.2.9"}
- {"dt": "2023-12-18T13:16:01.602081", "lvl": "target", "msg": "<5>[   10.007155] random: crng init done"}
- {"dt": "2023-12-18T13:16:01.617700", "lvl": "target", "msg": "<27>[   10.016089] udevd[97]: specified user 'tss' unknown"}
- {"dt": "2023-12-18T13:16:01.618503", "lvl": "target", "msg": "<27>[   10.020648] udevd[97]: specified group 'tss' unknown"}
- {"dt": "2023-12-18T13:16:01.621037", "lvl": "target", "msg": "<30>[   10.028033] udevd[99]: starting eudev-3.2.9"}
- {"dt": "2023-12-18T13:16:05.474044", "lvl": "target", "msg": "<6>[   13.880960] [drm] radeon kernel modesetting enabled."}
- {"dt": "2023-12-18T13:16:05.478918", "lvl": "target", "msg": "<6>[   13.886017] radeon 0000:07:00.0: enabling device (0000 -> 0003)"}
- {"dt": "2023-12-18T13:16:05.493244", "lvl": "target", "msg": "<6>[   13.892615] [drm] initializing kernel modesetting (CAICOS 0x1002:0x6779 0x1002:0x0000 0x00)."}
- {"dt": "2023-12-18T13:16:05.713959", "lvl": "target", "msg": "<6>[   14.121613] ATOM BIOS: C26401"}
- {"dt": "2023-12-18T13:16:05.717828", "lvl": "target", "msg": "<6>[   14.124257] [drm] GPU not posted. posting now..."}
- {"dt": "2023-12-18T13:16:05.729840", "lvl": "target", "msg": "<6>[   14.134483] radeon 0000:07:00.0: VRAM: 2048M 0x0000000000000000 - 0x000000007FFFFFFF (2048M used)"}
- {"dt": "2023-12-18T13:16:05.745437", "lvl": "target", "msg": "<6>[   14.142869] radeon 0000:07:00.0: GTT: 1024M 0x0000000080000000 - 0x00000000BFFFFFFF"}
- {"dt": "2023-12-18T13:16:05.747506", "lvl": "target", "msg": "<6>[   14.150771] [drm] Detected VRAM RAM=2048M, BAR=256M"}
- {"dt": "2023-12-18T13:16:05.749465", "lvl": "target", "msg": "<6>[   14.155885] [drm] RAM width 64bits DDR"}
- {"dt": "2023-12-18T13:16:05.761677", "lvl": "target", "msg": "<6>[   14.160101] [drm] radeon: 2048M of VRAM memory ready"}
- {"dt": "2023-12-18T13:16:05.763763", "lvl": "target", "msg": "<6>[   14.165101] [drm] radeon: 1024M of GTT memory ready."}
- {"dt": "2023-12-18T13:16:05.764998", "lvl": "target", "msg": "<6>[   14.170347] [drm] Loading CAICOS Microcode"}
- {"dt": "2023-12-18T13:16:05.777777", "lvl": "target", "msg": "<4>[   14.174855] radeon 0000:07:00.0: Direct firmware load for radeon/CAICOS_pfp.bin failed with error -2"}
- {"dt": "2023-12-18T13:16:05.780011", "lvl": "target", "msg": "<3>[   14.184054] ni_cp: Failed to load firmware \\\"radeon/CAICOS_pfp.bin\\\""}
- {"dt": "2023-12-18T13:16:05.793497", "lvl": "target", "msg": "<3>[   14.190457] [drm:evergreen_init [radeon]] *ERROR* Failed to load firmware!"}
- {"dt": "2023-12-18T13:16:05.795566", "lvl": "target", "msg": "<3>[   14.200775] radeon 0000:07:00.0: Fatal error during GPU init"}
- {"dt": "2023-12-18T13:16:05.797985", "lvl": "target", "msg": "<6>[   14.206678] [drm] radeon: finishing device."}
- {"dt": "2023-12-18T13:16:05.809760", "lvl": "target", "msg": "<6>[   14.218293] [drm] radeon: ttm finalized"}
- {"dt": "2023-12-18T13:16:05.813240", "lvl": "target", "msg": "<4>[   14.222277] radeon: probe of 0000:07:00.0 failed with error -2"}
- {"dt": "2023-12-18T13:16:05.843917", "lvl": "target", "msg": "done"}
- {"dt": "2023-12-18T13:16:05.860056", "lvl": "target", "msg": "Saving random seed: OK"}
- {"dt": "2023-12-18T13:16:05.876162", "lvl": "target", "msg": "Starting network: ip: RTNETLINK answers: File exists"}
- {"dt": "2023-12-18T13:16:05.877722", "lvl": "target", "msg": "FAIL"}
- {"dt": "2023-12-18T13:16:05.908166", "lvl": "target", "msg": "Starting dropbear sshd: OK"}
- {"dt": "2023-12-18T13:16:05.924124", "lvl": "target", "msg": "/bin/sh: can't access tty; job control turned off"}
- {"dt": "2023-12-18T13:16:05.926732", "lvl": "debug", "msg": "Matched prompt #10: / #"}
- {"dt": "2023-12-18T13:16:05.928289", "lvl": "results", "msg": {"case": "kernel-messages", "definition": "lava", "duration": "18.36", "extra": {"extra": []}, "level": "2.4.4.1", "namespace": "common", "result": "pass"}}
- {"dt": "2023-12-18T13:16:05.930777", "lvl": "debug", "msg": "Setting prompt string to ['/ #']"}
- {"dt": "2023-12-18T13:16:05.931710", "lvl": "debug", "msg": "end: 2.4.4.1 login-action (duration 00:00:18) [common]"}
- {"dt": "2023-12-18T13:16:05.932354", "lvl": "results", "msg": {"case": "login-action", "definition": "lava", "duration": "18.37", "extra": {"success": "No kernel warnings or errors detected."}, "level": "2.4.4.1", "namespace": "common", "result": "pass"}}
- {"dt": "2023-12-18T13:16:05.933577", "lvl": "debug", "msg": "end: 2.4.4 auto-login-action (duration 00:00:18) [common]"}
- {"dt": "2023-12-18T13:16:05.934368", "lvl": "debug", "msg": "start: 2.4.5 expect-shell-connection (timeout 00:03:46) [common]"}
- {"dt": "2023-12-18T13:16:05.935024", "lvl": "debug", "msg": "Setting prompt string to ['/ #']"}
- {"dt": "2023-12-18T13:16:05.935661", "lvl": "debug", "msg": "Forcing a shell prompt, looking for ['/ #']"}
- {"dt": "2023-12-18T13:16:05.936250", "lvl": "input", "msg": "\n"}
- {"dt": "2023-12-18T13:16:05.987193", "lvl": "target", "msg": "/ # "}
- {"dt": "2023-12-18T13:16:05.988317", "lvl": "debug", "msg": "expect-shell-connection: Wait for prompt ['/ #'] (timeout 00:05:00)"}
- {"dt": "2023-12-18T13:16:05.989688", "lvl": "debug", "msg": "Waiting using forced prompt support (timeout 00:02:30)"}
- {"dt": "2023-12-18T13:16:06.003963", "lvl": "target", "msg": ""}
- {"dt": "2023-12-18T13:16:06.005932", "lvl": "debug", "msg": "end: 2.4.5 expect-shell-connection (duration 00:00:00) [common]"}
- {"dt": "2023-12-18T13:16:06.007539", "lvl": "debug", "msg": "start: 2.4.6 export-device-env (timeout 00:03:46) [common]"}
- {"dt": "2023-12-18T13:16:06.009045", "lvl": "debug", "msg": "end: 2.4.6 export-device-env (duration 00:00:00) [common]"}
- {"dt": "2023-12-18T13:16:06.010500", "lvl": "debug", "msg": "end: 2.4 uboot-commands (duration 00:01:11) [common]"}
- {"dt": "2023-12-18T13:16:06.012069", "lvl": "info", "msg": "end: 2 uboot-action (duration 00:01:14) [common]"}
- {"dt": "2023-12-18T13:16:06.013576", "lvl": "info", "msg": "start: 3 lava-test-retry (timeout 00:01:00) [common]"}
- {"dt": "2023-12-18T13:16:06.015124", "lvl": "debug", "msg": "start: 3.1 lava-test-shell (timeout 00:01:00) [common]"}
- {"dt": "2023-12-18T13:16:06.015906", "lvl": "debug", "msg": "Using namespace: common"}
- {"dt": "2023-12-18T13:16:06.016619", "lvl": "input", "msg": "#\n"}
- {"dt": "2023-12-18T13:16:06.118118", "lvl": "target", "msg": "/ # #"}
- {"dt": "2023-12-18T13:16:06.119973", "lvl": "debug", "msg": "lava-test-shell: Wait for prompt ['/ #'] (timeout 00:01:00)"}
- {"dt": "2023-12-18T13:16:06.131893", "lvl": "target", "msg": "#"}
- {"dt": "2023-12-18T13:16:06.133397", "lvl": "debug", "msg": "Using /lava-34405"}
- {"dt": "2023-12-18T13:16:06.134359", "lvl": "input", "msg": "export SHELL=/bin/sh\n"}
- {"dt": "2023-12-18T13:16:06.236258", "lvl": "target", "msg": "/ # export SHELL=/bin/sh"}
- {"dt": "2023-12-18T13:16:06.244222", "lvl": "target", "msg": "export SHELL=/bin/sh"}
- {"dt": "2023-12-18T13:16:06.246455", "lvl": "input", "msg": ". /lava-34405/environment\n"}
- {"dt": "2023-12-18T13:16:06.349197", "lvl": "target", "msg": "/ # . /lava-34405/environment"}
- {"dt": "2023-12-18T13:16:06.356199", "lvl": "target", "msg": ". /lava-34405/environment"}
- {"dt": "2023-12-18T13:16:06.358558", "lvl": "input", "msg": "/lava-34405/bin/lava-test-runner /lava-34405/0\n"}
- {"dt": "2023-12-18T13:16:06.460502", "lvl": "target", "msg": "/ # /lava-34405/bin/lava-test-runner /lava-34405/0"}
- {"dt": "2023-12-18T13:16:06.462273", "lvl": "info", "msg": "Test shell timeout: 10s (minimum of the action and connection timeout)"}
- {"dt": "2023-12-18T13:16:06.468784", "lvl": "target", "msg": "/lava-34405/bin/lava-test-runner /lava-34405/0"}
- {"dt": "2023-12-18T13:16:06.497406", "lvl": "target", "msg": "+ export 'TESTRUN_ID=0_dmesg'"}
- {"dt": "2023-12-18T13:16:06.513930", "lvl": "target", "msg": "+ cd /lava-<8>[   14.914111] <LAVA_SIGNAL_STARTRUN 0_dmesg 34405_1.5.2.4.1>"}
- {"dt": "2023-12-18T13:16:06.515398", "lvl": "target", "msg": "34405/0/tests/0_dmesg"}
- {"dt": "2023-12-18T13:16:06.516680", "lvl": "target", "msg": "+ cat uuid"}
- {"dt": "2023-12-18T13:16:06.518054", "lvl": "target", "msg": "+ UUID=34405_1.5.2.4.1"}
- {"dt": "2023-12-18T13:16:06.519381", "lvl": "target", "msg": "+ set +x"}
- {"dt": "2023-12-18T13:16:06.521056", "lvl": "debug", "msg": "Received signal: <STARTRUN> 0_dmesg 34405_1.5.2.4.1"}
- {"dt": "2023-12-18T13:16:06.522372", "lvl": "info", "msg": "Starting test lava.0_dmesg (34405_1.5.2.4.1)"}
- {"dt": "2023-12-18T13:16:06.523568", "lvl": "info", "msg": "Skipping test definition patterns."}
- {"dt": "2023-12-18T13:16:06.524456", "lvl": "target", "msg": "+ KERNELCI_LAVA=y /bin/sh /opt/kernelci/dmesg.sh"}
- {"dt": "2023-12-18T13:16:06.548527", "lvl": "target", "msg": "<8>[   14.941194] <LAVA_SIGNAL_TESTCASE TEST_CASE_ID=crit RESULT=pass UNITS=lines MEASUREMENT=0>"}
- {"dt": "2023-12-18T13:16:06.549927", "lvl": "debug", "msg": "Received signal: <TESTCASE> TEST_CASE_ID=crit RESULT=pass UNITS=lines MEASUREMENT=0"}
- {"dt": "2023-12-18T13:16:06.551313", "lvl": "results", "msg": {"case": "crit", "definition": "0_dmesg", "endtc": ! "929", "measurement": ! "0.0", "result": "pass", "starttc": ! "929", "units": "lines"}}
- {"dt": "2023-12-18T13:16:06.564847", "lvl": "target", "msg": "<8>[   14.967238] <LAVA_SIGNAL_TESTCASE TEST_CASE_ID=alert RESULT=pass UNITS=lines MEASUREMENT=0>"}
- {"dt": "2023-12-18T13:16:06.566251", "lvl": "debug", "msg": "Received signal: <TESTCASE> TEST_CASE_ID=alert RESULT=pass UNITS=lines MEASUREMENT=0"}
- {"dt": "2023-12-18T13:16:06.567371", "lvl": "results", "msg": {"case": "alert", "definition": "0_dmesg", "endtc": ! "932", "measurement": ! "0.0", "result": "pass", "starttc": ! "932", "units": "lines"}}
- {"dt": "2023-12-18T13:16:06.593650", "lvl": "target", "msg": "<8>[   14.993594] <LAVA_SIGNAL_TESTCASE TEST_CASE_ID=emerg RESULT=pass UNITS=lines MEASUREMENT=0>"}
- {"dt": "2023-12-18T13:16:06.594834", "lvl": "target", "msg": "+ set +x"}
- {"dt": "2023-12-18T13:16:06.596572", "lvl": "debug", "msg": "Received signal: <TESTCASE> TEST_CASE_ID=emerg RESULT=pass UNITS=lines MEASUREMENT=0"}
- {"dt": "2023-12-18T13:16:06.598114", "lvl": "results", "msg": {"case": "emerg", "definition": "0_dmesg", "endtc": ! "936", "measurement": ! "0.0", "result": "pass", "starttc": ! "936", "units": "lines"}}
- {"dt": "2023-12-18T13:16:06.601085", "lvl": "target", "msg": "<8>[   15.002542] <LAVA_SIGNAL_ENDRUN 0_dmesg 34405_1.5.2.4.1>"}
- {"dt": "2023-12-18T13:16:06.602404", "lvl": "target", "msg": "<LAVA_TEST_RUNNER EXIT>"}
- {"dt": "2023-12-18T13:16:06.604179", "lvl": "debug", "msg": "Received signal: <ENDRUN> 0_dmesg 34405_1.5.2.4.1"}
- {"dt": "2023-12-18T13:16:06.605567", "lvl": "info", "msg": "Ending use of test pattern."}
- {"dt": "2023-12-18T13:16:06.606883", "lvl": "info", "msg": "Ending test lava.0_dmesg (34405_1.5.2.4.1), duration 0.08"}
- {"dt": "2023-12-18T13:16:06.608002", "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": "34405_1.5.2.4.1"}}
- {"dt": "2023-12-18T13:16:06.610096", "lvl": "info", "msg": "ok: lava_test_shell seems to have completed"}
- {"dt": "2023-12-18T13:16:06.611041", "lvl": "debug", "msg": "alert: pass\ncrit: pass\nemerg: pass\n"}
- {"dt": "2023-12-18T13:16:06.611895", "lvl": "debug", "msg": "end: 3.1 lava-test-shell (duration 00:00:01) [common]"}
- {"dt": "2023-12-18T13:16:06.612734", "lvl": "info", "msg": "end: 3 lava-test-retry (duration 00:00:01) [common]"}
- {"dt": "2023-12-18T13:16:06.613770", "lvl": "info", "msg": "start: 4 lava-test-retry (timeout 00:01:00) [common]"}
- {"dt": "2023-12-18T13:16:06.614652", "lvl": "debug", "msg": "start: 4.1 lava-test-shell (timeout 00:01:00) [common]"}
- {"dt": "2023-12-18T13:16:06.615253", "lvl": "debug", "msg": "Using namespace: common"}
- {"dt": "2023-12-18T13:16:06.615799", "lvl": "input", "msg": "#\n"}
- {"dt": "2023-12-18T13:16:06.717056", "lvl": "target", "msg": "/ # #"}
- {"dt": "2023-12-18T13:16:06.718492", "lvl": "debug", "msg": "lava-test-shell: Wait for prompt ['/ #'] (timeout 00:01:00)"}
- {"dt": "2023-12-18T13:16:06.720526", "lvl": "debug", "msg": "Using /lava-34405"}
- {"dt": "2023-12-18T13:16:06.722095", "lvl": "input", "msg": "export SHELL=/bin/sh\n"}
- {"dt": "2023-12-18T13:16:06.824070", "lvl": "target", "msg": "export SHELL=/bin/sh"}
- {"dt": "2023-12-18T13:16:06.826996", "lvl": "target", "msg": "#"}
- {"dt": "2023-12-18T13:16:06.829305", "lvl": "input", "msg": ". /lava-34405/environment\n"}
- {"dt": "2023-12-18T13:16:06.934290", "lvl": "target", "msg": "/ # export SHELL=/bin/sh. /lava-34405/environment"}
- {"dt": "2023-12-18T13:16:06.935974", "lvl": "target", "msg": ""}
- {"dt": "2023-12-18T13:16:06.937827", "lvl": "input", "msg": "/lava-34405/bin/lava-test-runner /lava-34405/1\n"}
- {"dt": "2023-12-18T13:16:07.039245", "lvl": "target", "msg": "/ # . /lava-34405/environment/lava-34405/bin/lava-test-runner /lava-34405/1"}
- {"dt": "2023-12-18T13:16:07.040076", "lvl": "info", "msg": "Test shell timeout: 10s (minimum of the action and connection timeout)"}
- {"dt": "2023-12-18T13:16:07.041428", "lvl": "target", "msg": ""}
- {"dt": "2023-12-18T13:16:07.044529", "lvl": "target", "msg": "/ # /lava-34405/bin/lava-test-runner /lava-34405/1"}
- {"dt": "2023-12-18T13:16:07.075758", "lvl": "target", "msg": "+ export 'TESTRUN_ID=1_bootrr'"}
- {"dt": "2023-12-18T13:16:07.089726", "lvl": "target", "msg": "+ cd /lava<8>[   15.491787] <LAVA_SIGNAL_STARTRUN 1_bootrr 34405_1.5.2.4.5>"}
- {"dt": "2023-12-18T13:16:07.091715", "lvl": "debug", "msg": "Received signal: <STARTRUN> 1_bootrr 34405_1.5.2.4.5"}
- {"dt": "2023-12-18T13:16:07.093048", "lvl": "info", "msg": "Starting test lava.1_bootrr (34405_1.5.2.4.5)"}
- {"dt": "2023-12-18T13:16:07.094623", "lvl": "info", "msg": "Skipping test definition patterns."}
- {"dt": "2023-12-18T13:16:07.096095", "lvl": "target", "msg": "-34405/1/tests/1_bootrr"}
- {"dt": "2023-12-18T13:16:07.096944", "lvl": "target", "msg": "+ cat uuid"}
- {"dt": "2023-12-18T13:16:07.097708", "lvl": "target", "msg": "+ UUID=34405_1.5.2.4.5"}
- {"dt": "2023-12-18T13:16:07.098450", "lvl": "target", "msg": "+ set +x"}
- {"dt": "2023-12-18T13:16:07.105585", "lvl": "target", "msg": "+ export 'PATH=/opt/bootrr/libexec/bootrr/helpers:/lava-34405/1/../bin:/sbin:/usr/sbin:/bin:/usr/bin'"}
- {"dt": "2023-12-18T13:16:07.106514", "lvl": "target", "msg": "+ cd /opt/bootrr/libexec/bootrr"}
- {"dt": "2023-12-18T13:16:07.107345", "lvl": "target", "msg": "+ sh helpers/bootrr-auto"}
- {"dt": "2023-12-18T13:16:07.109071", "lvl": "target", "msg": "/lava-34405/1/../bin/lava-test-case"}
- {"dt": "2023-12-18T13:16:07.125241", "lvl": "target", "msg": "<8>[   15.523430] <LAVA_SIGNAL_TESTCASE TEST_CASE_ID=deferred-probe-empty RESULT=pass>"}
- {"dt": "2023-12-18T13:16:07.126744", "lvl": "debug", "msg": "Received signal: <TESTCASE> TEST_CASE_ID=deferred-probe-empty RESULT=pass"}
- {"dt": "2023-12-18T13:16:07.127889", "lvl": "results", "msg": {"case": "deferred-probe-empty", "definition": "1_bootrr", "endtc": ! "980", "result": "pass", "starttc": ! "980"}}
- {"dt": "2023-12-18T13:16:07.137585", "lvl": "target", "msg": "/lava-34405/1/../bin/lava-test-case"}
- {"dt": "2023-12-18T13:16:07.141025", "lvl": "target", "msg": "<8>[   15.548440] <LAVA_SIGNAL_TESTCASE TEST_CASE_ID=all-cpus-are-online RESULT=pass>"}
- {"dt": "2023-12-18T13:16:07.142352", "lvl": "debug", "msg": "Received signal: <TESTCASE> TEST_CASE_ID=all-cpus-are-online RESULT=pass"}
- {"dt": "2023-12-18T13:16:07.143329", "lvl": "results", "msg": {"case": "all-cpus-are-online", "definition": "1_bootrr", "endtc": ! "984", "result": "pass", "starttc": ! "984"}}
- {"dt": "2023-12-18T13:16:07.153418", "lvl": "target", "msg": "/lava-34405/1/../bin/lava-test-case"}
- {"dt": "2023-12-18T13:16:07.156894", "lvl": "target", "msg": "<8>[   15.564924] <LAVA_SIGNAL_TESTCASE TEST_CASE_ID=tpm-chip-is-online RESULT=skip>"}
- {"dt": "2023-12-18T13:16:07.158274", "lvl": "debug", "msg": "Received signal: <TESTCASE> TEST_CASE_ID=tpm-chip-is-online RESULT=skip"}
- {"dt": "2023-12-18T13:16:07.159312", "lvl": "results", "msg": {"case": "tpm-chip-is-online", "definition": "1_bootrr", "endtc": ! "988", "result": "skip", "starttc": ! "988"}}
- {"dt": "2023-12-18T13:16:07.169505", "lvl": "target", "msg": "+ set +x"}
- {"dt": "2023-12-18T13:16:07.172991", "lvl": "target", "msg": "<8>[   15.579853] <LAVA_SIGNAL_ENDRUN 1_bootrr 34405_1.5.2.4.5>"}
- {"dt": "2023-12-18T13:16:07.174074", "lvl": "target", "msg": "<LAVA_TEST_RUNNER EXIT>"}
- {"dt": "2023-12-18T13:16:07.175381", "lvl": "debug", "msg": "Received signal: <ENDRUN> 1_bootrr 34405_1.5.2.4.5"}
- {"dt": "2023-12-18T13:16:07.176418", "lvl": "info", "msg": "Ending use of test pattern."}
- {"dt": "2023-12-18T13:16:07.177348", "lvl": "info", "msg": "Ending test lava.1_bootrr (34405_1.5.2.4.5), duration 0.08"}
- {"dt": "2023-12-18T13:16:07.178591", "lvl": "results", "msg": {"case": "1_bootrr", "definition": "lava", "duration": "0.09", "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": "34405_1.5.2.4.5"}}
- {"dt": "2023-12-18T13:16:07.180873", "lvl": "info", "msg": "ok: lava_test_shell seems to have completed"}
- {"dt": "2023-12-18T13:16:07.181828", "lvl": "debug", "msg": "all-cpus-are-online: pass\ndeferred-probe-empty: pass\ntpm-chip-is-online: skip\n"}
- {"dt": "2023-12-18T13:16:07.182522", "lvl": "debug", "msg": "end: 4.1 lava-test-shell (duration 00:00:01) [common]"}
- {"dt": "2023-12-18T13:16:07.183306", "lvl": "info", "msg": "end: 4 lava-test-retry (duration 00:00:01) [common]"}
- {"dt": "2023-12-18T13:16:07.184156", "lvl": "info", "msg": "start: 5 finalize (timeout 00:08:29) [common]"}
- {"dt": "2023-12-18T13:16:07.185060", "lvl": "debug", "msg": "start: 5.1 power-off (timeout 00:00:30) [common]"}
- {"dt": "2023-12-18T13:16:07.186014", "lvl": "debug", "msg": "Calling: 'nice' 'upower.sh' '--atx' 'off' '1'"}
- {"dt": "2023-12-18T13:16:11.038419", "lvl": "debug", "msg": ">> Accessing Gembird #0 USB device 015\r"}
- {"dt": "2023-12-18T13:16:11.041284", "lvl": "debug", "msg": ">> Switched outlet 1 off\r"}
- {"dt": "2023-12-18T13:16:11.048339", "lvl": "debug", "msg": "Returned 0 in 3 seconds"}
- {"dt": "2023-12-18T13:16:11.151468", "lvl": "debug", "msg": "end: 5.1 power-off (duration 00:00:04) [common]"}
- {"dt": "2023-12-18T13:16:11.153779", "lvl": "results", "msg": {"case": "power-off", "definition": "lava", "duration": "3.97", "extra": {"status": "success"}, "level": "5.1", "namespace": "common", "result": "pass"}}
- {"dt": "2023-12-18T13:16:11.158318", "lvl": "debug", "msg": "start: 5.2 read-feedback (timeout 00:08:25) [common]"}
- {"dt": "2023-12-18T13:16:11.163088", "lvl": "debug", "msg": "Listened to connection for namespace 'common' for up to 1s"}
- {"dt": "2023-12-18T13:16:11.164621", "lvl": "debug", "msg": "Listened to connection for namespace 'common' for up to 1s"}
- {"dt": "2023-12-18T13:16:12.166421", "lvl": "info", "msg": "Finalising connection for namespace 'common'"}
- {"dt": "2023-12-18T13:16:12.168795", "lvl": "info", "msg": "Disconnecting from shell: Finalise"}
- {"dt": "2023-12-18T13:16:12.169982", "lvl": "target", "msg": "/ # "}
- {"dt": "2023-12-18T13:16:12.272839", "lvl": "debug", "msg": "end: 5.2 read-feedback (duration 00:00:01) [common]"}
- {"dt": "2023-12-18T13:16:12.275055", "lvl": "info", "msg": "end: 5 finalize (duration 00:00:05) [common]"}
- {"dt": "2023-12-18T13:16:12.277400", "lvl": "info", "msg": "Cleaning after the job"}
- {"dt": "2023-12-18T13:16:12.279454", "lvl": "debug", "msg": "Cleaning up download directory: /var/lib/lava/dispatcher/tmp/34405/tftp-deploy-h2kejrfm/ramdisk"}
- {"dt": "2023-12-18T13:16:12.287978", "lvl": "debug", "msg": "Cleaning up download directory: /var/lib/lava/dispatcher/tmp/34405/tftp-deploy-h2kejrfm/kernel"}
- {"dt": "2023-12-18T13:16:12.295439", "lvl": "debug", "msg": "Cleaning up download directory: /var/lib/lava/dispatcher/tmp/34405/tftp-deploy-h2kejrfm/dtb"}
- {"dt": "2023-12-18T13:16:12.296822", "lvl": "debug", "msg": "Cleaning up download directory: /var/lib/lava/dispatcher/tmp/34405/tftp-deploy-h2kejrfm/modules"}
- {"dt": "2023-12-18T13:16:12.304934", "lvl": "info", "msg": "Override tmp directory removed at /var/lib/lava/dispatcher/tmp/34405"}
- {"dt": "2023-12-18T13:16:12.447374", "lvl": "info", "msg": "Root tmp directory removed at /var/lib/lava/dispatcher/tmp/34405"}
- {"dt": "2023-12-18T13:16:12.448436", "lvl": "info", "msg": "Job finished correctly"}
- {"dt": "2023-12-18T13:16:12.448985", "lvl": "results", "msg": {"case": "job", "definition": "lava", "result": "pass"}}
