Action timeout is larger than job timeout @ data['actions']['1']
Job error: auto-login-action timed out after 545 seconds
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-12-11 12:05:32.905392+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: 1.38
case: validate
case_id: 4112152
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 61999
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/38293/nbd-deploy-u6ninb76/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.95 s (2.16 MB/s)
end: 1.1.1 http-download (duration 00:00:01) [common]
case: http-download
case_id: 4112156
definition: lava
duration: 0.95
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/38293/nbd-deploy-u6ninb76/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 5.30 s (5.19 MB/s)
end: 1.2.1 http-download (duration 00:00:05) [common]
case: http-download
case_id: 4112156
definition: lava
duration: 5.30
extra: ...
level: 1.2.1
namespace: common
result: pass
end: 1.2 download-retry (duration 00:00:05) [common]
start: 1.3 download-retry (timeout 00:09:54) [common]
start: 1.3.1 http-download (timeout 00:09:54) [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/38293/nbd-deploy-u6ninb76/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: 4112156
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:53) [common]
start: 1.4.1 http-download (timeout 00:09:53) [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/38293/nbd-deploy-u6ninb76/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 40.50 s (11.63 MB/s)
end: 1.4.1 http-download (duration 00:00:41) [common]
case: http-download
case_id: 4112156
definition: lava
duration: 40.50
extra: ...
level: 1.4.1
namespace: common
result: pass
end: 1.4 download-retry (duration 00:00:41) [common]
start: 1.5 lava-overlay (timeout 00:09:13) [common]
[common] Preparing overlay tarball in /var/lib/lava/dispatcher/tmp/38293/lava-overlay-fgeqybpl
makedir: /var/lib/lava/dispatcher/tmp/38293/lava-overlay-fgeqybpl/lava-38293/bin
makedir: /var/lib/lava/dispatcher/tmp/38293/lava-overlay-fgeqybpl/lava-38293/tests
makedir: /var/lib/lava/dispatcher/tmp/38293/lava-overlay-fgeqybpl/lava-38293/results
Creating /var/lib/lava/dispatcher/tmp/38293/lava-overlay-fgeqybpl/lava-38293/bin/lava-add-keys
Creating /var/lib/lava/dispatcher/tmp/38293/lava-overlay-fgeqybpl/lava-38293/bin/lava-add-sources
Creating /var/lib/lava/dispatcher/tmp/38293/lava-overlay-fgeqybpl/lava-38293/bin/lava-background-process-start
Creating /var/lib/lava/dispatcher/tmp/38293/lava-overlay-fgeqybpl/lava-38293/bin/lava-background-process-stop
Creating /var/lib/lava/dispatcher/tmp/38293/lava-overlay-fgeqybpl/lava-38293/bin/lava-common-functions
Creating /var/lib/lava/dispatcher/tmp/38293/lava-overlay-fgeqybpl/lava-38293/bin/lava-echo-ipv4
Creating /var/lib/lava/dispatcher/tmp/38293/lava-overlay-fgeqybpl/lava-38293/bin/lava-install-packages
Creating /var/lib/lava/dispatcher/tmp/38293/lava-overlay-fgeqybpl/lava-38293/bin/lava-installed-packages
Creating /var/lib/lava/dispatcher/tmp/38293/lava-overlay-fgeqybpl/lava-38293/bin/lava-os-build
Creating /var/lib/lava/dispatcher/tmp/38293/lava-overlay-fgeqybpl/lava-38293/bin/lava-probe-channel
Creating /var/lib/lava/dispatcher/tmp/38293/lava-overlay-fgeqybpl/lava-38293/bin/lava-probe-ip
Creating /var/lib/lava/dispatcher/tmp/38293/lava-overlay-fgeqybpl/lava-38293/bin/lava-target-ip
Creating /var/lib/lava/dispatcher/tmp/38293/lava-overlay-fgeqybpl/lava-38293/bin/lava-target-mac
Creating /var/lib/lava/dispatcher/tmp/38293/lava-overlay-fgeqybpl/lava-38293/bin/lava-target-storage
Creating /var/lib/lava/dispatcher/tmp/38293/lava-overlay-fgeqybpl/lava-38293/bin/lava-test-case
Creating /var/lib/lava/dispatcher/tmp/38293/lava-overlay-fgeqybpl/lava-38293/bin/lava-test-event
Creating /var/lib/lava/dispatcher/tmp/38293/lava-overlay-fgeqybpl/lava-38293/bin/lava-test-feedback
Creating /var/lib/lava/dispatcher/tmp/38293/lava-overlay-fgeqybpl/lava-38293/bin/lava-test-raise
Creating /var/lib/lava/dispatcher/tmp/38293/lava-overlay-fgeqybpl/lava-38293/bin/lava-test-reference
Creating /var/lib/lava/dispatcher/tmp/38293/lava-overlay-fgeqybpl/lava-38293/bin/lava-test-runner
Creating /var/lib/lava/dispatcher/tmp/38293/lava-overlay-fgeqybpl/lava-38293/bin/lava-test-set
Creating /var/lib/lava/dispatcher/tmp/38293/lava-overlay-fgeqybpl/lava-38293/bin/lava-test-shell
Updating /var/lib/lava/dispatcher/tmp/38293/lava-overlay-fgeqybpl/lava-38293/bin/lava-install-packages (oe)
Updating /var/lib/lava/dispatcher/tmp/38293/lava-overlay-fgeqybpl/lava-38293/bin/lava-installed-packages (oe)
Creating /var/lib/lava/dispatcher/tmp/38293/lava-overlay-fgeqybpl/lava-38293/environment
LAVA metadata
- LAVA_JOB_ID=38293
- LAVA_DISPATCHER_IP=192.168.66.1
start: 1.5.1 ssh-authorize (timeout 00:09:13) [common]
end: 1.5.1 ssh-authorize (duration 00:00:00) [common]
start: 1.5.2 lava-vland-overlay (timeout 00:09:13) [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:09:13) [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:09:13) [common]
Loading test definitions
start: 1.5.4.1 inline-repo-action (timeout 00:09:13) [common]
Using /lava-38293 at stage 0
uuid=38293_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:09:13) [common]
end: 1.5.4.2 test-overlay (duration 00:00:00) [common]
case: test-overlay
case_id: 4112160
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:09:13) [common]
end: 1.5.4.3 test-install-overlay (duration 00:00:00) [common]
case: test-install-overlay
case_id: 4112161
definition: lava
duration: 0.00
extra: ...
level: 1.5.4.3
namespace: common
result: pass
start: 1.5.4.4 test-runscript-overlay (timeout 00:09:13) [common]
runner path: /var/lib/lava/dispatcher/tmp/38293/lava-overlay-fgeqybpl/lava-38293/0/tests/0_dmesg test_uuid 38293_1.5.4.1
end: 1.5.4.4 test-runscript-overlay (duration 00:00:00) [common]
case: test-runscript-overlay
case_id: 4112162
definition: lava
duration: 0.01
extra: ...
level: 1.5.4.4
namespace: common
result: pass
start: 1.5.4.5 inline-repo-action (timeout 00:09:13) [common]
Using /lava-38293 at stage 1
uuid=38293_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:09:13) [common]
end: 1.5.4.6 test-overlay (duration 00:00:00) [common]
case: test-overlay
case_id: 4112160
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:09:13) [common]
end: 1.5.4.7 test-install-overlay (duration 00:00:00) [common]
case: test-install-overlay
case_id: 4112161
definition: lava
duration: 0.00
extra: ...
level: 1.5.4.7
namespace: common
result: pass
start: 1.5.4.8 test-runscript-overlay (timeout 00:09:13) [common]
runner path: /var/lib/lava/dispatcher/tmp/38293/lava-overlay-fgeqybpl/lava-38293/1/tests/1_bootrr test_uuid 38293_1.5.4.5
end: 1.5.4.8 test-runscript-overlay (duration 00:00:00) [common]
case: test-runscript-overlay
case_id: 4112162
definition: lava
duration: 0.00
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/38293/lava-overlay-fgeqybpl/lava-38293/0 for stage 0
- 0_dmesg
Using lava-test-runner path: /var/lib/lava/dispatcher/tmp/38293/lava-overlay-fgeqybpl/lava-38293/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:09:13) [common]
end: 1.5.5 compress-overlay (duration 00:00:00) [common]
start: 1.5.6 persistent-nfs-overlay (timeout 00:09:13) [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:09:13) [common]
start: 1.6.1 uboot-prepare-kernel (timeout 00:09:13) [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:09:13) [common]
xnbd-server-deploy: starting nbd-server
NBD-IP: 192.168.66.1, NBD-PORT: 61999, NBD-ROOT: 38293/nbd-deploy-u6ninb76/nbdroot/agl-ivi-demo-qt-raspberrypi5-20241028040434.ext4
nbd-server 61999 /var/lib/lava/dispatcher/tmp/38293/nbd-deploy-u6ninb76/nbdroot/agl-ivi-demo-qt-raspberrypi5-20241028040434.ext4
output:
output: ** (process:15204): WARNING **: 12:06:21.493: 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:00:47) [common]
start: 2 minimal-boot (timeout 00:09:13) [common]
start: 2.1 connect-device (timeout 00:09:13) [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:09:13) [common]
start: 2.2.1 pdu-reboot (timeout 00:09:13) [common]
Calling: 'upower.sh' '--atx' 'reset' '2'
>> No GEMBIRD SiS-PM found. Check USB connections, please!
>> No GEMBIRD SiS-PM found. Check USB connections, please!
>> 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/38293/nbd-deploy-u6ninb76/initrd/initramfs-netboot-image-raspberrypi5-20241028040434.ext4
>> /var/lib/lava/dispatcher/tmp/initramfs-netboot-image-raspberrypi5.ext4.gz
>> 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
>> DEBUG: IMAGE=/var/lib/lava/dispatcher/tmp/38293/nbd-deploy-u6ninb76/kernel/Image
>> DEBUG: REL_IMAGE=38293/nbd-deploy-u6ninb76/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
>> 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
>> DEBUG: check LISTEN 0 10 0.0.0.0:61999 0.0.0.0:* users:(("nbd-server",pid=15205,fd=3))
>> DEBUG: PID=15205
>> NBDPORT=61999
>> basename: extra operand ‘/var/lib/lava/dispatcher/tmp/initramfs-netboot-image-raspberrypi5.ext4.gz’
>> Try 'basename --help' for more information.
>>
>> enable_uart=1
>> kernel 38293/nbd-deploy-u6ninb76/kernel/Image
>> initramfs
>>
>> 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/38293/nbd-deploy-u6ninb76/dtb/bcm2712-rpi-5-b.dtb
>> DEBUG: BASETFTP=/var/lib/lava/dispatcher/tmp/38293/nbd-deploy-u6ninb76
>> DEBUG: INITRD=/var/lib/lava/dispatcher/tmp/38293/nbd-deploy-u6ninb76/initrd/initramfs-netboot-image-raspberrypi5-20241028040434.ext4
>> DEBUG: REL_INITRD=38293/nbd-deploy-u6ninb76/initrd/initramfs-netboot-image-raspberrypi5-20241028040434.ext4
>> DEBUG: IMAGE=/var/lib/lava/dispatcher/tmp/38293/nbd-deploy-u6ninb76/kernel/Image
>> DEBUG: REL_IMAGE=38293/nbd-deploy-u6ninb76/kernel/Image
>> DEBUG: check LISTEN 0 10 0.0.0.0:61999 0.0.0.0:* users:(("nbd-server",pid=15205,fd=3))
>> DEBUG: PID=15205
>> NBDPORT=61999
>>
>> enable_uart=1
>> kernel 38293/nbd-deploy-u6ninb76/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: 4112163
definition: lava
duration: 7.36
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:09:05) [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 '^]'.
auto-login-action timed out after 545 seconds
end: 2.3 auto-login-action (duration 00:09:05) [common]
case: auto-login-action
case_id: 4112164
definition: lava
duration: 545.00
extra: ...
level: 2.3
namespace: common
result: fail
minimal-boot failed: 1 of 1 attempts. 'auto-login-action timed out after 545 seconds'
auto-login-action timed out after 545 seconds
end: 2 minimal-boot (duration 00:09:12) [common]
case: minimal-boot
case_id: 4112165
definition: lava
duration: 552.37
extra: ...
level: 2
namespace: common
result: fail
Cleaning after the job
Cleaning up download directory: /var/lib/lava/dispatcher/tmp/38293/nbd-deploy-u6ninb76/initrd
Cleaning up download directory: /var/lib/lava/dispatcher/tmp/38293/nbd-deploy-u6ninb76/kernel
Cleaning up download directory: /var/lib/lava/dispatcher/tmp/38293/nbd-deploy-u6ninb76/dtb
Cleaning up download directory: /var/lib/lava/dispatcher/tmp/38293/nbd-deploy-u6ninb76/nbdroot
start: 5.1 power-off (timeout 00:00:30) [common]
Calling: 'upower.sh' '--atx' 'off' '2'
>> No GEMBIRD SiS-PM found. Check USB connections, please!
Returned 0 in 1 seconds
end: 5.1 power-off (duration 00:00:01) [common]
case: power-off
case_id: 4112166
definition: lava
duration: 1.13
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 61999
Override tmp directory removed at /var/lib/lava/dispatcher/tmp/38293
Root tmp directory removed at /var/lib/lava/dispatcher/tmp/38293
JobError: Your job cannot terminate cleanly.
case: job
case_id: 4112167
definition: lava
error_msg: auto-login-action timed out after 545 seconds
error_type: Job
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.