lava-dispatcher, installed at version: 2023.10 start: 0 validate Start time: 2024-08-31 08:56:34.835907+00:00 (UTC) Validating that https://github.com/montjoie/lava-healthchecks-binary/blob/master/images/rootfs/buildroot/buildroot-baseline/20230623.0/riscv/rootfs.cpio.gz?raw=true exists Validating that https://github.com/montjoie/lava-healthchecks-binary/blob/master/stable/linux-6.1.y/v6.1.54/riscv/defconfig/gcc-10/kernel/Image?raw=true exists Validating that https://github.com/montjoie/lava-healthchecks-binary/blob/master/stable/linux-6.1.y/v6.1.54/riscv/defconfig/gcc-10/dtbs/sifive/hifive-unmatched-a00.dtb?raw=true exists Validating that https://github.com/montjoie/lava-healthchecks-binary/blob/master/stable/linux-6.1.y/v6.1.54/riscv/defconfig/gcc-10/modules.tar.xz?raw=true exists validate duration: 5.56 case: validate
case_id: 4039051
definition: lava
result: pass
start: 1 tftp-deploy (timeout 00:10:00) [common] start: 1.1 download-retry (timeout 00:10:00) [common] start: 1.1.1 http-download (timeout 00:10:00) [common] Not decompressing ramdisk as can be used compressed. downloading https://github.com/montjoie/lava-healthchecks-binary/blob/master/images/rootfs/buildroot/buildroot-baseline/20230623.0/riscv/rootfs.cpio.gz?raw=true saving as /var/lib/lava/dispatcher/tmp/36204/tftp-deploy-3pnphz2a/ramdisk/rootfs.cpio.gz total size: 7844224 (7 MB) progress 0 % (0 MB) progress 5 % (0 MB) progress 10 % (0 MB) progress 15 % (1 MB) progress 20 % (1 MB) progress 25 % (1 MB) progress 30 % (2 MB) progress 35 % (2 MB) progress 40 % (3 MB) progress 45 % (3 MB) progress 50 % (3 MB) progress 55 % (4 MB) progress 60 % (4 MB) progress 65 % (4 MB) progress 70 % (5 MB) progress 75 % (5 MB) progress 80 % (6 MB) progress 85 % (6 MB) progress 90 % (6 MB) progress 95 % (7 MB) progress 100 % (7 MB) 7 MB downloaded in 2.64 s (2.83 MB/s) end: 1.1.1 http-download (duration 00:00:03) [common] case: http-download
case_id: 4039073
definition: lava
duration: 2.64
extra: ...
level: 1.1.1
namespace: common
result: pass
end: 1.1 download-retry (duration 00:00:03) [common] start: 1.2 download-retry (timeout 00:09:57) [common] start: 1.2.1 http-download (timeout 00:09:57) [common] downloading https://github.com/montjoie/lava-healthchecks-binary/blob/master/stable/linux-6.1.y/v6.1.54/riscv/defconfig/gcc-10/kernel/Image?raw=true saving as /var/lib/lava/dispatcher/tmp/36204/tftp-deploy-3pnphz2a/kernel/Image total size: 19845120 (18 MB) No compression specified progress 0 % (0 MB) progress 5 % (0 MB) progress 10 % (1 MB) progress 15 % (2 MB) progress 20 % (3 MB) progress 25 % (4 MB) progress 30 % (5 MB) progress 35 % (6 MB) progress 40 % (7 MB) progress 45 % (8 MB) progress 50 % (9 MB) progress 55 % (10 MB) progress 60 % (11 MB) progress 65 % (12 MB) progress 70 % (13 MB) progress 75 % (14 MB) progress 80 % (15 MB) progress 85 % (16 MB) progress 90 % (17 MB) progress 95 % (18 MB) progress 100 % (18 MB) 18 MB downloaded in 3.54 s (5.34 MB/s) end: 1.2.1 http-download (duration 00:00:04) [common] case: http-download
case_id: 4039073
definition: lava
duration: 3.55
extra: ...
level: 1.2.1
namespace: common
result: pass
end: 1.2 download-retry (duration 00:00:04) [common] start: 1.3 download-retry (timeout 00:09:54) [common] start: 1.3.1 http-download (timeout 00:09:54) [common] downloading https://github.com/montjoie/lava-healthchecks-binary/blob/master/stable/linux-6.1.y/v6.1.54/riscv/defconfig/gcc-10/dtbs/sifive/hifive-unmatched-a00.dtb?raw=true saving as /var/lib/lava/dispatcher/tmp/36204/tftp-deploy-3pnphz2a/dtb/hifive-unmatched-a00.dtb total size: 10707 (0 MB) No compression specified progress 100 % (0 MB) 0 MB downloaded in 0.48 s (0.02 MB/s) end: 1.3.1 http-download (duration 00:00:00) [common] case: http-download
case_id: 4039073
definition: lava
duration: 0.49
extra: ...
level: 1.3.1
namespace: common
result: pass
end: 1.3 download-retry (duration 00:00:00) [common] start: 1.4 download-retry (timeout 00:09:53) [common] start: 1.4.1 http-download (timeout 00:09:53) [common] downloading https://github.com/montjoie/lava-healthchecks-binary/blob/master/stable/linux-6.1.y/v6.1.54/riscv/defconfig/gcc-10/modules.tar.xz?raw=true saving as /var/lib/lava/dispatcher/tmp/36204/tftp-deploy-3pnphz2a/modules/modules.tar total size: 3892756 (3 MB) Using unxz to decompress xz progress 0 % (0 MB) progress 5 % (0 MB) progress 10 % (0 MB) progress 15 % (0 MB) progress 20 % (0 MB) progress 25 % (0 MB) progress 30 % (1 MB) progress 35 % (1 MB) progress 40 % (1 MB) progress 45 % (1 MB) progress 50 % (1 MB) progress 55 % (2 MB) progress 60 % (2 MB) progress 65 % (2 MB) progress 70 % (2 MB) progress 75 % (2 MB) progress 80 % (3 MB) progress 85 % (3 MB) progress 90 % (3 MB) progress 95 % (3 MB) progress 100 % (3 MB) 3 MB downloaded in 2.26 s (1.64 MB/s) end: 1.4.1 http-download (duration 00:00:02) [common] case: http-download
case_id: 4039073
definition: lava
duration: 2.26
extra: ...
level: 1.4.1
namespace: common
result: pass
end: 1.4 download-retry (duration 00:00:02) [common] start: 1.5 prepare-tftp-overlay (timeout 00:09:51) [common] start: 1.5.1 extract-nfsrootfs (timeout 00:09:51) [common] end: 1.5.1 extract-nfsrootfs (duration 00:00:00) [common] start: 1.5.2 lava-overlay (timeout 00:09:51) [common] [common] Preparing overlay tarball in /var/lib/lava/dispatcher/tmp/36204/lava-overlay-3prkydl1 makedir: /var/lib/lava/dispatcher/tmp/36204/lava-overlay-3prkydl1/lava-36204/bin makedir: /var/lib/lava/dispatcher/tmp/36204/lava-overlay-3prkydl1/lava-36204/tests makedir: /var/lib/lava/dispatcher/tmp/36204/lava-overlay-3prkydl1/lava-36204/results Creating /var/lib/lava/dispatcher/tmp/36204/lava-overlay-3prkydl1/lava-36204/bin/lava-add-keys Creating /var/lib/lava/dispatcher/tmp/36204/lava-overlay-3prkydl1/lava-36204/bin/lava-add-sources Creating /var/lib/lava/dispatcher/tmp/36204/lava-overlay-3prkydl1/lava-36204/bin/lava-background-process-start Creating /var/lib/lava/dispatcher/tmp/36204/lava-overlay-3prkydl1/lava-36204/bin/lava-background-process-stop Creating /var/lib/lava/dispatcher/tmp/36204/lava-overlay-3prkydl1/lava-36204/bin/lava-common-functions Creating /var/lib/lava/dispatcher/tmp/36204/lava-overlay-3prkydl1/lava-36204/bin/lava-echo-ipv4 Creating /var/lib/lava/dispatcher/tmp/36204/lava-overlay-3prkydl1/lava-36204/bin/lava-install-packages Creating /var/lib/lava/dispatcher/tmp/36204/lava-overlay-3prkydl1/lava-36204/bin/lava-installed-packages Creating /var/lib/lava/dispatcher/tmp/36204/lava-overlay-3prkydl1/lava-36204/bin/lava-os-build Creating /var/lib/lava/dispatcher/tmp/36204/lava-overlay-3prkydl1/lava-36204/bin/lava-probe-channel Creating /var/lib/lava/dispatcher/tmp/36204/lava-overlay-3prkydl1/lava-36204/bin/lava-probe-ip Creating /var/lib/lava/dispatcher/tmp/36204/lava-overlay-3prkydl1/lava-36204/bin/lava-target-ip Creating /var/lib/lava/dispatcher/tmp/36204/lava-overlay-3prkydl1/lava-36204/bin/lava-target-mac Creating /var/lib/lava/dispatcher/tmp/36204/lava-overlay-3prkydl1/lava-36204/bin/lava-target-storage Creating /var/lib/lava/dispatcher/tmp/36204/lava-overlay-3prkydl1/lava-36204/bin/lava-test-case Creating /var/lib/lava/dispatcher/tmp/36204/lava-overlay-3prkydl1/lava-36204/bin/lava-test-event Creating /var/lib/lava/dispatcher/tmp/36204/lava-overlay-3prkydl1/lava-36204/bin/lava-test-feedback Creating /var/lib/lava/dispatcher/tmp/36204/lava-overlay-3prkydl1/lava-36204/bin/lava-test-raise Creating /var/lib/lava/dispatcher/tmp/36204/lava-overlay-3prkydl1/lava-36204/bin/lava-test-reference Creating /var/lib/lava/dispatcher/tmp/36204/lava-overlay-3prkydl1/lava-36204/bin/lava-test-runner Creating /var/lib/lava/dispatcher/tmp/36204/lava-overlay-3prkydl1/lava-36204/bin/lava-test-set Creating /var/lib/lava/dispatcher/tmp/36204/lava-overlay-3prkydl1/lava-36204/bin/lava-test-shell Updating /var/lib/lava/dispatcher/tmp/36204/lava-overlay-3prkydl1/lava-36204/bin/lava-install-packages (oe) Updating /var/lib/lava/dispatcher/tmp/36204/lava-overlay-3prkydl1/lava-36204/bin/lava-installed-packages (oe) Creating /var/lib/lava/dispatcher/tmp/36204/lava-overlay-3prkydl1/lava-36204/environment LAVA metadata - LAVA_JOB_ID=36204 - LAVA_DISPATCHER_IP=192.168.66.1 start: 1.5.2.1 ssh-authorize (timeout 00:09:51) [common] end: 1.5.2.1 ssh-authorize (duration 00:00:00) [common] start: 1.5.2.2 lava-vland-overlay (timeout 00:09:51) [common] skipped lava-vland-overlay end: 1.5.2.2 lava-vland-overlay (duration 00:00:00) [common] start: 1.5.2.3 lava-multinode-overlay (timeout 00:09:51) [common] skipped lava-multinode-overlay end: 1.5.2.3 lava-multinode-overlay (duration 00:00:00) [common] start: 1.5.2.4 test-definition (timeout 00:09:51) [common] Loading test definitions start: 1.5.2.4.1 inline-repo-action (timeout 00:09:51) [common] Using /lava-36204 at stage 0 uuid=36204_1.5.2.4.1 testdef=None end: 1.5.2.4.1 inline-repo-action (duration 00:00:00) [common] start: 1.5.2.4.2 test-overlay (timeout 00:09:51) [common] end: 1.5.2.4.2 test-overlay (duration 00:00:00) [common] case: test-overlay
case_id: 4039077
definition: lava
duration: 0.01
extra: ...
level: 1.5.2.4.2
namespace: common
result: pass
start: 1.5.2.4.3 test-install-overlay (timeout 00:09:51) [common] end: 1.5.2.4.3 test-install-overlay (duration 00:00:00) [common] case: test-install-overlay
case_id: 4039078
definition: lava
duration: 0.01
extra: ...
level: 1.5.2.4.3
namespace: common
result: pass
start: 1.5.2.4.4 test-runscript-overlay (timeout 00:09:51) [common] runner path: /var/lib/lava/dispatcher/tmp/36204/lava-overlay-3prkydl1/lava-36204/0/tests/0_dmesg test_uuid 36204_1.5.2.4.1 end: 1.5.2.4.4 test-runscript-overlay (duration 00:00:00) [common] case: test-runscript-overlay
case_id: 4039079
definition: lava
duration: 0.01
extra: ...
level: 1.5.2.4.4
namespace: common
result: pass
start: 1.5.2.4.5 inline-repo-action (timeout 00:09:51) [common] Using /lava-36204 at stage 1 uuid=36204_1.5.2.4.5 testdef=None end: 1.5.2.4.5 inline-repo-action (duration 00:00:00) [common] start: 1.5.2.4.6 test-overlay (timeout 00:09:51) [common] end: 1.5.2.4.6 test-overlay (duration 00:00:00) [common] case: test-overlay
case_id: 4039077
definition: lava
duration: 0.01
extra: ...
level: 1.5.2.4.6
namespace: common
result: pass
start: 1.5.2.4.7 test-install-overlay (timeout 00:09:51) [common] end: 1.5.2.4.7 test-install-overlay (duration 00:00:00) [common] case: test-install-overlay
case_id: 4039078
definition: lava
duration: 0.01
extra: ...
level: 1.5.2.4.7
namespace: common
result: pass
start: 1.5.2.4.8 test-runscript-overlay (timeout 00:09:51) [common] runner path: /var/lib/lava/dispatcher/tmp/36204/lava-overlay-3prkydl1/lava-36204/1/tests/1_bootrr test_uuid 36204_1.5.2.4.5 end: 1.5.2.4.8 test-runscript-overlay (duration 00:00:00) [common] case: test-runscript-overlay
case_id: 4039079
definition: lava
duration: 0.02
extra: ...
level: 1.5.2.4.8
namespace: common
result: pass
Creating lava-test-runner.conf files Using lava-test-runner path: /var/lib/lava/dispatcher/tmp/36204/lava-overlay-3prkydl1/lava-36204/0 for stage 0 - 0_dmesg Using lava-test-runner path: /var/lib/lava/dispatcher/tmp/36204/lava-overlay-3prkydl1/lava-36204/1 for stage 1 - 1_bootrr end: 1.5.2.4 test-definition (duration 00:00:00) [common] start: 1.5.2.5 compress-overlay (timeout 00:09:51) [common] end: 1.5.2.5 compress-overlay (duration 00:00:00) [common] start: 1.5.2.6 persistent-nfs-overlay (timeout 00:09:51) [common] end: 1.5.2.6 persistent-nfs-overlay (duration 00:00:00) [common] end: 1.5.2 lava-overlay (duration 00:00:00) [common] start: 1.5.3 extract-overlay-ramdisk (timeout 00:09:51) [common] end: 1.5.3 extract-overlay-ramdisk (duration 00:00:03) [common] start: 1.5.4 extract-modules (timeout 00:09:48) [common] extracting modules file /var/lib/lava/dispatcher/tmp/36204/tftp-deploy-3pnphz2a/modules/modules.tar to /var/lib/lava/dispatcher/tmp/36204/extract-overlay-ramdisk-hytg3pt1/ramdisk end: 1.5.4 extract-modules (duration 00:00:01) [common] start: 1.5.5 apply-overlay-tftp (timeout 00:09:47) [common] [common] Applying overlay /var/lib/lava/dispatcher/tmp/36204/compress-overlay-nqx28c6_/overlay-1.5.2.5.tar.gz to ramdisk [common] Applying overlay /var/lib/lava/dispatcher/tmp/36204/compress-overlay-nqx28c6_/overlay-1.5.2.5.tar.gz to directory /var/lib/lava/dispatcher/tmp/36204/extract-overlay-ramdisk-hytg3pt1/ramdisk end: 1.5.5 apply-overlay-tftp (duration 00:00:00) [common] start: 1.5.6 prepare-kernel (timeout 00:09:47) [common] start: 1.5.6.1 uboot-prepare-kernel (timeout 00:09:47) [common] end: 1.5.6.1 uboot-prepare-kernel (duration 00:00:00) [common] end: 1.5.6 prepare-kernel (duration 00:00:00) [common] start: 1.5.7 configure-preseed-file (timeout 00:09:47) [common] end: 1.5.7 configure-preseed-file (duration 00:00:00) [common] start: 1.5.8 compress-ramdisk (timeout 00:09:47) [common] Building ramdisk /var/lib/lava/dispatcher/tmp/36204/extract-overlay-ramdisk-hytg3pt1/ramdisk.cpio containing /var/lib/lava/dispatcher/tmp/36204/extract-overlay-ramdisk-hytg3pt1/ramdisk >> 86851 blocks Adding RAMdisk u-boot header. mkimage -A riscv -T ramdisk -C none -d /var/lib/lava/dispatcher/tmp/36204/extract-overlay-ramdisk-hytg3pt1/ramdisk.cpio.gz /var/lib/lava/dispatcher/tmp/36204/extract-overlay-ramdisk-hytg3pt1/ramdisk.cpio.gz.uboot output: Image Name: output: Created: Sat Aug 31 08:57:01 2024 output: Image Type: RISC-V Linux RAMDisk Image (uncompressed) output: Data Size: 13644227 Bytes = 13324.44 KiB = 13.01 MiB output: Load Address: 00000000 output: Entry Point: 00000000 output: rename /var/lib/lava/dispatcher/tmp/36204/extract-overlay-ramdisk-hytg3pt1/ramdisk.cpio.gz.uboot to /var/lib/lava/dispatcher/tmp/36204/tftp-deploy-3pnphz2a/ramdisk/ramdisk.cpio.gz.uboot end: 1.5.8 compress-ramdisk (duration 00:00:09) [common] end: 1.5 prepare-tftp-overlay (duration 00:00:13) [common] start: 1.6 lxc-create-udev-rule-action (timeout 00:09:38) [common] No LXC device requested end: 1.6 lxc-create-udev-rule-action (duration 00:00:00) [common] start: 1.7 deploy-device-env (timeout 00:09:38) [common] end: 1.7 deploy-device-env (duration 00:00:00) [common] Checking files for TFTP limit of 4294967296 bytes. end: 1 tftp-deploy (duration 00:00:22) [common] start: 2 uboot-action (timeout 00:05:00) [common] start: 2.1 uboot-from-media (timeout 00:05:00) [common] end: 2.1 uboot-from-media (duration 00:00:00) [common] start: 2.2 bootloader-overlay (timeout 00:05:00) [common] substitutions: - {BOOTX}: booti 0x80200000 0x83500000 0x83000000 - {DTB_ADDR}: 0x83000000 - {DTB}: 36204/tftp-deploy-3pnphz2a/dtb/hifive-unmatched-a00.dtb - {INITRD}: 36204/tftp-deploy-3pnphz2a/ramdisk/ramdisk.cpio.gz.uboot - {KERNEL_ADDR}: 0x80200000 - {KERNEL}: 36204/tftp-deploy-3pnphz2a/kernel/Image - {LAVA_MAC}: None - {PRESEED_CONFIG}: None - {PRESEED_LOCAL}: None - {RAMDISK_ADDR}: 0x83500000 - {RAMDISK}: 36204/tftp-deploy-3pnphz2a/ramdisk/ramdisk.cpio.gz.uboot - {ROOT_PART}: None - {ROOT}: None - {SERVER_IP}: 192.168.66.1 - {TEE_ADDR}: 0x83000000 - {TEE}: None Parsed boot commands: - setenv autoload no - setenv initrd_high 0xffffffffffffffff - setenv fdt_high 0xffffffffffffffff - dhcp - setenv serverip 192.168.66.1 - tftp 0x80200000 36204/tftp-deploy-3pnphz2a/kernel/Image - tftp 0x83500000 36204/tftp-deploy-3pnphz2a/ramdisk/ramdisk.cpio.gz.uboot - setenv initrd_size ${filesize} - tftp 0x83000000 36204/tftp-deploy-3pnphz2a/dtb/hifive-unmatched-a00.dtb - setenv bootargs '115200 root=/dev/ram0 console_msg_format=syslog earlycon deferred_probe_timeout=60 ip=dhcp' - booti 0x80200000 0x83500000 0x83000000 end: 2.2 bootloader-overlay (duration 00:00:00) [common] case: bootloader-overlay
case_id: 4039088
definition: lava
duration: 0.01
extra: ...
level: 2.2
namespace: common
result: pass
start: 2.3 connect-device (timeout 00:05:00) [common] [common] connect-device Connecting to device using 'telnet 127.0.0.1 63006' Setting prompt string to ['lava-test: # '] end: 2.3 connect-device (duration 00:00:05) [common] start: 2.4 uboot-commands (timeout 00:04:55) [common] start: 2.4.1 reset-device (timeout 00:04:55) [common] start: 2.4.1.1 pdu-reboot (timeout 00:04:55) [common] Calling: 'upower.sh' '--atx' 'reset' '1' >> Accessing Gembird #0 USB device 016 >> Switched outlet 1 off >> Accessing Gembird #0 USB device 016 >> Switched outlet 1 on >> FTDI RELAY: power on >> FTDI RELAY: power off Returned 0 in 11 seconds end: 2.4.1.1 pdu-reboot (duration 00:00:12) [common] case: pdu-reboot
case_id: 4039092
definition: lava
duration: 12.05
extra: ...
level: 2.4.1.1
namespace: common
result: pass
end: 2.4.1 reset-device (duration 00:00:12) [common] start: 2.4.2 bootloader-interrupt (timeout 00:04:43) [common] Setting prompt string to ['Hit any key to stop autoboot'] bootloader-interrupt: Wait for prompt ['Hit any key to stop autoboot'] (timeout 00:05:00) Trying 127.0.0.1... Connected to 127.0.0.1. Escape character is '^]'. bootloader-interrupt timed out after 283 seconds end: 2.4.2 bootloader-interrupt (duration 00:04:43) [common] case: bootloader-interrupt
case_id: 4039115
definition: lava
duration: 283.00
extra: ...
level: 2.4.2
namespace: common
result: fail
bootloader-interrupt timed out after 283 seconds end: 2.4 uboot-commands (duration 00:04:55) [common] case: uboot-commands
case_id: 4039116
definition: lava
duration: 295.07
extra: ...
level: 2.4
namespace: common
result: fail
uboot-action failed: 1 of 1 attempts. 'bootloader-interrupt timed out after 283 seconds' bootloader-interrupt timed out after 283 seconds end: 2 uboot-action (duration 00:05:00) [common] case: uboot-action
case_id: 4039117
definition: lava
duration: 299.93
extra: ...
level: 2
namespace: common
result: fail
Cleaning after the job Cleaning up download directory: /var/lib/lava/dispatcher/tmp/36204/tftp-deploy-3pnphz2a/ramdisk Cleaning up download directory: /var/lib/lava/dispatcher/tmp/36204/tftp-deploy-3pnphz2a/kernel Cleaning up download directory: /var/lib/lava/dispatcher/tmp/36204/tftp-deploy-3pnphz2a/dtb Cleaning up download directory: /var/lib/lava/dispatcher/tmp/36204/tftp-deploy-3pnphz2a/modules start: 5.1 power-off (timeout 00:00:30) [common] Calling: 'upower.sh' '--atx' 'off' '1' >> Accessing Gembird #0 USB device 016 >> Switched outlet 1 off Returned 0 in 3 seconds end: 5.1 power-off (duration 00:00:04) [common] case: power-off
case_id: 4039118
definition: lava
duration: 3.84
extra: ...
level: 5.1
namespace: common
result: pass
start: 5.2 read-feedback (timeout 00:09:56) [common] Listened to connection for namespace 'common' for up to 1s Finalising connection for namespace 'common' Disconnecting from shell: Finalise end: 5.2 read-feedback (duration 00:00:01) [common] Override tmp directory removed at /var/lib/lava/dispatcher/tmp/36204 Root tmp directory removed at /var/lib/lava/dispatcher/tmp/36204 InfrastructureError: The Infrastructure is not working correctly. Please report this error to LAVA admins. case: job
case_id: 4039119
definition: lava
error_msg: bootloader-interrupt timed out after 283 seconds
error_type: Infrastructure
result: fail