2013-09-24 05:08:25 PM INFO: Attempting to connect to device 2013-09-24 05:08:25 PM DEBUG: expect (10): '['Connection closed by foreign host\\.', 'Connected\\.\r', 'Data Buffering Suspended\\.', ]' Trying 127.0.0.1... Connected to localhost. Escape character is '^]'. ser2net port 2000 device /dev/ttyUSB0 [115200 N81] (Debian GNU/Linux) 2013-09-24 05:08:35 PM INFO: Matched which means all-good 2013-09-24 05:08:35 PM DEBUG: [ACTION-B] Single node test! 2013-09-24 05:08:35 PM INFO: [ACTION-B] dummy_deploy is started with {u'target_type': u'oe'} 2013-09-24 05:08:35 PM DEBUG: setting status pass 2013-09-24 05:08:35 PM DEBUG: finally status pass 2013-09-24 05:08:35 PM INFO: [ACTION-E] dummy_deploy is finished successfully. 2013-09-24 05:08:35 PM INFO: [ACTION-B] lava_test_shell is started with {u'testdef_urls': [u'scp://root@192.168.1.203:/home/novello/ae/test/lava/test-definitions/common/passfail.yaml'], u'timeout': 1800} 2013-09-24 05:08:35 PM INFO: attempting to access master filesystem 2:lava 2013-09-24 05:08:35 PM DEBUG: sendline : 2013-09-24 05:08:35 PM DEBUG: send : 2013-09-24 05:08:35 PM DEBUG: send : 2013-09-24 05:08:35 PM DEBUG: expect (10): '['bash-4.2 \\[rc=(\\d+)\\]# ', ]' bash-4.2# [ 61.607429] imx-sdma 20ec000.sdma: firmware not found 2013-09-24 05:08:45 PM INFO: Booting the system master image. Attempt: 1 2013-09-24 05:08:45 PM INFO: Perform soft reboot the system 2013-09-24 05:08:45 PM DEBUG: send :  2013-09-24 05:08:45 PM DEBUG: sendline : reboot 2013-09-24 05:08:45 PM DEBUG: send : reboot 2013-09-24 05:08:45 PM DEBUG: send : 2013-09-24 05:08:45 PM DEBUG: expect (120): '[, 'Restarting system.', 'The system is going down for reboot NOW', 'Will now restart', 'U-Boot']' ^C bash-4.2# reboot bash-4.2# [ 64.890842] fec 2188000.ethernet eth0: Freescale FEC PHY driver [Generic PHY] (mii_bus:phy_addr=2188000.ethernet:01, irq=-1) [ 65.221352] EXT4-fs (mmcblk0p2): re-mounted. Opts: (null) The system is going down NOW! Sent SIGTERM to all processes Sent SIGKILL to all processes[ 66.887666] libphy: 2188000.ethernet:01 - Link is Up - 100/Full [ 67.275553] reboot: Restarting system 2013-09-24 05:08:49 PM DEBUG: expect (300): 'Linux version' U-Boot 2013.07-dirty (Sep 14 2013 - 13:16:19) CPU: Freescale i.MX6DL rev1.1 at 792 MHz Reset cause: WDOG Board: Wandboard DRAM: 1 GiB MMC: FSL_SDHC: 0, FSL_SDHC: 1 *** Warning - bad CRC, using default environment In: serial Out: serial Err: serial Net: FEC [PRIME] Warning: FEC using MAC address from net device Hit any key to stop autoboot: 1  0 mmc0 is current device SD/MMC found on device 0 395 bytes read in 27 ms (13.7 KiB/s) Importing environment from mmc (uEnv.txt)... Checking if uenvcmd is set ... Running uenvcmd ... 4329112 bytes read in 534 ms (7.7 MiB/s) 32884 bytes read in 200 ms (160.2 KiB/s) Kernel image @ 0x12000000 [ 0x000000 - 0x420e98 ] ## Flattened Device Tree blob at 11000000 Booting using the fdt blob at 0x11000000 Using Device Tree in place at 11000000, end 1100b073 Starting kernel ... [ 0.000000] Booting Linux on physical CPU 0x0 [ 0.000000] Initializing cgroup subsys cpuset [ 0.000000] Initializing cgroup subsys cpu [ 0.000000] Initializing cgroup subsys cpuacct [ 0.000000] Linux version 3.11.2013-09-24 05:08:57 PM DEBUG: expect (150): 'bash-4.2' 0+ (novello@asus) (gcc version 4.7.3 20130226 (prerelease) (crosstool-NG linaro-1.13.1-4.7-2013.03-20130313 - Linaro GCC 2013.03) ) #2 SMP Wed Sep 18 17:19:10 CEST 2013 [ 0.000000] CPU: ARMv7 Processor [412fc09a] revision 10 (ARMv7), cr=10c5387d [ 0.000000] CPU: PIPT / VIPT nonaliasing data cache, VIPT aliasing instruction cache [ 0.000000] Machine: Freescale i.MX6 Quad/DualLite (Device Tree), model: Wandboard i.MX6 Dual Lite Board [ 0.000000] cma: CMA: reserved 16 MiB at 3e800000 [ 0.000000] Memory policy: ECC disabled, Data cache writealloc [ 0.000000] PERCPU: Embedded 9 pages/cpu @c191c000 s14080 r8192 d14592 u36864 [ 0.000000] Built 1 zonelists in Zone order, mobility grouping on. Total pages: 260434 [ 0.000000] Kernel command line: console=ttymxc0,115200 root=/dev/mmcblk0p2 ro rootfstype=ext4 rootwait fixrtc video=HDMI-A-1:800x600@60 [ 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] allocated 2097152 bytes of page_cgroup [ 0.000000] please try 'cgroup_disable=memory' option if you don't want memory cgroups [ 0.000000] Memory: 1005700K/1048576K available (8398K kernel code, 876K rwdata, 3412K rodata, 469K init, 1015K bss, 42876K reserved, 270336K highmem) [ 0.000000] Virtual kernel memory layout: [ 0.000000] vector : 0xffff0000 - 0xffff1000 ( 4 kB) [ 0.000000] fixmap : 0xfff00000 - 0xfffe0000 ( 896 kB) [ 0.000000] vmalloc : 0xf0000000 - 0xff000000 ( 240 MB) [ 0.000000] lowmem : 0xc0000000 - 0xef800000 ( 760 MB) [ 0.000000] pkmap : 0xbfe00000 - 0xc0000000 ( 2 MB) [ 0.000000] modules : 0xbf000000 - 0xbfe00000 ( 14 MB) [ 0.000000] .text : 0xc0008000 - 0xc0b90a44 (11811 kB) [ 0.000000] .init : 0xc0b91000 - 0xc0c06700 ( 470 kB) [ 0.000000] .data : 0xc0c08000 - 0xc0ce3168 ( 877 kB) [ 0.000000] .bss : 0xc0ce3168 - 0xc0de0e7c (1016 kB) [ 0.000000] SLUB: HWalign=64, Order=0-3, MinObjects=0, CPUs=2, Nodes=1 [ 0.000000] Hierarchical RCU implementation. [ 0.000000] RCU restricting CPUs from NR_CPUS=4 to nr_cpu_ids=2. [ 0.000000] NR_IRQS:16 nr_irqs:16 16 [ 0.000000] L310 cache controller enabled [ 0.000000] l2x0: 16 ways, CACHE_ID 0x410000c8, AUX_CTRL 0x32050000, Cache size: 524288 B [ 0.000000] sched_clock: 32 bits at 66MHz, resolution 15ns, wraps every 65075ms [ 0.000000] CPU identified as i.MX6DL, silicon rev 1.1 [ 0.000000] Console: colour dummy device 80x30 [ 0.000988] Calibrating delay loop... 1581.05 BogoMIPS (lpj=7905280) [ 0.090139] pid_max: default: 32768 minimum: 301 [ 0.090356] Security Framework initialized [ 0.090381] AppArmor: AppArmor initialized [ 0.090595] Mount-cache hash table entries: 512 [ 0.096369] Initializing cgroup subsys memory [ 0.096406] Initializing cgroup subsys devices [ 0.096416] Initializing cgroup subsys freezer [ 0.096426] Initializing cgroup subsys net_cls [ 0.096435] Initializing cgroup subsys blkio [ 0.096444] Initializing cgroup subsys perf_event [ 0.096539] CPU: Testing write buffer coherency: ok [ 0.097097] CPU0: thread -1, cpu 0, socket 0, mpidr 80000000 [ 0.097220] Setting up static identity map for 0xc07ef678 - 0xc07ef6d0 [ 0.099389] CPU1: Booted secondary processor [ 0.187150] CPU1: thread -1, cpu 1, socket 0, mpidr 80000001 [ 0.187280] Brought up 2 CPUs [ 0.187300] SMP: Total of 2 processors activated (3162.11 BogoMIPS). [ 0.187310] CPU: All CPU(s) started in SVC mode. [ 0.188476] devtmpfs: initialized [ 0.193913] xor: measuring software checksum speed [ 0.287133] arm4regs : 1112.400 MB/sec [ 0.387130] 8regs : 863.200 MB/sec [ 0.487129] 32regs : 908.800 MB/sec [ 0.487138] xor: using function: arm4regs (1112.400 MB/sec) [ 0.487157] pinctrl core: initialized pinctrl subsystem [ 0.487547] regulator-dummy: no parameters [ 0.497406] NET: Registered protocol family 16 [ 0.527903] DMA: preallocated 256 KiB pool for atomic coherent allocations [ 0.536437] syscon 20c8000.anatop: regmap [mem 0x020c8000-0x020c8fff] registered [ 0.536715] vdd1p1: 800 <--> 1375 mV at 1100 mV [ 0.537046] vdd3p0: 2800 <--> 3150 mV at 3000 mV [ 0.537448] vdd2p5: 2000 <--> 2750 mV at 2400 mV [ 0.537749] cpu: 725 <--> 1450 mV at 1150 mV [ 0.538021] vddpu: 725 <--> 1450 mV at 1150 mV [ 0.538310] vddsoc: 725 <--> 1450 mV at 1200 mV [ 0.539588] syscon 20e0000.iomuxc-gpr: regmap [mem 0x020e0000-0x020e0037] registered [ 0.541780] syscon 21bc000.ocotp: regmap [mem 0x021bc000-0x021bffff] registered [ 0.543078] No ATAGs? [ 0.543104] hw-breakpoint: found 5 (+1 reserved) breakpoint and 1 watchpoint registers. [ 0.543114] hw-breakpoint: maximum watchpoint size is 4 bytes. [ 0.544500] imx6dl-pinctrl 20e0000.iomuxc: initialized IMX pinctrl driver [ 0.566389] bio: create slab at 0 [ 0.727631] raid6: int32x1 76 MB/s [ 0.897365] raid6: int32x2 135 MB/s [ 1.067321] raid6: int32x4 130 MB/s [ 1.237178] raid6: int32x8 141 MB/s [ 1.237188] raid6: using algorithm int32x8 (141 MB/s) [ 1.237195] raid6: using intx1 recovery algorithm [ 1.237955] edma-dma-engine edma-dma-engine.0: Can't allocate PaRAM dummy slot [ 1.237988] edma-dma-engine: probe of edma-dma-engine.0 failed with error -5 [ 1.238508] 2P5V: 2500 mV [ 1.238726] 3P3V: 3300 mV [ 1.241350] SCSI subsystem initialized [ 1.241856] usbcore: registered new interface driver usbfs [ 1.241920] usbcore: registered new interface driver hub [ 1.242054] usbcore: registered new device driver usb [ 1.243380] i2c i2c-0: IMX I2C adapter registered [ 1.244255] i2c i2c-1: IMX I2C adapter registered [ 1.244593] i2c i2c-2: IMX I2C adapter registered [ 1.244837] media: Linux media interface: v0.10 [ 1.244890] Linux video capture interface: v2.00 [ 1.244967] pps_core: LinuxPPS API ver. 1 registered [ 1.244975] pps_core: Software ver. 5.3.6 - Copyright 2005-2007 Rodolfo Giometti [ 1.244999] PTP clock support registered [ 1.245075] EDAC MC: Ver: 3.0.0 [ 1.246311] NetLabel: Initializing [ 1.246323] NetLabel: domain hash size = 128 [ 1.246329] NetLabel: protocols = UNLABELED CIPSOv4 [ 1.246397] NetLabel: unlabeled traffic allowed by default [ 1.246594] nfc: nfc_init: NFC Core ver 0.1 [ 1.246657] NET: Registered protocol family 39 [ 1.247212] Switched to clocksource mxc_timer1 [ 1.264095] AppArmor: AppArmor Filesystem Enabled [ 1.274775] NET: Registered protocol family 2 [ 1.275603] TCP established hash table entries: 8192 (order: 4, 65536 bytes) [ 1.275925] TCP bind hash table entries: 8192 (order: 4, 65536 bytes) [ 1.276071] TCP: Hash tables configured (established 8192 bind 8192) [ 1.276311] TCP: reno registered [ 1.276378] UDP hash table entries: 512 (order: 2, 16384 bytes) [ 1.276463] UDP-Lite hash table entries: 512 (order: 2, 16384 bytes) [ 1.276910] NET: Registered protocol family 1 [ 1.277401] RPC: Registered named UNIX socket transport module. [ 1.277414] RPC: Registered udp transport module. [ 1.277421] RPC: Registered tcp transport module. [ 1.277428] RPC: Registered tcp NFSv4.1 backchannel transport module. [ 1.278446] hw perfevents: enabled with ARMv7 Cortex-A9 PMU driver, 7 counters available [ 1.279072] wandboard-rfkill rfkill.14: Wandboard rfkill initialization [ 1.279149] wandboard-rfkill rfkill.14: initialize wifi chip [ 1.307351] wandboard-rfkill rfkill.14: wifi-rfkill registered. [ 1.307404] wandboard-rfkill rfkill.14: initialize bluetooth chip [ 1.337355] wandboard-rfkill rfkill.14: bluetooth-rfkill registered. [ 1.338575] audit: initializing netlink socket (disabled) [ 1.338615] type=2000 audit(1.329:1): initialized [ 1.554202] bounce pool size: 64 pages [ 1.558596] VFS: Disk quotas dquot_6.5.2 [ 1.558886] Dquot-cache hash table entries: 1024 (order 0, 4096 bytes) [ 1.561458] NFS: Registering the id_resolver key type [ 1.561501] Key type id_resolver registered [ 1.561510] Key type id_legacy registered [ 1.561549] fuse init (API version 7.22) [ 1.562427] bio: create slab at 1 [ 1.563655] Btrfs loaded [ 1.563877] msgmni has been set to 1468 [ 1.565413] Block layer SCSI generic (bsg) driver version 0.4 loaded (major 249) [ 1.565564] io scheduler noop registered [ 1.565575] io scheduler deadline registered [ 1.565714] io scheduler cfq registered (default) [ 1.566225] imx-weim 21b8000.weim: Driver registered. [ 1.572899] imx-sdma 20ec000.sdma: initialized [ 1.636438] Serial: 8250/16550 driver, 4 ports, IRQ sharing disabled [ 1.637878] Serial: IMX driver [ 1.638127] 2020000.serial: ttymxc0 at MMIO 0x2020000 (irq = 58) is a IMX [ 2.455006] console [ttymxc0] enabled [ 2.459314] 21ec000.serial: ttymxc2 at MMIO 0x21ec000 (irq = 60) is a IMX [ 2.467151] serial: Freescale lpuart driver [ 2.471663] [drm] Initialized drm 1.1.0 20060810 [ 2.476377] usbcore: registered new interface driver udl [ 2.485579] imx6dl-pinctrl 20e0000.iomuxc: pin MX6DL_PAD_GPIO_16 already requested by 21a8000.i2c; cannot claim for 2188000.ethernet [ 2.497540] imx6dl-pinctrl 20e0000.iomuxc: pin-133 (2188000.ethernet) status -22 [ 2.504947] imx6dl-pinctrl 20e0000.iomuxc: could not request pin 133 on device 20e0000.iomuxc [ 2.513498] fec 2188000.ethernet: Error applying setting, reverse things back [ 2.525762] libphy: fec_enet_mii_bus: probed [ 2.530535] fec 2188000.ethernet eth0: registered PHC device 0 [ 2.537301] ehci_hcd: USB 2.0 'Enhanced' Host Controller (EHCI) Driver [ 2.543835] ehci-omap: OMAP-EHCI Host Controller driver [ 2.549305] usbcore: registered new interface driver usb-storage [ 2.555836] platform 2184200.usb: Driver imx_usb requests probe deferral [ 2.563259] mousedev: PS/2 mouse device common for all mice [ 2.569817] snvs_rtc 20cc034.snvs-rtc-lp: rtc core: registered 20cc034.snvs-rtc-lp as rtc0 [ 2.578528] b2c2-flexcop: B2C2 FlexcopII/II(b)/III digital TV receiver chip loaded successfully [ 2.587526] usbcore: registered new interface driver dvb_usb_vp7045 [ 2.593876] usbcore: registered new interface driver dvb_usb_vp702x [ 2.600229] usbcore: registered new interface driver dvb_usb_gp8psk [ 2.606554] usbcore: registered new interface driver dvb_usb_dtt200u [ 2.612987] usbcore: registered new interface driver dvb_usb_a800 [ 2.619177] usbcore: registered new interface driver dvb_usb_dibusb_mb [ 2.625768] usbcore: registered new interface driver dvb_usb_dibusb_mc [ 2.632374] usbcore: registered new interface driver dvb_usb_nova_t_usb2 [ 2.639156] usbcore: registered new interface driver dvb_usb_umt_010 [ 2.645591] usbcore: registered new interface driver dvb_usb_m920x [ 2.651858] usbcore: registered new interface driver dvb_usb_digitv [ 2.658206] usbcore: registered new interface driver dvb_usb_cxusb [ 2.664448] usbcore: registered new interface driver dvb_usb_ttusb2 [ 2.670815] usbcore: registered new interface driver dvb_usb_dib0700 [ 2.677252] usbcore: registered new interface driver opera1 [ 2.682887] usbcore: registered new interface driver dvb_usb_af9005 [ 2.689279] usbcore: registered new interface driver pctv452e [ 2.695112] usbcore: registered new interface driver dw2102 [ 2.700807] usbcore: registered new interface driver dvb_usb_dtv5100 [ 2.707255] usbcore: registered new interface driver cinergyT2 [ 2.713153] usbcore: registered new interface driver dvb_usb_friio [ 2.719441] usbcore: registered new interface driver dvb_usb_az6027 [ 2.725777] usbcore: registered new interface driver dvb_usb_technisat_usb2 [ 2.732842] usbcore: registered new interface driver dvb_usb_af9015 [ 2.739204] usbcore: registered new interface driver dvb_usb_af9035 [ 2.745543] usbcore: registered new interface driver dvb_usb_anysee [ 2.751913] usbcore: registered new interface driver dvb_usb_au6610 [ 2.758262] usbcore: registered new interface driver dvb_usb_az6007 [ 2.764604] usbcore: registered new interface driver dvb_usb_ce6230 [ 2.770967] usbcore: registered new interface driver dvb_usb_ec168 [ 2.777256] usbcore: registered new interface driver dvb_usb_it913x [ 2.783589] usbcore: registered new interface driver dvb_usb_lmedm04 [ 2.790028] usbcore: registered new interface driver dvb_usb_gl861 [ 2.796275] usbcore: registered new interface driver dvb_usb_mxl111sf [ 2.802811] usbcore: registered new interface driver dvb_usb_rtl28xxu [ 2.809373] usbcore: registered new interface driver smsusb [ 2.815081] usbcore: registered new interface driver b2c2_flexcop_usb [ 2.821607] usbcore: registered new interface driver zr364xx [ 2.827357] usbcore: registered new interface driver stkwebcam [ 2.833267] usbcore: registered new interface driver s2255 [ 2.838856] usbcore: registered new interface driver uvcvideo [ 2.844605] USB Video Class driver (1.1.1) [ 2.848719] gspca_main: v2.14.0 registered [ 2.852883] usbcore: registered new interface driver Philips webcam [ 2.859169] cpia2: V4L-Driver for Vision CPiA2 based cameras v3.0.1 [ 2.865494] usbcore: registered new interface driver cpia2 [ 2.871075] usbcore: registered new interface driver sn9c102 [ 2.876739] au0828 driver loaded [ 2.880043] usbcore: registered new interface driver au0828 [ 2.885674] usbcore: registered new interface driver hdpvr [ 2.891403] usbcore: registered new interface driver pvrusb2 [ 2.897069] pvrusb2: V4L in-tree version:Hauppauge WinTV-PVR-USB2 MPEG2 Encoder/Tuner [ 2.904926] pvrusb2: Debug mask is 31 (0x1f) [ 2.909279] usbcore: registered new interface driver usbvision [ 2.915115] USBVision USB Video Device Driver for Linux : 0.9.11 [ 2.921239] usbcore: registered new interface driver stk1160 [ 2.926960] usbcore: registered new interface driver cx231xx [ 2.932655] cx231xx: Cx231xx dvb Extension initialized [ 2.937906] usbcore: registered new interface driver tm6000 [ 2.943541] usbcore: registered new interface driver em28xx [ 2.949142] Em28xx: Initialized (Em28xx dvb Extension) extension [ 2.955154] Em28xx: Initialized (Em28xx Input Extension) extension [ 2.961414] usbcore: registered new interface driver usbtv [ 2.968375] imx2-wdt 20bc000.wdog: IMX2+ Watchdog Timer enabled. timeout=60s (nowayout=1) [ 2.976908] cpuidle: using governor ladder [ 2.981044] cpuidle: using governor menu [ 2.985025] sdhci: Secure Digital Host Controller Interface driver [ 2.991230] sdhci: Copyright(c) Pierre Ossman [ 2.995858] sdhci-pltfm: SDHCI platform and OF driver helper [ 3.003482] mmc0: no vqmmc regulator found [ 3.007626] mmc0: no vmmc regulator found [ 3.057247] mmc0: SDHCI controller on 2190000.usdhc [2190000.usdhc] using ADMA [ 3.065934] mmc1: no vqmmc regulator found [ 3.070070] mmc1: no vmmc regulator found [ 3.117216] mmc1: SDHCI controller on 2194000.usdhc [2194000.usdhc] using ADMA [ 3.130199] mmc2: no vqmmc regulator found [ 3.134331] mmc2: no vmmc regulator found [ 3.164756] mmc1: queuing unknown CIS tuple 0x80 (50 bytes) [ 3.177215] mmc2: SDHCI controller on 2198000.usdhc [2198000.usdhc] using ADMA [ 3.184699] ledtrig-cpu: registered to indicate activity on CPUs [ 3.191244] hidraw: raw HID events driver (C) Jiri Kosina [ 3.197141] usbcore: registered new interface driver usbhid [ 3.197408] mmc1: queuing unknown CIS tuple 0x80 (7 bytes) [ 3.199502] mmc1: queuing unknown CIS tuple 0x80 (4 bytes) [ 3.213714] usbhid: USB HID core driver [ 3.218167] ashmem: initialized [ 3.222415] [drm] Supports vblank timestamp caching Rev 1 (10.10.2010). [ 3.229064] [drm] No driver support for vblank timestamp query. [ 3.229301] mmc1: queuing unknown CIS tuple 0x02 (1 bytes) [ 3.236578] mmc1: new SDIO card at address 0001 [ 3.245036] [drm] Initialized imx-drm 1.0.0 20120507 on minor 0 [ 3.252413] imx-ipuv3 2400000.ipu: IPUv3H probed [ 3.257801] imx-hdmi 120000.hdmi: Detected HDMI controller 0x13:0x1a:0xa0:0xc1 [ 3.265227] imx-hdmi 120000.hdmi: initialized [ 3.270512] oprofile: using arm/armv7-ca9 [ 3.274885] TCP: cubic registered [ 3.278701] NET: Registered protocol family 10 [ 3.284161] mip6: Mobile IPv6 [ 3.287143] NET: Registered protocol family 17 [ 3.291717] Key type dns_resolver registered [ 3.296448] VFP support v0.3: implementor 41 architecture 3 part 30 variant 9 rev 4 [ 3.304218] failed to init OPP table [ 3.308219] imx6q-cpufreq imx6q-cpufreq.0: failed to get clocks [ 3.314156] imx6q-cpufreq: probe of imx6q-cpufreq.0 failed with error -2 [ 3.320921] ThumbEE CPU extension supported. [ 3.325215] Registering SWP/SWPB emulation handler [ 3.330578] registered taskstats version 1 [ 3.336519] ci_hdrc ci_hdrc.0: doesn't support gadget [ 3.341628] ci_hdrc ci_hdrc.0: EHCI Host Controller [ 3.346771] ci_hdrc ci_hdrc.0: new USB bus registered, assigned bus number 1 [ 3.346914] mmc2: host does not support reading read-only switch. assuming write-enable. [ 3.350050] mmc2: new SDHC card at address e624 [ 3.366738] mmcblk0: mmc2:e624 SU08G 7.40 GiB [ 3.375401] mmcblk0: p1 p2 p3 p4 [ 3.387228] ci_hdrc ci_hdrc.0: USB 2.0 started, EHCI 1.00 [ 3.392705] usb usb1: New USB device found, idVendor=1d6b, idProduct=0002 [ 3.399530] usb usb1: New USB device strings: Mfr=3, Product=2, SerialNumber=1 [ 3.406762] usb usb1: Product: EHCI Host Controller [ 3.411662] usb usb1: Manufacturer: Linux 3.11.0+ ehci_hcd [ 3.417154] usb usb1: SerialNumber: ci_hdrc.0 [ 3.422036] hub 1-0:1.0: USB hub found [ 3.425806] hub 1-0:1.0: 1 port detected [ 3.430319] snvs_rtc 20cc034.snvs-rtc-lp: setting system clock to 1970-01-01 00:01:14 UTC (74) [ 3.438985] sr_init: No PMIC hook to init smartreflex [ 3.444141] sr_init: platform driver register failed for SR [ 3.450859] imx-hdmi 120000.hdmi: failed to read edid [ 3.455951] imx_hdmi_connector_mode_valid [ 3.459987] imx_hdmi_connector_mode_valid [ 3.464000] imx_hdmi_connector_mode_valid [ 3.468028] imx_hdmi_connector_mode_valid [ 3.472039] imx_hdmi_connector_mode_valid [ 3.482106] imx_hdmi_encoder_prepare [ 3.482109] imx_hdmi_poweroff [ 3.482119] imx-hdmi 120000.hdmi: imx_hdmi_phy_disable [ 3.482209] imx_hdmi_encoder_mode_set [ 3.482215] imx-hdmi 120000.hdmi: imx_hdmi_setup [ 3.482223] imx-hdmi 120000.hdmi: imx_hdmi_setup - video mode changed [ 3.482229] imx-hdmi 120000.hdmi: Non-CEA mode used in HDMI [ 3.482234] imx-hdmi 120000.hdmi: hdmi_av_composer [ 3.482241] imx-hdmi 120000.hdmi: x=800, y=600, refresh=60 [ 3.482248] imx-hdmi 120000.hdmi: final pixclk = 39790080 [ 3.482260] imx-hdmi 120000.hdmi: hdmi_av_composer exit [ 3.482266] imx-hdmi 120000.hdmi: imx_hdmi_phy_init [ 3.482275] imx-hdmi 120000.hdmi: hdmi_phy_configure [ 3.496340] imx-hdmi 120000.hdmi: PHY PLL not locked [ 3.496348] imx-hdmi 120000.hdmi: imx_hdmi_phy_init: hdmi_phy_configure returned -22 [ 3.496357] imx-hdmi 120000.hdmi: hdmi_phy_configure [ 3.510402] imx-hdmi 120000.hdmi: PHY PLL not locked [ 3.510410] imx-hdmi 120000.hdmi: imx_hdmi_phy_init: hdmi_phy_configure returned -22 [ 3.510416] imx-hdmi 120000.hdmi: imx_hdmi_enable_video_path [ 3.510467] imx_hdmi_poweron [ 3.510472] imx-hdmi 120000.hdmi: imx_hdmi_setup [ 3.510478] imx-hdmi 120000.hdmi: imx_hdmi_setup - video mode changed [ 3.510485] imx-hdmi 120000.hdmi: Non-CEA mode used in HDMI [ 3.510491] imx-hdmi 120000.hdmi: hdmi_av_composer [ 3.510498] imx-hdmi 120000.hdmi: x=800, y=600, refresh=60 [ 3.510505] imx-hdmi 120000.hdmi: final pixclk = 39790080 [ 3.510517] imx-hdmi 120000.hdmi: hdmi_av_composer exit [ 3.510522] imx-hdmi 120000.hdmi: imx_hdmi_phy_init [ 3.510531] imx-hdmi 120000.hdmi: hdmi_phy_configure [ 3.521575] imx-hdmi 120000.hdmi: imx_hdmi_phy_init: hdmi_phy_configure returned 0 [ 3.521583] imx-hdmi 120000.hdmi: hdmi_phy_configure [ 3.532637] imx-hdmi 120000.hdmi: imx_hdmi_phy_init: hdmi_phy_configure returned 0 [ 3.532643] imx-hdmi 120000.hdmi: imx_hdmi_enable_video_path [ 3.536202] Console: switching to colour frame buffer device 100x37 [ 3.720838] imx-drm imx-drm: fb0: frame buffer device [ 3.725984] imx-drm imx-drm: registered panic notifier [ 3.750669] EXT4-fs (mmcblk0p2): mounted filesystem with ordered data mode. Opts: (null) [ 3.758859] VFS: Mounted root (ext4 filesystem) readonly on device 179:2. [ 3.781082] devtmpfs: mounted [ 3.784705] Freeing unused kernel memory: 468K (c0b91000 - c0c06000) [ 4.190814] EXT4-fs (mmcblk0p2): warning: mounting fs with errors, running e2fsck is recommended [ 4.201921] EXT4-fs (mmcblk0p2): re-mounted. Opts: (null) Starting logging: OK Populating /dev using udev: [ 4.835879] udevd[76]: starting version 182 done [ 5.174372] device-mapper: uevent: version 1.0.3 [ 5.179502] device-mapper: ioctl: 4.25.0-ioctl (2013-06-26) initialised: dm-devel@redhat.com Setting up DMRAID devices... no block devices found Initializing random number generator... done. [ 5.422064] cfg80211: Calling CRDA to update world regulatory domain [ 5.492580] brcmfmac: brcmf_sdio_chip_drivestrengthinit: No SDIO Drive strength init done for chip 4329 rev 3 pmurev 6 Starting network plug daemon: [ 5.546130] Bluetooth: Core ver 2.16 [ 5.549920] NET: Registered protocol family 31 [ 5.554379] Bluetooth: HCI device and connection manager initialized [ 5.560831] Bluetooth: HCI socket layer initialized [ 5.565739] Bluetooth: L2CAP socket layer initialized [ 5.570899] Bluetooth: SCO socket layer initialized [ 5.589094] Bluetooth: Generic Bluetooth SDIO driver ver 0.1 /etc/netplug.d/netplug eth0 probe -> pid 108 [ 5.686024] fec 2188000.ethernet eth0: Freescale FEC PHY driver [Generic PHY] (mii_bus:phy_addr=2188000.ethernet:01, irq=-1) [ 5.697557] IPv6: ADDRCONF(NETDEV_UP): eth0: link is not ready /etc/netplug.d/netplug eth1 probe -> pid 109 /etc/netplug.d/netplug eth2 probe -> pid 115 /etc/netplug.d/netplug eth3 probe -> pid 120 /etc/netplug.d/netplug eth4 probe -> pid 126 /etc/netplug.d/netplug eth5 probe -> pid 132 /etc/netplug.d/netplug eth6 probe -> pid 140 [ 6.533564] brcmfmac: brcmf_sdbrcm_download_code_file: Fail to request firmware -2 [ 6.541195] brcmfmac: _brcmf_sdbrcm_download_firmware: dongle image file download failed [ 6.549428] brcmfmac: brcmf_bus_start: brcmf_sdbrcm_bus_init failed -1 [ 6.555973] brcmfmac: brcmf_sdbrcm_probe: dongle is not responding [ 6.563226] brcmfmac: brcmf_sdio_probe: device attach failed [ 6.569086] brcmfmac: brcmf_ops_sdio_probe: F2 error, probe failed -19... /etc/netplug.d/netplug eth7 probe -> pid 149 /etc/netplug.d/netplug eth8 probe -> pid 155 /etc/netplug.d/netplug eth9 probe -> pid 160 /etc/netplug.d/netplug eth10 probe -> pid 165 /etc/netplug.d/netplug eth11 probe -> pid 170 /etc/netplug.d/netplug eth12 probe -> pid 175 /etc/netplug.d/netplug eth13 probe -> pid 180 /etc/netplug.d/netplug eth14 probe -> pid 185 /etc/netplug.d/netplug eth15 probe -> pid 190 touch: cannot touch '/var/lock/subsys/netplugd': No such file or directory Starting system message bus: done Starting network... udhcpc (v1.21.1) started grep: /etc/resolv.conf: No such file or directory Failed to kill daemon: No such file or directory Sending discover... [ 10.427548] libphy: 2188000.ethernet:01 - Link is Up - 100/Full [ 10.433500] IPv6: ADDRCONF(NETDEV_CHANGE): eth0: link becomes ready Sending discover... Sending select for 192.168.1.4... Lease of 192.168.1.4 obtained, lease time 268435455 Failed to kill daemon: No such file or directory deleting routers route: SIOCDELRT: No such process adding dns 192.168.1.1 Starting dropbear sshd: OK Starting pulseaudio: W: [pulseaudio] main.c: Running in system mode, but --disallow-exit not set! W: [pulseaudio] main.c: Running in system mode, but --disallow-module-loading not set! N: [pulseaudio] main.c: Running in system mode, forcibly disabling SHM mode! N: [pulseaudio] main.c: Running in system mode, forcibly disabling exit idle time! OK Starting sshd: OK Starting network management services:. Starting SMB services: done Starting NMB services: done Starting mpd: OK Starting atd: OK Starting input-event-daemon: input-event-daemon: open(/dev/input/event0): No such file or directory done Starting XDM: done bash-4.2# 2013-09-24 05:09:10 PM DEBUG: sendline : export PS1="bash-4.2 [rc=$(echo \$?)]# " 2013-09-24 05:09:10 PM DEBUG: send : export PS1="bash-4.2 [rc=$(echo \$?)]# " 2013-09-24 05:09:12 PM DEBUG: send : 2013-09-24 05:09:12 PM DEBUG: expect (120): 'bash-4.2 \[rc=(\d+)\]# ' export PS1="bash-4.2[ 15.643536] imx_hdmi_encoder_dpms [ 15.643539] imx_hdmi_poweroff [ 15.643550] imx-hdmi 120000.hdmi: imx_hdmi_phy_disable [ 15.643559] imx-hdmi 120000.hdmi: imx_hdmi_phy_disable - exit [rc=$(echo \$?)]# "[ 16.611576] imx_hdmi_encoder_dpms [ 16.611579] imx_hdmi_poweron [ 16.611590] imx-hdmi 120000.hdmi: imx_hdmi_setup [ 16.611598] imx-hdmi 120000.hdmi: imx_hdmi_setup - video mode changed [ 16.611604] imx-hdmi 120000.hdmi: Non-CEA mode used in HDMI [ 16.611610] imx-hdmi 120000.hdmi: hdmi_av_composer [ 16.611620] imx-hdmi 120000.hdmi: x=800, y=600, refresh=60 [ 16.611626] imx-hdmi 120000.hdmi: final pixclk = 39790080 [ 16.611639] imx-hdmi 120000.hdmi: hdmi_av_composer exit [ 16.611646] imx-hdmi 120000.hdmi: imx_hdmi_phy_init [ 16.611654] imx-hdmi 120000.hdmi: hdmi_phy_configure [ 16.622787] imx-hdmi 120000.hdmi: imx_hdmi_phy_init: hdmi_phy_configure returned 0 [ 16.622796] imx-hdmi 120000.hdmi: hdmi_phy_configure [ 16.633860] imx-hdmi 120000.hdmi: imx_hdmi_phy_init: hdmi_phy_configure returned 0 [ 16.633865] imx-hdmi 120000.hdmi: imx_hdmi_enable_video_path bash-4.2 [rc=0]# 2013-09-24 05:09:12 PM INFO: Waiting for network to come up 2013-09-24 05:09:12 PM DEBUG: expect (1): '['.+', , ]' 2013-09-24 05:09:13 PM DEBUG: sendline : LC_ALL=C ping -W4 -c1 192.168.1.203 2013-09-24 05:09:13 PM DEBUG: send : LC_ALL=C ping -W4 -c1 192.168.1.203 2013-09-24 05:09:14 PM DEBUG: send : 2013-09-24 05:09:15 PM DEBUG: expect (60): '['1 received|1 packets received', '0 received|0 packets received', 'Network is unreachable']' LC_ALL=C ping -W4 -c1 192.168.1.203 PING 192.168.1.203 (192.168.1.203): 56 data bytes 64 bytes from 192.168.1.203: seq=0 ttl=64 time=0.847 ms --- 192.168.1.203 ping statistics --- 1 packets transmitted, 1 packets received, 0% packet2013-09-24 05:09:15 PM DEBUG: expect (29): 'bash-4.2 \[rc=(\d+)\]# ' loss round-trip min/avg/max = 0.847/0.847/0.847 ms bash-4.2 [rc=0]# 2013-09-24 05:09:15 PM DEBUG: expect (1): '['.+', , ]' 2013-09-24 05:09:16 PM DEBUG: sendline : ifconfig eth0 | grep 'inet addr' | awk -F: '{print $2}' |awk '{print "<" $1 ">"}' 2013-09-24 05:09:16 PM DEBUG: send : ifconfig eth0 | grep 'inet addr' | awk -F: '{print $2}' |awk '{print "<" $1 ">"}' 2013-09-24 05:09:20 PM DEBUG: send : 2013-09-24 05:09:20 PM DEBUG: expect (60): '['<(\\d?\\d?\\d?\\.\\d?\\d?\\d?\\.\\d?\\d?\\d?\\.\\d?\\d?\\d?)>', , ]' ifconfig eth0 | grep 'inet addr' | awk -F: '{print $2}' |awk '{ print "<" $1 ">"}' <192.168.1.4> 2013-09-24 05:09:20 PM DEBUG: expect (29): 'bash-4.2 \[rc=(\d+)\]# ' bash-4.2 [rc=0]# 2013-09-24 05:09:20 PM DEBUG: Target image IP is 192.168.1.4 2013-09-24 05:09:20 PM DEBUG: expect (1): '['.+', , ]' 2013-09-24 05:09:21 PM DEBUG: sendline : echo "device_version=$(lava-master-image-info --master-image-hwpack | sed 's/[^0-9-]//g; s/^-\+//')/$(lava-master-image-info --master-image-rootfs | sed 's/[^0-9-]//g; s/^-\+//')" 2013-09-24 05:09:21 PM DEBUG: send : echo "device_version=$(lava-master-image-info --master-image-hwpack | sed 's/[^0-9-]//g; s/^-\+//')/$(lava-master-image-info --master-image-rootfs | sed 's/[^0-9-]//g; s/^-\+//')" 2013-09-24 05:09:30 PM DEBUG: send : 2013-09-24 05:09:30 PM DEBUG: expect (5): '['device_version=(\\d+-\\d+/\\d+-\\d+)', , ]' echo "device_version=$(lava-master-image-info --master-image-hw pack | sed 's/[^0-9-]//g; s/^-\+//')/$(lava-master-image-info --master-image-roo tfs | sed 's/[^0-9-]//g; s/^-\+//')" bash: lava-master-image-info: command not found bash: lava-master-image-info: command not found device_version=/ bash-4.2 [rc=0]# 2013-09-24 05:09:35 PM WARNING: Could not determine image version! 2013-09-24 05:09:35 PM INFO: Setting up http proxy 2013-09-24 05:09:35 PM DEBUG: expect (1): '['.+', , ]' 2013-09-24 05:09:35 PM DEBUG: expect (1): '['.+', , ]' 2013-09-24 05:09:36 PM DEBUG: sendline : export http_proxy=http://192.168.1.203:3128/ 2013-09-24 05:09:36 PM DEBUG: send : export http_proxy=http://192.168.1.203:3128/ 2013-09-24 05:09:38 PM DEBUG: send : 2013-09-24 05:09:38 PM DEBUG: expect (15): 'bash-4.2 \[rc=(\d+)\]# ' export http_proxy=http://192.168.1.203:3128/ bash-4.2 [rc=0]# 2013-09-24 05:09:38 PM INFO: System is in master image now 2013-09-24 05:09:38 PM DEBUG: expect (1): '['.+', , ]' 2013-09-24 05:09:39 PM DEBUG: sendline : mount /dev/disk/by-label/testrootfs /mnt 2013-09-24 05:09:39 PM DEBUG: send : mount /dev/disk/by-label/testrootfs /mnt 2013-09-24 05:09:41 PM DEBUG: send : 2013-09-24 05:09:41 PM DEBUG: expect (600): 'bash-4.2 \[rc=(\d+)\]# ' mount /dev/disk/by-label/testrootfs /mnt [ 46.465819] EXT4-fs (mmcblk0p3): mounted filesystem with ordered data mode. Opts: (null) bash-4.2 [rc=0]# 2013-09-24 05:09:41 PM DEBUG: expect (1): '['.+', , ]' 2013-09-24 05:09:42 PM DEBUG: sendline : ls /mnt/lava > /dev/null 2013-09-24 05:09:42 PM DEBUG: send : ls /mnt/lava > /dev/null 2013-09-24 05:09:44 PM DEBUG: send : 2013-09-24 05:09:44 PM DEBUG: expect (600): 'bash-4.2 \[rc=(\d+)\]# ' ls /mnt/lava > /dev/null bash-4.2 [rc=0]# 2013-09-24 05:09:44 PM DEBUG: expect (1): '['.+', , ]' 2013-09-24 05:09:45 PM DEBUG: sendline : nice tar -cf /tmp/fs.tgz -C /mnt lava 2013-09-24 05:09:45 PM DEBUG: send : nice tar -cf /tmp/fs.tgz -C /mnt lava 2013-09-24 05:09:47 PM DEBUG: send : 2013-09-24 05:09:47 PM DEBUG: expect (600): 'bash-4.2 \[rc=(\d+)\]# ' nice tar -cf /tmp/fs.tgz -C /mnt lava bash-4.2 [rc=0]# 2013-09-24 05:09:47 PM DEBUG: expect (1): '['.+', , ]' 2013-09-24 05:09:48 PM DEBUG: sendline : cd /tmp 2013-09-24 05:09:48 PM DEBUG: send : cd /tmp 2013-09-24 05:09:48 PM DEBUG: send : 2013-09-24 05:09:48 PM DEBUG: expect (600): 'bash-4.2 \[rc=(\d+)\]# ' cd /tmp bash-4.2 [rc=0]# 2013-09-24 05:09:48 PM DEBUG: sendline : python -m SimpleHTTPServer 0 2>/dev/null 2013-09-24 05:09:48 PM DEBUG: send : python -m SimpleHTTPServer 0 2>/dev/null 2013-09-24 05:09:50 PM DEBUG: send : 2013-09-24 05:09:50 PM DEBUG: expect (1200): '['Serving HTTP on 0.0.0.0 port (\\d+) \\.\\.', , ]' python -m SimpleHTTPServer 0 2>/dev/null [ 61.607356] imx-sdma 20ec000.sdma: firmware not found Serving HTTP on 0.0.0.0 port 38273 ... 2013-09-24 05:10:01 PM INFO: download_with_retry::About to download http://192.168.1.4:38273/fs.tgz to the host 2013-09-24 05:10:01 PM INFO: Downloading image: http://192.168.1.4:38273/fs.tgz 2013-09-24 05:10:01 PM INFO: Downloading image:url is http 2013-09-24 05:10:01 PM WARNING: unable to download: 'Traceback (most recent call last):\n File "/srv/lava/.cache/git-cache/exports/lava-dispatcher/2013-09-20-3ca1af8/lava_dispatcher/downloader.py", line 187, in download_with_retry\n return download_image(url, context, imgdir, decompress)\n File "/srv/lava/.cache/git-cache/exports/lava-dispatcher/2013-09-20-3ca1af8/lava_dispatcher/downloader.py", line 165, in download_image\n logging.info("downloader::Downloading_image:url is %s" % url)\nTypeError: not all arguments converted during string formatting\n' 2013-09-24 05:10:01 PM INFO: Sleep one minute and retry (1) 2013-09-24 05:11:01 PM INFO: Downloading image: http://192.168.1.4:38273/fs.tgz 2013-09-24 05:11:01 PM INFO: Downloading image:url is http 2013-09-24 05:11:01 PM WARNING: unable to download: 'Traceback (most recent call last):\n File "/srv/lava/.cache/git-cache/exports/lava-dispatcher/2013-09-20-3ca1af8/lava_dispatcher/downloader.py", line 187, in download_with_retry\n return download_image(url, context, imgdir, decompress)\n File "/srv/lava/.cache/git-cache/exports/lava-dispatcher/2013-09-20-3ca1af8/lava_dispatcher/downloader.py", line 165, in download_image\n logging.info("downloader::Downloading_image:url is %s" % url)\nTypeError: not all arguments converted during string formatting\n' 2013-09-24 05:11:01 PM INFO: Sleep one minute and retry (2) 2013-09-24 05:12:02 PM INFO: Downloading image: http://192.168.1.4:38273/fs.tgz 2013-09-24 05:12:02 PM INFO: Downloading image:url is http 2013-09-24 05:12:02 PM WARNING: unable to download: 'Traceback (most recent call last):\n File "/srv/lava/.cache/git-cache/exports/lava-dispatcher/2013-09-20-3ca1af8/lava_dispatcher/downloader.py", line 187, in download_with_retry\n return download_image(url, context, imgdir, decompress)\n File "/srv/lava/.cache/git-cache/exports/lava-dispatcher/2013-09-20-3ca1af8/lava_dispatcher/downloader.py", line 165, in download_image\n logging.info("downloader::Downloading_image:url is %s" % url)\nTypeError: not all arguments converted during string formatting\n' 2013-09-24 05:12:02 PM INFO: Sleep one minute and retry (3) 2013-09-24 05:13:02 PM INFO: Downloading image: http://192.168.1.4:38273/fs.tgz 2013-09-24 05:13:02 PM INFO: Downloading image:url is http 2013-09-24 05:13:02 PM WARNING: unable to download: 'Traceback (most recent call last):\n File "/srv/lava/.cache/git-cache/exports/lava-dispatcher/2013-09-20-3ca1af8/lava_dispatcher/downloader.py", line 187, in download_with_retry\n return download_image(url, context, imgdir, decompress)\n File "/srv/lava/.cache/git-cache/exports/lava-dispatcher/2013-09-20-3ca1af8/lava_dispatcher/downloader.py", line 165, in download_image\n logging.info("downloader::Downloading_image:url is %s" % url)\nTypeError: not all arguments converted during string formatting\n' 2013-09-24 05:13:02 PM INFO: Sleep one minute and retry (4) 2013-09-24 05:14:02 PM INFO: Downloading image: http://192.168.1.4:38273/fs.tgz 2013-09-24 05:14:02 PM INFO: Downloading image:url is http 2013-09-24 05:14:02 PM WARNING: unable to download: 'Traceback (most recent call last):\n File "/srv/lava/.cache/git-cache/exports/lava-dispatcher/2013-09-20-3ca1af8/lava_dispatcher/downloader.py", line 187, in download_with_retry\n return download_image(url, context, imgdir, decompress)\n File "/srv/lava/.cache/git-cache/exports/lava-dispatcher/2013-09-20-3ca1af8/lava_dispatcher/downloader.py", line 165, in download_image\n logging.info("downloader::Downloading_image:url is %s" % url)\nTypeError: not all arguments converted during string formatting\n' 2013-09-24 05:14:02 PM INFO: Sleep one minute and retry (5) 2013-09-24 05:15:02 PM INFO: Downloading image: http://192.168.1.4:38273/fs.tgz 2013-09-24 05:15:02 PM INFO: Downloading image:url is http 2013-09-24 05:15:02 PM WARNING: unable to download: 'Traceback (most recent call last):\n File "/srv/lava/.cache/git-cache/exports/lava-dispatcher/2013-09-20-3ca1af8/lava_dispatcher/downloader.py", line 187, in download_with_retry\n return download_image(url, context, imgdir, decompress)\n File "/srv/lava/.cache/git-cache/exports/lava-dispatcher/2013-09-20-3ca1af8/lava_dispatcher/downloader.py", line 165, in download_image\n logging.info("downloader::Downloading_image:url is %s" % url)\nTypeError: not all arguments converted during string formatting\n' 2013-09-24 05:15:02 PM DEBUG: send :  2013-09-24 05:15:02 PM DEBUG: expect (1): '['.+', , ]' 2013-09-24 05:15:02 PM DEBUG: expect (1): '['.+', , ]' [ 303.847205] EXT4-fs (mmcblk0p2): error count: 1 [ 303.851749] EXT4-fs (mmcblk0p2): initial error at 1379834369: __ext4_get_inode_loc:3629: inode 132557: block 524588 [ 303.862258] EXT4-fs (mmcblk0p2): last error at 1379834369: __ext4_get_inode_loc:3629: inode 132557: block 524588 2013-09-24 05:15:02 PM DEBUG: expect (1): '['.+', , ]' ^2013-09-24 05:15:02 PM DEBUG: expect (1): '['.+', , ]' C2013-09-24 05:15:02 PM DEBUG: expect (1): '['.+', , ]' bash-2013-09-24 05:15:02 PM DEBUG: expect (1): '['.+', , ]' 42013-09-24 05:15:02 PM DEBUG: expect (1): '['.+', , ]' .2 [rc=2552013-09-24 05:15:02 PM DEBUG: expect (1): '['.+', , ]' ]# 2013-09-24 05:15:02 PM DEBUG: expect (1): '['.+', , ]' 2013-09-24 05:15:03 PM DEBUG: sendline : umount /mnt 2013-09-24 05:15:03 PM DEBUG: send : umount /mnt 2013-09-24 05:15:03 PM DEBUG: send : 2013-09-24 05:15:03 PM DEBUG: expect (600): 'bash-4.2 \[rc=(\d+)\]# ' umount /mnt bash-4.2 [rc=0]# 2013-09-24 05:15:03 PM INFO: General Exception: downloading http://192.168.1.4:38273/fs.tgz failed after 6 tries 2013-09-24 05:15:03 PM DEBUG: finally status fail 2013-09-24 05:15:03 PM WARNING: [ACTION-E] lava_test_shell is finished with error (downloading http://192.168.1.4:38273/fs.tgz failed after 6 tries). ErrorMessage: downloading http://192.168.1.4:38273/fs.tgz failed after 6 tries Lava failed at action lava_test_shell with error:downloading http://192.168.1.4:38273/fs.tgz failed after 6 tries Traceback (most recent call last): File "/srv/lava/.cache/git-cache/exports/lava-dispatcher/2013-09-20-3ca1af8/lava_dispatcher/job.py", line 254, in run action.run(**params) File "/srv/lava/.cache/git-cache/exports/lava-dispatcher/2013-09-20-3ca1af8/lava_dispatcher/actions/lava_test_shell.py", line 543, in run testdefs_by_uuid = self._configure_target(target, testdef_urls, testdef_repos) File "/srv/lava/.cache/git-cache/exports/lava-dispatcher/2013-09-20-3ca1af8/lava_dispatcher/actions/lava_test_shell.py", line 669, in _configure_target with target.file_system(results_part, 'lava') as d: File "/usr/lib/python2.7/contextlib.py", line 17, in __enter__ return self.gen.next() File "/srv/lava/.cache/git-cache/exports/lava-dispatcher/2013-09-20-3ca1af8/lava_dispatcher/device/master.py", line 352, in file_system self.context, self.scratch_dir, url, False) File "/srv/lava/.cache/git-cache/exports/lava-dispatcher/2013-09-20-3ca1af8/lava_dispatcher/downloader.py", line 193, in download_with_retry 'downloading %s failed after %d tries' % (url, tries)) RuntimeError: downloading http://192.168.1.4:38273/fs.tgz failed after 6 tries 2013-09-24 etwork is unreachable']' LC_ALL=C ping -W4 -c1 192.168.1.203 PING 192.168.1.203 (192.168.1.203): 56 data bytes 64 bytes from 192.168.1.203: seq=0 ttl=64 time=0.847 ms --- 192.168.1.203 ping statistics --- 1 packets transmitted, 1 packets received, 0% packet2013-09-24 05:09:15 PM DEBUG: expect (29): 'bash-4.2 \[rc=(\d+)\]# ' loss round-trip min/avg/max = 0.847/0.847/0.847 ms bash-4.2 [rc=0]# 2013-09-24 05:09:15 PM DEBUG: expect (1): '['.+', , ]' 2013-09-24 05:09:16 PM DEBUG: sendline : ifconfig eth0 | grep 'inet addr' | awk -F: '{print $2}' |awk '{print "<" $1 ">"}' 2013-09-24 05:09:16 PM DEBUG: send : ifconfig eth0 | grep 'inet addr' | awk -F: '{print $2}' |awk '{print "<" $1 ">"}' 2013-09-24 05:09:20 PM DEBUG: send : 2013-09-24 05:09:20 PM DEBUG: expect (60): '['<(\\d?\\d?\\d?\\.\\d?\\d?\\d?\\.\\d?\\d?\\d?\\.\\d?\\d?\\d?)>', , ]' print "<" $1 ">"}'ep 'inet addr' | awk -F: '{print $2}' |awk '{ <192.168.1.4> 2013-09-24 05:09:20 PM DEBUG: expect (29): 'bash-4.2 \[rc=(\d+)\]# ' bash-4.2 [rc=0]# 2013-09-24 05:09:20 PM DEBUG: Target image IP is 192.168.1.4 2013-09-24 05:09:20 PM DEBUG: expect (1): '['.+', , ]' 2013-09-24 05:09:21 PM DEBUG: sendline : echo "device_version=$(lava-master-image-info --master-image-hwpack | sed 's/[^0-9-]//g; s/^-\+//')/$(lava-master-image-info --master-image-rootfs | sed 's/[^0-9-]//g; s/^-\+//')" 2013-09-24 05:09:21 PM DEBUG: send : echo "device_version=$(lava-master-image-info --master-image-hwpack | sed 's/[^0-9-]//g; s/^-\+//')/$(lava-master-image-info --master-image-rootfs | sed 's/[^0-9-]//g; s/^-\+//')" 2013-09-24 05:09:30 PM DEBUG: send : 2013-09-24 05:09:30 PM DEBUG: expect (5): '['device_version=(\\d+-\\d+/\\d+-\\d+)', , ]' tfs | sed 's/[^0-9-]//g; s/^-\+//')"/$(lava-master-image-info --master-image-roo bash: lava-master-image-info: command not found bash: lava-master-image-info: command not found device_version=/ bash-4.2 [rc=0]# 2013-09-24 05:09:35 PM WARNING: Could not determine image version! 2013-09-24 05:09:35 PM INFO: Setting up http proxy 2013-09-24 05:09:35 PM DEBUG: expect (1): '['.+', , ]' 2013-09-24 05:09:35 PM DEBUG: expect (1): '['.+', , ]' 2013-09-24 05:09:36 PM DEBUG: sendline : export http_proxy=http://192.168.1.203:3128/ 2013-09-24 05:09:36 PM DEBUG: send : export http_proxy=http://192.168.1.203:3128/ 2013-09-24 05:09:38 PM DEBUG: send : 2013-09-24 05:09:38 PM DEBUG: expect (15): 'bash-4.2 \[rc=(\d+)\]# ' export http_proxy=http://192.168.1.203:3128/ bash-4.2 [rc=0]# 2013-09-24 05:09:38 PM INFO: System is in master image now 2013-09-24 05:09:38 PM DEBUG: expect (1): '['.+', , ]' 2013-09-24 05:09:39 PM DEBUG: sendline : mount /dev/disk/by-label/testrootfs /mnt 2013-09-24 05:09:39 PM DEBUG: send : mount /dev/disk/by-label/testrootfs /mnt 2013-09-24 05:09:41 PM DEBUG: send : 2013-09-24 05:09:41 PM DEBUG: expect (600): 'bash-4.2 \[rc=(\d+)\]# ' mount /dev/disk/by-label/testrootfs /mnt [ 46.465819] EXT4-fs (mmcblk0p3): mounted filesystem with ordered data mode. Opts: (null) bash-4.2 [rc=0]# 2013-09-24 05:09:41 PM DEBUG: expect (1): '['.+', , ]' 2013-09-24 05:09:42 PM DEBUG: sendline : ls /mnt/lava > /dev/null 2013-09-24 05:09:42 PM DEBUG: send : ls /mnt/lava > /dev/null 2013-09-24 05:09:44 PM DEBUG: send : 2013-09-24 05:09:44 PM DEBUG: expect (600): 'bash-4.2 \[rc=(\d+)\]# ' ls /mnt/lava > /dev/null bash-4.2 [rc=0]# 2013-09-24 05:09:44 PM DEBUG: expect (1): '['.+', , ]' 2013-09-24 05:09:45 PM DEBUG: sendline : nice tar -cf /tmp/fs.tgz -C /mnt lava 2013-09-24 05:09:45 PM DEBUG: send : nice tar -cf /tmp/fs.tgz -C /mnt lava 2013-09-24 05:09:47 PM DEBUG: send : 2013-09-24 05:09:47 PM DEBUG: expect (600): 'bash-4.2 \[rc=(\d+)\]# ' nice tar -cf /tmp/fs.tgz -C /mnt lava bash-4.2 [rc=0]# 2013-09-24 05:09:47 PM DEBUG: expect (1): '['.+', , ]' 2013-09-24 05:09:48 PM DEBUG: sendline : cd /tmp 2013-09-24 05:09:48 PM DEBUG: send : cd /tmp 2013-09-24 05:09:48 PM DEBUG: send : 2013-09-24 05:09:48 PM DEBUG: expect (600): 'bash-4.2 \[rc=(\d+)\]# ' cd /tmp bash-4.2 [rc=0]# 2013-09-24 05:09:48 PM DEBUG: sendline : python -m SimpleHTTPServer 0 2>/dev/null 2013-09-24 05:09:48 PM DEBUG: send : python -m SimpleHTTPServer 0 2>/dev/null 2013-09-24 05:09:50 PM DEBUG: send : 2013-09-24 05:09:50 PM DEBUG: expect (1200): '['Serving HTTP on 0.0.0.0 port (\\d+) \\.\\.', , ]' python -m SimpleHTTPServer 0 2>/dev/null [ 61.607356] imx-sdma 20ec000.sdma: firmware not found Serving HTTP on 0.0.0.0 port 38273 ... 2013-09-24 05:10:01 PM INFO: download_with_retry::About to download http://192.168.1.4:38273/fs.tgz to the host 2013-09-24 05:10:01 PM INFO: Downloading image: http://192.168.1.4:38273/fs.tgz 2013-09-24 05:10:01 PM INFO: Downloading image:url is http 2013-09-24 05:10:01 PM WARNING: unable to download: 'Traceback (most recent call last):\n File "/srv/lava/.cache/git-cache/exports/lava-dispatcher/2013-09-20-3ca1af8/lava_dispatcher/downloader.py", line 187, in download_with_retry\n return download_image(url, context, imgdir, decompress)\n File "/srv/lava/.cache/git-cache/exports/lava-dispatcher/2013-09-20-3ca1af8/lava_dispatcher/downloader.py", line 165, in download_image\n logging.info("downloader::Downloading_image:url is %s" % url)\nTypeError: not all arguments converted during string formatting\n' 2013-09-24 05:10:01 PM INFO: Sleep one minute and retry (1) 2013-09-24 05:11:01 PM INFO: Downloading image: http://192.168.1.4:38273/fs.tgz 2013-09-24 05:11:01 PM INFO: Downloading image:url is http 2013-09-24 05:11:01 PM WARNING: unable to download: 'Traceback (most recent call last):\n File "/srv/lava/.cache/git-cache/exports/lava-dispatcher/2013-09-20-3ca1af8/lava_dispatcher/downloader.py", line 187, in download_with_retry\n return download_image(url, context, imgdir, decompress)\n File "/srv/lava/.cache/git-cache/exports/lava-dispatcher/2013-09-20-3ca1af8/lava_dispatcher/downloader.py", line 165, in download_image\n logging.info("downloader::Downloading_image:url is %s" % url)\nTypeError: not all arguments converted during string formatting\n' 2013-09-24 05:11:01 PM INFO: Sleep one minute and retry (2) 2013-09-24 05:12:02 PM INFO: Downloading image: http://192.168.1.4:38273/fs.tgz 2013-09-24 05:12:02 PM INFO: Downloading image:url is http 2013-09-24 05:12:02 PM WARNING: unable to download: 'Traceback (most recent call last):\n File "/srv/lava/.cache/git-cache/exports/lava-dispatcher/2013-09-20-3ca1af8/lava_dispatcher/downloader.py", line 187, in download_with_retry\n return download_image(url, context, imgdir, decompress)\n File "/srv/lava/.cache/git-cache/exports/lava-dispatcher/2013-09-20-3ca1af8/lava_dispatcher/downloader.py", line 165, in download_image\n logging.info("downloader::Downloading_image:url is %s" % url)\nTypeError: not all arguments converted during string formatting\n' 2013-09-24 05:12:02 PM INFO: Sleep one minute and retry (3) 2013-09-24 05:13:02 PM INFO: Downloading image: http://192.168.1.4:38273/fs.tgz 2013-09-24 05:13:02 PM INFO: Downloading image:url is http 2013-09-24 05:13:02 PM WARNING: unable to download: 'Traceback (most recent call last):\n File "/srv/lava/.cache/git-cache/exports/lava-dispatcher/2013-09-20-3ca1af8/lava_dispatcher/downloader.py", line 187, in download_with_retry\n return download_image(url, context, imgdir, decompress)\n File "/srv/lava/.cache/git-cache/exports/lava-dispatcher/2013-09-20-3ca1af8/lava_dispatcher/downloader.py", line 165, in download_image\n logging.info("downloader::Downloading_image:url is %s" % url)\nTypeError: not all arguments converted during string formatting\n' 2013-09-24 05:13:02 PM INFO: Sleep one minute and retry (4) 2013-09-24 05:14:02 PM INFO: Downloading image: http://192.168.1.4:38273/fs.tgz 2013-09-24 05:14:02 PM INFO: Downloading image:url is http 2013-09-24 05:14:02 PM WARNING: unable to download: 'Traceback (most recent call last):\n File "/srv/lava/.cache/git-cache/exports/lava-dispatcher/2013-09-20-3ca1af8/lava_dispatcher/downloader.py", line 187, in download_with_retry\n return download_image(url, context, imgdir, decompress)\n File "/srv/lava/.cache/git-cache/exports/lava-dispatcher/2013-09-20-3ca1af8/lava_dispatcher/downloader.py", line 165, in download_image\n logging.info("downloader::Downloading_image:url is %s" % url)\nTypeError: not all arguments converted during string formatting\n' 2013-09-24 05:14:02 PM INFO: Sleep one minute and retry (5) 2013-09-24 05:15:02 PM INFO: Downloading image: http://192.168.1.4:38273/fs.tgz 2013-09-24 05:15:02 PM INFO: Downloading image:url is http 2013-09-24 05:15:02 PM WARNING: unable to download: 'Traceback (most recent call last):\n File "/srv/lava/.cache/git-cache/exports/lava-dispatcher/2013-09-20-3ca1af8/lava_dispatcher/downloader.py", line 187, in download_with_retry\n return download_image(url, context, imgdir, decompress)\n File "/srv/lava/.cache/git-cache/exports/lava-dispatcher/2013-09-20-3ca1af8/lava_dispatcher/downloader.py", line 165, in download_image\n logging.info("downloader::Downloading_image:url is %s" % url)\nTypeError: not all arguments converted during string formatting\n' 2013-09-24 05:15:02 PM DEBUG: send :  2013-09-24 05:15:02 PM DEBUG: expect (1): '['.+', , ]' 2013-09-24 05:15:02 PM DEBUG: expect (1): '['.+', , ]' [ 303.847205] EXT4-fs (mmcblk0p2): error count: 1 [ 303.851749] EXT4-fs (mmcblk0p2): initial error at 1379834369: __ext4_get_inode_loc:3629: inode 132557: block 524588 [ 303.862258] EXT4-fs (mmcblk0p2): last error at 1379834369: __ext4_get_inode_loc:3629: inode 132557: block 524588 2013-09-24 05:15:02 PM DEBUG: expect (1): '['.+', , ]' ^2013-09-24 05:15:02 PM DEBUG: expect (1): '['.+', , ]' C2013-09-24 05:15:02 PM DEBUG: expect (1): '['.+', , ]' bash-2013-09-24 05:15:02 PM DEBUG: expect (1): '['.+', , ]' 42013-09-24 05:15:02 PM DEBUG: expect (1): '['.+', , ]' .2 [rc=2552013-09-24 05:15:02 PM DEBUG: expect (1): '['.+', , ]' ]# 2013-09-24 05:15:02 PM DEBUG: expect (1): '['.+', , ]' 2013-09-24 05:15:03 PM DEBUG: sendline : umount /mnt 2013-09-24 05:15:03 PM DEBUG: send : umount /mnt 2013-09-24 05:15:03 PM DEBUG: send : 2013-09-24 05:15:03 PM DEBUG: expect (600): 'bash-4.2 \[rc=(\d+)\]# ' umount /mnt bash-4.2 [rc=0]# 2013-09-24 05:15:03 PM INFO: General Exception: downloading http://192.168.1.4:38273/fs.tgz failed after 6 tries 2013-09-24 05:15:03 PM DEBUG: finally status fail 2013-09-24 05:15:03 PM WARNING: [ACTION-E] lava_test_shell is finished with error (downloading http://192.168.1.4:38273/fs.tgz failed after 6 tries). ErrorMessage: downloading http://192.168.1.4:38273/fs.tgz failed after 6 tries Lava failed at action lava_test_shell with error:downloading http://192.168.1.4:38273/fs.tgz failed after 6 tries Traceback (most recent call last): File "/srv/lava/.cache/git-cache/exports/lava-dispatcher/2013-09-20-3ca1af8/lava_dispatcher/job.py", line 254, in run action.run(**params) File "/srv/lava/.cache/git-cache/exports/lava-dispatcher/2013-09-20-3ca1af8/lava_dispatcher/actions/lava_test_shell.py", line 543, in run testdefs_by_uuid = self._configure_target(target, testdef_urls, testdef_repos) File "/srv/lava/.cache/git-cache/exports/lava-dispatcher/2013-09-20-3ca1af8/lava_dispatcher/actions/lava_test_shell.py", line 669, in _configure_target with target.file_system(results_part, 'lava') as d: File "/usr/lib/python2.7/contextlib.py", line 17, in __enter__ return self.gen.next() File "/srv/lava/.cache/git-cache/exports/lava-dispatcher/2013-09-20-3ca1af8/lava_dispatcher/device/master.py", line 352, in file_system self.context, self.scratch_dir, url, False) File "/srv/lava/.cache/git-cache/exports/lava-dispatcher/2013-09-20-3ca1af8/lava_dispatcher/downloader.py", line 193, in download_with_retry 'downloading %s failed after %d tries' % (url, tries)) RuntimeError: downloading http://192.168.1.4:38273/fs.tgz failed after 6 tries 2013-09-24 05:15:03 PM INFO: Submitting the test result with parameters = {u'stream': u'/anonymous/wand/', u'server': u'http://novello@192.168.1.203/RPC2/'} 2013-09-24 05:15:03 PM WARNING: specifying a user without a token is unlikely to work 2013-09-24 05:15:03 PM DEBUG: server RPC endpoint URL: http://novello@192.168.1.203/RPC2/ 2013-09-24 05:15:03 PM ERROR: Failed to submit the test result. Error = Username provided but no token found. ERROR: Username provided but no token found. (oe)root@novello-HP-Compaq-6720s:/media# 05:15:03 PM INFO: Submitting the test result with parameters = {u'stream': u'/anonymous/wand/', u'server': u'http://novello@192.168.1.203/RPC2/'} 2013-09-24 05:15:03 PM WARNING: specifying a user without a token is unlikely to work 2013-09-24 05:15:03 PM DEBUG: server RPC endpoint URL: http://novello@192.168.1.203/RPC2/ 2013-09-24 05:15:03 PM ERROR: Failed to submit the test result. Error = Username provided but no token found. !!!!!MORE INFO ON THE MISTAKE etwork is unreachable']' LC_ALL=C ping -W4 -c1 192.168.1.203 PING 192.168.1.203 (192.168.1.203): 56 data bytes 64 bytes from 192.168.1.203: seq=0 ttl=64 time=0.847 ms --- 192.168.1.203 ping statistics --- 1 packets transmitted, 1 packets received, 0% packet2013-09-24 05:09:15 PM DEBUG: expect (29): 'bash-4.2 \[rc=(\d+)\]# ' loss round-trip min/avg/max = 0.847/0.847/0.847 ms bash-4.2 [rc=0]# 2013-09-24 05:09:15 PM DEBUG: expect (1): '['.+', , ]' 2013-09-24 05:09:16 PM DEBUG: sendline : ifconfig eth0 | grep 'inet addr' | awk -F: '{print $2}' |awk '{print "<" $1 ">"}' 2013-09-24 05:09:16 PM DEBUG: send : ifconfig eth0 | grep 'inet addr' | awk -F: '{print $2}' |awk '{print "<" $1 ">"}' 2013-09-24 05:09:20 PM DEBUG: send : 2013-09-24 05:09:20 PM DEBUG: expect (60): '['<(\\d?\\d?\\d?\\.\\d?\\d?\\d?\\.\\d?\\d?\\d?\\.\\d?\\d?\\d?)>', , ]' print "<" $1 ">"}'ep 'inet addr' | awk -F: '{print $2}' |awk '{ <192.168.1.4> 2013-09-24 05:09:20 PM DEBUG: expect (29): 'bash-4.2 \[rc=(\d+)\]# ' bash-4.2 [rc=0]# 2013-09-24 05:09:20 PM DEBUG: Target image IP is 192.168.1.4 2013-09-24 05:09:20 PM DEBUG: expect (1): '['.+', , ]' 2013-09-24 05:09:21 PM DEBUG: sendline : echo "device_version=$(lava-master-image-info --master-image-hwpack | sed 's/[^0-9-]//g; s/^-\+//')/$(lava-master-image-info --master-image-rootfs | sed 's/[^0-9-]//g; s/^-\+//')" 2013-09-24 05:09:21 PM DEBUG: send : echo "device_version=$(lava-master-image-info --master-image-hwpack | sed 's/[^0-9-]//g; s/^-\+//')/$(lava-master-image-info --master-image-rootfs | sed 's/[^0-9-]//g; s/^-\+//')" 2013-09-24 05:09:30 PM DEBUG: send : 2013-09-24 05:09:30 PM DEBUG: expect (5): '['device_version=(\\d+-\\d+/\\d+-\\d+)', , ]' tfs | sed 's/[^0-9-]//g; s/^-\+//')"/$(lava-master-image-info --master-image-roo bash: lava-master-image-info: command not found bash: lava-master-image-info: command not found device_version=/ bash-4.2 [rc=0]# 2013-09-24 05:09:35 PM WARNING: Could not determine image version! 2013-09-24 05:09:35 PM INFO: Setting up http proxy 2013-09-24 05:09:35 PM DEBUG: expect (1): '['.+', , ]' 2013-09-24 05:09:35 PM DEBUG: expect (1): '['.+', , ]' 2013-09-24 05:09:36 PM DEBUG: sendline : export http_proxy=http://192.168.1.203:3128/ 2013-09-24 05:09:36 PM DEBUG: send : export http_proxy=http://192.168.1.203:3128/ 2013-09-24 05:09:38 PM DEBUG: send : 2013-09-24 05:09:38 PM DEBUG: expect (15): 'bash-4.2 \[rc=(\d+)\]# ' export http_proxy=http://192.168.1.203:3128/ bash-4.2 [rc=0]# 2013-09-24 05:09:38 PM INFO: System is in master image now 2013-09-24 05:09:38 PM DEBUG: expect (1): '['.+', , ]' 2013-09-24 05:09:39 PM DEBUG: sendline : mount /dev/disk/by-label/testrootfs /mnt 2013-09-24 05:09:39 PM DEBUG: send : mount /dev/disk/by-label/testrootfs /mnt 2013-09-24 05:09:41 PM DEBUG: send : 2013-09-24 05:09:41 PM DEBUG: expect (600): 'bash-4.2 \[rc=(\d+)\]# ' mount /dev/disk/by-label/testrootfs /mnt [ 46.465819] EXT4-fs (mmcblk0p3): mounted filesystem with ordered data mode. Opts: (null) bash-4.2 [rc=0]# 2013-09-24 05:09:41 PM DEBUG: expect (1): '['.+', , ]' 2013-09-24 05:09:42 PM DEBUG: sendline : ls /mnt/lava > /dev/null 2013-09-24 05:09:42 PM DEBUG: send : ls /mnt/lava > /dev/null 2013-09-24 05:09:44 PM DEBUG: send : 2013-09-24 05:09:44 PM DEBUG: expect (600): 'bash-4.2 \[rc=(\d+)\]# ' ls /mnt/lava > /dev/null bash-4.2 [rc=0]# 2013-09-24 05:09:44 PM DEBUG: expect (1): '['.+', , ]' 2013-09-24 05:09:45 PM DEBUG: sendline : nice tar -cf /tmp/fs.tgz -C /mnt lava 2013-09-24 05:09:45 PM DEBUG: send : nice tar -cf /tmp/fs.tgz -C /mnt lava 2013-09-24 05:09:47 PM DEBUG: send : 2013-09-24 05:09:47 PM DEBUG: expect (600): 'bash-4.2 \[rc=(\d+)\]# ' nice tar -cf /tmp/fs.tgz -C /mnt lava bash-4.2 [rc=0]# 2013-09-24 05:09:47 PM DEBUG: expect (1): '['.+', , ]' 2013-09-24 05:09:48 PM DEBUG: sendline : cd /tmp 2013-09-24 05:09:48 PM DEBUG: send : cd /tmp 2013-09-24 05:09:48 PM DEBUG: send : 2013-09-24 05:09:48 PM DEBUG: expect (600): 'bash-4.2 \[rc=(\d+)\]# ' cd /tmp bash-4.2 [rc=0]# 2013-09-24 05:09:48 PM DEBUG: sendline : python -m SimpleHTTPServer 0 2>/dev/null 2013-09-24 05:09:48 PM DEBUG: send : python -m SimpleHTTPServer 0 2>/dev/null 2013-09-24 05:09:50 PM DEBUG: send : 2013-09-24 05:09:50 PM DEBUG: expect (1200): '['Serving HTTP on 0.0.0.0 port (\\d+) \\.\\.', , ]' python -m SimpleHTTPServer 0 2>/dev/null [ 61.607356] imx-sdma 20ec000.sdma: firmware not found Serving HTTP on 0.0.0.0 port 38273 ... 2013-09-24 05:10:01 PM INFO: download_with_retry::About to download http://192.168.1.4:38273/fs.tgz to the host 2013-09-24 05:10:01 PM INFO: Downloading image: http://192.168.1.4:38273/fs.tgz 2013-09-24 05:10:01 PM INFO: Downloading image:url is http 2013-09-24 05:10:01 PM WARNING: unable to download: 'Traceback (most recent call last):\n File "/srv/lava/.cache/git-cache/exports/lava-dispatcher/2013-09-20-3ca1af8/lava_dispatcher/downloader.py", line 187, in download_with_retry\n return download_image(url, context, imgdir, decompress)\n File "/srv/lava/.cache/git-cache/exports/lava-dispatcher/2013-09-20-3ca1af8/lava_dispatcher/downloader.py", line 165, in download_image\n logging.info("downloader::Downloading_image:url is %s" % url)\nTypeError: not all arguments converted during string formatting\n' 2013-09-24 05:10:01 PM INFO: Sleep one minute and retry (1) 2013-09-24 05:11:01 PM INFO: Downloading image: http://192.168.1.4:38273/fs.tgz 2013-09-24 05:11:01 PM INFO: Downloading image:url is http 2013-09-24 05:11:01 PM WARNING: unable to download: 'Traceback (most recent call last):\n File "/srv/lava/.cache/git-cache/exports/lava-dispatcher/2013-09-20-3ca1af8/lava_dispatcher/downloader.py", line 187, in download_with_retry\n return download_image(url, context, imgdir, decompress)\n File "/srv/lava/.cache/git-cache/exports/lava-dispatcher/2013-09-20-3ca1af8/lava_dispatcher/downloader.py", line 165, in download_image\n logging.info("downloader::Downloading_image:url is %s" % url)\nTypeError: not all arguments converted during string formatting\n' 2013-09-24 05:11:01 PM INFO: Sleep one minute and retry (2) 2013-09-24 05:12:02 PM INFO: Downloading image: http://192.168.1.4:38273/fs.tgz 2013-09-24 05:12:02 PM INFO: Downloading image:url is http 2013-09-24 05:12:02 PM WARNING: unable to download: 'Traceback (most recent call last):\n File "/srv/lava/.cache/git-cache/exports/lava-dispatcher/2013-09-20-3ca1af8/lava_dispatcher/downloader.py", line 187, in download_with_retry\n return download_image(url, context, imgdir, decompress)\n File "/srv/lava/.cache/git-cache/exports/lava-dispatcher/2013-09-20-3ca1af8/lava_dispatcher/downloader.py", line 165, in download_image\n logging.info("downloader::Downloading_image:url is %s" % url)\nTypeError: not all arguments converted during string formatting\n' 2013-09-24 05:12:02 PM INFO: Sleep one minute and retry (3) 2013-09-24 05:13:02 PM INFO: Downloading image: http://192.168.1.4:38273/fs.tgz 2013-09-24 05:13:02 PM INFO: Downloading image:url is http 2013-09-24 05:13:02 PM WARNING: unable to download: 'Traceback (most recent call last):\n File "/srv/lava/.cache/git-cache/exports/lava-dispatcher/2013-09-20-3ca1af8/lava_dispatcher/downloader.py", line 187, in download_with_retry\n return download_image(url, context, imgdir, decompress)\n File "/srv/lava/.cache/git-cache/exports/lava-dispatcher/2013-09-20-3ca1af8/lava_dispatcher/downloader.py", line 165, in download_image\n logging.info("downloader::Downloading_image:url is %s" % url)\nTypeError: not all arguments converted during string formatting\n' 2013-09-24 05:13:02 PM INFO: Sleep one minute and retry (4) 2013-09-24 05:14:02 PM INFO: Downloading image: http://192.168.1.4:38273/fs.tgz 2013-09-24 05:14:02 PM INFO: Downloading image:url is http 2013-09-24 05:14:02 PM WARNING: unable to download: 'Traceback (most recent call last):\n File "/srv/lava/.cache/git-cache/exports/lava-dispatcher/2013-09-20-3ca1af8/lava_dispatcher/downloader.py", line 187, in download_with_retry\n return download_image(url, context, imgdir, decompress)\n File "/srv/lava/.cache/git-cache/exports/lava-dispatcher/2013-09-20-3ca1af8/lava_dispatcher/downloader.py", line 165, in download_image\n logging.info("downloader::Downloading_image:url is %s" % url)\nTypeError: not all arguments converted during string formatting\n' 2013-09-24 05:14:02 PM INFO: Sleep one minute and retry (5) 2013-09-24 05:15:02 PM INFO: Downloading image: http://192.168.1.4:38273/fs.tgz 2013-09-24 05:15:02 PM INFO: Downloading image:url is http 2013-09-24 05:15:02 PM WARNING: unable to download: 'Traceback (most recent call last):\n File "/srv/lava/.cache/git-cache/exports/lava-dispatcher/2013-09-20-3ca1af8/lava_dispatcher/downloader.py", line 187, in download_with_retry\n return download_image(url, context, imgdir, decompress)\n File "/srv/lava/.cache/git-cache/exports/lava-dispatcher/2013-09-20-3ca1af8/lava_dispatcher/downloader.py", line 165, in download_image\n logging.info("downloader::Downloading_image:url is %s" % url)\nTypeError: not all arguments converted during string formatting\n' 2013-09-24 05:15:02 PM DEBUG: send :  2013-09-24 05:15:02 PM DEBUG: expect (1): '['.+', , ]' 2013-09-24 05:15:02 PM DEBUG: expect (1): '['.+', , ]' [ 303.847205] EXT4-fs (mmcblk0p2): error count: 1 [ 303.851749] EXT4-fs (mmcblk0p2): initial error at 1379834369: __ext4_get_inode_loc:3629: inode 132557: block 524588 [ 303.862258] EXT4-fs (mmcblk0p2): last error at 1379834369: __ext4_get_inode_loc:3629: inode 132557: block 524588 2013-09-24 05:15:02 PM DEBUG: expect (1): '['.+', , ]' ^2013-09-24 05:15:02 PM DEBUG: expect (1): '['.+', , ]' C2013-09-24 05:15:02 PM DEBUG: expect (1): '['.+', , ]' bash-2013-09-24 05:15:02 PM DEBUG: expect (1): '['.+', , ]' 42013-09-24 05:15:02 PM DEBUG: expect (1): '['.+', , ]' .2 [rc=2552013-09-24 05:15:02 PM DEBUG: expect (1): '['.+', , ]' ]# 2013-09-24 05:15:02 PM DEBUG: expect (1): '['.+', , ]' 2013-09-24 05:15:03 PM DEBUG: sendline : umount /mnt 2013-09-24 05:15:03 PM DEBUG: send : umount /mnt 2013-09-24 05:15:03 PM DEBUG: send : 2013-09-24 05:15:03 PM DEBUG: expect (600): 'bash-4.2 \[rc=(\d+)\]# ' umount /mnt bash-4.2 [rc=0]# 2013-09-24 05:15:03 PM INFO: General Exception: downloading http://192.168.1.4:38273/fs.tgz failed after 6 tries 2013-09-24 05:15:03 PM DEBUG: finally status fail 2013-09-24 05:15:03 PM WARNING: [ACTION-E] lava_test_shell is finished with error (downloading http://192.168.1.4:38273/fs.tgz failed after 6 tries). ErrorMessage: downloading http://192.168.1.4:38273/fs.tgz failed after 6 tries Lava failed at action lava_test_shell with error:downloading http://192.168.1.4:38273/fs.tgz failed after 6 tries Traceback (most recent call last): File "/srv/lava/.cache/git-cache/exports/lava-dispatcher/2013-09-20-3ca1af8/lava_dispatcher/job.py", line 254, in run action.run(**params) File "/srv/lava/.cache/git-cache/exports/lava-dispatcher/2013-09-20-3ca1af8/lava_dispatcher/actions/lava_test_shell.py", line 543, in run testdefs_by_uuid = self._configure_target(target, testdef_urls, testdef_repos) File "/srv/lava/.cache/git-cache/exports/lava-dispatcher/2013-09-20-3ca1af8/lava_dispatcher/actions/lava_test_shell.py", line 669, in _configure_target with target.file_system(results_part, 'lava') as d: File "/usr/lib/python2.7/contextlib.py", line 17, in __enter__ return self.gen.next() File "/srv/lava/.cache/git-cache/exports/lava-dispatcher/2013-09-20-3ca1af8/lava_dispatcher/device/master.py", line 352, in file_system self.context, self.scratch_dir, url, False) File "/srv/lava/.cache/git-cache/exports/lava-dispatcher/2013-09-20-3ca1af8/lava_dispatcher/downloader.py", line 193, in download_with_retry 'downloading %s failed after %d tries' % (url, tries)) RuntimeError: downloading http://192.168.1.4:38273/fs.tgz failed after 6 tries 2013-09-24 05:15:03 PM INFO: Submitting the test result with parameters = {u'stream': u'/anonymous/wand/', u'server': u'http://novello@192.168.1.203/RPC2/'} 2013-09-24 05:15:03 PM WARNING: specifying a user without a token is unlikely to work 2013-09-24 05:15:03 PM DEBUG: server RPC endpoint URL: http://novello@192.168.1.203/RPC2/ 2013-09-24 05:15:03 PM ERROR: Failed to submit the test result. Error = Username provided but no token found. ERROR: Username provided but no token found. (oe)root@novello-HP-Compaq-6720s:/media# nload_image(url, context, imgdir, decompress)\n File "/srv/lava/.cache/git-cache/exports/lava-dispatcher/2013-09-20-3ca1af8/lava_dispatcher/downloader.py", line 165, in download_image\n logging.info("downloader::Downloading_image:url is %s" % url)\nTypeError: not all arguments converted during string formatting\n' 2013-09-24 05:10:01 PM INFO: Sleep one minute and retry (1) 2013-09-24 05:11:01 PM INFO: Downloading image: http://192.168.1.4:38273/fs.tgz 2013-09-24 05:11:01 PM INFO: Downloading image:url is http 2013-09-24 05:11:01 PM WARNING: unable to download: 'Traceback (most recent call last):\n File "/srv/lava/.cache/git-cache/exports/lava-dispatcher/2013-09-20-3ca1af8/lava_dispatcher/downloader.py", line 187, in download_with_retry\n return download_image(url, context, imgdir, decompress)\n File "/srv/lava/.cache/git-cache/exports/lava-dispatcher/2013-09-20-3ca1af8/lava_dispatcher/downloader.py", line 165, in download_image\n logging.info("downloader::Downloading_image:url is %s" % url)\nTypeError: not all arguments converted during string formatting\n' 2013-09-24 05:11:01 PM INFO: Sleep one minute and retry (2) 2013-09-24 05:12:02 PM INFO: Downloading image: http://192.168.1.4:38273/fs.tgz 2013-09-24 05:12:02 PM INFO: Downloading image:url is http 2013-09-24 05:12:02 PM WARNING: unable to download: 'Traceback (most recent call last):\n File "/srv/lava/.cache/git-cache/exports/lava-dispatcher/2013-09-20-3ca1af8/lava_dispatcher/downloader.py", line 187, in download_with_retry\n return download_image(url, context, imgdir, decompress)\n File "/srv/lava/.cache/git-cache/exports/lava-dispatcher/2013-09-20-3ca1af8/lava_dispatcher/downloader.py", line 165, in download_image\n logging.info("downloader::Downloading_image:url is %s" % url)\nTypeError: not all arguments converted during string formatting\n' 2013-09-24 05:12:02 PM INFO: Sleep one minute and retry (3) 2013-09-24 05:13:02 PM INFO: Downloading image: http://192.168.1.4:38273/fs.tgz 2013-09-24 05:13:02 PM INFO: Downloading image:url is http 2013-09-24 05:13:02 PM WARNING: unable to download: 'Traceback (most recent call last):\n File "/srv/lava/.cache/git-cache/exports/lava-dispatcher/2013-09-20-3ca1af8/lava_dispatcher/downloader.py", line 187, in download_with_retry\n return download_image(url, context, imgdir, decompress)\n File "/srv/lava/.cache/git-cache/exports/lava-dispatcher/2013-09-20-3ca1af8/lava_dispatcher/downloader.py", line 165, in download_image\n logging.info("downloader::Downloading_image:url is %s" % url)\nTypeError: not all arguments converted during string formatting\n' 2013-09-24 05:13:02 PM INFO: Sleep one minute and retry (4) 2013-09-24 05:14:02 PM INFO: Downloading image: http://192.168.1.4:38273/fs.tgz 2013-09-24 05:14:02 PM INFO: Downloading image:url is http 2013-09-24 05:14:02 PM WARNING: unable to download: 'Traceback (most recent call last):\n File "/srv/lava/.cache/git-cache/exports/lava-dispatcher/2013-09-20-3ca1af8/lava_dispatcher/downloader.py", line 187, in download_with_retry\n return download_image(url, context, imgdir, decompress)\n File "/srv/lava/.cache/git-cache/exports/lava-dispatcher/2013-09-20-3ca1af8/lava_dispatcher/downloader.py", line 165, in download_image\n logging.info("downloader::Downloading_image:url is %s" % url)\nTypeError: not all arguments converted during string formatting\n' 2013-09-24 05:14:02 PM INFO: Sleep one minute and retry (5) 2013-09-24 05:15:02 PM INFO: Downloading image: http://192.168.1.4:38273/fs.tgz 2013-09-24 05:15:02 PM INFO: Downloading image:url is http 2013-09-24 05:15:02 PM WARNING: unable to download: 'Traceback (most recent call last):\n File "/srv/lava/.cache/git-cache/exports/lava-dispatcher/2013-09-20-3ca1af8/lava_dispatcher/downloader.py", line 187, in download_with_retry\n return download_image(url, context, imgdir, decompress)\n File "/srv/lava/.cache/git-cache/exports/lava-dispatcher/2013-09-20-3ca1af8/lava_dispatcher/downloader.py", line 165, in download_image\n logging.info("downloader::Downloading_image:url is %s" % url)\nTypeError: not all arguments converted during string formatting\n' 2013-09-24 05:15:02 PM DEBUG: send :  2013-09-24 05:15:02 PM DEBUG: expect (1): '['.+', \n' HAVE I TO INGREASE THE WAITING TIME ??? BEST REGARDS NOVELLO G.