lava-dispatcher, installed at version: 2018.2-1+stretch start: 0 validate Start time: 2018-02-22 05:01:09.373744+00:00 (UTC) Validating that http://134.86.62.223:8000/nfs/initrd.img exists Validating that http://134.86.62.223:8000/nfs/vmlinuz exists WARNING: Using boot commands supplied in the job definition, NOT the LAVA device configuration validate duration: 0.01 case: validate case_id: 445 definition: lava result: pass start: 1 tftp-deploy (timeout 00:08:00) [common] start: 1.1 download-retry (timeout 00:08:00) [common] start: 1.1.1 http-download (timeout 00:08:00) [common] Not decompressing ramdisk as can be used compressed. No compression specified. downloading http://134.86.62.223:8000/nfs/initrd.img saving as /var/lib/lava/dispatcher/tmp/171/tftp-deploy-pz6iqH/ramdisk/initrd.img total size: 17205723 (16MB) progress 0% (0MB) progress 5% (0MB) progress 10% (1MB) progress 15% (2MB) progress 20% (3MB) progress 25% (4MB) progress 30% (4MB) progress 35% (5MB) progress 40% (6MB) progress 45% (7MB) progress 50% (8MB) progress 55% (9MB) progress 60% (9MB) progress 65% (10MB) progress 70% (11MB) progress 75% (12MB) progress 80% (13MB) progress 85% (13MB) progress 90% (14MB) progress 95% (15MB) progress 100% (16MB) 16MB downloaded in 0.17s (96.38MB/s) end: 1.1.1 http-download (duration 00:00:00) [common] case: http-download case_id: 447 definition: lava duration: 0.17 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:08:00) [common] start: 1.2.1 http-download (timeout 00:08:00) [common] No compression specified. downloading http://134.86.62.223:8000/nfs/vmlinuz saving as /var/lib/lava/dispatcher/tmp/171/tftp-deploy-pz6iqH/kernel/vmlinuz total size: 4216608 (4MB) progress 0% (0MB) progress 5% (0MB) progress 10% (0MB) progress 15% (0MB) progress 20% (0MB) progress 25% (1MB) progress 30% (1MB) progress 35% (1MB) progress 40% (1MB) progress 45% (1MB) progress 50% (2MB) progress 55% (2MB) progress 60% (2MB) progress 65% (2MB) progress 70% (2MB) progress 75% (3MB) progress 80% (3MB) progress 85% (3MB) progress 90% (3MB) progress 95% (3MB) progress 100% (4MB) 4MB downloaded in 0.07s (56.92MB/s) end: 1.2.1 http-download (duration 00:00:00) [common] case: http-download case_id: 447 definition: lava duration: 0.07 extra: ... level: 1.2.1 namespace: common result: pass end: 1.2 download-retry (duration 00:00:00) [common] start: 1.3 prepare-tftp-overlay (timeout 00:08:00) [common] start: 1.3.1 extract-nfsrootfs (timeout 00:08:00) [common] end: 1.3.1 extract-nfsrootfs (duration 00:00:00) [common] start: 1.3.2 lava-overlay (timeout 00:08:00) [common] [common] Preparing overlay tarball in /var/lib/lava/dispatcher/tmp/171/lava-overlay-yNZASX makedir: /var/lib/lava/dispatcher/tmp/171/lava-overlay-yNZASX/lava-171/bin makedir: /var/lib/lava/dispatcher/tmp/171/lava-overlay-yNZASX/lava-171/tests makedir: /var/lib/lava/dispatcher/tmp/171/lava-overlay-yNZASX/lava-171/results Creating /var/lib/lava/dispatcher/tmp/171/lava-overlay-yNZASX/lava-171/bin/lava-add-keys Creating /var/lib/lava/dispatcher/tmp/171/lava-overlay-yNZASX/lava-171/bin/lava-add-sources Creating /var/lib/lava/dispatcher/tmp/171/lava-overlay-yNZASX/lava-171/bin/lava-background-process-start Creating /var/lib/lava/dispatcher/tmp/171/lava-overlay-yNZASX/lava-171/bin/lava-background-process-stop Creating /var/lib/lava/dispatcher/tmp/171/lava-overlay-yNZASX/lava-171/bin/lava-echo-ipv4 Creating /var/lib/lava/dispatcher/tmp/171/lava-overlay-yNZASX/lava-171/bin/lava-install-packages Creating /var/lib/lava/dispatcher/tmp/171/lava-overlay-yNZASX/lava-171/bin/lava-installed-packages Creating /var/lib/lava/dispatcher/tmp/171/lava-overlay-yNZASX/lava-171/bin/lava-os-build Creating /var/lib/lava/dispatcher/tmp/171/lava-overlay-yNZASX/lava-171/bin/lava-probe-channel Creating /var/lib/lava/dispatcher/tmp/171/lava-overlay-yNZASX/lava-171/bin/lava-probe-ip Creating /var/lib/lava/dispatcher/tmp/171/lava-overlay-yNZASX/lava-171/bin/lava-target-ip Creating /var/lib/lava/dispatcher/tmp/171/lava-overlay-yNZASX/lava-171/bin/lava-target-mac Creating /var/lib/lava/dispatcher/tmp/171/lava-overlay-yNZASX/lava-171/bin/lava-target-storage Creating /var/lib/lava/dispatcher/tmp/171/lava-overlay-yNZASX/lava-171/bin/lava-test-case Creating /var/lib/lava/dispatcher/tmp/171/lava-overlay-yNZASX/lava-171/bin/lava-test-feedback Creating /var/lib/lava/dispatcher/tmp/171/lava-overlay-yNZASX/lava-171/bin/lava-test-raise Creating /var/lib/lava/dispatcher/tmp/171/lava-overlay-yNZASX/lava-171/bin/lava-test-reference Creating /var/lib/lava/dispatcher/tmp/171/lava-overlay-yNZASX/lava-171/bin/lava-test-runner Creating /var/lib/lava/dispatcher/tmp/171/lava-overlay-yNZASX/lava-171/bin/lava-test-set Creating /var/lib/lava/dispatcher/tmp/171/lava-overlay-yNZASX/lava-171/bin/lava-test-shell Updating /var/lib/lava/dispatcher/tmp/171/lava-overlay-yNZASX/lava-171/bin/lava-add-keys (debian) Updating /var/lib/lava/dispatcher/tmp/171/lava-overlay-yNZASX/lava-171/bin/lava-add-sources (debian) Updating /var/lib/lava/dispatcher/tmp/171/lava-overlay-yNZASX/lava-171/bin/lava-install-packages (debian) Updating /var/lib/lava/dispatcher/tmp/171/lava-overlay-yNZASX/lava-171/bin/lava-installed-packages (debian) Updating /var/lib/lava/dispatcher/tmp/171/lava-overlay-yNZASX/lava-171/bin/lava-os-build (debian) start: 1.3.2.1 ssh-authorize (timeout 00:08:00) [common] end: 1.3.2.1 ssh-authorize (duration 00:00:00) [common] start: 1.3.2.2 lava-vland-overlay (timeout 00:08:00) [common] skipped lava-vland-overlay end: 1.3.2.2 lava-vland-overlay (duration 00:00:00) [common] start: 1.3.2.3 lava-multinode-overlay (timeout 00:08:00) [common] skipped lava-multinode-overlay end: 1.3.2.3 lava-multinode-overlay (duration 00:00:00) [common] start: 1.3.2.4 test-definition (timeout 00:08:00) [common] Loading test definitions start: 1.3.2.4.1 git-repo-action (timeout 00:08:00) [common] Using /lava-171 at stage 0 Symlink used from: /var/lib/lava/dispatcher/tmp/171/lava-overlay-yNZASX/lava-171/0/repos/git.linaro.org/lava-team/lava-functional-tests.git Runner path: /var/lib/lava/dispatcher/tmp/171/lava-overlay-yNZASX/lava-171/0/tests/0_smoke-tests Fetching tests from http://git.linaro.org/lava-team/lava-functional-tests.git Running '/usr/bin/git clone http://git.linaro.org/lava-team/lava-functional-tests.git /var/lib/lava/dispatcher/tmp/171/lava-overlay-yNZASX/lava-171/0/tests/0_smoke-tests --depth=1' Tests stored (tmp) in /var/lib/lava/dispatcher/tmp/171/lava-overlay-yNZASX/lava-171/0/tests/0_smoke-tests/lava-test-shell/smoke-tests-basic.yaml uuid=171_1.3.2.4.1 testdef={'testdef_pattern': {'pattern': '(?P.*-*)\\s+:\\s+(?P(PASS|pass|FAIL|fail|SKIP|skip|UNKNOWN|unknown))', 'fixupdict': {'FAIL': 'fail', 'SKIP': 'skip', 'UNKNOWN': 'unknown', 'PASS': 'pass'}}} end: 1.3.2.4.1 git-repo-action (duration 00:00:01) [common] case: git-repo-action case_id: 448 definition: lava duration: 1.46 extra: ... level: 1.3.2.4.1 namespace: common result: pass start: 1.3.2.4.2 test-overlay (timeout 00:07:58) [common] end: 1.3.2.4.2 test-overlay (duration 00:00:00) [common] case: test-overlay case_id: 449 definition: lava duration: 0.01 extra: ... level: 1.3.2.4.2 namespace: common result: pass start: 1.3.2.4.3 test-install-overlay (timeout 00:07:58) [common] end: 1.3.2.4.3 test-install-overlay (duration 00:00:00) [common] case: test-install-overlay case_id: 450 definition: lava duration: 0.01 extra: ... level: 1.3.2.4.3 namespace: common result: pass start: 1.3.2.4.4 test-runscript-overlay (timeout 00:07:58) [common] runner path: /var/lib/lava/dispatcher/tmp/171/lava-overlay-yNZASX/lava-171/0/tests/0_smoke-tests test_uuid 171_1.3.2.4.1 end: 1.3.2.4.4 test-runscript-overlay (duration 00:00:00) [common] case: test-runscript-overlay case_id: 451 definition: lava duration: 0.02 extra: ... level: 1.3.2.4.4 namespace: common result: pass Creating lava-test-runner.conf files Using lava-test-runner path: /var/lib/lava/dispatcher/tmp/171/lava-overlay-yNZASX/lava-171/0 for stage 0 - 0_smoke-tests end: 1.3.2.4 test-definition (duration 00:00:01) [common] start: 1.3.2.5 compress-overlay (timeout 00:07:58) [common] end: 1.3.2.5 compress-overlay (duration 00:00:00) [common] start: 1.3.2.6 persistent-nfs-overlay (timeout 00:07:58) [common] end: 1.3.2.6 persistent-nfs-overlay (duration 00:00:00) [common] end: 1.3.2 lava-overlay (duration 00:00:02) [common] start: 1.3.3 extract-overlay-ramdisk (timeout 00:07:58) [common] nice cpio -iud -F /var/lib/lava/dispatcher/tmp/171/extract-overlay-ramdisk-vduY2_/ramdisk.cpio command output 107284 blocks end: 1.3.3 extract-overlay-ramdisk (duration 00:00:00) [common] start: 1.3.4 extract-modules (timeout 00:07:58) [common] end: 1.3.4 extract-modules (duration 00:00:00) [common] start: 1.3.5 apply-overlay-tftp (timeout 00:07:58) [common] [common] Applying overlay /var/lib/lava/dispatcher/slave/tmp/171/overlay-1.3.2.5.tar.gz to ramdisk [common] Applying overlay /var/lib/lava/dispatcher/slave/tmp/171/overlay-1.3.2.5.tar.gz to directory /var/lib/lava/dispatcher/tmp/171/extract-overlay-ramdisk-vduY2_/ramdisk end: 1.3.5 apply-overlay-tftp (duration 00:00:00) [common] start: 1.3.6 prepare-kernel (timeout 00:07:58) [common] end: 1.3.6 prepare-kernel (duration 00:00:00) [common] start: 1.3.7 configure-preseed-file (timeout 00:07:58) [common] end: 1.3.7 configure-preseed-file (duration 00:00:00) [common] start: 1.3.8 compress-ramdisk (timeout 00:07:58) [common] Building ramdisk /var/lib/lava/dispatcher/tmp/171/extract-overlay-ramdisk-vduY2_/ramdisk.cpio containing /var/lib/lava/dispatcher/tmp/171/extract-overlay-ramdisk-vduY2_/ramdisk find . | cpio --create --format='newc' > /var/lib/lava/dispatcher/tmp/171/extract-overlay-ramdisk-vduY2_/ramdisk.cpio 107846 blocks rename /var/lib/lava/dispatcher/tmp/171/extract-overlay-ramdisk-vduY2_/ramdisk.cpio.gz to /var/lib/lava/dispatcher/tmp/171/tftp-deploy-pz6iqH/ramdisk/ramdisk.cpio.gz end: 1.3.8 compress-ramdisk (duration 00:00:02) [common] end: 1.3 prepare-tftp-overlay (duration 00:00:04) [common] start: 1.4 lxc-create-udev-rule-action (timeout 00:07:56) [common] No LXC device requested end: 1.4 lxc-create-udev-rule-action (duration 00:00:00) [common] start: 1.5 deploy-device-env (timeout 00:07:56) [common] end: 1.5 deploy-device-env (duration 00:00:00) [common] Checking files for TFTP limit of 4294967296 bytes. end: 1 tftp-deploy (duration 00:00:04) [common] start: 2 bootloader-action (timeout 00:02:00) [common] start: 2.1 bootloader-overlay (timeout 00:02:00) [common] Parsed boot commands: dhcp net0; set console console=ttyS0,115200n8 lava_mac={LAVA_MAC}; set extraargs ip=dhcp root=/dev/sda1; kernel tftp://134.86.62.86/171/tftp-deploy-pz6iqH/kernel/vmlinuz ${extraargs} ${console}; initrd tftp://134.86.62.86/171/tftp-deploy-pz6iqH/ramdisk/ramdisk.cpio.gz; boot end: 2.1 bootloader-overlay (duration 00:00:00) [common] start: 2.2 connect-device (timeout 00:02:00) [common] [common] connect-device Connecting to device using 'telnet localhost 8021' end: 2.2 connect-device (duration 00:00:00) [common] start: 2.3 bootloader-retry (timeout 00:02:00) [common] start: 2.3.1 reset-device (timeout 00:02:00) [common] start: 2.3.1.1 send-reboot-commands (timeout 00:02:00) [common] No soft reboot command defined in the test job. Using defaults. reboot reboot reboot -n reboot -n reboot -nf reboot -nf send-reboot-commands: Wait for prompt The system is going down for reboot NOW (timeout 00:02:00) Trying ::1... Connected to localhost. Escape character is '^]'. ser2net port 8021 device /dev/ttyS0 [115200 N81] (Debian GNU/Linux) reboot reboot -n[[0;32m OK [0m] Closed Load/Save RF Kill Switch Status /dev/rfkill Watch. [[0;32m OK [0m] Stopped target Graphical Interface. [[0;32m OK [0[[0;32m OK [0m] Stopped Daily apt upgrade and clean activities. reboot -nf [[0;32m OK [0m] Stopped Session 1 of user root. [[0;32m OK [0m] Removed slice User Slice of root. Stopping Login Service... Stopping Permit User Sessions... [[0;32m OK [0m] Stopped Permit User Sessions. [[0;32m OK [0m] Stopped target Remote File Systems. [[0;32m OK [0m] Stopped Login Service. [ 764.893598] lxcbr0: port 1(veth9EPBLD) entered disabled state [ 765.130337] lxcbr0: port 1(veth9EPBLD) entered disabled state [ 765.137313] device veth9EPBLD left promiscuous mode [ 765.142225] lxcbr0: port 1(veth9EPBLD) entered disabled state [[0;32m OK [0m] Stopped LXC Container: exenia. [[0;32m OK [0m] Removed slice system-lxc.slice. Stopping LXC Container Initialization and Autoboot Code... [[0;32m OK [0m] Stopped LXC Container Initialization and Autoboot Code. Stopping LXC network bridge setup... [[0;32m OK [0m] Stopped target Network. Stopping Network Manager... [[0;32m OK [0m] Stopped LXC network bridge setup. [[0;32m OK [0m] Stopped Network Manager. Stopping D-Bus System Message Bus... [[0;32m OK [0m] Stopped D-Bus System Message Bus. [[0;32m OK [0m] Stopped target Basic System. [[0;32m OK [0m] Stopped target Paths. [[0;32m OK [0m] Stopped target Slices. [[0;32m OK [0m] Removed slice User and Session Slice. [[0;32m OK [0m] Stopped target Sockets. [[0;32m OK [0m] Closed SWUpdate socket listener. [[0;32m OK [0m] Closed D-Bus System Message Bus Socket. [[0;32m OK [0m] Stopped target System Initialization. [[0;32m OK [0m] Stopped target Encrypted Volumes. [[0;32m OK [0m] Stopped Dispatch Password Requests to Console Directory Watch. [[0;32m OK [0m] Stopped Forward Password Requests to Wall Directory Watch. Stopping Load/Save Screen Backlight…htness of backlight:acpi_video0... [[0;32m OK [0m] Stopped Apply Kernel Variables. [[0;32m OK [0m] Stopped Load Kernel Modules. Stopping Update UTMP about System Boot/Shutdown... [[0;32m OK [0m] Stopped target Swap. Stopping Load/Save Random Seed... Stopping Network Time Synchronization... [[0;32m OK [0m] Stopped Network Time Synchronization. [[0;32m OK [0m] Stopped Update UTMP about System Boot/Shutdown. [[0;32m OK [0m] Stopped Create Volatile Files and Directories. [[0;32m OK [0m] Stopped target Local File Systems. Unmounting /run/user/0... [[0;32m OK [0m] Unmounted /run/user/0. [[0;32m OK [0m] Stopped Load/Save Screen Backlight …ightness of backlight:acpi_video0. [[0;32m OK [0m] Removed slice system-systemd\x2dbacklight.slice. [[0;32m OK [0m] Reached target Unmount All Filesystems. [[0;32m OK [0m] Stopped target Local File Systems (Pre). [[0;32m OK [0m] Stopped Create Static Device Nodes in /dev. [[0;32m OK [0m] Stopped Load/Save Random Seed. [[0;32m OK [0m] Stopped Remount Root and Kernel File Systems. [[0;32m OK [0m] Reached target Shutdown. [ 767.154275] watchdog: watchdog0: watchdog did not stop! [ 767.164652] systemd-shutdow: 24 output lines suppressed due to ratelimiting [ 767.186034] systemd-shutdown[1]: Sending SIGTERM to remaining processes... [ 767.200416] systemd-journald[210]: Received SIGTERM from PID 1 (systemd-shutdow). [ 767.215209] systemd-shutdown[1]: Sending SIGKILL to remaining processes... [ 767.228550] systemd-shutdown[1]: Hardware watchdog 'iTCO_wdt', version 0 [ 767.238047] systemd-shutdown[1]: Unmounting file systems. [ 767.243941] systemd-shutdown[1]: Remounting '/' read-only with options 'vers=3,rsize=1048576,wsize=1048576,namlen=255,hard,nolock,proto=tcp,port=2049,timeo=7,retrans=10,sec=sys,local_lock=all,addr=134.86.62.223'. [ 767.265504] systemd-shutdown[1]: Remounting '/' read-only with options 'vers=3,rsize=1048576,wsize=1048576,namlen=255,hard,nolock,proto=tcp,port=2049,timeo=7,retrans=10,sec=sys,local_lock=all,addr=134.86.62.223'. [ 767.284446] systemd-shutdown[1]: All filesystems unmounted. [ 767.290082] systemd-shutdown[1]: Deactivating swaps. [ 767.295779] systemd-shutdown[1]: All swaps deactivated. [ 767.301065] systemd-shutdown[1]: Detaching loop devices. [ 767.313410] kvm: exiting hardware virtualization [ 767.463303] reboot: Restarting system [ 767.466983] reboot: machine restart TSrs;;e1 Srs;;e1 RSrs;;e1 ok Matt hacked colour fix -- iPXE 1.0.0+ (8dd18) -- Open Source Network Boot Firmware -- http://ipxe.org Features: HTTP iSCSI DNS TFTP AoE SRP bzImage ELF MBOOT PXE PXEXT Menu Press Ctrl-B for the iPXE command line...                                         net0: 74:fe:48:1d:93:df using i210 on PCI03:00.0 (open) [Link:down, TX:0 TXE:0 RX:0 RXE:0] [Link status: Down (http://ipxe.org/38086101)] Waiting for link-up on net0... failed: Down (http://ipxe.org/38086101) net1: 74:fe:48:1d:93:e0 using i210 on PCI04:00.0 (open) [Link:up, TX:0 TXE:0 RX:0 RXE:0] DHCP (net1 74:fe:48:1d:93:e0)...... ok net1: 134.86.62.71/255.255.255.0 gw 134.86.62.254 Filename: pxelinux.0 Could not start download: Operation not supported (http://ipxe.org/3c092003) net2: 00:0b:ab:d1:97:5e using i210 on PCI07:00.0 (open) [Link:down, TX:0 TXE:0 RX:0 RXE:0] [Link status: Down (http://ipxe.org/38086101)] Waiting for link-up on net2... failed: Down (http://ipxe.org/38086101) net3: 00:0b:ab:d1:97:5d using i210 on PCI09:00.0 (open) [Link:down, TX:0 TXE:0 RX:0 RXE:0] [Link status: Down (http://ipxe.org/38086101)] send-reboot-commands timed out after 119 seconds end: 2.3.1.1 send-reboot-commands (duration 00:01:59) [common] case: send-reboot-commands case_id: 452 definition: lava duration: 119.00 extra: ... level: 2.3.1.1 namespace: common result: fail send-reboot-commands timed out after 119 seconds end: 2.3.1 reset-device (duration 00:01:59) [common] case: reset-device case_id: 453 definition: lava duration: 119.00 extra: ... level: 2.3.1 namespace: common result: fail bootloader-retry failed: 1 of 1 attempts. 'send-reboot-commands timed out after 119 seconds' send-reboot-commands timed out after 119 seconds end: 2.3 bootloader-retry (duration 00:00:00) [common] case: bootloader-retry case_id: 454 definition: lava duration: 0.00 extra: ... level: 2.3 namespace: common result: fail bootloader-action failed: 1 of 1 attempts. 'send-reboot-commands timed out after 119 seconds' send-reboot-commands timed out after 119 seconds end: 2 bootloader-action (duration 00:00:00) [common] case: bootloader-action case_id: 455 definition: lava duration: 0.00 extra: ... level: 2 namespace: common result: fail Cleaning after the job Cleaning up download directory: /var/lib/lava/dispatcher/tmp/171/tftp-deploy-pz6iqH/ramdisk Cleaning up download directory: /var/lib/lava/dispatcher/tmp/171/tftp-deploy-pz6iqH/kernel start: 4.1 power-off (timeout 00:03:00) [common] end: 4.1 power-off (duration 00:00:00) [common] case: power-off case_id: 456 definition: lava duration: 0.00 extra: ... level: 4.1 namespace: common result: pass start: 4.2 read-feedback (timeout 00:03:00) [common] No connection for namespace common end: 4.2 read-feedback (duration 00:00:00) [common] Override tmp directory removed at /var/lib/lava/dispatcher/tmp/171 Root tmp directory removed at /var/lib/lava/dispatcher/tmp/171 JobError: Your job cannot terminate cleanly. case: job case_id: 457 definition: lava error_msg: send-reboot-commands timed out after 119 seconds error_type: Job result: fail