lava-dispatcher, installed at version: 2021.01.0018.gb56370de5 start: 0 validate Start time: 2021-02-19 09:11:10.912131+00:00 (UTC) Validating that https://files.lavasoftware.org/components/lava/standard/debian/stretch/armhf/3/initrd.img-4.9.0-4-armmp exists Validating that https://files.lavasoftware.org/components/lava/standard/debian/stretch/armhf/3/vmlinuz-4.9.0-4-armmp exists Validating that https://files.lavasoftware.org/components/lava/standard/debian/stretch/armhf/3/dtbs/sun7i-a20-cubietruck.dtb exists Validating that https://files.lavasoftware.org/components/lava/standard/debian/stretch/armhf/3/modules.tar.gz exists validate duration: 0.18 case: validate
case_id: 66015
definition: lava
result: pass
start: 1 tftp-deploy (timeout 00:04:00) [common] start: 1.1 download-retry (timeout 00:04:00) [common] start: 1.1.1 http-download (timeout 00:04:00) [common] Not decompressing ramdisk as can be used compressed. downloading https://files.lavasoftware.org/components/lava/standard/debian/stretch/armhf/3/initrd.img-4.9.0-4-armmp saving as /var/lib/lava/dispatcher/tmp/lavafed-3502/tftp-deploy-8n5djgeq/ramdisk/initrd.img-4.9.0-4-armmp total size: 16078096 (15MB) progress 0% (0MB) progress 5% (0MB) progress 10% (1MB) progress 15% (2MB) progress 20% (3MB) progress 25% (3MB) progress 30% (4MB) progress 35% (5MB) progress 40% (6MB) progress 45% (6MB) progress 50% (7MB) progress 55% (8MB) progress 60% (9MB) progress 65% (9MB) progress 70% (10MB) progress 75% (11MB) progress 80% (12MB) progress 85% (13MB) progress 90% (13MB) progress 95% (14MB) progress 100% (15MB) 15MB downloaded in 0.36s (42.72MB/s) end: 1.1.1 http-download (duration 00:00:00) [common] case: http-download
case_id: 66016
definition: lava
duration: 0.36
extra: ...
level: 1.1.1
namespace: common
result: pass
end: 1.1 download-retry (duration 00:00:00) [common] start: 1.2 download-retry (timeout 00:04:00) [common] start: 1.2.1 http-download (timeout 00:04:00) [common] downloading https://files.lavasoftware.org/components/lava/standard/debian/stretch/armhf/3/vmlinuz-4.9.0-4-armmp saving as /var/lib/lava/dispatcher/tmp/lavafed-3502/tftp-deploy-8n5djgeq/kernel/vmlinuz-4.9.0-4-armmp total size: 3707576 (3MB) No compression specified progress 0% (0MB) progress 5% (0MB) progress 10% (0MB) progress 15% (0MB) progress 20% (0MB) progress 25% (0MB) progress 30% (1MB) progress 35% (1MB) progress 40% (1MB) progress 45% (1MB) progress 50% (1MB) progress 55% (1MB) progress 60% (2MB) progress 65% (2MB) progress 70% (2MB) progress 75% (2MB) progress 80% (2MB) progress 85% (3MB) progress 90% (3MB) progress 95% (3MB) progress 100% (3MB) 3MB downloaded in 0.16s (22.14MB/s) end: 1.2.1 http-download (duration 00:00:00) [common] case: http-download
case_id: 66016
definition: lava
duration: 0.16
extra: ...
level: 1.2.1
namespace: common
result: pass
end: 1.2 download-retry (duration 00:00:00) [common] start: 1.3 download-retry (timeout 00:03:59) [common] start: 1.3.1 http-download (timeout 00:03:59) [common] downloading https://files.lavasoftware.org/components/lava/standard/debian/stretch/armhf/3/dtbs/sun7i-a20-cubietruck.dtb saving as /var/lib/lava/dispatcher/tmp/lavafed-3502/tftp-deploy-8n5djgeq/dtb/sun7i-a20-cubietruck.dtb total size: 35938 (0MB) No compression specified progress 91% (0MB) progress 100% (0MB) 0MB downloaded in 0.04s (0.77MB/s) end: 1.3.1 http-download (duration 00:00:00) [common] case: http-download
case_id: 66016
definition: lava
duration: 0.05
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:03:59) [common] start: 1.4.1 http-download (timeout 00:03:59) [common] downloading https://files.lavasoftware.org/components/lava/standard/debian/stretch/armhf/3/modules.tar.gz saving as /var/lib/lava/dispatcher/tmp/lavafed-3502/tftp-deploy-8n5djgeq/modules/modules.tar total size: 40209031 (38MB) Using gunzip to decompress gz progress 0% (0MB) progress 5% (1MB) progress 10% (3MB) progress 15% (5MB) progress 20% (7MB) progress 25% (9MB) progress 30% (11MB) progress 35% (13MB) progress 40% (15MB) progress 45% (17MB) progress 50% (19MB) progress 55% (21MB) progress 60% (23MB) progress 65% (24MB) progress 70% (26MB) progress 75% (28MB) progress 80% (30MB) progress 85% (32MB) progress 90% (34MB) progress 95% (36MB) progress 100% (38MB) 38MB downloaded in 1.95s (19.67MB/s) end: 1.4.1 http-download (duration 00:00:02) [common] case: http-download
case_id: 66016
definition: lava
duration: 1.95
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:03:57) [common] start: 1.5.1 extract-nfsrootfs (timeout 00:03:57) [common] end: 1.5.1 extract-nfsrootfs (duration 00:00:00) [common] start: 1.5.2 lava-overlay (timeout 00:03:57) [common] [common] Preparing overlay tarball in /var/lib/lava/dispatcher/tmp/lavafed-3502/lava-overlay-m67izeb3 makedir: /var/lib/lava/dispatcher/tmp/lavafed-3502/lava-overlay-m67izeb3/lava-3502/bin makedir: /var/lib/lava/dispatcher/tmp/lavafed-3502/lava-overlay-m67izeb3/lava-3502/tests makedir: /var/lib/lava/dispatcher/tmp/lavafed-3502/lava-overlay-m67izeb3/lava-3502/results Creating /var/lib/lava/dispatcher/tmp/lavafed-3502/lava-overlay-m67izeb3/lava-3502/bin/lava-add-keys Creating /var/lib/lava/dispatcher/tmp/lavafed-3502/lava-overlay-m67izeb3/lava-3502/bin/lava-add-sources Creating /var/lib/lava/dispatcher/tmp/lavafed-3502/lava-overlay-m67izeb3/lava-3502/bin/lava-background-process-start Creating /var/lib/lava/dispatcher/tmp/lavafed-3502/lava-overlay-m67izeb3/lava-3502/bin/lava-background-process-stop Creating /var/lib/lava/dispatcher/tmp/lavafed-3502/lava-overlay-m67izeb3/lava-3502/bin/lava-common-functions Creating /var/lib/lava/dispatcher/tmp/lavafed-3502/lava-overlay-m67izeb3/lava-3502/bin/lava-echo-ipv4 Creating /var/lib/lava/dispatcher/tmp/lavafed-3502/lava-overlay-m67izeb3/lava-3502/bin/lava-install-packages Creating /var/lib/lava/dispatcher/tmp/lavafed-3502/lava-overlay-m67izeb3/lava-3502/bin/lava-installed-packages Creating /var/lib/lava/dispatcher/tmp/lavafed-3502/lava-overlay-m67izeb3/lava-3502/bin/lava-os-build Creating /var/lib/lava/dispatcher/tmp/lavafed-3502/lava-overlay-m67izeb3/lava-3502/bin/lava-probe-channel Creating /var/lib/lava/dispatcher/tmp/lavafed-3502/lava-overlay-m67izeb3/lava-3502/bin/lava-probe-ip Creating /var/lib/lava/dispatcher/tmp/lavafed-3502/lava-overlay-m67izeb3/lava-3502/bin/lava-target-ip Creating /var/lib/lava/dispatcher/tmp/lavafed-3502/lava-overlay-m67izeb3/lava-3502/bin/lava-target-mac Creating /var/lib/lava/dispatcher/tmp/lavafed-3502/lava-overlay-m67izeb3/lava-3502/bin/lava-target-storage Creating /var/lib/lava/dispatcher/tmp/lavafed-3502/lava-overlay-m67izeb3/lava-3502/bin/lava-test-case Creating /var/lib/lava/dispatcher/tmp/lavafed-3502/lava-overlay-m67izeb3/lava-3502/bin/lava-test-event Creating /var/lib/lava/dispatcher/tmp/lavafed-3502/lava-overlay-m67izeb3/lava-3502/bin/lava-test-feedback Creating /var/lib/lava/dispatcher/tmp/lavafed-3502/lava-overlay-m67izeb3/lava-3502/bin/lava-test-raise Creating /var/lib/lava/dispatcher/tmp/lavafed-3502/lava-overlay-m67izeb3/lava-3502/bin/lava-test-reference Creating /var/lib/lava/dispatcher/tmp/lavafed-3502/lava-overlay-m67izeb3/lava-3502/bin/lava-test-runner Creating /var/lib/lava/dispatcher/tmp/lavafed-3502/lava-overlay-m67izeb3/lava-3502/bin/lava-test-set Creating /var/lib/lava/dispatcher/tmp/lavafed-3502/lava-overlay-m67izeb3/lava-3502/bin/lava-test-shell Creating /var/lib/lava/dispatcher/tmp/lavafed-3502/lava-overlay-m67izeb3/lava-3502/environment LAVA metadata - LAVA_JOB_ID=3502 start: 1.5.2.1 ssh-authorize (timeout 00:03:57) [common] end: 1.5.2.1 ssh-authorize (duration 00:00:00) [common] start: 1.5.2.2 lava-vland-overlay (timeout 00:03:57) [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:03:57) [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:03:57) [common] Loading test definitions start: 1.5.2.4.1 git-repo-action (timeout 00:03:57) [common] Using /lava-3502 at stage 0 Fetching tests from https://git.lavasoftware.org/lava/functional-tests.git Running '/usr/bin/git clone https://git.lavasoftware.org/lava/functional-tests.git /var/lib/lava/dispatcher/tmp/lavafed-3502/lava-overlay-m67izeb3/lava-3502/0/tests/0_smoke-tests --depth=1' Tests stored (tmp) in /var/lib/lava/dispatcher/tmp/lavafed-3502/lava-overlay-m67izeb3/lava-3502/0/tests/0_smoke-tests/posix/smoke-tests-basic.yaml uuid=3502_1.5.2.4.1 testdef=None end: 1.5.2.4.1 git-repo-action (duration 00:00:01) [common] case: git-repo-action
case_id: 66023
definition: lava
duration: 0.65
extra: ...
level: 1.5.2.4.1
namespace: common
result: pass
start: 1.5.2.4.2 test-overlay (timeout 00:03:57) [common] end: 1.5.2.4.2 test-overlay (duration 00:00:00) [common] case: test-overlay
case_id: 66024
definition: lava
duration: 0.00
extra: ...
level: 1.5.2.4.2
namespace: common
result: pass
start: 1.5.2.4.3 test-install-overlay (timeout 00:03:57) [common] end: 1.5.2.4.3 test-install-overlay (duration 00:00:00) [common] case: test-install-overlay
case_id: 66025
definition: lava
duration: 0.00
extra: ...
level: 1.5.2.4.3
namespace: common
result: pass
start: 1.5.2.4.4 test-runscript-overlay (timeout 00:03:57) [common] runner path: /var/lib/lava/dispatcher/tmp/lavafed-3502/lava-overlay-m67izeb3/lava-3502/0/tests/0_smoke-tests test_uuid 3502_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: 66026
definition: lava
duration: 0.00
extra: ...
level: 1.5.2.4.4
namespace: common
result: pass
Creating lava-test-runner.conf files Using lava-test-runner path: /var/lib/lava/dispatcher/tmp/lavafed-3502/lava-overlay-m67izeb3/lava-3502/0 for stage 0 - 0_smoke-tests end: 1.5.2.4 test-definition (duration 00:00:01) [common] start: 1.5.2.5 compress-overlay (timeout 00:03:57) [common] end: 1.5.2.5 compress-overlay (duration 00:00:00) [common] start: 1.5.2.6 persistent-nfs-overlay (timeout 00:03:57) [common] end: 1.5.2.6 persistent-nfs-overlay (duration 00:00:00) [common] end: 1.5.2 lava-overlay (duration 00:00:01) [common] start: 1.5.3 extract-overlay-ramdisk (timeout 00:03:57) [common] end: 1.5.3 extract-overlay-ramdisk (duration 00:00:01) [common] start: 1.5.4 extract-modules (timeout 00:03:56) [common] extracting modules file /var/lib/lava/dispatcher/tmp/lavafed-3502/tftp-deploy-8n5djgeq/modules/modules.tar to /var/lib/lava/dispatcher/tmp/lavafed-3502/extract-overlay-ramdisk-pj_iavrl/ramdisk end: 1.5.4 extract-modules (duration 00:00:01) [common] start: 1.5.5 apply-overlay-tftp (timeout 00:03:54) [common] [common] Applying overlay /var/lib/lava/dispatcher/tmp/lavafed-3502/compress-overlay-i7jgpxd7/overlay-1.5.2.5.tar.gz to ramdisk [common] Applying overlay /var/lib/lava/dispatcher/tmp/lavafed-3502/compress-overlay-i7jgpxd7/overlay-1.5.2.5.tar.gz to directory /var/lib/lava/dispatcher/tmp/lavafed-3502/extract-overlay-ramdisk-pj_iavrl/ramdisk end: 1.5.5 apply-overlay-tftp (duration 00:00:00) [common] start: 1.5.6 prepare-kernel (timeout 00:03:54) [common] start: 1.5.6.1 uboot-prepare-kernel (timeout 00:03:54) [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:03:54) [common] end: 1.5.7 configure-preseed-file (duration 00:00:00) [common] start: 1.5.8 compress-ramdisk (timeout 00:03:54) [common] Building ramdisk /var/lib/lava/dispatcher/tmp/lavafed-3502/extract-overlay-ramdisk-pj_iavrl/ramdisk.cpio containing /var/lib/lava/dispatcher/tmp/lavafed-3502/extract-overlay-ramdisk-pj_iavrl/ramdisk >> 237985 blocks Adding RAMdisk u-boot header. mkimage -A arm -T ramdisk -C none -d /var/lib/lava/dispatcher/tmp/lavafed-3502/extract-overlay-ramdisk-pj_iavrl/ramdisk.cpio.gz /var/lib/lava/dispatcher/tmp/lavafed-3502/extract-overlay-ramdisk-pj_iavrl/ramdisk.cpio.gz.uboot output: Image Name: output: Created: Fri Feb 19 09:11:32 2021 output: Image Type: ARM Linux RAMDisk Image (uncompressed) output: Data Size: 42954462 Bytes = 41947.72 KiB = 40.96 MiB output: Load Address: 00000000 output: Entry Point: 00000000 output: rename /var/lib/lava/dispatcher/tmp/lavafed-3502/extract-overlay-ramdisk-pj_iavrl/ramdisk.cpio.gz.uboot to /var/lib/lava/dispatcher/tmp/lavafed-3502/tftp-deploy-8n5djgeq/ramdisk/ramdisk.cpio.gz.uboot end: 1.5.8 compress-ramdisk (duration 00:00:16) [common] end: 1.5 prepare-tftp-overlay (duration 00:00:19) [common] start: 1.6 lxc-create-udev-rule-action (timeout 00:03: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:03: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:02:00) [common] start: 2.1 uboot-from-media (timeout 00:02:00) [common] end: 2.1 uboot-from-media (duration 00:00:00) [common] start: 2.2 bootloader-overlay (timeout 00:02:00) [common] substitutions: - {BOOTX}: bootz 0x42000000 0x43300000 0x43000000 - {DTB_ADDR}: 0x43000000 - {DTB}: lavafed-3502/tftp-deploy-8n5djgeq/dtb/sun7i-a20-cubietruck.dtb - {INITRD}: lavafed-3502/tftp-deploy-8n5djgeq/ramdisk/ramdisk.cpio.gz.uboot - {KERNEL_ADDR}: 0x42000000 - {KERNEL}: lavafed-3502/tftp-deploy-8n5djgeq/kernel/vmlinuz-4.9.0-4-armmp - {LAVA_MAC}: None - {PRESEED_CONFIG}: None - {PRESEED_LOCAL}: None - {RAMDISK_ADDR}: 0x43300000 - {RAMDISK}: lavafed-3502/tftp-deploy-8n5djgeq/ramdisk/ramdisk.cpio.gz.uboot - {ROOT_PART}: None - {ROOT}: None - {SERVER_IP}: 10.3.1.1 - {TEE_ADDR}: 0x83000000 - {TEE}: None Parsed boot commands: - setenv autoload no - setenv initrd_high 0xffffffff - setenv fdt_high 0xffffffff - dhcp - setenv serverip 10.3.1.1 - tftp 0x42000000 lavafed-3502/tftp-deploy-8n5djgeq/kernel/vmlinuz-4.9.0-4-armmp - tftp 0x43300000 lavafed-3502/tftp-deploy-8n5djgeq/ramdisk/ramdisk.cpio.gz.uboot - setenv initrd_size ${filesize} - tftp 0x43000000 lavafed-3502/tftp-deploy-8n5djgeq/dtb/sun7i-a20-cubietruck.dtb - setenv bootargs 'console=ttyS0,115200n8 root=/dev/ram0 ip=dhcp' - bootz 0x42000000 0x43300000 0x43000000 end: 2.2 bootloader-overlay (duration 00:00:00) [common] case: bootloader-overlay
case_id: 66039
definition: lava
duration: 0.01
extra: ...
level: 2.2
namespace: common
result: pass
start: 2.3 connect-device (timeout 00:02:00) [common] [common] connect-device Connecting to device using 'telnet staging03 7101' Setting prompt string to ['lava-test: # '] end: 2.3 connect-device (duration 00:00:01) [common] start: 2.4 uboot-commands (timeout 00:01:59) [common] start: 2.4.1 reset-device (timeout 00:01:59) [common] start: 2.4.1.1 pdu-reboot (timeout 00:01:59) [common] Calling: 'nice' '/usr/local/lab-scripts/snmp_pdu_control' '--hostname' 'pdu18' '--command' 'reboot' '--port' '14' '--delay' '30' >> pdu18 port 14 now powered off >> pdu18 port 14 now powered on >> pdu18 port 14 now power cycled Returned 0 in 36 seconds end: 2.4.1.1 pdu-reboot (duration 00:00:37) [common] case: pdu-reboot
case_id: 66048
definition: lava
duration: 37.10
extra: ...
level: 2.4.1.1
namespace: common
result: pass
end: 2.4.1 reset-device (duration 00:00:37) [common] start: 2.4.2 bootloader-interrupt (timeout 00:01:22) [common] Setting prompt string to ['Hit any key to stop autoboot'] bootloader-interrupt: Wait for prompt ['Hit any key to stop autoboot'] (timeout 00:02:00) Trying 10.3.3.1... Connected to staging03.lavalab. Escape character is '^]'. cubietruck01 7101 [115200 N81] � U-Boot SPL 2014.10+dfsg1-3 (Feb 21 2015 - 21:59:32) DRAM: 2048 MiB CPU: 960000000Hz, AXI/AHB/APB: 3/2/2 U-Boot 2014.10+dfsg1-3 (Feb 21 2015 - 21:59:32) Allwinner Technology CPU: Allwinner A20 (SUN7I) I2C: ready DRAM: 2 GiB MMC: SUNXI SD/MMC: 0 In: serial Out: serial Err: serial SCSI: SUNXI SCSI INIT SATA link 0 timeout. AHCI 0001.0100 32 slots 1 ports 3 Gbps 0x1 impl SATA mode flags: ncq stag pm led clo only pmp pio slum part ccc apst Net: dwmac.1c50000 Hit any key to stop autoboot: 2 end: 2.4.2 bootloader-interrupt (duration 00:00:00) [common] start: 2.4.3 bootloader-commands (timeout 00:01:22) [common] Setting prompt string to ['sun7i#'] bootloader-commands: Wait for prompt ['sun7i#'] (timeout 00:01:22)  0 Setting prompt string to ['sun7i#', 'Resetting CPU', 'Must RESET board to recover', 'TIMEOUT', 'Retry count exceeded', 'Retry time exceeded; starting again', 'ERROR: The remote end did not respond in time.', 'File not found', 'Bad Linux ARM64 Image magic!', 'Wrong Ramdisk Image Format', 'Ramdisk image is corrupt or invalid', 'ERROR: Failed to allocate', 'TFTP error: trying to overwrite reserved memory'] setenv autoload no sun7i# setenv autoload no bootloader-commands: Wait for prompt ['sun7i#', 'Resetting CPU', 'Must RESET board to recover', 'TIMEOUT', 'Retry count exceeded', 'Retry time exceeded; starting again', 'ERROR: The remote end did not respond in time.', 'File not found', 'Bad Linux ARM64 Image magic!', 'Wrong Ramdisk Image Format', 'Ramdisk image is corrupt or invalid', 'ERROR: Failed to allocate', 'TFTP error: trying to overwrite reserved memory'] (timeout 00:01:22) setenv autoload no setenv initrd_high 0xffffffff sun7i# setenv initrd_high 0xffffffff bootloader-commands: Wait for prompt ['sun7i#', 'Resetting CPU', 'Must RESET board to recover', 'TIMEOUT', 'Retry count exceeded', 'Retry time exceeded; starting again', 'ERROR: The remote end did not respond in time.', 'File not found', 'Bad Linux ARM64 Image magic!', 'Wrong Ramdisk Image Format', 'Ramdisk image is corrupt or invalid', 'ERROR: Failed to allocate', 'TFTP error: trying to overwrite reserved memory'] (timeout 00:01:22) setenv initrd_high 0xffffffff setenv fdt_high 0xffffffff sun7i# setenv fdt_high 0xffffffff bootloader-commands: Wait for prompt ['sun7i#', 'Resetting CPU', 'Must RESET board to recover', 'TIMEOUT', 'Retry count exceeded', 'Retry time exceeded; starting again', 'ERROR: The remote end did not respond in time.', 'File not found', 'Bad Linux ARM64 Image magic!', 'Wrong Ramdisk Image Format', 'Ramdisk image is corrupt or invalid', 'ERROR: Failed to allocate', 'TFTP error: trying to overwrite reserved memory'] (timeout 00:01:22) setenv fdt_high 0xffffffff dhcp sun7i# dhcp bootloader-commands: Wait for prompt ['sun7i#', 'Resetting CPU', 'Must RESET board to recover', 'TIMEOUT', 'Retry count exceeded', 'Retry time exceeded; starting again', 'ERROR: The remote end did not respond in time.', 'File not found', 'Bad Linux ARM64 Image magic!', 'Wrong Ramdisk Image Format', 'Ramdisk image is corrupt or invalid', 'ERROR: Failed to allocate', 'TFTP error: trying to overwrite reserved memory'] (timeout 00:01:21) dhcp dwmac.1c50000 Waiting for PHY auto negotiation to complete...... done Speed: 1000, full duplex BOOTP broadcast 1 BOOTP broadcast 2 BOOTP broadcast 3 BOOTP broadcast 4 BOOTP broadcast 5 BOOTP broadcast 6 DHCP client bound to address 10.15.1.209 (6765 ms) setenv serverip 10.3.1.1 sun7i# setenv serverip 10.3.1.1 bootloader-commands: Wait for prompt ['sun7i#', 'Resetting CPU', 'Must RESET board to recover', 'TIMEOUT', 'Retry count exceeded', 'Retry time exceeded; starting again', 'ERROR: The remote end did not respond in time.', 'File not found', 'Bad Linux ARM64 Image magic!', 'Wrong Ramdisk Image Format', 'Ramdisk image is corrupt or invalid', 'ERROR: Failed to allocate', 'TFTP error: trying to overwrite reserved memory'] (timeout 00:01:11) setenv serverip 10.3.1.1 tftp 0x42000000 lavafed-3502/tftp-deploy-8n5djgeq/kernel/vmlinuz-4.9.0-4-armmp sun7i# tftp 0x42000000 lavafed-3502/tftp-deploy-8n5djgeq/kernel/vmlinuz-4.9.0-4-armmp bootloader-commands: Wait for prompt ['sun7i#', 'Resetting CPU', 'Must RESET board to recover', 'TIMEOUT', 'Retry count exceeded', 'Retry time exceeded; starting again', 'ERROR: The remote end did not respond in time.', 'File not found', 'Bad Linux ARM64 Image magic!', 'Wrong Ramdisk Image Format', 'Ramdisk image is corrupt or invalid', 'ERROR: Failed to allocate', 'TFTP error: trying to overwrite reserved memory'] (timeout 00:01:11) tftp 0x42000000 lavafed-3502/tftp-deploy-8n5djgeq/kernel/vmlinuz-4.9.0-4-armmp Speed: 1000, full duplex Using dwmac.1c50000 device TFTP from server 10.3.1.1; our IP address is 10.15.1.209 Filename 'lavafed-3502/tftp-deploy-8n5djgeq/kernel/vmlinuz-4.9.0-4-armmp'. Load address: 0x42000000 Loading: *################################################################# ################################################################# ################################################################# ########################################################## 10.8 MiB/s done Bytes transferred = 3707576 (3892b8 hex) tftp 0x43300000 lavafed-3502/tftp-deploy-8n5djgeq/ramdisk/ramdisk.cpio.gz.uboot sun7i# tftp 0x43300000 lavafed-3502/tftp-deploy-8n5djgeq/ramdisk/ramdisk.cpio.gz.uboot bootloader-commands: Wait for prompt ['sun7i#', 'Resetting CPU', 'Must RESET board to recover', 'TIMEOUT', 'Retry count exceeded', 'Retry time exceeded; starting again', 'ERROR: The remote end did not respond in time.', 'File not found', 'Bad Linux ARM64 Image magic!', 'Wrong Ramdisk Image Format', 'Ramdisk image is corrupt or invalid', 'ERROR: Failed to allocate', 'TFTP error: trying to overwrite reserved memory'] (timeout 00:01:11) tftp 0x43300000 lavafed-3502/tftp-deploy-8n5djgeq/ramdisk/ramdisk.cpio.gz.uboot Speed: 1000, full duplex Using dwmac.1c50000 device TFTP from server 10.3.1.1; our IP address is 10.15.1.209 Filename 'lavafed-3502/tftp-deploy-8n5djgeq/ramdisk/ramdisk.cpio.gz.uboot'. Load address: 0x43300000 Loading: *################################################################# ################################################################# ################################################################# ################################################################# ################################################################# ################################################################# ################################################################# ################################################################# ################################################################# ################################################################# ################################################################# ################################################################# ################################################################# ################################################################# ################################################################# ################################################################# ################################################################# ################################################################# ################################################################# ################################################################# ################################################################# ################################################################# ################################################################# ################################################################# ################################################################# ################################################################# ################################################################# ################################################################# ################################################################# ################################################################# ################################################################# ################################################################# ################################################################# ################################################################# ################################################################# ################################################################# ################################################################# ################################################################# ################################################################# ################################################################# ################################################################# ################################################################# ################################################################# ################################################################# ################################################################# ## 10.9 MiB/s done Bytes transferred = 42954526 (28f6f1e hex) setenv initrd_size ${filesize} sun7i# setenv initrd_size ${filesize} bootloader-commands: Wait for prompt ['sun7i#', 'Resetting CPU', 'Must RESET board to recover', 'TIMEOUT', 'Retry count exceeded', 'Retry time exceeded; starting again', 'ERROR: The remote end did not respond in time.', 'File not found', 'Bad Linux ARM64 Image magic!', 'Wrong Ramdisk Image Format', 'Ramdisk image is corrupt or invalid', 'ERROR: Failed to allocate', 'TFTP error: trying to overwrite reserved memory'] (timeout 00:01:07) setenv initrd_size ${filesize} tftp 0x43000000 lavafed-3502/tftp-deploy-8n5djgeq/dtb/sun7i-a20-cubietruck.dtb sun7i# tftp 0x43000000 lavafed-3502/tftp-deploy-8n5djgeq/dtb/sun7i-a20-cubietruck.dtb bootloader-commands: Wait for prompt ['sun7i#', 'Resetting CPU', 'Must RESET board to recover', 'TIMEOUT', 'Retry count exceeded', 'Retry time exceeded; starting again', 'ERROR: The remote end did not respond in time.', 'File not found', 'Bad Linux ARM64 Image magic!', 'Wrong Ramdisk Image Format', 'Ramdisk image is corrupt or invalid', 'ERROR: Failed to allocate', 'TFTP error: trying to overwrite reserved memory'] (timeout 00:01:07) tftp 0x43000000 lavafed-3502/tftp-deploy-8n5djgeq/dtb/sun7i-a20-cubietruck.dtb Speed: 1000, full duplex Using dwmac.1c50000 device TFTP from server 10.3.1.1; our IP address is 10.15.1.209 Filename 'lavafed-3502/tftp-deploy-8n5djgeq/dtb/sun7i-a20-cubietruck.dtb'. Load address: 0x43000000 Loading: *### 5.7 MiB/s done Bytes transferred = 35938 (8c62 hex) setenv bootargs 'console=ttyS0,115200n8 root=/dev/ram0 ip=dhcp' sun7i# setenv bootargs 'console=ttyS0,115200n8 root=/dev/ram0 ip=dhcp' bootloader-commands: Wait for prompt ['sun7i#', 'Resetting CPU', 'Must RESET board to recover', 'TIMEOUT', 'Retry count exceeded', 'Retry time exceeded; starting again', 'ERROR: The remote end did not respond in time.', 'File not found', 'Bad Linux ARM64 Image magic!', 'Wrong Ramdisk Image Format', 'Ramdisk image is corrupt or invalid', 'ERROR: Failed to allocate', 'TFTP error: trying to overwrite reserved memory'] (timeout 00:01:07) setenv bootargs 'console=ttyS0,115200n8 root=/dev/ram0 ip=dhcp' bootz 0x42000000 0x43300000 0x43000000 sun7i# bootz 0x42000000 0x43300000 0x43000000 Setting prompt string to ['Starting kernel'] bootloader-commands: Wait for prompt ['Starting kernel'] (timeout 00:01:07) bootz 0x42000000 0x43300000 0x43000000 Kernel image @ 0x42000000 [ 0x000000 - 0x3892b8 ] ## Loading init Ramdisk from Legacy Image at 43300000 ... Image Name: Image Type: ARM Linux RAMDisk Image (uncompressed) Data Size: 42954462 Bytes = 41 MiB Load Address: 00000000 Entry Point: 00000000 Verifying Checksum ... OK ## Flattened Device Tree blob at 43000000 Booting using the fdt blob at 0x43000000 Using Device Tree in place at 43000000, end 4300bc61 Starting kernel ... end: 2.4.3 bootloader-commands (duration 00:00:16) [common] start: 2.4.4 auto-login-action (timeout 00:01:06) [common] Setting prompt string to ['Linux version [0-9]'] Setting prompt string to ['Linux version [0-9]', 'Resetting CPU', 'Must RESET board to recover', 'TIMEOUT', 'Retry count exceeded', 'Retry time exceeded; starting again', 'ERROR: The remote end did not respond in time.', 'File not found', 'Bad Linux ARM64 Image magic!', 'Wrong Ramdisk Image Format', 'Ramdisk image is corrupt or invalid', 'ERROR: Failed to allocate', 'TFTP error: trying to overwrite reserved memory'] auto-login-action: Wait for prompt ['Linux version [0-9]', 'Resetting CPU', 'Must RESET board to recover', 'TIMEOUT', 'Retry count exceeded', 'Retry time exceeded; starting again', 'ERROR: The remote end did not respond in time.', 'File not found', 'Bad Linux ARM64 Image magic!', 'Wrong Ramdisk Image Format', 'Ramdisk image is corrupt or invalid', 'ERROR: Failed to allocate', 'TFTP error: trying to overwrite reserved memory'] (timeout 00:02:00) [ 0.000000] Booting Linux on physical CPU 0x0 [ 0.000000] Linux version 4.9.0-4-armmp (debian-kernel@lists.debian.org) (gcc version 6.3.0 20170516 (Debian 6.3.0-18) ) #1 SMP Debian 4.9.65-3 (2017-12-03) [ 0.000000] CPU: ARMv7 Processor [410fc074] revision 4 (ARMv7), cr=10c5387d start: 2.4.4.1 login-action (timeout 00:01:00) [common] Setting prompt string to ['-+\\[ cut here \\]-+\\s+(.*\\s+-+\\[ end trace (\\w*) \\]-+)', '(Unhandled fault.*)\\r\\n', 'Kernel panic - (.*) end Kernel panic', 'Stack:\\s+(.*\\s+-+\\[ end trace (\\w*) \\]-+)'] Using line separator: #'\n'# No login prompt set. Parsing kernel messages ['-+\\[ cut here \\]-+\\s+(.*\\s+-+\\[ end trace (\\w*) \\]-+)', '(Unhandled fault.*)\\r\\n', 'Kernel panic - (.*) end Kernel panic', 'Stack:\\s+(.*\\s+-+\\[ end trace (\\w*) \\]-+)', '\\(initramfs\\)', 'Login timed out', 'Login incorrect'] [login-action] Waiting for messages, (timeout 00:01:00) [ 0.000000] CPU: div instructions available: patching division code [ 0.000000] CPU: PIPT / VIPT nonaliasing data cache, VIPT aliasing instruction cache [ 0.000000] OF: fdt:Machine model: Cubietech Cubietruck [ 0.000000] efi: Getting EFI parameters from FDT: [ 0.000000] efi: UEFI not found. [ 0.000000] cma: Reserved 16 MiB at 0xbf000000 [ 0.000000] Memory policy: Data cache writealloc [ 0.000000] psci: probing for conduit method from DT. [ 0.000000] psci: Using PSCI v0.1 Function IDs from DT [ 0.000000] percpu: Embedded 14 pages/cpu @eedc0000 s27596 r8192 d21556 u57344 [ 0.000000] Built 1 zonelists in Zone order, mobility grouping on. Total pages: 522560 [ 0.000000] Kernel command line: console=ttyS0,115200n8 root=/dev/ram0 ip=dhcp [ 0.000000] PID hash table entries: 4096 (order: 2, 16384 bytes) [ 0.000000] Dentry cache hash table entries: 131072 (order: 7, 524288 bytes) [ 0.000000] Inode-cache hash table entries: 65536 (order: 6, 262144 bytes) [ 0.000000] Memory: 2006688K/2097152K available (7168K kernel code, 1004K rwdata, 2212K rodata, 1024K init, 335K bss, 74080K reserved, 16384K cma-reserved, 1294336K highmem) [ 0.000000] Virtual kernel memory layout: [ 0.000000] vector : 0xffff0000 - 0xffff1000 ( 4 kB) [ 0.000000] fixmap : 0xffc00000 - 0xfff00000 (3072 kB) [ 0.000000] vmalloc : 0xf0800000 - 0xff800000 ( 240 MB) [ 0.000000] lowmem : 0xc0000000 - 0xf0000000 ( 768 MB) [ 0.000000] pkmap : 0xbfe00000 - 0xc0000000 ( 2 MB) [ 0.000000] modules : 0xbf000000 - 0xbfe00000 ( 14 MB) [ 0.000000] .text : 0xc0008000 - 0xc0800000 (8160 kB) [ 0.000000] .init : 0xc0b00000 - 0xc0c00000 (1024 kB) [ 0.000000] .data : 0xc0c00000 - 0xc0cfb10c (1005 kB) [ 0.000000] .bss : 0xc0cfd000 - 0xc0d50c0c ( 336 kB) [ 0.000000] Hierarchical RCU implementation. [ 0.000000] Build-time adjustment of leaf fanout to 32. [ 0.000000] RCU restricting CPUs from NR_CPUS=8 to nr_cpu_ids=2. [ 0.000000] RCU: Adjusting geometry for rcu_fanout_leaf=32, nr_cpu_ids=2 [ 0.000000] NR_IRQS:16 nr_irqs:16 16 [ 0.000000] arm_arch_timer: Architected cp15 timer(s) running at 24.00MHz (phys). [ 0.000000] clocksource: arch_sys_counter: mask: 0xffffffffffffff max_cycles: 0x588fe9dc0, max_idle_ns: 440795202592 ns [ 0.000007] sched_clock: 56 bits at 24MHz, resolution 41ns, wraps every 4398046511097ns [ 0.000021] Switching to timer-based delay loop, resolution 41ns [ 0.002684] clocksource: timer: mask: 0xffffffff max_cycles: 0xffffffff, max_idle_ns: 79635851949 ns [ 0.003563] clocksource: hstimer: mask: 0xffffffff max_cycles: 0xffffffff, max_idle_ns: 12741736309 ns [ 0.004333] Console: colour dummy device 80x30 [ 0.004373] Calibrating delay loop (skipped), value calculated using timer frequency.. 48.00 BogoMIPS (lpj=120000) [ 0.004390] pid_max: default: 32768 minimum: 301 [ 0.004654] Security Framework initialized [ 0.004669] Yama: disabled by default; enable with sysctl kernel.yama.* [ 0.004708] AppArmor: AppArmor disabled by boot time parameter [ 0.004877] Mount-cache hash table entries: 2048 (order: 1, 8192 bytes) [ 0.004891] Mountpoint-cache hash table entries: 2048 (order: 1, 8192 bytes) [ 0.005971] CPU: Testing write buffer coherency: ok [ 0.006035] ftrace: allocating 26738 entries in 79 pages [ 0.064204] /cpus/cpu@0 missing clock-frequency property [ 0.064238] /cpus/cpu@1 missing clock-frequency property [ 0.064252] CPU0: thread -1, cpu 0, socket 0, mpidr 80000000 [ 0.064301] Setting up static identity map for 0x40100000 - 0x40100098 [ 0.069777] EFI services will not be available. [ 0.071311] CPU1: thread -1, cpu 1, socket 0, mpidr 80000001 [ 0.071463] Brought up 2 CPUs [ 0.071485] SMP: Total of 2 processors activated (96.00 BogoMIPS). [ 0.071493] CPU: All CPU(s) started in HYP mode. [ 0.071498] CPU: Virtualization extensions available. [ 0.072682] devtmpfs: initialized [ 0.084127] VFP support v0.3: implementor 41 architecture 2 part 30 variant 7 rev 4 [ 0.084632] clocksource: jiffies: mask: 0xffffffff max_cycles: 0xffffffff, max_idle_ns: 9556302231375000 ns [ 0.084663] futex hash table entries: 512 (order: 3, 32768 bytes) [ 0.085578] pinctrl core: initialized pinctrl subsystem [ 0.087721] NET: Registered protocol family 16 [ 0.089564] DMA: preallocated 256 KiB pool for atomic coherent allocations [ 0.092095] No ATAGs? [ 0.092142] hw-breakpoint: found 5 (+1 reserved) breakpoint and 4 watchpoint registers. [ 0.092154] hw-breakpoint: maximum watchpoint size is 8 bytes. [ 0.093133] Serial: AMBA PL011 UART driver [ 0.127906] reg-fixed-voltage ahci-5v: could not find pctldev for node /soc@01c00000/pinctrl@01c20800/ahci_pwr_pin@1, deferring probe [ 0.127971] reg-fixed-voltage usb0-vbus: could not find pctldev for node /soc@01c00000/pinctrl@01c20800/usb0_vbus_pin@0, deferring probe [ 0.128007] reg-fixed-voltage usb1-vbus: could not find pctldev for node /soc@01c00000/pinctrl@01c20800/usb1_vbus_pin@0, deferring probe [ 0.128041] reg-fixed-voltage usb2-vbus: could not find pctldev for node /soc@01c00000/pinctrl@01c20800/usb2_vbus_pin@0, deferring probe [ 0.131643] vgaarb: loaded [ 0.132795] media: Linux media interface: v0.10 [ 0.132858] Linux video capture interface: v2.00 [ 0.132959] pps_core: LinuxPPS API ver. 1 registered [ 0.132966] pps_core: Software ver. 5.3.6 - Copyright 2005-2007 Rodolfo Giometti <giometti@linux.it> [ 0.132991] PTP clock support registered [ 0.135072] clocksource: Switched to clocksource arch_sys_counter [ 0.181508] VFS: Disk quotas dquot_6.6.0 [ 0.181620] VFS: Dquot-cache hash table entries: 1024 (order 0, 4096 bytes) [ 0.195771] NET: Registered protocol family 2 [ 0.196736] TCP established hash table entries: 8192 (order: 3, 32768 bytes) [ 0.196829] TCP bind hash table entries: 8192 (order: 4, 65536 bytes) [ 0.196951] TCP: Hash tables configured (established 8192 bind 8192) [ 0.197050] UDP hash table entries: 512 (order: 2, 16384 bytes) [ 0.197110] UDP-Lite hash table entries: 512 (order: 2, 16384 bytes) [ 0.197423] NET: Registered protocol family 1 [ 0.198071] Unpacking initramfs... [ 3.734275] Freeing initrd memory: 41948K [ 3.734893] hw perfevents: enabled with armv7_cortex_a7 PMU driver, 5 counters available [ 3.737056] audit: initializing netlink subsys (disabled) [ 3.737163] audit: type=2000 audit(3.700:1): initialized [ 3.738560] workingset: timestamp_bits=14 max_order=19 bucket_order=5 [ 3.738768] zbud: loaded [ 3.742463] bounce: pool size: 64 pages [ 3.742614] Block layer SCSI generic (bsg) driver version 0.4 loaded (major 247) [ 3.742813] io scheduler noop registered [ 3.742826] io scheduler deadline registered [ 3.742922] io scheduler cfq registered (default) [ 3.749107] sun7i-a20-pinctrl 1c20800.pinctrl: initialized sunXi PIO driver [ 3.764804] Serial: 8250/16550 driver, 4 ports, IRQ sharing disabled [ 3.767387] console [ttyS0] disabled [ 3.787634] 1c28000.serial: ttyS0 at MMIO 0x1c28000 (irq = 46, base_baud = 1500000) is a U6_16550A [ 4.451937] console [ttyS0] enabled [ 4.456376] Serial: AMBA driver [ 4.463009] libphy: Fixed MDIO Bus: probed [ 4.468157] mousedev: PS/2 mouse device common for all mice [ 4.476144] sunxi-rtc 1c20d00.rtc: rtc core: registered rtc-sunxi as rtc0 [ 4.482976] sunxi-rtc 1c20d00.rtc: RTC enabled [ 4.490556] ledtrig-cpu: registered to indicate activity on CPUs [ 4.497519] NET: Registered protocol family 10 [ 4.503245] mip6: Mobile IPv6 [ 4.506316] NET: Registered protocol family 17 [ 4.510802] mpls_gso: MPLS GSO support [ 4.514636] ThumbEE CPU extension supported. [ 4.518938] Registering SWP/SWPB emulation handler [ 4.524777] registered taskstats version 1 [ 4.529035] zswap: loaded using pool lzo/zbud [ 4.533759] ima: No TPM chip found, activating TPM-bypass! [ 4.549421] sunxi-rtc 1c20d00.rtc: setting system clock to 1970-01-01 00:00:22 UTC (22) [ 4.557500] sr_init: No PMIC hook to init smartreflex [ 4.562779] sr_init: platform driver register failed for SR [ 4.568814] vcc3v0: disabling [ 4.571832] vcc3v3: disabling [ 4.574799] vcc5v0: disabling [ 4.577781] ahci-5v: disabling [ 4.580855] usb0-vbus: disabling [ 4.584082] usb1-vbus: disabling [ 4.587320] usb2-vbus: disabling [ 4.592289] Freeing unused kernel memory: 1024K Loading, please wait... starting version 232 [ 4.717202] random: systemd-udevd: uninitialized urandom read (16 bytes read) [ 4.725465] random: systemd-udevd: uninitialized urandom read (16 bytes read) [ 4.725806] random: udevadm: uninitialized urandom read (16 bytes read) [ 4.727618] random: udevadm: uninitialized urandom read (16 bytes read) [ 4.728180] random: udevadm: uninitialized urandom read (16 bytes read) [ 4.728777] random: udevadm: uninitialized urandom read (16 bytes read) [ 4.729273] random: udevadm: uninitialized urandom read (16 bytes read) [ 4.729745] random: udevadm: uninitialized urandom read (16 bytes read) [ 4.730408] random: udevadm: uninitialized urandom read (16 bytes read) [ 4.730958] random: udevadm: uninitialized urandom read (16 bytes read) [ 5.015553] sunxi-mmc 1c0f000.mmc: Got CD GPIO [ 5.070827] sunxi-mmc 1c0f000.mmc: base:0xf08cd000 irq:27 [ 5.073432] SCSI subsystem initialized [ 5.074222] usbcore: registered new interface driver usbfs [ 5.074305] usbcore: registered new interface driver hub [ 5.080437] usbcore: registered new device driver usb [ 5.083539] ehci_hcd: USB 2.0 'Enhanced' Host Controller (EHCI) Driver [ 5.085880] ohci_hcd: USB 1.1 'Open' Host Controller (OHCI) Driver [ 5.087151] ohci-platform: OHCI generic platform driver [ 5.116095] ehci-platform: EHCI generic platform driver [ 5.128438] ohci-platform 1c14400.usb: Generic Platform OHCI controller [ 5.146385] ohci-platform 1c14400.usb: new USB bus registered, assigned bus number 1 [ 5.169168] ohci-platform 1c14400.usb: irq 31, io mem 0x01c14400 [ 5.181765] mmc0: host does not support reading read-only switch, assuming write-enable [ 5.199793] mmc0: new high speed SDHC card at address aaaa [ 5.207021] mmcblk0: mmc0:aaaa SU08G 7.40 GiB [ 5.213597] mmcblk0: p1 [ 5.239441] usb usb1: New USB device found, idVendor=1d6b, idProduct=0001 [ 5.246318] usb usb1: New USB device strings: Mfr=3, Product=2, SerialNumber=1 [ 5.253596] usb usb1: Product: Generic Platform OHCI controller [ 5.259554] usb usb1: Manufacturer: Linux 4.9.0-4-armmp ohci_hcd [ 5.265593] usb usb1: SerialNumber: 1c14400.usb [ 5.271279] hub 1-0:1.0: USB hub found [ 5.275225] hub 1-0:1.0: 1 port detected [ 5.335230] ahci-sunxi 1c18000.sata: controller can't do PMP, turning off CAP_PMP [ 5.342774] ahci-sunxi 1c18000.sata: forcing PORTS_IMPL to 0x1 [ 5.348703] ahci-sunxi 1c18000.sata: AHCI 0001.0100 32 slots 1 ports 3 Gbps 0x1 impl platform mode [ 5.357686] ahci-sunxi 1c18000.sata: flags: ncq sntf pm led clo only pio slum part ccc [ 5.367440] scsi host0: ahci-sunxi [ 5.371400] ata1: SATA max UDMA/133 mmio [mem 0x01c18000-0x01c18fff] port 0x100 irq 33 [ 5.380518] sun4i-ss 1c15000.crypto-engine: no reset control found [ 5.388380] sun4i-ss 1c15000.crypto-engine: Die ID 0 [ 5.397208] ehci-platform 1c14000.usb: EHCI Host Controller [ 5.402944] ehci-platform 1c14000.usb: new USB bus registered, assigned bus number 2 [ 5.411298] ehci-platform 1c14000.usb: irq 30, io mem 0x01c14000 [ 5.430146] ehci-platform 1c14000.usb: USB 2.0 started, EHCI 1.00 [ 5.436730] usb usb2: New USB device found, idVendor=1d6b, idProduct=0002 [ 5.443596] usb usb2: New USB device strings: Mfr=3, Product=2, SerialNumber=1 [ 5.450877] usb usb2: Product: EHCI Host Controller [ 5.455786] usb usb2: Manufacturer: Linux 4.9.0-4-armmp ehci_hcd [ 5.461815] usb usb2: SerialNumber: 1c14000.usb [ 5.467478] hub 2-0:1.0: USB hub found [ 5.471414] hub 2-0:1.0: 1 port detected [ 5.477489] usb_phy_generic.0.auto supply vcc not found, using dummy regulator [ 5.491532] musb-hdrc musb-hdrc.1.auto: MUSB HDRC host driver [ 5.497459] musb-hdrc musb-hdrc.1.auto: new USB bus registered, assigned bus number 3 [ 5.505645] usb usb3: New USB device found, idVendor=1d6b, idProduct=0002 [ 5.512488] usb usb3: New USB device strings: Mfr=3, Product=2, SerialNumber=1 [ 5.519781] usb usb3: Product: MUSB HDRC host driver [ 5.524791] usb usb3: Manufacturer: Linux 4.9.0-4-armmp musb-hcd [ 5.530839] usb usb3: SerialNumber: musb-hdrc.1.auto [ 5.536909] hub 3-0:1.0: USB hub found [ 5.540826] hub 3-0:1.0: 1 port detected [ 5.548808] sunxi-mmc 1c12000.mmc: allocated mmc-pwrseq [ 5.595128] sunxi-mmc 1c12000.mmc: base:0xf0d17000 irq:28 [ 5.601981] sunxi-wdt 1c20c90.watchdog: Watchdog enabled (timeout=16 sec, nowayout=0) [ 5.614315] sunxi-mmc 1c12000.mmc: smc 1 err, cmd 8, RTO !! [ 5.622438] ohci-platform 1c1c400.usb: Generic Platform OHCI controller [ 5.630497] ohci-platform 1c1c400.usb: new USB bus registered, assigned bus number 4 [ 5.650975] mmc1: queuing unknown CIS tuple 0x80 (2 bytes) [ 5.656975] ohci-platform 1c1c400.usb: irq 35, io mem 0x01c1c400 [ 5.666450] mmc1: queuing unknown CIS tuple 0x80 (3 bytes) [ 5.681407] mmc1: queuing unknown CIS tuple 0x80 (3 bytes) [ 5.697602] mmc1: queuing unknown CIS tuple 0x80 (7 bytes) [ 5.724492] usb usb4: New USB device found, idVendor=1d6b, idProduct=0001 [ 5.731361] usb usb4: New USB device strings: Mfr=3, Product=2, SerialNumber=1 [ 5.731421] ata1: SATA link down (SStatus 0 SControl 300) [ 5.744076] usb usb4: Product: Generic Platform OHCI controller [ 5.750136] usb usb4: Manufacturer: Linux 4.9.0-4-armmp ohci_hcd [ 5.756252] usb usb4: SerialNumber: 1c1c400.usb [ 5.761023] random: fast init done [ 5.765397] mmc1: new high speed SDIO card at address 0001 [ 5.765816] hub 4-0:1.0: USB hub found [ 5.765873] hub 4-0:1.0: 1 port detected [ 5.779292] Registered IR keymap rc-empty [ 5.783922] input: sunxi-ir as /devices/platform/soc@01c00000/1c21800.ir/rc/rc0/input0 [ 5.793271] rc rc0: sunxi-ir as /devices/platform/soc@01c00000/1c21800.ir/rc/rc0 [ 5.807865] lirc_dev: IR Remote Control driver registered, major 242 [ 5.814580] sunxi-ir 1c21800.ir: initialized sunXi IR driver [ 5.821994] ehci-platform 1c1c000.usb: EHCI Host Controller [ 5.827697] ehci-platform 1c1c000.usb: new USB bus registered, assigned bus number 5 [ 5.836384] ehci-platform 1c1c000.usb: irq 34, io mem 0x01c1c000 [ 5.844161] rc rc0: lirc_dev: driver ir-lirc-codec (sunxi-ir) registered at minor = 0 [ 5.853138] IR LIRC bridge handler initialized [ 5.857724] ehci-platform 1c1c000.usb: USB 2.0 started, EHCI 1.00 [ 5.865881] usb usb5: New USB device found, idVendor=1d6b, idProduct=0002 [ 5.872804] usb usb5: New USB device strings: Mfr=3, Product=2, SerialNumber=1 [ 5.880108] usb usb5: Product: EHCI Host Controller [ 5.884989] usb usb5: Manufacturer: Linux 4.9.0-4-armmp ehci_hcd [ 5.891020] usb usb5: SerialNumber: 1c1c000.usb [ 5.898001] hub 5-0:1.0: USB hub found [ 5.902018] hub 5-0:1.0: 1 port detected [ 5.913306] sun4i-codec 1c22c00.codec: Codec <-> 1c22c00.codec mapping ok [ 5.927600] axp20x-i2c 0-0034: AXP20x variant AXP209 found [ 5.944857] axp20x-i2c 0-0034: AXP20X driver loaded [ 5.958580] sun7i-dwmac 1c50000.ethernet: no regulator found [ 5.969887] sun7i-dwmac 1c50000.ethernet: no reset control found [ 5.979472] Ring mode enabled [ 5.982632] DMA HW capability register supported[ 5.987260] Normal descriptors [ 6.021234] libphy: stmmac: probed [ 6.024698] eth%d: PHY ID 001cc915 at 0 IRQ POLL (stmmac-0:00) active [ 6.031197] eth%d: PHY ID 001cc915 at 1 IRQ POLL (stmmac-0:01) [ 6.246352] input: axp20x-pek as /devices/platform/soc@01c00000/1c2ac00.i2c/i2c-0/0-0034/axp20x-pek/input/input1 [ 6.272483] usbcore: registered new interface driver brcmfmac [ 6.279780] brcmfmac mmc1:0001:1: firmware: failed to load brcm/brcmfmac43362-sdio.bin (-2) [ 6.288284] brcmfmac mmc1:0001:1: Direct firmware load for brcm/brcmfmac43362-sdio.bin failed with error -2 Begin: Loading essential drivers ... done. Begin: Running /scripts/init-premount ... done. Begin: Mounting root file system ... Begin: Running /scripts/local-top ... done. Begin: Running /scripts/local-premount ... done. Begin: Waiting for root file system ... [ 7.330231] brcmfmac: brcmf_sdio_htclk: HT Avail timeout (1000000): clkctl 0x50 Begin: Running /scripts/local-block ... done. [ 8.346382] brcmfmac: brcmf_sdio_htclk: HT Avail timeout (1000000): clkctl 0x50 Begin: Running /scripts/local-block ... done. Begin: Running /scripts/local-block ... done. Begin: Running /scripts/local-block ... done. Begin: Running /scripts/local-block ... done. Begin: Running /scripts/local-block ... done. Begin: Running /scripts/local-block ... done. Begin: Running /scripts/local-block ... done. Begin: Running /scripts/local-block ... done. Begin: Running /scripts/local-block ... done. Begin: Running /scripts/local-block ... done. Begin: Running /scripts/local-block ... done. Begin: Running /scripts/local-block ... done. Begin: Running /scripts/local-block ... done. Begin: Running /scripts/local-block ... done. Begin: Running /scripts/local-block ... done. Begin: Running /scripts/local-block ... done. Begin: Running /scripts/local-block ... done. Begin: Running /scripts/local-block ... done. Begin: Running /scripts/local-block ... done. Begin: Running /scripts/local-block ... done. Begin: Running /scripts/local-block ... done. Begin: Running /scripts/local-block ... done. Begin: Running /scripts/local-block ... done. Begin: Running /scripts/local-block ... done. Begin: Running /scripts/local-block ... done. Begin: Running /scripts/local-block ... done. Begin: Running /scripts/local-block ... done. Begin: Running /scripts/local-block ... done. Begin: Running /scripts/local-block ... done. Begin: Running /scripts/local-block ... done. done. Gave up waiting for root file system device. Common problems: - Boot args (cat /proc/cmdline) - Check rootdelay= (did the system wait long enough?) - Missing modules (cat /proc/modules; ls /dev) ALERT! /dev/ram0 does not exist. Dropping to a shell! BusyBox v1.22.1 (Debian 1:1.22.0-19+b3) built-in shell (ash) Enter 'help' for a list of built-in commands. Matched prompt #4: \(initramfs\) case: kernel-messages
case_id: 66049
definition: lava
duration: 34.06
extra: ...
level: 2.4.4.1
namespace: common
result: pass
Setting prompt string to ['\\(initramfs\\)'] end: 2.4.4.1 login-action (duration 00:00:34) [common] case: login-action
case_id: 66050
definition: lava
duration: 34.07
extra: ...
level: 2.4.4.1
namespace: common
result: pass
end: 2.4.4 auto-login-action (duration 00:00:40) [common] start: 2.4.5 expect-shell-connection (timeout 00:00:26) [common] Setting prompt string to ['\\(initramfs\\)'] Forcing a shell prompt, looking for ['\\(initramfs\\)'] (initramfs) [6n expect-shell-connection: Wait for prompt ['\\(initramfs\\)'] (timeout 00:02:00) Waiting using forced prompt support (timeout 00:01:00) end: 2.4.5 expect-shell-connection (duration 00:00:00) [common] start: 2.4.6 export-device-env (timeout 00:00:26) [common] end: 2.4.6 export-device-env (duration 00:00:00) [common] end: 2.4 uboot-commands (duration 00:01:33) [common] end: 2 uboot-action (duration 00:01:34) [common] start: 3 lava-test-retry (timeout 00:05:00) [common] start: 3.1 lava-test-shell (timeout 00:05:00) [common] Using namespace: common # (initramfs) [6n# lava-test-shell: Wait for prompt ['\\(initramfs\\)'] (timeout 00:05:00) # Using /lava-3502 export SHELL=/bin/sh (initramfs) [6nexport SHELL=/bin/sh export SHELL=/bin/sh . /lava-3502/environment (initramfs) [6n. /lava-3502/environment . /lava-3502/environment /lava-3502/bin/lava-test-runner /lava-3502/0 (initramfs) [6n/lava-3502/bin/lava-test-runner /lava-3502/0 Test shell timeout: 10s (minimum of the action and connection timeout) /lava-3502/bin/lava-test-runner /lava-3502/0 + export TESTRUN_ID=0_smoke-tests + cd /lava-3502/0/tests/0_smoke-tests + cat uuid + UUID=3502_1.5.2.4.1 + set +x <LAVA_SIGNAL_STARTRUN 0_smoke-tests 3502_1.5.2.4.1> + lava-test-case linux-posix-pwd --shell pwd <LAVA_SIGNAL_STARTTC linux-posix-pwd> /lava-3502/0/tests/0_smoke-tests Received signal: <STARTRUN> 0_smoke-tests 3502_1.5.2.4.1 Starting test lava.0_smoke-tests (3502_1.5.2.4.1) Skipping test definition patterns. Received signal: <STARTTC> linux-posix-pwd <LAVA_SIGNAL_ENDTC linux-posix-pwd> <LAVA_SIGNAL_TESTCASE TEST_CASE_ID=linux-posix-pwd RESULT=pass> + lava-test-case linux-posix-uname --shell uname -a <LAVA_SIGNAL_STARTTC linux-posix-uname> Received signal: <ENDTC> linux-posix-pwd Received signal: <TESTCASE> TEST_CASE_ID=linux-posix-pwd RESULT=pass case: linux-posix-pwd
case_id: 66051
definition: 0_smoke-tests
endtc: 819
result: pass
starttc: 814
Received signal: <STARTTC> linux-posix-uname Linux (none) 4.9.0-4-armmp #1 SMP Debian 4.9.65-3 (2017-12-03) armv7l GNU/Linux <LAVA_SIGNAL_ENDTC linux-posix-uname> Received signal: <ENDTC> linux-posix-uname <LAVA_SIGNAL_TESTCASE TEST_CASE_ID=linux-posix-uname RESULT=pass> + lava-test-case linux-posix-vmstat --shell vmstat <LAVA_SIGNAL_STARTTC linux-posix-vmstat> /lava-3502/0/../bin/lava-test-case: eval: line 1: vmstat: not found <LAVA_SIGNAL_ENDTC linux-posix-vmstat> Received signal: <TESTCASE> TEST_CASE_ID=linux-posix-uname RESULT=pass case: linux-posix-uname
case_id: 66052
definition: 0_smoke-tests
endtc: 825
result: pass
starttc: 822
Received signal: <STARTTC> linux-posix-vmstat Received signal: <ENDTC> linux-posix-vmstat <LAVA_SIGNAL_TESTCASE TEST_CASE_ID=linux-posix-vmstat RESULT=fail> Received signal: <TESTCASE> TEST_CASE_ID=linux-posix-vmstat RESULT=fail case: linux-posix-vmstat
case_id: 66053
definition: 0_smoke-tests
endtc: 834
result: fail
starttc: 833
+ lava-test-case linux-posix-ifconfig --shell ifconfig -a <LAVA_SIGNAL_STARTTC linux-posix-ifconfig> Received signal: <STARTTC> linux-posix-ifconfig eth0 Link encap:Ethernet HWaddr 02:8D:07:42:51:FA BROADCAST MULTICAST MTU:1500 Metric:1 RX packets:0 errors:0 dropped:0 overruns:0 frame:0 TX packets:0 errors:0 dropped:0 overruns:0 carrier:0 collisions:0 txqueuelen:1000 RX bytes:0 (0.0 B) TX bytes:0 (0.0 B) Interrupt:50 lo Link encap:Local Loopback LOOPBACK MTU:65536 Metric:1 RX packets:0 errors:0 dropped:0 overruns:0 frame:0 TX packets:0 errors:0 dropped:0 overruns:0 carrier:0 collisions:0 txqueuelen:1 RX bytes:0 (0.0 B) TX bytes:0 (0.0 B) <LAVA_SIGNAL_ENDTC linux-posix-ifconfig> Received signal: <ENDTC> linux-posix-ifconfig <LAVA_SIGNAL_TESTCASE TEST_CASE_ID=linux-posix-ifconfig RESULT=pass> + lava-test-case linux-posix-lscpu --shell lscpu <LAVA_SIGNAL_STARTTC linux-posix-lscpu> /lava-3502/0/../bin/lava-test-case: eval: line 1: lscpu: not found Received signal: <TESTCASE> TEST_CASE_ID=linux-posix-ifconfig RESULT=pass case: linux-posix-ifconfig
case_id: 66054
definition: 0_smoke-tests
endtc: 857
result: pass
starttc: 840
Received signal: <STARTTC> linux-posix-lscpu <LAVA_SIGNAL_ENDTC linux-posix-lscpu> Received signal: <ENDTC> linux-posix-lscpu <LAVA_SIGNAL_TESTCASE TEST_CASE_ID=linux-posix-lscpu RESULT=fail> + lava-test-case linux-posix-lsb_release --shell lsb_release -a <LAVA_SIGNAL_STARTTC linux-posix-lsb_release> /lava-3502/0/../bin/lava-test-case: eval: line 1: lsb_release: not found <LAVA_SIGNAL_ENDTC linux-posix-lsb_release> <LAVA_SIGNAL_TESTCASE TEST_CASE_ID=linux-posix-lsb_release RESULT=fail> + set +x Received signal: <TESTCASE> TEST_CASE_ID=linux-posix-lscpu RESULT=fail case: linux-posix-lscpu
case_id: 66055
definition: 0_smoke-tests
endtc: 866
result: fail
starttc: 864
Received signal: <STARTTC> linux-posix-lsb_release Received signal: <ENDTC> linux-posix-lsb_release Received signal: <TESTCASE> TEST_CASE_ID=linux-posix-lsb_release RESULT=fail case: linux-posix-lsb_release
case_id: 66056
definition: 0_smoke-tests
endtc: 877
result: fail
starttc: 876
<LAVA_SIGNAL_ENDRUN 0_smoke-tests 3502_1.5.2.4.1> <LAVA_TEST_RUNNER EXIT> Received signal: <ENDRUN> 0_smoke-tests 3502_1.5.2.4.1 Ending use of test pattern. Ending test lava.0_smoke-tests (3502_1.5.2.4.1), duration 0.18 case: 0_smoke-tests
case_id: 66057
commit_id: 6fe5657d02e9e0211c2a973c6f4742a1fa7c7314
definition: lava
duration: 0.18
namespace: common
path: posix/smoke-tests-basic.yaml
repository: https://git.lavasoftware.org/lava/functional-tests.git
result: pass
revision: unspecified
uuid: 3502_1.5.2.4.1
ok: lava_test_shell seems to have completed linux-posix-ifconfig: pass linux-posix-lsb_release: fail linux-posix-lscpu: fail linux-posix-pwd: pass linux-posix-uname: pass linux-posix-vmstat: fail end: 3.1 lava-test-shell (duration 00:00:01) [common] end: 3 lava-test-retry (duration 00:00:01) [common] start: 4 finalize (timeout 00:00:30) [common] start: 4.1 power-off (timeout 00:00:10) [common] Calling: 'nice' '/usr/local/lab-scripts/snmp_pdu_control' '--hostname' 'pdu18' '--command' 'off' '--port' '14' >> pdu18 port 14 now powered off Returned 0 in 3 seconds end: 4.1 power-off (duration 00:00:04) [common] case: power-off
case_id: 66058
definition: lava
duration: 4.00
extra: ...
level: 4.1
namespace: common
result: pass
start: 4.2 read-feedback (timeout 00:00:26) [common] Listened to connection for namespace 'common' for 1s Finalising connection for namespace 'common' Disconnecting ShellSession Disconnecting from telnet: Finalise ] quit (initramfs) [6nquit end: 4.2 read-feedback (duration 00:00:01) [common] end: 4 finalize (duration 00:00:05) [common] Cleaning after the job Cleaning up download directory: /var/lib/lava/dispatcher/tmp/lavafed-3502/tftp-deploy-8n5djgeq/ramdisk Cleaning up download directory: /var/lib/lava/dispatcher/tmp/lavafed-3502/tftp-deploy-8n5djgeq/kernel Cleaning up download directory: /var/lib/lava/dispatcher/tmp/lavafed-3502/tftp-deploy-8n5djgeq/dtb Cleaning up download directory: /var/lib/lava/dispatcher/tmp/lavafed-3502/tftp-deploy-8n5djgeq/modules Override tmp directory removed at /var/lib/lava/dispatcher/tmp/lavafed-3502 Root tmp directory removed at /var/lib/lava/dispatcher/tmp/lavafed-3502 Job finished correctly case: job
case_id: 66059
definition: lava
result: pass