- {"dt": "2024-12-11T12:05:32.890206", "lvl": "warning", "msg": "Action timeout for connect-device exceeds Job timeout"}
- {"dt": "2024-12-11T12:05:32.890586", "lvl": "warning", "msg": "Action timeout for pdu-reboot exceeds Job timeout"}
- {"dt": "2024-12-11T12:05:32.890717", "lvl": "warning", "msg": "Action timeout for reset-device exceeds Job timeout"}
- {"dt": "2024-12-11T12:05:32.890856", "lvl": "warning", "msg": "Action timeout for login-action exceeds Job timeout"}
- {"dt": "2024-12-11T12:05:32.890968", "lvl": "warning", "msg": "Action timeout for auto-login-action exceeds Job timeout"}
- {"dt": "2024-12-11T12:05:32.891109", "lvl": "warning", "msg": "Action timeout for expect-shell-connection exceeds Job timeout"}
- {"dt": "2024-12-11T12:05:32.891216", "lvl": "warning", "msg": "Action timeout for overlay-unpack exceeds Job timeout"}
- {"dt": "2024-12-11T12:05:32.891330", "lvl": "warning", "msg": "Action timeout for export-device-env exceeds Job timeout"}
- {"dt": "2024-12-11T12:05:32.891453", "lvl": "warning", "msg": "Action timeout for minimal-boot exceeds Job timeout"}
- {"dt": "2024-12-11T12:05:32.905134", "lvl": "info", "msg": "lava-dispatcher, installed at version: 2023.10"}
- {"dt": "2024-12-11T12:05:32.905252", "lvl": "info", "msg": "start: 0 validate"}
- {"dt": "2024-12-11T12:05:32.905402", "lvl": "info", "msg": "Start time: 2024-12-11 12:05:32.905392+00:00 (UTC)"}
- {"dt": "2024-12-11T12:05:32.905591", "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:05:33.672273", "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:05:33.877354", "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:05:34.081961", "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:05:34.289960", "lvl": "info", "msg": "validate duration: 1.38"}
- {"dt": "2024-12-11T12:05:34.290100", "lvl": "results", "msg": {"case": "validate", "definition": "lava", "result": "pass"}}
- {"dt": "2024-12-11T12:05:34.290281", "lvl": "info", "msg": "start: 1 nbd-deploy (timeout 00:10:00) [common]"}
- {"dt": "2024-12-11T12:05:34.290370", "lvl": "info", "msg": "Making protocol call for nbd-deploy using lava-xnbd"}
- {"dt": "2024-12-11T12:05:34.290446", "lvl": "debug", "msg": "[nbd-deploy] Checking protocol data for lava-xnbd"}
- {"dt": "2024-12-11T12:05:34.290522", "lvl": "debug", "msg": "Get a port from pool"}
- {"dt": "2024-12-11T12:05:34.290688", "lvl": "debug", "msg": "Set_port 61999"}
- {"dt": "2024-12-11T12:05:34.290797", "lvl": "debug", "msg": "start: 1.1 download-retry (timeout 00:10:00) [common]"}
- {"dt": "2024-12-11T12:05:34.290897", "lvl": "debug", "msg": "start: 1.1.1 http-download (timeout 00:10:00) [common]"}
- {"dt": "2024-12-11T12:05:34.291131", "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:05:34.291228", "lvl": "debug", "msg": "saving as /var/lib/lava/dispatcher/tmp/38293/nbd-deploy-u6ninb76/initrd/initramfs-netboot-image-raspberrypi5-20241028040434.ext4"}
- {"dt": "2024-12-11T12:05:34.291312", "lvl": "debug", "msg": "total size: 2153804 (2\u202FMB)"}
- {"dt": "2024-12-11T12:05:34.291394", "lvl": "info", "msg": "Using gunzip to decompress gz"}
- {"dt": "2024-12-11T12:05:34.595073", "lvl": "debug", "msg": "progress   1\u202F% (0\u202FMB)"}
- {"dt": "2024-12-11T12:05:34.791457", "lvl": "debug", "msg": "progress   6\u202F% (0\u202FMB)"}
- {"dt": "2024-12-11T12:05:34.890630", "lvl": "debug", "msg": "progress  12\u202F% (0\u202FMB)"}
- {"dt": "2024-12-11T12:05:34.906553", "lvl": "debug", "msg": "progress  18\u202F% (0\u202FMB)"}
- {"dt": "2024-12-11T12:05:34.989810", "lvl": "debug", "msg": "progress  24\u202F% (0\u202FMB)"}
- {"dt": "2024-12-11T12:05:35.010810", "lvl": "debug", "msg": "progress  30\u202F% (0\u202FMB)"}
- {"dt": "2024-12-11T12:05:35.011712", "lvl": "debug", "msg": "progress  36\u202F% (0\u202FMB)"}
- {"dt": "2024-12-11T12:05:35.012414", "lvl": "debug", "msg": "progress  41\u202F% (0\u202FMB)"}
- {"dt": "2024-12-11T12:05:35.089530", "lvl": "debug", "msg": "progress  47\u202F% (0\u202FMB)"}
- {"dt": "2024-12-11T12:05:35.095023", "lvl": "debug", "msg": "progress  53\u202F% (1\u202FMB)"}
- {"dt": "2024-12-11T12:05:35.103970", "lvl": "debug", "msg": "progress  59\u202F% (1\u202FMB)"}
- {"dt": "2024-12-11T12:05:35.105463", "lvl": "debug", "msg": "progress  65\u202F% (1\u202FMB)"}
- {"dt": "2024-12-11T12:05:35.115233", "lvl": "debug", "msg": "progress  71\u202F% (1\u202FMB)"}
- {"dt": "2024-12-11T12:05:35.115819", "lvl": "debug", "msg": "progress  76\u202F% (1\u202FMB)"}
- {"dt": "2024-12-11T12:05:35.120519", "lvl": "debug", "msg": "progress  82\u202F% (1\u202FMB)"}
- {"dt": "2024-12-11T12:05:35.187274", "lvl": "debug", "msg": "progress  88\u202F% (1\u202FMB)"}
- {"dt": "2024-12-11T12:05:35.207433", "lvl": "debug", "msg": "progress  94\u202F% (1\u202FMB)"}
- {"dt": "2024-12-11T12:05:35.208544", "lvl": "debug", "msg": "progress 100\u202F% (2\u202FMB)"}
- {"dt": "2024-12-11T12:05:35.241608", "lvl": "info", "msg": "2\u202FMB downloaded in 0.95\u202Fs (2.16\u202FMB/s)"}
- {"dt": "2024-12-11T12:05:35.241925", "lvl": "debug", "msg": "end: 1.1.1 http-download (duration 00:00:01) [common]"}
- {"dt": "2024-12-11T12:05:35.242014", "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:05:35.242205", "lvl": "debug", "msg": "end: 1.1 download-retry (duration 00:00:01) [common]"}
- {"dt": "2024-12-11T12:05:35.242297", "lvl": "debug", "msg": "start: 1.2 download-retry (timeout 00:09:59) [common]"}
- {"dt": "2024-12-11T12:05:35.242387", "lvl": "debug", "msg": "start: 1.2.1 http-download (timeout 00:09:59) [common]"}
- {"dt": "2024-12-11T12:05:35.242583", "lvl": "info", "msg": "downloading http://download.automotivelinux.org/AGL/release/ricefish/18.0.2/raspberrypi5/deploy/images/raspberrypi5/Image"}
- {"dt": "2024-12-11T12:05:35.242658", "lvl": "debug", "msg": "saving as /var/lib/lava/dispatcher/tmp/38293/nbd-deploy-u6ninb76/kernel/Image"}
- {"dt": "2024-12-11T12:05:35.242720", "lvl": "debug", "msg": "total size: 28887552 (27\u202FMB)"}
- {"dt": "2024-12-11T12:05:35.242783", "lvl": "debug", "msg": "No compression specified"}
- {"dt": "2024-12-11T12:05:35.543963", "lvl": "debug", "msg": "progress   0\u202F% (0\u202FMB)"}
- {"dt": "2024-12-11T12:05:36.055447", "lvl": "debug", "msg": "progress   5\u202F% (1\u202FMB)"}
- {"dt": "2024-12-11T12:05:36.172847", "lvl": "debug", "msg": "progress  10\u202F% (2\u202FMB)"}
- {"dt": "2024-12-11T12:05:36.300699", "lvl": "debug", "msg": "progress  15\u202F% (4\u202FMB)"}
- {"dt": "2024-12-11T12:05:36.818061", "lvl": "debug", "msg": "progress  20\u202F% (5\u202FMB)"}
- {"dt": "2024-12-11T12:05:37.460978", "lvl": "debug", "msg": "progress  25\u202F% (6\u202FMB)"}
- {"dt": "2024-12-11T12:05:39.717960", "lvl": "debug", "msg": "progress  30\u202F% (8\u202FMB)"}
- {"dt": "2024-12-11T12:05:39.737435", "lvl": "debug", "msg": "progress  35\u202F% (9\u202FMB)"}
- {"dt": "2024-12-11T12:05:39.757279", "lvl": "debug", "msg": "progress  40\u202F% (11\u202FMB)"}
- {"dt": "2024-12-11T12:05:39.875392", "lvl": "debug", "msg": "progress  45\u202F% (12\u202FMB)"}
- {"dt": "2024-12-11T12:05:40.029715", "lvl": "debug", "msg": "progress  50\u202F% (13\u202FMB)"}
- {"dt": "2024-12-11T12:05:40.036458", "lvl": "debug", "msg": "progress  55\u202F% (15\u202FMB)"}
- {"dt": "2024-12-11T12:05:40.135127", "lvl": "debug", "msg": "progress  60\u202F% (16\u202FMB)"}
- {"dt": "2024-12-11T12:05:40.147911", "lvl": "debug", "msg": "progress  65\u202F% (17\u202FMB)"}
- {"dt": "2024-12-11T12:05:40.238335", "lvl": "debug", "msg": "progress  70\u202F% (19\u202FMB)"}
- {"dt": "2024-12-11T12:05:40.249792", "lvl": "debug", "msg": "progress  75\u202F% (20\u202FMB)"}
- {"dt": "2024-12-11T12:05:40.338734", "lvl": "debug", "msg": "progress  80\u202F% (22\u202FMB)"}
- {"dt": "2024-12-11T12:05:40.348866", "lvl": "debug", "msg": "progress  85\u202F% (23\u202FMB)"}
- {"dt": "2024-12-11T12:05:40.445668", "lvl": "debug", "msg": "progress  90\u202F% (24\u202FMB)"}
- {"dt": "2024-12-11T12:05:40.524118", "lvl": "debug", "msg": "progress  95\u202F% (26\u202FMB)"}
- {"dt": "2024-12-11T12:05:40.545817", "lvl": "debug", "msg": "progress 100\u202F% (27\u202FMB)"}
- {"dt": "2024-12-11T12:05:40.546127", "lvl": "info", "msg": "27\u202FMB downloaded in 5.30\u202Fs (5.19\u202FMB/s)"}
- {"dt": "2024-12-11T12:05:40.546330", "lvl": "debug", "msg": "end: 1.2.1 http-download (duration 00:00:05) [common]"}
- {"dt": "2024-12-11T12:05:40.546420", "lvl": "results", "msg": {"case": "http-download", "definition": "lava", "duration": "5.30", "extra": {"label": "kernel", "md5sum": "601b383c3c881d04e3368bd84040fdbd", "sha256sum": "99041f31b2ec83f4057caf62ca4bf1534d860cf2d8612fde079894451d55e486", "sha512sum": "e956efcf89178c3aa3fe2491edd04292d25136cf49bc45f7fdfcaa45b40768824dafc595be0d4dbccf066dc2d8dcfce3c6b446189612fa22ab6f3c465cab66c3", "size": ! "28887552"}, "level": "1.2.1", "namespace": "common", "result": "pass"}}
- {"dt": "2024-12-11T12:05:40.546613", "lvl": "debug", "msg": "end: 1.2 download-retry (duration 00:00:05) [common]"}
- {"dt": "2024-12-11T12:05:40.546706", "lvl": "debug", "msg": "start: 1.3 download-retry (timeout 00:09:54) [common]"}
- {"dt": "2024-12-11T12:05:40.546796", "lvl": "debug", "msg": "start: 1.3.1 http-download (timeout 00:09:54) [common]"}
- {"dt": "2024-12-11T12:05:40.546995", "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:05:40.547071", "lvl": "debug", "msg": "saving as /var/lib/lava/dispatcher/tmp/38293/nbd-deploy-u6ninb76/dtb/bcm2712-rpi-5-b.dtb"}
- {"dt": "2024-12-11T12:05:40.547134", "lvl": "debug", "msg": "total size: 78059 (0\u202FMB)"}
- {"dt": "2024-12-11T12:05:40.547198", "lvl": "debug", "msg": "No compression specified"}
- {"dt": "2024-12-11T12:05:40.845959", "lvl": "debug", "msg": "progress  41\u202F% (0\u202FMB)"}
- {"dt": "2024-12-11T12:05:40.944449", "lvl": "debug", "msg": "progress  83\u202F% (0\u202FMB)"}
- {"dt": "2024-12-11T12:05:40.945963", "lvl": "debug", "msg": "progress 100\u202F% (0\u202FMB)"}
- {"dt": "2024-12-11T12:05:40.946717", "lvl": "info", "msg": "0\u202FMB downloaded in 0.40\u202Fs (0.19\u202FMB/s)"}
- {"dt": "2024-12-11T12:05:40.947364", "lvl": "debug", "msg": "end: 1.3.1 http-download (duration 00:00:00) [common]"}
- {"dt": "2024-12-11T12:05:40.947692", "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:05:40.948401", "lvl": "debug", "msg": "end: 1.3 download-retry (duration 00:00:00) [common]"}
- {"dt": "2024-12-11T12:05:40.948801", "lvl": "debug", "msg": "start: 1.4 download-retry (timeout 00:09:53) [common]"}
- {"dt": "2024-12-11T12:05:40.949175", "lvl": "debug", "msg": "start: 1.4.1 http-download (timeout 00:09:53) [common]"}
- {"dt": "2024-12-11T12:05:40.949713", "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:05:40.949799", "lvl": "debug", "msg": "saving as /var/lib/lava/dispatcher/tmp/38293/nbd-deploy-u6ninb76/nbdroot/agl-ivi-demo-qt-raspberrypi5-20241028040434.ext4"}
- {"dt": "2024-12-11T12:05:40.949861", "lvl": "debug", "msg": "total size: 493866112 (470\u202FMB)"}
- {"dt": "2024-12-11T12:05:40.949924", "lvl": "info", "msg": "Using unxz to decompress xz"}
- {"dt": "2024-12-11T12:05:41.251684", "lvl": "debug", "msg": "progress   0\u202F% (0\u202FMB)"}
- {"dt": "2024-12-11T12:05:43.585789", "lvl": "debug", "msg": "progress   5\u202F% (23\u202FMB)"}
- {"dt": "2024-12-11T12:05:45.198029", "lvl": "debug", "msg": "progress  10\u202F% (47\u202FMB)"}
- {"dt": "2024-12-11T12:05:46.964363", "lvl": "debug", "msg": "progress  15\u202F% (70\u202FMB)"}
- {"dt": "2024-12-11T12:05:48.774918", "lvl": "debug", "msg": "progress  20\u202F% (94\u202FMB)"}
- {"dt": "2024-12-11T12:05:50.529235", "lvl": "debug", "msg": "progress  25\u202F% (117\u202FMB)"}
- {"dt": "2024-12-11T12:05:52.400721", "lvl": "debug", "msg": "progress  30\u202F% (141\u202FMB)"}
- {"dt": "2024-12-11T12:05:54.297408", "lvl": "debug", "msg": "progress  35\u202F% (164\u202FMB)"}
- {"dt": "2024-12-11T12:05:56.264318", "lvl": "debug", "msg": "progress  40\u202F% (188\u202FMB)"}
- {"dt": "2024-12-11T12:05:57.847802", "lvl": "debug", "msg": "progress  45\u202F% (211\u202FMB)"}
- {"dt": "2024-12-11T12:05:59.553538", "lvl": "debug", "msg": "progress  50\u202F% (235\u202FMB)"}
- {"dt": "2024-12-11T12:06:01.242060", "lvl": "debug", "msg": "progress  55\u202F% (259\u202FMB)"}
- {"dt": "2024-12-11T12:06:03.108297", "lvl": "debug", "msg": "progress  60\u202F% (282\u202FMB)"}
- {"dt": "2024-12-11T12:06:04.705399", "lvl": "debug", "msg": "progress  65\u202F% (306\u202FMB)"}
- {"dt": "2024-12-11T12:06:06.490859", "lvl": "debug", "msg": "progress  70\u202F% (329\u202FMB)"}
- {"dt": "2024-12-11T12:06:08.713327", "lvl": "debug", "msg": "progress  75\u202F% (353\u202FMB)"}
- {"dt": "2024-12-11T12:06:10.629296", "lvl": "debug", "msg": "progress  80\u202F% (376\u202FMB)"}
- {"dt": "2024-12-11T12:06:12.246027", "lvl": "debug", "msg": "progress  85\u202F% (400\u202FMB)"}
- {"dt": "2024-12-11T12:06:14.195913", "lvl": "debug", "msg": "progress  90\u202F% (423\u202FMB)"}
- {"dt": "2024-12-11T12:06:16.045479", "lvl": "debug", "msg": "progress  95\u202F% (447\u202FMB)"}
- {"dt": "2024-12-11T12:06:20.034322", "lvl": "debug", "msg": "progress 100\u202F% (470\u202FMB)"}
- {"dt": "2024-12-11T12:06:21.453529", "lvl": "info", "msg": "470\u202FMB downloaded in 40.50\u202Fs (11.63\u202FMB/s)"}
- {"dt": "2024-12-11T12:06:21.453853", "lvl": "debug", "msg": "end: 1.4.1 http-download (duration 00:00:41) [common]"}
- {"dt": "2024-12-11T12:06:21.453953", "lvl": "results", "msg": {"case": "http-download", "definition": "lava", "duration": "40.50", "extra": {"label": "nbdroot", "md5sum": "4efb22dd71d11d782c04913029ebe146", "sha256sum": "b475a2953ee1a6be85506449e60e93d14579f8af2dc5577723d004a952eda229", "sha512sum": "888ffdcec6b22a5b3cd3e391eaa7a1bf5c6493efe72df9f895ac361c0117ba23335502223b5b769ad9e63ef740001581525ce5eaeaf2ac29e1b76eb53d8395b8", "size": ! "493866112"}, "level": "1.4.1", "namespace": "common", "result": "pass"}}
- {"dt": "2024-12-11T12:06:21.454159", "lvl": "debug", "msg": "end: 1.4 download-retry (duration 00:00:41) [common]"}
- {"dt": "2024-12-11T12:06:21.454279", "lvl": "debug", "msg": "start: 1.5 lava-overlay (timeout 00:09:13) [common]"}
- {"dt": "2024-12-11T12:06:21.454602", "lvl": "debug", "msg": "[common] Preparing overlay tarball in /var/lib/lava/dispatcher/tmp/38293/lava-overlay-fgeqybpl"}
- {"dt": "2024-12-11T12:06:21.454805", "lvl": "debug", "msg": "makedir: /var/lib/lava/dispatcher/tmp/38293/lava-overlay-fgeqybpl/lava-38293/bin"}
- {"dt": "2024-12-11T12:06:21.454938", "lvl": "debug", "msg": "makedir: /var/lib/lava/dispatcher/tmp/38293/lava-overlay-fgeqybpl/lava-38293/tests"}
- {"dt": "2024-12-11T12:06:21.455068", "lvl": "debug", "msg": "makedir: /var/lib/lava/dispatcher/tmp/38293/lava-overlay-fgeqybpl/lava-38293/results"}
- {"dt": "2024-12-11T12:06:21.455204", "lvl": "debug", "msg": "Creating /var/lib/lava/dispatcher/tmp/38293/lava-overlay-fgeqybpl/lava-38293/bin/lava-add-keys"}
- {"dt": "2024-12-11T12:06:21.455421", "lvl": "debug", "msg": "Creating /var/lib/lava/dispatcher/tmp/38293/lava-overlay-fgeqybpl/lava-38293/bin/lava-add-sources"}
- {"dt": "2024-12-11T12:06:21.455616", "lvl": "debug", "msg": "Creating /var/lib/lava/dispatcher/tmp/38293/lava-overlay-fgeqybpl/lava-38293/bin/lava-background-process-start"}
- {"dt": "2024-12-11T12:06:21.455807", "lvl": "debug", "msg": "Creating /var/lib/lava/dispatcher/tmp/38293/lava-overlay-fgeqybpl/lava-38293/bin/lava-background-process-stop"}
- {"dt": "2024-12-11T12:06:21.456007", "lvl": "debug", "msg": "Creating /var/lib/lava/dispatcher/tmp/38293/lava-overlay-fgeqybpl/lava-38293/bin/lava-common-functions"}
- {"dt": "2024-12-11T12:06:21.456201", "lvl": "debug", "msg": "Creating /var/lib/lava/dispatcher/tmp/38293/lava-overlay-fgeqybpl/lava-38293/bin/lava-echo-ipv4"}
- {"dt": "2024-12-11T12:06:21.456389", "lvl": "debug", "msg": "Creating /var/lib/lava/dispatcher/tmp/38293/lava-overlay-fgeqybpl/lava-38293/bin/lava-install-packages"}
- {"dt": "2024-12-11T12:06:21.456574", "lvl": "debug", "msg": "Creating /var/lib/lava/dispatcher/tmp/38293/lava-overlay-fgeqybpl/lava-38293/bin/lava-installed-packages"}
- {"dt": "2024-12-11T12:06:21.456768", "lvl": "debug", "msg": "Creating /var/lib/lava/dispatcher/tmp/38293/lava-overlay-fgeqybpl/lava-38293/bin/lava-os-build"}
- {"dt": "2024-12-11T12:06:21.456959", "lvl": "debug", "msg": "Creating /var/lib/lava/dispatcher/tmp/38293/lava-overlay-fgeqybpl/lava-38293/bin/lava-probe-channel"}
- {"dt": "2024-12-11T12:06:21.457142", "lvl": "debug", "msg": "Creating /var/lib/lava/dispatcher/tmp/38293/lava-overlay-fgeqybpl/lava-38293/bin/lava-probe-ip"}
- {"dt": "2024-12-11T12:06:21.457324", "lvl": "debug", "msg": "Creating /var/lib/lava/dispatcher/tmp/38293/lava-overlay-fgeqybpl/lava-38293/bin/lava-target-ip"}
- {"dt": "2024-12-11T12:06:21.457506", "lvl": "debug", "msg": "Creating /var/lib/lava/dispatcher/tmp/38293/lava-overlay-fgeqybpl/lava-38293/bin/lava-target-mac"}
- {"dt": "2024-12-11T12:06:21.457687", "lvl": "debug", "msg": "Creating /var/lib/lava/dispatcher/tmp/38293/lava-overlay-fgeqybpl/lava-38293/bin/lava-target-storage"}
- {"dt": "2024-12-11T12:06:21.457878", "lvl": "debug", "msg": "Creating /var/lib/lava/dispatcher/tmp/38293/lava-overlay-fgeqybpl/lava-38293/bin/lava-test-case"}
- {"dt": "2024-12-11T12:06:21.458061", "lvl": "debug", "msg": "Creating /var/lib/lava/dispatcher/tmp/38293/lava-overlay-fgeqybpl/lava-38293/bin/lava-test-event"}
- {"dt": "2024-12-11T12:06:21.458241", "lvl": "debug", "msg": "Creating /var/lib/lava/dispatcher/tmp/38293/lava-overlay-fgeqybpl/lava-38293/bin/lava-test-feedback"}
- {"dt": "2024-12-11T12:06:21.458423", "lvl": "debug", "msg": "Creating /var/lib/lava/dispatcher/tmp/38293/lava-overlay-fgeqybpl/lava-38293/bin/lava-test-raise"}
- {"dt": "2024-12-11T12:06:21.458617", "lvl": "debug", "msg": "Creating /var/lib/lava/dispatcher/tmp/38293/lava-overlay-fgeqybpl/lava-38293/bin/lava-test-reference"}
- {"dt": "2024-12-11T12:06:21.458801", "lvl": "debug", "msg": "Creating /var/lib/lava/dispatcher/tmp/38293/lava-overlay-fgeqybpl/lava-38293/bin/lava-test-runner"}
- {"dt": "2024-12-11T12:06:21.458982", "lvl": "debug", "msg": "Creating /var/lib/lava/dispatcher/tmp/38293/lava-overlay-fgeqybpl/lava-38293/bin/lava-test-set"}
- {"dt": "2024-12-11T12:06:21.459160", "lvl": "debug", "msg": "Creating /var/lib/lava/dispatcher/tmp/38293/lava-overlay-fgeqybpl/lava-38293/bin/lava-test-shell"}
- {"dt": "2024-12-11T12:06:21.459343", "lvl": "debug", "msg": "Updating /var/lib/lava/dispatcher/tmp/38293/lava-overlay-fgeqybpl/lava-38293/bin/lava-install-packages (oe)"}
- {"dt": "2024-12-11T12:06:21.459575", "lvl": "debug", "msg": "Updating /var/lib/lava/dispatcher/tmp/38293/lava-overlay-fgeqybpl/lava-38293/bin/lava-installed-packages (oe)"}
- {"dt": "2024-12-11T12:06:21.459758", "lvl": "debug", "msg": "Creating /var/lib/lava/dispatcher/tmp/38293/lava-overlay-fgeqybpl/lava-38293/environment"}
- {"dt": "2024-12-11T12:06:21.459908", "lvl": "debug", "msg": "LAVA metadata"}
- {"dt": "2024-12-11T12:06:21.460000", "lvl": "debug", "msg": "- LAVA_JOB_ID=38293"}
- {"dt": "2024-12-11T12:06:21.460084", "lvl": "debug", "msg": "- LAVA_DISPATCHER_IP=192.168.66.1"}
- {"dt": "2024-12-11T12:06:21.460231", "lvl": "debug", "msg": "start: 1.5.1 ssh-authorize (timeout 00:09:13) [common]"}
- {"dt": "2024-12-11T12:06:21.460633", "lvl": "debug", "msg": "end: 1.5.1 ssh-authorize (duration 00:00:00) [common]"}
- {"dt": "2024-12-11T12:06:21.460764", "lvl": "debug", "msg": "start: 1.5.2 lava-vland-overlay (timeout 00:09:13) [common]"}
- {"dt": "2024-12-11T12:06:21.460855", "lvl": "debug", "msg": "skipped lava-vland-overlay"}
- {"dt": "2024-12-11T12:06:21.460952", "lvl": "debug", "msg": "end: 1.5.2 lava-vland-overlay (duration 00:00:00) [common]"}
- {"dt": "2024-12-11T12:06:21.461051", "lvl": "debug", "msg": "start: 1.5.3 lava-multinode-overlay (timeout 00:09:13) [common]"}
- {"dt": "2024-12-11T12:06:21.461128", "lvl": "debug", "msg": "skipped lava-multinode-overlay"}
- {"dt": "2024-12-11T12:06:21.461219", "lvl": "debug", "msg": "end: 1.5.3 lava-multinode-overlay (duration 00:00:00) [common]"}
- {"dt": "2024-12-11T12:06:21.461316", "lvl": "debug", "msg": "start: 1.5.4 test-definition (timeout 00:09:13) [common]"}
- {"dt": "2024-12-11T12:06:21.461406", "lvl": "info", "msg": "Loading test definitions"}
- {"dt": "2024-12-11T12:06:21.461515", "lvl": "debug", "msg": "start: 1.5.4.1 inline-repo-action (timeout 00:09:13) [common]"}
- {"dt": "2024-12-11T12:06:21.461606", "lvl": "debug", "msg": "Using /lava-38293 at stage 0"}
- {"dt": "2024-12-11T12:06:21.462135", "lvl": "debug", "msg": "uuid=38293_1.5.4.1 testdef=None"}
- {"dt": "2024-12-11T12:06:21.462258", "lvl": "debug", "msg": "end: 1.5.4.1 inline-repo-action (duration 00:00:00) [common]"}
- {"dt": "2024-12-11T12:06:21.462363", "lvl": "debug", "msg": "start: 1.5.4.2 test-overlay (timeout 00:09:13) [common]"}
- {"dt": "2024-12-11T12:06:21.463144", "lvl": "debug", "msg": "end: 1.5.4.2 test-overlay (duration 00:00:00) [common]"}
- {"dt": "2024-12-11T12:06:21.463243", "lvl": "results", "msg": {"case": "test-overlay", "definition": "lava", "duration": "0.00", "extra": {"from": "inline", "name": "dmesg", "path": "inline/dmesg.yaml", "uuid": "38293_1.5.4.1"}, "level": "1.5.4.2", "namespace": "common", "result": "pass"}}
- {"dt": "2024-12-11T12:06:21.463448", "lvl": "debug", "msg": "start: 1.5.4.3 test-install-overlay (timeout 00:09:13) [common]"}
- {"dt": "2024-12-11T12:06:21.464446", "lvl": "debug", "msg": "end: 1.5.4.3 test-install-overlay (duration 00:00:00) [common]"}
- {"dt": "2024-12-11T12:06:21.464549", "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": "38293_1.5.4.1", "uuid": "38293_1.5.4.1"}, "level": "1.5.4.3", "namespace": "common", "result": "pass"}}
- {"dt": "2024-12-11T12:06:21.464765", "lvl": "debug", "msg": "start: 1.5.4.4 test-runscript-overlay (timeout 00:09:13) [common]"}
- {"dt": "2024-12-11T12:06:21.473485", "lvl": "debug", "msg": "runner path: /var/lib/lava/dispatcher/tmp/38293/lava-overlay-fgeqybpl/lava-38293/0/tests/0_dmesg test_uuid 38293_1.5.4.1"}
- {"dt": "2024-12-11T12:06:21.473808", "lvl": "debug", "msg": "end: 1.5.4.4 test-runscript-overlay (duration 00:00:00) [common]"}
- {"dt": "2024-12-11T12:06:21.473946", "lvl": "results", "msg": {"case": "test-runscript-overlay", "definition": "lava", "duration": "0.01", "extra": {"filename": "/var/lib/lava/dispatcher/tmp/38293/lava-overlay-fgeqybpl/lava-38293/0/tests/0_dmesg/run.sh", "from": "inline", "name": "dmesg", "path": "inline/dmesg.yaml", "uuid": "38293_1.5.4.1"}, "level": "1.5.4.4", "namespace": "common", "result": "pass"}}
- {"dt": "2024-12-11T12:06:21.474230", "lvl": "debug", "msg": "start: 1.5.4.5 inline-repo-action (timeout 00:09:13) [common]"}
- {"dt": "2024-12-11T12:06:21.474352", "lvl": "debug", "msg": "Using /lava-38293 at stage 1"}
- {"dt": "2024-12-11T12:06:21.475002", "lvl": "debug", "msg": "uuid=38293_1.5.4.5 testdef=None"}
- {"dt": "2024-12-11T12:06:21.475171", "lvl": "debug", "msg": "end: 1.5.4.5 inline-repo-action (duration 00:00:00) [common]"}
- {"dt": "2024-12-11T12:06:21.475324", "lvl": "debug", "msg": "start: 1.5.4.6 test-overlay (timeout 00:09:13) [common]"}
- {"dt": "2024-12-11T12:06:21.476332", "lvl": "debug", "msg": "end: 1.5.4.6 test-overlay (duration 00:00:00) [common]"}
- {"dt": "2024-12-11T12:06:21.476457", "lvl": "results", "msg": {"case": "test-overlay", "definition": "lava", "duration": "0.00", "extra": {"from": "inline", "name": "bootrr", "path": "inline/bootrr.yaml", "uuid": "38293_1.5.4.5"}, "level": "1.5.4.6", "namespace": "common", "result": "pass"}}
- {"dt": "2024-12-11T12:06:21.476719", "lvl": "debug", "msg": "start: 1.5.4.7 test-install-overlay (timeout 00:09:13) [common]"}
- {"dt": "2024-12-11T12:06:21.477939", "lvl": "debug", "msg": "end: 1.5.4.7 test-install-overlay (duration 00:00:00) [common]"}
- {"dt": "2024-12-11T12:06:21.478058", "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": "38293_1.5.4.5", "uuid": "38293_1.5.4.5"}, "level": "1.5.4.7", "namespace": "common", "result": "pass"}}
- {"dt": "2024-12-11T12:06:21.478295", "lvl": "debug", "msg": "start: 1.5.4.8 test-runscript-overlay (timeout 00:09:13) [common]"}
- {"dt": "2024-12-11T12:06:21.479314", "lvl": "debug", "msg": "runner path: /var/lib/lava/dispatcher/tmp/38293/lava-overlay-fgeqybpl/lava-38293/1/tests/1_bootrr test_uuid 38293_1.5.4.5"}
- {"dt": "2024-12-11T12:06:21.479563", "lvl": "debug", "msg": "end: 1.5.4.8 test-runscript-overlay (duration 00:00:00) [common]"}
- {"dt": "2024-12-11T12:06:21.479664", "lvl": "results", "msg": {"case": "test-runscript-overlay", "definition": "lava", "duration": "0.00", "extra": {"filename": "/var/lib/lava/dispatcher/tmp/38293/lava-overlay-fgeqybpl/lava-38293/1/tests/1_bootrr/run.sh", "from": "inline", "name": "bootrr", "path": "inline/bootrr.yaml", "uuid": "38293_1.5.4.5"}, "level": "1.5.4.8", "namespace": "common", "result": "pass"}}
- {"dt": "2024-12-11T12:06:21.479836", "lvl": "info", "msg": "Creating lava-test-runner.conf files"}
- {"dt": "2024-12-11T12:06:21.479909", "lvl": "debug", "msg": "Using lava-test-runner path: /var/lib/lava/dispatcher/tmp/38293/lava-overlay-fgeqybpl/lava-38293/0 for stage 0"}
- {"dt": "2024-12-11T12:06:21.480028", "lvl": "debug", "msg": "- 0_dmesg"}
- {"dt": "2024-12-11T12:06:21.480134", "lvl": "debug", "msg": "Using lava-test-runner path: /var/lib/lava/dispatcher/tmp/38293/lava-overlay-fgeqybpl/lava-38293/1 for stage 1"}
- {"dt": "2024-12-11T12:06:21.480258", "lvl": "debug", "msg": "- 1_bootrr"}
- {"dt": "2024-12-11T12:06:21.480376", "lvl": "debug", "msg": "end: 1.5.4 test-definition (duration 00:00:00) [common]"}
- {"dt": "2024-12-11T12:06:21.480473", "lvl": "debug", "msg": "start: 1.5.5 compress-overlay (timeout 00:09:13) [common]"}
- {"dt": "2024-12-11T12:06:21.489854", "lvl": "debug", "msg": "end: 1.5.5 compress-overlay (duration 00:00:00) [common]"}
- {"dt": "2024-12-11T12:06:21.489992", "lvl": "debug", "msg": "start: 1.5.6 persistent-nfs-overlay (timeout 00:09:13) [common]"}
- {"dt": "2024-12-11T12:06:21.490094", "lvl": "debug", "msg": "end: 1.5.6 persistent-nfs-overlay (duration 00:00:00) [common]"}
- {"dt": "2024-12-11T12:06:21.490192", "lvl": "debug", "msg": "end: 1.5 lava-overlay (duration 00:00:00) [common]"}
- {"dt": "2024-12-11T12:06:21.490286", "lvl": "debug", "msg": "start: 1.6 prepare-kernel (timeout 00:09:13) [common]"}
- {"dt": "2024-12-11T12:06:21.490379", "lvl": "debug", "msg": "start: 1.6.1 uboot-prepare-kernel (timeout 00:09:13) [common]"}
- {"dt": "2024-12-11T12:06:21.490481", "lvl": "debug", "msg": "end: 1.6.1 uboot-prepare-kernel (duration 00:00:00) [common]"}
- {"dt": "2024-12-11T12:06:21.490567", "lvl": "debug", "msg": "end: 1.6 prepare-kernel (duration 00:00:00) [common]"}
- {"dt": "2024-12-11T12:06:21.490654", "lvl": "debug", "msg": "start: 1.7 xnbd-server-deploy (timeout 00:09:13) [common]"}
- {"dt": "2024-12-11T12:06:21.490723", "lvl": "debug", "msg": "xnbd-server-deploy: starting nbd-server"}
- {"dt": "2024-12-11T12:06:21.490793", "lvl": "debug", "msg": "NBD-IP: 192.168.66.1, NBD-PORT: 61999, NBD-ROOT: 38293/nbd-deploy-u6ninb76/nbdroot/agl-ivi-demo-qt-raspberrypi5-20241028040434.ext4"}
- {"dt": "2024-12-11T12:06:21.491241", "lvl": "debug", "msg": "nbd-server 61999 /var/lib/lava/dispatcher/tmp/38293/nbd-deploy-u6ninb76/nbdroot/agl-ivi-demo-qt-raspberrypi5-20241028040434.ext4"}
- {"dt": "2024-12-11T12:06:21.494004", "lvl": "debug", "msg": "output: "}
- {"dt": "2024-12-11T12:06:21.494171", "lvl": "debug", "msg": "output: ** (process:15204): WARNING **: 12:06:21.493: Specifying an export on the command line no longer uses the oldstyle protocol."}
- {"dt": "2024-12-11T12:06:21.494269", "lvl": "debug", "msg": "output: "}
- {"dt": "2024-12-11T12:06:21.494351", "lvl": "debug", "msg": "xnbd-server-deploy: starting nbd-server done"}
- {"dt": "2024-12-11T12:06:21.494476", "lvl": "debug", "msg": "end: 1.7 xnbd-server-deploy (duration 00:00:00) [common]"}
- {"dt": "2024-12-11T12:06:21.494596", "lvl": "info", "msg": "end: 1 nbd-deploy (duration 00:00:47) [common]"}
- {"dt": "2024-12-11T12:06:21.494708", "lvl": "info", "msg": "start: 2 minimal-boot (timeout 00:09:13) [common]"}
- {"dt": "2024-12-11T12:06:21.494813", "lvl": "debug", "msg": "start: 2.1 connect-device (timeout 00:09:13) [common]"}
- {"dt": "2024-12-11T12:06:21.494896", "lvl": "info", "msg": "[common] connect-device Connecting to device using 'telnet 127.0.0.1 63007'"}
- {"dt": "2024-12-11T12:06:21.498538", "lvl": "debug", "msg": "Setting prompt string to ['lava-test: # ']"}
- {"dt": "2024-12-11T12:06:21.499082", "lvl": "debug", "msg": "end: 2.1 connect-device (duration 00:00:00) [common]"}
- {"dt": "2024-12-11T12:06:21.499243", "lvl": "debug", "msg": "start: 2.2 reset-device (timeout 00:09:13) [common]"}
- {"dt": "2024-12-11T12:06:21.499370", "lvl": "debug", "msg": "start: 2.2.1 pdu-reboot (timeout 00:09:13) [common]"}
- {"dt": "2024-12-11T12:06:21.499587", "lvl": "debug", "msg": "Calling: 'upower.sh' '--atx' 'reset' '2'"}
- {"dt": "2024-12-11T12:06:22.481349", "lvl": "debug", "msg": ">> No GEMBIRD SiS-PM found. Check USB connections, please!\r"}
- {"dt": "2024-12-11T12:06:26.505188", "lvl": "debug", "msg": ">> No GEMBIRD SiS-PM found. Check USB connections, please!\r"}
- {"dt": "2024-12-11T12:06:28.519290", "lvl": "debug", "msg": ">> export LANG='C'\r"}
- {"dt": "2024-12-11T12:06:28.519892", "lvl": "debug", "msg": ">> export LC_ALL='C.UTF-8'\r"}
- {"dt": "2024-12-11T12:06:28.520269", "lvl": "debug", "msg": ">> export PATH='/usr/local/bin:/usr/local/sbin:/bin:/usr/bin:/usr/sbin:/sbin'\r"}
- {"dt": "2024-12-11T12:06:28.520593", "lvl": "debug", "msg": ">> export PWD='/'\r"}
- {"dt": "2024-12-11T12:06:28.532150", "lvl": "debug", "msg": ">> DEBUG: found /var/lib/lava/dispatcher/tmp/bcm2712-rpi-5-b.dtb\r"}
- {"dt": "2024-12-11T12:06:28.540119", "lvl": "debug", "msg": ">> DEBUG: BASETFTP=/var/lib/lava/dispatcher/tmp\r"}
- {"dt": "2024-12-11T12:06:28.547461", "lvl": "debug", "msg": ">> DEBUG: INITRD=/var/lib/lava/dispatcher/tmp/initramfs-netboot-image-raspberrypi5-20241028040434.ext4\r"}
- {"dt": "2024-12-11T12:06:28.547996", "lvl": "debug", "msg": ">> /var/lib/lava/dispatcher/tmp/38293/nbd-deploy-u6ninb76/initrd/initramfs-netboot-image-raspberrypi5-20241028040434.ext4\r"}
- {"dt": "2024-12-11T12:06:28.548388", "lvl": "debug", "msg": ">> /var/lib/lava/dispatcher/tmp/initramfs-netboot-image-raspberrypi5.ext4.gz\r"}
- {"dt": "2024-12-11T12:06:28.552820", "lvl": "debug", "msg": ">> DEBUG: REL_INITRD=initramfs-netboot-image-raspberrypi5-20241028040434.ext4 /var/lib/lava/dispatcher/tmp/38293/nbd-deploy-u6ninb76/initrd/initramfs-netboot-image-raspberrypi5-20241028040434.ext4 /var/lib/lava/dispatcher/tmp/initramfs-netboot-image-raspberrypi5.ext4.gz\r"}
- {"dt": "2024-12-11T12:06:28.559988", "lvl": "debug", "msg": ">> DEBUG: IMAGE=/var/lib/lava/dispatcher/tmp/38293/nbd-deploy-u6ninb76/kernel/Image\r"}
- {"dt": "2024-12-11T12:06:28.564707", "lvl": "debug", "msg": ">> DEBUG: REL_IMAGE=38293/nbd-deploy-u6ninb76/kernel/Image\r"}
- {"dt": "2024-12-11T12:06:28.573847", "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:06:28.605915", "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:06:28.641297", "lvl": "debug", "msg": ">> DEBUG: check LISTEN 0      10           0.0.0.0:61999      0.0.0.0:*    users:((\"nbd-server\",pid=15205,fd=3))\r"}
- {"dt": "2024-12-11T12:06:28.643389", "lvl": "debug", "msg": ">> DEBUG: PID=15205\r"}
- {"dt": "2024-12-11T12:06:28.651158", "lvl": "debug", "msg": ">> NBDPORT=61999\r"}
- {"dt": "2024-12-11T12:06:28.655293", "lvl": "debug", "msg": ">> basename: extra operand \u2018/var/lib/lava/dispatcher/tmp/initramfs-netboot-image-raspberrypi5.ext4.gz\u2019\r"}
- {"dt": "2024-12-11T12:06:28.655517", "lvl": "debug", "msg": ">> Try 'basename --help' for more information.\r"}
- {"dt": "2024-12-11T12:06:28.657296", "lvl": "debug", "msg": ">> \r"}
- {"dt": "2024-12-11T12:06:28.657543", "lvl": "debug", "msg": ">> \t\tenable_uart=1\r"}
- {"dt": "2024-12-11T12:06:28.657765", "lvl": "debug", "msg": ">> \t\tkernel 38293/nbd-deploy-u6ninb76/kernel/Image\r"}
- {"dt": "2024-12-11T12:06:28.658049", "lvl": "debug", "msg": ">> \t\tinitramfs \r"}
- {"dt": "2024-12-11T12:06:28.658333", "lvl": "debug", "msg": ">> \t\t\r"}
- {"dt": "2024-12-11T12:06:28.659732", "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:06:28.660339", "lvl": "debug", "msg": ">> DEBUG: found /var/lib/lava/dispatcher/tmp/38293/nbd-deploy-u6ninb76/dtb/bcm2712-rpi-5-b.dtb\r"}
- {"dt": "2024-12-11T12:06:28.663467", "lvl": "debug", "msg": ">> DEBUG: BASETFTP=/var/lib/lava/dispatcher/tmp/38293/nbd-deploy-u6ninb76\r"}
- {"dt": "2024-12-11T12:06:28.666665", "lvl": "debug", "msg": ">> DEBUG: INITRD=/var/lib/lava/dispatcher/tmp/38293/nbd-deploy-u6ninb76/initrd/initramfs-netboot-image-raspberrypi5-20241028040434.ext4\r"}
- {"dt": "2024-12-11T12:06:28.670701", "lvl": "debug", "msg": ">> DEBUG: REL_INITRD=38293/nbd-deploy-u6ninb76/initrd/initramfs-netboot-image-raspberrypi5-20241028040434.ext4\r"}
- {"dt": "2024-12-11T12:06:28.674682", "lvl": "debug", "msg": ">> DEBUG: IMAGE=/var/lib/lava/dispatcher/tmp/38293/nbd-deploy-u6ninb76/kernel/Image\r"}
- {"dt": "2024-12-11T12:06:28.679413", "lvl": "debug", "msg": ">> DEBUG: REL_IMAGE=38293/nbd-deploy-u6ninb76/kernel/Image\r"}
- {"dt": "2024-12-11T12:06:28.739012", "lvl": "debug", "msg": ">> DEBUG: check LISTEN 0      10           0.0.0.0:61999      0.0.0.0:*    users:((\"nbd-server\",pid=15205,fd=3))\r"}
- {"dt": "2024-12-11T12:06:28.741296", "lvl": "debug", "msg": ">> DEBUG: PID=15205\r"}
- {"dt": "2024-12-11T12:06:28.750803", "lvl": "debug", "msg": ">> NBDPORT=61999\r"}
- {"dt": "2024-12-11T12:06:28.755187", "lvl": "debug", "msg": ">> \r"}
- {"dt": "2024-12-11T12:06:28.755475", "lvl": "debug", "msg": ">> \t\tenable_uart=1\r"}
- {"dt": "2024-12-11T12:06:28.755703", "lvl": "debug", "msg": ">> \t\tkernel 38293/nbd-deploy-u6ninb76/kernel/Image\r"}
- {"dt": "2024-12-11T12:06:28.755984", "lvl": "debug", "msg": ">> \t\tinitramfs initramfs-netboot-image-raspberrypi5-20241028040434.ext4\r"}
- {"dt": "2024-12-11T12:06:28.756179", "lvl": "debug", "msg": ">> \t\t\r"}
- {"dt": "2024-12-11T12:06:28.759003", "lvl": "debug", "msg": "Returned 0 in 7 seconds"}
- {"dt": "2024-12-11T12:06:28.860113", "lvl": "debug", "msg": "end: 2.2.1 pdu-reboot (duration 00:00:07) [common]"}
- {"dt": "2024-12-11T12:06:28.860698", "lvl": "results", "msg": {"case": "pdu-reboot", "definition": "lava", "duration": "7.36", "extra": {"status": "success"}, "level": "2.2.1", "namespace": "common", "result": "pass"}}
- {"dt": "2024-12-11T12:06:28.861427", "lvl": "debug", "msg": "end: 2.2 reset-device (duration 00:00:07) [common]"}
- {"dt": "2024-12-11T12:06:28.861837", "lvl": "debug", "msg": "start: 2.3 auto-login-action (timeout 00:09:05) [common]"}
- {"dt": "2024-12-11T12:06:28.862205", "lvl": "debug", "msg": "Setting prompt string to ['Linux version [0-9]']"}
- {"dt": "2024-12-11T12:06:28.862522", "lvl": "debug", "msg": "auto-login-action: Wait for prompt ['Linux version [0-9]'] (timeout 00:20:00)"}
- {"dt": "2024-12-11T12:06:28.863525", "lvl": "target", "msg": "Trying 127.0.0.1..."}
- {"dt": "2024-12-11T12:06:28.863845", "lvl": "target", "msg": "Connected to 127.0.0.1."}
- {"dt": "2024-12-11T12:06:28.864109", "lvl": "target", "msg": "Escape character is '^]'."}
- {"dt": "2024-12-11T12:15:33.862329", "lvl": "exception", "msg": "auto-login-action timed out after 545 seconds"}
- {"dt": "2024-12-11T12:15:33.862954", "lvl": "debug", "msg": "end: 2.3 auto-login-action (duration 00:09:05) [common]"}
- {"dt": "2024-12-11T12:15:33.863346", "lvl": "results", "msg": {"case": "auto-login-action", "definition": "lava", "duration": "545.00", "extra": {"fail": "auto-login-action timed out after 545 seconds"}, "level": "2.3", "namespace": "common", "result": "fail"}}
- {"dt": "2024-12-11T12:15:33.863918", "lvl": "error", "msg": "minimal-boot failed: 1 of 1 attempts. 'auto-login-action timed out after 545 seconds'"}
- {"dt": "2024-12-11T12:15:33.864350", "lvl": "exception", "msg": "auto-login-action timed out after 545 seconds"}
- {"dt": "2024-12-11T12:15:33.864659", "lvl": "info", "msg": "end: 2 minimal-boot (duration 00:09:12) [common]"}
- {"dt": "2024-12-11T12:15:33.865032", "lvl": "results", "msg": {"case": "minimal-boot", "definition": "lava", "duration": "552.37", "extra": {"fail": "auto-login-action timed out after 545 seconds"}, "level": "2", "namespace": "common", "result": "fail"}}
- {"dt": "2024-12-11T12:15:33.865754", "lvl": "info", "msg": "Cleaning after the job"}
- {"dt": "2024-12-11T12:15:33.866196", "lvl": "debug", "msg": "Cleaning up download directory: /var/lib/lava/dispatcher/tmp/38293/nbd-deploy-u6ninb76/initrd"}
- {"dt": "2024-12-11T12:15:33.868417", "lvl": "debug", "msg": "Cleaning up download directory: /var/lib/lava/dispatcher/tmp/38293/nbd-deploy-u6ninb76/kernel"}
- {"dt": "2024-12-11T12:15:33.871631", "lvl": "debug", "msg": "Cleaning up download directory: /var/lib/lava/dispatcher/tmp/38293/nbd-deploy-u6ninb76/dtb"}
- {"dt": "2024-12-11T12:15:33.871873", "lvl": "debug", "msg": "Cleaning up download directory: /var/lib/lava/dispatcher/tmp/38293/nbd-deploy-u6ninb76/nbdroot"}
- {"dt": "2024-12-11T12:15:34.096923", "lvl": "debug", "msg": "start: 5.1 power-off (timeout 00:00:30) [common]"}
- {"dt": "2024-12-11T12:15:34.097136", "lvl": "debug", "msg": "Calling: 'upower.sh' '--atx' 'off' '2'"}
- {"dt": "2024-12-11T12:15:35.125286", "lvl": "debug", "msg": ">> No GEMBIRD SiS-PM found. Check USB connections, please!\r"}
- {"dt": "2024-12-11T12:15:35.126830", "lvl": "debug", "msg": "Returned 0 in 1 seconds"}
- {"dt": "2024-12-11T12:15:35.227668", "lvl": "debug", "msg": "end: 5.1 power-off (duration 00:00:01) [common]"}
- {"dt": "2024-12-11T12:15:35.228247", "lvl": "results", "msg": {"case": "power-off", "definition": "lava", "duration": "1.13", "extra": {"status": "success"}, "level": "5.1", "namespace": "common", "result": "pass"}}
- {"dt": "2024-12-11T12:15:35.229019", "lvl": "debug", "msg": "start: 5.2 read-feedback (timeout 00:09:59) [common]"}
- {"dt": "2024-12-11T12:15:35.230004", "lvl": "debug", "msg": "Listened to connection for namespace 'common' for up to 1s"}
- {"dt": "2024-12-11T12:15:36.230940", "lvl": "info", "msg": "Finalising connection for namespace 'common'"}
- {"dt": "2024-12-11T12:15:36.231585", "lvl": "info", "msg": "Disconnecting from shell: Finalise"}
- {"dt": "2024-12-11T12:15:36.332697", "lvl": "debug", "msg": "end: 5.2 read-feedback (duration 00:00:01) [common]"}
- {"dt": "2024-12-11T12:15:36.333324", "lvl": "debug", "msg": "lava-xnbd cleanup"}
- {"dt": "2024-12-11T12:15:36.333659", "lvl": "debug", "msg": "clean NBD port 61999"}
- {"dt": "2024-12-11T12:15:36.445747", "lvl": "info", "msg": "Override tmp directory removed at /var/lib/lava/dispatcher/tmp/38293"}
- {"dt": "2024-12-11T12:15:36.451252", "lvl": "info", "msg": "Root tmp directory removed at /var/lib/lava/dispatcher/tmp/38293"}
- {"dt": "2024-12-11T12:15:36.451439", "lvl": "error", "msg": "JobError: Your job cannot terminate cleanly."}
- {"dt": "2024-12-11T12:15:36.451525", "lvl": "results", "msg": {"case": "job", "definition": "lava", "error_msg": "auto-login-action timed out after 545 seconds", "error_type": "Job", "result": "fail"}}
