- {"dt": "2024-12-11T12:35:53.023120", "lvl": "warning", "msg": "Action timeout for connect-device exceeds Job timeout"}
- {"dt": "2024-12-11T12:35:53.023497", "lvl": "warning", "msg": "Action timeout for pdu-reboot exceeds Job timeout"}
- {"dt": "2024-12-11T12:35:53.023628", "lvl": "warning", "msg": "Action timeout for reset-device exceeds Job timeout"}
- {"dt": "2024-12-11T12:35:53.023764", "lvl": "warning", "msg": "Action timeout for login-action exceeds Job timeout"}
- {"dt": "2024-12-11T12:35:53.023874", "lvl": "warning", "msg": "Action timeout for auto-login-action exceeds Job timeout"}
- {"dt": "2024-12-11T12:35:53.024013", "lvl": "warning", "msg": "Action timeout for expect-shell-connection exceeds Job timeout"}
- {"dt": "2024-12-11T12:35:53.024123", "lvl": "warning", "msg": "Action timeout for overlay-unpack exceeds Job timeout"}
- {"dt": "2024-12-11T12:35:53.024235", "lvl": "warning", "msg": "Action timeout for export-device-env exceeds Job timeout"}
- {"dt": "2024-12-11T12:35:53.024359", "lvl": "warning", "msg": "Action timeout for minimal-boot exceeds Job timeout"}
- {"dt": "2024-12-11T12:35:53.038138", "lvl": "info", "msg": "lava-dispatcher, installed at version: 2023.10"}
- {"dt": "2024-12-11T12:35:53.038257", "lvl": "info", "msg": "start: 0 validate"}
- {"dt": "2024-12-11T12:35:53.038403", "lvl": "info", "msg": "Start time: 2024-12-11 12:35:53.038394+00:00 (UTC)"}
- {"dt": "2024-12-11T12:35:53.038594", "lvl": "debug", "msg": "Validating that http://download.automotivelinux.org/AGL/release/ricefish/18.0.2/raspberrypi5/deploy/images/raspberrypi5/initramfs-netboot-image-raspberrypi5-20241028040434.ext4.gz exists"}
- {"dt": "2024-12-11T12:35:55.319657", "lvl": "debug", "msg": "Validating that http://download.automotivelinux.org/AGL/release/ricefish/18.0.2/raspberrypi5/deploy/images/raspberrypi5/Image exists"}
- {"dt": "2024-12-11T12:35:55.522102", "lvl": "debug", "msg": "Validating that http://download.automotivelinux.org/AGL/release/ricefish/18.0.2/raspberrypi5/deploy/images/raspberrypi5/bcm2712-rpi-5-b.dtb exists"}
- {"dt": "2024-12-11T12:35:55.725480", "lvl": "debug", "msg": "Validating that http://download.automotivelinux.org/AGL/release/ricefish/18.0.2/raspberrypi5/deploy/images/raspberrypi5/agl-ivi-demo-qt-raspberrypi5-20241028040434.ext4.xz exists"}
- {"dt": "2024-12-11T12:35:55.931689", "lvl": "info", "msg": "validate duration: 2.89"}
- {"dt": "2024-12-11T12:35:55.931828", "lvl": "results", "msg": {"case": "validate", "definition": "lava", "result": "pass"}}
- {"dt": "2024-12-11T12:35:55.932007", "lvl": "info", "msg": "start: 1 nbd-deploy (timeout 00:10:00) [common]"}
- {"dt": "2024-12-11T12:35:55.932095", "lvl": "info", "msg": "Making protocol call for nbd-deploy using lava-xnbd"}
- {"dt": "2024-12-11T12:35:55.932171", "lvl": "debug", "msg": "[nbd-deploy] Checking protocol data for lava-xnbd"}
- {"dt": "2024-12-11T12:35:55.932247", "lvl": "debug", "msg": "Get a port from pool"}
- {"dt": "2024-12-11T12:35:55.932415", "lvl": "debug", "msg": "Set_port 61969"}
- {"dt": "2024-12-11T12:35:55.932520", "lvl": "debug", "msg": "start: 1.1 download-retry (timeout 00:10:00) [common]"}
- {"dt": "2024-12-11T12:35:55.932621", "lvl": "debug", "msg": "start: 1.1.1 http-download (timeout 00:10:00) [common]"}
- {"dt": "2024-12-11T12:35:55.932863", "lvl": "info", "msg": "downloading http://download.automotivelinux.org/AGL/release/ricefish/18.0.2/raspberrypi5/deploy/images/raspberrypi5/initramfs-netboot-image-raspberrypi5-20241028040434.ext4.gz"}
- {"dt": "2024-12-11T12:35:55.932963", "lvl": "debug", "msg": "saving as /var/lib/lava/dispatcher/tmp/38298/nbd-deploy-tl6t4a6t/initrd/initramfs-netboot-image-raspberrypi5-20241028040434.ext4"}
- {"dt": "2024-12-11T12:35:55.933047", "lvl": "debug", "msg": "total size: 2153804 (2\u202FMB)"}
- {"dt": "2024-12-11T12:35:55.933130", "lvl": "info", "msg": "Using gunzip to decompress gz"}
- {"dt": "2024-12-11T12:35:56.231806", "lvl": "debug", "msg": "progress   1\u202F% (0\u202FMB)"}
- {"dt": "2024-12-11T12:35:56.429364", "lvl": "debug", "msg": "progress   6\u202F% (0\u202FMB)"}
- {"dt": "2024-12-11T12:35:56.528173", "lvl": "debug", "msg": "progress  12\u202F% (0\u202FMB)"}
- {"dt": "2024-12-11T12:35:56.546178", "lvl": "debug", "msg": "progress  18\u202F% (0\u202FMB)"}
- {"dt": "2024-12-11T12:35:56.626750", "lvl": "debug", "msg": "progress  24\u202F% (0\u202FMB)"}
- {"dt": "2024-12-11T12:35:56.645548", "lvl": "debug", "msg": "progress  30\u202F% (0\u202FMB)"}
- {"dt": "2024-12-11T12:35:56.726313", "lvl": "debug", "msg": "progress  36\u202F% (0\u202FMB)"}
- {"dt": "2024-12-11T12:35:56.726877", "lvl": "debug", "msg": "progress  41\u202F% (0\u202FMB)"}
- {"dt": "2024-12-11T12:35:56.735493", "lvl": "debug", "msg": "progress  47\u202F% (0\u202FMB)"}
- {"dt": "2024-12-11T12:35:56.737636", "lvl": "debug", "msg": "progress  53\u202F% (1\u202FMB)"}
- {"dt": "2024-12-11T12:35:56.747972", "lvl": "debug", "msg": "progress  59\u202F% (1\u202FMB)"}
- {"dt": "2024-12-11T12:35:56.822880", "lvl": "debug", "msg": "progress  65\u202F% (1\u202FMB)"}
- {"dt": "2024-12-11T12:35:56.823569", "lvl": "debug", "msg": "progress  71\u202F% (1\u202FMB)"}
- {"dt": "2024-12-11T12:35:56.825891", "lvl": "debug", "msg": "progress  76\u202F% (1\u202FMB)"}
- {"dt": "2024-12-11T12:35:56.838375", "lvl": "debug", "msg": "progress  82\u202F% (1\u202FMB)"}
- {"dt": "2024-12-11T12:35:56.840828", "lvl": "debug", "msg": "progress  88\u202F% (1\u202FMB)"}
- {"dt": "2024-12-11T12:35:56.852562", "lvl": "debug", "msg": "progress  94\u202F% (1\u202FMB)"}
- {"dt": "2024-12-11T12:35:56.853358", "lvl": "debug", "msg": "progress 100\u202F% (2\u202FMB)"}
- {"dt": "2024-12-11T12:35:56.885833", "lvl": "info", "msg": "2\u202FMB downloaded in 0.95\u202Fs (2.16\u202FMB/s)"}
- {"dt": "2024-12-11T12:35:56.886157", "lvl": "debug", "msg": "end: 1.1.1 http-download (duration 00:00:01) [common]"}
- {"dt": "2024-12-11T12:35:56.886247", "lvl": "results", "msg": {"case": "http-download", "definition": "lava", "duration": "0.95", "extra": {"label": "initrd", "md5sum": "69fcb22a915d8fa6208b51a2d38a1bd0", "sha256sum": "59fb98aa51ec6733051adf76648cfc363ccc8367467a4fb8794cfaf7c3b33988", "sha512sum": "52fefc4f3925b72ed297cf2bb536aefa2358e2d66fefd61cede40b155efd2e9b101119081caf7f09fd61d798027cdc78cb63718fd91f573a718dfcb5894851c7", "size": ! "2153804"}, "level": "1.1.1", "namespace": "common", "result": "pass"}}
- {"dt": "2024-12-11T12:35:56.886437", "lvl": "debug", "msg": "end: 1.1 download-retry (duration 00:00:01) [common]"}
- {"dt": "2024-12-11T12:35:56.886530", "lvl": "debug", "msg": "start: 1.2 download-retry (timeout 00:09:59) [common]"}
- {"dt": "2024-12-11T12:35:56.886631", "lvl": "debug", "msg": "start: 1.2.1 http-download (timeout 00:09:59) [common]"}
- {"dt": "2024-12-11T12:35:56.886828", "lvl": "info", "msg": "downloading http://download.automotivelinux.org/AGL/release/ricefish/18.0.2/raspberrypi5/deploy/images/raspberrypi5/Image"}
- {"dt": "2024-12-11T12:35:56.886901", "lvl": "debug", "msg": "saving as /var/lib/lava/dispatcher/tmp/38298/nbd-deploy-tl6t4a6t/kernel/Image"}
- {"dt": "2024-12-11T12:35:56.886963", "lvl": "debug", "msg": "total size: 28887552 (27\u202FMB)"}
- {"dt": "2024-12-11T12:35:56.887026", "lvl": "debug", "msg": "No compression specified"}
- {"dt": "2024-12-11T12:35:57.181022", "lvl": "debug", "msg": "progress   0\u202F% (0\u202FMB)"}
- {"dt": "2024-12-11T12:35:59.621644", "lvl": "debug", "msg": "progress   5\u202F% (1\u202FMB)"}
- {"dt": "2024-12-11T12:36:03.386114", "lvl": "debug", "msg": "progress  10\u202F% (2\u202FMB)"}
- {"dt": "2024-12-11T12:36:04.068076", "lvl": "debug", "msg": "progress  15\u202F% (4\u202FMB)"}
- {"dt": "2024-12-11T12:36:04.650902", "lvl": "debug", "msg": "progress  20\u202F% (5\u202FMB)"}
- {"dt": "2024-12-11T12:36:05.140541", "lvl": "debug", "msg": "progress  25\u202F% (6\u202FMB)"}
- {"dt": "2024-12-11T12:36:05.537765", "lvl": "debug", "msg": "progress  30\u202F% (8\u202FMB)"}
- {"dt": "2024-12-11T12:36:05.926007", "lvl": "debug", "msg": "progress  35\u202F% (9\u202FMB)"}
- {"dt": "2024-12-11T12:36:06.310595", "lvl": "debug", "msg": "progress  40\u202F% (11\u202FMB)"}
- {"dt": "2024-12-11T12:36:06.609639", "lvl": "debug", "msg": "progress  45\u202F% (12\u202FMB)"}
- {"dt": "2024-12-11T12:36:06.902849", "lvl": "debug", "msg": "progress  50\u202F% (13\u202FMB)"}
- {"dt": "2024-12-11T12:36:07.190853", "lvl": "debug", "msg": "progress  55\u202F% (15\u202FMB)"}
- {"dt": "2024-12-11T12:36:07.476615", "lvl": "debug", "msg": "progress  60\u202F% (16\u202FMB)"}
- {"dt": "2024-12-11T12:36:07.681323", "lvl": "debug", "msg": "progress  65\u202F% (17\u202FMB)"}
- {"dt": "2024-12-11T12:36:07.883077", "lvl": "debug", "msg": "progress  70\u202F% (19\u202FMB)"}
- {"dt": "2024-12-11T12:36:08.159354", "lvl": "debug", "msg": "progress  75\u202F% (20\u202FMB)"}
- {"dt": "2024-12-11T12:36:08.355740", "lvl": "debug", "msg": "progress  80\u202F% (22\u202FMB)"}
- {"dt": "2024-12-11T12:36:08.550957", "lvl": "debug", "msg": "progress  85\u202F% (23\u202FMB)"}
- {"dt": "2024-12-11T12:36:08.746167", "lvl": "debug", "msg": "progress  90\u202F% (24\u202FMB)"}
- {"dt": "2024-12-11T12:36:08.857041", "lvl": "debug", "msg": "progress  95\u202F% (26\u202FMB)"}
- {"dt": "2024-12-11T12:36:09.049232", "lvl": "debug", "msg": "progress 100\u202F% (27\u202FMB)"}
- {"dt": "2024-12-11T12:36:09.050216", "lvl": "info", "msg": "27\u202FMB downloaded in 12.16\u202Fs (2.26\u202FMB/s)"}
- {"dt": "2024-12-11T12:36:09.050923", "lvl": "debug", "msg": "end: 1.2.1 http-download (duration 00:00:12) [common]"}
- {"dt": "2024-12-11T12:36:09.051259", "lvl": "results", "msg": {"case": "http-download", "definition": "lava", "duration": "12.16", "extra": {"label": "kernel", "md5sum": "601b383c3c881d04e3368bd84040fdbd", "sha256sum": "99041f31b2ec83f4057caf62ca4bf1534d860cf2d8612fde079894451d55e486", "sha512sum": "e956efcf89178c3aa3fe2491edd04292d25136cf49bc45f7fdfcaa45b40768824dafc595be0d4dbccf066dc2d8dcfce3c6b446189612fa22ab6f3c465cab66c3", "size": ! "28887552"}, "level": "1.2.1", "namespace": "common", "result": "pass"}}
- {"dt": "2024-12-11T12:36:09.051937", "lvl": "debug", "msg": "end: 1.2 download-retry (duration 00:00:12) [common]"}
- {"dt": "2024-12-11T12:36:09.052283", "lvl": "debug", "msg": "start: 1.3 download-retry (timeout 00:09:47) [common]"}
- {"dt": "2024-12-11T12:36:09.052601", "lvl": "debug", "msg": "start: 1.3.1 http-download (timeout 00:09:47) [common]"}
- {"dt": "2024-12-11T12:36:09.053245", "lvl": "info", "msg": "downloading http://download.automotivelinux.org/AGL/release/ricefish/18.0.2/raspberrypi5/deploy/images/raspberrypi5/bcm2712-rpi-5-b.dtb"}
- {"dt": "2024-12-11T12:36:09.053494", "lvl": "debug", "msg": "saving as /var/lib/lava/dispatcher/tmp/38298/nbd-deploy-tl6t4a6t/dtb/bcm2712-rpi-5-b.dtb"}
- {"dt": "2024-12-11T12:36:09.053689", "lvl": "debug", "msg": "total size: 78059 (0\u202FMB)"}
- {"dt": "2024-12-11T12:36:09.053886", "lvl": "debug", "msg": "No compression specified"}
- {"dt": "2024-12-11T12:36:09.350501", "lvl": "debug", "msg": "progress  41\u202F% (0\u202FMB)"}
- {"dt": "2024-12-11T12:36:09.448323", "lvl": "debug", "msg": "progress  83\u202F% (0\u202FMB)"}
- {"dt": "2024-12-11T12:36:09.449848", "lvl": "debug", "msg": "progress 100\u202F% (0\u202FMB)"}
- {"dt": "2024-12-11T12:36:09.450619", "lvl": "info", "msg": "0\u202FMB downloaded in 0.40\u202Fs (0.19\u202FMB/s)"}
- {"dt": "2024-12-11T12:36:09.451267", "lvl": "debug", "msg": "end: 1.3.1 http-download (duration 00:00:00) [common]"}
- {"dt": "2024-12-11T12:36:09.451596", "lvl": "results", "msg": {"case": "http-download", "definition": "lava", "duration": "0.40", "extra": {"label": "dtb", "md5sum": "e8c29afbbe377e6f0331d46da1c32f91", "sha256sum": "a91e4fa0dcc0ab08b873cfac3c0b7fc17c22ee715d941cbc915a44966c1e8c99", "sha512sum": "6e77dc7abf1cdc1c07a6f9e5f0168f52a9704b6d0142112e5b28cef3e166f8b93612a76b6341e5168e6c1e3d7ab7b4ed115d87749a7379c2d5174a78e19b46c3", "size": ! "78059"}, "level": "1.3.1", "namespace": "common", "result": "pass"}}
- {"dt": "2024-12-11T12:36:09.452301", "lvl": "debug", "msg": "end: 1.3 download-retry (duration 00:00:00) [common]"}
- {"dt": "2024-12-11T12:36:09.452661", "lvl": "debug", "msg": "start: 1.4 download-retry (timeout 00:09:46) [common]"}
- {"dt": "2024-12-11T12:36:09.453064", "lvl": "debug", "msg": "start: 1.4.1 http-download (timeout 00:09:46) [common]"}
- {"dt": "2024-12-11T12:36:09.453419", "lvl": "info", "msg": "downloading http://download.automotivelinux.org/AGL/release/ricefish/18.0.2/raspberrypi5/deploy/images/raspberrypi5/agl-ivi-demo-qt-raspberrypi5-20241028040434.ext4.xz"}
- {"dt": "2024-12-11T12:36:09.453504", "lvl": "debug", "msg": "saving as /var/lib/lava/dispatcher/tmp/38298/nbd-deploy-tl6t4a6t/nbdroot/agl-ivi-demo-qt-raspberrypi5-20241028040434.ext4"}
- {"dt": "2024-12-11T12:36:09.453568", "lvl": "debug", "msg": "total size: 493866112 (470\u202FMB)"}
- {"dt": "2024-12-11T12:36:09.453631", "lvl": "info", "msg": "Using unxz to decompress xz"}
- {"dt": "2024-12-11T12:36:09.749618", "lvl": "debug", "msg": "progress   0\u202F% (0\u202FMB)"}
- {"dt": "2024-12-11T12:36:13.610418", "lvl": "debug", "msg": "progress   5\u202F% (23\u202FMB)"}
- {"dt": "2024-12-11T12:36:15.419025", "lvl": "debug", "msg": "progress  10\u202F% (47\u202FMB)"}
- {"dt": "2024-12-11T12:36:17.242231", "lvl": "debug", "msg": "progress  15\u202F% (70\u202FMB)"}
- {"dt": "2024-12-11T12:36:19.047642", "lvl": "debug", "msg": "progress  20\u202F% (94\u202FMB)"}
- {"dt": "2024-12-11T12:36:20.801737", "lvl": "debug", "msg": "progress  25\u202F% (117\u202FMB)"}
- {"dt": "2024-12-11T12:36:22.641104", "lvl": "debug", "msg": "progress  30\u202F% (141\u202FMB)"}
- {"dt": "2024-12-11T12:36:24.518364", "lvl": "debug", "msg": "progress  35\u202F% (164\u202FMB)"}
- {"dt": "2024-12-11T12:36:26.475682", "lvl": "debug", "msg": "progress  40\u202F% (188\u202FMB)"}
- {"dt": "2024-12-11T12:36:27.916001", "lvl": "debug", "msg": "progress  45\u202F% (211\u202FMB)"}
- {"dt": "2024-12-11T12:36:29.630204", "lvl": "debug", "msg": "progress  50\u202F% (235\u202FMB)"}
- {"dt": "2024-12-11T12:36:31.308613", "lvl": "debug", "msg": "progress  55\u202F% (259\u202FMB)"}
- {"dt": "2024-12-11T12:36:33.196950", "lvl": "debug", "msg": "progress  60\u202F% (282\u202FMB)"}
- {"dt": "2024-12-11T12:36:34.991860", "lvl": "debug", "msg": "progress  65\u202F% (306\u202FMB)"}
- {"dt": "2024-12-11T12:36:36.638625", "lvl": "debug", "msg": "progress  70\u202F% (329\u202FMB)"}
- {"dt": "2024-12-11T12:36:38.697315", "lvl": "debug", "msg": "progress  75\u202F% (353\u202FMB)"}
- {"dt": "2024-12-11T12:36:40.344088", "lvl": "debug", "msg": "progress  80\u202F% (376\u202FMB)"}
- {"dt": "2024-12-11T12:36:41.815767", "lvl": "debug", "msg": "progress  85\u202F% (400\u202FMB)"}
- {"dt": "2024-12-11T12:36:43.738869", "lvl": "debug", "msg": "progress  90\u202F% (423\u202FMB)"}
- {"dt": "2024-12-11T12:36:45.350278", "lvl": "debug", "msg": "progress  95\u202F% (447\u202FMB)"}
- {"dt": "2024-12-11T12:36:49.081272", "lvl": "debug", "msg": "progress 100\u202F% (470\u202FMB)"}
- {"dt": "2024-12-11T12:36:50.501722", "lvl": "info", "msg": "470\u202FMB downloaded in 41.05\u202Fs (11.47\u202FMB/s)"}
- {"dt": "2024-12-11T12:36:50.502046", "lvl": "debug", "msg": "end: 1.4.1 http-download (duration 00:00:41) [common]"}
- {"dt": "2024-12-11T12:36:50.502145", "lvl": "results", "msg": {"case": "http-download", "definition": "lava", "duration": "41.05", "extra": {"label": "nbdroot", "md5sum": "4efb22dd71d11d782c04913029ebe146", "sha256sum": "b475a2953ee1a6be85506449e60e93d14579f8af2dc5577723d004a952eda229", "sha512sum": "888ffdcec6b22a5b3cd3e391eaa7a1bf5c6493efe72df9f895ac361c0117ba23335502223b5b769ad9e63ef740001581525ce5eaeaf2ac29e1b76eb53d8395b8", "size": ! "493866112"}, "level": "1.4.1", "namespace": "common", "result": "pass"}}
- {"dt": "2024-12-11T12:36:50.502352", "lvl": "debug", "msg": "end: 1.4 download-retry (duration 00:00:41) [common]"}
- {"dt": "2024-12-11T12:36:50.502469", "lvl": "debug", "msg": "start: 1.5 lava-overlay (timeout 00:09:05) [common]"}
- {"dt": "2024-12-11T12:36:50.502785", "lvl": "debug", "msg": "[common] Preparing overlay tarball in /var/lib/lava/dispatcher/tmp/38298/lava-overlay-mlxcgyo1"}
- {"dt": "2024-12-11T12:36:50.502983", "lvl": "debug", "msg": "makedir: /var/lib/lava/dispatcher/tmp/38298/lava-overlay-mlxcgyo1/lava-38298/bin"}
- {"dt": "2024-12-11T12:36:50.503115", "lvl": "debug", "msg": "makedir: /var/lib/lava/dispatcher/tmp/38298/lava-overlay-mlxcgyo1/lava-38298/tests"}
- {"dt": "2024-12-11T12:36:50.503247", "lvl": "debug", "msg": "makedir: /var/lib/lava/dispatcher/tmp/38298/lava-overlay-mlxcgyo1/lava-38298/results"}
- {"dt": "2024-12-11T12:36:50.503382", "lvl": "debug", "msg": "Creating /var/lib/lava/dispatcher/tmp/38298/lava-overlay-mlxcgyo1/lava-38298/bin/lava-add-keys"}
- {"dt": "2024-12-11T12:36:50.503596", "lvl": "debug", "msg": "Creating /var/lib/lava/dispatcher/tmp/38298/lava-overlay-mlxcgyo1/lava-38298/bin/lava-add-sources"}
- {"dt": "2024-12-11T12:36:50.503791", "lvl": "debug", "msg": "Creating /var/lib/lava/dispatcher/tmp/38298/lava-overlay-mlxcgyo1/lava-38298/bin/lava-background-process-start"}
- {"dt": "2024-12-11T12:36:50.503976", "lvl": "debug", "msg": "Creating /var/lib/lava/dispatcher/tmp/38298/lava-overlay-mlxcgyo1/lava-38298/bin/lava-background-process-stop"}
- {"dt": "2024-12-11T12:36:50.504174", "lvl": "debug", "msg": "Creating /var/lib/lava/dispatcher/tmp/38298/lava-overlay-mlxcgyo1/lava-38298/bin/lava-common-functions"}
- {"dt": "2024-12-11T12:36:50.504365", "lvl": "debug", "msg": "Creating /var/lib/lava/dispatcher/tmp/38298/lava-overlay-mlxcgyo1/lava-38298/bin/lava-echo-ipv4"}
- {"dt": "2024-12-11T12:36:50.504551", "lvl": "debug", "msg": "Creating /var/lib/lava/dispatcher/tmp/38298/lava-overlay-mlxcgyo1/lava-38298/bin/lava-install-packages"}
- {"dt": "2024-12-11T12:36:50.504751", "lvl": "debug", "msg": "Creating /var/lib/lava/dispatcher/tmp/38298/lava-overlay-mlxcgyo1/lava-38298/bin/lava-installed-packages"}
- {"dt": "2024-12-11T12:36:50.504944", "lvl": "debug", "msg": "Creating /var/lib/lava/dispatcher/tmp/38298/lava-overlay-mlxcgyo1/lava-38298/bin/lava-os-build"}
- {"dt": "2024-12-11T12:36:50.505130", "lvl": "debug", "msg": "Creating /var/lib/lava/dispatcher/tmp/38298/lava-overlay-mlxcgyo1/lava-38298/bin/lava-probe-channel"}
- {"dt": "2024-12-11T12:36:50.505313", "lvl": "debug", "msg": "Creating /var/lib/lava/dispatcher/tmp/38298/lava-overlay-mlxcgyo1/lava-38298/bin/lava-probe-ip"}
- {"dt": "2024-12-11T12:36:50.505493", "lvl": "debug", "msg": "Creating /var/lib/lava/dispatcher/tmp/38298/lava-overlay-mlxcgyo1/lava-38298/bin/lava-target-ip"}
- {"dt": "2024-12-11T12:36:50.505674", "lvl": "debug", "msg": "Creating /var/lib/lava/dispatcher/tmp/38298/lava-overlay-mlxcgyo1/lava-38298/bin/lava-target-mac"}
- {"dt": "2024-12-11T12:36:50.505852", "lvl": "debug", "msg": "Creating /var/lib/lava/dispatcher/tmp/38298/lava-overlay-mlxcgyo1/lava-38298/bin/lava-target-storage"}
- {"dt": "2024-12-11T12:36:50.506041", "lvl": "debug", "msg": "Creating /var/lib/lava/dispatcher/tmp/38298/lava-overlay-mlxcgyo1/lava-38298/bin/lava-test-case"}
- {"dt": "2024-12-11T12:36:50.506222", "lvl": "debug", "msg": "Creating /var/lib/lava/dispatcher/tmp/38298/lava-overlay-mlxcgyo1/lava-38298/bin/lava-test-event"}
- {"dt": "2024-12-11T12:36:50.506400", "lvl": "debug", "msg": "Creating /var/lib/lava/dispatcher/tmp/38298/lava-overlay-mlxcgyo1/lava-38298/bin/lava-test-feedback"}
- {"dt": "2024-12-11T12:36:50.506578", "lvl": "debug", "msg": "Creating /var/lib/lava/dispatcher/tmp/38298/lava-overlay-mlxcgyo1/lava-38298/bin/lava-test-raise"}
- {"dt": "2024-12-11T12:36:50.506771", "lvl": "debug", "msg": "Creating /var/lib/lava/dispatcher/tmp/38298/lava-overlay-mlxcgyo1/lava-38298/bin/lava-test-reference"}
- {"dt": "2024-12-11T12:36:50.506950", "lvl": "debug", "msg": "Creating /var/lib/lava/dispatcher/tmp/38298/lava-overlay-mlxcgyo1/lava-38298/bin/lava-test-runner"}
- {"dt": "2024-12-11T12:36:50.507129", "lvl": "debug", "msg": "Creating /var/lib/lava/dispatcher/tmp/38298/lava-overlay-mlxcgyo1/lava-38298/bin/lava-test-set"}
- {"dt": "2024-12-11T12:36:50.507305", "lvl": "debug", "msg": "Creating /var/lib/lava/dispatcher/tmp/38298/lava-overlay-mlxcgyo1/lava-38298/bin/lava-test-shell"}
- {"dt": "2024-12-11T12:36:50.507485", "lvl": "debug", "msg": "Updating /var/lib/lava/dispatcher/tmp/38298/lava-overlay-mlxcgyo1/lava-38298/bin/lava-install-packages (oe)"}
- {"dt": "2024-12-11T12:36:50.507734", "lvl": "debug", "msg": "Updating /var/lib/lava/dispatcher/tmp/38298/lava-overlay-mlxcgyo1/lava-38298/bin/lava-installed-packages (oe)"}
- {"dt": "2024-12-11T12:36:50.507926", "lvl": "debug", "msg": "Creating /var/lib/lava/dispatcher/tmp/38298/lava-overlay-mlxcgyo1/lava-38298/environment"}
- {"dt": "2024-12-11T12:36:50.508093", "lvl": "debug", "msg": "LAVA metadata"}
- {"dt": "2024-12-11T12:36:50.508187", "lvl": "debug", "msg": "- LAVA_JOB_ID=38298"}
- {"dt": "2024-12-11T12:36:50.508270", "lvl": "debug", "msg": "- LAVA_DISPATCHER_IP=192.168.66.1"}
- {"dt": "2024-12-11T12:36:50.508416", "lvl": "debug", "msg": "start: 1.5.1 ssh-authorize (timeout 00:09:05) [common]"}
- {"dt": "2024-12-11T12:36:50.508822", "lvl": "debug", "msg": "end: 1.5.1 ssh-authorize (duration 00:00:00) [common]"}
- {"dt": "2024-12-11T12:36:50.508923", "lvl": "debug", "msg": "start: 1.5.2 lava-vland-overlay (timeout 00:09:05) [common]"}
- {"dt": "2024-12-11T12:36:50.508991", "lvl": "debug", "msg": "skipped lava-vland-overlay"}
- {"dt": "2024-12-11T12:36:50.509066", "lvl": "debug", "msg": "end: 1.5.2 lava-vland-overlay (duration 00:00:00) [common]"}
- {"dt": "2024-12-11T12:36:50.509144", "lvl": "debug", "msg": "start: 1.5.3 lava-multinode-overlay (timeout 00:09:05) [common]"}
- {"dt": "2024-12-11T12:36:50.509203", "lvl": "debug", "msg": "skipped lava-multinode-overlay"}
- {"dt": "2024-12-11T12:36:50.509274", "lvl": "debug", "msg": "end: 1.5.3 lava-multinode-overlay (duration 00:00:00) [common]"}
- {"dt": "2024-12-11T12:36:50.509350", "lvl": "debug", "msg": "start: 1.5.4 test-definition (timeout 00:09:05) [common]"}
- {"dt": "2024-12-11T12:36:50.509426", "lvl": "info", "msg": "Loading test definitions"}
- {"dt": "2024-12-11T12:36:50.509514", "lvl": "debug", "msg": "start: 1.5.4.1 inline-repo-action (timeout 00:09:05) [common]"}
- {"dt": "2024-12-11T12:36:50.509587", "lvl": "debug", "msg": "Using /lava-38298 at stage 0"}
- {"dt": "2024-12-11T12:36:50.510011", "lvl": "debug", "msg": "uuid=38298_1.5.4.1 testdef=None"}
- {"dt": "2024-12-11T12:36:50.510106", "lvl": "debug", "msg": "end: 1.5.4.1 inline-repo-action (duration 00:00:00) [common]"}
- {"dt": "2024-12-11T12:36:50.510188", "lvl": "debug", "msg": "start: 1.5.4.2 test-overlay (timeout 00:09:05) [common]"}
- {"dt": "2024-12-11T12:36:50.510812", "lvl": "debug", "msg": "end: 1.5.4.2 test-overlay (duration 00:00:00) [common]"}
- {"dt": "2024-12-11T12:36:50.510889", "lvl": "results", "msg": {"case": "test-overlay", "definition": "lava", "duration": "0.00", "extra": {"from": "inline", "name": "dmesg", "path": "inline/dmesg.yaml", "uuid": "38298_1.5.4.1"}, "level": "1.5.4.2", "namespace": "common", "result": "pass"}}
- {"dt": "2024-12-11T12:36:50.511048", "lvl": "debug", "msg": "start: 1.5.4.3 test-install-overlay (timeout 00:09:05) [common]"}
- {"dt": "2024-12-11T12:36:50.511931", "lvl": "debug", "msg": "end: 1.5.4.3 test-install-overlay (duration 00:00:00) [common]"}
- {"dt": "2024-12-11T12:36:50.512019", "lvl": "results", "msg": {"case": "test-install-overlay", "definition": "lava", "duration": "0.00", "extra": {"from": "inline", "name": "dmesg", "path": "inline/dmesg.yaml", "skipped test-install-overlay": "38298_1.5.4.1", "uuid": "38298_1.5.4.1"}, "level": "1.5.4.3", "namespace": "common", "result": "pass"}}
- {"dt": "2024-12-11T12:36:50.512185", "lvl": "debug", "msg": "start: 1.5.4.4 test-runscript-overlay (timeout 00:09:05) [common]"}
- {"dt": "2024-12-11T12:36:50.513050", "lvl": "debug", "msg": "runner path: /var/lib/lava/dispatcher/tmp/38298/lava-overlay-mlxcgyo1/lava-38298/0/tests/0_dmesg test_uuid 38298_1.5.4.1"}
- {"dt": "2024-12-11T12:36:50.513253", "lvl": "debug", "msg": "end: 1.5.4.4 test-runscript-overlay (duration 00:00:00) [common]"}
- {"dt": "2024-12-11T12:36:50.513332", "lvl": "results", "msg": {"case": "test-runscript-overlay", "definition": "lava", "duration": "0.00", "extra": {"filename": "/var/lib/lava/dispatcher/tmp/38298/lava-overlay-mlxcgyo1/lava-38298/0/tests/0_dmesg/run.sh", "from": "inline", "name": "dmesg", "path": "inline/dmesg.yaml", "uuid": "38298_1.5.4.1"}, "level": "1.5.4.4", "namespace": "common", "result": "pass"}}
- {"dt": "2024-12-11T12:36:50.513496", "lvl": "debug", "msg": "start: 1.5.4.5 inline-repo-action (timeout 00:09:05) [common]"}
- {"dt": "2024-12-11T12:36:50.513576", "lvl": "debug", "msg": "Using /lava-38298 at stage 1"}
- {"dt": "2024-12-11T12:36:50.513948", "lvl": "debug", "msg": "uuid=38298_1.5.4.5 testdef=None"}
- {"dt": "2024-12-11T12:36:50.514039", "lvl": "debug", "msg": "end: 1.5.4.5 inline-repo-action (duration 00:00:00) [common]"}
- {"dt": "2024-12-11T12:36:50.514119", "lvl": "debug", "msg": "start: 1.5.4.6 test-overlay (timeout 00:09:05) [common]"}
- {"dt": "2024-12-11T12:36:50.514672", "lvl": "debug", "msg": "end: 1.5.4.6 test-overlay (duration 00:00:00) [common]"}
- {"dt": "2024-12-11T12:36:50.514745", "lvl": "results", "msg": {"case": "test-overlay", "definition": "lava", "duration": "0.00", "extra": {"from": "inline", "name": "bootrr", "path": "inline/bootrr.yaml", "uuid": "38298_1.5.4.5"}, "level": "1.5.4.6", "namespace": "common", "result": "pass"}}
- {"dt": "2024-12-11T12:36:50.514896", "lvl": "debug", "msg": "start: 1.5.4.7 test-install-overlay (timeout 00:09:05) [common]"}
- {"dt": "2024-12-11T12:36:50.515731", "lvl": "debug", "msg": "end: 1.5.4.7 test-install-overlay (duration 00:00:00) [common]"}
- {"dt": "2024-12-11T12:36:50.515833", "lvl": "results", "msg": {"case": "test-install-overlay", "definition": "lava", "duration": "0.00", "extra": {"from": "inline", "name": "bootrr", "path": "inline/bootrr.yaml", "skipped test-install-overlay": "38298_1.5.4.5", "uuid": "38298_1.5.4.5"}, "level": "1.5.4.7", "namespace": "common", "result": "pass"}}
- {"dt": "2024-12-11T12:36:50.516035", "lvl": "debug", "msg": "start: 1.5.4.8 test-runscript-overlay (timeout 00:09:05) [common]"}
- {"dt": "2024-12-11T12:36:50.516968", "lvl": "debug", "msg": "runner path: /var/lib/lava/dispatcher/tmp/38298/lava-overlay-mlxcgyo1/lava-38298/1/tests/1_bootrr test_uuid 38298_1.5.4.5"}
- {"dt": "2024-12-11T12:36:50.517204", "lvl": "debug", "msg": "end: 1.5.4.8 test-runscript-overlay (duration 00:00:00) [common]"}
- {"dt": "2024-12-11T12:36:50.517302", "lvl": "results", "msg": {"case": "test-runscript-overlay", "definition": "lava", "duration": "0.00", "extra": {"filename": "/var/lib/lava/dispatcher/tmp/38298/lava-overlay-mlxcgyo1/lava-38298/1/tests/1_bootrr/run.sh", "from": "inline", "name": "bootrr", "path": "inline/bootrr.yaml", "uuid": "38298_1.5.4.5"}, "level": "1.5.4.8", "namespace": "common", "result": "pass"}}
- {"dt": "2024-12-11T12:36:50.517477", "lvl": "info", "msg": "Creating lava-test-runner.conf files"}
- {"dt": "2024-12-11T12:36:50.517554", "lvl": "debug", "msg": "Using lava-test-runner path: /var/lib/lava/dispatcher/tmp/38298/lava-overlay-mlxcgyo1/lava-38298/0 for stage 0"}
- {"dt": "2024-12-11T12:36:50.517680", "lvl": "debug", "msg": "- 0_dmesg"}
- {"dt": "2024-12-11T12:36:50.517792", "lvl": "debug", "msg": "Using lava-test-runner path: /var/lib/lava/dispatcher/tmp/38298/lava-overlay-mlxcgyo1/lava-38298/1 for stage 1"}
- {"dt": "2024-12-11T12:36:50.517918", "lvl": "debug", "msg": "- 1_bootrr"}
- {"dt": "2024-12-11T12:36:50.518048", "lvl": "debug", "msg": "end: 1.5.4 test-definition (duration 00:00:00) [common]"}
- {"dt": "2024-12-11T12:36:50.518154", "lvl": "debug", "msg": "start: 1.5.5 compress-overlay (timeout 00:09:05) [common]"}
- {"dt": "2024-12-11T12:36:50.527856", "lvl": "debug", "msg": "end: 1.5.5 compress-overlay (duration 00:00:00) [common]"}
- {"dt": "2024-12-11T12:36:50.527995", "lvl": "debug", "msg": "start: 1.5.6 persistent-nfs-overlay (timeout 00:09:05) [common]"}
- {"dt": "2024-12-11T12:36:50.528096", "lvl": "debug", "msg": "end: 1.5.6 persistent-nfs-overlay (duration 00:00:00) [common]"}
- {"dt": "2024-12-11T12:36:50.528193", "lvl": "debug", "msg": "end: 1.5 lava-overlay (duration 00:00:00) [common]"}
- {"dt": "2024-12-11T12:36:50.528287", "lvl": "debug", "msg": "start: 1.6 prepare-kernel (timeout 00:09:05) [common]"}
- {"dt": "2024-12-11T12:36:50.528380", "lvl": "debug", "msg": "start: 1.6.1 uboot-prepare-kernel (timeout 00:09:05) [common]"}
- {"dt": "2024-12-11T12:36:50.528481", "lvl": "debug", "msg": "end: 1.6.1 uboot-prepare-kernel (duration 00:00:00) [common]"}
- {"dt": "2024-12-11T12:36:50.528568", "lvl": "debug", "msg": "end: 1.6 prepare-kernel (duration 00:00:00) [common]"}
- {"dt": "2024-12-11T12:36:50.528655", "lvl": "debug", "msg": "start: 1.7 xnbd-server-deploy (timeout 00:09:05) [common]"}
- {"dt": "2024-12-11T12:36:50.528725", "lvl": "debug", "msg": "xnbd-server-deploy: starting nbd-server"}
- {"dt": "2024-12-11T12:36:50.528835", "lvl": "debug", "msg": "NBD-IP: 192.168.66.1, NBD-PORT: 61969, NBD-ROOT: 38298/nbd-deploy-tl6t4a6t/nbdroot/agl-ivi-demo-qt-raspberrypi5-20241028040434.ext4"}
- {"dt": "2024-12-11T12:36:50.529288", "lvl": "debug", "msg": "nbd-server 61969 /var/lib/lava/dispatcher/tmp/38298/nbd-deploy-tl6t4a6t/nbdroot/agl-ivi-demo-qt-raspberrypi5-20241028040434.ext4"}
- {"dt": "2024-12-11T12:36:50.531974", "lvl": "debug", "msg": "output: "}
- {"dt": "2024-12-11T12:36:50.532138", "lvl": "debug", "msg": "output: ** (process:15289): WARNING **: 12:36:50.531: Specifying an export on the command line no longer uses the oldstyle protocol."}
- {"dt": "2024-12-11T12:36:50.532236", "lvl": "debug", "msg": "output: "}
- {"dt": "2024-12-11T12:36:50.532318", "lvl": "debug", "msg": "xnbd-server-deploy: starting nbd-server done"}
- {"dt": "2024-12-11T12:36:50.532440", "lvl": "debug", "msg": "end: 1.7 xnbd-server-deploy (duration 00:00:00) [common]"}
- {"dt": "2024-12-11T12:36:50.532548", "lvl": "info", "msg": "end: 1 nbd-deploy (duration 00:00:55) [common]"}
- {"dt": "2024-12-11T12:36:50.532655", "lvl": "info", "msg": "start: 2 minimal-boot (timeout 00:09:05) [common]"}
- {"dt": "2024-12-11T12:36:50.532772", "lvl": "debug", "msg": "start: 2.1 connect-device (timeout 00:09:05) [common]"}
- {"dt": "2024-12-11T12:36:50.532857", "lvl": "info", "msg": "[common] connect-device Connecting to device using 'telnet 127.0.0.1 63007'"}
- {"dt": "2024-12-11T12:36:50.536505", "lvl": "debug", "msg": "Setting prompt string to ['lava-test: # ']"}
- {"dt": "2024-12-11T12:36:50.537092", "lvl": "debug", "msg": "end: 2.1 connect-device (duration 00:00:00) [common]"}
- {"dt": "2024-12-11T12:36:50.537287", "lvl": "debug", "msg": "start: 2.2 reset-device (timeout 00:09:05) [common]"}
- {"dt": "2024-12-11T12:36:50.537414", "lvl": "debug", "msg": "start: 2.2.1 pdu-reboot (timeout 00:09:05) [common]"}
- {"dt": "2024-12-11T12:36:50.537629", "lvl": "debug", "msg": "Calling: 'upower.sh' '--atx' 'reset' '2'"}
- {"dt": "2024-12-11T12:36:51.485328", "lvl": "debug", "msg": ">> No GEMBIRD SiS-PM found. Check USB connections, please!\r"}
- {"dt": "2024-12-11T12:36:55.509184", "lvl": "debug", "msg": ">> No GEMBIRD SiS-PM found. Check USB connections, please!\r"}
- {"dt": "2024-12-11T12:36:57.512816", "lvl": "debug", "msg": ">> export LANG='C'\r"}
- {"dt": "2024-12-11T12:36:57.513425", "lvl": "debug", "msg": ">> export LC_ALL='C.UTF-8'\r"}
- {"dt": "2024-12-11T12:36:57.513807", "lvl": "debug", "msg": ">> export PATH='/usr/local/bin:/usr/local/sbin:/bin:/usr/bin:/usr/sbin:/sbin'\r"}
- {"dt": "2024-12-11T12:36:57.514129", "lvl": "debug", "msg": ">> export PWD='/'\r"}
- {"dt": "2024-12-11T12:36:57.518379", "lvl": "debug", "msg": ">> DEBUG: found /var/lib/lava/dispatcher/tmp/bcm2712-rpi-5-b.dtb\r"}
- {"dt": "2024-12-11T12:36:57.521983", "lvl": "debug", "msg": ">> DEBUG: BASETFTP=/var/lib/lava/dispatcher/tmp\r"}
- {"dt": "2024-12-11T12:36:57.529310", "lvl": "debug", "msg": ">> DEBUG: INITRD=/var/lib/lava/dispatcher/tmp/38298/nbd-deploy-tl6t4a6t/initrd/initramfs-netboot-image-raspberrypi5-20241028040434.ext4\r"}
- {"dt": "2024-12-11T12:36:57.529831", "lvl": "debug", "msg": ">> /var/lib/lava/dispatcher/tmp/initramfs-netboot-image-raspberrypi5-20241028040434.ext4\r"}
- {"dt": "2024-12-11T12:36:57.530227", "lvl": "debug", "msg": ">> /var/lib/lava/dispatcher/tmp/initramfs-netboot-image-raspberrypi5.ext4.gz\r"}
- {"dt": "2024-12-11T12:36:57.534349", "lvl": "debug", "msg": ">> DEBUG: REL_INITRD=38298/nbd-deploy-tl6t4a6t/initrd/initramfs-netboot-image-raspberrypi5-20241028040434.ext4 /var/lib/lava/dispatcher/tmp/initramfs-netboot-image-raspberrypi5-20241028040434.ext4 /var/lib/lava/dispatcher/tmp/initramfs-netboot-image-raspberrypi5.ext4.gz\r"}
- {"dt": "2024-12-11T12:36:57.536046", "lvl": "debug", "msg": ">> DEBUG: IMAGE=/var/lib/lava/dispatcher/tmp/38298/nbd-deploy-tl6t4a6t/kernel/Image\r"}
- {"dt": "2024-12-11T12:36:57.540866", "lvl": "debug", "msg": ">> DEBUG: REL_IMAGE=38298/nbd-deploy-tl6t4a6t/kernel/Image\r"}
- {"dt": "2024-12-11T12:36:57.581256", "lvl": "debug", "msg": ">> cp: '/var/lib/lava/dispatcher/tmp/initramfs-netboot-image-raspberrypi5-20241028040434.ext4' and '/var/lib/lava/dispatcher/tmp/initramfs-netboot-image-raspberrypi5-20241028040434.ext4' are the same file\r"}
- {"dt": "2024-12-11T12:36:57.581872", "lvl": "debug", "msg": ">> cp: '/var/lib/lava/dispatcher/tmp/initramfs-netboot-image-raspberrypi5.ext4.gz' and '/var/lib/lava/dispatcher/tmp/initramfs-netboot-image-raspberrypi5.ext4.gz' are the same file\r"}
- {"dt": "2024-12-11T12:36:57.601437", "lvl": "debug", "msg": ">> DEBUG: check LISTEN 0      10           0.0.0.0:61969      0.0.0.0:*    users:((\"nbd-server\",pid=15290,fd=3))\r"}
- {"dt": "2024-12-11T12:36:57.603156", "lvl": "debug", "msg": ">> DEBUG: PID=15290\r"}
- {"dt": "2024-12-11T12:36:57.609605", "lvl": "debug", "msg": ">> NBDPORT=61969\r"}
- {"dt": "2024-12-11T12:36:57.610920", "lvl": "debug", "msg": ">> basename: extra operand \u2018/var/lib/lava/dispatcher/tmp/initramfs-netboot-image-raspberrypi5.ext4.gz\u2019\r"}
- {"dt": "2024-12-11T12:36:57.611069", "lvl": "debug", "msg": ">> Try 'basename --help' for more information.\r"}
- {"dt": "2024-12-11T12:36:57.611845", "lvl": "debug", "msg": ">> \r"}
- {"dt": "2024-12-11T12:36:57.611968", "lvl": "debug", "msg": ">> \t\tenable_uart=1\r"}
- {"dt": "2024-12-11T12:36:57.612056", "lvl": "debug", "msg": ">> \t\tkernel 38298/nbd-deploy-tl6t4a6t/kernel/Image\r"}
- {"dt": "2024-12-11T12:36:57.612136", "lvl": "debug", "msg": ">> \t\tinitramfs \r"}
- {"dt": "2024-12-11T12:36:57.612254", "lvl": "debug", "msg": ">> \t\t\r"}
- {"dt": "2024-12-11T12:36:57.613049", "lvl": "debug", "msg": ">> cp: '/var/lib/lava/dispatcher/tmp/bcm2712-rpi-5-b.dtb' and '/var/lib/lava/dispatcher/tmp/bcm2712-rpi-5-b.dtb' are the same file\r"}
- {"dt": "2024-12-11T12:36:57.613365", "lvl": "debug", "msg": ">> DEBUG: found /var/lib/lava/dispatcher/tmp/38298/nbd-deploy-tl6t4a6t/dtb/bcm2712-rpi-5-b.dtb\r"}
- {"dt": "2024-12-11T12:36:57.614761", "lvl": "debug", "msg": ">> DEBUG: BASETFTP=/var/lib/lava/dispatcher/tmp/38298/nbd-deploy-tl6t4a6t\r"}
- {"dt": "2024-12-11T12:36:57.616267", "lvl": "debug", "msg": ">> DEBUG: INITRD=/var/lib/lava/dispatcher/tmp/38298/nbd-deploy-tl6t4a6t/initrd/initramfs-netboot-image-raspberrypi5-20241028040434.ext4\r"}
- {"dt": "2024-12-11T12:36:57.617728", "lvl": "debug", "msg": ">> DEBUG: REL_INITRD=38298/nbd-deploy-tl6t4a6t/initrd/initramfs-netboot-image-raspberrypi5-20241028040434.ext4\r"}
- {"dt": "2024-12-11T12:36:57.619000", "lvl": "debug", "msg": ">> DEBUG: IMAGE=/var/lib/lava/dispatcher/tmp/38298/nbd-deploy-tl6t4a6t/kernel/Image\r"}
- {"dt": "2024-12-11T12:36:57.620509", "lvl": "debug", "msg": ">> DEBUG: REL_IMAGE=38298/nbd-deploy-tl6t4a6t/kernel/Image\r"}
- {"dt": "2024-12-11T12:36:57.680101", "lvl": "debug", "msg": ">> DEBUG: check LISTEN 0      10           0.0.0.0:61969      0.0.0.0:*    users:((\"nbd-server\",pid=15290,fd=3))\r"}
- {"dt": "2024-12-11T12:36:57.682049", "lvl": "debug", "msg": ">> DEBUG: PID=15290\r"}
- {"dt": "2024-12-11T12:36:57.688797", "lvl": "debug", "msg": ">> NBDPORT=61969\r"}
- {"dt": "2024-12-11T12:36:57.690970", "lvl": "debug", "msg": ">> \r"}
- {"dt": "2024-12-11T12:36:57.691121", "lvl": "debug", "msg": ">> \t\tenable_uart=1\r"}
- {"dt": "2024-12-11T12:36:57.691223", "lvl": "debug", "msg": ">> \t\tkernel 38298/nbd-deploy-tl6t4a6t/kernel/Image\r"}
- {"dt": "2024-12-11T12:36:57.691319", "lvl": "debug", "msg": ">> \t\tinitramfs initramfs-netboot-image-raspberrypi5-20241028040434.ext4\r"}
- {"dt": "2024-12-11T12:36:57.691416", "lvl": "debug", "msg": ">> \t\t\r"}
- {"dt": "2024-12-11T12:36:57.692731", "lvl": "debug", "msg": "Returned 0 in 7 seconds"}
- {"dt": "2024-12-11T12:36:57.793441", "lvl": "debug", "msg": "end: 2.2.1 pdu-reboot (duration 00:00:07) [common]"}
- {"dt": "2024-12-11T12:36:57.794034", "lvl": "results", "msg": {"case": "pdu-reboot", "definition": "lava", "duration": "7.26", "extra": {"status": "success"}, "level": "2.2.1", "namespace": "common", "result": "pass"}}
- {"dt": "2024-12-11T12:36:57.794706", "lvl": "debug", "msg": "end: 2.2 reset-device (duration 00:00:07) [common]"}
- {"dt": "2024-12-11T12:36:57.795114", "lvl": "debug", "msg": "start: 2.3 auto-login-action (timeout 00:08:58) [common]"}
- {"dt": "2024-12-11T12:36:57.795474", "lvl": "debug", "msg": "Setting prompt string to ['Linux version [0-9]']"}
- {"dt": "2024-12-11T12:36:57.795789", "lvl": "debug", "msg": "auto-login-action: Wait for prompt ['Linux version [0-9]'] (timeout 00:20:00)"}
- {"dt": "2024-12-11T12:36:57.796821", "lvl": "target", "msg": "Trying 127.0.0.1..."}
- {"dt": "2024-12-11T12:36:57.797143", "lvl": "target", "msg": "Connected to 127.0.0.1."}
- {"dt": "2024-12-11T12:36:57.797397", "lvl": "target", "msg": "Escape character is '^]'."}
- {"dt": "2024-12-11T12:45:55.795624", "lvl": "exception", "msg": "auto-login-action timed out after 538 seconds"}
- {"dt": "2024-12-11T12:45:55.796258", "lvl": "debug", "msg": "end: 2.3 auto-login-action (duration 00:08:58) [common]"}
- {"dt": "2024-12-11T12:45:55.796647", "lvl": "results", "msg": {"case": "auto-login-action", "definition": "lava", "duration": "538.00", "extra": {"fail": "auto-login-action timed out after 538 seconds"}, "level": "2.3", "namespace": "common", "result": "fail"}}
- {"dt": "2024-12-11T12:45:55.797278", "lvl": "error", "msg": "minimal-boot failed: 1 of 1 attempts. 'auto-login-action timed out after 538 seconds'"}
- {"dt": "2024-12-11T12:45:55.797721", "lvl": "exception", "msg": "auto-login-action timed out after 538 seconds"}
- {"dt": "2024-12-11T12:45:55.798026", "lvl": "info", "msg": "end: 2 minimal-boot (duration 00:09:05) [common]"}
- {"dt": "2024-12-11T12:45:55.798342", "lvl": "results", "msg": {"case": "minimal-boot", "definition": "lava", "duration": "545.27", "extra": {"fail": "auto-login-action timed out after 538 seconds"}, "level": "2", "namespace": "common", "result": "fail"}}
- {"dt": "2024-12-11T12:45:55.799026", "lvl": "info", "msg": "Cleaning after the job"}
- {"dt": "2024-12-11T12:45:55.799467", "lvl": "debug", "msg": "Cleaning up download directory: /var/lib/lava/dispatcher/tmp/38298/nbd-deploy-tl6t4a6t/initrd"}
- {"dt": "2024-12-11T12:45:55.801874", "lvl": "debug", "msg": "Cleaning up download directory: /var/lib/lava/dispatcher/tmp/38298/nbd-deploy-tl6t4a6t/kernel"}
- {"dt": "2024-12-11T12:45:55.805090", "lvl": "debug", "msg": "Cleaning up download directory: /var/lib/lava/dispatcher/tmp/38298/nbd-deploy-tl6t4a6t/dtb"}
- {"dt": "2024-12-11T12:45:55.805332", "lvl": "debug", "msg": "Cleaning up download directory: /var/lib/lava/dispatcher/tmp/38298/nbd-deploy-tl6t4a6t/nbdroot"}
- {"dt": "2024-12-11T12:45:56.030794", "lvl": "debug", "msg": "start: 5.1 power-off (timeout 00:00:30) [common]"}
- {"dt": "2024-12-11T12:45:56.031005", "lvl": "debug", "msg": "Calling: 'upower.sh' '--atx' 'off' '2'"}
- {"dt": "2024-12-11T12:45:57.069275", "lvl": "debug", "msg": ">> No GEMBIRD SiS-PM found. Check USB connections, please!\r"}
- {"dt": "2024-12-11T12:45:57.071029", "lvl": "debug", "msg": "Returned 0 in 1 seconds"}
- {"dt": "2024-12-11T12:45:57.171864", "lvl": "debug", "msg": "end: 5.1 power-off (duration 00:00:01) [common]"}
- {"dt": "2024-12-11T12:45:57.172439", "lvl": "results", "msg": {"case": "power-off", "definition": "lava", "duration": "1.14", "extra": {"status": "success"}, "level": "5.1", "namespace": "common", "result": "pass"}}
- {"dt": "2024-12-11T12:45:57.173204", "lvl": "debug", "msg": "start: 5.2 read-feedback (timeout 00:09:59) [common]"}
- {"dt": "2024-12-11T12:45:57.174184", "lvl": "debug", "msg": "Listened to connection for namespace 'common' for up to 1s"}
- {"dt": "2024-12-11T12:45:58.175153", "lvl": "info", "msg": "Finalising connection for namespace 'common'"}
- {"dt": "2024-12-11T12:45:58.175805", "lvl": "info", "msg": "Disconnecting from shell: Finalise"}
- {"dt": "2024-12-11T12:45:58.276950", "lvl": "debug", "msg": "end: 5.2 read-feedback (duration 00:00:01) [common]"}
- {"dt": "2024-12-11T12:45:58.277518", "lvl": "debug", "msg": "lava-xnbd cleanup"}
- {"dt": "2024-12-11T12:45:58.277856", "lvl": "debug", "msg": "clean NBD port 61969"}
- {"dt": "2024-12-11T12:45:58.389216", "lvl": "info", "msg": "Override tmp directory removed at /var/lib/lava/dispatcher/tmp/38298"}
- {"dt": "2024-12-11T12:45:58.394455", "lvl": "info", "msg": "Root tmp directory removed at /var/lib/lava/dispatcher/tmp/38298"}
- {"dt": "2024-12-11T12:45:58.394636", "lvl": "error", "msg": "JobError: Your job cannot terminate cleanly."}
- {"dt": "2024-12-11T12:45:58.394720", "lvl": "results", "msg": {"case": "job", "definition": "lava", "error_msg": "auto-login-action timed out after 538 seconds", "error_type": "Job", "result": "fail"}}
