Action timeout is larger than job timeout @ data['actions']['1']
Canceled error: The job was canceled
Action timeout for connect-device exceeds Job timeout
Action timeout for pdu-reboot exceeds Job timeout
Action timeout for reset-device exceeds Job timeout
Action timeout for login-action exceeds Job timeout
Action timeout for auto-login-action exceeds Job timeout
Action timeout for expect-shell-connection exceeds Job timeout
Action timeout for overlay-unpack exceeds Job timeout
Action timeout for export-device-env exceeds Job timeout
Action timeout for minimal-boot exceeds Job timeout
lava-dispatcher, installed at version: 2023.10
start: 0 validate
Start time: 2024-11-21 10:54:58.837643+00:00 (UTC)
Validating that http://download.automotivelinux.org/AGL/release/ricefish/18.0.2/raspberrypi5/deploy/images/raspberrypi5/initramfs-netboot-image-raspberrypi5-20241028040434.ext4.gz exists
Validating that http://download.automotivelinux.org/AGL/release/ricefish/18.0.2/raspberrypi5/deploy/images/raspberrypi5/Image exists
Validating that http://download.automotivelinux.org/AGL/release/ricefish/18.0.2/raspberrypi5/deploy/images/raspberrypi5/bcm2712-rpi-5-b.dtb exists
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
validate duration: 0.96
case: validate
case_id: 4089087
definition: lava
result: pass
start: 1 nbd-deploy (timeout 00:10:00) [common]
Making protocol call for nbd-deploy using lava-xnbd
[nbd-deploy] Checking protocol data for lava-xnbd
Get a port from pool
Set_port 61991
start: 1.1 download-retry (timeout 00:10:00) [common]
start: 1.1.1 http-download (timeout 00:10:00) [common]
downloading http://download.automotivelinux.org/AGL/release/ricefish/18.0.2/raspberrypi5/deploy/images/raspberrypi5/initramfs-netboot-image-raspberrypi5-20241028040434.ext4.gz
saving as /var/lib/lava/dispatcher/tmp/37653/nbd-deploy-5s6de01_/initrd/initramfs-netboot-image-raspberrypi5-20241028040434.ext4
total size: 2153804 (2 MB)
Using gunzip to decompress gz
progress 1 % (0 MB)
progress 6 % (0 MB)
progress 12 % (0 MB)
progress 18 % (0 MB)
progress 24 % (0 MB)
progress 30 % (0 MB)
progress 36 % (0 MB)
progress 41 % (0 MB)
progress 47 % (0 MB)
progress 53 % (1 MB)
progress 59 % (1 MB)
progress 65 % (1 MB)
progress 71 % (1 MB)
progress 76 % (1 MB)
progress 82 % (1 MB)
progress 88 % (1 MB)
progress 94 % (1 MB)
progress 100 % (2 MB)
2 MB downloaded in 0.94 s (2.19 MB/s)
end: 1.1.1 http-download (duration 00:00:01) [common]
case: http-download
case_id: 4089091
definition: lava
duration: 0.94
extra: ...
level: 1.1.1
namespace: common
result: pass
end: 1.1 download-retry (duration 00:00:01) [common]
start: 1.2 download-retry (timeout 00:09:59) [common]
start: 1.2.1 http-download (timeout 00:09:59) [common]
downloading http://download.automotivelinux.org/AGL/release/ricefish/18.0.2/raspberrypi5/deploy/images/raspberrypi5/Image
saving as /var/lib/lava/dispatcher/tmp/37653/nbd-deploy-5s6de01_/kernel/Image
total size: 28887552 (27 MB)
No compression specified
progress 0 % (0 MB)
progress 5 % (1 MB)
progress 10 % (2 MB)
progress 15 % (4 MB)
progress 20 % (5 MB)
progress 25 % (6 MB)
progress 30 % (8 MB)
progress 35 % (9 MB)
progress 40 % (11 MB)
progress 45 % (12 MB)
progress 50 % (13 MB)
progress 55 % (15 MB)
progress 60 % (16 MB)
progress 65 % (17 MB)
progress 70 % (19 MB)
progress 75 % (20 MB)
progress 80 % (22 MB)
progress 85 % (23 MB)
progress 90 % (24 MB)
progress 95 % (26 MB)
progress 100 % (27 MB)
27 MB downloaded in 2.82 s (9.76 MB/s)
end: 1.2.1 http-download (duration 00:00:03) [common]
case: http-download
case_id: 4089091
definition: lava
duration: 2.82
extra: ...
level: 1.2.1
namespace: common
result: pass
end: 1.2 download-retry (duration 00:00:03) [common]
start: 1.3 download-retry (timeout 00:09:56) [common]
start: 1.3.1 http-download (timeout 00:09:56) [common]
downloading http://download.automotivelinux.org/AGL/release/ricefish/18.0.2/raspberrypi5/deploy/images/raspberrypi5/bcm2712-rpi-5-b.dtb
saving as /var/lib/lava/dispatcher/tmp/37653/nbd-deploy-5s6de01_/dtb/bcm2712-rpi-5-b.dtb
total size: 78059 (0 MB)
No compression specified
progress 41 % (0 MB)
progress 83 % (0 MB)
progress 100 % (0 MB)
0 MB downloaded in 0.40 s (0.19 MB/s)
end: 1.3.1 http-download (duration 00:00:00) [common]
case: http-download
case_id: 4089091
definition: lava
duration: 0.40
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:56) [common]
start: 1.4.1 http-download (timeout 00:09:56) [common]
downloading http://download.automotivelinux.org/AGL/release/ricefish/18.0.2/raspberrypi5/deploy/images/raspberrypi5/agl-ivi-demo-qt-raspberrypi5-20241028040434.ext4.xz
saving as /var/lib/lava/dispatcher/tmp/37653/nbd-deploy-5s6de01_/nbdroot/agl-ivi-demo-qt-raspberrypi5-20241028040434.ext4
total size: 493866112 (470 MB)
Using unxz to decompress xz
progress 0 % (0 MB)
progress 5 % (23 MB)
progress 10 % (47 MB)
progress 15 % (70 MB)
progress 20 % (94 MB)
progress 25 % (117 MB)
progress 30 % (141 MB)
progress 35 % (164 MB)
progress 40 % (188 MB)
progress 45 % (211 MB)
progress 50 % (235 MB)
progress 55 % (259 MB)
progress 60 % (282 MB)
progress 65 % (306 MB)
progress 70 % (329 MB)
progress 75 % (353 MB)
progress 80 % (376 MB)
progress 85 % (400 MB)
progress 90 % (423 MB)
progress 95 % (447 MB)
progress 100 % (470 MB)
470 MB downloaded in 74.36 s (6.33 MB/s)
end: 1.4.1 http-download (duration 00:01:14) [common]
case: http-download
case_id: 4089091
definition: lava
duration: 74.36
extra: ...
level: 1.4.1
namespace: common
result: pass
end: 1.4 download-retry (duration 00:01:14) [common]
start: 1.5 lava-overlay (timeout 00:08:41) [common]
[common] Preparing overlay tarball in /var/lib/lava/dispatcher/tmp/37653/lava-overlay-9k0ct2mn
makedir: /var/lib/lava/dispatcher/tmp/37653/lava-overlay-9k0ct2mn/lava-37653/bin
makedir: /var/lib/lava/dispatcher/tmp/37653/lava-overlay-9k0ct2mn/lava-37653/tests
makedir: /var/lib/lava/dispatcher/tmp/37653/lava-overlay-9k0ct2mn/lava-37653/results
Creating /var/lib/lava/dispatcher/tmp/37653/lava-overlay-9k0ct2mn/lava-37653/bin/lava-add-keys
Creating /var/lib/lava/dispatcher/tmp/37653/lava-overlay-9k0ct2mn/lava-37653/bin/lava-add-sources
Creating /var/lib/lava/dispatcher/tmp/37653/lava-overlay-9k0ct2mn/lava-37653/bin/lava-background-process-start
Creating /var/lib/lava/dispatcher/tmp/37653/lava-overlay-9k0ct2mn/lava-37653/bin/lava-background-process-stop
Creating /var/lib/lava/dispatcher/tmp/37653/lava-overlay-9k0ct2mn/lava-37653/bin/lava-common-functions
Creating /var/lib/lava/dispatcher/tmp/37653/lava-overlay-9k0ct2mn/lava-37653/bin/lava-echo-ipv4
Creating /var/lib/lava/dispatcher/tmp/37653/lava-overlay-9k0ct2mn/lava-37653/bin/lava-install-packages
Creating /var/lib/lava/dispatcher/tmp/37653/lava-overlay-9k0ct2mn/lava-37653/bin/lava-installed-packages
Creating /var/lib/lava/dispatcher/tmp/37653/lava-overlay-9k0ct2mn/lava-37653/bin/lava-os-build
Creating /var/lib/lava/dispatcher/tmp/37653/lava-overlay-9k0ct2mn/lava-37653/bin/lava-probe-channel
Creating /var/lib/lava/dispatcher/tmp/37653/lava-overlay-9k0ct2mn/lava-37653/bin/lava-probe-ip
Creating /var/lib/lava/dispatcher/tmp/37653/lava-overlay-9k0ct2mn/lava-37653/bin/lava-target-ip
Creating /var/lib/lava/dispatcher/tmp/37653/lava-overlay-9k0ct2mn/lava-37653/bin/lava-target-mac
Creating /var/lib/lava/dispatcher/tmp/37653/lava-overlay-9k0ct2mn/lava-37653/bin/lava-target-storage
Creating /var/lib/lava/dispatcher/tmp/37653/lava-overlay-9k0ct2mn/lava-37653/bin/lava-test-case
Creating /var/lib/lava/dispatcher/tmp/37653/lava-overlay-9k0ct2mn/lava-37653/bin/lava-test-event
Creating /var/lib/lava/dispatcher/tmp/37653/lava-overlay-9k0ct2mn/lava-37653/bin/lava-test-feedback
Creating /var/lib/lava/dispatcher/tmp/37653/lava-overlay-9k0ct2mn/lava-37653/bin/lava-test-raise
Creating /var/lib/lava/dispatcher/tmp/37653/lava-overlay-9k0ct2mn/lava-37653/bin/lava-test-reference
Creating /var/lib/lava/dispatcher/tmp/37653/lava-overlay-9k0ct2mn/lava-37653/bin/lava-test-runner
Creating /var/lib/lava/dispatcher/tmp/37653/lava-overlay-9k0ct2mn/lava-37653/bin/lava-test-set
Creating /var/lib/lava/dispatcher/tmp/37653/lava-overlay-9k0ct2mn/lava-37653/bin/lava-test-shell
Updating /var/lib/lava/dispatcher/tmp/37653/lava-overlay-9k0ct2mn/lava-37653/bin/lava-install-packages (oe)
Updating /var/lib/lava/dispatcher/tmp/37653/lava-overlay-9k0ct2mn/lava-37653/bin/lava-installed-packages (oe)
Creating /var/lib/lava/dispatcher/tmp/37653/lava-overlay-9k0ct2mn/lava-37653/environment
LAVA metadata
- LAVA_JOB_ID=37653
- LAVA_DISPATCHER_IP=192.168.66.1
start: 1.5.1 ssh-authorize (timeout 00:08:41) [common]
end: 1.5.1 ssh-authorize (duration 00:00:00) [common]
start: 1.5.2 lava-vland-overlay (timeout 00:08:41) [common]
skipped lava-vland-overlay
end: 1.5.2 lava-vland-overlay (duration 00:00:00) [common]
start: 1.5.3 lava-multinode-overlay (timeout 00:08:41) [common]
skipped lava-multinode-overlay
end: 1.5.3 lava-multinode-overlay (duration 00:00:00) [common]
start: 1.5.4 test-definition (timeout 00:08:41) [common]
Loading test definitions
start: 1.5.4.1 inline-repo-action (timeout 00:08:41) [common]
Using /lava-37653 at stage 0
uuid=37653_1.5.4.1 testdef=None
end: 1.5.4.1 inline-repo-action (duration 00:00:00) [common]
start: 1.5.4.2 test-overlay (timeout 00:08:41) [common]
end: 1.5.4.2 test-overlay (duration 00:00:00) [common]
case: test-overlay
case_id: 4089095
definition: lava
duration: 0.00
extra: ...
level: 1.5.4.2
namespace: common
result: pass
start: 1.5.4.3 test-install-overlay (timeout 00:08:41) [common]
end: 1.5.4.3 test-install-overlay (duration 00:00:00) [common]
case: test-install-overlay
case_id: 4089096
definition: lava
duration: 0.02
extra: ...
level: 1.5.4.3
namespace: common
result: pass
start: 1.5.4.4 test-runscript-overlay (timeout 00:08:41) [common]
runner path: /var/lib/lava/dispatcher/tmp/37653/lava-overlay-9k0ct2mn/lava-37653/0/tests/0_dmesg test_uuid 37653_1.5.4.1
end: 1.5.4.4 test-runscript-overlay (duration 00:00:00) [common]
case: test-runscript-overlay
case_id: 4089097
definition: lava
duration: 0.02
extra: ...
level: 1.5.4.4
namespace: common
result: pass
start: 1.5.4.5 inline-repo-action (timeout 00:08:41) [common]
Using /lava-37653 at stage 1
uuid=37653_1.5.4.5 testdef=None
end: 1.5.4.5 inline-repo-action (duration 00:00:00) [common]
start: 1.5.4.6 test-overlay (timeout 00:08:41) [common]
end: 1.5.4.6 test-overlay (duration 00:00:00) [common]
case: test-overlay
case_id: 4089095
definition: lava
duration: 0.00
extra: ...
level: 1.5.4.6
namespace: common
result: pass
start: 1.5.4.7 test-install-overlay (timeout 00:08:41) [common]
end: 1.5.4.7 test-install-overlay (duration 00:00:00) [common]
case: test-install-overlay
case_id: 4089096
definition: lava
duration: 0.03
extra: ...
level: 1.5.4.7
namespace: common
result: pass
start: 1.5.4.8 test-runscript-overlay (timeout 00:08:41) [common]
runner path: /var/lib/lava/dispatcher/tmp/37653/lava-overlay-9k0ct2mn/lava-37653/1/tests/1_bootrr test_uuid 37653_1.5.4.5
end: 1.5.4.8 test-runscript-overlay (duration 00:00:00) [common]
case: test-runscript-overlay
case_id: 4089097
definition: lava
duration: 0.03
extra: ...
level: 1.5.4.8
namespace: common
result: pass
Creating lava-test-runner.conf files
Using lava-test-runner path: /var/lib/lava/dispatcher/tmp/37653/lava-overlay-9k0ct2mn/lava-37653/0 for stage 0
- 0_dmesg
Using lava-test-runner path: /var/lib/lava/dispatcher/tmp/37653/lava-overlay-9k0ct2mn/lava-37653/1 for stage 1
- 1_bootrr
end: 1.5.4 test-definition (duration 00:00:00) [common]
start: 1.5.5 compress-overlay (timeout 00:08:41) [common]
end: 1.5.5 compress-overlay (duration 00:00:00) [common]
start: 1.5.6 persistent-nfs-overlay (timeout 00:08:41) [common]
end: 1.5.6 persistent-nfs-overlay (duration 00:00:00) [common]
end: 1.5 lava-overlay (duration 00:00:00) [common]
start: 1.6 prepare-kernel (timeout 00:08:41) [common]
start: 1.6.1 uboot-prepare-kernel (timeout 00:08:41) [common]
end: 1.6.1 uboot-prepare-kernel (duration 00:00:00) [common]
end: 1.6 prepare-kernel (duration 00:00:00) [common]
start: 1.7 xnbd-server-deploy (timeout 00:08:41) [common]
xnbd-server-deploy: starting nbd-server
NBD-IP: 192.168.66.1, NBD-PORT: 61991, NBD-ROOT: 37653/nbd-deploy-5s6de01_/nbdroot/agl-ivi-demo-qt-raspberrypi5-20241028040434.ext4
nbd-server 61991 /var/lib/lava/dispatcher/tmp/37653/nbd-deploy-5s6de01_/nbdroot/agl-ivi-demo-qt-raspberrypi5-20241028040434.ext4
output:
output: ** (process:492): WARNING **: 10:56:18.480: Specifying an export on the command line no longer uses the oldstyle protocol.
output:
xnbd-server-deploy: starting nbd-server done
end: 1.7 xnbd-server-deploy (duration 00:00:00) [common]
end: 1 nbd-deploy (duration 00:01:19) [common]
start: 2 minimal-boot (timeout 00:08:41) [common]
start: 2.1 connect-device (timeout 00:08:41) [common]
[common] connect-device Connecting to device using 'telnet 127.0.0.1 63007'
Setting prompt string to ['lava-test: # ']
end: 2.1 connect-device (duration 00:00:00) [common]
start: 2.2 reset-device (timeout 00:08:41) [common]
start: 2.2.1 pdu-reboot (timeout 00:08:41) [common]
Calling: 'upower.sh' '--atx' 'reset' '2'
>> Accessing Gembird #0 USB device 002
>> Switched outlet 2 off
>> Accessing Gembird #0 USB device 002
>> Switched outlet 2 on
>> export LANG='C'
>> export LC_ALL='C.UTF-8'
>> export PATH='/usr/local/bin:/usr/local/sbin:/bin:/usr/bin:/usr/sbin:/sbin'
>> export PWD='/'
>> DEBUG: found /var/lib/lava/dispatcher/tmp/bcm2712-rpi-5-b.dtb
>> DEBUG: BASETFTP=/var/lib/lava/dispatcher/tmp
>> DEBUG: INITRD=/var/lib/lava/dispatcher/tmp/initramfs-netboot-image-raspberrypi5-20241028040434.ext4
>> /var/lib/lava/dispatcher/tmp/37653/nbd-deploy-5s6de01_/initrd/initramfs-netboot-image-raspberrypi5-20241028040434.ext4
>> DEBUG: REL_INITRD=initramfs-netboot-image-raspberrypi5-20241028040434.ext4 /var/lib/lava/dispatcher/tmp/37653/nbd-deploy-5s6de01_/initrd/initramfs-netboot-image-raspberrypi5-20241028040434.ext4
>> DEBUG: IMAGE=/var/lib/lava/dispatcher/tmp/37653/nbd-deploy-5s6de01_/kernel/Image
>> DEBUG: REL_IMAGE=37653/nbd-deploy-5s6de01_/kernel/Image
>> 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
>> DEBUG: check LISTEN 0 10 0.0.0.0:61991 0.0.0.0:* users:(("nbd-server",pid=493,fd=3))
>> DEBUG: PID=493
>> NBDPORT=61991
>>
>> enable_uart=1
>> kernel 37653/nbd-deploy-5s6de01_/kernel/Image
>> initramfs initramfs-netboot-image-raspberrypi5-20241028040434.ext4
>>
>> 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
>> DEBUG: found /var/lib/lava/dispatcher/tmp/37653/nbd-deploy-5s6de01_/dtb/bcm2712-rpi-5-b.dtb
>> DEBUG: BASETFTP=/var/lib/lava/dispatcher/tmp/37653/nbd-deploy-5s6de01_
>> DEBUG: INITRD=/var/lib/lava/dispatcher/tmp/37653/nbd-deploy-5s6de01_/initrd/initramfs-netboot-image-raspberrypi5-20241028040434.ext4
>> DEBUG: REL_INITRD=37653/nbd-deploy-5s6de01_/initrd/initramfs-netboot-image-raspberrypi5-20241028040434.ext4
>> DEBUG: IMAGE=/var/lib/lava/dispatcher/tmp/37653/nbd-deploy-5s6de01_/kernel/Image
>> DEBUG: REL_IMAGE=37653/nbd-deploy-5s6de01_/kernel/Image
>> DEBUG: check LISTEN 0 10 0.0.0.0:61991 0.0.0.0:* users:(("nbd-server",pid=493,fd=3))
>> DEBUG: PID=493
>> NBDPORT=61991
>>
>> enable_uart=1
>> kernel 37653/nbd-deploy-5s6de01_/kernel/Image
>> initramfs initramfs-netboot-image-raspberrypi5-20241028040434.ext4
>>
Returned 0 in 7 seconds
end: 2.2.1 pdu-reboot (duration 00:00:07) [common]
case: pdu-reboot
case_id: 4089098
definition: lava
duration: 7.38
extra: ...
level: 2.2.1
namespace: common
result: pass
end: 2.2 reset-device (duration 00:00:07) [common]
start: 2.3 auto-login-action (timeout 00:08:34) [common]
Setting prompt string to ['Linux version [0-9]']
auto-login-action: Wait for prompt ['Linux version [0-9]'] (timeout 00:20:00)
Trying 127.0.0.1...
Connected to 127.0.0.1.
Escape character is '^]'.
RPi: BOOTSYS release VERSION:5f2f71fa DATE: 2023/09/25 TIME: 11:44:03
BOOTMODE: 0x06 partition 0 build-ts BUILD_TIMESTAMP=1695638643 serial a18d1bdb boardrev d04170 stc 1605773
AON_RESET: 00000003 PM_RSTS 00001000
RP1_BOOT chip ID: 0x20001927
PM_RSTS: 0x00001000
part 00000000 reset_info 00000000
PMIC reset-event 00000000 rtc 00000001 alarm 00000000 enabled 0
uSD voltage 3.3V
Initialising SDRAM 'Micron' 32Gb x2 total-size: 64 Gbit 4267
DDR 4267 1 0 64 152
RP1_BOOT chip ID: 0x20001927
RP1_BOOT chip ID: 0x20001927
RP1_BOOT: fw size 25968
PCI2 init
PCI2 reset
PCIe scan 00001de4:00000001
RP1_CHIP_INFO 20001927
RPi: BOOTLOADER release VERSION:5f2f71fa DATE: 2023/09/25 TIME: 11:44:03
BOOTMODE: 0x06 partition 0 build-ts BUILD_TIMESTAMP=1695638643 serial a18d1bdb boardrev d04170 stc 4583163
AON_RESET: 00000003 PM_RSTS 00001000
status
USB_PD CONFIG 0 41
Boot mode: SD (01) order 24
SD HOST: 200000000 CTL0: 0x00800f00 BUS: 400000 Hz actual: 390625 HZ div: 512 (256) status: 0x1fff0000 delay: 276
SD HOST: 200000000 CTL0: 0x00800f00 BUS: 400000 Hz actual: 390625 HZ div: 512 (256) status: 0x1fff0000 delay: 276
EMMC
SD retry 1 oc 0
SD HOST: 200000000 CTL0: 0x00800000 BUS: 400000 Hz actual: 390625 HZ div: 512 (256) status: 0x1fff0000 delay: 276
SD retry 2 oc 0
SD HOST: 200000000 CTL0: 0x00800000 BUS: 400000 Hz actual: 390625 HZ div: 512 (256) status: 0x1fff0000 delay: 276
SDV1
SD CMD: 0x371a0010 (55) 0x0 0x1fff0001
USB-PD: src-cap PDO object1 0x0a11912c
Current 3000 mA
Voltage 5000 mV
USB-PD: src-cap PDO object2 0x0012d12c
Current 3000 mA
Voltage 9000 mV
USB-PD: src-cap PDO object3 0x0014b12c
Current 3000 mA
Voltage 15000 mV
USB-PD: src-cap PDO object4 0x00164145
Current 3250 mA
Voltage 20000 mV
Failed to open device: 'sdcard' (cmd 371a0010 status 1fff0001)
Retry SD 1
SD HOST: 200000000 CTL0: 0x00800000 BUS: 400000 Hz actual: 390625 HZ div: 512 (256) status: 0x1fff0000 delay: 276
SD HOST: 200000000 CTL0: 0x00800f00 BUS: 400000 Hz actual: 390625 HZ div: 512 (256) status: 0x1fff0000 delay: 276
EMMC
SD retry 1 oc 0
SD HOST: 200000000 CTL0: 0x00800000 BUS: 400000 Hz actual: 390625 HZ div: 512 (256) status: 0x1fff0000 delay: 276
SD retry 2 oc 0
SD HOST: 200000000 CTL0: 0x00800000 BUS: 400000 Hz actual: 390625 HZ div: 512 (256) status: 0x1fff0000 delay: 276
SDV1
SD CMD: 0x371a0010 (55) 0x0 0x1fff0001
Failed to open device: 'sdcard' (cmd 371a0010 status 1fff0001)
Boot mode: USB-MSD (04) order 2
XHCI-STOP
xHC0 ver: 272 HCS: 03000440 140000f1 07ff000a HCC: 0240fe6d
USBSTS 1
xHC0 ver: 272 HCS: 03000440 140000f1 07ff000a HCC: 0240fe6d
xHC0 ports 3 slots 64 intrs 4
XHCI-STOP
xHC1 ver: 272 HCS: 03000440 140000f1 07ff000a HCC: 0240fe6d
USBSTS 1
xHC1 ver: 272 HCS: 03000440 140000f1 07ff000a HCC: 0240fe6d
xHC1 ports 3 slots 64 intrs 4
XHCI-STOP
xHC0 ver: 272 HCS: 03000440 140000f1 07ff000a HCC: 0240fe6d
USBSTS 0
XHCI-STOP
xHC1 ver: 272 HCS: 03000440 140000f1 07ff000a HCC: 0240fe6d
USBSTS 0
USB MSD stopped. Timeout: 25 seconds
Boot mode: NETWORK (02) order 0
NETWORK: d8:3a:dd:e5:72:37 wait for link TFTP: 192.168.68.1
LINK STATUS: speed: 1000 full duplex
Link ready
RX: 0 IP: 0 IPV4: 0 MAC: 0 UDP: 0 UDP RECV: 0 IP_CSUM_ERR: 0 UDP_CSUM_ERR: 0
DHCP src: 70:70:fc:05:68:c7 192.168.66.1
YI_ADDR 192.168.68.231
SI_ADDR 192.168.68.1
OPTIONS:-
op: 53 len: 1 DHCP recv OFFER (2) expect OFFER
op: 54 len: 4 192.168.66.1
op: 51 len: 4
op: 1 len: 4 255.255.255.0
op: 3 len: 4 192.168.68.1
op: 43 len: 17
DHCP src: 70:70:fc:05:68:c7 192.168.66.1
YI_ADDR 192.168.68.231
SI_ADDR 192.168.68.1
OPTIONS:-
op: 53 len: 1 DHCP recv ACK (5) expect ACK
op: 54 len: 4 192.168.66.1
op: 51 len: 4
op: 1 len: 4 255.255.255.0
op: 3 len: 4 192.168.68.1
op: 6 len: 4 10.1.1.1
op: 150 len: 4
op: 43 len: 17
op: 15 len: 11
NET 192.168.68.231 255.255.255.0 gw 0.0.0.0 tftp 192.168.68.1
ARP 192.168.68.1 70:70:fc:05:68:c7
NET 192.168.68.231 255.255.255.0 gw 0.0.0.0 tftp 192.168.68.1
RX: 3 IP: 0 IPV4: 2 MAC: 2 UDP: 2 UDP RECV: 2 IP_CSUM_ERR: 0 UDP_CSUM_ERR: 0
TFTP_GET: 70:70:fc:05:68:c7 192.168.68.1 a18d1bdb/config.txt
RX: 3 IP: 0 IPV4: 2 MAC: 2 UDP: 2 UDP RECV: 2 IP_CSUM_ERR: 0 UDP_CSUM_ERR: 0
ARP TX resp: sender: d8:3a:dd:e5:72:37 192.168.68.231 target: 192.168.68.1
TFTP: disconnect: timeouts 14
RX: 19 IP: 0 IPV4: 17 MAC: 17 UDP: 2 UDP RECV: 2 IP_CSUM_ERR: 0 UDP_CSUM_ERR: 0
BMD \"a18d1bdb/config.txt\" not found
TFTP_GET: 70:70:fc:05:68:c7 192.168.68.1 config.txt
RX: 20 IP: 0 IPV4: 18 MAC: 18 UDP: 2 UDP RECV: 2 IP_CSUM_ERR: 0 UDP_CSUM_ERR: 0
ARP TX resp: sender: d8:3a:dd:e5:72:37 192.168.68.231 target: 192.168.68.1
TFTP: disconnect: timeouts 28
RX: 36 IP: 0 IPV4: 33 MAC: 33 UDP: 2 UDP RECV: 2 IP_CSUM_ERR: 0 UDP_CSUM_ERR: 0
Read config.txt failed
Retry NETWORK 1
Stopping network
RX: 37 IP: 0 IPV4: 34 MAC: 34 UDP: 2 UDP RECV: 2 IP_CSUM_ERR: 0 UDP_CSUM_ERR: 0
RX: 37 IP: 0 IPV4: 34 MAC: 34 UDP: 2 UDP RECV: 2 IP_CSUM_ERR: 0 UDP_CSUM_ERR: 0
RP1_NET NETWORK_CONTROL : 0x0000001c
RP1_NET NETWORK_CONFIG : 0x00d40502
RP1_NET NETWORK_STATUS : 0x00000006
RP1_NET DMA_CONFIG : 0x4020071f
RP1_NET TRANSMIT_STATUS : 0x00000021
RP1_NET RECEIVE_STATUS : 0x00000002
RP1_NET INT_STATUS : 0x0000008a
RP1_NET FRAMES_TXED_64 : 0x00000003
RP1_NET FRAMES_TXED_65 : 0x0000001b
RP1_NET FRAMES_TXED_128 : 0x00000002
RP1_NET FRAMES_TXED_256 : 0x00000006
RP1_NET FRAMES_TXED_512 : 0x00000000
RP1_NET FRAMES_TXED_1024 : 0x00000000
RP1_NET FRAMES_TXED_1519 : 0x00000000
RP1_NET TX_UNDERRUNS : 0x00000000
RP1_NET FRAMES_RXED_OK : 0x00000025
RP1_NET BROADCAST_RXED : 0x00000000
RP1_NET MULTICAST_RXED : 0x00000000
RP1_NET FRAMES_RXED_64 : 0x00000003
RP1_NET FRAMES_RXED_65 : 0x00000020
RP1_NET FRAMES_RXED_128 : 0x00000000
RP1_NET FRAMES_RXED_256 : 0x00000002
RP1_NET FRAMES_RXED_512 : 0x00000000
RP1_NET FRAMES_RXED_1024 : 0x00000000
RP1_NET FRAMES_RXED_1519 : 0x00000000
RP1_NET FCS_ERRORS : 0x00000000
RP1_NET RX_RESOURCE_ERRORS : 0x00000000
RP1_NET RX_OVERRUNS : 0x00000000
RP1_NET TRANSMIT_Q_PTR : 0x3c320920
RP1_NET RECEIVE_Q_PTR : 0x3c320610
RP1_NET tx_q_base : 0xfc3208c0
RP1_NET rx_q_base : 0xfc3203c0
RP1_NET rx dropped : 0
Stopping network
Stopping network
NETWORK: d8:3a:dd:e5:72:37 wait for link TFTP: 192.168.68.1
LINK STATUS: speed: 1000 full duplex
Link ready
RX: 37 IP: 0 IPV4: 34 MAC: 34 UDP: 2 UDP RECV: 2 IP_CSUM_ERR: 0 UDP_CSUM_ERR: 0
Stopping network
RX: 37 IP: 0 IPV4: 34 MAC: 34 UDP: 2 UDP RECV: 2 IP_CSUM_ERR: 0 UDP_CSUM_ERR: 0
RX: 37 IP: 0 IPV4: 34 MAC: 34 UDP: 2 UDP RECV: 2 IP_CSUM_ERR: 0 UDP_CSUM_ERR: 0
RP1_NET NETWORK_CONTROL : 0x0000001c
RP1_NET NETWORK_CONFIG : 0x00d40502
RP1_NET NETWORK_STATUS : 0x00000006
RP1_NET DMA_CONFIG : 0x4020071f
RP1_NET TRANSMIT_STATUS : 0x00000021
RP1_NET RECEIVE_STATUS : 0x00000002
RP1_NET INT_STATUS : 0x0000008a
RP1_NET FRAMES_TXED_64 : 0x00000000
RP1_NET FRAMES_TXED_65 : 0x00000000
RP1_NET FRAMES_TXED_128 : 0x00000000
RP1_NET FRAMES_TXED_256 : 0x00000003
RP1_NET FRAMES_TXED_512 : 0x00000000
RP1_NET FRAMES_TXED_1024 : 0x00000000
RP1_NET FRAMES_TXED_1519 : 0x00000000
RP1_NET TX_UNDERRUNS : 0x00000000
RP1_NET FRAMES_RXED_OK : 0x00000006
RP1_NET BROADCAST_RXED : 0x00000000
RP1_NET MULTICAST_RXED : 0x00000000
RP1_NET FRAMES_RXED_64 : 0x00000003
RP1_NET FRAMES_RXED_65 : 0x00000000
RP1_NET FRAMES_RXED_128 : 0x00000000
RP1_NET FRAMES_RXED_256 : 0x00000003
RP1_NET FRAMES_RXED_512 : 0x00000000
RP1_NET FRAMES_RXED_1024 : 0x00000000
RP1_NET FRAMES_RXED_1519 : 0x00000000
RP1_NET FCS_ERRORS : 0x00000000
RP1_NET RX_RESOURCE_ERRORS : 0x00000000
RP1_NET RX_OVERRUNS : 0x00000000
RP1_NET TRANSMIT_Q_PTR : 0x3c3208f0
RP1_NET RECEIVE_Q_PTR : 0x3c320420
RP1_NET tx_q_base : 0xfc3208c0
RP1_NET rx_q_base : 0xfc3203c0
RP1_NET rx dropped : 0
NETBOOT CANCEL
NETBOOT init failed
Retry NETWORK 2
Stopping network
Stopping network
NETWORK: d8:3a:dd:e5:72:37 wait for link TFTP: 192.168.68.1
LINK STATUS: speed: 1000 full duplex
Link ready
RX: 37 IP: 0 IPV4: 34 MAC: 34 UDP: 2 UDP RECV: 2 IP_CSUM_ERR: 0 UDP_CSUM_ERR: 0
The job was canceled
end: 2.3 auto-login-action (duration 00:03:12) [common]
case: auto-login-action
case_id: 4089099
definition: lava
duration: 192.49
extra: ...
level: 2.3
namespace: common
result: fail
The job was canceled
end: 2 minimal-boot (duration 00:03:20) [common]
case: minimal-boot
case_id: 4089100
definition: lava
duration: 199.88
extra: ...
level: 2
namespace: common
result: fail
Cleaning after the job
Cleaning up download directory: /var/lib/lava/dispatcher/tmp/37653/nbd-deploy-5s6de01_/initrd
Cleaning up download directory: /var/lib/lava/dispatcher/tmp/37653/nbd-deploy-5s6de01_/kernel
Cleaning up download directory: /var/lib/lava/dispatcher/tmp/37653/nbd-deploy-5s6de01_/dtb
Cleaning up download directory: /var/lib/lava/dispatcher/tmp/37653/nbd-deploy-5s6de01_/nbdroot
start: 5.1 power-off (timeout 00:00:30) [common]
Calling: 'upower.sh' '--atx' 'off' '2'
>> Accessing Gembird #0 USB device 002
>> Switched outlet 2 off
Returned 0 in 1 seconds
end: 5.1 power-off (duration 00:00:01) [common]
case: power-off
case_id: 4089101
definition: lava
duration: 1.12
extra: ...
level: 5.1
namespace: common
result: pass
start: 5.2 read-feedback (timeout 00:09:59) [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]
lava-xnbd cleanup
clean NBD port 61991
Override tmp directory removed at /var/lib/lava/dispatcher/tmp/37653
Root tmp directory removed at /var/lib/lava/dispatcher/tmp/37653
JobCanceled: The job was canceled
case: job
case_id: 4089102
definition: lava
error_msg: The job was canceled
error_type: Canceled
result: fail
Please read the triage guidelines for help on debugging failures in the test job, test definitions or in individual test cases.
This section helps test writers to check for actions with a duration which is much shorter than the requested timeout. Reducing these timeouts will allow failures to be identified more quickly.
The graph only shows actions that are longer than 1 second. The full list is anyway available in the table.