- {"dt": "2023-11-07T19:54:18.275518", "lvl": "info", "msg": "lava-dispatcher, installed at version: 2023.01"}
- {"dt": "2023-11-07T19:54:18.276868", "lvl": "info", "msg": "start: 0 validate"}
- {"dt": "2023-11-07T19:54:18.277889", "lvl": "info", "msg": "Start time: 2023-11-07 19:54:18.277827+00:00 (UTC)"}
- {"dt": "2023-11-07T19:54:18.279101", "lvl": "debug", "msg": "Validating that http://download.automotivelinux.org/AGL/upload/ci/29389/1/raspberrypi4/initramfs-netboot-image-raspberrypi4-64.ext4.gz exists"}
- {"dt": "2023-11-07T19:54:18.501225", "lvl": "debug", "msg": "Validating that http://download.automotivelinux.org/AGL/upload/ci/29389/1/raspberrypi4/Image exists"}
- {"dt": "2023-11-07T19:54:18.722734", "lvl": "debug", "msg": "Validating that http://download.automotivelinux.org/AGL/upload/ci/29389/1/raspberrypi4/bcm2711-rpi-4-b+vc4.dtb exists"}
- {"dt": "2023-11-07T19:54:18.934613", "lvl": "debug", "msg": "Validating that http://download.automotivelinux.org/AGL/upload/ci/29389/1/raspberrypi4/agl-demo-platform-raspberrypi4-64.ext4.xz exists"}
- {"dt": "2023-11-07T19:54:19.163946", "lvl": "info", "msg": "validate duration: 0.89"}
- {"dt": "2023-11-07T19:54:19.164816", "lvl": "results", "msg": {"case": "validate", "definition": "lava", "result": "pass"}}
- {"dt": "2023-11-07T19:54:19.165935", "lvl": "info", "msg": "start: 1 nbd-deploy (timeout 01:30:00) [common]"}
- {"dt": "2023-11-07T19:54:19.166601", "lvl": "info", "msg": "Making protocol call for nbd-deploy using lava-xnbd"}
- {"dt": "2023-11-07T19:54:19.167523", "lvl": "debug", "msg": "[nbd-deploy] Checking protocol data for lava-xnbd"}
- {"dt": "2023-11-07T19:54:19.168224", "lvl": "debug", "msg": "Get a port from pool"}
- {"dt": "2023-11-07T19:54:19.169327", "lvl": "debug", "msg": "Set_port 61981"}
- {"dt": "2023-11-07T19:54:19.170318", "lvl": "debug", "msg": "start: 1.1 download-retry (timeout 01:30:00) [common]"}
- {"dt": "2023-11-07T19:54:19.171292", "lvl": "debug", "msg": "start: 1.1.1 http-download (timeout 01:30:00) [common]"}
- {"dt": "2023-11-07T19:54:19.172984", "lvl": "info", "msg": "downloading http://download.automotivelinux.org/AGL/upload/ci/29389/1/raspberrypi4/initramfs-netboot-image-raspberrypi4-64.ext4.gz"}
- {"dt": "2023-11-07T19:54:19.173757", "lvl": "debug", "msg": "saving as /var/lib/lava/dispatcher/tmp/33369/nbd-deploy-vpt9pq7o/initrd/initramfs-netboot-image-raspberrypi4-64.ext4.gz"}
- {"dt": "2023-11-07T19:54:19.174887", "lvl": "debug", "msg": "total size: 2066383 (1MB)"}
- {"dt": "2023-11-07T19:54:19.175592", "lvl": "debug", "msg": "No compression specified"}
- {"dt": "2023-11-07T19:54:19.489528", "lvl": "debug", "msg": "progress   1% (0MB)"}
- {"dt": "2023-11-07T19:54:19.688934", "lvl": "debug", "msg": "progress   6% (0MB)"}
- {"dt": "2023-11-07T19:54:19.787610", "lvl": "debug", "msg": "progress  11% (0MB)"}
- {"dt": "2023-11-07T19:54:19.884550", "lvl": "debug", "msg": "progress  17% (0MB)"}
- {"dt": "2023-11-07T19:54:19.889341", "lvl": "debug", "msg": "progress  22% (0MB)"}
- {"dt": "2023-11-07T19:54:19.895028", "lvl": "debug", "msg": "progress  28% (0MB)"}
- {"dt": "2023-11-07T19:54:19.983872", "lvl": "debug", "msg": "progress  33% (0MB)"}
- {"dt": "2023-11-07T19:54:19.989016", "lvl": "debug", "msg": "progress  38% (0MB)"}
- {"dt": "2023-11-07T19:54:19.994909", "lvl": "debug", "msg": "progress  44% (0MB)"}
- {"dt": "2023-11-07T19:54:19.999594", "lvl": "debug", "msg": "progress  49% (0MB)"}
- {"dt": "2023-11-07T19:54:20.005625", "lvl": "debug", "msg": "progress  55% (1MB)"}
- {"dt": "2023-11-07T19:54:20.085371", "lvl": "debug", "msg": "progress  60% (1MB)"}
- {"dt": "2023-11-07T19:54:20.090041", "lvl": "debug", "msg": "progress  65% (1MB)"}
- {"dt": "2023-11-07T19:54:20.095733", "lvl": "debug", "msg": "progress  71% (1MB)"}
- {"dt": "2023-11-07T19:54:20.100901", "lvl": "debug", "msg": "progress  76% (1MB)"}
- {"dt": "2023-11-07T19:54:20.184422", "lvl": "debug", "msg": "progress  82% (1MB)"}
- {"dt": "2023-11-07T19:54:20.191644", "lvl": "debug", "msg": "progress  87% (1MB)"}
- {"dt": "2023-11-07T19:54:20.198346", "lvl": "debug", "msg": "progress  93% (1MB)"}
- {"dt": "2023-11-07T19:54:20.202970", "lvl": "debug", "msg": "progress  98% (1MB)"}
- {"dt": "2023-11-07T19:54:20.206806", "lvl": "info", "msg": "1MB downloaded in 1.03s (1.91MB/s)"}
- {"dt": "2023-11-07T19:54:20.208046", "lvl": "debug", "msg": "end: 1.1.1 http-download (duration 00:00:01) [common]"}
- {"dt": "2023-11-07T19:54:20.208769", "lvl": "results", "msg": {"case": "http-download", "definition": "lava", "duration": "1.04", "extra": {"label": "initrd", "md5sum": "c5b121286549e8796d531fa182aaca46", "sha256sum": "2260fdff0566811cc0492e1497b6d00b03cc74b3af8dae4a5d2bc87462eb08e5", "sha512sum": "dfd43df2c86cf26fac074b2441c6c9896bc89d59d91a63e5f81eb9fcb7770ca08dd2e6254d2eda8a182fe074a0f7a4e14e5ebdbfea6fc9f1f222f59a93e2413e", "size": ! "2066383"}, "level": "1.1.1", "namespace": "common", "result": "pass"}}
- {"dt": "2023-11-07T19:54:20.210119", "lvl": "debug", "msg": "end: 1.1 download-retry (duration 00:00:01) [common]"}
- {"dt": "2023-11-07T19:54:20.210758", "lvl": "debug", "msg": "start: 1.2 download-retry (timeout 01:29:59) [common]"}
- {"dt": "2023-11-07T19:54:20.211378", "lvl": "debug", "msg": "start: 1.2.1 http-download (timeout 01:29:59) [common]"}
- {"dt": "2023-11-07T19:54:20.212417", "lvl": "info", "msg": "downloading http://download.automotivelinux.org/AGL/upload/ci/29389/1/raspberrypi4/Image"}
- {"dt": "2023-11-07T19:54:20.213063", "lvl": "debug", "msg": "saving as /var/lib/lava/dispatcher/tmp/33369/nbd-deploy-vpt9pq7o/kernel/Image"}
- {"dt": "2023-11-07T19:54:20.213530", "lvl": "debug", "msg": "total size: 24244736 (23MB)"}
- {"dt": "2023-11-07T19:54:20.213972", "lvl": "debug", "msg": "No compression specified"}
- {"dt": "2023-11-07T19:54:20.527150", "lvl": "debug", "msg": "progress   0% (0MB)"}
- {"dt": "2023-11-07T19:54:21.121835", "lvl": "debug", "msg": "progress   5% (1MB)"}
- {"dt": "2023-11-07T19:54:21.337382", "lvl": "debug", "msg": "progress  10% (2MB)"}
- {"dt": "2023-11-07T19:54:21.548424", "lvl": "debug", "msg": "progress  15% (3MB)"}
- {"dt": "2023-11-07T19:54:21.759239", "lvl": "debug", "msg": "progress  20% (4MB)"}
- {"dt": "2023-11-07T19:54:22.021756", "lvl": "debug", "msg": "progress  25% (5MB)"}
- {"dt": "2023-11-07T19:54:22.232694", "lvl": "debug", "msg": "progress  30% (6MB)"}
- {"dt": "2023-11-07T19:54:22.436547", "lvl": "debug", "msg": "progress  35% (8MB)"}
- {"dt": "2023-11-07T19:54:22.635852", "lvl": "debug", "msg": "progress  40% (9MB)"}
- {"dt": "2023-11-07T19:54:22.823924", "lvl": "debug", "msg": "progress  45% (10MB)"}
- {"dt": "2023-11-07T19:54:22.971378", "lvl": "debug", "msg": "progress  50% (11MB)"}
- {"dt": "2023-11-07T19:54:23.165107", "lvl": "debug", "msg": "progress  55% (12MB)"}
- {"dt": "2023-11-07T19:54:23.343066", "lvl": "debug", "msg": "progress  60% (13MB)"}
- {"dt": "2023-11-07T19:54:23.506731", "lvl": "debug", "msg": "progress  65% (15MB)"}
- {"dt": "2023-11-07T19:54:23.650799", "lvl": "debug", "msg": "progress  70% (16MB)"}
- {"dt": "2023-11-07T19:54:23.810839", "lvl": "debug", "msg": "progress  75% (17MB)"}
- {"dt": "2023-11-07T19:54:23.949269", "lvl": "debug", "msg": "progress  80% (18MB)"}
- {"dt": "2023-11-07T19:54:24.075730", "lvl": "debug", "msg": "progress  85% (19MB)"}
- {"dt": "2023-11-07T19:54:24.235945", "lvl": "debug", "msg": "progress  90% (20MB)"}
- {"dt": "2023-11-07T19:54:24.356160", "lvl": "debug", "msg": "progress  95% (21MB)"}
- {"dt": "2023-11-07T19:54:24.572167", "lvl": "debug", "msg": "progress 100% (23MB)"}
- {"dt": "2023-11-07T19:54:24.575395", "lvl": "info", "msg": "23MB downloaded in 4.36s (5.30MB/s)"}
- {"dt": "2023-11-07T19:54:24.576637", "lvl": "debug", "msg": "end: 1.2.1 http-download (duration 00:00:04) [common]"}
- {"dt": "2023-11-07T19:54:24.577327", "lvl": "results", "msg": {"case": "http-download", "definition": "lava", "duration": "4.37", "extra": {"label": "kernel", "md5sum": "66b8fd214f2f7be835a17bec1ca3c3bb", "sha256sum": "67454e961704ae6231674c1ca03d89f0abc16886ccb74d10b3da661d5e311c4b", "sha512sum": "049ce1c442751dd48a568a1f62bb4e6217ad3d57a570b9c4913020b9a701525c2bfa22a79d5eca35a1cc0386fbf528fe2df0bbfa219cf0514731439bc8b4fcda", "size": ! "24244736"}, "level": "1.2.1", "namespace": "common", "result": "pass"}}
- {"dt": "2023-11-07T19:54:24.578880", "lvl": "debug", "msg": "end: 1.2 download-retry (duration 00:00:04) [common]"}
- {"dt": "2023-11-07T19:54:24.579657", "lvl": "debug", "msg": "start: 1.3 download-retry (timeout 01:29:55) [common]"}
- {"dt": "2023-11-07T19:54:24.580568", "lvl": "debug", "msg": "start: 1.3.1 http-download (timeout 01:29:55) [common]"}
- {"dt": "2023-11-07T19:54:24.581679", "lvl": "info", "msg": "downloading http://download.automotivelinux.org/AGL/upload/ci/29389/1/raspberrypi4/bcm2711-rpi-4-b+vc4.dtb"}
- {"dt": "2023-11-07T19:54:24.582367", "lvl": "debug", "msg": "saving as /var/lib/lava/dispatcher/tmp/33369/nbd-deploy-vpt9pq7o/dtb/bcm2711-rpi-4-b+vc4.dtb"}
- {"dt": "2023-11-07T19:54:24.582902", "lvl": "debug", "msg": "total size: 52323 (0MB)"}
- {"dt": "2023-11-07T19:54:24.583423", "lvl": "debug", "msg": "No compression specified"}
- {"dt": "2023-11-07T19:54:24.882852", "lvl": "debug", "msg": "progress  62% (0MB)"}
- {"dt": "2023-11-07T19:54:24.979451", "lvl": "debug", "msg": "progress 100% (0MB)"}
- {"dt": "2023-11-07T19:54:24.981065", "lvl": "info", "msg": "0MB downloaded in 0.40s (0.13MB/s)"}
- {"dt": "2023-11-07T19:54:24.982205", "lvl": "debug", "msg": "end: 1.3.1 http-download (duration 00:00:00) [common]"}
- {"dt": "2023-11-07T19:54:24.982946", "lvl": "results", "msg": {"case": "http-download", "definition": "lava", "duration": "0.40", "extra": {"label": "dtb", "md5sum": "d7a4cb0280ed4fd58429b66aa7c47c35", "sha256sum": "269fa995628c3cc9d2c61733476fd57a7097aabb09c0ea3834733ad1dccd8a34", "sha512sum": "ddc53aa3b527bd7de40f6adc176407cacfc66ae7c52e4776c33116167e306b83e4408eed562c53c91c57bab665eea1d917c62aa781a363ce5253d43c380d20ca", "size": ! "52323"}, "level": "1.3.1", "namespace": "common", "result": "pass"}}
- {"dt": "2023-11-07T19:54:24.984465", "lvl": "debug", "msg": "end: 1.3 download-retry (duration 00:00:00) [common]"}
- {"dt": "2023-11-07T19:54:24.985295", "lvl": "debug", "msg": "start: 1.4 download-retry (timeout 01:29:54) [common]"}
- {"dt": "2023-11-07T19:54:24.986079", "lvl": "debug", "msg": "start: 1.4.1 http-download (timeout 01:29:54) [common]"}
- {"dt": "2023-11-07T19:54:24.987149", "lvl": "info", "msg": "downloading http://download.automotivelinux.org/AGL/upload/ci/29389/1/raspberrypi4/agl-demo-platform-raspberrypi4-64.ext4.xz"}
- {"dt": "2023-11-07T19:54:24.987833", "lvl": "debug", "msg": "saving as /var/lib/lava/dispatcher/tmp/33369/nbd-deploy-vpt9pq7o/nbdroot/agl-demo-platform-raspberrypi4-64.ext4"}
- {"dt": "2023-11-07T19:54:24.988445", "lvl": "debug", "msg": "total size: 795770124 (758MB)"}
- {"dt": "2023-11-07T19:54:24.989000", "lvl": "info", "msg": "Using unxz to decompress xz"}
- {"dt": "2023-11-07T19:54:25.305162", "lvl": "debug", "msg": "progress   0% (0MB)"}
- {"dt": "2023-11-07T19:54:35.428002", "lvl": "debug", "msg": "progress   5% (37MB)"}
- {"dt": "2023-11-07T19:54:44.727888", "lvl": "debug", "msg": "progress  10% (75MB)"}
- {"dt": "2023-11-07T19:54:54.700846", "lvl": "debug", "msg": "progress  15% (113MB)"}
- {"dt": "2023-11-07T19:55:07.858017", "lvl": "debug", "msg": "progress  20% (151MB)"}
- {"dt": "2023-11-07T19:55:13.178014", "lvl": "debug", "msg": "progress  25% (189MB)"}
- {"dt": "2023-11-07T19:55:27.209237", "lvl": "debug", "msg": "progress  30% (227MB)"}
- {"dt": "2023-11-07T19:55:37.430619", "lvl": "debug", "msg": "progress  35% (265MB)"}
- {"dt": "2023-11-07T19:55:43.675759", "lvl": "debug", "msg": "progress  40% (303MB)"}
- {"dt": "2023-11-07T19:55:49.345423", "lvl": "debug", "msg": "progress  45% (341MB)"}
- {"dt": "2023-11-07T19:55:54.659903", "lvl": "debug", "msg": "progress  50% (379MB)"}
- {"dt": "2023-11-07T19:55:59.395375", "lvl": "debug", "msg": "progress  55% (417MB)"}
- {"dt": "2023-11-07T19:56:05.091178", "lvl": "debug", "msg": "progress  60% (455MB)"}
- {"dt": "2023-11-07T19:56:16.250484", "lvl": "debug", "msg": "progress  65% (493MB)"}
- {"dt": "2023-11-07T19:56:31.763578", "lvl": "debug", "msg": "progress  70% (531MB)"}
- {"dt": "2023-11-07T19:56:41.567505", "lvl": "debug", "msg": "progress  75% (569MB)"}
- {"dt": "2023-11-07T19:56:52.673087", "lvl": "debug", "msg": "progress  80% (607MB)"}
- {"dt": "2023-11-07T19:57:02.833173", "lvl": "debug", "msg": "progress  85% (645MB)"}
- {"dt": "2023-11-07T19:57:14.331224", "lvl": "debug", "msg": "progress  90% (683MB)"}
- {"dt": "2023-11-07T19:57:23.312744", "lvl": "debug", "msg": "progress  95% (720MB)"}
- {"dt": "2023-11-07T19:57:34.378306", "lvl": "debug", "msg": "progress 100% (758MB)"}
- {"dt": "2023-11-07T19:57:38.689305", "lvl": "info", "msg": "758MB downloaded in 193.70s (3.92MB/s)"}
- {"dt": "2023-11-07T19:57:38.691687", "lvl": "debug", "msg": "end: 1.4.1 http-download (duration 00:03:14) [common]"}
- {"dt": "2023-11-07T19:57:38.692980", "lvl": "results", "msg": {"case": "http-download", "definition": "lava", "duration": "193.71", "extra": {"label": "nbdroot", "md5sum": "f30bddd3dcfba78c073a44ced2183c1d", "sha256sum": "c2efac279d0f3f4bdcdce668562a096e01c6eb7971911bde34d36583d65e7449", "sha512sum": "3864c78ae1ae904a6e714783a45c7379aebf821b162b7d6176fa777239cec0922a2da2521e0fd6b40af7e9026b027104d51b4b31a85855a48e0b4837eef8e853", "size": ! "795770124"}, "level": "1.4.1", "namespace": "common", "result": "pass"}}
- {"dt": "2023-11-07T19:57:38.696004", "lvl": "debug", "msg": "end: 1.4 download-retry (duration 00:03:14) [common]"}
- {"dt": "2023-11-07T19:57:38.697411", "lvl": "debug", "msg": "start: 1.5 lava-overlay (timeout 01:26:40) [common]"}
- {"dt": "2023-11-07T19:57:38.700428", "lvl": "debug", "msg": "[common] Preparing overlay tarball in /var/lib/lava/dispatcher/tmp/33369/lava-overlay-8gfwny5n"}
- {"dt": "2023-11-07T19:57:38.702957", "lvl": "debug", "msg": "makedir: /var/lib/lava/dispatcher/tmp/33369/lava-overlay-8gfwny5n/lava-33369/bin"}
- {"dt": "2023-11-07T19:57:38.705040", "lvl": "debug", "msg": "makedir: /var/lib/lava/dispatcher/tmp/33369/lava-overlay-8gfwny5n/lava-33369/tests"}
- {"dt": "2023-11-07T19:57:38.706140", "lvl": "debug", "msg": "makedir: /var/lib/lava/dispatcher/tmp/33369/lava-overlay-8gfwny5n/lava-33369/results"}
- {"dt": "2023-11-07T19:57:38.707144", "lvl": "debug", "msg": "Creating /var/lib/lava/dispatcher/tmp/33369/lava-overlay-8gfwny5n/lava-33369/bin/lava-add-keys"}
- {"dt": "2023-11-07T19:57:38.708596", "lvl": "debug", "msg": "Creating /var/lib/lava/dispatcher/tmp/33369/lava-overlay-8gfwny5n/lava-33369/bin/lava-add-sources"}
- {"dt": "2023-11-07T19:57:38.709984", "lvl": "debug", "msg": "Creating /var/lib/lava/dispatcher/tmp/33369/lava-overlay-8gfwny5n/lava-33369/bin/lava-background-process-start"}
- {"dt": "2023-11-07T19:57:38.711346", "lvl": "debug", "msg": "Creating /var/lib/lava/dispatcher/tmp/33369/lava-overlay-8gfwny5n/lava-33369/bin/lava-background-process-stop"}
- {"dt": "2023-11-07T19:57:38.712750", "lvl": "debug", "msg": "Creating /var/lib/lava/dispatcher/tmp/33369/lava-overlay-8gfwny5n/lava-33369/bin/lava-common-functions"}
- {"dt": "2023-11-07T19:57:38.714089", "lvl": "debug", "msg": "Creating /var/lib/lava/dispatcher/tmp/33369/lava-overlay-8gfwny5n/lava-33369/bin/lava-echo-ipv4"}
- {"dt": "2023-11-07T19:57:38.715435", "lvl": "debug", "msg": "Creating /var/lib/lava/dispatcher/tmp/33369/lava-overlay-8gfwny5n/lava-33369/bin/lava-install-packages"}
- {"dt": "2023-11-07T19:57:38.716891", "lvl": "debug", "msg": "Creating /var/lib/lava/dispatcher/tmp/33369/lava-overlay-8gfwny5n/lava-33369/bin/lava-installed-packages"}
- {"dt": "2023-11-07T19:57:38.718242", "lvl": "debug", "msg": "Creating /var/lib/lava/dispatcher/tmp/33369/lava-overlay-8gfwny5n/lava-33369/bin/lava-os-build"}
- {"dt": "2023-11-07T19:57:38.719569", "lvl": "debug", "msg": "Creating /var/lib/lava/dispatcher/tmp/33369/lava-overlay-8gfwny5n/lava-33369/bin/lava-probe-channel"}
- {"dt": "2023-11-07T19:57:38.720941", "lvl": "debug", "msg": "Creating /var/lib/lava/dispatcher/tmp/33369/lava-overlay-8gfwny5n/lava-33369/bin/lava-probe-ip"}
- {"dt": "2023-11-07T19:57:38.722287", "lvl": "debug", "msg": "Creating /var/lib/lava/dispatcher/tmp/33369/lava-overlay-8gfwny5n/lava-33369/bin/lava-target-ip"}
- {"dt": "2023-11-07T19:57:38.723617", "lvl": "debug", "msg": "Creating /var/lib/lava/dispatcher/tmp/33369/lava-overlay-8gfwny5n/lava-33369/bin/lava-target-mac"}
- {"dt": "2023-11-07T19:57:38.724995", "lvl": "debug", "msg": "Creating /var/lib/lava/dispatcher/tmp/33369/lava-overlay-8gfwny5n/lava-33369/bin/lava-target-storage"}
- {"dt": "2023-11-07T19:57:38.726342", "lvl": "debug", "msg": "Creating /var/lib/lava/dispatcher/tmp/33369/lava-overlay-8gfwny5n/lava-33369/bin/lava-test-case"}
- {"dt": "2023-11-07T19:57:38.727683", "lvl": "debug", "msg": "Creating /var/lib/lava/dispatcher/tmp/33369/lava-overlay-8gfwny5n/lava-33369/bin/lava-test-event"}
- {"dt": "2023-11-07T19:57:38.729080", "lvl": "debug", "msg": "Creating /var/lib/lava/dispatcher/tmp/33369/lava-overlay-8gfwny5n/lava-33369/bin/lava-test-feedback"}
- {"dt": "2023-11-07T19:57:38.730425", "lvl": "debug", "msg": "Creating /var/lib/lava/dispatcher/tmp/33369/lava-overlay-8gfwny5n/lava-33369/bin/lava-test-raise"}
- {"dt": "2023-11-07T19:57:38.731812", "lvl": "debug", "msg": "Creating /var/lib/lava/dispatcher/tmp/33369/lava-overlay-8gfwny5n/lava-33369/bin/lava-test-reference"}
- {"dt": "2023-11-07T19:57:38.733221", "lvl": "debug", "msg": "Creating /var/lib/lava/dispatcher/tmp/33369/lava-overlay-8gfwny5n/lava-33369/bin/lava-test-runner"}
- {"dt": "2023-11-07T19:57:38.734561", "lvl": "debug", "msg": "Creating /var/lib/lava/dispatcher/tmp/33369/lava-overlay-8gfwny5n/lava-33369/bin/lava-test-set"}
- {"dt": "2023-11-07T19:57:38.735932", "lvl": "debug", "msg": "Creating /var/lib/lava/dispatcher/tmp/33369/lava-overlay-8gfwny5n/lava-33369/bin/lava-test-shell"}
- {"dt": "2023-11-07T19:57:38.737417", "lvl": "debug", "msg": "Updating /var/lib/lava/dispatcher/tmp/33369/lava-overlay-8gfwny5n/lava-33369/bin/lava-install-packages (oe)"}
- {"dt": "2023-11-07T19:57:38.738981", "lvl": "debug", "msg": "Updating /var/lib/lava/dispatcher/tmp/33369/lava-overlay-8gfwny5n/lava-33369/bin/lava-installed-packages (oe)"}
- {"dt": "2023-11-07T19:57:38.740389", "lvl": "debug", "msg": "Creating /var/lib/lava/dispatcher/tmp/33369/lava-overlay-8gfwny5n/lava-33369/environment"}
- {"dt": "2023-11-07T19:57:38.741508", "lvl": "debug", "msg": "LAVA metadata"}
- {"dt": "2023-11-07T19:57:38.742263", "lvl": "debug", "msg": "- LAVA_JOB_ID=33369"}
- {"dt": "2023-11-07T19:57:38.742902", "lvl": "debug", "msg": "- LAVA_DISPATCHER_IP=192.168.66.1"}
- {"dt": "2023-11-07T19:57:38.743928", "lvl": "debug", "msg": "start: 1.5.1 ssh-authorize (timeout 01:26:40) [common]"}
- {"dt": "2023-11-07T19:57:38.746285", "lvl": "debug", "msg": "end: 1.5.1 ssh-authorize (duration 00:00:00) [common]"}
- {"dt": "2023-11-07T19:57:38.747185", "lvl": "debug", "msg": "start: 1.5.2 lava-vland-overlay (timeout 01:26:40) [common]"}
- {"dt": "2023-11-07T19:57:38.747875", "lvl": "debug", "msg": "skipped lava-vland-overlay"}
- {"dt": "2023-11-07T19:57:38.748680", "lvl": "debug", "msg": "end: 1.5.2 lava-vland-overlay (duration 00:00:00) [common]"}
- {"dt": "2023-11-07T19:57:38.749458", "lvl": "debug", "msg": "start: 1.5.3 lava-multinode-overlay (timeout 01:26:40) [common]"}
- {"dt": "2023-11-07T19:57:38.750067", "lvl": "debug", "msg": "skipped lava-multinode-overlay"}
- {"dt": "2023-11-07T19:57:38.750781", "lvl": "debug", "msg": "end: 1.5.3 lava-multinode-overlay (duration 00:00:00) [common]"}
- {"dt": "2023-11-07T19:57:38.751647", "lvl": "debug", "msg": "start: 1.5.4 test-definition (timeout 01:26:40) [common]"}
- {"dt": "2023-11-07T19:57:38.752474", "lvl": "info", "msg": "Loading test definitions"}
- {"dt": "2023-11-07T19:57:38.753385", "lvl": "debug", "msg": "start: 1.5.4.1 git-repo-action (timeout 01:26:40) [common]"}
- {"dt": "2023-11-07T19:57:38.754104", "lvl": "debug", "msg": "Using /lava-33369 at stage 0"}
- {"dt": "2023-11-07T19:57:38.755084", "lvl": "info", "msg": "Fetching tests from https://git.automotivelinux.org/src/qa-testdefinitions"}
- {"dt": "2023-11-07T19:57:38.755860", "lvl": "debug", "msg": "Running '/usr/bin/git clone --depth=1 https://git.automotivelinux.org/src/qa-testdefinitions /var/lib/lava/dispatcher/tmp/33369/lava-overlay-8gfwny5n/lava-33369/0/tests/0_network-veth'"}
- {"dt": "2023-11-07T19:57:39.482069", "lvl": "debug", "msg": "Tests stored (tmp) in /var/lib/lava/dispatcher/tmp/33369/lava-overlay-8gfwny5n/lava-33369/0/tests/0_network-veth/test-suites/short-smoke/network-veth.yaml"}
- {"dt": "2023-11-07T19:57:39.487699", "lvl": "debug", "msg": "uuid=33369_1.5.4.1 testdef=None"}
- {"dt": "2023-11-07T19:57:39.489084", "lvl": "debug", "msg": "end: 1.5.4.1 git-repo-action (duration 00:00:01) [common]"}
- {"dt": "2023-11-07T19:57:39.489969", "lvl": "results", "msg": {"case": "git-repo-action", "definition": "lava", "duration": "0.74", "extra": {"commit": "b4aef27928ee7897aae9de1b5fa47d0aad61803c", "path": "test-suites/short-smoke/network-veth.yaml", "repository": "https://git.automotivelinux.org/src/qa-testdefinitions"}, "level": "1.5.4.1", "namespace": "common", "result": "pass"}}
- {"dt": "2023-11-07T19:57:39.492104", "lvl": "debug", "msg": "start: 1.5.4.2 test-overlay (timeout 01:26:40) [common]"}
- {"dt": "2023-11-07T19:57:39.498264", "lvl": "debug", "msg": "end: 1.5.4.2 test-overlay (duration 00:00:00) [common]"}
- {"dt": "2023-11-07T19:57:39.498919", "lvl": "results", "msg": {"case": "test-overlay", "definition": "lava", "duration": "0.01", "extra": {"from": "git", "name": "network-veth", "path": "test-suites/short-smoke/network-veth.yaml", "repository": "https://git.automotivelinux.org/src/qa-testdefinitions", "uuid": "33369_1.5.4.1"}, "level": "1.5.4.2", "namespace": "common", "result": "pass"}}
- {"dt": "2023-11-07T19:57:39.500411", "lvl": "debug", "msg": "start: 1.5.4.3 test-install-overlay (timeout 01:26:40) [common]"}
- {"dt": "2023-11-07T19:57:39.506339", "lvl": "debug", "msg": "end: 1.5.4.3 test-install-overlay (duration 00:00:00) [common]"}
- {"dt": "2023-11-07T19:57:39.507025", "lvl": "results", "msg": {"case": "test-install-overlay", "definition": "lava", "duration": "0.01", "extra": {"from": "git", "name": "network-veth", "path": "test-suites/short-smoke/network-veth.yaml", "repository": "https://git.automotivelinux.org/src/qa-testdefinitions", "skipped test-install-overlay": "33369_1.5.4.1", "uuid": "33369_1.5.4.1"}, "level": "1.5.4.3", "namespace": "common", "result": "pass"}}
- {"dt": "2023-11-07T19:57:39.508585", "lvl": "debug", "msg": "start: 1.5.4.4 test-runscript-overlay (timeout 01:26:40) [common]"}
- {"dt": "2023-11-07T19:57:39.514206", "lvl": "debug", "msg": "runner path: /var/lib/lava/dispatcher/tmp/33369/lava-overlay-8gfwny5n/lava-33369/0/tests/0_network-veth test_uuid 33369_1.5.4.1"}
- {"dt": "2023-11-07T19:57:39.515732", "lvl": "debug", "msg": "end: 1.5.4.4 test-runscript-overlay (duration 00:00:00) [common]"}
- {"dt": "2023-11-07T19:57:39.516521", "lvl": "results", "msg": {"case": "test-runscript-overlay", "definition": "lava", "duration": "0.01", "extra": {"filename": "/var/lib/lava/dispatcher/tmp/33369/lava-overlay-8gfwny5n/lava-33369/0/tests/0_network-veth/run.sh", "from": "git", "name": "network-veth", "path": "test-suites/short-smoke/network-veth.yaml", "repository": "https://git.automotivelinux.org/src/qa-testdefinitions", "uuid": "33369_1.5.4.1"}, "level": "1.5.4.4", "namespace": "common", "result": "pass"}}
- {"dt": "2023-11-07T19:57:39.518020", "lvl": "debug", "msg": "start: 1.5.4.5 git-repo-action (timeout 01:26:40) [common]"}
- {"dt": "2023-11-07T19:57:39.518641", "lvl": "debug", "msg": "Using /lava-33369 at stage 1"}
- {"dt": "2023-11-07T19:57:39.519481", "lvl": "info", "msg": "Fetching tests from https://git.automotivelinux.org/src/qa-testdefinitions"}
- {"dt": "2023-11-07T19:57:39.520124", "lvl": "debug", "msg": "Running '/usr/bin/git clone --depth=1 https://git.automotivelinux.org/src/qa-testdefinitions /var/lib/lava/dispatcher/tmp/33369/lava-overlay-8gfwny5n/lava-33369/1/tests/1_ci-busybox'"}
- {"dt": "2023-11-07T19:57:40.254954", "lvl": "debug", "msg": "Removing '.git' directory in /var/lib/lava/dispatcher/tmp/33369/lava-overlay-8gfwny5n/lava-33369/1/tests/1_ci-busybox"}
- {"dt": "2023-11-07T19:57:40.271799", "lvl": "debug", "msg": "Tests stored (tmp) in /var/lib/lava/dispatcher/tmp/33369/lava-overlay-8gfwny5n/lava-33369/1/tests/1_ci-busybox/test-suites/short-smoke/busybox.yaml"}
- {"dt": "2023-11-07T19:57:40.276828", "lvl": "debug", "msg": "uuid=33369_1.5.4.5 testdef={'testdef_pattern': {'pattern': '^(?P<test_case_id>[a-zA-Z0-9_-]+):\\\\s(?P<result>\\\\w+)', 'fixupdict': {'PASS': 'pass', 'FAIL': 'fail'}}}"}
- {"dt": "2023-11-07T19:57:40.278319", "lvl": "debug", "msg": "end: 1.5.4.5 git-repo-action (duration 00:00:01) [common]"}
- {"dt": "2023-11-07T19:57:40.279384", "lvl": "results", "msg": {"case": "git-repo-action", "definition": "lava", "duration": "0.76", "extra": {"commit": "b4aef27928ee7897aae9de1b5fa47d0aad61803c", "path": "test-suites/short-smoke/busybox.yaml", "repository": "https://git.automotivelinux.org/src/qa-testdefinitions"}, "level": "1.5.4.5", "namespace": "common", "result": "pass"}}
- {"dt": "2023-11-07T19:57:40.281342", "lvl": "debug", "msg": "start: 1.5.4.6 test-overlay (timeout 01:26:39) [common]"}
- {"dt": "2023-11-07T19:57:40.287146", "lvl": "debug", "msg": "end: 1.5.4.6 test-overlay (duration 00:00:00) [common]"}
- {"dt": "2023-11-07T19:57:40.287838", "lvl": "results", "msg": {"case": "test-overlay", "definition": "lava", "duration": "0.01", "extra": {"from": "git", "name": "ci-busybox", "path": "test-suites/short-smoke/busybox.yaml", "repository": "https://git.automotivelinux.org/src/qa-testdefinitions", "uuid": "33369_1.5.4.5"}, "level": "1.5.4.6", "namespace": "common", "result": "pass"}}
- {"dt": "2023-11-07T19:57:40.289487", "lvl": "debug", "msg": "start: 1.5.4.7 test-install-overlay (timeout 01:26:39) [common]"}
- {"dt": "2023-11-07T19:57:40.297193", "lvl": "debug", "msg": "end: 1.5.4.7 test-install-overlay (duration 00:00:00) [common]"}
- {"dt": "2023-11-07T19:57:40.297896", "lvl": "results", "msg": {"case": "test-install-overlay", "definition": "lava", "duration": "0.01", "extra": {"from": "git", "name": "ci-busybox", "path": "test-suites/short-smoke/busybox.yaml", "repository": "https://git.automotivelinux.org/src/qa-testdefinitions", "skipped test-install-overlay": "33369_1.5.4.5", "uuid": "33369_1.5.4.5"}, "level": "1.5.4.7", "namespace": "common", "result": "pass"}}
- {"dt": "2023-11-07T19:57:40.299481", "lvl": "debug", "msg": "start: 1.5.4.8 test-runscript-overlay (timeout 01:26:39) [common]"}
- {"dt": "2023-11-07T19:57:40.307214", "lvl": "debug", "msg": "runner path: /var/lib/lava/dispatcher/tmp/33369/lava-overlay-8gfwny5n/lava-33369/1/tests/1_ci-busybox test_uuid 33369_1.5.4.5"}
- {"dt": "2023-11-07T19:57:40.308918", "lvl": "debug", "msg": "end: 1.5.4.8 test-runscript-overlay (duration 00:00:00) [common]"}
- {"dt": "2023-11-07T19:57:40.309692", "lvl": "results", "msg": {"case": "test-runscript-overlay", "definition": "lava", "duration": "0.01", "extra": {"filename": "/var/lib/lava/dispatcher/tmp/33369/lava-overlay-8gfwny5n/lava-33369/1/tests/1_ci-busybox/run.sh", "from": "git", "name": "ci-busybox", "path": "test-suites/short-smoke/busybox.yaml", "repository": "https://git.automotivelinux.org/src/qa-testdefinitions", "uuid": "33369_1.5.4.5"}, "level": "1.5.4.8", "namespace": "common", "result": "pass"}}
- {"dt": "2023-11-07T19:57:40.311302", "lvl": "debug", "msg": "start: 1.5.4.9 git-repo-action (timeout 01:26:39) [common]"}
- {"dt": "2023-11-07T19:57:40.312049", "lvl": "debug", "msg": "Using /lava-33369 at stage 1"}
- {"dt": "2023-11-07T19:57:40.313223", "lvl": "info", "msg": "Fetching tests from https://git.automotivelinux.org/src/qa-testdefinitions"}
- {"dt": "2023-11-07T19:57:40.314016", "lvl": "debug", "msg": "Running '/usr/bin/git clone --depth=1 https://git.automotivelinux.org/src/qa-testdefinitions /var/lib/lava/dispatcher/tmp/33369/lava-overlay-8gfwny5n/lava-33369/1/tests/2_ci-smoke-tests-basic'"}
- {"dt": "2023-11-07T19:57:41.024675", "lvl": "debug", "msg": "Removing '.git' directory in /var/lib/lava/dispatcher/tmp/33369/lava-overlay-8gfwny5n/lava-33369/1/tests/2_ci-smoke-tests-basic"}
- {"dt": "2023-11-07T19:57:41.038341", "lvl": "debug", "msg": "Tests stored (tmp) in /var/lib/lava/dispatcher/tmp/33369/lava-overlay-8gfwny5n/lava-33369/1/tests/2_ci-smoke-tests-basic/test-suites/short-smoke/smoke-tests-basic.yaml"}
- {"dt": "2023-11-07T19:57:41.041290", "lvl": "debug", "msg": "uuid=33369_1.5.4.9 testdef=None"}
- {"dt": "2023-11-07T19:57:41.042361", "lvl": "debug", "msg": "end: 1.5.4.9 git-repo-action (duration 00:00:01) [common]"}
- {"dt": "2023-11-07T19:57:41.043089", "lvl": "results", "msg": {"case": "git-repo-action", "definition": "lava", "duration": "0.73", "extra": {"commit": "b4aef27928ee7897aae9de1b5fa47d0aad61803c", "path": "test-suites/short-smoke/smoke-tests-basic.yaml", "repository": "https://git.automotivelinux.org/src/qa-testdefinitions"}, "level": "1.5.4.9", "namespace": "common", "result": "pass"}}
- {"dt": "2023-11-07T19:57:41.044619", "lvl": "debug", "msg": "start: 1.5.4.10 test-overlay (timeout 01:26:38) [common]"}
- {"dt": "2023-11-07T19:57:41.050068", "lvl": "debug", "msg": "end: 1.5.4.10 test-overlay (duration 00:00:00) [common]"}
- {"dt": "2023-11-07T19:57:41.050804", "lvl": "results", "msg": {"case": "test-overlay", "definition": "lava", "duration": "0.01", "extra": {"from": "git", "name": "ci-smoke-tests-basic", "path": "test-suites/short-smoke/smoke-tests-basic.yaml", "repository": "https://git.automotivelinux.org/src/qa-testdefinitions", "uuid": "33369_1.5.4.9"}, "level": "1.5.4.10", "namespace": "common", "result": "pass"}}
- {"dt": "2023-11-07T19:57:41.052425", "lvl": "debug", "msg": "start: 1.5.4.11 test-install-overlay (timeout 01:26:38) [common]"}
- {"dt": "2023-11-07T19:57:41.059637", "lvl": "debug", "msg": "end: 1.5.4.11 test-install-overlay (duration 00:00:00) [common]"}
- {"dt": "2023-11-07T19:57:41.060425", "lvl": "results", "msg": {"case": "test-install-overlay", "definition": "lava", "duration": "0.01", "extra": {"from": "git", "name": "ci-smoke-tests-basic", "path": "test-suites/short-smoke/smoke-tests-basic.yaml", "repository": "https://git.automotivelinux.org/src/qa-testdefinitions", "skipped test-install-overlay": "33369_1.5.4.9", "uuid": "33369_1.5.4.9"}, "level": "1.5.4.11", "namespace": "common", "result": "pass"}}
- {"dt": "2023-11-07T19:57:41.062038", "lvl": "debug", "msg": "start: 1.5.4.12 test-runscript-overlay (timeout 01:26:38) [common]"}
- {"dt": "2023-11-07T19:57:41.069061", "lvl": "debug", "msg": "runner path: /var/lib/lava/dispatcher/tmp/33369/lava-overlay-8gfwny5n/lava-33369/1/tests/2_ci-smoke-tests-basic test_uuid 33369_1.5.4.9"}
- {"dt": "2023-11-07T19:57:41.071686", "lvl": "debug", "msg": "end: 1.5.4.12 test-runscript-overlay (duration 00:00:00) [common]"}
- {"dt": "2023-11-07T19:57:41.072613", "lvl": "results", "msg": {"case": "test-runscript-overlay", "definition": "lava", "duration": "0.01", "extra": {"filename": "/var/lib/lava/dispatcher/tmp/33369/lava-overlay-8gfwny5n/lava-33369/1/tests/2_ci-smoke-tests-basic/run.sh", "from": "git", "name": "ci-smoke-tests-basic", "path": "test-suites/short-smoke/smoke-tests-basic.yaml", "repository": "https://git.automotivelinux.org/src/qa-testdefinitions", "uuid": "33369_1.5.4.9"}, "level": "1.5.4.12", "namespace": "common", "result": "pass"}}
- {"dt": "2023-11-07T19:57:41.074245", "lvl": "debug", "msg": "start: 1.5.4.13 git-repo-action (timeout 01:26:38) [common]"}
- {"dt": "2023-11-07T19:57:41.074986", "lvl": "debug", "msg": "Using /lava-33369 at stage 1"}
- {"dt": "2023-11-07T19:57:41.075989", "lvl": "info", "msg": "Fetching tests from https://git.automotivelinux.org/src/qa-testdefinitions"}
- {"dt": "2023-11-07T19:57:41.076815", "lvl": "debug", "msg": "Running '/usr/bin/git clone --depth=1 https://git.automotivelinux.org/src/qa-testdefinitions /var/lib/lava/dispatcher/tmp/33369/lava-overlay-8gfwny5n/lava-33369/1/tests/3_ci-service-check'"}
- {"dt": "2023-11-07T19:57:41.758237", "lvl": "debug", "msg": "Removing '.git' directory in /var/lib/lava/dispatcher/tmp/33369/lava-overlay-8gfwny5n/lava-33369/1/tests/3_ci-service-check"}
- {"dt": "2023-11-07T19:57:41.768519", "lvl": "debug", "msg": "Tests stored (tmp) in /var/lib/lava/dispatcher/tmp/33369/lava-overlay-8gfwny5n/lava-33369/1/tests/3_ci-service-check/test-suites/short-smoke/service-check.yaml"}
- {"dt": "2023-11-07T19:57:41.772077", "lvl": "debug", "msg": "uuid=33369_1.5.4.13 testdef=None"}
- {"dt": "2023-11-07T19:57:41.773213", "lvl": "debug", "msg": "end: 1.5.4.13 git-repo-action (duration 00:00:01) [common]"}
- {"dt": "2023-11-07T19:57:41.773940", "lvl": "results", "msg": {"case": "git-repo-action", "definition": "lava", "duration": "0.70", "extra": {"commit": "b4aef27928ee7897aae9de1b5fa47d0aad61803c", "path": "test-suites/short-smoke/service-check.yaml", "repository": "https://git.automotivelinux.org/src/qa-testdefinitions"}, "level": "1.5.4.13", "namespace": "common", "result": "pass"}}
- {"dt": "2023-11-07T19:57:41.775351", "lvl": "debug", "msg": "start: 1.5.4.14 test-overlay (timeout 01:26:37) [common]"}
- {"dt": "2023-11-07T19:57:41.781013", "lvl": "debug", "msg": "end: 1.5.4.14 test-overlay (duration 00:00:00) [common]"}
- {"dt": "2023-11-07T19:57:41.781703", "lvl": "results", "msg": {"case": "test-overlay", "definition": "lava", "duration": "0.01", "extra": {"from": "git", "name": "ci-service-check", "path": "test-suites/short-smoke/service-check.yaml", "repository": "https://git.automotivelinux.org/src/qa-testdefinitions", "uuid": "33369_1.5.4.13"}, "level": "1.5.4.14", "namespace": "common", "result": "pass"}}
- {"dt": "2023-11-07T19:57:41.783249", "lvl": "debug", "msg": "start: 1.5.4.15 test-install-overlay (timeout 01:26:37) [common]"}
- {"dt": "2023-11-07T19:57:41.790608", "lvl": "debug", "msg": "end: 1.5.4.15 test-install-overlay (duration 00:00:00) [common]"}
- {"dt": "2023-11-07T19:57:41.791337", "lvl": "results", "msg": {"case": "test-install-overlay", "definition": "lava", "duration": "0.01", "extra": {"from": "git", "name": "ci-service-check", "path": "test-suites/short-smoke/service-check.yaml", "repository": "https://git.automotivelinux.org/src/qa-testdefinitions", "skipped test-install-overlay": "33369_1.5.4.13", "uuid": "33369_1.5.4.13"}, "level": "1.5.4.15", "namespace": "common", "result": "pass"}}
- {"dt": "2023-11-07T19:57:41.793082", "lvl": "debug", "msg": "start: 1.5.4.16 test-runscript-overlay (timeout 01:26:37) [common]"}
- {"dt": "2023-11-07T19:57:41.799972", "lvl": "debug", "msg": "runner path: /var/lib/lava/dispatcher/tmp/33369/lava-overlay-8gfwny5n/lava-33369/1/tests/3_ci-service-check test_uuid 33369_1.5.4.13"}
- {"dt": "2023-11-07T19:57:41.800806", "lvl": "debug", "msg": "BUILD_TAGS=''"}
- {"dt": "2023-11-07T19:57:41.801430", "lvl": "debug", "msg": "DEVICE_TAGS=''"}
- {"dt": "2023-11-07T19:57:41.802850", "lvl": "debug", "msg": "end: 1.5.4.16 test-runscript-overlay (duration 00:00:00) [common]"}
- {"dt": "2023-11-07T19:57:41.803561", "lvl": "results", "msg": {"case": "test-runscript-overlay", "definition": "lava", "duration": "0.01", "extra": {"filename": "/var/lib/lava/dispatcher/tmp/33369/lava-overlay-8gfwny5n/lava-33369/1/tests/3_ci-service-check/run.sh", "from": "git", "name": "ci-service-check", "path": "test-suites/short-smoke/service-check.yaml", "repository": "https://git.automotivelinux.org/src/qa-testdefinitions", "uuid": "33369_1.5.4.13"}, "level": "1.5.4.16", "namespace": "common", "result": "pass"}}
- {"dt": "2023-11-07T19:57:41.805188", "lvl": "debug", "msg": "start: 1.5.4.17 git-repo-action (timeout 01:26:37) [common]"}
- {"dt": "2023-11-07T19:57:41.805917", "lvl": "debug", "msg": "Using /lava-33369 at stage 2"}
- {"dt": "2023-11-07T19:57:41.806921", "lvl": "info", "msg": "Fetching tests from https://git.automotivelinux.org/src/qa-testdefinitions"}
- {"dt": "2023-11-07T19:57:41.807677", "lvl": "debug", "msg": "Running '/usr/bin/git clone --depth=1 https://git.automotivelinux.org/src/qa-testdefinitions /var/lib/lava/dispatcher/tmp/33369/lava-overlay-8gfwny5n/lava-33369/2/tests/4_screenshooter'"}
- {"dt": "2023-11-07T19:57:42.489395", "lvl": "debug", "msg": "Tests stored (tmp) in /var/lib/lava/dispatcher/tmp/33369/lava-overlay-8gfwny5n/lava-33369/2/tests/4_screenshooter/test-suites/short-smoke/screenshooter.yaml"}
- {"dt": "2023-11-07T19:57:42.494203", "lvl": "debug", "msg": "uuid=33369_1.5.4.17 testdef=None"}
- {"dt": "2023-11-07T19:57:42.495772", "lvl": "debug", "msg": "end: 1.5.4.17 git-repo-action (duration 00:00:01) [common]"}
- {"dt": "2023-11-07T19:57:42.496830", "lvl": "results", "msg": {"case": "git-repo-action", "definition": "lava", "duration": "0.69", "extra": {"commit": "b4aef27928ee7897aae9de1b5fa47d0aad61803c", "path": "test-suites/short-smoke/screenshooter.yaml", "repository": "https://git.automotivelinux.org/src/qa-testdefinitions"}, "level": "1.5.4.17", "namespace": "common", "result": "pass"}}
- {"dt": "2023-11-07T19:57:42.498327", "lvl": "debug", "msg": "start: 1.5.4.18 test-overlay (timeout 01:26:37) [common]"}
- {"dt": "2023-11-07T19:57:42.502972", "lvl": "debug", "msg": "end: 1.5.4.18 test-overlay (duration 00:00:00) [common]"}
- {"dt": "2023-11-07T19:57:42.503658", "lvl": "results", "msg": {"case": "test-overlay", "definition": "lava", "duration": "0.00", "extra": {"from": "git", "name": "screenshooter", "path": "test-suites/short-smoke/screenshooter.yaml", "repository": "https://git.automotivelinux.org/src/qa-testdefinitions", "uuid": "33369_1.5.4.17"}, "level": "1.5.4.18", "namespace": "common", "result": "pass"}}
- {"dt": "2023-11-07T19:57:42.505282", "lvl": "debug", "msg": "start: 1.5.4.19 test-install-overlay (timeout 01:26:37) [common]"}
- {"dt": "2023-11-07T19:57:42.511389", "lvl": "debug", "msg": "end: 1.5.4.19 test-install-overlay (duration 00:00:00) [common]"}
- {"dt": "2023-11-07T19:57:42.512144", "lvl": "results", "msg": {"case": "test-install-overlay", "definition": "lava", "duration": "0.01", "extra": {"from": "git", "name": "screenshooter", "path": "test-suites/short-smoke/screenshooter.yaml", "repository": "https://git.automotivelinux.org/src/qa-testdefinitions", "skipped test-install-overlay": "33369_1.5.4.17", "uuid": "33369_1.5.4.17"}, "level": "1.5.4.19", "namespace": "common", "result": "pass"}}
- {"dt": "2023-11-07T19:57:42.513869", "lvl": "debug", "msg": "start: 1.5.4.20 test-runscript-overlay (timeout 01:26:37) [common]"}
- {"dt": "2023-11-07T19:57:42.519828", "lvl": "debug", "msg": "runner path: /var/lib/lava/dispatcher/tmp/33369/lava-overlay-8gfwny5n/lava-33369/2/tests/4_screenshooter test_uuid 33369_1.5.4.17"}
- {"dt": "2023-11-07T19:57:42.521457", "lvl": "debug", "msg": "end: 1.5.4.20 test-runscript-overlay (duration 00:00:00) [common]"}
- {"dt": "2023-11-07T19:57:42.522220", "lvl": "results", "msg": {"case": "test-runscript-overlay", "definition": "lava", "duration": "0.01", "extra": {"filename": "/var/lib/lava/dispatcher/tmp/33369/lava-overlay-8gfwny5n/lava-33369/2/tests/4_screenshooter/run.sh", "from": "git", "name": "screenshooter", "path": "test-suites/short-smoke/screenshooter.yaml", "repository": "https://git.automotivelinux.org/src/qa-testdefinitions", "uuid": "33369_1.5.4.17"}, "level": "1.5.4.20", "namespace": "common", "result": "pass"}}
- {"dt": "2023-11-07T19:57:42.523813", "lvl": "debug", "msg": "start: 1.5.4.21 git-repo-action (timeout 01:26:37) [common]"}
- {"dt": "2023-11-07T19:57:42.524583", "lvl": "debug", "msg": "Using /lava-33369 at stage 3"}
- {"dt": "2023-11-07T19:57:42.525659", "lvl": "info", "msg": "Fetching tests from https://git.automotivelinux.org/src/qa-testdefinitions"}
- {"dt": "2023-11-07T19:57:42.526432", "lvl": "debug", "msg": "Running '/usr/bin/git clone --depth=1 https://git.automotivelinux.org/src/qa-testdefinitions /var/lib/lava/dispatcher/tmp/33369/lava-overlay-8gfwny5n/lava-33369/3/tests/5_ci-dumpjournal'"}
- {"dt": "2023-11-07T19:57:43.238786", "lvl": "debug", "msg": "Removing '.git' directory in /var/lib/lava/dispatcher/tmp/33369/lava-overlay-8gfwny5n/lava-33369/3/tests/5_ci-dumpjournal"}
- {"dt": "2023-11-07T19:57:43.253097", "lvl": "debug", "msg": "Tests stored (tmp) in /var/lib/lava/dispatcher/tmp/33369/lava-overlay-8gfwny5n/lava-33369/3/tests/5_ci-dumpjournal/test-suites/short-smoke/dumpjournal.yaml"}
- {"dt": "2023-11-07T19:57:43.256301", "lvl": "debug", "msg": "uuid=33369_1.5.4.21 testdef={'testdef_pattern': {'pattern': '^(?P<test_case_id>[a-zA-Z0-9_-]+):\\\\s(?P<result>\\\\w+)', 'fixupdict': {'PASS': 'pass', 'FAIL': 'fail'}}}"}
- {"dt": "2023-11-07T19:57:43.257407", "lvl": "debug", "msg": "end: 1.5.4.21 git-repo-action (duration 00:00:01) [common]"}
- {"dt": "2023-11-07T19:57:43.258184", "lvl": "results", "msg": {"case": "git-repo-action", "definition": "lava", "duration": "0.73", "extra": {"commit": "b4aef27928ee7897aae9de1b5fa47d0aad61803c", "path": "test-suites/short-smoke/dumpjournal.yaml", "repository": "https://git.automotivelinux.org/src/qa-testdefinitions"}, "level": "1.5.4.21", "namespace": "common", "result": "pass"}}
- {"dt": "2023-11-07T19:57:43.259656", "lvl": "debug", "msg": "start: 1.5.4.22 test-overlay (timeout 01:26:36) [common]"}
- {"dt": "2023-11-07T19:57:43.265340", "lvl": "debug", "msg": "end: 1.5.4.22 test-overlay (duration 00:00:00) [common]"}
- {"dt": "2023-11-07T19:57:43.266003", "lvl": "results", "msg": {"case": "test-overlay", "definition": "lava", "duration": "0.01", "extra": {"from": "git", "name": "ci-dumpjournal", "path": "test-suites/short-smoke/dumpjournal.yaml", "repository": "https://git.automotivelinux.org/src/qa-testdefinitions", "uuid": "33369_1.5.4.21"}, "level": "1.5.4.22", "namespace": "common", "result": "pass"}}
- {"dt": "2023-11-07T19:57:43.267570", "lvl": "debug", "msg": "start: 1.5.4.23 test-install-overlay (timeout 01:26:36) [common]"}
- {"dt": "2023-11-07T19:57:43.275051", "lvl": "debug", "msg": "end: 1.5.4.23 test-install-overlay (duration 00:00:00) [common]"}
- {"dt": "2023-11-07T19:57:43.275764", "lvl": "results", "msg": {"case": "test-install-overlay", "definition": "lava", "duration": "0.01", "extra": {"from": "git", "name": "ci-dumpjournal", "path": "test-suites/short-smoke/dumpjournal.yaml", "repository": "https://git.automotivelinux.org/src/qa-testdefinitions", "skipped test-install-overlay": "33369_1.5.4.21", "uuid": "33369_1.5.4.21"}, "level": "1.5.4.23", "namespace": "common", "result": "pass"}}
- {"dt": "2023-11-07T19:57:43.277894", "lvl": "debug", "msg": "start: 1.5.4.24 test-runscript-overlay (timeout 01:26:36) [common]"}
- {"dt": "2023-11-07T19:57:43.285302", "lvl": "debug", "msg": "runner path: /var/lib/lava/dispatcher/tmp/33369/lava-overlay-8gfwny5n/lava-33369/3/tests/5_ci-dumpjournal test_uuid 33369_1.5.4.21"}
- {"dt": "2023-11-07T19:57:43.286901", "lvl": "debug", "msg": "end: 1.5.4.24 test-runscript-overlay (duration 00:00:00) [common]"}
- {"dt": "2023-11-07T19:57:43.287625", "lvl": "results", "msg": {"case": "test-runscript-overlay", "definition": "lava", "duration": "0.01", "extra": {"filename": "/var/lib/lava/dispatcher/tmp/33369/lava-overlay-8gfwny5n/lava-33369/3/tests/5_ci-dumpjournal/run.sh", "from": "git", "name": "ci-dumpjournal", "path": "test-suites/short-smoke/dumpjournal.yaml", "repository": "https://git.automotivelinux.org/src/qa-testdefinitions", "uuid": "33369_1.5.4.21"}, "level": "1.5.4.24", "namespace": "common", "result": "pass"}}
- {"dt": "2023-11-07T19:57:43.289120", "lvl": "info", "msg": "Creating lava-test-runner.conf files"}
- {"dt": "2023-11-07T19:57:43.289781", "lvl": "debug", "msg": "Using lava-test-runner path: /var/lib/lava/dispatcher/tmp/33369/lava-overlay-8gfwny5n/lava-33369/0 for stage 0"}
- {"dt": "2023-11-07T19:57:43.290794", "lvl": "debug", "msg": "- 0_network-veth"}
- {"dt": "2023-11-07T19:57:43.291662", "lvl": "debug", "msg": "Using lava-test-runner path: /var/lib/lava/dispatcher/tmp/33369/lava-overlay-8gfwny5n/lava-33369/1 for stage 1"}
- {"dt": "2023-11-07T19:57:43.292813", "lvl": "debug", "msg": "- 1_ci-busybox"}
- {"dt": "2023-11-07T19:57:43.293507", "lvl": "debug", "msg": "- 2_ci-smoke-tests-basic"}
- {"dt": "2023-11-07T19:57:43.294088", "lvl": "debug", "msg": "- 3_ci-service-check"}
- {"dt": "2023-11-07T19:57:43.294821", "lvl": "debug", "msg": "Using lava-test-runner path: /var/lib/lava/dispatcher/tmp/33369/lava-overlay-8gfwny5n/lava-33369/2 for stage 2"}
- {"dt": "2023-11-07T19:57:43.295814", "lvl": "debug", "msg": "- 4_screenshooter"}
- {"dt": "2023-11-07T19:57:43.296710", "lvl": "debug", "msg": "Using lava-test-runner path: /var/lib/lava/dispatcher/tmp/33369/lava-overlay-8gfwny5n/lava-33369/3 for stage 3"}
- {"dt": "2023-11-07T19:57:43.297718", "lvl": "debug", "msg": "- 5_ci-dumpjournal"}
- {"dt": "2023-11-07T19:57:43.298750", "lvl": "debug", "msg": "end: 1.5.4 test-definition (duration 00:00:05) [common]"}
- {"dt": "2023-11-07T19:57:43.299639", "lvl": "debug", "msg": "start: 1.5.5 compress-overlay (timeout 01:26:36) [common]"}
- {"dt": "2023-11-07T19:57:43.983352", "lvl": "debug", "msg": "end: 1.5.5 compress-overlay (duration 00:00:01) [common]"}
- {"dt": "2023-11-07T19:57:43.984348", "lvl": "debug", "msg": "start: 1.5.6 persistent-nfs-overlay (timeout 01:26:35) [common]"}
- {"dt": "2023-11-07T19:57:43.985647", "lvl": "debug", "msg": "end: 1.5.6 persistent-nfs-overlay (duration 00:00:00) [common]"}
- {"dt": "2023-11-07T19:57:43.986587", "lvl": "debug", "msg": "end: 1.5 lava-overlay (duration 00:00:05) [common]"}
- {"dt": "2023-11-07T19:57:43.987426", "lvl": "debug", "msg": "start: 1.6 prepare-kernel (timeout 01:26:35) [common]"}
- {"dt": "2023-11-07T19:57:43.988269", "lvl": "debug", "msg": "start: 1.6.1 uboot-prepare-kernel (timeout 01:26:35) [common]"}
- {"dt": "2023-11-07T19:57:43.989181", "lvl": "debug", "msg": "end: 1.6.1 uboot-prepare-kernel (duration 00:00:00) [common]"}
- {"dt": "2023-11-07T19:57:43.989974", "lvl": "debug", "msg": "end: 1.6 prepare-kernel (duration 00:00:00) [common]"}
- {"dt": "2023-11-07T19:57:43.990775", "lvl": "debug", "msg": "start: 1.7 xnbd-server-deploy (timeout 01:26:35) [common]"}
- {"dt": "2023-11-07T19:57:43.991494", "lvl": "debug", "msg": "xnbd-server-deploy: starting nbd-server"}
- {"dt": "2023-11-07T19:57:43.992165", "lvl": "debug", "msg": "NBD-IP: 192.168.66.1, NBD-PORT: 61981, NBD-ROOT: 33369/nbd-deploy-vpt9pq7o/nbdroot/agl-demo-platform-raspberrypi4-64.ext4"}
- {"dt": "2023-11-07T19:57:43.995740", "lvl": "debug", "msg": "nbd-server 61981 /var/lib/lava/dispatcher/tmp/33369/nbd-deploy-vpt9pq7o/nbdroot/agl-demo-platform-raspberrypi4-64.ext4"}
- {"dt": "2023-11-07T19:57:44.021085", "lvl": "debug", "msg": "output: "}
- {"dt": "2023-11-07T19:57:44.022936", "lvl": "debug", "msg": "output: ** (process:1372): WARNING **: 19:57:44.019: Specifying an export on the command line no longer uses the oldstyle protocol."}
- {"dt": "2023-11-07T19:57:44.023663", "lvl": "debug", "msg": "output: "}
- {"dt": "2023-11-07T19:57:44.024368", "lvl": "debug", "msg": "xnbd-server-deploy: starting nbd-server done"}
- {"dt": "2023-11-07T19:57:44.025475", "lvl": "debug", "msg": "end: 1.7 xnbd-server-deploy (duration 00:00:00) [common]"}
- {"dt": "2023-11-07T19:57:44.026475", "lvl": "info", "msg": "end: 1 nbd-deploy (duration 00:03:25) [common]"}
- {"dt": "2023-11-07T19:57:44.027461", "lvl": "info", "msg": "start: 2 uboot-action (timeout 00:20:00) [common]"}
- {"dt": "2023-11-07T19:57:44.028507", "lvl": "debug", "msg": "start: 2.1 uboot-from-media (timeout 00:20:00) [common]"}
- {"dt": "2023-11-07T19:57:44.029418", "lvl": "debug", "msg": "end: 2.1 uboot-from-media (duration 00:00:00) [common]"}
- {"dt": "2023-11-07T19:57:44.030335", "lvl": "debug", "msg": "start: 2.2 bootloader-overlay (timeout 00:20:00) [common]"}
- {"dt": "2023-11-07T19:57:44.031710", "lvl": "debug", "msg": "substitutions:"}
- {"dt": "2023-11-07T19:57:44.032530", "lvl": "debug", "msg": "- {BOOTX}: booti 0x00080000 0x02700000:${initrd_size} 0x02400000"}
- {"dt": "2023-11-07T19:57:44.033282", "lvl": "debug", "msg": "- {DTB_ADDR}: 0x02400000"}
- {"dt": "2023-11-07T19:57:44.033940", "lvl": "debug", "msg": "- {DTB}: 33369/nbd-deploy-vpt9pq7o/dtb/bcm2711-rpi-4-b+vc4.dtb"}
- {"dt": "2023-11-07T19:57:44.034569", "lvl": "debug", "msg": "- {INITRD}: 33369/nbd-deploy-vpt9pq7o/initrd/initramfs-netboot-image-raspberrypi4-64.ext4.gz"}
- {"dt": "2023-11-07T19:57:44.035200", "lvl": "debug", "msg": "- {KERNEL_ADDR}: 0x00080000"}
- {"dt": "2023-11-07T19:57:44.035801", "lvl": "debug", "msg": "- {KERNEL}: 33369/nbd-deploy-vpt9pq7o/kernel/Image"}
- {"dt": "2023-11-07T19:57:44.036472", "lvl": "debug", "msg": "- {LAVA_MAC}: None"}
- {"dt": "2023-11-07T19:57:44.037107", "lvl": "debug", "msg": "- {NBDSERVERIP}: 192.168.66.1"}
- {"dt": "2023-11-07T19:57:44.037706", "lvl": "debug", "msg": "- {NBDSERVERPORT}: 61981"}
- {"dt": "2023-11-07T19:57:44.038286", "lvl": "debug", "msg": "- {PRESEED_CONFIG}: None"}
- {"dt": "2023-11-07T19:57:44.038851", "lvl": "debug", "msg": "- {PRESEED_LOCAL}: None"}
- {"dt": "2023-11-07T19:57:44.039412", "lvl": "debug", "msg": "- {RAMDISK_ADDR}: 0x02700000"}
- {"dt": "2023-11-07T19:57:44.039979", "lvl": "debug", "msg": "- {RAMDISK}: 33369/nbd-deploy-vpt9pq7o/initrd/initramfs-netboot-image-raspberrypi4-64.ext4.gz"}
- {"dt": "2023-11-07T19:57:44.040646", "lvl": "debug", "msg": "- {ROOT_PART}: None"}
- {"dt": "2023-11-07T19:57:44.041290", "lvl": "debug", "msg": "- {ROOT}: None"}
- {"dt": "2023-11-07T19:57:44.041903", "lvl": "debug", "msg": "- {SERVER_IP}: 192.168.66.1"}
- {"dt": "2023-11-07T19:57:44.042498", "lvl": "debug", "msg": "- {TEE_ADDR}: 0x83000000"}
- {"dt": "2023-11-07T19:57:44.043072", "lvl": "debug", "msg": "- {TEE}: None"}
- {"dt": "2023-11-07T19:57:44.043655", "lvl": "info", "msg": "Parsed boot commands:"}
- {"dt": "2023-11-07T19:57:44.044295", "lvl": "info", "msg": "- setenv autoload no"}
- {"dt": "2023-11-07T19:57:44.044909", "lvl": "info", "msg": "- setenv initrd_high 0xffffffff"}
- {"dt": "2023-11-07T19:57:44.045533", "lvl": "info", "msg": "- setenv fdt_high 0xffffffff"}
- {"dt": "2023-11-07T19:57:44.046143", "lvl": "info", "msg": "- dhcp"}
- {"dt": "2023-11-07T19:57:44.046740", "lvl": "info", "msg": "- setenv serverip 192.168.66.1"}
- {"dt": "2023-11-07T19:57:44.047328", "lvl": "info", "msg": "- tftp 0x00080000 33369/nbd-deploy-vpt9pq7o/kernel/Image"}
- {"dt": "2023-11-07T19:57:44.047894", "lvl": "info", "msg": "- tftp 0x02700000 33369/nbd-deploy-vpt9pq7o/initrd/initramfs-netboot-image-raspberrypi4-64.ext4.gz"}
- {"dt": "2023-11-07T19:57:44.048585", "lvl": "info", "msg": "- setenv initrd_size ${filesize}"}
- {"dt": "2023-11-07T19:57:44.049200", "lvl": "info", "msg": "- tftp 0x02400000 33369/nbd-deploy-vpt9pq7o/dtb/bcm2711-rpi-4-b+vc4.dtb"}
- {"dt": "2023-11-07T19:57:44.049800", "lvl": "info", "msg": "- setenv bootargs 'console=ttyS0,115200n8 rw nbd.server=192.168.66.1 nbd.port=61981 root=/dev/ram0 ramdisk_size=16384 rootdelay=7   coherent_pool=1M 8250.nr_uarts=1 rw fstab=no systemd.mask=systemd-network-generator.service ip=dhcp verbose earlyprintk systemd.log_color=false ${extraargs} rw'"}
- {"dt": "2023-11-07T19:57:44.050478", "lvl": "info", "msg": "- fdt addr 0x02400000; fdt boardsetup; fdt resize; fdt set audio status okay; booti 0x00080000 0x02700000:${initrd_size} 0x02400000"}
- {"dt": "2023-11-07T19:57:44.051260", "lvl": "debug", "msg": "end: 2.2 bootloader-overlay (duration 00:00:00) [common]"}
- {"dt": "2023-11-07T19:57:44.051978", "lvl": "results", "msg": {"case": "bootloader-overlay", "definition": "lava", "duration": "0.02", "extra": {"dtb_addr": "0x02400000", "kernel_addr": "0x00080000", "ramdisk_addr": "0x02700000", "tee_addr": "0x83000000"}, "level": "2.2", "namespace": "common", "result": "pass"}}
- {"dt": "2023-11-07T19:57:44.053674", "lvl": "debug", "msg": "start: 2.3 connect-device (timeout 00:20:00) [common]"}
- {"dt": "2023-11-07T19:57:44.054442", "lvl": "info", "msg": "[common] connect-device Connecting to device using 'telnet 127.0.0.1 63003'"}
- {"dt": "2023-11-07T19:57:47.260970", "lvl": "debug", "msg": "Setting prompt string to ['lava-test: # ']"}
- {"dt": "2023-11-07T19:57:47.264029", "lvl": "debug", "msg": "end: 2.3 connect-device (duration 00:00:03) [common]"}
- {"dt": "2023-11-07T19:57:47.265388", "lvl": "debug", "msg": "start: 2.4 uboot-commands (timeout 00:19:57) [common]"}
- {"dt": "2023-11-07T19:57:47.266333", "lvl": "debug", "msg": "start: 2.4.1 reset-device (timeout 00:19:57) [common]"}
- {"dt": "2023-11-07T19:57:47.267341", "lvl": "debug", "msg": "start: 2.4.1.1 pdu-reboot (timeout 00:19:57) [common]"}
- {"dt": "2023-11-07T19:57:47.268723", "lvl": "debug", "msg": "Calling: 'nice' '/usr/local/bin/acme-cli' '-s' '192.168.66.2' 'reset' '7'"}
- {"dt": "2023-11-07T19:57:51.371872", "lvl": "debug", "msg": ">> Success\r"}
- {"dt": "2023-11-07T19:57:52.444514", "lvl": "debug", "msg": ">> Success\r"}
- {"dt": "2023-11-07T19:57:52.480559", "lvl": "debug", "msg": "Returned 0 in 5 seconds"}
- {"dt": "2023-11-07T19:57:52.583772", "lvl": "debug", "msg": "end: 2.4.1.1 pdu-reboot (duration 00:00:05) [common]"}
- {"dt": "2023-11-07T19:57:52.586146", "lvl": "results", "msg": {"case": "pdu-reboot", "definition": "lava", "duration": "5.32", "extra": {"status": "success"}, "level": "2.4.1.1", "namespace": "common", "result": "pass"}}
- {"dt": "2023-11-07T19:57:52.589173", "lvl": "debug", "msg": "end: 2.4.1 reset-device (duration 00:00:05) [common]"}
- {"dt": "2023-11-07T19:57:52.589936", "lvl": "debug", "msg": "start: 2.4.2 bootloader-interrupt (timeout 00:19:51) [common]"}
- {"dt": "2023-11-07T19:57:52.590589", "lvl": "debug", "msg": "Setting prompt string to ['Hit any key to stop autoboot']"}
- {"dt": "2023-11-07T19:57:52.591136", "lvl": "debug", "msg": "bootloader-interrupt: Wait for prompt ['Hit any key to stop autoboot'] (timeout 00:20:00)"}
- {"dt": "2023-11-07T19:57:52.593074", "lvl": "target", "msg": "Trying 127.0.0.1..."}
- {"dt": "2023-11-07T19:57:52.593803", "lvl": "target", "msg": "Connected to 127.0.0.1."}
- {"dt": "2023-11-07T19:57:52.594298", "lvl": "target", "msg": "Escape character is '^]'."}
- {"dt": "2023-11-07T19:57:59.071025", "lvl": "target", "msg": "\0"}
- {"dt": "2023-11-07T19:57:59.072621", "lvl": "target", "msg": ""}
- {"dt": "2023-11-07T19:57:59.074836", "lvl": "target", "msg": "U-Boot 2020.07-00717-gfee68b98fe-dirty (Jul 17 2020 - 09:59:08 +0200)"}
- {"dt": "2023-11-07T19:57:59.076009", "lvl": "target", "msg": ""}
- {"dt": "2023-11-07T19:57:59.217250", "lvl": "target", "msg": "DRAM:  3.9 GiB"}
- {"dt": "2023-11-07T19:57:59.249204", "lvl": "target", "msg": "RPI 4 Model B (0xc03111)"}
- {"dt": "2023-11-07T19:57:59.285881", "lvl": "target", "msg": "MMC:   emmc2@7e340000: 0, mmcnr@7e300000: 1"}
- {"dt": "2023-11-07T19:57:59.352926", "lvl": "target", "msg": "Loading Environment from FAT... *** Warning - bad CRC, using default environment"}
- {"dt": "2023-11-07T19:57:59.354145", "lvl": "target", "msg": ""}
- {"dt": "2023-11-07T19:57:59.379789", "lvl": "target", "msg": "In:    serial"}
- {"dt": "2023-11-07T19:57:59.380941", "lvl": "target", "msg": "Out:   serial"}
- {"dt": "2023-11-07T19:57:59.381925", "lvl": "target", "msg": "Err:   serial"}
- {"dt": "2023-11-07T19:57:59.382862", "lvl": "target", "msg": "Net:   eth0: genet@7d580000"}
- {"dt": "2023-11-07T19:57:59.384687", "lvl": "target", "msg": "starting USB..."}
- {"dt": "2023-11-07T19:57:59.385731", "lvl": "target", "msg": "No working controllers found"}
- {"dt": "2023-11-07T19:57:59.387796", "lvl": "input", "msg": "c"}
- {"dt": "2023-11-07T19:57:59.389126", "lvl": "debug", "msg": "end: 2.4.2 bootloader-interrupt (duration 00:00:07) [common]"}
- {"dt": "2023-11-07T19:57:59.390067", "lvl": "debug", "msg": "start: 2.4.3 bootloader-commands (timeout 00:19:45) [common]"}
- {"dt": "2023-11-07T19:57:59.390835", "lvl": "debug", "msg": "Setting prompt string to ['U-Boot>']"}
- {"dt": "2023-11-07T19:57:59.391679", "lvl": "debug", "msg": "bootloader-commands: Wait for prompt ['U-Boot>'] (timeout 00:19:45)"}
- {"dt": "2023-11-07T19:57:59.414127", "lvl": "target", "msg": "Hit any key to stop autoboot:  2 \x03\b\b\b 0 "}
- {"dt": "2023-11-07T19:57:59.416011", "lvl": "debug", "msg": "Setting prompt string to ['U-Boot>', 'Resetting CPU', 'Must RESET board to recover', 'TIMEOUT', 'Retry count exceeded', 'Retry time exceeded; starting again', 'ERROR: The remote end did not respond in time.', 'File not found', 'Bad Linux ARM64 Image magic!', 'Wrong Ramdisk Image Format', 'Ramdisk image is corrupt or invalid', 'ERROR: Failed to allocate', 'TFTP error: trying to overwrite reserved memory', 'Bad Linux RISCV Image magic!', 'Wrong Image Format for boot', 'ERROR: Did not find a cmdline Flattened Device Tree', 'ERROR: RD image overlaps OS image']"}
- {"dt": "2023-11-07T19:57:59.417141", "lvl": "input", "msg": "setenv autoload no\n"}
- {"dt": "2023-11-07T19:57:59.519046", "lvl": "target", "msg": "U-Boot> setenv autoload no"}
- {"dt": "2023-11-07T19:57:59.520518", "lvl": "debug", "msg": "bootloader-commands: Wait for prompt ['U-Boot>', 'Resetting CPU', 'Must RESET board to recover', 'TIMEOUT', 'Retry count exceeded', 'Retry time exceeded; starting again', 'ERROR: The remote end did not respond in time.', 'File not found', 'Bad Linux ARM64 Image magic!', 'Wrong Ramdisk Image Format', 'Ramdisk image is corrupt or invalid', 'ERROR: Failed to allocate', 'TFTP error: trying to overwrite reserved memory', 'Bad Linux RISCV Image magic!', 'Wrong Image Format for boot', 'ERROR: Did not find a cmdline Flattened Device Tree', 'ERROR: RD image overlaps OS image'] (timeout 00:19:45)"}
- {"dt": "2023-11-07T19:57:59.533138", "lvl": "target", "msg": "setenv autoload no"}
- {"dt": "2023-11-07T19:57:59.534216", "lvl": "input", "msg": "setenv initrd_high 0xffffffff\n"}
- {"dt": "2023-11-07T19:57:59.635846", "lvl": "target", "msg": "U-Boot> setenv initrd_high 0xffffffff"}
- {"dt": "2023-11-07T19:57:59.638093", "lvl": "debug", "msg": "bootloader-commands: Wait for prompt ['U-Boot>', 'Resetting CPU', 'Must RESET board to recover', 'TIMEOUT', 'Retry count exceeded', 'Retry time exceeded; starting again', 'ERROR: The remote end did not respond in time.', 'File not found', 'Bad Linux ARM64 Image magic!', 'Wrong Ramdisk Image Format', 'Ramdisk image is corrupt or invalid', 'ERROR: Failed to allocate', 'TFTP error: trying to overwrite reserved memory', 'Bad Linux RISCV Image magic!', 'Wrong Image Format for boot', 'ERROR: Did not find a cmdline Flattened Device Tree', 'ERROR: RD image overlaps OS image'] (timeout 00:19:44)"}
- {"dt": "2023-11-07T19:57:59.653939", "lvl": "target", "msg": "setenv initrd_high 0xffffffff"}
- {"dt": "2023-11-07T19:57:59.655701", "lvl": "input", "msg": "setenv fdt_high 0xffffffff\n"}
- {"dt": "2023-11-07T19:57:59.757649", "lvl": "target", "msg": "U-Boot> setenv fdt_high 0xffffffff"}
- {"dt": "2023-11-07T19:57:59.759685", "lvl": "debug", "msg": "bootloader-commands: Wait for prompt ['U-Boot>', 'Resetting CPU', 'Must RESET board to recover', 'TIMEOUT', 'Retry count exceeded', 'Retry time exceeded; starting again', 'ERROR: The remote end did not respond in time.', 'File not found', 'Bad Linux ARM64 Image magic!', 'Wrong Ramdisk Image Format', 'Ramdisk image is corrupt or invalid', 'ERROR: Failed to allocate', 'TFTP error: trying to overwrite reserved memory', 'Bad Linux RISCV Image magic!', 'Wrong Image Format for boot', 'ERROR: Did not find a cmdline Flattened Device Tree', 'ERROR: RD image overlaps OS image'] (timeout 00:19:44)"}
- {"dt": "2023-11-07T19:57:59.765833", "lvl": "target", "msg": "setenv fdt_high 0xffffffff"}
- {"dt": "2023-11-07T19:57:59.767977", "lvl": "input", "msg": "dhcp\n"}
- {"dt": "2023-11-07T19:57:59.870526", "lvl": "target", "msg": "U-Boot> dhcp"}
- {"dt": "2023-11-07T19:57:59.872316", "lvl": "debug", "msg": "bootloader-commands: Wait for prompt ['U-Boot>', 'Resetting CPU', 'Must RESET board to recover', 'TIMEOUT', 'Retry count exceeded', 'Retry time exceeded; starting again', 'ERROR: The remote end did not respond in time.', 'File not found', 'Bad Linux ARM64 Image magic!', 'Wrong Ramdisk Image Format', 'Ramdisk image is corrupt or invalid', 'ERROR: Failed to allocate', 'TFTP error: trying to overwrite reserved memory', 'Bad Linux RISCV Image magic!', 'Wrong Image Format for boot', 'ERROR: Did not find a cmdline Flattened Device Tree', 'ERROR: RD image overlaps OS image'] (timeout 00:19:44)"}
- {"dt": "2023-11-07T19:57:59.877292", "lvl": "target", "msg": "dhcp"}
- {"dt": "2023-11-07T19:58:02.994293", "lvl": "target", "msg": "genet@7d580000 Waiting for PHY auto negotiation to complete....... done"}
- {"dt": "2023-11-07T19:58:02.995342", "lvl": "target", "msg": "BOOTP broadcast 1"}
- {"dt": "2023-11-07T19:58:03.249562", "lvl": "target", "msg": "BOOTP broadcast 2"}
- {"dt": "2023-11-07T19:58:03.745294", "lvl": "target", "msg": "BOOTP broadcast 3"}
- {"dt": "2023-11-07T19:58:04.737818", "lvl": "target", "msg": "BOOTP broadcast 4"}
- {"dt": "2023-11-07T19:58:05.883456", "lvl": "target", "msg": "DHCP client bound to address 192.168.66.241 (2881 ms)"}
- {"dt": "2023-11-07T19:58:05.884573", "lvl": "input", "msg": "setenv serverip 192.168.66.1\n"}
- {"dt": "2023-11-07T19:58:05.986226", "lvl": "target", "msg": "U-Boot> setenv serverip 192.168.66.1"}
- {"dt": "2023-11-07T19:58:05.988362", "lvl": "debug", "msg": "bootloader-commands: Wait for prompt ['U-Boot>', 'Resetting CPU', 'Must RESET board to recover', 'TIMEOUT', 'Retry count exceeded', 'Retry time exceeded; starting again', 'ERROR: The remote end did not respond in time.', 'File not found', 'Bad Linux ARM64 Image magic!', 'Wrong Ramdisk Image Format', 'Ramdisk image is corrupt or invalid', 'ERROR: Failed to allocate', 'TFTP error: trying to overwrite reserved memory', 'Bad Linux RISCV Image magic!', 'Wrong Image Format for boot', 'ERROR: Did not find a cmdline Flattened Device Tree', 'ERROR: RD image overlaps OS image'] (timeout 00:19:38)"}
- {"dt": "2023-11-07T19:58:05.995164", "lvl": "target", "msg": "setenv serverip 192.168.66.1"}
- {"dt": "2023-11-07T19:58:05.997411", "lvl": "input", "msg": "tftp 0x00080000 33369/nbd-deploy-vpt9pq7o/kernel/Image\n"}
- {"dt": "2023-11-07T19:58:06.100240", "lvl": "target", "msg": "U-Boot> tftp 0x00080000 33369/nbd-deploy-vpt9pq7o/kernel/Image"}
- {"dt": "2023-11-07T19:58:06.102483", "lvl": "debug", "msg": "bootloader-commands: Wait for prompt ['U-Boot>', 'Resetting CPU', 'Must RESET board to recover', 'TIMEOUT', 'Retry count exceeded', 'Retry time exceeded; starting again', 'ERROR: The remote end did not respond in time.', 'File not found', 'Bad Linux ARM64 Image magic!', 'Wrong Ramdisk Image Format', 'Ramdisk image is corrupt or invalid', 'ERROR: Failed to allocate', 'TFTP error: trying to overwrite reserved memory', 'Bad Linux RISCV Image magic!', 'Wrong Image Format for boot', 'ERROR: Did not find a cmdline Flattened Device Tree', 'ERROR: RD image overlaps OS image'] (timeout 00:19:38)"}
- {"dt": "2023-11-07T19:58:06.106978", "lvl": "target", "msg": "tftp 0x00080000 33369/nbd-deploy-vpt9pq7o/kernel/Image"}
- {"dt": "2023-11-07T19:58:06.130342", "lvl": "target", "msg": "Using genet@7d580000 device"}
- {"dt": "2023-11-07T19:58:06.131363", "lvl": "target", "msg": "TFTP from server 192.168.66.1; our IP address is 192.168.66.241"}
- {"dt": "2023-11-07T19:58:06.133138", "lvl": "target", "msg": "Filename '33369/nbd-deploy-vpt9pq7o/kernel/Image'."}
- {"dt": "2023-11-07T19:58:06.134349", "lvl": "target", "msg": "Load address: 0x80000"}
- {"dt": "2023-11-07T19:59:05.469857", "lvl": "target", "msg": "Loading: *\bT #T ###############################T ##################  23.1 MiB"}
- {"dt": "2023-11-07T19:59:05.470648", "lvl": "target", "msg": "\t 398.4 KiB/s"}
- {"dt": "2023-11-07T19:59:05.471345", "lvl": "target", "msg": "done"}
- {"dt": "2023-11-07T19:59:05.473575", "lvl": "target", "msg": "Bytes transferred = 24244736 (171f200 hex)"}
- {"dt": "2023-11-07T19:59:05.474666", "lvl": "input", "msg": "tftp 0x02700000 33369/nbd-deploy-vpt9pq7o/initrd/initramfs-netboot-image-raspberrypi4-64.ext4.gz\n"}
- {"dt": "2023-11-07T19:59:05.576290", "lvl": "target", "msg": "U-Boot> tftp 0x02700000 33369/nbd-deploy-vpt9pq7o/initrd/initramfs-netboot-image-raspberrypi4-64.ext4.gz"}
- {"dt": "2023-11-07T19:59:05.577452", "lvl": "debug", "msg": "bootloader-commands: Wait for prompt ['U-Boot>', 'Resetting CPU', 'Must RESET board to recover', 'TIMEOUT', 'Retry count exceeded', 'Retry time exceeded; starting again', 'ERROR: The remote end did not respond in time.', 'File not found', 'Bad Linux ARM64 Image magic!', 'Wrong Ramdisk Image Format', 'Ramdisk image is corrupt or invalid', 'ERROR: Failed to allocate', 'TFTP error: trying to overwrite reserved memory', 'Bad Linux RISCV Image magic!', 'Wrong Image Format for boot', 'ERROR: Did not find a cmdline Flattened Device Tree', 'ERROR: RD image overlaps OS image'] (timeout 00:18:38)"}
- {"dt": "2023-11-07T19:59:05.582059", "lvl": "target", "msg": "tftp 0x02700000 33369/nbd-deploy-vpt9pq7o/initrd/initramfs-netboot-image-raspberrypi4-64.ext4.gz"}
- {"dt": "2023-11-07T19:59:05.611958", "lvl": "target", "msg": "Using genet@7d580000 device"}
- {"dt": "2023-11-07T19:59:05.612870", "lvl": "target", "msg": "TFTP from server 192.168.66.1; our IP address is 192.168.66.241"}
- {"dt": "2023-11-07T19:59:05.614026", "lvl": "target", "msg": "Filename '33369/nbd-deploy-vpt9pq7o/initrd/initramfs-netboot-image-raspberrypi4-64.ext4.gz'."}
- {"dt": "2023-11-07T19:59:05.615361", "lvl": "target", "msg": "Load address: 0x2700000"}
- {"dt": "2023-11-07T19:59:07.148938", "lvl": "target", "msg": "Loading: *\b##################################################  2 MiB"}
- {"dt": "2023-11-07T19:59:07.149786", "lvl": "target", "msg": "\t 1.3 MiB/s"}
- {"dt": "2023-11-07T19:59:07.150463", "lvl": "target", "msg": "done"}
- {"dt": "2023-11-07T19:59:07.164873", "lvl": "target", "msg": "Bytes transferred = 2066383 (1f87cf hex)"}
- {"dt": "2023-11-07T19:59:07.166028", "lvl": "input", "msg": "setenv initrd_size ${filesize}\n"}
- {"dt": "2023-11-07T19:59:07.267690", "lvl": "target", "msg": "U-Boot> setenv initrd_size ${filesize}"}
- {"dt": "2023-11-07T19:59:07.268697", "lvl": "debug", "msg": "bootloader-commands: Wait for prompt ['U-Boot>', 'Resetting CPU', 'Must RESET board to recover', 'TIMEOUT', 'Retry count exceeded', 'Retry time exceeded; starting again', 'ERROR: The remote end did not respond in time.', 'File not found', 'Bad Linux ARM64 Image magic!', 'Wrong Ramdisk Image Format', 'Ramdisk image is corrupt or invalid', 'ERROR: Failed to allocate', 'TFTP error: trying to overwrite reserved memory', 'Bad Linux RISCV Image magic!', 'Wrong Image Format for boot', 'ERROR: Did not find a cmdline Flattened Device Tree', 'ERROR: RD image overlaps OS image'] (timeout 00:18:37)"}
- {"dt": "2023-11-07T19:59:07.276707", "lvl": "target", "msg": "setenv initrd_size ${filesize}"}
- {"dt": "2023-11-07T19:59:07.277899", "lvl": "input", "msg": "tftp 0x02400000 33369/nbd-deploy-vpt9pq7o/dtb/bcm2711-rpi-4-b+vc4.dtb\n"}
- {"dt": "2023-11-07T19:59:07.379642", "lvl": "target", "msg": "U-Boot> tftp 0x02400000 33369/nbd-deploy-vpt9pq7o/dtb/bcm2711-rpi-4-b+vc4.dtb"}
- {"dt": "2023-11-07T19:59:07.380796", "lvl": "debug", "msg": "bootloader-commands: Wait for prompt ['U-Boot>', 'Resetting CPU', 'Must RESET board to recover', 'TIMEOUT', 'Retry count exceeded', 'Retry time exceeded; starting again', 'ERROR: The remote end did not respond in time.', 'File not found', 'Bad Linux ARM64 Image magic!', 'Wrong Ramdisk Image Format', 'Ramdisk image is corrupt or invalid', 'ERROR: Failed to allocate', 'TFTP error: trying to overwrite reserved memory', 'Bad Linux RISCV Image magic!', 'Wrong Image Format for boot', 'ERROR: Did not find a cmdline Flattened Device Tree', 'ERROR: RD image overlaps OS image'] (timeout 00:18:37)"}
- {"dt": "2023-11-07T19:59:07.416950", "lvl": "target", "msg": "tftp 0x02400000 33369/nbd-deploy-vpt9pq7o/dtb/bcm2711-rpi-4-b+vc4.dtb"}
- {"dt": "2023-11-07T19:59:07.420012", "lvl": "target", "msg": "Using genet@7d580000 device"}
- {"dt": "2023-11-07T19:59:07.424646", "lvl": "target", "msg": "TFTP from server 192.168.66.1; our IP address is 192.168.66.241"}
- {"dt": "2023-11-07T19:59:07.426876", "lvl": "target", "msg": "Filename '33369/nbd-deploy-vpt9pq7o/dtb/bcm2711-rpi-4-b+vc4.dtb'."}
- {"dt": "2023-11-07T19:59:07.427956", "lvl": "target", "msg": "Load address: 0x2400000"}
- {"dt": "2023-11-07T19:59:07.455446", "lvl": "target", "msg": "Loading: *\b##################################################  51.1 KiB"}
- {"dt": "2023-11-07T19:59:07.456331", "lvl": "target", "msg": "\t 1.5 MiB/s"}
- {"dt": "2023-11-07T19:59:07.457084", "lvl": "target", "msg": "done"}
- {"dt": "2023-11-07T19:59:07.459016", "lvl": "target", "msg": "Bytes transferred = 52323 (cc63 hex)"}
- {"dt": "2023-11-07T19:59:07.461070", "lvl": "input", "msg": "setenv bootargs 'console=ttyS0,115200n8 rw nbd.server=192.168.66.1 nbd.port=61981 root=/dev/ram0 ramdisk_size=16384 rootdelay=7   coherent_pool=1M 8250.nr_uarts=1 rw fstab=no systemd.mask=systemd-network-generator.service ip=dhcp verbose earlyprintk systemd.log_color=false ${extraargs} rw'\n"}
- {"dt": "2023-11-07T19:59:07.563682", "lvl": "target", "msg": "U-Boot> setenv bootargs 'console=ttyS0,115200n8 rw nbd.server=192.168.66.1 nbd.port=61981 root=/dev/ram0 ramdisk_size=16384 rootdelay=7   coherent_pool=1M 8250.nr_uarts=1 rw fstab=no systemd.mask=systemd-network-generator.service ip=dhcp verbose earlyprintk systemd.log_color=false ${extraargs} rw'"}
- {"dt": "2023-11-07T19:59:07.565408", "lvl": "debug", "msg": "bootloader-commands: Wait for prompt ['U-Boot>', 'Resetting CPU', 'Must RESET board to recover', 'TIMEOUT', 'Retry count exceeded', 'Retry time exceeded; starting again', 'ERROR: The remote end did not respond in time.', 'File not found', 'Bad Linux ARM64 Image magic!', 'Wrong Ramdisk Image Format', 'Ramdisk image is corrupt or invalid', 'ERROR: Failed to allocate', 'TFTP error: trying to overwrite reserved memory', 'Bad Linux RISCV Image magic!', 'Wrong Image Format for boot', 'ERROR: Did not find a cmdline Flattened Device Tree', 'ERROR: RD image overlaps OS image'] (timeout 00:18:36)"}
- {"dt": "2023-11-07T19:59:07.569890", "lvl": "target", "msg": "setenv bootargs 'console=ttyS0,115200n8 rw nbd.server=192.168.66.1 nbd.port=61981 root=/dev/ram0 ramdisk_size=16384 rootdelay=7   coherent_pool=1M 8250.nr_uarts=1 rw fstab=no systemd.mask=systemd-network-generator.service ip=dhcp verbose earlyprintk systemd.log_color=false ${extraargs} rw'"}
- {"dt": "2023-11-07T19:59:07.586893", "lvl": "input", "msg": "fdt addr 0x02400000; fdt boardsetup; fdt resize; fdt set audio status okay; booti 0x00080000 0x02700000:${initrd_size} 0x02400000\n"}
- {"dt": "2023-11-07T19:59:07.690101", "lvl": "target", "msg": "U-Boot> fdt addr 0x02400000; fdt boardsetup; fdt resize; fdt set audio status okay; booti 0x00080000 0x02700000:${initrd_size} 0x02400000"}
- {"dt": "2023-11-07T19:59:07.692364", "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-11-07T19:59:07.694884", "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:18:36)"}
- {"dt": "2023-11-07T19:59:07.701360", "lvl": "target", "msg": "fdt addr 0x02400000; fdt boardsetup; fdt resize; fdt set audio status okay; booti 0x00080000 0x02700000:${initrd_size} 0x02400000"}
- {"dt": "2023-11-07T19:59:07.890356", "lvl": "target", "msg": "## Flattened Device Tree blob at 02400000"}
- {"dt": "2023-11-07T19:59:07.891455", "lvl": "target", "msg": "   Booting using the fdt blob at 0x2400000"}
- {"dt": "2023-11-07T19:59:07.893624", "lvl": "target", "msg": "   Loading Ramdisk to 3ad50000, end 3af487cf ... OK"}
- {"dt": "2023-11-07T19:59:07.914875", "lvl": "target", "msg": "   Loading Device Tree to 000000003ad40000, end 000000003ad4ffff ... OK"}
- {"dt": "2023-11-07T19:59:07.915599", "lvl": "target", "msg": ""}
- {"dt": "2023-11-07T19:59:07.918102", "lvl": "target", "msg": "Starting kernel ..."}
- {"dt": "2023-11-07T19:59:07.918906", "lvl": "target", "msg": ""}
- {"dt": "2023-11-07T19:59:07.920278", "lvl": "debug", "msg": "end: 2.4.3 bootloader-commands (duration 00:01:09) [common]"}
- {"dt": "2023-11-07T19:59:07.921355", "lvl": "debug", "msg": "start: 2.4.4 auto-login-action (timeout 00:18:36) [common]"}
- {"dt": "2023-11-07T19:59:07.922199", "lvl": "debug", "msg": "Setting prompt string to ['Linux version [0-9]']"}
- {"dt": "2023-11-07T19:59:07.923001", "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-11-07T19:59:07.923793", "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:20:00)"}
- {"dt": "2023-11-07T19:59:09.754044", "lvl": "target", "msg": "[    0.000000] Booting Linux on physical CPU 0x0000000000 [0x410fd083]"}
- {"dt": "2023-11-07T19:59:09.755933", "lvl": "target", "msg": "[    0.000000] Linux version 5.15.34-v8 (oe-user@oe-host) (aarch64-agl-linux-gcc (GCC) 11.4.0, GNU ld (GNU Binutils) 2.38.20220708) #1 SMP PREEMPT Wed Aug 2 18:13:20 UTC 2023"}
- {"dt": "2023-11-07T19:59:09.758183", "lvl": "target", "msg": "[    0.000000] Machine model: Raspberry Pi 4 Model B"}
- {"dt": "2023-11-07T19:59:09.759938", "lvl": "target", "msg": "[    0.000000] efi: UEFI not found."}
- {"dt": "2023-11-07T19:59:09.761788", "lvl": "target", "msg": "[    0.000000] Reserved memory: created CMA memory pool at 0x000000001c400000, size 316 MiB"}
- {"dt": "2023-11-07T19:59:09.764549", "lvl": "debug", "msg": "start: 2.4.4.1 login-action (timeout 00:18:34) [common]"}
- {"dt": "2023-11-07T19:59:09.765306", "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-11-07T19:59:09.765954", "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-11-07T19:59:09.766488", "lvl": "debug", "msg": "Using line separator: #'\\n'#"}
- {"dt": "2023-11-07T19:59:09.766942", "lvl": "info", "msg": "Waiting for the login prompt"}
- {"dt": "2023-11-07T19:59:09.767389", "lvl": "info", "msg": "Parsing kernel messages"}
- {"dt": "2023-11-07T19:59:09.767806", "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", "root@raspberrypi4-64:~", "raspberrypi4-64:~#", "/ #", "login:", "Login incorrect"]}
- {"dt": "2023-11-07T19:59:09.768789", "lvl": "debug", "msg": "[login-action] Waiting for messages, (timeout 00:18:34)"}
- {"dt": "2023-11-07T19:59:09.796935", "lvl": "target", "msg": "[    0.000000] OF: reserved mem: initialized node linux,cma, compatible id shared-dma-pool"}
- {"dt": "2023-11-07T19:59:09.797923", "lvl": "target", "msg": "[    0.000000] Zone ranges:"}
- {"dt": "2023-11-07T19:59:09.799344", "lvl": "target", "msg": "[    0.000000]   DMA      [mem 0x0000000000000000-0x000000003fffffff]"}
- {"dt": "2023-11-07T19:59:09.800324", "lvl": "target", "msg": "[    0.000000]   DMA32    [mem 0x0000000040000000-0x00000000fbffffff]"}
- {"dt": "2023-11-07T19:59:09.801147", "lvl": "target", "msg": "[    0.000000]   Normal   empty"}
- {"dt": "2023-11-07T19:59:09.801895", "lvl": "target", "msg": "[    0.000000] Movable zone start for each node"}
- {"dt": "2023-11-07T19:59:09.802641", "lvl": "target", "msg": "[    0.000000] Early memory node ranges"}
- {"dt": "2023-11-07T19:59:09.803398", "lvl": "target", "msg": "[    0.000000]   node   0: [mem 0x0000000000000000-0x000000003b3fffff]"}
- {"dt": "2023-11-07T19:59:09.804334", "lvl": "target", "msg": "[    0.000000]   node   0: [mem 0x0000000040000000-0x00000000fbffffff]"}
- {"dt": "2023-11-07T19:59:09.840585", "lvl": "target", "msg": "[    0.000000] Initmem setup node 0 [mem 0x0000000000000000-0x00000000fbffffff]"}
- {"dt": "2023-11-07T19:59:09.841636", "lvl": "target", "msg": "[    0.000000] percpu: Embedded 29 pages/cpu s77848 r8192 d32744 u118784"}
- {"dt": "2023-11-07T19:59:09.842204", "lvl": "target", "msg": "[    0.000000] Detected PIPT I-cache on CPU0"}
- {"dt": "2023-11-07T19:59:09.842649", "lvl": "target", "msg": "[    0.000000] CPU features: detected: Spectre-v2"}
- {"dt": "2023-11-07T19:59:09.843076", "lvl": "target", "msg": "[    0.000000] CPU features: detected: Spectre-v3a"}
- {"dt": "2023-11-07T19:59:09.843499", "lvl": "target", "msg": "[    0.000000] CPU features: detected: Spectre-v4"}
- {"dt": "2023-11-07T19:59:09.843920", "lvl": "target", "msg": "[    0.000000] CPU features: detected: Spectre-BHB"}
- {"dt": "2023-11-07T19:59:09.845515", "lvl": "target", "msg": "[    0.000000] CPU features: detected: ARM errata 1165522, 1319367, or 1530923"}
- {"dt": "2023-11-07T19:59:09.884732", "lvl": "target", "msg": "[    0.000000] Built 1 zonelists, mobility grouping on.  Total pages: 996912"}
- {"dt": "2023-11-07T19:59:09.886375", "lvl": "target", "msg": "[    0.000000] Kernel command line: console=ttyS0,115200n8 rw nbd.server=192.168.66.1 nbd.port=61981 root=/dev/ram0 ramdisk_size=16384 rootdelay=7   coherent_pool=1M 8250.nr_uarts=1 rw fstab=no systemd.mask=systemd-network-generator.service ip=dhcp verbose earlyprintk systemd.log_color=false ${extraargs} rw"}
- {"dt": "2023-11-07T19:59:09.889599", "lvl": "target", "msg": "[    0.000000] Unknown kernel command line parameters \\\"verbose earlyprintk ${extraargs} fstab=no\\\", will be passed to user space."}
- {"dt": "2023-11-07T19:59:09.929346", "lvl": "target", "msg": "[    0.000000] Dentry cache hash table entries: 524288 (order: 10, 4194304 bytes, linear)"}
- {"dt": "2023-11-07T19:59:09.930480", "lvl": "target", "msg": "[    0.000000] Inode-cache hash table entries: 262144 (order: 9, 2097152 bytes, linear)"}
- {"dt": "2023-11-07T19:59:09.931680", "lvl": "target", "msg": "[    0.000000] mem auto-init: stack:off, heap alloc:off, heap free:off"}
- {"dt": "2023-11-07T19:59:09.932795", "lvl": "target", "msg": "[    0.000000] software IO TLB: mapped [mem 0x0000000036d40000-0x000000003ad40000] (64MB)"}
- {"dt": "2023-11-07T19:59:09.934599", "lvl": "target", "msg": "[    0.000000] Memory: 3553928K/4050944K available (12928K kernel code, 2044K rwdata, 4504K rodata, 4096K init, 1007K bss, 173432K reserved, 323584K cma-reserved)"}
- {"dt": "2023-11-07T19:59:09.973121", "lvl": "target", "msg": "[    0.000000] SLUB: HWalign=64, Order=0-3, MinObjects=0, CPUs=4, Nodes=1"}
- {"dt": "2023-11-07T19:59:09.974673", "lvl": "target", "msg": "[    0.000000] ftrace: allocating 40745 entries in 160 pages"}
- {"dt": "2023-11-07T19:59:09.976040", "lvl": "target", "msg": "[    0.000000] ftrace: allocated 160 pages with 2 groups"}
- {"dt": "2023-11-07T19:59:09.977451", "lvl": "target", "msg": "[    0.000000] trace event string verifier disabled"}
- {"dt": "2023-11-07T19:59:09.979030", "lvl": "target", "msg": "[    0.000000] rcu: Preemptible hierarchical RCU implementation."}
- {"dt": "2023-11-07T19:59:09.980478", "lvl": "target", "msg": "[    0.000000] rcu: \tRCU event tracing is enabled."}
- {"dt": "2023-11-07T19:59:09.981816", "lvl": "target", "msg": "[    0.000000] rcu: \tRCU restricting CPUs from NR_CPUS=256 to nr_cpu_ids=4."}
- {"dt": "2023-11-07T19:59:09.983144", "lvl": "target", "msg": "[    0.000000] \tTrampoline variant of Tasks RCU enabled."}
- {"dt": "2023-11-07T19:59:10.016306", "lvl": "target", "msg": "[    0.000000] \tRude variant of Tasks RCU enabled."}
- {"dt": "2023-11-07T19:59:10.017920", "lvl": "target", "msg": "[    0.000000] \tTracing variant of Tasks RCU enabled."}
- {"dt": "2023-11-07T19:59:10.018760", "lvl": "target", "msg": "[    0.000000] rcu: RCU calculated value of scheduler-enlistment delay is 25 jiffies."}
- {"dt": "2023-11-07T19:59:10.019514", "lvl": "target", "msg": "[    0.000000] rcu: Adjusting geometry for rcu_fanout_leaf=16, nr_cpu_ids=4"}
- {"dt": "2023-11-07T19:59:10.020319", "lvl": "target", "msg": "[    0.000000] NR_IRQS: 64, nr_irqs: 64, preallocated irqs: 0"}
- {"dt": "2023-11-07T19:59:10.021085", "lvl": "target", "msg": "[    0.000000] Root IRQ handler: gic_handle_irq"}
- {"dt": "2023-11-07T19:59:10.021961", "lvl": "target", "msg": "[    0.000000] GIC: Using split EOI/Deactivate mode"}
- {"dt": "2023-11-07T19:59:10.060106", "lvl": "target", "msg": "[    0.000000] irq_brcmstb_l2: registered L2 intc (/soc/interrupt-controller@7ef00100, parent irq: 10)"}
- {"dt": "2023-11-07T19:59:10.061608", "lvl": "target", "msg": "[    0.000000] random: get_random_bytes called from start_kernel+0x514/0x708 with crng_init=0"}
- {"dt": "2023-11-07T19:59:10.062247", "lvl": "target", "msg": "[    0.000000] arch_timer: cp15 timer(s) running at 54.00MHz (phys)."}
- {"dt": "2023-11-07T19:59:10.062793", "lvl": "target", "msg": "[    0.000000] clocksource: arch_sys_counter: mask: 0xffffffffffffff max_cycles: 0xc743ce346, max_idle_ns: 440795203123 ns"}
- {"dt": "2023-11-07T19:59:10.063334", "lvl": "target", "msg": "[    0.000001] sched_clock: 56 bits at 54MHz, resolution 18ns, wraps every 4398046511102ns"}
- {"dt": "2023-11-07T19:59:10.065105", "lvl": "target", "msg": "[    0.000251] Console: colour dummy device 80x25"}
- {"dt": "2023-11-07T19:59:10.104658", "lvl": "target", "msg": "[    0.000330] Calibrating delay loop (skipped), value calculated using timer frequency.. 108.00 BogoMIPS (lpj=216000)"}
- {"dt": "2023-11-07T19:59:10.105777", "lvl": "target", "msg": "[    0.000360] pid_max: default: 32768 minimum: 301"}
- {"dt": "2023-11-07T19:59:10.106734", "lvl": "target", "msg": "[    0.000493] LSM: Security Framework initializing"}
- {"dt": "2023-11-07T19:59:10.107647", "lvl": "target", "msg": "[    0.000739] Mount-cache hash table entries: 8192 (order: 4, 65536 bytes, linear)"}
- {"dt": "2023-11-07T19:59:10.108782", "lvl": "target", "msg": "[    0.000803] Mountpoint-cache hash table entries: 8192 (order: 4, 65536 bytes, linear)"}
- {"dt": "2023-11-07T19:59:10.109720", "lvl": "target", "msg": "[    0.001978] cgroup: Disabling memory control group subsystem"}
- {"dt": "2023-11-07T19:59:10.148099", "lvl": "target", "msg": "[    0.004531] rcu: Hierarchical SRCU implementation."}
- {"dt": "2023-11-07T19:59:10.149131", "lvl": "target", "msg": "[    0.005557] EFI services will not be available."}
- {"dt": "2023-11-07T19:59:10.150839", "lvl": "target", "msg": "[    0.006061] smp: Bringing up secondary CPUs ..."}
- {"dt": "2023-11-07T19:59:10.151777", "lvl": "target", "msg": "[    0.007120] Detected PIPT I-cache on CPU1"}
- {"dt": "2023-11-07T19:59:10.152741", "lvl": "target", "msg": "[    0.007192] CPU1: Booted secondary processor 0x0000000001 [0x410fd083]"}
- {"dt": "2023-11-07T19:59:10.153657", "lvl": "target", "msg": "[    0.008450] Detected PIPT I-cache on CPU2"}
- {"dt": "2023-11-07T19:59:10.154486", "lvl": "target", "msg": "[    0.008499] CPU2: Booted secondary processor 0x0000000002 [0x410fd083]"}
- {"dt": "2023-11-07T19:59:10.155274", "lvl": "target", "msg": "[    0.009622] Detected PIPT I-cache on CPU3"}
- {"dt": "2023-11-07T19:59:10.156236", "lvl": "target", "msg": "[    0.009671] CPU3: Booted secondary processor 0x0000000003 [0x410fd083]"}
- {"dt": "2023-11-07T19:59:10.191251", "lvl": "target", "msg": "[    0.009854] smp: Brought up 1 node, 4 CPUs"}
- {"dt": "2023-11-07T19:59:10.193255", "lvl": "target", "msg": "[    0.009901] SMP: Total of 4 processors activated."}
- {"dt": "2023-11-07T19:59:10.194258", "lvl": "target", "msg": "[    0.009917] CPU features: detected: 32-bit EL0 Support"}
- {"dt": "2023-11-07T19:59:10.195153", "lvl": "target", "msg": "[    0.009930] CPU features: detected: 32-bit EL1 Support"}
- {"dt": "2023-11-07T19:59:10.196122", "lvl": "target", "msg": "[    0.009946] CPU features: detected: CRC32 instructions"}
- {"dt": "2023-11-07T19:59:10.197231", "lvl": "target", "msg": "[    0.042684] CPU: All CPU(s) started at EL2"}
- {"dt": "2023-11-07T19:59:10.198207", "lvl": "target", "msg": "[    0.042770] alternatives: patching kernel code"}
- {"dt": "2023-11-07T19:59:10.199159", "lvl": "target", "msg": "[    0.044376] devtmpfs: initialized"}
- {"dt": "2023-11-07T19:59:10.200105", "lvl": "target", "msg": "[    0.054719] Enabled cp15_barrier support"}
- {"dt": "2023-11-07T19:59:10.201336", "lvl": "target", "msg": "[    0.054765] Enabled setend support"}
- {"dt": "2023-11-07T19:59:10.236141", "lvl": "target", "msg": "[    0.054788] KASLR disabled due to lack of seed"}
- {"dt": "2023-11-07T19:59:10.237333", "lvl": "target", "msg": "[    0.055113] clocksource: jiffies: mask: 0xffffffff max_cycles: 0xffffffff, max_idle_ns: 7645041785100000 ns"}
- {"dt": "2023-11-07T19:59:10.238290", "lvl": "target", "msg": "[    0.055149] futex hash table entries: 1024 (order: 4, 65536 bytes, linear)"}
- {"dt": "2023-11-07T19:59:10.239205", "lvl": "target", "msg": "[    0.065551] pinctrl core: initialized pinctrl subsystem"}
- {"dt": "2023-11-07T19:59:10.240090", "lvl": "target", "msg": "[    0.066341] DMI not present or invalid."}
- {"dt": "2023-11-07T19:59:10.241073", "lvl": "target", "msg": "[    0.066948] NET: Registered PF_NETLINK/PF_ROUTE protocol family"}
- {"dt": "2023-11-07T19:59:10.242168", "lvl": "target", "msg": "[    0.070408] DMA: preallocated 1024 KiB GFP_KERNEL pool for atomic allocations"}
- {"dt": "2023-11-07T19:59:10.280296", "lvl": "target", "msg": "[    0.070710] DMA: preallocated 1024 KiB GFP_KERNEL|GFP_DMA pool for atomic allocations"}
- {"dt": "2023-11-07T19:59:10.281309", "lvl": "target", "msg": "[    0.071597] DMA: preallocated 1024 KiB GFP_KERNEL|GFP_DMA32 pool for atomic allocations"}
- {"dt": "2023-11-07T19:59:10.282175", "lvl": "target", "msg": "[    0.071694] audit: initializing netlink subsys (disabled)"}
- {"dt": "2023-11-07T19:59:10.283200", "lvl": "target", "msg": "[    0.071979] audit: type=2000 audit(0.068:1): state=initialized audit_enabled=0 res=1"}
- {"dt": "2023-11-07T19:59:10.284092", "lvl": "target", "msg": "[    0.072518] thermal_sys: Registered thermal governor 'step_wise'"}
- {"dt": "2023-11-07T19:59:10.284988", "lvl": "target", "msg": "[    0.072747] cpuidle: using governor menu"}
- {"dt": "2023-11-07T19:59:10.323850", "lvl": "target", "msg": "[    0.072977] hw-breakpoint: found 6 breakpoint and 4 watchpoint registers."}
- {"dt": "2023-11-07T19:59:10.326393", "lvl": "target", "msg": "[    0.073163] ASID allocator initialised with 65536 entries"}
- {"dt": "2023-11-07T19:59:10.327684", "lvl": "target", "msg": "[    0.073317] Serial: AMBA PL011 UART driver"}
- {"dt": "2023-11-07T19:59:10.328933", "lvl": "target", "msg": "[    0.085001] bcm2835-mbox fe00b880.mailbox: mailbox enabled"}
- {"dt": "2023-11-07T19:59:10.330140", "lvl": "target", "msg": "[    0.112340] raspberrypi-firmware soc:firmware: Attached to firmware from 2020-01-22T17:23:15, variant start"}
- {"dt": "2023-11-07T19:59:10.331341", "lvl": "target", "msg": "[    0.116359] raspberrypi-firmware soc:firmware: Firmware hash is acb03c7d18aa08f25f6419d696d0cc39761d3e62"}
- {"dt": "2023-11-07T19:59:10.332790", "lvl": "target", "msg": "[    0.166974] bcm2835-dma fe007000.dma: DMA legacy API manager, dmachans=0x1"}
- {"dt": "2023-11-07T19:59:10.367839", "lvl": "target", "msg": "[    0.171241] vgaarb: loaded"}
- {"dt": "2023-11-07T19:59:10.369371", "lvl": "target", "msg": "[    0.171656] SCSI subsystem initialized"}
- {"dt": "2023-11-07T19:59:10.371913", "lvl": "target", "msg": "[    0.171866] usbcore: registered new interface driver usbfs"}
- {"dt": "2023-11-07T19:59:10.373431", "lvl": "target", "msg": "[    0.171924] usbcore: registered new interface driver hub"}
- {"dt": "2023-11-07T19:59:10.374729", "lvl": "target", "msg": "[    0.171991] usbcore: registered new device driver usb"}
- {"dt": "2023-11-07T19:59:10.375703", "lvl": "target", "msg": "[    0.172342] usb_phy_generic phy: supply vcc not found, using dummy regulator"}
- {"dt": "2023-11-07T19:59:10.376655", "lvl": "target", "msg": "[    0.172876] pps_core: LinuxPPS API ver. 1 registered"}
- {"dt": "2023-11-07T19:59:10.377735", "lvl": "target", "msg": "[    0.172894] pps_core: Software ver. 5.3.6 - Copyright 2005-2007 Rodolfo Giometti <giometti@linux.it>"}
- {"dt": "2023-11-07T19:59:10.411983", "lvl": "target", "msg": "[    0.172930] PTP clock support registered"}
- {"dt": "2023-11-07T19:59:10.414001", "lvl": "target", "msg": "[    0.173191] Advanced Linux Sound Architecture Driver Initialized."}
- {"dt": "2023-11-07T19:59:10.415084", "lvl": "target", "msg": "[    0.174396] clocksource: Switched to clocksource arch_sys_counter"}
- {"dt": "2023-11-07T19:59:10.416064", "lvl": "target", "msg": "[    0.262970] VFS: Disk quotas dquot_6.6.0"}
- {"dt": "2023-11-07T19:59:10.417131", "lvl": "target", "msg": "[    0.263090] VFS: Dquot-cache hash table entries: 512 (order 0, 4096 bytes)"}
- {"dt": "2023-11-07T19:59:10.418118", "lvl": "target", "msg": "[    0.263256] FS-Cache: Loaded"}
- {"dt": "2023-11-07T19:59:10.419087", "lvl": "target", "msg": "[    0.263484] CacheFiles: Loaded"}
- {"dt": "2023-11-07T19:59:10.420046", "lvl": "target", "msg": "[    0.274203] NET: Registered PF_INET protocol family"}
- {"dt": "2023-11-07T19:59:10.455826", "lvl": "target", "msg": "[    0.274694] IP idents hash table entries: 65536 (order: 7, 524288 bytes, linear)"}
- {"dt": "2023-11-07T19:59:10.458017", "lvl": "target", "msg": "[    0.278016] tcp_listen_portaddr_hash hash table entries: 2048 (order: 3, 32768 bytes, linear)"}
- {"dt": "2023-11-07T19:59:10.459323", "lvl": "target", "msg": "[    0.278078] TCP established hash table entries: 32768 (order: 6, 262144 bytes, linear)"}
- {"dt": "2023-11-07T19:59:10.460377", "lvl": "target", "msg": "[    0.278298] TCP bind hash table entries: 32768 (order: 7, 524288 bytes, linear)"}
- {"dt": "2023-11-07T19:59:10.461281", "lvl": "target", "msg": "[    0.278860] TCP: Hash tables configured (established 32768 bind 32768)"}
- {"dt": "2023-11-07T19:59:10.462211", "lvl": "target", "msg": "[    0.279093] UDP hash table entries: 2048 (order: 4, 65536 bytes, linear)"}
- {"dt": "2023-11-07T19:59:10.500264", "lvl": "target", "msg": "[    0.279161] UDP-Lite hash table entries: 2048 (order: 4, 65536 bytes, linear)"}
- {"dt": "2023-11-07T19:59:10.503111", "lvl": "target", "msg": "[    0.279462] NET: Registered PF_UNIX/PF_LOCAL protocol family"}
- {"dt": "2023-11-07T19:59:10.504771", "lvl": "target", "msg": "[    0.280453] RPC: Registered named UNIX socket transport module."}
- {"dt": "2023-11-07T19:59:10.506180", "lvl": "target", "msg": "[    0.280477] RPC: Registered udp transport module."}
- {"dt": "2023-11-07T19:59:10.507628", "lvl": "target", "msg": "[    0.280491] RPC: Registered tcp transport module."}
- {"dt": "2023-11-07T19:59:10.509048", "lvl": "target", "msg": "[    0.280505] RPC: Registered tcp NFSv4.1 backchannel transport module."}
- {"dt": "2023-11-07T19:59:10.510445", "lvl": "target", "msg": "[    0.280527] PCI: CLS 0 bytes, default 64"}
- {"dt": "2023-11-07T19:59:10.511783", "lvl": "target", "msg": "[    0.281069] Trying to unpack rootfs image as initramfs..."}
- {"dt": "2023-11-07T19:59:10.543671", "lvl": "target", "msg": "[    0.281480] rootfs image is not initramfs (no cpio magic); looks like an initrd"}
- {"dt": "2023-11-07T19:59:10.544789", "lvl": "target", "msg": "[    0.288590] Freeing initrd memory: 2016K"}
- {"dt": "2023-11-07T19:59:10.546598", "lvl": "target", "msg": "[    0.290471] hw perfevents: enabled with armv8_cortex_a72 PMU driver, 7 counters available"}
- {"dt": "2023-11-07T19:59:10.547480", "lvl": "target", "msg": "[    0.290814] kvm [1]: IPA Size Limit: 44 bits"}
- {"dt": "2023-11-07T19:59:10.548389", "lvl": "target", "msg": "[    0.292060] kvm [1]: vgic interrupt IRQ9"}
- {"dt": "2023-11-07T19:59:10.549055", "lvl": "target", "msg": "[    0.292334] kvm [1]: Hyp mode initialized successfully"}
- {"dt": "2023-11-07T19:59:10.549687", "lvl": "target", "msg": "[    1.052893] Initialise system trusted keyrings"}
- {"dt": "2023-11-07T19:59:10.550305", "lvl": "target", "msg": "[    1.053243] workingset: timestamp_bits=46 max_order=20 bucket_order=0"}
- {"dt": "2023-11-07T19:59:10.551069", "lvl": "target", "msg": "[    1.059886] zbud: loaded"}
- {"dt": "2023-11-07T19:59:10.587302", "lvl": "target", "msg": "[    1.061688] FS-Cache: Netfs 'nfs' registered for caching"}
- {"dt": "2023-11-07T19:59:10.588860", "lvl": "target", "msg": "[    1.062318] NFS: Registering the id_resolver key type"}
- {"dt": "2023-11-07T19:59:10.591189", "lvl": "target", "msg": "[    1.062370] Key type id_resolver registered"}
- {"dt": "2023-11-07T19:59:10.592613", "lvl": "target", "msg": "[    1.062425] Key type id_legacy registered"}
- {"dt": "2023-11-07T19:59:10.593744", "lvl": "target", "msg": "[    1.062534] nfs4filelayout_init: NFSv4 File Layout Driver Registering..."}
- {"dt": "2023-11-07T19:59:10.594818", "lvl": "target", "msg": "[    1.062551] nfs4flexfilelayout_init: NFSv4 Flexfile Layout Driver Registering..."}
- {"dt": "2023-11-07T19:59:10.595887", "lvl": "target", "msg": "[    1.063830] NET: Registered PF_ALG protocol family"}
- {"dt": "2023-11-07T19:59:10.597254", "lvl": "target", "msg": "[    1.063854] Key type asymmetric registered"}
- {"dt": "2023-11-07T19:59:10.631033", "lvl": "target", "msg": "[    1.063869] Asymmetric key parser 'x509' registered"}
- {"dt": "2023-11-07T19:59:10.633411", "lvl": "target", "msg": "[    1.063951] Block layer SCSI generic (bsg) driver version 0.4 loaded (major 246)"}
- {"dt": "2023-11-07T19:59:10.634454", "lvl": "target", "msg": "[    1.064198] io scheduler mq-deadline registered"}
- {"dt": "2023-11-07T19:59:10.635387", "lvl": "target", "msg": "[    1.064217] io scheduler kyber registered"}
- {"dt": "2023-11-07T19:59:10.636439", "lvl": "target", "msg": "[    1.071754] brcm-pcie fd500000.pcie: host bridge /scb/pcie@7d500000 ranges:"}
- {"dt": "2023-11-07T19:59:10.637111", "lvl": "target", "msg": "[    1.071803] brcm-pcie fd500000.pcie:   No bus range found for /scb/pcie@7d500000, using [bus 00-ff]"}
- {"dt": "2023-11-07T19:59:10.637908", "lvl": "target", "msg": "[    1.071891] brcm-pcie fd500000.pcie:      MEM 0x0600000000..0x063fffffff -> 0x00c0000000"}
- {"dt": "2023-11-07T19:59:10.674705", "lvl": "target", "msg": "[    1.071984] brcm-pcie fd500000.pcie:   IB MEM 0x0000000000..0x00bfffffff -> 0x0000000000"}
- {"dt": "2023-11-07T19:59:10.676871", "lvl": "target", "msg": "[    1.120495] brcm-pcie fd500000.pcie: link up, 5.0 GT/s PCIe x1 (SSC)"}
- {"dt": "2023-11-07T19:59:10.677914", "lvl": "target", "msg": "[    1.120895] brcm-pcie fd500000.pcie: PCI host bridge to bus 0000:00"}
- {"dt": "2023-11-07T19:59:10.678976", "lvl": "target", "msg": "[    1.120917] pci_bus 0000:00: root bus resource [bus 00-ff]"}
- {"dt": "2023-11-07T19:59:10.679908", "lvl": "target", "msg": "[    1.120939] pci_bus 0000:00: root bus resource [mem 0x600000000-0x63fffffff] (bus address [0xc0000000-0xffffffff])"}
- {"dt": "2023-11-07T19:59:10.681013", "lvl": "target", "msg": "[    1.121026] pci 0000:00:00.0: [14e4:2711] type 01 class 0x060400"}
- {"dt": "2023-11-07T19:59:10.718677", "lvl": "target", "msg": "[    1.121273] pci 0000:00:00.0: PME# supported from D0 D3hot"}
- {"dt": "2023-11-07T19:59:10.729160", "lvl": "target", "msg": "[    1.124997] pci 0000:00:00.0: bridge configuration invalid ([bus 00-00]), reconfiguring"}
- {"dt": "2023-11-07T19:59:10.730772", "lvl": "target", "msg": "[    1.125272] pci 0000:01:00.0: [1106:3483] type 00 class 0x0c0330"}
- {"dt": "2023-11-07T19:59:10.731913", "lvl": "target", "msg": "[    1.125344] pci 0000:01:00.0: reg 0x10: [mem 0x00000000-0x00000fff 64bit]"}
- {"dt": "2023-11-07T19:59:10.732489", "lvl": "target", "msg": "[    1.125590] pci 0000:01:00.0: PME# supported from D0 D3cold"}
- {"dt": "2023-11-07T19:59:10.732982", "lvl": "target", "msg": "[    1.129174] pci_bus 0000:01: busn_res: [bus 01-ff] end is updated to 01"}
- {"dt": "2023-11-07T19:59:10.733628", "lvl": "target", "msg": "[    1.129223] pci 0000:00:00.0: BAR 8: assigned [mem 0x600000000-0x6000fffff]"}
- {"dt": "2023-11-07T19:59:10.764609", "lvl": "target", "msg": "[    1.129249] pci 0000:01:00.0: BAR 0: assigned [mem 0x600000000-0x600000fff 64bit]"}
- {"dt": "2023-11-07T19:59:10.766414", "lvl": "target", "msg": "[    1.129291] pci 0000:00:00.0: PCI bridge to [bus 01]"}
- {"dt": "2023-11-07T19:59:10.768134", "lvl": "target", "msg": "[    1.129316] pci 0000:00:00.0:   bridge window [mem 0x600000000-0x6000fffff]"}
- {"dt": "2023-11-07T19:59:10.768980", "lvl": "target", "msg": "[    1.135494] Serial: 8250/16550 driver, 1 ports, IRQ sharing enabled"}
- {"dt": "2023-11-07T19:59:10.769706", "lvl": "target", "msg": "[    1.138310] iproc-rng200 fe104000.rng: hwrng registered"}
- {"dt": "2023-11-07T19:59:10.770259", "lvl": "target", "msg": "[    1.138836] vc-mem: phys_addr:0x00000000 mem_base=0x00000000 mem_size:0x00000000(0 MiB)"}
- {"dt": "2023-11-07T19:59:10.805894", "lvl": "target", "msg": "[    1.140272] gpiomem-bcm2835 fe200000.gpiomem: Initialised: Registers at 0xfe200000"}
- {"dt": "2023-11-07T19:59:10.806992", "lvl": "target", "msg": "[    1.153027] brd: module loaded"}
- {"dt": "2023-11-07T19:59:10.807833", "lvl": "target", "msg": "[    1.162659] loop: module loaded"}
- {"dt": "2023-11-07T19:59:10.809628", "lvl": "target", "msg": "[    1.193466] Loading iSCSI transport class v2.0-870."}
- {"dt": "2023-11-07T19:59:10.810534", "lvl": "target", "msg": "[    1.198126] bcmgenet fd580000.ethernet: GENET 5.0 EPHY: 0x0000"}
- {"dt": "2023-11-07T19:59:10.811340", "lvl": "target", "msg": "[    1.258549] unimac-mdio unimac-mdio.-19: Broadcom UniMAC MDIO bus"}
- {"dt": "2023-11-07T19:59:10.812122", "lvl": "target", "msg": "[    1.259626] usbcore: registered new interface driver r8152"}
- {"dt": "2023-11-07T19:59:10.812977", "lvl": "target", "msg": "[    1.259694] usbcore: registered new interface driver lan78xx"}
- {"dt": "2023-11-07T19:59:10.849587", "lvl": "target", "msg": "[    1.259711] ehci_hcd: USB 2.0 'Enhanced' Host Controller (EHCI) Driver"}
- {"dt": "2023-11-07T19:59:10.851037", "lvl": "target", "msg": "[    1.259726] ehci-pci: EHCI PCI platform driver"}
- {"dt": "2023-11-07T19:59:10.853625", "lvl": "target", "msg": "[    1.259789] ohci_hcd: USB 1.1 'Open' Host Controller (OHCI) Driver"}
- {"dt": "2023-11-07T19:59:10.854843", "lvl": "target", "msg": "[    1.259827] ohci-pci: OHCI PCI platform driver"}
- {"dt": "2023-11-07T19:59:10.855934", "lvl": "target", "msg": "[    1.261388] pci 0000:00:00.0: enabling device (0000 -> 0002)"}
- {"dt": "2023-11-07T19:59:10.857218", "lvl": "target", "msg": "[    1.261430] xhci_hcd 0000:01:00.0: enabling device (0000 -> 0002)"}
- {"dt": "2023-11-07T19:59:10.858445", "lvl": "target", "msg": "[    1.261534] xhci_hcd 0000:01:00.0: xHCI Host Controller"}
- {"dt": "2023-11-07T19:59:10.859667", "lvl": "target", "msg": "[    1.261569] xhci_hcd 0000:01:00.0: new USB bus registered, assigned bus number 1"}
- {"dt": "2023-11-07T19:59:10.895076", "lvl": "target", "msg": "[    1.262290] xhci_hcd 0000:01:00.0: hcc params 0x002841eb hci version 0x100 quirks 0x00003c0000000890"}
- {"dt": "2023-11-07T19:59:10.896797", "lvl": "target", "msg": "[    1.263241] usb usb1: New USB device found, idVendor=1d6b, idProduct=0002, bcdDevice= 5.15"}
- {"dt": "2023-11-07T19:59:10.898319", "lvl": "target", "msg": "[    1.263267] usb usb1: New USB device strings: Mfr=3, Product=2, SerialNumber=1"}
- {"dt": "2023-11-07T19:59:10.900018", "lvl": "target", "msg": "[    1.263286] usb usb1: Product: xHCI Host Controller"}
- {"dt": "2023-11-07T19:59:10.901600", "lvl": "target", "msg": "[    1.263303] usb usb1: Manufacturer: Linux 5.15.34-v8 xhci-hcd"}
- {"dt": "2023-11-07T19:59:10.903074", "lvl": "target", "msg": "[    1.263319] usb usb1: SerialNumber: 0000:01:00.0"}
- {"dt": "2023-11-07T19:59:10.904559", "lvl": "target", "msg": "[    1.264047] hub 1-0:1.0: USB hub found"}
- {"dt": "2023-11-07T19:59:10.937588", "lvl": "target", "msg": "[    1.264128] hub 1-0:1.0: 1 port detected"}
- {"dt": "2023-11-07T19:59:10.939692", "lvl": "target", "msg": "[    1.264781] xhci_hcd 0000:01:00.0: xHCI Host Controller"}
- {"dt": "2023-11-07T19:59:10.940758", "lvl": "target", "msg": "[    1.264808] xhci_hcd 0000:01:00.0: new USB bus registered, assigned bus number 2"}
- {"dt": "2023-11-07T19:59:10.941316", "lvl": "target", "msg": "[    1.264848] xhci_hcd 0000:01:00.0: Host supports USB 3.0 SuperSpeed"}
- {"dt": "2023-11-07T19:59:10.941856", "lvl": "target", "msg": "[    1.265223] usb usb2: New USB device found, idVendor=1d6b, idProduct=0003, bcdDevice= 5.15"}
- {"dt": "2023-11-07T19:59:10.942395", "lvl": "target", "msg": "[    1.265247] usb usb2: New USB device strings: Mfr=3, Product=2, SerialNumber=1"}
- {"dt": "2023-11-07T19:59:10.943020", "lvl": "target", "msg": "[    1.265264] usb usb2: Product: xHCI Host Controller"}
- {"dt": "2023-11-07T19:59:10.981342", "lvl": "target", "msg": "[    1.265280] usb usb2: Manufacturer: Linux 5.15.34-v8 xhci-hcd"}
- {"dt": "2023-11-07T19:59:10.983548", "lvl": "target", "msg": "[    1.265296] usb usb2: SerialNumber: 0000:01:00.0"}
- {"dt": "2023-11-07T19:59:10.984234", "lvl": "target", "msg": "[    1.265983] hub 2-0:1.0: USB hub found"}
- {"dt": "2023-11-07T19:59:10.984828", "lvl": "target", "msg": "[    1.266051] hub 2-0:1.0: 4 ports detected"}
- {"dt": "2023-11-07T19:59:10.985369", "lvl": "target", "msg": "[    1.267657] dwc_otg: version 3.00a 10-AUG-2012 (platform bus)"}
- {"dt": "2023-11-07T19:59:10.985897", "lvl": "target", "msg": "[    1.268521] usbcore: registered new interface driver uas"}
- {"dt": "2023-11-07T19:59:10.986418", "lvl": "target", "msg": "[    1.268625] usbcore: registered new interface driver usb-storage"}
- {"dt": "2023-11-07T19:59:10.987474", "lvl": "target", "msg": "[    1.268746] usbcore: registered new interface driver usbserial_generic"}
- {"dt": "2023-11-07T19:59:11.025131", "lvl": "target", "msg": "[    1.268783] usbserial: USB Serial support registered for generic"}
- {"dt": "2023-11-07T19:59:11.027734", "lvl": "target", "msg": "[    1.268853] usbcore: registered new interface driver cp210x"}
- {"dt": "2023-11-07T19:59:11.029225", "lvl": "target", "msg": "[    1.268896] usbserial: USB Serial support registered for cp210x"}
- {"dt": "2023-11-07T19:59:11.030569", "lvl": "target", "msg": "[    1.269124] mousedev: PS/2 mouse device common for all mice"}
- {"dt": "2023-11-07T19:59:11.031379", "lvl": "target", "msg": "[    1.269719] usbcore: registered new interface driver i2c-tiny-usb"}
- {"dt": "2023-11-07T19:59:11.032436", "lvl": "target", "msg": "[    1.274768] sdhci: Secure Digital Host Controller Interface driver"}
- {"dt": "2023-11-07T19:59:11.033598", "lvl": "target", "msg": "[    1.274791] sdhci: Copyright(c) Pierre Ossman"}
- {"dt": "2023-11-07T19:59:11.034433", "lvl": "target", "msg": "[    1.275432] sdhci-pltfm: SDHCI platform and OF driver helper"}
- {"dt": "2023-11-07T19:59:11.069025", "lvl": "target", "msg": "[    1.278873] ledtrig-cpu: registered to indicate activity on CPUs"}
- {"dt": "2023-11-07T19:59:11.070925", "lvl": "target", "msg": "[    1.279456] hid: raw HID events driver (C) Jiri Kosina"}
- {"dt": "2023-11-07T19:59:11.071868", "lvl": "target", "msg": "[    1.279803] usbcore: registered new interface driver usbhid"}
- {"dt": "2023-11-07T19:59:11.072795", "lvl": "target", "msg": "[    1.279821] usbhid: USB HID core driver"}
- {"dt": "2023-11-07T19:59:11.073725", "lvl": "target", "msg": "[    1.280129] ashmem: initialized"}
- {"dt": "2023-11-07T19:59:11.074586", "lvl": "target", "msg": "[    1.288209] usbcore: registered new interface driver snd-usb-audio"}
- {"dt": "2023-11-07T19:59:11.075457", "lvl": "target", "msg": "[    1.289195] Initializing XFRM netlink socket"}
- {"dt": "2023-11-07T19:59:11.076350", "lvl": "target", "msg": "[    1.289240] NET: Registered PF_PACKET protocol family"}
- {"dt": "2023-11-07T19:59:11.077136", "lvl": "target", "msg": "[    1.289376] Key type dns_resolver registered"}
- {"dt": "2023-11-07T19:59:11.112224", "lvl": "target", "msg": "[    1.290599] registered taskstats version 1"}
- {"dt": "2023-11-07T19:59:11.114175", "lvl": "target", "msg": "[    1.290637] Loading compiled-in X.509 certificates"}
- {"dt": "2023-11-07T19:59:11.115121", "lvl": "target", "msg": "[    1.291615] Key type ._fscrypt registered"}
- {"dt": "2023-11-07T19:59:11.115955", "lvl": "target", "msg": "[    1.291635] Key type .fscrypt registered"}
- {"dt": "2023-11-07T19:59:11.116869", "lvl": "target", "msg": "[    1.291649] Key type fscrypt-provisioning registered"}
- {"dt": "2023-11-07T19:59:11.117735", "lvl": "target", "msg": "[    1.303008] uart-pl011 fe201000.serial: there is not valid maps for state default"}
- {"dt": "2023-11-07T19:59:11.118584", "lvl": "target", "msg": "[    1.303291] uart-pl011 fe201000.serial: cts_event_workaround enabled"}
- {"dt": "2023-11-07T19:59:11.119598", "lvl": "target", "msg": "[    1.303474] fe201000.serial: ttyAMA0 at MMIO 0xfe201000 (irq = 19, base_baud = 0) is a PL011 rev2"}
- {"dt": "2023-11-07T19:59:11.156448", "lvl": "target", "msg": "[    1.311492] bcm2835-aux-uart fe215040.serial: there is not valid maps for state default"}
- {"dt": "2023-11-07T19:59:11.158251", "lvl": "target", "msg": "[    1.312190] printk: console [ttyS0] disabled"}
- {"dt": "2023-11-07T19:59:11.161223", "lvl": "target", "msg": "[    1.312308] fe215040.serial: ttyS0 at MMIO 0xfe215040 (irq = 20, base_baud = 62500000) is a 16550"}
- {"dt": "2023-11-07T19:59:11.162419", "lvl": "target", "msg": "[    1.518436] usb 1-1: new high-speed USB device number 2 using xhci_hcd"}
- {"dt": "2023-11-07T19:59:11.163384", "lvl": "target", "msg": "[    1.531007] printk: console [ttyS0] enabled"}
- {"dt": "2023-11-07T19:59:11.164287", "lvl": "target", "msg": "[    1.684043] usb 1-1: New USB device found, idVendor=2109, idProduct=3431, bcdDevice= 4.20"}
- {"dt": "2023-11-07T19:59:11.199698", "lvl": "target", "msg": "[    1.690116] bcm2835-wdt bcm2835-wdt: Broadcom BCM2835 watchdog timer"}
- {"dt": "2023-11-07T19:59:11.202707", "lvl": "target", "msg": "[    1.696593] usb 1-1: New USB device strings: Mfr=0, Product=1, SerialNumber=0"}
- {"dt": "2023-11-07T19:59:11.204283", "lvl": "target", "msg": "[    1.702833] bcm2835-power bcm2835-power: Broadcom BCM2835 power domains driver"}
- {"dt": "2023-11-07T19:59:11.205649", "lvl": "target", "msg": "[    1.707215] usb 1-1: Product: USB2.0 Hub"}
- {"dt": "2023-11-07T19:59:11.206937", "lvl": "target", "msg": "[    1.713019] mmc-bcm2835 fe300000.mmcnr: mmc_debug:0 mmc_debug2:0"}
- {"dt": "2023-11-07T19:59:11.208162", "lvl": "target", "msg": "[    1.717858] hub 1-1:1.0: USB hub found"}
- {"dt": "2023-11-07T19:59:11.209464", "lvl": "target", "msg": "[    1.720546] mmc-bcm2835 fe300000.mmcnr: DMA channel allocated"}
- {"dt": "2023-11-07T19:59:11.211112", "lvl": "target", "msg": "[    1.727570] hub 1-1:1.0: 4 ports detected"}
- {"dt": "2023-11-07T19:59:11.212582", "lvl": "target", "msg": "[    1.760684] of_cfs_init"}
- {"dt": "2023-11-07T19:59:11.248892", "lvl": "target", "msg": "[    1.795118] mmc0: SDHCI controller on fe340000.mmc [fe340000.mmc] using ADMA"}
- {"dt": "2023-11-07T19:59:11.249560", "lvl": "target", "msg": "[    1.797301] of_cfs_init: OK"}
- {"dt": "2023-11-07T19:59:11.250020", "lvl": "target", "msg": "[    2.098439] usb 1-1.3: new high-speed USB device number 3 using xhci_hcd"}
- {"dt": "2023-11-07T19:59:11.250451", "lvl": "target", "msg": "[    2.109053] random: fast init done"}
- {"dt": "2023-11-07T19:59:11.250982", "lvl": "target", "msg": "[    2.823596] bcmgenet fd580000.ethernet: configuring instance for external RGMII (RX delay)"}
- {"dt": "2023-11-07T19:59:11.251441", "lvl": "target", "msg": "[    2.832441] bcmgenet fd580000.ethernet eth0: Link is Down"}
- {"dt": "2023-11-07T19:59:11.282762", "lvl": "target", "msg": "[    2.865832] mmc1: new high speed SDIO card at address 0001"}
- {"dt": "2023-11-07T19:59:11.365771", "lvl": "target", "msg": "[    2.923232] mmc0: new ultra high speed DDR50 SDHC card at address 59b4"}
- {"dt": "2023-11-07T19:59:11.367724", "lvl": "target", "msg": "[    2.924398] usb 1-1.3: New USB device found, idVendor=2109, idProduct=2812, bcdDevice= b.e0"}
- {"dt": "2023-11-07T19:59:11.369376", "lvl": "target", "msg": "[    2.930862] mmcblk0: mmc0:59b4 USDU1 7.51 GiB "}
- {"dt": "2023-11-07T19:59:11.371149", "lvl": "target", "msg": "[    2.938363] usb 1-1.3: New USB device strings: Mfr=1, Product=2, SerialNumber=0"}
- {"dt": "2023-11-07T19:59:11.372942", "lvl": "target", "msg": "[    2.945857]  mmcblk0: p1 p2"}
- {"dt": "2023-11-07T19:59:11.374951", "lvl": "target", "msg": "[    2.950318] usb 1-1.3: Product: USB2.0 Hub             "}
- {"dt": "2023-11-07T19:59:11.376676", "lvl": "target", "msg": "[    2.950332] usb 1-1.3: Manufacturer: VIA Labs, Inc.         "}
- {"dt": "2023-11-07T19:59:11.384709", "lvl": "target", "msg": "[    2.953677] mmcblk0: mmc0:59b4 USDU1 7.51 GiB"}
- {"dt": "2023-11-07T19:59:11.385377", "lvl": "target", "msg": "[    2.960030] hub 1-1.3:1.0: USB hub found"}
- {"dt": "2023-11-07T19:59:11.387877", "lvl": "target", "msg": "[    2.972930] hub 1-1.3:1.0: 4 ports detected"}
- {"dt": "2023-11-07T19:59:11.703279", "lvl": "target", "msg": "[    3.282427] usb 1-1.3.1: new high-speed USB device number 4 using xhci_hcd"}
- {"dt": "2023-11-07T19:59:11.853257", "lvl": "target", "msg": "[    3.404374] usb 1-1.3.1: New USB device found, idVendor=2109, idProduct=2812, bcdDevice= b.e0"}
- {"dt": "2023-11-07T19:59:11.855178", "lvl": "target", "msg": "[    3.413056] usb 1-1.3.1: New USB device strings: Mfr=1, Product=2, SerialNumber=0"}
- {"dt": "2023-11-07T19:59:11.856979", "lvl": "target", "msg": "[    3.420675] usb 1-1.3.1: Product: USB2.0 Hub             "}
- {"dt": "2023-11-07T19:59:11.858695", "lvl": "target", "msg": "[    3.426173] usb 1-1.3.1: Manufacturer: VIA Labs, Inc.         "}
- {"dt": "2023-11-07T19:59:11.860402", "lvl": "target", "msg": "[    3.433519] hub 1-1.3.1:1.0: USB hub found"}
- {"dt": "2023-11-07T19:59:11.862382", "lvl": "target", "msg": "[    3.437959] hub 1-1.3.1:1.0: 4 ports detected"}
- {"dt": "2023-11-07T19:59:12.167707", "lvl": "target", "msg": "[    3.746426] usb 1-1.3.1.1: new high-speed USB device number 5 using xhci_hcd"}
- {"dt": "2023-11-07T19:59:12.320366", "lvl": "target", "msg": "[    3.878088] usb 1-1.3.1.1: New USB device found, idVendor=0bda, idProduct=2838, bcdDevice= 1.00"}
- {"dt": "2023-11-07T19:59:12.322319", "lvl": "target", "msg": "[    3.886950] usb 1-1.3.1.1: New USB device strings: Mfr=1, Product=2, SerialNumber=3"}
- {"dt": "2023-11-07T19:59:12.324061", "lvl": "target", "msg": "[    3.894752] usb 1-1.3.1.1: Product: RTL2838UHIDIR"}
- {"dt": "2023-11-07T19:59:12.325806", "lvl": "target", "msg": "[    3.899542] usb 1-1.3.1.1: Manufacturer: Realtek"}
- {"dt": "2023-11-07T19:59:12.327738", "lvl": "target", "msg": "[    3.904242] usb 1-1.3.1.1: SerialNumber: 00000001"}
- {"dt": "2023-11-07T19:59:15.331543", "lvl": "target", "msg": "[    6.910659] bcmgenet fd580000.ethernet eth0: Link is Up - 1Gbps/Full - flow control rx/tx"}
- {"dt": "2023-11-07T19:59:16.401779", "lvl": "target", "msg": "[    6.942420] Sending DHCP requests ., OK"}
- {"dt": "2023-11-07T19:59:16.405340", "lvl": "target", "msg": "[    7.962396] IP-Config: Got DHCP answer from 192.168.66.1, my address is 192.168.66.241"}
- {"dt": "2023-11-07T19:59:16.407316", "lvl": "target", "msg": "[    7.970471] IP-Config: Complete:"}
- {"dt": "2023-11-07T19:59:16.409302", "lvl": "target", "msg": "[    7.973747]      device=eth0, hwaddr=dc:a6:32:54:fa:25, ipaddr=192.168.66.241, mask=255.255.255.0, gw=192.168.66.1"}
- {"dt": "2023-11-07T19:59:16.411083", "lvl": "target", "msg": "[    7.984271]      host=192.168.66.241, domain=, nis-domain=(none)"}
- {"dt": "2023-11-07T19:59:16.412706", "lvl": "target", "msg": "[    7.990391]      bootserver=0.0.0.0, rootserver=0.0.0.0, rootpath="}
- {"dt": "2023-11-07T19:59:16.413284", "lvl": "target", "msg": "[    7.990404]      nameserver0=10.1.1.1"}
- {"dt": "2023-11-07T19:59:16.423213", "lvl": "target", "msg": "[    8.002504] ALSA device list:"}
- {"dt": "2023-11-07T19:59:16.424035", "lvl": "target", "msg": "[    8.005530]   No soundcards found."}
- {"dt": "2023-11-07T19:59:16.426673", "lvl": "target", "msg": "[    8.009446] Waiting 7 sec before mounting root device..."}
- {"dt": "2023-11-07T19:59:23.490185", "lvl": "target", "msg": "[   15.070618] RAMDISK: gzip image found at block 0"}
- {"dt": "2023-11-07T19:59:23.829562", "lvl": "target", "msg": "[   15.383418] EXT4-fs (ram0): mounted filesystem with ordered data mode. Opts: (null). Quota mode: none."}
- {"dt": "2023-11-07T19:59:23.831639", "lvl": "target", "msg": "[   15.392982] VFS: Mounted root (ext4 filesystem) on device 1:0."}
- {"dt": "2023-11-07T19:59:23.833544", "lvl": "target", "msg": "[   15.399137] devtmpfs: mounted"}
- {"dt": "2023-11-07T19:59:23.835626", "lvl": "target", "msg": "[   15.411590] Freeing unused kernel memory: 4096K"}
- {"dt": "2023-11-07T19:59:23.837499", "lvl": "target", "msg": "[   15.416418] Run /sbin/init as init process"}
- {"dt": "2023-11-07T19:59:23.881413", "lvl": "target", "msg": "________________________________________________________________________________"}
- {"dt": "2023-11-07T19:59:23.883050", "lvl": "target", "msg": "         ___   ________                _   __     __  __                __"}
- {"dt": "2023-11-07T19:59:23.884678", "lvl": "target", "msg": "        /   | / ____/ /               / | / /__  / /_/ /_  ____  ____  / /_"}
- {"dt": "2023-11-07T19:59:23.886453", "lvl": "target", "msg": "       / /| |/ / __/ /      ______   /  |/ / _ \\/ __/ __ \\/ __ \\/ __ \\/ __/"}
- {"dt": "2023-11-07T19:59:23.888006", "lvl": "target", "msg": "      / ___ / /_/ / /___   /_____/  / /|  /  __/ /_/ /_/ / /_/ / /_/ / /_"}
- {"dt": "2023-11-07T19:59:23.889614", "lvl": "target", "msg": "     /_/  |_\\____/_____/           /_/ |_/\\___/\\__/_.___/\\____/\\____/\\__/"}
- {"dt": "2023-11-07T19:59:23.928209", "lvl": "target", "msg": "________________________________________________________________________________"}
- {"dt": "2023-11-07T19:59:23.929798", "lvl": "target", "msg": "/sbin/init[1]: starting initrd script"}
- {"dt": "2023-11-07T19:59:23.930824", "lvl": "target", "msg": "/sbin/init[1]: mounting FS: proc /proc"}
- {"dt": "2023-11-07T19:59:23.931731", "lvl": "target", "msg": "/sbin/init[1]: mounting FS: sysfs /sys"}
- {"dt": "2023-11-07T19:59:23.932728", "lvl": "target", "msg": "/sbin/init[1]: mounting FS: devtmpfs /dev"}
- {"dt": "2023-11-07T19:59:23.933626", "lvl": "target", "msg": "/sbin/init[1]: /dev (devtmpfs) already mounted"}
- {"dt": "2023-11-07T19:59:23.934551", "lvl": "target", "msg": "/sbin/init[1]: mounting FS: devpts /dev/pts"}
- {"dt": "2023-11-07T19:59:23.935588", "lvl": "target", "msg": "/sbin/init[1]: mounting FS: tmpfs /dev/shm"}
- {"dt": "2023-11-07T19:59:23.936527", "lvl": "target", "msg": "/sbin/init[1]: mounting FS: tmpfs /tmp"}
- {"dt": "2023-11-07T19:59:23.946655", "lvl": "target", "msg": "/sbin/init[1]: mounting FS: tmpfs /run"}
- {"dt": "2023-11-07T19:59:23.972687", "lvl": "target", "msg": "/sbin/init[1]: NBD parameters: device /dev/nbd0, server 192.168.66.1:61981"}
- {"dt": "2023-11-07T19:59:23.974390", "lvl": "target", "msg": "/sbin/init[1]: Starting NBD client"}
- {"dt": "2023-11-07T19:59:24.004512", "lvl": "target", "msg": "[   15.583550] nbd0: detected capacity change from 0 to 8526288"}
- {"dt": "2023-11-07T19:59:24.005594", "lvl": "target", "msg": "/sbin/init[1]: NBD client successfully started"}
- {"dt": "2023-11-07T19:59:24.664891", "lvl": "target", "msg": "[   16.211985] EXT4-fs (nbd0): recovery complete"}
- {"dt": "2023-11-07T19:59:24.667876", "lvl": "target", "msg": "[   16.220403] EXT4-fs (nbd0): mounted filesystem with ordered data mode. Opts: (null). Quota mode: none."}
- {"dt": "2023-11-07T19:59:24.668624", "lvl": "target", "msg": "/sbin/init[1]: Moving /dev to new rootfs"}
- {"dt": "2023-11-07T19:59:24.669226", "lvl": "target", "msg": "/sbin/init[1]: Moving /proc to new rootfs"}
- {"dt": "2023-11-07T19:59:24.669884", "lvl": "target", "msg": "/sbin/init[1]: Moving /sys to new rootfs"}
- {"dt": "2023-11-07T19:59:24.670527", "lvl": "target", "msg": "/sbin/init[1]: Moving /tmp to new rootfs"}
- {"dt": "2023-11-07T19:59:24.671090", "lvl": "target", "msg": "/sbin/init[1]: Moving /run to new rootfs"}
- {"dt": "2023-11-07T19:59:24.671776", "lvl": "target", "msg": "/sbin/init[1]: Switching to new rootfs"}
- {"dt": "2023-11-07T19:59:29.915185", "lvl": "target", "msg": "[   16.371340] request_module: kmod_concurrent_max (0) close to 0 (max_modprobes: 50), for module binfmt-464c, throttling..."}
- {"dt": "2023-11-07T19:59:29.917043", "lvl": "target", "msg": "/sbin/init[1]: ERROR Unable to find any active network interface."}
- {"dt": "2023-11-07T19:59:29.920429", "lvl": "target", "msg": "/sbin/init[1]: Adjusting Connman command line. Will be: 'connmand -r -n'"}
- {"dt": "2023-11-07T19:59:29.949072", "lvl": "target", "msg": "[   21.470430] request_module: modprobe binfmt-464c cannot be processed, kmod busy with 50 threads for more than 5 seconds now"}
- {"dt": "2023-11-07T19:59:35.015613", "lvl": "target", "msg": "[   21.524256] request_module: kmod_concurrent_max (0) close to 0 (max_modprobes: 50), for module binfmt-464c, throttling..."}
- {"dt": "2023-11-07T19:59:35.018002", "lvl": "target", "msg": "/sbin/init: line 150: sed: not found"}
- {"dt": "2023-11-07T19:59:35.054398", "lvl": "target", "msg": "[   26.590463] request_module: modprobe binfmt-464c cannot be processed, kmod busy with 50 threads for more than 5 seconds now"}
- {"dt": "2023-11-07T19:59:40.135279", "lvl": "target", "msg": "[   26.627845] request_module: kmod_concurrent_max (0) close to 0 (max_modprobes: 50), for module binfmt-464c, throttling..."}
- {"dt": "2023-11-07T19:59:40.137602", "lvl": "target", "msg": "/sbin/init: line 154: rm: not found"}
- {"dt": "2023-11-07T19:59:40.177137", "lvl": "target", "msg": "[   31.710424] request_module: modprobe binfmt-464c cannot be processed, kmod busy with 50 threads for more than 5 seconds now"}
- {"dt": "2023-11-07T19:59:40.180788", "lvl": "target", "msg": "[   31.740954] request_module: kmod_concurrent_max (0) close to 0 (max_modprobes: 50), for module binfmt-464c, throttling..."}
- {"dt": "2023-11-07T19:59:45.285582", "lvl": "target", "msg": "[   31.741140] request_module: kmod_concurrent_max (0) close to 0 (max_modprobes: 50), for module binfmt-464c, throttling..."}
- {"dt": "2023-11-07T19:59:45.286450", "lvl": "target", "msg": "[   36.830423] request_module: modprobe binfmt-464c cannot be processed, kmod busy with 50 threads for more than 5 seconds now"}
- {"dt": "2023-11-07T19:59:45.287130", "lvl": "target", "msg": "/sbin/init: line 155: grep: not found"}
- {"dt": "2023-11-07T19:59:45.287896", "lvl": "target", "msg": "/sbin/init: line 155: sed: not found"}
- {"dt": "2023-11-07T19:59:45.288746", "lvl": "target", "msg": "/sbin/init[1]: Unmounting /tmp and /run"}
- {"dt": "2023-11-07T19:59:45.303348", "lvl": "target", "msg": "[   36.830445] request_module: modprobe binfmt-464c cannot be processed, kmod busy with 50 threads for more than 5 seconds now"}
- {"dt": "2023-11-07T19:59:48.325523", "lvl": "target", "msg": "[   36.877857] request_module: kmod_concurrent_max (0) close to 0 (max_modprobes: 50), for module binfmt-464c, throttling..."}
- {"dt": "2023-11-07T19:59:48.328787", "lvl": "target", "msg": "[   39.902447] cam-dummy-reg: disabling"}
- {"dt": "2023-11-07T19:59:50.373208", "lvl": "target", "msg": "/sbin/init: line 175: umount: not found"}
- {"dt": "2023-11-07T19:59:50.393983", "lvl": "target", "msg": "[   41.950425] request_module: modprobe binfmt-464c cannot be processed, kmod busy with 50 threads for more than 5 seconds now"}
- {"dt": "2023-11-07T19:59:55.506320", "lvl": "target", "msg": "[   41.972620] request_module: kmod_concurrent_max (0) close to 0 (max_modprobes: 50), for module binfmt-464c, throttling..."}
- {"dt": "2023-11-07T19:59:55.507320", "lvl": "target", "msg": "/sbin/init: line 176: umount: not found"}
- {"dt": "2023-11-07T19:59:55.512316", "lvl": "target", "msg": "/sbin/init[1]: Exec'ing systemd"}
- {"dt": "2023-11-07T19:59:55.535497", "lvl": "target", "msg": "[   47.070495] request_module: modprobe binfmt-464c cannot be processed, kmod busy with 50 threads for more than 5 seconds now"}
- {"dt": "2023-11-07T20:00:00.614094", "lvl": "target", "msg": "[   47.109582] request_module: kmod_concurrent_max (0) close to 0 (max_modprobes: 50), for module binfmt-464c, throttling..."}
- {"dt": "2023-11-07T20:00:00.616788", "lvl": "target", "msg": "/sbin/init: line 183: cat: not found"}
- {"dt": "2023-11-07T20:00:00.662457", "lvl": "target", "msg": "[   52.190424] request_module: modprobe binfmt-464c cannot be processed, kmod busy with 50 threads for more than 5 seconds now"}
- {"dt": "2023-11-07T20:00:05.758593", "lvl": "target", "msg": "[   52.239525] request_module: kmod_concurrent_max (0) close to 0 (max_modprobes: 50), for module binfmt-464c, throttling..."}
- {"dt": "2023-11-07T20:00:05.759767", "lvl": "target", "msg": "/sbin/in[   57.310453] request_module: modprobe binfmt-464c cannot be processed, kmod busy with 50 threads for more than 5 seconds now"}
- {"dt": "2023-11-07T20:00:05.760666", "lvl": "target", "msg": "it:[  e x57.329480] Kernel panic - not syncing: Attempted to kill init! exitcode=0x00007f00"}
- {"dt": "2023-11-07T20:00:05.761343", "lvl": "target", "msg": "ec: line[   57.349478] CPU: 1 PID: 1 Comm: init Not tainted 5.15.34-v8 #1"}
- {"dt": "2023-11-07T20:00:05.762845", "lvl": "debug", "msg": "Matched prompt #9: Kernel panic - not syncing"}
- {"dt": "2023-11-07T20:00:05.763653", "lvl": "debug", "msg": "Setting prompt string to ['end Kernel panic[^\\\\r]*\\\\r', 'root@raspberrypi4-64:~', 'raspberrypi4-64:~#', '/ #', 'login:', 'Login incorrect']"}
- {"dt": "2023-11-07T20:00:05.801773", "lvl": "target", "msg": " 193: /l[   57.356087] Hardware name: Raspberry Pi 4 Model B (DT)"}
- {"dt": "2023-11-07T20:00:05.802897", "lvl": "target", "msg": "ib/syste[   57.361998] Call trace:"}
- {"dt": "2023-11-07T20:00:05.804509", "lvl": "target", "msg": "md/syste[   57.365172]  dump_backtrace+0x0/0x1b0"}
- {"dt": "2023-11-07T20:00:05.805195", "lvl": "target", "msg": "md: not [   57.369584]  show_stack+0x24/0x30"}
- {"dt": "2023-11-07T20:00:05.805742", "lvl": "target", "msg": "found"}
- {"dt": "2023-11-07T20:00:05.806407", "lvl": "target", "msg": "[   57.373642]  dump_stack_lvl+0x8c/0xb8"}
- {"dt": "2023-11-07T20:00:05.807016", "lvl": "target", "msg": "[   57.377964]  dump_stack+0x18/0x34"}
- {"dt": "2023-11-07T20:00:05.807539", "lvl": "target", "msg": "[   57.381326]  panic+0x17c/0x374"}
- {"dt": "2023-11-07T20:00:05.808051", "lvl": "target", "msg": "[   57.384428]  do_exit+0x9c0/0xa10"}
- {"dt": "2023-11-07T20:00:05.808640", "lvl": "target", "msg": "[   57.387706]  do_group_exit+0x44/0xac"}
- {"dt": "2023-11-07T20:00:05.809191", "lvl": "target", "msg": "[   57.391335]  __wake_up_parent+0x0/0x3c"}
- {"dt": "2023-11-07T20:00:05.809735", "lvl": "target", "msg": "[   57.395140]  invoke_syscall+0x50/0x120"}
- {"dt": "2023-11-07T20:00:05.810538", "lvl": "target", "msg": "[   57.398949]  el0_svc_common.constprop.0+0x68/0x124"}
- {"dt": "2023-11-07T20:00:05.850292", "lvl": "target", "msg": "[   57.403814]  do_el0_svc+0x34/0x9c"}
- {"dt": "2023-11-07T20:00:05.851407", "lvl": "target", "msg": "[   57.407179]  el0_svc+0x2c/0x90"}
- {"dt": "2023-11-07T20:00:05.853059", "lvl": "target", "msg": "[   57.410282]  el0t_64_sync_handler+0xa4/0x130"}
- {"dt": "2023-11-07T20:00:05.854053", "lvl": "target", "msg": "[   57.414617]  el0t_64_sync+0x1a0/0x1a4"}
- {"dt": "2023-11-07T20:00:05.855032", "lvl": "target", "msg": "[   57.418334] SMP: stopping secondary CPUs"}
- {"dt": "2023-11-07T20:00:05.856058", "lvl": "target", "msg": "[   57.422316] Kernel Offset: disabled"}
- {"dt": "2023-11-07T20:00:05.857135", "lvl": "target", "msg": "[   57.425851] CPU features: 0x200000f1,00000846"}
- {"dt": "2023-11-07T20:00:05.858099", "lvl": "target", "msg": "[   57.430270] Memory Limit: none"}
- {"dt": "2023-11-07T20:00:05.860134", "lvl": "target", "msg": "[   57.433371] ---[ end Kernel panic - not syncing: Attempted to kill init! exitcode=0x00007f00 ]---"}
- {"dt": "2023-11-07T20:00:05.861624", "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', 'root@raspberrypi4-64:~', 'raspberrypi4-64:~#', '/ #', 'login:', 'Login incorrect']"}
- {"dt": "2023-11-07T20:00:05.862410", "lvl": "error", "msg": "login-action kernel 'panic'"}
- {"dt": "2023-11-07T20:00:05.863169", "lvl": "results", "msg": {"case": "kernel-messages", "definition": "lava", "duration": "56.09", "extra": {"extra": [{"kind": "panic", "message": "it:[  e x57.329480] Kernel panic - not syncing: Attempted to kill init! exitcode=0x00007f00\r\nec: line[   57.349478] CPU: 1 PID: 1 Comm: init Not tainted 5.15.34-v8 #1\r\n 193: /l[   57.356087] Hardware name: Raspberry Pi 4 Model B (DT)\r\nib/syste[   57.361998] Call trace:\r\nmd/syste[   57.365172]  dump_backtrace+0x0/0x1b0\r\nmd: not [   57.369584]  show_stack+0x24/0x30\r\nfound\r\n[   57.373642]  dump_stack_lvl+0x8c/0xb8\r\n[   57.377964]  dump_stack+0x18/0x34\r\n[   57.381326]  panic+0x17c/0x374\r\n[   57.384428]  do_exit+0x9c0/0xa10\r\n[   57.387706]  do_group_exit+0x44/0xac\r\n[   57.391335]  __wake_up_parent+0x0/0x3c\r\n[   57.395140]  invoke_syscall+0x50/0x120\r\n[   57.398949]  el0_svc_common.constprop.0+0x68/0x124\r\n[   57.403814]  do_el0_svc+0x34/0x9c\r\n[   57.407179]  el0_svc+0x2c/0x90\r\n[   57.410282]  el0t_64_sync_handler+0xa4/0x130\r\n[   57.414617]  el0t_64_sync+0x1a0/0x1a4\r\n[   57.418334] SMP: stopping secondary CPUs\r\n[   57.422316] Kernel Offset: disabled\r\n[   57.425851] CPU features: 0x200000f1,00000846\r\n[   57.430270] Memory Limit: none\r\n[   57.433371] ---[ end Kernel panic - not syncing: Attempted to kill init! exitcode=0x00007f00 ]---"}]}, "level": "2.4.4.1", "namespace": "common", "result": "fail"}}
- {"dt": "2023-11-07T20:00:05.864809", "lvl": "exception", "msg": "it:[  e x57.329480] Kernel panic - not syncing: Attempted to kill init! exitcode=0x00007f00\r\nec: line[   57.349478] CPU: 1 PID: 1 Comm: init Not tainted 5.15.34-v8 #1\r\n 193: /l[   57.356087] Hardware name: Raspberry Pi 4 Model B (DT)\r\nib/syste[   57.361998] Call trace:\r\nmd/syste[   57.365172]  dump_backtrace+0x0/0x1b0\r\nmd: not [   57.369584]  show_stack+0x24/0x30\r\nfound\r\n[   57.373642]  dump_stack_lvl+0x8c/0xb8\r\n[   57.377964]  dump_stack+0x18/0x34\r\n[   57.381326]  panic+0x17c/0x374\r\n[   57.384428]  do_exit+0x9c0/0xa10\r\n[   57.387706]  do_group_exit+0x44/0xac\r\n[   57.391335]  __wake_up_parent+0x0/0x3c\r\n[   57.395140]  invoke_syscall+0x50/0x120\r\n[   57.398949]  el0_svc_common.constprop.0+0x68/0x124\r\n[   57.403814]  do_el0_svc+0x34/0x9c\r\n[   57.407179]  el0_svc+0x2c/0x90\r\n[   57.410282]  el0t_64_sync_handler+0xa4/0x130\r\n[   57.414617]  el0t_64_sync+0x1a0/0x1a4\r\n[   57.418334] SMP: stopping secondary CPUs\r\n[   57.422316] Kernel Offset: disabled\r\n[   57.425851] CPU features: 0x200000f1,00000846\r\n[   57.430270] Memory Limit: none\r\n[   57.433371] ---[ end Kernel panic - not syncing: Attempted to kill init! exitcode=0x00007f00 ]---"}
- {"dt": "2023-11-07T20:00:05.865637", "lvl": "debug", "msg": "end: 2.4.4.1 login-action (duration 00:00:56) [common]"}
- {"dt": "2023-11-07T20:00:05.866300", "lvl": "results", "msg": {"case": "login-action", "definition": "lava", "duration": "56.10", "extra": {"fail": "it:[  e x57.329480] Kernel panic - not syncing: Attempted to kill init! exitcode=0x00007f00\r\nec: line[   57.349478] CPU: 1 PID: 1 Comm: init Not tainted 5.15.34-v8 #1\r\n 193: /l[   57.356087] Hardware name: Raspberry Pi 4 Model B (DT)\r\nib/syste[   57.361998] Call trace:\r\nmd/syste[   57.365172]  dump_backtrace+0x0/0x1b0\r\nmd: not [   57.369584]  show_stack+0x24/0x30\r\nfound\r\n[   57.373642]  dump_stack_lvl+0x8c/0xb8\r\n[   57.377964]  dump_stack+0x18/0x34\r\n[   57.381326]  panic+0x17c/0x374\r\n[   57.384428]  do_exit+0x9c0/0xa10\r\n[   57.387706]  do_group_exit+0x44/0xac\r\n[   57.391335]  __wake_up_parent+0x0/0x3c\r\n[   57.395140]  invoke_syscall+0x50/0x120\r\n[   57.398949]  el0_svc_common.constprop.0+0x68/0x124\r\n[   57.403814]  do_el0_svc+0x34/0x9c\r\n[   57.407179]  el0_svc+0x2c/0x90\r\n[   57.410282]  el0t_64_sync_handler+0xa4/0x130\r\n[   57.414617]  el0t_64_sync+0x1a0/0x1a4\r\n[   57.418334] SMP: stopping secondary CPUs\r\n[   57.422316] Kernel Offset: disabled\r\n[   57.425851] CPU features: 0x200000f1,00000846\r\n[   57.430270] Memory Limit: none\r\n[   57.433371] ---[ end Kernel panic - not syncing: Attempted to kill init! exitcode=0x00007f00 ]---"}, "level": "2.4.4.1", "namespace": "common", "result": "fail"}}
- {"dt": "2023-11-07T20:00:05.867579", "lvl": "error", "msg": "auto-login-action failed: 1 of 1 attempts. 'it:[  e x57.329480] Kernel panic - not syncing: Attempted to kill init! exitcode=0x00007f00\r\nec: line[   57.349478] CPU: 1 PID: 1 Comm: init Not tainted 5.15.34-v8 #1\r\n 193: /l[   57.356087] Hardware name: Raspberry Pi 4 Model B (DT)\r\nib/syste[   57.361998] Call trace:\r\nmd/syste[   57.365172]  dump_backtrace+0x0/0x1b0\r\nmd: not [   57.369584]  show_stack+0x24/0x30\r\nfound\r\n[   57.373642]  dump_stack_lvl+0x8c/0xb8\r\n[   57.377964]  dump_stack+0x18/0x34\r\n[   57.381326]  panic+0x17c/0x374\r\n[   57.384428]  do_exit+0x9c0/0xa10\r\n[   57.387706]  do_group_exit+0x44/0xac\r\n[   57.391335]  __wake_up_parent+0x0/0x3c\r\n[   57.395140]  invoke_syscall+0x50/0x120\r\n[   57.398949]  el0_svc_common.constprop.0+0x68/0x124\r\n[   57.403814]  do_el0_svc+0x34/0x9c\r\n[   57.407179]  el0_svc+0x2c/0x90\r\n[   57.410282]  el0t_64_sync_handler+0xa4/0x130\r\n[   57.414617]  el0t_64_sync+0x1a0/0x1a4\r\n[   57.418334] SMP: stopping secondary CPUs\r\n[   57.422316] Kernel Offset: disabled\r\n[   57.425851] CPU features: 0x200000f1,00000846\r\n[   57.430270] Memory Limit: none\r\n[   57.433371] ---[ end Kernel panic - not syncing: Attempted to kill init! exitcode=0x00007f00 ]---'"}
- {"dt": "2023-11-07T20:00:05.868498", "lvl": "exception", "msg": "it:[  e x57.329480] Kernel panic - not syncing: Attempted to kill init! exitcode=0x00007f00\r\nec: line[   57.349478] CPU: 1 PID: 1 Comm: init Not tainted 5.15.34-v8 #1\r\n 193: /l[   57.356087] Hardware name: Raspberry Pi 4 Model B (DT)\r\nib/syste[   57.361998] Call trace:\r\nmd/syste[   57.365172]  dump_backtrace+0x0/0x1b0\r\nmd: not [   57.369584]  show_stack+0x24/0x30\r\nfound\r\n[   57.373642]  dump_stack_lvl+0x8c/0xb8\r\n[   57.377964]  dump_stack+0x18/0x34\r\n[   57.381326]  panic+0x17c/0x374\r\n[   57.384428]  do_exit+0x9c0/0xa10\r\n[   57.387706]  do_group_exit+0x44/0xac\r\n[   57.391335]  __wake_up_parent+0x0/0x3c\r\n[   57.395140]  invoke_syscall+0x50/0x120\r\n[   57.398949]  el0_svc_common.constprop.0+0x68/0x124\r\n[   57.403814]  do_el0_svc+0x34/0x9c\r\n[   57.407179]  el0_svc+0x2c/0x90\r\n[   57.410282]  el0t_64_sync_handler+0xa4/0x130\r\n[   57.414617]  el0t_64_sync+0x1a0/0x1a4\r\n[   57.418334] SMP: stopping secondary CPUs\r\n[   57.422316] Kernel Offset: disabled\r\n[   57.425851] CPU features: 0x200000f1,00000846\r\n[   57.430270] Memory Limit: none\r\n[   57.433371] ---[ end Kernel panic - not syncing: Attempted to kill init! exitcode=0x00007f00 ]---"}
- {"dt": "2023-11-07T20:00:05.869277", "lvl": "debug", "msg": "end: 2.4.4 auto-login-action (duration 00:00:58) [common]"}
- {"dt": "2023-11-07T20:00:05.870000", "lvl": "results", "msg": {"case": "auto-login-action", "definition": "lava", "duration": "57.95", "extra": {"fail": "it:[  e x57.329480] Kernel panic - not syncing: Attempted to kill init! exitcode=0x00007f00\r\nec: line[   57.349478] CPU: 1 PID: 1 Comm: init Not tainted 5.15.34-v8 #1\r\n 193: /l[   57.356087] Hardware name: Raspberry Pi 4 Model B (DT)\r\nib/syste[   57.361998] Call trace:\r\nmd/syste[   57.365172]  dump_backtrace+0x0/0x1b0\r\nmd: not [   57.369584]  show_stack+0x24/0x30\r\nfound\r\n[   57.373642]  dump_stack_lvl+0x8c/0xb8\r\n[   57.377964]  dump_stack+0x18/0x34\r\n[   57.381326]  panic+0x17c/0x374\r\n[   57.384428]  do_exit+0x9c0/0xa10\r\n[   57.387706]  do_group_exit+0x44/0xac\r\n[   57.391335]  __wake_up_parent+0x0/0x3c\r\n[   57.395140]  invoke_syscall+0x50/0x120\r\n[   57.398949]  el0_svc_common.constprop.0+0x68/0x124\r\n[   57.403814]  do_el0_svc+0x34/0x9c\r\n[   57.407179]  el0_svc+0x2c/0x90\r\n[   57.410282]  el0t_64_sync_handler+0xa4/0x130\r\n[   57.414617]  el0t_64_sync+0x1a0/0x1a4\r\n[   57.418334] SMP: stopping secondary CPUs\r\n[   57.422316] Kernel Offset: disabled\r\n[   57.425851] CPU features: 0x200000f1,00000846\r\n[   57.430270] Memory Limit: none\r\n[   57.433371] ---[ end Kernel panic - not syncing: Attempted to kill init! exitcode=0x00007f00 ]---"}, "level": "2.4.4", "namespace": "common", "result": "fail"}}
- {"dt": "2023-11-07T20:00:05.871389", "lvl": "exception", "msg": "it:[  e x57.329480] Kernel panic - not syncing: Attempted to kill init! exitcode=0x00007f00\r\nec: line[   57.349478] CPU: 1 PID: 1 Comm: init Not tainted 5.15.34-v8 #1\r\n 193: /l[   57.356087] Hardware name: Raspberry Pi 4 Model B (DT)\r\nib/syste[   57.361998] Call trace:\r\nmd/syste[   57.365172]  dump_backtrace+0x0/0x1b0\r\nmd: not [   57.369584]  show_stack+0x24/0x30\r\nfound\r\n[   57.373642]  dump_stack_lvl+0x8c/0xb8\r\n[   57.377964]  dump_stack+0x18/0x34\r\n[   57.381326]  panic+0x17c/0x374\r\n[   57.384428]  do_exit+0x9c0/0xa10\r\n[   57.387706]  do_group_exit+0x44/0xac\r\n[   57.391335]  __wake_up_parent+0x0/0x3c\r\n[   57.395140]  invoke_syscall+0x50/0x120\r\n[   57.398949]  el0_svc_common.constprop.0+0x68/0x124\r\n[   57.403814]  do_el0_svc+0x34/0x9c\r\n[   57.407179]  el0_svc+0x2c/0x90\r\n[   57.410282]  el0t_64_sync_handler+0xa4/0x130\r\n[   57.414617]  el0t_64_sync+0x1a0/0x1a4\r\n[   57.418334] SMP: stopping secondary CPUs\r\n[   57.422316] Kernel Offset: disabled\r\n[   57.425851] CPU features: 0x200000f1,00000846\r\n[   57.430270] Memory Limit: none\r\n[   57.433371] ---[ end Kernel panic - not syncing: Attempted to kill init! exitcode=0x00007f00 ]---"}
- {"dt": "2023-11-07T20:00:05.872156", "lvl": "debug", "msg": "end: 2.4 uboot-commands (duration 00:02:19) [common]"}
- {"dt": "2023-11-07T20:00:05.873010", "lvl": "results", "msg": {"case": "uboot-commands", "definition": "lava", "duration": "138.61", "extra": {"fail": "it:[  e x57.329480] Kernel panic - not syncing: Attempted to kill init! exitcode=0x00007f00\r\nec: line[   57.349478] CPU: 1 PID: 1 Comm: init Not tainted 5.15.34-v8 #1\r\n 193: /l[   57.356087] Hardware name: Raspberry Pi 4 Model B (DT)\r\nib/syste[   57.361998] Call trace:\r\nmd/syste[   57.365172]  dump_backtrace+0x0/0x1b0\r\nmd: not [   57.369584]  show_stack+0x24/0x30\r\nfound\r\n[   57.373642]  dump_stack_lvl+0x8c/0xb8\r\n[   57.377964]  dump_stack+0x18/0x34\r\n[   57.381326]  panic+0x17c/0x374\r\n[   57.384428]  do_exit+0x9c0/0xa10\r\n[   57.387706]  do_group_exit+0x44/0xac\r\n[   57.391335]  __wake_up_parent+0x0/0x3c\r\n[   57.395140]  invoke_syscall+0x50/0x120\r\n[   57.398949]  el0_svc_common.constprop.0+0x68/0x124\r\n[   57.403814]  do_el0_svc+0x34/0x9c\r\n[   57.407179]  el0_svc+0x2c/0x90\r\n[   57.410282]  el0t_64_sync_handler+0xa4/0x130\r\n[   57.414617]  el0t_64_sync+0x1a0/0x1a4\r\n[   57.418334] SMP: stopping secondary CPUs\r\n[   57.422316] Kernel Offset: disabled\r\n[   57.425851] CPU features: 0x200000f1,00000846\r\n[   57.430270] Memory Limit: none\r\n[   57.433371] ---[ end Kernel panic - not syncing: Attempted to kill init! exitcode=0x00007f00 ]---"}, "level": "2.4", "namespace": "common", "result": "fail"}}
- {"dt": "2023-11-07T20:00:05.874383", "lvl": "error", "msg": "uboot-action failed: 1 of 1 attempts. 'it:[  e x57.329480] Kernel panic - not syncing: Attempted to kill init! exitcode=0x00007f00\r\nec: line[   57.349478] CPU: 1 PID: 1 Comm: init Not tainted 5.15.34-v8 #1\r\n 193: /l[   57.356087] Hardware name: Raspberry Pi 4 Model B (DT)\r\nib/syste[   57.361998] Call trace:\r\nmd/syste[   57.365172]  dump_backtrace+0x0/0x1b0\r\nmd: not [   57.369584]  show_stack+0x24/0x30\r\nfound\r\n[   57.373642]  dump_stack_lvl+0x8c/0xb8\r\n[   57.377964]  dump_stack+0x18/0x34\r\n[   57.381326]  panic+0x17c/0x374\r\n[   57.384428]  do_exit+0x9c0/0xa10\r\n[   57.387706]  do_group_exit+0x44/0xac\r\n[   57.391335]  __wake_up_parent+0x0/0x3c\r\n[   57.395140]  invoke_syscall+0x50/0x120\r\n[   57.398949]  el0_svc_common.constprop.0+0x68/0x124\r\n[   57.403814]  do_el0_svc+0x34/0x9c\r\n[   57.407179]  el0_svc+0x2c/0x90\r\n[   57.410282]  el0t_64_sync_handler+0xa4/0x130\r\n[   57.414617]  el0t_64_sync+0x1a0/0x1a4\r\n[   57.418334] SMP: stopping secondary CPUs\r\n[   57.422316] Kernel Offset: disabled\r\n[   57.425851] CPU features: 0x200000f1,00000846\r\n[   57.430270] Memory Limit: none\r\n[   57.433371] ---[ end Kernel panic - not syncing: Attempted to kill init! exitcode=0x00007f00 ]---'"}
- {"dt": "2023-11-07T20:00:05.875408", "lvl": "exception", "msg": "it:[  e x57.329480] Kernel panic - not syncing: Attempted to kill init! exitcode=0x00007f00\r\nec: line[   57.349478] CPU: 1 PID: 1 Comm: init Not tainted 5.15.34-v8 #1\r\n 193: /l[   57.356087] Hardware name: Raspberry Pi 4 Model B (DT)\r\nib/syste[   57.361998] Call trace:\r\nmd/syste[   57.365172]  dump_backtrace+0x0/0x1b0\r\nmd: not [   57.369584]  show_stack+0x24/0x30\r\nfound\r\n[   57.373642]  dump_stack_lvl+0x8c/0xb8\r\n[   57.377964]  dump_stack+0x18/0x34\r\n[   57.381326]  panic+0x17c/0x374\r\n[   57.384428]  do_exit+0x9c0/0xa10\r\n[   57.387706]  do_group_exit+0x44/0xac\r\n[   57.391335]  __wake_up_parent+0x0/0x3c\r\n[   57.395140]  invoke_syscall+0x50/0x120\r\n[   57.398949]  el0_svc_common.constprop.0+0x68/0x124\r\n[   57.403814]  do_el0_svc+0x34/0x9c\r\n[   57.407179]  el0_svc+0x2c/0x90\r\n[   57.410282]  el0t_64_sync_handler+0xa4/0x130\r\n[   57.414617]  el0t_64_sync+0x1a0/0x1a4\r\n[   57.418334] SMP: stopping secondary CPUs\r\n[   57.422316] Kernel Offset: disabled\r\n[   57.425851] CPU features: 0x200000f1,00000846\r\n[   57.430270] Memory Limit: none\r\n[   57.433371] ---[ end Kernel panic - not syncing: Attempted to kill init! exitcode=0x00007f00 ]---"}
- {"dt": "2023-11-07T20:00:05.876276", "lvl": "info", "msg": "end: 2 uboot-action (duration 00:02:22) [common]"}
- {"dt": "2023-11-07T20:00:05.877037", "lvl": "results", "msg": {"case": "uboot-action", "definition": "lava", "duration": "141.85", "extra": {"fail": "it:[  e x57.329480] Kernel panic - not syncing: Attempted to kill init! exitcode=0x00007f00\r\nec: line[   57.349478] CPU: 1 PID: 1 Comm: init Not tainted 5.15.34-v8 #1\r\n 193: /l[   57.356087] Hardware name: Raspberry Pi 4 Model B (DT)\r\nib/syste[   57.361998] Call trace:\r\nmd/syste[   57.365172]  dump_backtrace+0x0/0x1b0\r\nmd: not [   57.369584]  show_stack+0x24/0x30\r\nfound\r\n[   57.373642]  dump_stack_lvl+0x8c/0xb8\r\n[   57.377964]  dump_stack+0x18/0x34\r\n[   57.381326]  panic+0x17c/0x374\r\n[   57.384428]  do_exit+0x9c0/0xa10\r\n[   57.387706]  do_group_exit+0x44/0xac\r\n[   57.391335]  __wake_up_parent+0x0/0x3c\r\n[   57.395140]  invoke_syscall+0x50/0x120\r\n[   57.398949]  el0_svc_common.constprop.0+0x68/0x124\r\n[   57.403814]  do_el0_svc+0x34/0x9c\r\n[   57.407179]  el0_svc+0x2c/0x90\r\n[   57.410282]  el0t_64_sync_handler+0xa4/0x130\r\n[   57.414617]  el0t_64_sync+0x1a0/0x1a4\r\n[   57.418334] SMP: stopping secondary CPUs\r\n[   57.422316] Kernel Offset: disabled\r\n[   57.425851] CPU features: 0x200000f1,00000846\r\n[   57.430270] Memory Limit: none\r\n[   57.433371] ---[ end Kernel panic - not syncing: Attempted to kill init! exitcode=0x00007f00 ]---"}, "level": "2", "namespace": "common", "result": "fail"}}
- {"dt": "2023-11-07T20:00:05.878501", "lvl": "info", "msg": "Cleaning after the job"}
- {"dt": "2023-11-07T20:00:05.879358", "lvl": "debug", "msg": "Cleaning up download directory: /var/lib/lava/dispatcher/tmp/33369/nbd-deploy-vpt9pq7o/initrd"}
- {"dt": "2023-11-07T20:00:05.883336", "lvl": "debug", "msg": "Cleaning up download directory: /var/lib/lava/dispatcher/tmp/33369/nbd-deploy-vpt9pq7o/kernel"}
- {"dt": "2023-11-07T20:00:05.890566", "lvl": "debug", "msg": "Cleaning up download directory: /var/lib/lava/dispatcher/tmp/33369/nbd-deploy-vpt9pq7o/dtb"}
- {"dt": "2023-11-07T20:00:05.892128", "lvl": "debug", "msg": "Cleaning up download directory: /var/lib/lava/dispatcher/tmp/33369/nbd-deploy-vpt9pq7o/nbdroot"}
- {"dt": "2023-11-07T20:00:06.252708", "lvl": "debug", "msg": "start: 7.1 power-off (timeout 00:00:10) [common]"}
- {"dt": "2023-11-07T20:00:06.253864", "lvl": "debug", "msg": "Calling: 'nice' '/usr/local/bin/acme-cli' '-s' '192.168.66.2' 'switch_off' '7'"}
- {"dt": "2023-11-07T20:00:09.919718", "lvl": "debug", "msg": ">> Success\r"}
- {"dt": "2023-11-07T20:00:09.963577", "lvl": "debug", "msg": "Returned 0 in 3 seconds"}
- {"dt": "2023-11-07T20:00:10.065772", "lvl": "debug", "msg": "end: 7.1 power-off (duration 00:00:04) [common]"}
- {"dt": "2023-11-07T20:00:10.066872", "lvl": "results", "msg": {"case": "power-off", "definition": "lava", "duration": "3.81", "extra": {"status": "success"}, "level": "7.1", "namespace": "common", "result": "pass"}}
- {"dt": "2023-11-07T20:00:10.069204", "lvl": "debug", "msg": "start: 7.2 read-feedback (timeout 00:29:56) [common]"}
- {"dt": "2023-11-07T20:00:11.072557", "lvl": "info", "msg": "Finalising connection for namespace 'common'"}
- {"dt": "2023-11-07T20:00:11.073490", "lvl": "info", "msg": "Disconnecting from shell: Finalise"}
- {"dt": "2023-11-07T20:00:11.175193", "lvl": "debug", "msg": "end: 7.2 read-feedback (duration 00:00:01) [common]"}
- {"dt": "2023-11-07T20:00:11.175993", "lvl": "debug", "msg": "lava-xnbd cleanup"}
- {"dt": "2023-11-07T20:00:11.176591", "lvl": "debug", "msg": "clean NBD port 61981"}
- {"dt": "2023-11-07T20:00:16.705529", "lvl": "info", "msg": "Override tmp directory removed at /var/lib/lava/dispatcher/tmp/33369"}
- {"dt": "2023-11-07T20:00:16.811950", "lvl": "info", "msg": "Root tmp directory removed at /var/lib/lava/dispatcher/tmp/33369"}
- {"dt": "2023-11-07T20:00:16.813216", "lvl": "error", "msg": "JobError: Your job cannot terminate cleanly."}
- {"dt": "2023-11-07T20:00:16.814049", "lvl": "results", "msg": {"case": "job", "definition": "lava", "error_msg": "it:[  e x57.329480] Kernel panic - not syncing: Attempted to kill init! exitcode=0x00007f00\r\nec: line[   57.349478] CPU: 1 PID: 1 Comm: init Not tainted 5.15.34-v8 #1\r\n 193: /l[   57.356087] Hardware name: Raspberry Pi 4 Model B (DT)\r\nib/syste[   57.361998] Call trace:\r\nmd/syste[   57.365172]  dump_backtrace+0x0/0x1b0\r\nmd: not [   57.369584]  show_stack+0x24/0x30\r\nfound\r\n[   57.373642]  dump_stack_lvl+0x8c/0xb8\r\n[   57.377964]  dump_stack+0x18/0x34\r\n[   57.381326]  panic+0x17c/0x374\r\n[   57.384428]  do_exit+0x9c0/0xa10\r\n[   57.387706]  do_group_exit+0x44/0xac\r\n[   57.391335]  __wake_up_parent+0x0/0x3c\r\n[   57.395140]  invoke_syscall+0x50/0x120\r\n[   57.398949]  el0_svc_common.constprop.0+0x68/0x124\r\n[   57.403814]  do_el0_svc+0x34/0x9c\r\n[   57.407179]  el0_svc+0x2c/0x90\r\n[   57.410282]  el0t_64_sync_handler+0xa4/0x130\r\n[   57.414617]  el0t_64_sync+0x1a0/0x1a4\r\n[   57.418334] SMP: stopping secondary CPUs\r\n[   57.422316] Kernel Offset: disabled\r\n[   57.425851] CPU features: 0x200000f1,00000846\r\n[   57.430270] Memory Limit: none\r\n[   57.433371] ---[ end Kernel panic - not syncing: Attempted to kill init! exitcode=0x00007f00 ]---", "error_type": "Job", "result": "fail"}}
