Action timeout is larger than job timeout @ data['actions']['0']
Infrastructure error: Connection closed
Action timeout for http-download exceeds Job timeout
Action timeout for download-retry exceeds Job timeout
Action timeout for http-download exceeds Job timeout
Action timeout for download-retry exceeds Job timeout
Action timeout for deploy-device-env exceeds Job timeout
Action timeout for ssh-authorize exceeds Job timeout
Action timeout for lava-vland-overlay exceeds Job timeout
Action timeout for lava-multinode-overlay exceeds Job timeout
Action timeout for git-repo-action exceeds Job timeout
Action timeout for test-overlay exceeds Job timeout
Action timeout for test-install-overlay exceeds Job timeout
Action timeout for test-runscript-overlay exceeds Job timeout
Action timeout for test-definition exceeds Job timeout
Action timeout for compress-overlay exceeds Job timeout
Action timeout for persistent-nfs-overlay exceeds Job timeout
Action timeout for lava-overlay exceeds Job timeout
Action timeout for deploy-flasher exceeds Job timeout
Action timeout for deploy-flasher-retry exceeds Job timeout
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: 2021.11.0091.ga8b0101b7
start: 0 validate
Start time: 2021-12-21 04:04:37.318210+00:00 (UTC)
Validating that http://citools.st.com/artifacts/artifactory/oeivi-codex-st-com/oemanifest-v2/refs/tags/openstlinux-20-11-12/openstlinux-weston/images/stm32mp1/flashlayout_st-image-weston/trusted/FlashLayout_sdcard_stm32mp157c-dk2-trusted.tsv exists
Validating that http://citools.st.com/artifacts/artifactory/oeivi-codex-st-com/oemanifest-v2/refs/tags/openstlinux-20-11-12/openstlinux-weston/IMAGES-st-image-weston-openstlinux-weston-stm32mp1-openstlinux-20-11-12.tar.xz exists
validate duration: 0.08
case: validate
case_id: 76357
definition: lava
result: pass
start: 1 deploy-flasher-retry (timeout 00:20:00) [common]
start: 1.1 deploy-flasher (timeout 00:20:00) [common]
start: 1.1.1 download-retry (timeout 00:20:00) [common]
start: 1.1.1.1 http-download (timeout 00:20:00) [common]
downloading http://citools.st.com/artifacts/artifactory/oeivi-codex-st-com/oemanifest-v2/refs/tags/openstlinux-20-11-12/openstlinux-weston/images/stm32mp1/flashlayout_st-image-weston/trusted/FlashLayout_sdcard_stm32mp157c-dk2-trusted.tsv
saving as /var/lib/lava/dispatcher/tmp/lavafed-4096/deploy-flasher-du13oba8/layout/FlashLayout_sdcard_stm32mp157c-dk2-trusted.tsv
total size: 835 (0MB)
No compression specified
progress 100% (0MB)
0MB downloaded in 0.04s (0.02MB/s)
end: 1.1.1.1 http-download (duration 00:00:00) [common]
case: http-download
case_id: 76358
definition: lava
duration: 0.04
extra: ...
level: 1.1.1.1
namespace: common
result: pass
end: 1.1.1 download-retry (duration 00:00:00) [common]
start: 1.1.2 download-retry (timeout 00:20:00) [common]
start: 1.1.2.1 http-download (timeout 00:20:00) [common]
downloading http://citools.st.com/artifacts/artifactory/oeivi-codex-st-com/oemanifest-v2/refs/tags/openstlinux-20-11-12/openstlinux-weston/IMAGES-st-image-weston-openstlinux-weston-stm32mp1-openstlinux-20-11-12.tar.xz
saving as /var/lib/lava/dispatcher/tmp/lavafed-4096/deploy-flasher-du13oba8/tarball/IMAGES-st-image-weston-openstlinux-weston-stm32mp1-openstlinux-20-11-12.tar.xz
total size: 655472848 (625MB)
No compression specified
progress 0% (0MB)
progress 5% (31MB)
progress 10% (62MB)
progress 15% (93MB)
progress 20% (125MB)
progress 25% (156MB)
progress 30% (187MB)
progress 35% (218MB)
progress 40% (250MB)
progress 45% (281MB)
progress 50% (312MB)
progress 55% (343MB)
progress 60% (375MB)
progress 65% (406MB)
progress 70% (437MB)
progress 75% (468MB)
progress 80% (500MB)
progress 85% (531MB)
progress 90% (562MB)
progress 95% (593MB)
progress 100% (625MB)
625MB downloaded in 37.38s (16.72MB/s)
end: 1.1.2.1 http-download (duration 00:00:37) [common]
case: http-download
case_id: 76358
definition: lava
duration: 37.38
extra: ...
level: 1.1.2.1
namespace: common
result: pass
end: 1.1.2 download-retry (duration 00:00:37) [common]
start: 1.1.3 deploy-device-env (timeout 00:19:23) [common]
end: 1.1.3 deploy-device-env (duration 00:00:00) [common]
start: 1.1.4 lava-overlay (timeout 00:19:23) [common]
[common] Preparing overlay tarball in /var/lib/lava/dispatcher/tmp/lavafed-4096/lava-overlay-5zvcf702
makedir: /var/lib/lava/dispatcher/tmp/lavafed-4096/lava-overlay-5zvcf702/lava-4096/bin
makedir: /var/lib/lava/dispatcher/tmp/lavafed-4096/lava-overlay-5zvcf702/lava-4096/tests
makedir: /var/lib/lava/dispatcher/tmp/lavafed-4096/lava-overlay-5zvcf702/lava-4096/results
Creating /var/lib/lava/dispatcher/tmp/lavafed-4096/lava-overlay-5zvcf702/lava-4096/bin/lava-add-keys
Creating /var/lib/lava/dispatcher/tmp/lavafed-4096/lava-overlay-5zvcf702/lava-4096/bin/lava-add-sources
Creating /var/lib/lava/dispatcher/tmp/lavafed-4096/lava-overlay-5zvcf702/lava-4096/bin/lava-background-process-start
Creating /var/lib/lava/dispatcher/tmp/lavafed-4096/lava-overlay-5zvcf702/lava-4096/bin/lava-background-process-stop
Creating /var/lib/lava/dispatcher/tmp/lavafed-4096/lava-overlay-5zvcf702/lava-4096/bin/lava-common-functions
Creating /var/lib/lava/dispatcher/tmp/lavafed-4096/lava-overlay-5zvcf702/lava-4096/bin/lava-echo-ipv4
Creating /var/lib/lava/dispatcher/tmp/lavafed-4096/lava-overlay-5zvcf702/lava-4096/bin/lava-install-packages
Creating /var/lib/lava/dispatcher/tmp/lavafed-4096/lava-overlay-5zvcf702/lava-4096/bin/lava-installed-packages
Creating /var/lib/lava/dispatcher/tmp/lavafed-4096/lava-overlay-5zvcf702/lava-4096/bin/lava-os-build
Creating /var/lib/lava/dispatcher/tmp/lavafed-4096/lava-overlay-5zvcf702/lava-4096/bin/lava-probe-channel
Creating /var/lib/lava/dispatcher/tmp/lavafed-4096/lava-overlay-5zvcf702/lava-4096/bin/lava-probe-ip
Creating /var/lib/lava/dispatcher/tmp/lavafed-4096/lava-overlay-5zvcf702/lava-4096/bin/lava-target-ip
Creating /var/lib/lava/dispatcher/tmp/lavafed-4096/lava-overlay-5zvcf702/lava-4096/bin/lava-target-mac
Creating /var/lib/lava/dispatcher/tmp/lavafed-4096/lava-overlay-5zvcf702/lava-4096/bin/lava-target-storage
Creating /var/lib/lava/dispatcher/tmp/lavafed-4096/lava-overlay-5zvcf702/lava-4096/bin/lava-test-case
Creating /var/lib/lava/dispatcher/tmp/lavafed-4096/lava-overlay-5zvcf702/lava-4096/bin/lava-test-event
Creating /var/lib/lava/dispatcher/tmp/lavafed-4096/lava-overlay-5zvcf702/lava-4096/bin/lava-test-feedback
Creating /var/lib/lava/dispatcher/tmp/lavafed-4096/lava-overlay-5zvcf702/lava-4096/bin/lava-test-raise
Creating /var/lib/lava/dispatcher/tmp/lavafed-4096/lava-overlay-5zvcf702/lava-4096/bin/lava-test-reference
Creating /var/lib/lava/dispatcher/tmp/lavafed-4096/lava-overlay-5zvcf702/lava-4096/bin/lava-test-runner
Creating /var/lib/lava/dispatcher/tmp/lavafed-4096/lava-overlay-5zvcf702/lava-4096/bin/lava-test-set
Creating /var/lib/lava/dispatcher/tmp/lavafed-4096/lava-overlay-5zvcf702/lava-4096/bin/lava-test-shell
Updating /var/lib/lava/dispatcher/tmp/lavafed-4096/lava-overlay-5zvcf702/lava-4096/bin/lava-install-packages (oe)
Updating /var/lib/lava/dispatcher/tmp/lavafed-4096/lava-overlay-5zvcf702/lava-4096/bin/lava-installed-packages (oe)
Creating /var/lib/lava/dispatcher/tmp/lavafed-4096/lava-overlay-5zvcf702/lava-4096/environment
LAVA metadata
- LAVA_JOB_ID=4096
start: 1.1.4.1 ssh-authorize (timeout 00:19:23) [common]
end: 1.1.4.1 ssh-authorize (duration 00:00:00) [common]
start: 1.1.4.2 lava-vland-overlay (timeout 00:19:23) [common]
skipped lava-vland-overlay
end: 1.1.4.2 lava-vland-overlay (duration 00:00:00) [common]
start: 1.1.4.3 lava-multinode-overlay (timeout 00:19:23) [common]
skipped lava-multinode-overlay
end: 1.1.4.3 lava-multinode-overlay (duration 00:00:00) [common]
start: 1.1.4.4 test-definition (timeout 00:19:23) [common]
Loading test definitions
start: 1.1.4.4.1 git-repo-action (timeout 00:19:23) [common]
Using /lava-4096 at stage 0
Fetching tests from ssh://gerrit.st.com:29418/oeivi/test/lava/lava-tests
Running '/usr/bin/git clone ssh://gerrit.st.com:29418/oeivi/test/lava/lava-tests /var/lib/lava/dispatcher/tmp/lavafed-4096/lava-overlay-5zvcf702/lava-4096/0/tests/0_TC_SYS_1_2'
Running '/usr/bin/git checkout MPU_TEST-1.74bis
Removing '.git' directory in /var/lib/lava/dispatcher/tmp/lavafed-4096/lava-overlay-5zvcf702/lava-4096/0/tests/0_TC_SYS_1_2
Tests stored (tmp) in /var/lib/lava/dispatcher/tmp/lavafed-4096/lava-overlay-5zvcf702/lava-4096/0/tests/0_TC_SYS_1_2/tests-def/system/TC_SYS_1_2.yaml
uuid=4096_1.1.4.4.1 testdef=None
end: 1.1.4.4.1 git-repo-action (duration 00:00:05) [common]
case: git-repo-action
case_id: 76360
definition: lava
duration: 5.32
extra: ...
level: 1.1.4.4.1
namespace: common
result: pass
start: 1.1.4.4.2 test-overlay (timeout 00:19:17) [common]
end: 1.1.4.4.2 test-overlay (duration 00:00:00) [common]
case: test-overlay
case_id: 76361
definition: lava
duration: 0.00
extra: ...
level: 1.1.4.4.2
namespace: common
result: pass
start: 1.1.4.4.3 test-install-overlay (timeout 00:19:17) [common]
end: 1.1.4.4.3 test-install-overlay (duration 00:00:00) [common]
case: test-install-overlay
case_id: 76362
definition: lava
duration: 0.10
extra: ...
level: 1.1.4.4.3
namespace: common
result: pass
start: 1.1.4.4.4 test-runscript-overlay (timeout 00:19:17) [common]
runner path: /var/lib/lava/dispatcher/tmp/lavafed-4096/lava-overlay-5zvcf702/lava-4096/0/tests/0_TC_SYS_1_2 test_uuid 4096_1.1.4.4.1
MD5SUM_BUILD='fd06fe125bbc782a6f9704f916e23c1c'
end: 1.1.4.4.4 test-runscript-overlay (duration 00:00:00) [common]
case: test-runscript-overlay
case_id: 76363
definition: lava
duration: 0.19
extra: ...
level: 1.1.4.4.4
namespace: common
result: pass
Creating lava-test-runner.conf files
Using lava-test-runner path: /var/lib/lava/dispatcher/tmp/lavafed-4096/lava-overlay-5zvcf702/lava-4096/0 for stage 0
- 0_TC_SYS_1_2
end: 1.1.4.4 test-definition (duration 00:00:06) [common]
start: 1.1.4.5 compress-overlay (timeout 00:19:17) [common]
end: 1.1.4.5 compress-overlay (duration 00:00:01) [common]
start: 1.1.4.6 persistent-nfs-overlay (timeout 00:19:16) [common]
end: 1.1.4.6 persistent-nfs-overlay (duration 00:00:00) [common]
end: 1.1.4 lava-overlay (duration 00:00:06) [common]
Calling: 'nice' 'ln' '-s' 'layout/FlashLayout_sdcard_stm32mp157c-dk2-trusted.tsv' '.'
Returned 0 in 0 seconds
Calling: 'nice' 'ls' '-l'
>> total 8
>> lrwxrwxrwx 1 root root 53 Dec 21 04:05 FlashLayout_sdcard_stm32mp157c-dk2-trusted.tsv -> layout/FlashLayout_sdcard_stm32mp157c-dk2-trusted.tsv
>> drwxr-xr-x 2 root root 4096 Dec 21 04:04 layout
>> drwxr-xr-x 2 root root 4096 Dec 21 04:04 tarball
Returned 0 in 0 seconds
Calling: 'nice' '/root/git/lava-config/scripts/boot_management.sh' '-l' 'layout/FlashLayout_sdcard_stm32mp157c-dk2-trusted.tsv' '-z' 'tarball/IMAGES-st-image-weston-openstlinux-weston-stm32mp1-openstlinux-20-11-12.tar.xz' '-e' '{UPDATE}' '-b' 'ttyACM.nucleo_lmecxd0318_4' '-s' '12_13' '-u' 'epowerswitch_03.lme.st.com' '-p' '3' '-d' '0027003F3338510534383330' '-t' 'mp157-disco' '-f' 'on'
>> [04:05:22] [DEBUG] Boot Pin
>> [04:05:22] #### BootManagement script started with layout/FlashLayout_sdcard_stm32mp157c-dk2-trusted.tsv tarball/IMAGES-st-image-weston-openstlinux-weston-stm32mp1-openstlinux-20-11-12.tar.xz
>> [04:05:22] [DEBUG] md5sum computation start
>> [04:05:22] [DEBUG] md5sum computation done.
>> ######### MD5SUM for FlashLayout_sdcard_stm32mp157c-dk2-trusted.tsv file
>> Calculated : 2c8df6859f370b6a764587c4c80fb6f8
>> #################################
>> [04:05:22] Boot media : mmc0
>> [04:05:22] *** Start normal boot procedure ***
>> [04:05:22] *** Binary preparation ***
>> [04:05:22] Tarball file extraction procedure for tarball/IMAGES-st-image-weston-openstlinux-weston-stm32mp1-openstlinux-20-11-12.tar.xz
>> [04:05:22] [DEBUG] md5sum computation start
>> [04:05:24] [DEBUG] md5sum computation done.
>> ######### MD5SUM for IMAGES-st-image-weston-openstlinux-weston-stm32mp1-openstlinux-20-11-12.tar.xz file
>> Calculated : 7ceb1485128ee599de7ef478f3c5dc0d
>> #################################
>> [04:05:24] Tarball extraction start:
>> [04:06:07] Tarball extraction done.
>> [04:06:08] Try launching flasher operation number 1
>> [04:06:08] Wait to get lock for board in DFU...
>> [04:06:08] Activate lock for board in DFU done.
>> [04:06:08] Configure bootpins:
>> [04:06:08] [DEBUG] BOOT_PIN INPUT: 12_13
>> [04:06:08] [DEBUG] BOOT_PIN[0]: 12
>> [04:06:08] [DEBUG] BOOT_PIN[1]: 13
>> [04:06:08] Reset boot pin to flash mode
>> [04:06:08] [DEBUG] D12=0
>> [04:06:08] Wait to get lock for /dev/ttyACM.nucleo_lmecxd0318_4...
>> [04:06:08] Activate lock for /dev/ttyACM.nucleo_lmecxd0318_4.
>> [04:06:09] D12=0
>> [04:06:09] Release lock for /dev/ttyACM.nucleo_lmecxd0318_4 done.
>> [04:06:09] [DEBUG] D13=0
>> [04:06:09] Wait to get lock for /dev/ttyACM.nucleo_lmecxd0318_4...
>> [04:06:09] Activate lock for /dev/ttyACM.nucleo_lmecxd0318_4.
>> [04:06:09] D13=0
>> [04:06:09] Release lock for /dev/ttyACM.nucleo_lmecxd0318_4 done.
>> [04:06:10] [DEBUG] off Media_boot mmc0
>> [04:06:10] [DEBUG] D12=0
>> [04:06:10] Wait to get lock for /dev/ttyACM.nucleo_lmecxd0318_4...
>> [04:06:10] Activate lock for /dev/ttyACM.nucleo_lmecxd0318_4.
>> [04:06:10] D12=0
>> [04:06:10] Release lock for /dev/ttyACM.nucleo_lmecxd0318_4 done.
>> [04:06:10] [DEBUG] D13=0
>> [04:06:10] Wait to get lock for /dev/ttyACM.nucleo_lmecxd0318_4...
>> [04:06:11] Activate lock for /dev/ttyACM.nucleo_lmecxd0318_4.
>> [04:06:11] D13=0
>> [04:06:11] Release lock for /dev/ttyACM.nucleo_lmecxd0318_4 done.
>> [04:06:11] Wait for Relay to be established: 1 ms
>> [04:06:12] Bootpins configure done.
>> [04:06:12] [DEBUG] /root/git/lava-config/scripts/epower_switch.sh -u epowerswitch_03.lme.st.com -p 3 -c REBOOT -n 2001
>> [04:06:12] [DEBUG] last digit correct
>> ePowerSwitch epowerswitch_03.lme.st.com selected 3
>> Send reboot command switch epowerswitch_03.lme.st.com on prt 3
>> [04:06:12] [DEBUG] Switch OFF Power supply
>> [04:06:12] [DEBUG] CMD: wget -O - http://epowerswitch_03.lme.st.com/hidden.htm?M0:O3=Off
>> [04:06:29] [DEBUG] Switch ON Power supply
>> [04:06:29] [DEBUG] CMD: wget -O - http://epowerswitch_03.lme.st.com/hidden.htm?M0:O3=On
>> [04:06:29] Wait for 15 seconds...
>> [04:06:44] *** Flashing Procedure ***
>> [04:06:44] Launch Flashing operation number 1
>> [04:06:44] Wait for DFU to be up...
>> [04:06:44] [DEBUG] DFU detection loop: 1
>> [04:06:44] [DEBUG] USB DFU device(s) available on host
>> [04:06:45] [DEBUG] *** /root/git/programmer/x86_64-linux/bin/STM32_Programmer_CLI -l usb ***
>> [04:06:45] -------------------------------------------------------------------
>> [04:06:45] STM32CubeProgrammer v2.7.0
>> [04:06:45] -------------------------------------------------------------------
>> [04:06:45]
>> [04:06:45] ===== DFU Interface =====
>> [04:06:45]
>> [04:06:45] Total number of available STM32 device in DFU mode: 1
>> [04:06:45]
>> [04:06:45] Device Index : USB1
>> [04:06:45] USB Bus Number : 002
>> [04:06:45] USB Address Number : 005
>> [04:06:45] Product ID : DFU in HS Mode @Device ID /0x500, @Revision ID /0x0000
>> [04:06:45] Serial number : 0027003F3338510534383330
>> [04:06:45] Firmware version : 0x0110
>> [04:06:45] Device ID : 0x0500
>> [04:06:45] [DEBUG] ***
>> [04:06:45] Found USB DFU device usb1 for serial number 0027003f3338510534383330
>> [04:06:45] Wait for DFU during 1 seconds
>> [04:06:45] *********************** Use following command to flash: ***********************
>> [04:06:45] TIMEOUT_VALUE=15m ARTIFACTS_DIR=/var/lib/lava/dispatcher/tmp/lavafed-4096/deploy-flasher-du13oba8 EXTRA_SPACE=0x40000000 bash /root/git/meta-st-valid/recipes-devtools/flashing/flashing-stm32mp/STM32_Programmer_CLI.sh no-ui extra -w layout/FlashLayout_sdcard_stm32mp157c-dk2-trusted.tsv -c port=usb1 -q
>> [ROOTFS EXTRA SPACE configuration]
>> EXTRA_SPACE: 0x40000000
>>
>> New computed offset for userfs:
>> >>> from : 0x33C84400
>> >>> to : 0x73c84400
>> [ARTIFACTS_DIR configuration]
>> ARTIFACTS_DIR: /var/lib/lava/dispatcher/tmp/lavafed-4096/deploy-flasher-du13oba8
>>
>> [TIMEOUT_VALUE configuration]
>> TIMEOUT_VALUE: 15m
>>
>>
>> ==============================================================
>> *** Populate binaries to device with TSV file:
>> layout/FlashLayout_sdcard_stm32mp157c-dk2-trusted.tsv
>> ==============================================================
>> #Opt Id Name Type IP Offset Binary
>> - 0x01 fsbl1-boot Binary none 0x0 arm-trusted-firmware/tf-a-stm32mp157c-dk2-serialboot.stm32
>> - 0x03 ssbl-boot Binary none 0x0 bootloader/u-boot-stm32mp157c-dk2-trusted.stm32
>> P 0x04 fsbl1 Binary mmc0 0x00004400 arm-trusted-firmware/tf-a-stm32mp157c-dk2-trusted.stm32
>> P 0x05 fsbl2 Binary mmc0 0x00044400 arm-trusted-firmware/tf-a-stm32mp157c-dk2-trusted.stm32
>> PD 0x06 ssbl Binary mmc0 0x00084400 bootloader/u-boot-stm32mp157c-dk2-trusted.stm32
>> P 0x21 boot System mmc0 0x00284400 st-image-bootfs-openstlinux-weston-stm32mp1.ext4
>> P 0x22 vendorfs FileSystem mmc0 0x04284400 st-image-vendorfs-openstlinux-weston-stm32mp1.ext4
>> P 0x23 rootfs FileSystem mmc0 0x05284400 st-image-weston-openstlinux-weston-stm32mp1.ext4
>> P 0x24 userfs FileSystem mmc0 0x33C84400 st-image-userfs-openstlinux-weston-stm32mp1.ext4
>> ==============================================================
>> -------------------------------------------------------------------
>> STM32CubeProgrammer v2.7.0
>> -------------------------------------------------------------------
>>
>>
>>
>> Warning: Timeout is forced to 65535 ms
>>
>>
>> USB speed : High Speed (480MBit/s)
>> Manuf. ID : STMicroelectronics
>> Product ID : DFU in HS Mode @Device ID /0x500, @Revision ID /0x0000
>> SN : 0027003F3338510534383330
>> FW version : 0x0110
>> Device ID : 0x0500
>> Device name : STM32MP1
>> Device type : MPU
>> Device CPU : Cortex-A7
>>
>>
>> Start Embedded Flashing service
>>
>>
>>
>> Memory Programming ...
>> Opening and parsing file: tf-a-stm32mp157c-dk2-serialboot.stm32
>> File : tf-a-stm32mp157c-dk2-serialboot.stm32
>> Size : 237896 Bytes
>> Partition ID : 0x01
>>
>> Download in Progress:
>>
>>
>> File download complete
>> Time elapsed during download operation: 00:00:00.473
>>
>> RUNNING Program ...
>> PartID: :0x01
>> Start operation done successfully at partition 0x01
>>
>> Flashlayout Programming ...
>>
>> Running Flashlayout Partition ...
>> Flashlayout partition started successfully
>>
>>
>> Memory Programming ...
>> Opening and parsing file: u-boot-stm32mp157c-dk2-trusted.stm32
>> File : u-boot-stm32mp157c-dk2-trusted.stm32
>> Size : 904820 Bytes
>> Partition ID : 0x03
>>
>> Download in Progress:
>>
>>
>> File download complete
>> Time elapsed during download operation: 00:00:00.961
>>
>> RUNNING Program ...
>> PartID: :0x03
>>
>> Reconnecting the device ...
>>
>> Error:
>> Unable to reconnect the target device: time out expired
>>
>>
>> Error: Start operation failed at partition 0x03
>> Error: TSV flashing service failed
>>
>> ==============================================================
>> *** Spent 68s for operation.
>> *** (0h01m08s)
>> ==============================================================
>>
>> [04:07:53] Flashing operation failed...
>> [04:07:53] Launch Flashing operation number 2
>> [04:07:53] Wait for DFU to be up...
>> [04:07:53] [DEBUG] DFU detection loop: 1
>> [04:07:53] [DEBUG] USB DFU device(s) available on host
>> [04:07:53] [DEBUG] *** /root/git/programmer/x86_64-linux/bin/STM32_Programmer_CLI -l usb ***
>> [04:07:53] -------------------------------------------------------------------
>> [04:07:53] STM32CubeProgrammer v2.7.0
>> [04:07:53] -------------------------------------------------------------------
>> [04:07:53]
>> [04:07:53] ===== DFU Interface =====
>> [04:07:53]
>> [04:07:53] Total number of available STM32 device in DFU mode: 1
>> [04:07:53]
>> [04:07:53] Device Index : USB1
>> [04:07:53] USB Bus Number : 002
>> [04:07:53] USB Address Number : 005
>> [04:07:53] Product ID : USB download gadget@Device ID /0x500, @Revision ID /0x2000, @Name /STM32MP157CAC Rev.B,
>> [04:07:53] Serial number : 0027003F3338510534383330
>> [04:07:53] Firmware version : 0x0110
>> [04:07:53] Device ID : 0x0500
>> [04:07:53] [DEBUG] ***
>> [04:07:53] Found USB DFU device usb1 for serial number 0027003f3338510534383330
>> [04:07:53] Wait for DFU during 0 seconds
>> [04:07:53] *********************** Use following command to flash: ***********************
>> [04:07:53] TIMEOUT_VALUE=15m ARTIFACTS_DIR=/var/lib/lava/dispatcher/tmp/lavafed-4096/deploy-flasher-du13oba8 EXTRA_SPACE=0x40000000 bash /root/git/meta-st-valid/recipes-devtools/flashing/flashing-stm32mp/STM32_Programmer_CLI.sh no-ui extra -w layout/FlashLayout_sdcard_stm32mp157c-dk2-trusted.tsv -c port=usb1 -q
>> [ROOTFS EXTRA SPACE configuration]
>> EXTRA_SPACE: 0x40000000
>>
>> New computed offset for userfs:
>> >>> from : 0x33C84400
>> >>> to : 0x73c84400
>> [ARTIFACTS_DIR configuration]
>> ARTIFACTS_DIR: /var/lib/lava/dispatcher/tmp/lavafed-4096/deploy-flasher-du13oba8
>>
>> [TIMEOUT_VALUE configuration]
>> TIMEOUT_VALUE: 15m
>>
>>
>> ==============================================================
>> *** Populate binaries to device with TSV file:
>> layout/FlashLayout_sdcard_stm32mp157c-dk2-trusted.tsv
>> ==============================================================
>> #Opt Id Name Type IP Offset Binary
>> - 0x01 fsbl1-boot Binary none 0x0 arm-trusted-firmware/tf-a-stm32mp157c-dk2-serialboot.stm32
>> - 0x03 ssbl-boot Binary none 0x0 bootloader/u-boot-stm32mp157c-dk2-trusted.stm32
>> P 0x04 fsbl1 Binary mmc0 0x00004400 arm-trusted-firmware/tf-a-stm32mp157c-dk2-trusted.stm32
>> P 0x05 fsbl2 Binary mmc0 0x00044400 arm-trusted-firmware/tf-a-stm32mp157c-dk2-trusted.stm32
>> PD 0x06 ssbl Binary mmc0 0x00084400 bootloader/u-boot-stm32mp157c-dk2-trusted.stm32
>> P 0x21 boot System mmc0 0x00284400 st-image-bootfs-openstlinux-weston-stm32mp1.ext4
>> P 0x22 vendorfs FileSystem mmc0 0x04284400 st-image-vendorfs-openstlinux-weston-stm32mp1.ext4
>> P 0x23 rootfs FileSystem mmc0 0x05284400 st-image-weston-openstlinux-weston-stm32mp1.ext4
>> P 0x24 userfs FileSystem mmc0 0x33C84400 st-image-userfs-openstlinux-weston-stm32mp1.ext4
>> ==============================================================
>> -------------------------------------------------------------------
>> STM32CubeProgrammer v2.7.0
>> -------------------------------------------------------------------
>>
>>
>>
>> Warning: Timeout is forced to 65535 ms
>>
>>
>> USB speed : High Speed (480MBit/s)
>> Manuf. ID : STMicroelectronics
>> Product ID : USB download gadget@Device ID /0x500, @Revision ID /0x2000, @Name /STM32MP157CAC Rev.B,
>> SN : 0027003F3338510534383330
>> FW version : 0x0110
>> Device ID : 0x0500
>> Device name : STM32MP157CAC Rev.B
>> Device type : MPU
>> Device CPU : Cortex-A7
>>
>>
>> Start Embedded Flashing service
>>
>>
>>
>> Memory Programming ...
>> Opening and parsing file: tf-a-stm32mp157c-dk2-trusted.stm32
>> File : tf-a-stm32mp157c-dk2-trusted.stm32
>> Size : 233800 Bytes
>> Partition ID : 0x04
>>
>> Download in Progress:
>>
>>
>> File download complete
>> Time elapsed during download operation: 00:00:00.053
>>
>> RUNNING Program ...
>> PartID: :0x04
>> Start operation done successfully at partition 0x04
>>
>>
>> Memory Programming ...
>> Opening and parsing file: tf-a-stm32mp157c-dk2-trusted.stm32
>> File : tf-a-stm32mp157c-dk2-trusted.stm32
>> Size : 233800 Bytes
>> Partition ID : 0x05
>>
>> Download in Progress:
>>
>>
>> File download complete
>> Time elapsed during download operation: 00:00:00.060
>>
>> RUNNING Program ...
>> PartID: :0x05
>> Start operation done successfully at partition 0x05
>>
>>
>> Memory Programming ...
>> Opening and parsing file: u-boot-stm32mp157c-dk2-trusted.stm32
>> File : u-boot-stm32mp157c-dk2-trusted.stm32
>> Size : 904820 Bytes
>> Partition ID : 0x06
>>
>> Download in Progress:
>>
>>
>> File download complete
>> Time elapsed during download operation: 00:00:00.212
>>
>> RUNNING Program ...
>> PartID: :0x06
>> Start operation done successfully at partition 0x06
>>
>>
>> Memory Programming ...
>> Opening and parsing file: st-image-bootfs-openstlinux-weston-stm32mp1.ext4
>> File : st-image-bootfs-openstlinux-weston-stm32mp1.ext4
>> Size : 64 MBytes
>> Partition ID : 0x21
>>
>> Download in Progress:
>>
>>
>> File download complete
>> Time elapsed during download operation: 00:00:21.047
>>
>> RUNNING Program ...
>> PartID: :0x21
>> Start operation done successfully at partition 0x21
>>
>>
>> Memory Programming ...
>> Opening and parsing file: st-image-vendorfs-openstlinux-weston-stm32mp1.ext4
>> File : st-image-vendorfs-openstlinux-weston-stm32mp1.ext4
>> Size : 16 MBytes
>> Partition ID : 0x22
>>
>> Download in Progress:
>>
>>
>> File download complete
>> Time elapsed during download operation: 00:00:04.932
>>
>> RUNNING Program ...
>> PartID: :0x22
>> Start operation done successfully at partition 0x22
>>
>>
>> Memory Programming ...
>> Opening and parsing file: st-image-weston-openstlinux-weston-stm32mp1.ext4
>> File : st-image-weston-openstlinux-weston-stm32mp1.ext4
>> Size : 548556 KBytes
>> Partition ID : 0x23
>>
>> Download in Progress:
>>
>>
>> File download complete
>> Time elapsed during download operation: 00:02:43.968
>>
>> RUNNING Program ...
>> PartID: :0x23
>> Start operation done successfully at partition 0x23
>>
>>
>> Memory Programming ...
>> Opening and parsing file: st-image-userfs-openstlinux-weston-stm32mp1.ext4
>> File : st-image-userfs-openstlinux-weston-stm32mp1.ext4
>> Size : 128 MBytes
>> Partition ID : 0x24
>>
>> Download in Progress:
>>
>>
>> File download complete
>> Time elapsed during download operation: 00:00:39.209
>>
>> RUNNING Program ...
>> PartID: :0x24
>> Start operation done successfully at partition 0x24
>> Flashing service completed successfully
>>
>> ==============================================================
>> *** Spent 235s for operation.
>> *** (0h03m55s)
>> ==============================================================
>>
>> *** PROGRAMMER DONE ***
>> [04:11:48] Flashing operation success
>> [04:11:48] *************** Flashing operation complete with SUCCESS status ***************
>> [04:11:48] Release lock for board in DFU done.
>> [04:11:48] [DEBUG] RETURNCODE: 0
>> [04:11:48] Telnet connection available
>> [04:11:48] Configure bootpins:
>> [04:11:48] [DEBUG] BOOT_PIN INPUT: 12_13
>> [04:11:48] [DEBUG] BOOT_PIN[0]: 12
>> [04:11:48] [DEBUG] BOOT_PIN[1]: 13
>> [04:11:48] Reset boot pin to flash mode
>> [04:11:48] [DEBUG] D12=0
>> [04:11:48] Wait to get lock for /dev/ttyACM.nucleo_lmecxd0318_4...
>> [04:11:48] Activate lock for /dev/ttyACM.nucleo_lmecxd0318_4.
>> [04:11:49] D12=0
>> [04:11:49] Release lock for /dev/ttyACM.nucleo_lmecxd0318_4 done.
>> [04:11:49] [DEBUG] D13=0
>> [04:11:49] Wait to get lock for /dev/ttyACM.nucleo_lmecxd0318_4...
>> [04:11:49] Activate lock for /dev/ttyACM.nucleo_lmecxd0318_4.
>> [04:11:49] D13=0
>> [04:11:49] Release lock for /dev/ttyACM.nucleo_lmecxd0318_4 done.
>> [04:11:49] [DEBUG] on Media_boot mmc0
>> [04:11:49] [DEBUG] D12=1
>> [04:11:49] Wait to get lock for /dev/ttyACM.nucleo_lmecxd0318_4...
>> [04:11:49] Activate lock for /dev/ttyACM.nucleo_lmecxd0318_4.
>> [04:11:49] D12=1
>> [04:11:49] Release lock for /dev/ttyACM.nucleo_lmecxd0318_4 done.
>> [04:11:49] [DEBUG] D13=1
>> [04:11:49] Wait to get lock for /dev/ttyACM.nucleo_lmecxd0318_4...
>> [04:11:49] Activate lock for /dev/ttyACM.nucleo_lmecxd0318_4.
>> [04:11:49] D13=1
>> [04:11:49] Release lock for /dev/ttyACM.nucleo_lmecxd0318_4 done.
>> [04:11:49] Wait for Relay to be established: 1 ms
>> [04:11:50] Bootpins configure done.
>> [04:11:50] [DEBUG] /root/git/lava-config/scripts/epower_switch.sh -u epowerswitch_03.lme.st.com -p 3 -c OFF -n 2001
>> [04:11:50] [DEBUG] last digit correct
>> ePowerSwitch epowerswitch_03.lme.st.com selected 3
>> Set pwrSwitch epowerswitch_03.lme.st.com on prt 3 to Off
>> [04:11:50] [DEBUG] Switch Off Power supply
>> [04:11:50] [DEBUG] CMD: wget -O - http://epowerswitch_03.lme.st.com/hidden.htm?M0:O3=Off
>> [04:11:50] Boot_management script successfully executed
Returned 0 in 388 seconds
end: 1.1 deploy-flasher (duration 00:07:13) [common]
end: 1 deploy-flasher-retry (duration 00:07:13) [common]
start: 2 minimal-boot (timeout 00:12:47) [common]
start: 2.1 connect-device (timeout 00:12:47) [common]
[common] connect-device Connecting to device using 'telnet localhost 2001'
Setting prompt string to ['lava-test: # ']
end: 2.1 connect-device (duration 00:00:00) [common]
start: 2.2 reset-device (timeout 00:12:46) [common]
start: 2.2.1 pdu-reboot (timeout 00:12:46) [common]
Calling: 'nice' '/root/git/lava-config/scripts/epower_switch.sh' '-u' 'epowerswitch_03.lme.st.com' '-p' '3' '-c' 'REBOOT'
>> [04:11:51] [DEBUG] last digit correct
>> ePowerSwitch epowerswitch_03.lme.st.com selected 3
>> Send reboot command switch epowerswitch_03.lme.st.com on prt 3
>> [04:11:51] [DEBUG] Switch OFF Power supply
>> [04:11:51] [DEBUG] CMD: wget -O - http://epowerswitch_03.lme.st.com/hidden.htm?M0:O3=Off
>> [04:12:06] [DEBUG] Switch ON Power supply
>> [04:12:06] [DEBUG] CMD: wget -O - http://epowerswitch_03.lme.st.com/hidden.htm?M0:O3=On
Returned 0 in 15 seconds
end: 2.2.1 pdu-reboot (duration 00:00:16) [common]
case: pdu-reboot
case_id: 76364
definition: lava
duration: 15.89
extra: ...
level: 2.2.1
namespace: common
result: pass
end: 2.2 reset-device (duration 00:00:16) [common]
start: 2.3 auto-login-action (timeout 00:12:30) [common]
Setting prompt string to ['Linux version [0-9]']
auto-login-action: Wait for prompt ['Linux version [0-9]'] (timeout 00:25:00)
Trying 127.0.0.1...
Connected to localhost.
Escape character is '^]'.
Device open failure: Internal I/O error
Connection closed by foreign host.
Connection closed
end: 2.3 auto-login-action (duration 00:00:00) [common]
case: auto-login-action
case_id: 76365
definition: lava
duration: 0.00
extra: ...
level: 2.3
namespace: common
result: fail
minimal-boot failed: 1 of 2 attempts. 'Connection closed'
Retrying: 2 minimal-boot (timeout 00:12:47)
start: 2.1 connect-device (timeout 00:12:47) [common]
Dead connection, reconnecting
[common] connect-device Connecting to device using 'telnet localhost 2001'
Setting prompt string to ['lava-test: # ']
end: 2.1 connect-device (duration 00:00:00) [common]
start: 2.2 reset-device (timeout 00:12:46) [common]
start: 2.2.1 pdu-reboot (timeout 00:12:46) [common]
Calling: 'nice' '/root/git/lava-config/scripts/epower_switch.sh' '-u' 'epowerswitch_03.lme.st.com' '-p' '3' '-c' 'REBOOT'
>> [04:12:08] [DEBUG] last digit correct
>> ePowerSwitch epowerswitch_03.lme.st.com selected 3
>> Send reboot command switch epowerswitch_03.lme.st.com on prt 3
>> [04:12:08] [DEBUG] Switch OFF Power supply
>> [04:12:08] [DEBUG] CMD: wget -O - http://epowerswitch_03.lme.st.com/hidden.htm?M0:O3=Off
>> [04:12:23] [DEBUG] Switch ON Power supply
>> [04:12:23] [DEBUG] CMD: wget -O - http://epowerswitch_03.lme.st.com/hidden.htm?M0:O3=On
Returned 0 in 15 seconds
end: 2.2.1 pdu-reboot (duration 00:00:16) [common]
case: pdu-reboot
case_id: 76364
definition: lava
duration: 15.63
extra: ...
level: 2.2.1
namespace: common
result: pass
end: 2.2 reset-device (duration 00:00:16) [common]
start: 2.3 auto-login-action (timeout 00:12:31) [common]
Setting prompt string to ['Linux version [0-9]']
auto-login-action: Wait for prompt ['Linux version [0-9]'] (timeout 00:25:00)
Trying 127.0.0.1...
Connected to localhost.
Escape character is '^]'.
Device open failure: Internal I/O error
Connection closed by foreign host.
Connection closed
end: 2.3 auto-login-action (duration 00:00:00) [common]
case: auto-login-action
case_id: 76365
definition: lava
duration: 0.00
extra: ...
level: 2.3
namespace: common
result: fail
minimal-boot failed: 2 of 2 attempts. 'Connection closed'
Connection closed
end: 2 minimal-boot (duration 00:00:16) [common]
case: minimal-boot
case_id: 76368
definition: lava
duration: 15.94
extra: ...
level: 2
namespace: common
result: fail
Cleaning after the job
Cleaning up download directory: /var/lib/lava/dispatcher/tmp/lavafed-4096/deploy-flasher-du13oba8/layout
Cleaning up download directory: /var/lib/lava/dispatcher/tmp/lavafed-4096/deploy-flasher-du13oba8/tarball
start: 4.1 power-off (timeout 00:00:15) [common]
Calling: 'nice' '/root/git/lava-config/scripts/epower_switch.sh' '-u' 'epowerswitch_03.lme.st.com' '-p' '3' '-c' 'OFF'
>> [04:12:24] [DEBUG] last digit correct
>> ePowerSwitch epowerswitch_03.lme.st.com selected 3
>> Set pwrSwitch epowerswitch_03.lme.st.com on prt 3 to Off
>> [04:12:24] [DEBUG] Switch Off Power supply
>> [04:12:24] [DEBUG] CMD: wget -O - http://epowerswitch_03.lme.st.com/hidden.htm?M0:O3=Off
Returned 0 in 0 seconds
end: 4.1 power-off (duration 00:00:01) [common]
case: power-off
case_id: 76369
definition: lava
duration: 0.52
extra: ...
level: 4.1
namespace: common
result: pass
start: 4.2 read-feedback (timeout 00:00:29) [common]
Finalising connection for namespace 'common'
Already disconnected
end: 4.2 read-feedback (duration 00:00:00) [common]
Root tmp directory removed at /var/lib/lava/dispatcher/tmp/lavafed-4096
InfrastructureError: The Infrastructure is not working correctly. Please report this error to LAVA admins.
case: job
case_id: 76370
definition: lava
error_msg: Connection closed
error_type: Infrastructure
result: fail
Please read the triage guidelines for help on debugging failures in the test job, test definitions or in individual test cases.
Pipeline jobs use the job definition to generate a descriptive YAML file when the pipeline is validated. The file represents the data sent to the dispatcher at the start of the job, including details of the device as well as the job parameters and the details of the parameters sent to each of the deploy, boot and test actions in the job pipeline.
Click on the Metadata, Device or Job Actions headings below to see some of the information from the description file for this job or download the complete file as YAML using the link above.
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.