Back to build
Raw log | Switch to full mode | Login

2 files remaining... DEBUG: config flag: /etc/botanist/config.json DEBUG: executing command: "/etc/connectivity/host_cmds.sh" environment of subprocess: [] 2019/04/20 00:27:00 attempting to send <<netboot>>cmdline... 2019/04/20 00:27:00 done 2019/04/20 00:27:00 attempting to send <<image>>sparse.fvm... 2019/04/20 00:27:02 done 2019/04/20 00:27:02 attempting to send <<image>>bootloader.img... 2019/04/20 00:27:02 target is busy, retrying in one second 2019/04/20 00:27:03 attempting to send <<image>>bootloader.img... 2019/04/20 00:27:03 done 2019/04/20 00:27:03 attempting to send <<image>>zircona.img... 2019/04/20 00:27:03 done 2019/04/20 00:27:03 attempting to send <<image>>zirconr.img... 2019/04/20 00:27:03 target is busy, retrying in one second [0.000] 00000.00000> zbi: @ 0xffffff80012f2000 (17482848 bytes) [0.000] 00000.00000> UART: FIFO depth 16 [0.000] 00000.00000> PMM: boot reserve add [0x100000, 0x2c5fff] [0.000] 00000.00000> PMM: boot reserve add [0x12f2000, 0x239efff] [0.000] 00000.00000> PMM: arena too small to be useful (size 4096) [0.000] 00000.00000> PMM: pmm_add_arena failed to initialize arena [0.000] 00000.00000> MEM: Failed to add pmm range at 0x8afff000 size 0x1000 [0.000] 00000.00000> PMM: boot reserve marking WIRED [0x100000, 0x2c5fff] [0.000] 00000.00000> PMM: boot reserve marking WIRED [0x12f2000, 0x239efff] [0.000] 00000.00000> welcome to Zircon [0.000] 00000.00000> KASLR: .text section at 0xffffffff00100000 [0.000] 00000.00000> INIT: cpu 0, calling hook 0xffffffff001aa428 (global_prng_seed) at level 0x30000, flags 0x1 [0.000] 00000.00000> initializing vm pre-heap [0.000] 00000.00000> VM: marking boot alloc used range [0x239f000, 0x239f100) [0.000] 00000.00000> INIT: cpu 0, calling hook 0xffffffff00147abc (elf_build_id) at level 0x4fffe, flags 0x1 [0.000] 00000.00000> INIT: cpu 0, calling hook 0xffffffff00147c48 (version) at level 0x4ffff, flags 0x1 [0.000] 00000.00000> version: [0.000] 00000.00000> arch: x86 [0.000] 00000.00000> platform: pc [0.000] 00000.00000> target: pc [0.000] 00000.00000> project: x64 [0.000] 00000.00000> buildid: git-13ee3dc5e4c46bf127977ad28645c47442ec517d [0.000] 00000.00000> ELF build ID: 5f3e39bd4ed89d3b8122947842f1eac846a04683 [0.000] 00000.00000> initializing heap [0.000] 00000.00000> INIT: cpu 0, calling hook 0xffffffff00102e1c (x86_resource_init) at level 0x50000, flags 0x1 [0.000] 00000.00000> INIT: cpu 0, calling hook 0xffffffff001a9630 (console) at level 0x50000, flags 0x1 [0.000] 00000.00000> initializing vm [0.000] 00000.00000> VM: reserving kernel region [0xffffffff00100000, 0xffffffff001ee000) flags 0x28 name 'kernel_code' [0.000] 00000.00000> VM: reserving kernel region [0xffffffff001ee000, 0xffffffff00232000) flags 0x8 name 'kernel_rodata' [0.000] 00000.00000> VM: reserving kernel region [0xffffffff00232000, 0xffffffff00242000) flags 0x18 name 'kernel_data' [0.000] 00000.00000> VM: reserving kernel region [0xffffffff00242000, 0xffffffff002c6000) flags 0x18 name 'kernel_bss' [0.000] 00000.00000> INIT: cpu 0, calling hook 0xffffffff00103ae0 (display_memtype) at level 0x60001, flags 0x1 [0.000] 00000.00000> INIT: cpu 0, calling hook 0xffffffff00138fa0 (acpi_tables) at level 0x60001, flags 0x1 [0.000] 00000.00000> INIT: cpu 0, calling hook 0xffffffff00101c40 (hpet) at level 0x60002, flags 0x1 [0.000] 00000.00000> INIT: cpu 0, calling hook 0xffffffff00102000 (apic) at level 0x60002, flags 0x1 [0.000] 00000.00000> x2APIC enabled [0.000] 00000.00000> INIT: cpu 0, calling hook 0xffffffff001061b4 (timer) at level 0x60003, flags 0x1 [0.000] 00000.00000> HPET frequency: 23999 ticks/ms [0.000] 00000.00000> TSC frequency: 2712000 ticks/ms [21.040] 00000.00000> timer features: constant_tsc 1 invariant_tsc 1 tsc_deadline 1 [21.040] 00000.00000> Using TSC as wallclock [21.040] 00000.00000> initializing kernel [21.040] 00000.00000> initializing mp [21.040] 00000.00000> initializing timers [21.040] 00000.00000> INIT: cpu 0, calling hook 0xffffffff0013c578 (debuglog) at level 0x7ffff, flags 0x1 [21.040] 00000.00000> INIT: cpu 0, calling hook 0xffffffff00195518 (thread_set_priority_experiment) at level 0x7ffff, flags 0x1 [21.040] 00000.00000> thread set priority experiment is : ENABLED [21.040] 00000.00000> INIT: cpu 0, calling hook 0xffffffff001aa67c (global_prng_thread_safe) at level 0x7ffff, flags 0x1 [21.040] 00000.00000> creating bootstrap completion thread [21.381] 00000.00000> top of bootstrap2() [21.381] 00000.00000> INIT: cpu 0, calling hook 0xffffffff0013151c (dpc) at level 0x80000, flags 0x1 [21.395] 00000.00000> INIT: cpu 0, calling hook 0xffffffff00152978 (libobject) at level 0x80000, flags 0x1 [21.395] 00000.00000> OOM: started thread [21.408] 00000.00000> Processor Model Info: type 0 family 0x6 model 0xe stepping 0x9 [21.408] 00000.00000> display_family 0x6 display_model 0x8e [21.408] 00000.00000> Vendor: Intel [21.408] 00000.00000> Microarch: Kaby Lake [21.408] 00000.00000> F/M/S: 6/8e/9 [21.408] 00000.00000> Brand: Intel(R) Core(TM) i5-7300U CPU @ 2.60GHz [21.408] 00000.00000> Features: fpu sse sse2 sse3 ssse3 sse4.1 sse4.2 mmx avx avx2 fxsr pcid xsave mon aesni clflush [21.408] 00000.00000> clflushopt fsgsbase tsc_adj smep smap erms rdrand rdseed syscall nx huge rdtscp [21.408] 00000.00000> invar_tsc tsc_deadline x2apic vmx pt hwp [21.408] 00000.00000> initializing platform [21.408] 00000.00000> INIT: cpu 0, calling hook 0xffffffff001101f4 (x86_perfmon) at level 0x90000, flags 0x1 [21.408] 00000.00000> PMU: version 4 [21.408] 00000.00000> UART: started IRQ driven RX [21.408] 00000.00000> UART: started IRQ driven TX [21.408] 00000.00000> cpu topology: [21.408] 00000.00000> 0: apic id 0x0 package 0 node 0 core 0 smt 0 BSP [21.408] 00000.00000> 1: apic id 0x2 package 0 node 0 core 1 smt 0 [21.408] 00000.00000> 2: apic id 0x1 package 0 node 0 core 0 smt 1 [21.408] 00000.00000> 3: apic id 0x3 package 0 node 0 core 1 smt 1 [21.408] 00000.00000> Found 4 cpus [21.408] 00000.00000> booting apic ids: 0x2 0x1 0x3 [21.424] 00000.00000> entering scheduler on cpu 2 [21.425] 00000.00000> entering scheduler on cpu 3 [21.425] 00000.00000> entering scheduler on cpu 1 [21.428] 00000.00000> smbios: manufacturer="Intel Corporation" product="NUC7i5DNHE" [21.428] 00000.00000> initializing target [21.428] 00000.00000> INIT: cpu 0, calling hook 0xffffffff001053a0 (x86_pcie_init) at level 0xa0000, flags 0x1 [21.428] 00000.00000> moving to last init level [21.428] 00000.00000> INIT: cpu 0, calling hook 0xffffffff00144140 (ktrace) at level 0xc0000, flags 0x1 [21.431] 00000.00000> ktrace: buffer at 0xffffff9ad2116000 (33554432 bytes) [21.431] 00000.00000> INIT: cpu 0, calling hook 0xffffffff00147ab4 (userboot) at level 0xc0000, flags 0x1 [21.431] 00000.00000> userboot: ramdisk 0x10ad000 @ 0xffffff80012f2000 [21.431] 00000.00000> userboot: userboot rodata 0 @ [0x44261c679000,0x44261c67c000) [21.431] 00000.00000> userboot: userboot code 0x3000 @ [0x44261c67c000,0x44261c687000) [21.431] 00000.00000> userboot: vdso/full rodata 0 @ [0x44261c687000,0x44261c68e000) [21.431] 00000.00000> userboot: vdso/full code 0x7000 @ [0x44261c68e000,0x44261c68f000) [21.431] 00000.00000> userboot: entry point @ 0x44261c67cc10 [21.431] 00000.00000> INIT: cpu 0, calling hook 0xffffffff001aa030 (kernel_shell) at level 0xc0000, flags 0x1 [21.431] 01036.01043> userboot: option "netsvc.disable=true" [21.431] 01036.01043> userboot: option "zircon.system.disable-automount=true" [21.431] 01036.01043> userboot: option "zircon.autorun.boot=/boot/infra/setup" [21.431] 01036.01043> userboot: option "kernel.serial=legacy" [21.431] 01036.01043> userboot: option "http://192.168.42.1/multiboot/54%3Ab2%3A03%3A13%3Ab3%3Ae7=" [21.431] 01036.01043> userboot: option "multiboot.boot_loader_name=iPXE+1.0.0++(d2063)" [21.470] 01036.01043> userboot: searching bootfs for 'bin/bootsvc' [21.470] 01036.01043> userboot: 'bin/bootsvc' has PT_INTERP "lib/ld.so.1" [21.470] 01036.01043> userboot: searching bootfs for 'lib/ld.so.1' [21.470] 01036.01043> userboot: userboot: loaded lib/ld.so.1 at 0x4b27d0c12000, entry point 0x4b27d0c980d3 [21.470] 01036.01043> userboot: userboot: loaded vDSO at 0x467fdf19e000, entry point 0x0 [21.470] 01036.01043> userboot: process bin/bootsvc started. [21.470] 01036.01043> userboot: waiting for loader-service requests... [21.471] 01036.01043> userboot: searching bootfs for 'lib/libasync-default.so' [21.471] 01036.01043> userboot: searching bootfs for 'lib/libfdio.so' [21.471] 01036.01043> userboot: searching bootfs for 'lib/liblaunchpad.so' [21.471] 01036.01043> userboot: searching bootfs for 'lib/libtrace-engine.so' [21.471] 01050.01053> dso: id=18de7d58f51e8ba5c4f6afdd0cc8440f482c2b45 base=0x000068cdd85be000 name=<application> [21.471] 01050.01053> dso: id=c189f51f19d10785d93b5235ad1b46dca4451b00 base=0x00006a850f892000 name=libasync-default.so [21.471] 01050.01053> dso: id=40ab5fa3b61f12fef4a44477a687f608661cd450 base=0x0000467fdf19e000 name=<vDSO> [21.471] 01050.01053> dso: id=67a12284bce140fc32aaaeac223e0e8f85cb5085 base=0x00004b27d0c12000 name=libc.so [21.471] 01050.01053> dso: id=27787977e95f3b9563c9e0bd4d34ec92b7e9ad88 base=0x00001f0217c1f000 name=libfdio.so [21.471] 01050.01053> dso: id=6fc2232dc8c1bc5c6adb8ad50ca794b5a260ee4f base=0x0000240437c7a000 name=liblaunchpad.so [21.471] 01050.01053> dso: id=c9042b83fe01206008fcefb16395238417248169 base=0x0000390a20481000 name=libtrace-engine.so [21.471] 01050.01053> bootsvc: Starting... [21.471] 01036.01043> userboot: loader-service channel peer closed [21.471] 01036.01043> userboot: finished! [21.471] 01050.01053> bootsvc: Creating bootfs service... [21.472] 01050.01053> bootsvc: Processing bootdata... [21.472] 01050.01053> bootsvc: Loading boot cmdline overrides... [21.472] 01050.01053> bootsvc: Loading kernel VMOs... [21.472] 01050.01053> bootsvc: Creating loader service... [21.472] 01050.01053> bootsvc: Launching next process... [21.472] 01050.01096> bootsvc: launched bin/devmgr [21.473] 01104.01117> devmgr: main() [21.473] 01104.01117> cmdline: netsvc.disable=true [21.473] 01104.01117> cmdline: zircon.system.disable-automount=true [21.473] 01104.01117> cmdline: zircon.autorun.boot=/boot/infra/setup [21.473] 01104.01117> cmdline: kernel.serial=legacy [21.473] 01104.01117> cmdline: http://192.168.42.1/multiboot/54%3Ab2%3A03%3A13%3Ab3%3Ae7= [21.473] 01104.01117> cmdline: multiboot.boot_loader_name=iPXE+1.0.0++(d2063) [21.473] 01104.01117> devmgr: coordinator_init() [21.473] 01104.01117> devmgr: init [21.473] 01104.01117> devmgr: svc init [21.473] 01104.01117> devmgr: launch /boot/bin/svchost (svchost) OK [21.473] 01104.01117> devmgr: vfs init [21.473] 01104.01117> devmgr: launch /boot/bin/fshost (fshost) OK [21.473] 01104.01225> devmgr: shell startup [21.474] 01182.01202> fshost: started. [21.475] 01104.01212> devmgr: launch /boot/bin/pwrbtn-monitor (pwrbtn-monitor) OK [21.475] 01104.01238> devmgr: launch /boot/bin/virtual-console (virtual-console) OK [21.475] 01104.01238> zircon.autorun.boot: starting '/boot/infra/setup'... [21.476] 01104.01238> devmgr: launch /boot/infra/setup (autorun:boot) OK [21.479] 01104.01117> devcoord: launch devhost 'devhost:sys': pid=2049 [21.479] 01104.01117> devcoord: launch devhost 'devhost:test': pid=2082 [21.479] 01104.01117> devcoord: launch devhost 'devhost:root': pid=2115 [21.479] 01104.01117> devcoord: launch devhost 'devhost:misc': pid=2168 [21.480] 02049.02073> devhost: trace provider registry begun [21.482] 02082.02105> devhost: trace provider registry begun [21.482] 02115.02155> devhost: trace provider registry begun [21.483] 02168.02204> devhost: trace provider registry begun [21.485] 01104.01225> devmgr: launch /boot/bin/sh (sh:console) OK [21.550] 02049.02073> acpi-bus: not using IOMMU [21.555] 02049.02073> acpi-pwrbtn: initialized [21.577] 02049.02073> acpi: published device pci(0x5e910ce54200), parent=proxy(0x5e910ce50540), handle=0x5e910ce8cc30 [21.578] 02049.02073> acpi: published device rtc(0x5e910ce4f080), parent=acpi(0x5e910ce50780), handle=0x5e910cea55b0 [21.579] 02049.02073> acpi-ec: initialized [21.581] 02049.02073> acpi: failed to create NHLT VMO (res -10) [21.581] 02049.02073> acpi: failed to publish NHLT metadata [21.584] 02049.02073> [sysmem_init 28] async_get_default_dispatcher(): 0x5e910ce430a0 [21.584] 02049.02073> [sysmem_bind 40] sysmem_bind() [21.584] 02049.02073> acpi-bus: sysmem_register_protocol() intentionally ignored for now. [21.584] 02049.02073> PMU: 7 arch events [21.584] 02049.02073> PMU: arch event id range: 1-7 [21.584] 02049.02073> PMU: 102 model events [21.584] 02049.02073> PMU: model event id range: 1-241 [21.584] 02049.02073> Intel Processor Trace configuration for this chipset: [21.584] 02049.02073> mtc_freq_mask: 0x249 [21.584] 02049.02073> cyc_thresh_mask: 0x3fff [21.584] 02049.02073> psb_freq_mask: 0x3f [21.584] 02049.02073> num addr ranges: 2 [21.584] 01250.01579> vc: new input device /dev/class/input/000 [21.585] 01104.01117> devcoord: launch devhost 'devhost:pci#1:8086:5916': pid=3043 [21.585] 01104.01117> devcoord: launch devhost 'devhost:pci#3:8086:9d2f': pid=3100 [21.586] 01104.01117> devcoord: launch devhost 'devhost:pci#5:8086:9d60': pid=3162 [21.586] 03043.03073> devhost: trace provider registry begun [21.586] 01104.01117> devcoord: launch devhost 'devhost:pci#6:8086:9d61': pid=3250 [21.587] 01104.01117> devcoord: launch devhost 'devhost:pci#9:8086:9d03': pid=3323 [21.587] 03162.03201> devhost: trace provider registry begun [21.588] 01104.01117> devcoord: launch devhost 'devhost:pci#14:8086:9d71': pid=3425 [21.588] 03100.03137> devhost: trace provider registry begun [21.589] 03250.03295> devhost: trace provider registry begun [21.589] 01104.01117> devcoord: launch devhost 'devhost:pci#16:8086:156f': pid=3515 [21.590] 03250.03295> initialized intel serialio i2c driver, reg=0x5203fa27a000 regsize=4096 [21.590] 03162.03201> initialized intel serialio i2c driver, reg=0xd123d0be000 regsize=4096 [21.592] 03323.03373> devhost: trace provider registry begun [21.593] 03425.03477> devhost: trace provider registry begun [21.593] 03323.03373> ahci: using MSI interrupt [21.593] 03515.03574> devhost: trace provider registry begun [21.594] 03100.03850> * found USB device (0x18d1:0xa002, USB 2.0) config 1 [21.595] 03100.03850> * found USB device (0x18d1:0xa003, USB 3.0) config 1 [21.596] 03425.03477> [IHDA DSP 00:1f.3] Failed to fetch NHLT (res -25) [21.596] 03425.03477> devhost[00:1f.3/intel-hda-000/intel-sst-dsp-000] bind driver '/boot/driver/dsp.so' failed: -25 [21.596] 01104.01117> devcoord: rpc: bind-driver 'intel-sst-dsp-000' status -25 [21.694] 01250.01579> vc: new display device /dev/class/display-controller/000/virtcon [21.834] 03043.04142> i915: MST not supported [22.307] 03100.03850> * found USB device (0x0781:0x5583, USB 3.0) config 1 [22.308] 03100.03137> UMS: parent: 'ifc-000' [22.308] 03100.03137> UMS:Max lun is: 0 [22.337] 03043.04142> i915: MST not supported [23.057] 03100.03850> * found USB device (0x0cf3:0xe300, USB 2.1) config 1 [23.059] 03100.03137> devhost[00:14.0/xhci/usb-bus/002/002/ifc-001] bind driver '/boot/driver/bt-transport-usb.so' failed: -2 [23.059] 01104.01117> devcoord: rpc: bind-driver 'ifc-001' status -2 [23.310] 03100.04229> UMS: block size is: 0x00000200 [23.310] 03100.04229> UMS: total blocks is: 30031872 [23.310] 03100.04229> UMS: total size is: 15376318464 [23.310] 03100.04229> UMS: read-only: 0 removable: 1 [23.311] 01182.01202> devmgr: /dev/class/block/000: MBR? [23.311] 01104.01117> devcoord: dc_bind_device() '/boot/driver/mbr.so' [23.313] 01182.01202> devmgr: /dev/class/block/002: MBR? [23.313] 01104.01117> devcoord: dc_bind_device() '/boot/driver/mbr.so' [23.382] 03043.04142> i915: No displays detected [23.593] 03250.03295> intel-i2c-controller: intel_serialio_i2c_slave_transfer: -21 [23.593] 03250.03295> i2c-hid: could not read HID descriptor: 0 [23.593] 03250.03295> devhost[00:15.1/i2c-bus-9d61/004c] bind driver '/boot/driver/i2c-hid.so' failed: -2 [23.593] 01104.01117> devcoord: rpc: bind-driver '004c' status -2 [23.593] 03162.03201> intel-i2c-controller: intel_serialio_i2c_slave_transfer: -21 [23.593] 03162.03201> i2c-hid: could not read HID descriptor: 0 [23.593] 03162.03201> devhost[00:15.0/i2c-bus-9d60/0020] bind driver '/boot/driver/i2c-hid.so' failed: -2 [23.593] 01104.01117> devcoord: rpc: bind-driver '0020' status -2 [23.607] 03323.03810> sata2: dev info [23.607] 03323.03810> serial=AA000000000000008069 [23.607] 03323.03810> firmware rev=0R08A1 0 [23.607] 03323.03810> model id=ETMAT 8MSP1582 G [23.607] 03323.03810> major=0x3f0 ACS2 DMA 32 commands [23.607] 03323.03810> LBA48 250069680 sectors, sector size=512 [23.610] 04483.04497> paver:[InitializeGpt] Located GPT is invalid; Attempting to initialize [23.610] 01104.01117> devcoord: dc_bind_device() '/boot/driver/gpt.so' [23.610] 03323.03373> gpt: device_get_metadata failed (-25) [23.612] 04483.04497> paver:[Initialize] Successfully initialized EFI Device Partitioner [23.612] 01104.01117> devcoord: dc_bind_device() '' [23.612] 01182.01202> devmgr: /dev/class/block/003: GPT? [23.612] 01104.01117> devcoord: dc_bind_device() '/boot/driver/gpt.so' [23.612] 03323.03373> gpt: device_get_metadata failed (-25) [23.615] 04647.04666> 34+0 records in [23.615] 04647.04666> 34+0 records out [23.615] 04647.04666> 17408 bytes copied [23.617] 04756.04770> 34+0 records in [23.617] 04756.04770> 34+0 records out [23.617] 04756.04770> 17408 bytes copied [23.618] 04860.04874> netifc: ? /dev/class/ethernet/000 [23.618] 04860.04874> netifc: create 512 eth buffers [23.618] 04860.04874> macaddr: 54:b2:03:13:b3:e7 [23.618] 04860.04874> ip6addr: fe80::56b2:34d:fe13:b3e7 [23.618] 04860.04874> snmaddr: ff02::1:ff13:b3e7 [23.619] 04860.04874> netsvc: using /dev/class/ethernet/000 [23.619] 04860.04874> _ _ _ [23.619] 04860.04874> | | | | | [23.619] 04860.04874> _______ __| | |__ ___ ___ | |_ [23.619] 04860.04874> |_ / _ \/ _` | '_ \ / _ \ / _ \| __| [23.619] 04860.04874> / / __/ (_| | |_) | (_) | (_) | |_ [23.619] 04860.04874> /___\___|\__,_|_.__/ \___/ \___/ \__| [23.619] 04860.04874> zedboot: version: 0.7.13 [23.619] 04860.04874> netsvc: nodename='rash-moan-copy-slob' [23.619] 04860.04874> netsvc: will not advertise [23.619] 04860.04874> netsvc: start [793.023] 04860.04874> netsvc: tftp write of file <<netboot>>cmdline completed [793.023] 04860.04874> netsvc: metrics: {"inorderblks": 1,"oooblks": 0,"ack": 1,"nack": 0,"timeouts": 0,"sas": 0,"inorderbytes": 55} [793.024] 04860.04874> netsvc: Running FVM Paver [793.026] 04860.04968> paver:[InitializeGpt] Located GPT is invalid; Attempting to initialize [793.026] 01104.01117> devcoord: dc_bind_device() '' [793.026] 01104.01117> devcoord: dc_bind_device() '/boot/driver/gpt.so' [793.027] 03323.03373> gpt: device_get_metadata failed (-25) [793.028] 01182.01202> devmgr: /dev/class/block/003: GPT? [793.028] 01104.01117> devcoord: dc_bind_device() '/boot/driver/gpt.so' [793.028] 03323.03373> devhost: rpc:bind-device failed: -20 [793.028] 04860.04968> paver:[Initialize] Successfully initialized EFI Device Partitioner [793.028] 04860.04968> paver:[PartitionPave] Paving partition. [793.028] 04860.04968> paver:[FindFirstFit] Looking for space [793.028] 04860.04968> paver:[FindFirstFit] Sorting [793.028] 04860.04968> paver:[FindFirstFit] Partition[0] From Block [0, 34) ... (next partition starts at block 250069646) [793.029] 04860.04968> paver:[FindFirstFit] There are 250069612 free blocks (16777216 requested) [793.029] 04860.04968> paver:[AddPartition] Found space in GPT - OK 250069612 @ 34 [793.029] 04860.04968> paver:[AddPartition] Final space in GPT - OK 16777216 @ 34 [793.029] 04860.04968> paver:[AddPartition] Added partition, waiting for bind [793.029] 01104.01117> devcoord: dc_bind_device() '' [793.030] 01182.01202> devmgr: /dev/class/block/003: GPT? [793.030] 01104.01117> devcoord: dc_bind_device() '/boot/driver/gpt.so' [793.030] 03323.03373> gpt: device_get_metadata failed (-25) [793.031] 04860.04968> paver:[AddPartition] Added partition, waiting for bind - OK [793.031] 04860.04968> paver:[PartitionPave] Streaming partitions... [793.031] 04948.04962> Found compressed file [793.031] 04860.04968> paver:[FvmStreamPartitions] Header Validated - OK [793.031] 04860.04968> paver:[FvmPartitionFormat] Initializing partition as FVM [793.034] 01104.01117> devcoord: dc_bind_device() '/boot/driver/fvm.so' [794.036] 04860.04968> paver:[FvmStreamPartitions] Partitions pre-validated successfully: Enough space exists to pave. [794.036] 04860.04968> paver:[AllocatePartitions] Allocating partition blobfs consisting of 1 slices [794.040] 04860.04968> paver:[AllocatePartitions] Allocating partition minfs consisting of 1 slices [794.041] 04860.04968> paver:[AllocatePartitions] Creating zxcrypt volume [794.042] 03323.03373> devhost_get_handles(0x684ed50fb9c0:block) open path='zxcrypt/block', r=-2 [794.042] 01104.01117> devcoord: dc_bind_device() '/boot/driver/zxcrypt.so' [794.043] 03323.03373> devhost_get_handles(0x684ed50fb9c0:block) open path='zxcrypt', r=-2 [794.047] 04860.04968> paver:[FvmStreamPartitions] Partition space pre-allocated successfully. [794.047] 04860.04968> paver:[FvmStreamPartitions] Streaming partition 0 [794.047] 04860.04968> paver:[StreamFvmPartition] Writing extent 0... [794.047] 04860.04974> netsvc: paver write progress 0.2% [794.047] 04860.04968> paver:[StreamFvmPartition] 8192 bytes written, 8380416 zeroes left [794.074] 04860.04968> paver:[StreamFvmPartition] Writing extent 1... [794.074] 04860.04968> paver:[StreamFvmPartition] 8192 bytes written, 8380416 zeroes left [794.090] 04860.04968> paver:[StreamFvmPartition] Writing extent 2... [794.095] 04860.04968> paver:[StreamFvmPartition] 2097152 bytes written, 6291456 zeroes left [794.107] 04860.04968> paver:[StreamFvmPartition] Writing extent 3... [794.112] 04860.04968> paver:[StreamFvmPartition] 2097152 bytes written, 6291456 zeroes left [794.124] 04860.04968> paver:[StreamFvmPartition] Writing extent 4... [794.632] 04860.04874> netsvc: tftp write of file <<image>>sparse.fvm completed [794.632] 04860.04874> netsvc: metrics: {"inorderblks": 165711,"oooblks": 0,"ack": 648,"nack": 0,"timeouts": 0,"sas": 0,"inorderbytes": 169687319} [794.633] 04860.04968> paver:[StreamFvmPartition] 182951936 bytes written, 1597440 zeroes left [794.636] 04860.04968> paver:[FvmStreamPartitions] Done streaming partition 0 [794.636] 04860.04968> paver:[FvmStreamPartitions] Done flushing partition 0 [794.636] 04860.04968> paver:[FvmStreamPartitions] Streaming partition 1 [794.636] 04860.04968> paver:[StreamFvmPartition] Writing extent 0... [794.636] 04860.04968> paver:[StreamFvmPartition] 8192 bytes written, 8380416 zeroes left [794.675] 04860.04968> paver:[StreamFvmPartition] Writing extent 1... [794.676] 04860.04968> paver:[StreamFvmPartition] 65536 bytes written, 8323072 zeroes left [794.714] 04860.04968> paver:[StreamFvmPartition] Writing extent 2... [794.714] 04860.04968> paver:[StreamFvmPartition] 65536 bytes written, 8323072 zeroes left [794.752] 04860.04968> paver:[StreamFvmPartition] Writing extent 3... [794.791] 04860.04968> paver:[StreamFvmPartition] Writing extent 4... [794.800] 04860.04968> paver:[StreamFvmPartition] 2097152 bytes written, 14680064 zeroes left [794.863] 04860.04968> paver:[StreamFvmPartition] Writing extent 5... [794.863] 04860.04968> paver:[StreamFvmPartition] 57344 bytes written, 8331264 zeroes left [794.907] 04860.04968> paver:[FvmStreamPartitions] Done streaming partition 1 [794.907] 04860.04968> paver:[FvmStreamPartitions] Done flushing partition 1 [794.908] 04948.04962> Reading FVM from compressed file: true [794.908] 04948.04962> Remaining bytes read into compression buffer: 0 [794.908] 04948.04962> Remaining bytes written to decompression buffer: 0 [794.908] 04948.04962> Time reading bytes from sparse FVM file: 234583970 (0 s) [794.908] 04948.04962> Time reading bytes AND decompressing them: 338865372 (0 s) [794.908] 04860.04968> paver:[PartitionPave] Completed successfully [795.633] 04860.04874> netsvc: Running BOOTLOADER Paver [795.636] 04860.05704> paver:[Initialize] Successfully initialized EFI Device Partitioner [795.636] 04860.05704> paver:[RealMain] SKIPPING BOOTLOADER install on x64 device, pass --force if desired. [795.645] 04860.04874> netsvc: tftp write of file <<image>>bootloader.img completed [795.645] 04860.04874> netsvc: metrics: {"inorderblks": 1093,"oooblks": 0,"ack": 5,"nack": 0,"timeouts": 0,"sas": 0,"inorderbytes": 1118208} [795.645] 04860.04874> netsvc: Running ZIRCON-A Paver [795.648] 04860.05845> paver:[Initialize] Successfully initialized EFI Device Partitioner [795.648] 04860.05845> paver:[PartitionPave] Paving partition. [795.648] 04860.05845> paver:[FindFirstFit] Looking for space [795.648] 04860.05845> paver:[FindFirstFit] Partition seen with start 34, end 16777249 (length 16777216) [795.648] 04860.05845> paver:[FindFirstFit] Sorting [795.648] 04860.05845> paver:[FindFirstFit] Partition[0] From Block [0, 34) ... (next partition starts at block 34) [795.648] 04860.05845> paver:[FindFirstFit] There are 0 free blocks (32768 requested) [795.648] 04860.05845> paver:[FindFirstFit] Partition[1] From Block [34, 16777250) ... (next partition starts at block 250069646) [795.648] 04860.05845> paver:[FindFirstFit] There are 233292396 free blocks (32768 requested) [795.648] 04860.05845> paver:[AddPartition] Found space in GPT - OK 233292396 @ 16777250 [795.648] 04860.05845> paver:[AddPartition] Final space in GPT - OK 32768 @ 16777250 [795.648] 03323.03373> block: Joining un-closed FIFO server [795.648] 04860.05845> paver:[AddPartition] Added partition, waiting for bind [795.648] 03323.03373> block: Joining un-closed FIFO server [795.649] 01104.01117> devcoord: dc_bind_device() '' [795.650] 01182.01202> devmgr: /dev/class/block/003: GPT? [795.650] 01104.01117> devcoord: dc_bind_device() '/boot/driver/gpt.so' [795.650] 03323.03373> gpt: device_get_metadata failed (-25) [795.651] 01182.01202> devmgr: /dev/class/block/008: FVM? [795.651] 01104.01117> devcoord: dc_bind_device() '/boot/driver/fvm.so' [795.651] 04860.05845> paver:[AddPartition] Added partition, waiting for bind - OK [795.782] 04860.04874> netsvc: tftp write of file <<image>>zircona.img completed [795.782] 04860.04874> netsvc: metrics: {"inorderblks": 13900,"oooblks": 0,"ack": 55,"nack": 0,"timeouts": 0,"sas": 0,"inorderbytes": 14233280} [795.809] 04860.05845> paver:[PartitionPave] Completed successfully 2019/04/20 00:27:04 attempting to send <<image>>zirconr.img... [796.784] 04860.04874> netsvc: Running ZIRCON-R Paver [796.786] 04860.06118> paver:[Initialize] Successfully initialized EFI Device Partitioner [796.786] 04860.06118> paver:[PartitionPave] Paving partition. [796.786] 04860.06118> paver:[FindFirstFit] Looking for space [796.786] 04860.06118> paver:[FindFirstFit] Partition seen with start 34, end 16777249 (length 16777216) [796.786] 04860.06118> paver:[FindFirstFit] Partition seen with start 16777250, end 16810017 (length 32768) [796.786] 04860.06118> paver:[FindFirstFit] Sorting [796.786] 04860.06118> paver:[FindFirstFit] Partition[0] From Block [0, 34) ... (next partition starts at block 34) [796.786] 04860.06118> paver:[FindFirstFit] There are 0 free blocks (49152 requested) [796.786] 04860.06118> paver:[FindFirstFit] Partition[1] From Block [34, 16777250) ... (next partition starts at block 16777250) [796.786] 04860.06118> paver:[FindFirstFit] There are 0 free blocks (49152 requested) [796.786] 04860.06118> paver:[FindFirstFit] Partition[2] From Block [16777250, 16810018) ... (next partition starts at block 250069646) [796.786] 04860.06118> paver:[FindFirstFit] There are 233259628 free blocks (49152 requested) [796.786] 04860.06118> paver:[AddPartition] Found space in GPT - OK 233259628 @ 16810018 [796.786] 04860.06118> paver:[AddPartition] Final space in GPT - OK 49152 @ 16810018 [796.787] 04860.06118> paver:[AddPartition] Added partition, waiting for bind [796.787] 03323.03373> block: Joining un-closed FIFO server [796.787] 01104.01117> devcoord: dc_bind_device() '' [796.788] 01182.01202> devmgr: /dev/class/block/003: GPT? [796.788] 01104.01117> devcoord: dc_bind_device() '/boot/driver/gpt.so' [796.788] 03323.03373> gpt: device_get_metadata failed (-25) [796.789] 01182.01202> devmgr: /dev/class/block/012: FVM? [796.789] 01104.01117> devcoord: dc_bind_device() '/boot/driver/fvm.so' [796.790] 04860.06118> paver:[AddPartition] Added partition, waiting for bind - OK 2019/04/20 00:27:04 done 2019/04/20 00:27:04 attempting to send <<image>>authorized_keys... 2019/04/20 00:27:04 target is busy, retrying in one second [796.913] 04860.04874> netsvc: tftp write of file <<image>>zirconr.img completed [796.913] 04860.04874> netsvc: metrics: {"inorderblks": 12589,"oooblks": 0,"ack": 50,"nack": 0,"timeouts": 0,"sas": 0,"inorderbytes": 12890296} [796.938] 04860.06118> paver:[PartitionPave] Completed successfully 2019/04/20 00:27:05 attempting to send <<image>>authorized_keys... 2019/04/20 00:27:05 done 2019/04/20 00:27:05 attempting to send <<netboot>>kernel.bin... 2019/04/20 00:27:05 target is busy, retrying in one second [797.914] 04860.04874> netsvc: Installing SSH authorized_keys [797.914] 04860.04874> netsvc: tftp write of file <<image>>authorized_keys completed [797.914] 04860.04874> netsvc: metrics: {"inorderblks": 1,"oooblks": 0,"ack": 1,"nack": 0,"timeouts": 0,"sas": 0,"inorderbytes": 806} [797.916] 04860.06408> paver:[Initialize] Successfully initialized EFI Device Partitioner [797.917] 01104.01117> devcoord: dc_bind_device() '/boot/driver/zxcrypt.so' [797.917] 03323.03373> devhost_get_handles(0x684ed50fb9c0:block) open path='zxcrypt', r=-2 [797.944] 04860.06408> paver:[DataFilePave] Wrote ssh/authorized_keys 2019/04/20 00:27:06 attempting to send <<netboot>>kernel.bin... 2019/04/20 00:27:06 done [0.000] 00000.00000> zbi: @ 0xffffff8005d9d000 (12706992 bytes) [0.000] 00000.00000> UART: FIFO depth 16 [0.000] 00000.00000> PMM: boot reserve add [0x100000, 0x2fffff] [0.000] 00000.00000> PMM: boot reserve add [0x5d9d000, 0x69bbfff] [0.000] 00000.00000> PMM: arena too small to be useful (size 4096) [0.000] 00000.00000> PMM: pmm_add_arena failed to initialize arena [0.000] 00000.00000> MEM: Failed to add pmm range at 0x8afff000 size 0x1000 [0.000] 00000.00000> PMM: boot reserve marking WIRED [0x100000, 0x2fffff] [0.000] 00000.00000> PMM: boot reserve marking WIRED [0x5d9d000, 0x69bbfff] [0.000] 00000.00000> welcome to Zircon [0.000] 00000.00000> KASLR: .text section at 0xffffffff00100000 [0.000] 00000.00000> INIT: cpu 0, calling hook 0xffffffff00114ec4 (global_prng_seed) at level 0x30000, flags 0x1 [0.000] 00000.00000> initializing vm pre-heap [0.000] 00000.00000> VM: marking boot alloc used range [0x69bc000, 0x69bc100) [0.000] 00000.00000> INIT: cpu 0, calling hook 0xffffffff00122274 (elf_build_id) at level 0x4fffe, flags 0x1 [0.000] 00000.00000> INIT: cpu 0, calling hook 0xffffffff00122400 (version) at level 0x4ffff, flags 0x1 [0.000] 00000.00000> version: [0.000] 00000.00000> arch: x86 [0.000] 00000.00000> platform: XXX [0.000] 00000.00000> target: XXX [0.000] 00000.00000> project: x64 [0.000] 00000.00000> buildid: git-94e2c4380a7d2d27cbed602ea615e94237be4004-dirty [0.000] 00000.00000> ELF build ID: 2cbba575d5db32065a4e99bcd19ee2534429d77f [0.000] 00000.00000> initializing heap [0.000] 00000.00000> INIT: cpu 0, calling hook 0xffffffff00101fc4 (console) at level 0x50000, flags 0x1 [0.000] 00000.00000> INIT: cpu 0, calling hook 0xffffffff001826c4 (x86_resource_init) at level 0x50000, flags 0x1 [0.000] 00000.00000> initializing vm [0.000] 00000.00000> VM: reserving kernel region [0xffffffff00100000, 0xffffffff0021b000) flags 0x28 name 'kernel_code' [0.000] 00000.00000> VM: reserving kernel region [0xffffffff0021b000, 0xffffffff0026c000) flags 0x8 name 'kernel_rodata' [0.000] 00000.00000> VM: reserving kernel region [0xffffffff0026c000, 0xffffffff00274000) flags 0x18 name 'kernel_data' [0.000] 00000.00000> VM: reserving kernel region [0xffffffff00274000, 0xffffffff00300000) flags 0x18 name 'kernel_bss' [0.000] 00000.00000> INIT: cpu 0, calling hook 0xffffffff00183388 (display_memtype) at level 0x60001, flags 0x1 [0.000] 00000.00000> INIT: cpu 0, calling hook 0xffffffff00186818 (acpi_tables) at level 0x60001, flags 0x1 [0.000] 00000.00000> INIT: cpu 0, calling hook 0xffffffff001814c8 (hpet) at level 0x60002, flags 0x1 [0.000] 00000.00000> INIT: cpu 0, calling hook 0xffffffff00181888 (apic) at level 0x60002, flags 0x1 [0.000] 00000.00000> x2APIC enabled [0.000] 00000.00000> INIT: cpu 0, calling hook 0xffffffff001a7e6c (system_topology_init) at level 0x60002, flags 0x1 [0.000] 00000.00000> WARNING: more than 1000 levels of cache, couldn't find highest. [0.000] 00000.00000> WARNING: unable to find any cache levels. [0.000] 00000.00000> Could not find SRAT table. ACPICA returned: 5 [0.000] 00000.00000> INIT: cpu 0, calling hook 0xffffffff00185e08 (timer) at level 0x60003, flags 0x1 [0.000] 00000.00000> HPET frequency: 23999 ticks/ms [0.000] 00000.00000> TSC frequency: 2712000 ticks/ms [799.313] 00000.00000> timer features: constant_tsc 1 invariant_tsc 1 tsc_deadline 1 [799.313] 00000.00000> Using TSC as wallclock [799.313] 00000.00000> INIT: cpu 0, calling hook 0xffffffff00208930 (percpu_heap_init) at level 0x60003, flags 0x1 [799.313] 00000.00000> initializing kernel [799.313] 00000.00000> initializing mp [799.313] 00000.00000> INIT: cpu 0, calling hook 0xffffffff00115118 (global_prng_thread_safe) at level 0x7ffff, flags 0x1 [799.313] 00000.00000> creating bootstrap completion thread [799.313] 00000.00000> top of bootstrap2() [799.313] 00000.00000> INIT: cpu 0, calling hook 0xffffffff00131734 (libobject) at level 0x80000, flags 0x1 [799.313] 00000.00000> OOM: started thread [799.313] 00000.00000> INIT: cpu 0, calling hook 0xffffffff0020589c (dpc) at level 0x80000, flags 0x1 [799.313] 00000.00000> Processor Model Info: type 0 family 0x6 model 0xe stepping 0x9 [799.313] 00000.00000> display_family 0x6 display_model 0x8e [799.313] 00000.00000> Vendor: Intel [799.313] 00000.00000> Microarch: Kaby Lake [799.313] 00000.00000> F/M/S: 6/8e/9 [799.313] 00000.00000> patch_level: 8e [799.313] 00000.00000> Brand: Intel(R) Core(TM) i5-7300U CPU @ 2.60GHz [799.313] 00000.00000> Features: fpu sse sse2 sse3 ssse3 sse4.1 sse4.2 mmx avx avx2 fxsr pcid xsave mon aesni clflush [799.313] 00000.00000> clflushopt fsgsbase tsc_adj smep smap erms rdrand rdseed syscall nx huge rdtscp [799.313] 00000.00000> invar_tsc tsc_deadline x2apic vmx pt hwp [799.313] 00000.00000> Properties: meltdown l1tf pcid_good [799.313] 00000.00000> initializing platform [799.313] 00000.00000> INIT: cpu 0, calling hook 0xffffffff001a157c (x86_perfmon) at level 0x90000, flags 0x1 [799.313] 00000.00000> PMU: version 4 [799.313] 00000.00000> UART: started IRQ driven RX [799.313] 00000.00000> UART: started IRQ driven TX [799.313] 00000.00000> cpu topology: [799.313] 00000.00000> 0: apic id 0x0 BSP [799.313] 00000.00000> 1: apic id 0x1 [799.313] 00000.00000> 2: apic id 0x2 [799.313] 00000.00000> 3: apic id 0x3 [799.313] 00000.00000> Found 4 cpus [799.313] 00000.00000> booting apic ids: 0x1 0x2 0x3 [799.328] 00000.00000> entering scheduler on cpu 1 [799.329] 00000.00000> entering scheduler on cpu 3 [799.329] 00000.00000> entering scheduler on cpu 2 [799.332] 00000.00000> smbios: manufacturer="Intel Corporation" product="NUC7i5DNHE" [799.332] 00000.00000> initializing target [799.332] 00000.00000> INIT: cpu 0, calling hook 0xffffffff001850b8 (x86_pcie_init) at level 0xa0000, flags 0x1 [799.332] 00000.00000> moving to last init level [799.332] 00000.00000> INIT: cpu 0, calling hook 0xffffffff001214cc (debuglog) at level 0xb0000, flags 0x1 [799.332] 00000.00000> INIT: cpu 0, calling hook 0xffffffff00174d40 (kcounters) at level 0xb0000, flags 0x1 [799.332] 00000.00000> INIT: cpu 0, calling hook 0xffffffff00102aec (kernel_shell) at level 0xc0000, flags 0x1 [799.332] 00000.00000> INIT: cpu 0, calling hook 0xffffffff00202ad4 (ktrace) at level 0xc0000, flags 0x1 [799.335] 00000.00000> ktrace: buffer at 0xffffff948438a000 (33554432 bytes) [799.335] 00000.00000> INIT: cpu 0, calling hook 0xffffffff002184f8 (userboot) at level 0xc0000, flags 0x1 [799.335] 00000.00000> userboot: ramdisk 0xc1f000 @ 0xffffff8005d9d000 [799.335] 00000.00000> userboot: userboot rodata 0 @ [0xb277498b000,0xb277498e000) [799.335] 00000.00000> userboot: userboot code 0x3000 @ [0xb277498e000,0xb2774999000) [799.335] 00000.00000> userboot: vdso/full rodata 0 @ [0xb2774999000,0xb27749a0000) [799.335] 00000.00000> userboot: vdso/full code 0x7000 @ [0xb27749a0000,0xb27749a1000) [799.336] 00000.00000> userboot: entry point @ 0xb277498ec90 [799.336] 01036.01043> userboot: option "zircon.autorun.system=/boot/bin/sh+/boot/infra/runcmds" [799.366] 01036.01043> userboot: searching bootfs for 'bin/bootsvc' [799.366] 01036.01043> userboot: 'bin/bootsvc' has PT_INTERP "lib/ld.so.1" [799.366] 01036.01043> userboot: searching bootfs for 'lib/ld.so.1' [799.366] 01036.01043> userboot: userboot: loaded lib/ld.so.1 at 0x4c806eeb5000, entry point 0x4c806eed33d0 [799.366] 01036.01043> userboot: userboot: loaded vDSO at 0x62935f2aa000, entry point 0x62935f2b18fa [799.366] 01036.01043> userboot: process bin/bootsvc started. [799.366] 01036.01043> userboot: waiting for loader-service requests... [799.366] 01036.01043> userboot: searching bootfs for 'lib/libasync-default.so' [799.366] 01036.01043> userboot: searching bootfs for 'lib/libfdio.so' [799.366] 01036.01043> userboot: searching bootfs for 'lib/libtrace-engine.so' [799.366] 01036.01043> userboot: searching bootfs for 'lib/liblaunchpad.so' [799.366] 01050.01053> dso: id=367d3374904876b8f143f2ed5e4dfb0248fef748 base=0x000068f57c582000 name=<application> [799.366] 01050.01053> dso: id=71712e0a455898a51e34d40a4013786ab1fa5335 base=0x000062935f2aa000 name=<vDSO> [799.366] 01050.01053> dso: id=8c511b4202cf569c8fdde14ca97222102ba3a9e0 base=0x0000530ee7e2e000 name=libasync-default.so [799.366] 01050.01053> dso: id=3efa72b2e3bd2e4271f835d34a81d9719d6e08a7 base=0x000053713347a000 name=libfdio.so [799.366] 01050.01053> dso: id=95bc229c3cf2ab8a51f12c33a311105ff8976120 base=0x00004694a69fe000 name=libtrace-engine.so [799.366] 01050.01053> dso: id=5b0854856213eae6bab93c982f39551f8f9591c5 base=0x000019923dac4000 name=liblaunchpad.so [799.366] 01050.01053> dso: id=5d417db61b3a48a58a8fa1ffbfc2e71b830e0857 base=0x00004c806eeb5000 name=libc.so [799.366] 01050.01053> bootsvc: Starting... [799.366] 01036.01043> userboot: loader-service channel peer closed [799.366] 01036.01043> userboot: finished! [799.366] 01050.01053> bootsvc: Creating bootfs service... [799.367] 01050.01053> bootsvc: Retrieving boot image... [799.367] 01050.01053> bootsvc: Decommitted BOOTDATA VMO from 0 to 0xc1e000 [799.367] 01050.01053> bootsvc: Loading boot arguments... [799.367] 01050.01053> bootsvc: Creating svcfs service... [799.367] 01050.01053> bootsvc: Loading kernel VMOs... [799.367] 01050.01053> bootsvc: Creating loader service... [799.367] 01050.01053> bootsvc: Launching next process... [799.367] 01050.01108> bootsvc: Launched bin/devcoordinator [799.368] 01115.01130> devcoordinator: launch /boot/bin/svchost (svchost) OK [799.369] 01115.01130> devcoordinator: launch /boot/bin/fshost (fshost) OK [799.371] 01115.01321> devcoordinator: launch /boot/bin/pwrbtn-monitor (pwrbtn-monitor) OK [799.371] 01115.01344> devcoordinator: launch /boot/bin/netsvc (netsvc) OK [799.372] 01115.01344> devcoordinator: launch /boot/bin/virtual-console (virtual-console) OK [799.376] 01115.01130> devcoordinator: full system required, ignoring fallback drivers until /system is loaded [799.376] 01115.01130> devcoordinator: launch devhost 'devhost:sys': pid=2187 [799.376] 01115.01130> devcoordinator: launch devhost 'devhost:test': pid=2219 [799.377] 01115.01130> devcoordinator: launch devhost 'devhost:root': pid=2279 [799.378] 01115.01130> devcoordinator: launch devhost 'devhost:misc': pid=2330 [799.378] 02187.02201> devhost: trace provider registry begun [799.378] 02219.02241> devhost: trace provider registry begun [799.379] 02279.02309> devhost: trace provider registry begun [799.380] 02330.02380> devhost: trace provider registry begun [799.380] 01115.01333> devcoordinator: launch /boot/bin/sh (sh:console) OK [799.465] 02187.02201> acpi-bus: not using IOMMU [799.473] 02187.02201> PMU: 7 arch events [799.473] 02187.02201> PMU: arch event id range: 1-7 [799.473] 02187.02201> PMU: 102 arch events [799.473] 02187.02201> PMU: arch event id range: 1-241 [799.473] 02187.02201> Intel Processor Trace configuration for this chipset: [799.473] 02187.02201> mtc_freq_mask: 0x249 [799.473] 02187.02201> cyc_thresh_mask: 0x3fff [799.473] 02187.02201> psb_freq_mask: 0x3f [799.473] 02187.02201> num addr ranges: 2 [799.473] 02187.02201> [sysmem_init 28] async_get_default_dispatcher(): 0x35ac07588b50 [799.473] 02187.02201> [sysmem_bind 40] sysmem_bind() [799.473] 02187.02879> acpi-pwrbtn: initialized [799.473] 01727.01762> vc: new input device /dev/class/input/000 [799.504] 02187.02879> acpi: published device pci(0x35ab475eea50), parent=sys(0x35ac87585d10), handle=0x35ab0759ba50 [799.505] 01115.01130> devcoordinator: launch devhost 'devhost:pci#1:8086:5916': pid=2975 [799.505] 01115.01130> devcoordinator: launch devhost 'devhost:pci#3:8086:9d2f': pid=3023 [799.507] 02187.02879> acpi: published device rtc(0x35ab475a9690), parent=acpi(0x35ac87584510), handle=0x35ab075c1b50 [799.508] 01115.01130> devcoordinator: launch devhost 'devhost:pci#5:8086:9d60': pid=3123 [799.508] 02975.02989> devhost: trace provider registry begun [799.508] 01115.01130> devcoordinator: launch devhost 'devhost:pci#6:8086:9d61': pid=3200 [799.509] 02187.02879> acpi-ec: initialized [799.509] 03123.03137> devhost: trace provider registry begun [799.510] 03023.03045> devhost: trace provider registry begun [799.510] 01115.01130> devcoordinator: launch devhost 'devhost:pci#9:8086:9d03': pid=3342 [799.511] 03200.03233> devhost: trace provider registry begun [799.511] 01115.01130> devcoordinator: launch devhost 'devhost:pci#14:8086:9d71': pid=3521 [799.511] 03342.03393> devhost: trace provider registry begun [799.513] 02187.02879> acpi: failed to create NHLT VMO (res -10) [799.513] 02187.02879> acpi: failed to publish NHLT metadata [799.515] 01115.01130> devcoordinator: launch devhost 'devhost:pci#16:8086:156f': pid=3617 [799.516] 03521.03535> devhost: trace provider registry begun [799.516] 03342.03393> ahci: using MSI interrupt [799.518] 03123.03137> initialized intel serialio i2c driver, reg=0x49fa72537000 regsize=4096 [799.518] 03617.03643> devhost: trace provider registry begun [799.519] 03200.03233> initialized intel serialio i2c driver, reg=0x4695a518000 regsize=4096 [799.523] 03521.03535> [IHDA DSP 00:1f.3] Failed to fetch NHLT (res -25) [799.523] 03521.03535> [IHDA Controller 00:1f.3] Failed to initialize DSP device (res = -25) [799.526] 03023.03913> * found USB device (0x18d1:0xa002, USB 2.0) config 1 [799.526] 03023.03913> * found USB device (0x18d1:0xa003, USB 3.0) config 1 [799.596] 01626.01650> netifc: ? /dev/class/ethernet/000 [799.596] 01626.01650> netifc: create 512 eth buffers [799.596] 01626.01650> macaddr: 54:b2:03:13:b3:e7 [799.596] 01626.01650> ip6addr: fe80::56b2:34d:fe13:b3e7 [799.596] 01626.01650> snmaddr: ff02::1:ff13:b3e7 [799.596] 01626.01650> netsvc: using /dev/class/ethernet/000 [799.596] 01626.01650> netsvc: nodename='rash-moan-copy-slob' [799.596] 01626.01650> netsvc: start [799.621] 01727.01762> vc: new display device /dev/class/display-controller/000 [799.662] 02975.04243> i915: MST not supported [800.164] 02975.04243> i915: MST not supported [800.238] 03023.03913> * found USB device (0x0781:0x5583, USB 3.0) config 1 [800.989] 03023.03913> * found USB device (0x0cf3:0xe300, USB 2.1) config 1 [801.209] 02975.04243> i915: No displays detected [801.523] 03200.03233> intel-i2c-controller: intel_serialio_i2c_slave_transfer: -21 [801.523] 03200.03233> i2c-hid: could not read HID descriptor: 0 [801.523] 03200.03233> devhost[00:15.1/i2c-bus-9d61/004c] bind driver '/boot/driver/i2c-hid.so' failed: -2 [801.523] 01115.01130> devcoordinator: rpc: bind-driver '004c' status -2 [801.523] 03123.03137> intel-i2c-controller: intel_serialio_i2c_slave_transfer: -21 [801.523] 03123.03137> i2c-hid: could not read HID descriptor: 0 [801.523] 03123.03137> devhost[00:15.0/i2c-bus-9d60/0020] bind driver '/boot/driver/i2c-hid.so' failed: -2 [801.523] 01115.01130> devcoordinator: rpc: bind-driver '0020' status -2 [801.534] 03342.03864> sata2: dev info [801.534] 03342.03864> serial=AA000000000000008069 [801.534] 03342.03864> firmware rev=0R08A1 0 [801.534] 03342.03864> model id=ETMAT 8MSP1582 G [801.534] 03342.03864> major=0x3f0 ACS2 DMA 32 commands [801.534] 03342.03864> LBA48 250069680 sectors, sector size=512 [801.535] 01299.01313> fshost: /dev/class/block/000: GPT? [801.535] 03342.03393> gpt: device_get_metadata failed (-25) [801.536] 01299.01313> fshost: /dev/class/block/001: FVM? [801.539] 01299.01313> devcoordinator: launch /boot/bin/blobfs (blobfs:/blob) OK [801.675] 01299.01313> fshost: starting 'bin/pkgsvr' 'ce51c3716b4313902d765fffc9c56a0599fde751c72b3aeb298f1adaa69b15fe'... [801.681] 01299.01313> devcoordinator: launch bin/pkgsvr (pkgfs) OK [801.692] 04634.04838> pkgsvr: system: will be served from ce51c3716b4313902d765fffc9c56a0599fde751c72b3aeb298f1adaa69b15fe [801.692] 04634.04838> pkgsvr: pkgfs serving index /data/pkgfs_index from blobfs /blob [801.692] 01299.01313> fshost: /dev/class/block/005: zxcrypt? [801.692] 03342.03393> devhost_get_handles(0x79044f910510:block) open path='zxcrypt', r=-2 [801.695] 01299.01313> fshost: mounting minfs [801.695] 01299.01313> devcoordinator: launch /boot/bin/minfs (minfs:/data) OK [801.726] 01115.04888> devcoordinator: adding system driver 'rtl88xx' '/system/driver/rtl88xx.so' [801.726] 01115.01786> devcoordinator: launch /system/bin/appmgr (appmgr) OK [801.726] 01115.01786> autorun: starting '/boot/bin/sh' '/boot/infra/runcmds'... [801.726] 01115.01786> devcoordinator: launch /boot/bin/sh (autorun:system) OK [801.734] 01115.04888> devcoordinator: adding system driver 'virtual_audio' '/system/driver/virtual_audio_driver.so' [801.743] 01115.04888> devcoordinator: adding system driver 'wlan' '/system/driver/wlanif.so' [801.755] 01115.04888> devcoordinator: adding system driver 'qmi_fake' '/system/driver/qmi-fake.so' [801.771] 01115.04888> devcoordinator: adding system driver 'virtual_camera' '/system/driver/virtual_camera_driver.so' [801.783] 01115.04888> devcoordinator: adding system driver 'wlan' '/system/driver/wlanphy.so' [801.788] 01115.04888> devcoordinator: adding system driver 'ath10k_pci' '/system/driver/ath10k.so' [801.795] 01115.04888> devcoordinator: adding system driver 'brcmfmac' '/system/driver/brcmfmac.so' [801.805] 01115.04888> devcoordinator: adding system driver 'gpu' '/system/driver/libmsd_intel.so' [801.815] 01115.04888> devcoordinator: adding system driver 'qmi_usb' '/system/driver/qmi-transport.so' [801.870] 01115.04888> devcoordinator: adding system driver 'wlan' '/system/driver/wlan.so' [801.872] 01115.04888> devcoordinator: adding system driver 'bt_hci_passthrough' '/system/driver/bt-hci-passthrough.so' [801.881] 01115.04888> devcoordinator: adding system driver 'magma_pdev_gpu' '/system/driver/libmsd_arm.so' [801.883] 01115.04888> devcoordinator: adding system driver 'bt_hog' '/system/driver/bt-hog.so' [801.894] 01115.04888> devcoordinator: adding system driver 'usb_video' '/system/driver/usb_video.so' [801.922] 01115.04888> devcoordinator: adding system driver 'bt_host' '/system/driver/bt-host.so' [801.939] 01115.04888> devcoordinator: adding system driver 'mt8167s_gpu' '/system/driver/libmsd_img_rgx_mtk.so' [801.951] 05183.05203> [INFO:namespace_builder.cc(93)] config-data for sysmgr [802.007] 01115.04888> devcoordinator: adding system driver 'ralink' '/system/driver/ralink.so' [802.031] 01115.04888> devcoordinator: adding system driver 'bt_hci_intel' '/system/driver/bt-hci-intel.so' [802.034] 01115.04888> devcoordinator: adding system driver 'iwlwifi_pci' '/system/driver/iwlwifi.so' [802.058] 01115.04888> devcoordinator: adding system driver 'bt_hci_atheros' '/system/driver/bt-hci-atheros.so' [802.070] 01115.04888> devcoordinator: adding system driver 'bt_hci_fake' '/system/driver/bt-hci-fake.so' [802.071] 01115.01130> devcoordinator: driver 'bt_hci_fake' added [802.071] 01115.01130> devcoordinator: driver 'bt_hci_atheros' added [802.071] 01115.01130> devcoordinator: driver 'iwlwifi_pci' added [802.071] 01115.01130> devcoordinator: driver 'bt_hci_intel' added [802.071] 01115.01130> devcoordinator: driver 'ralink' added [802.071] 01115.01130> devcoordinator: driver 'mt8167s_gpu' added [802.071] 01115.01130> devcoordinator: driver 'bt_host' added [802.071] 01115.01130> devcoordinator: driver 'usb_video' added [802.071] 01115.01130> devcoordinator: driver 'bt_hog' added [802.071] 01115.01130> devcoordinator: driver 'magma_pdev_gpu' added [802.071] 01115.01130> devcoordinator: driver 'wlan' added [802.071] 01115.01130> devcoordinator: driver 'qmi_usb' added [802.071] 01115.01130> devcoordinator: driver 'gpu' added [802.071] 01115.01130> devcoordinator: driver 'brcmfmac' added [802.071] 01115.01130> devcoordinator: driver 'ath10k_pci' added [802.072] 01115.01130> devcoordinator: launch devhost 'devhost:pci#11:168c:003e': pid=5938 [802.072] 01115.01130> devcoordinator: driver 'wlan' added [802.072] 01115.01130> devcoordinator: driver 'qmi_fake' added [802.072] 01115.01130> devcoordinator: driver 'wlan' added [802.072] 01115.01130> devcoordinator: driver 'rtl88xx' added [802.072] 01115.01130> devcoordinator: driver 'bt_hci_passthrough' added [802.072] 01115.01130> devcoordinator: fallback driver 'usb_composite' is available [802.072] 01115.01130> devcoordinator: driver 'usb_composite' added [802.072] 01115.01130> devcoordinator: fallback driver 'intel_disp' is available [802.072] 01115.01130> devcoordinator: driver 'intel_disp' added [802.073] 05938.05952> devhost: trace provider registry begun [802.073] 05938.05952> ath10k: Probed chip QCA6174 ver: 2.1 [802.076] 03023.03045> UMS: parent: 'ifc-000' [802.076] 03023.03045> UMS:Max lun is: 0 [802.076] 03023.03045> devhost[00:14.0/xhci/usb-bus/002/002/ifc-001] bind driver '/boot/driver/bt-transport-usb.so' failed: -2 [802.076] 01115.01130> devcoordinator: rpc: bind-driver 'ifc-001' status -2 [802.078] 03023.06497> UMS: block size is: 0x00000200 [802.078] 03023.06497> UMS: total blocks is: 30031872 [802.078] 03023.06497> UMS: total size is: 15376318464 [802.078] 03023.06497> UMS: read-only: 0 removable: 1 [802.104] 03023.09189> btatheros: Making visible [802.106] 03023.09189> btatheros: loaded successfully [802.107] 03023.09420> [INFO:command_channel.cc(149)] hci: initialized [802.110] 01299.01313> fshost: /dev/class/block/007: MBR? [802.114] 01299.01313> fshost: /dev/class/block/009: MBR? [802.142] 05183.05203> [INFO:namespace_builder.cc(93)] config-data for amber [802.175] 03023.09420> [WARN:adapter.cc(274)] gap: controller is using legacy HCI version 4.1 [802.187] 03023.09420> [INFO:acl_data_channel.cc(91)] hci: initialized [802.223] 05183.05203> [INFO:namespace_builder.cc(93)] config-data for pkg_resolver [802.339] 13655.13667> [INFO:cobalt_main.cc(219)] Cobalt is starting with the following parameters: schedule_interval=3600 seconds, min_interval=10 seconds, initial_interval=60 seconds, max_bytes_per_observation_store=1048576, event_aggregator_bac [802.339] 13655.13667> kfill_days=2, start_event_aggregator_worker=1. [802.394] 05183.05203> [INFO:namespace_builder.cc(93)] config-data for mdns [802.426] 05183.05203> [INFO:namespace_builder.cc(93)] config-data for wlancfg [802.450] 05938.13578> devhost: rpc:load-firmware failed: -25 [802.450] 05938.13578> devhost: rpc:load-firmware failed: -25 [802.691] 05183.05203> [INFO:namespace_builder.cc(93)] config-data for crashpad_agent [802.718] 16631.16645> [INFO:main.cc(35)] Trace Manager starting with config: /pkg/data/tracing.config [802.743] 15784.15796> [INFO:system_metrics_main.cc(23)] Cobalt SystemMetricsDaemon: System metrics daemon created. [802.815] 17066.17078> wlanstack2 [I]: Starting [803.150] 05938.13178> ath10k: Unknown eventid: 0x1d019 [803.153] 05938.13178> ath10k: Unknown eventid: 0x16006 [803.158] 05938.05952> wlanphy: event loop started [803.158] 05938.05952> wlanphy_bind [803.158] 17066.17078> wlanstack2::device [I]: new phy #0: /dev/sys/pci/01:00.0/ath10k-wlanphy/wlanphy [803.158] 14447.14459> wlancfg got event: OnPhyAdded { phy_id: 0 } [803.158] 14447.14459> wlancfg: phy 0 added [803.158] 17066.17078> wlanstack2::service [I]: query_phy(id = 0) [803.159] 17066.17078> wlanstack2::service [I]: query_phy(id = 0): received a 'QueryResult' from device [803.159] 14447.14459> wlancfg: received a PhyInfo from phy #0: path is /dev/sys/pci/01:00.0/ath10k-wlanphy/wlanphy [803.159] 14447.14459> using default wlan config entry for phy [803.159] 14447.14459> wlancfg: Creating Client iface for phy 0 [803.165] 05938.05952> wlan_bind [803.167] 05938.05952> ath10k: adding a station interface (vdev_id=0) ... [803.168] 05938.05952> wlan: [I] Initialize a client MLME. [803.169] 05938.18028> wlan: [I] starting MainLoop [803.169] 05938.05952> wlan: [I] channel opened [803.170] 17066.17078> wlanstack2::device [I]: new iface #0 with role 'Client': /dev/sys/pci/01:00.0/ath10k-wlanphy/ath10k-wlanmac/wlan [803.171] 14447.14459> wlancfg got event: OnIfaceAdded { iface_id: 0 } [803.171] 14447.14459> wlancfg: new iface 0 added successfully [803.171] 14447.14459> wlancfg: Starting auto-connect loop with 0 saved networks [803.749] 14221.14233> Starting mDNS on interface ethp001f6 [80fe::b256:ff03:13fe:e7b3] [803.750] 14221.14233> [WARNING:garnet/bin/mdns/service/mdns_interface_transceiver_v6.cc(29)] NET-291 IPV6_MULTICAST_LOOP not supported (ENOPROTOOPT), continuing anyway [803.750] 14221.14233> [WARNING:garnet/bin/mdns/service/mdns_interface_transceiver_v6.cc(50)] NET-2180 IPV6_JOIN_GROUP returned ENODEV, mDNS will not communicate via IPV6 [807.330] 14221.14233> Starting mDNS on interface ethp001f6 192.168.42.103 [807.330] 14221.14233> [WARNING:garnet/bin/mdns/service/mdns_interface_transceiver_v4.cc(68)] NET-2177 IP_TTL not supported (ENOPROTOOPT), continuing anyway. May cause spurious IP traffic [807.330] 14221.14233> Starting mDNS on interface ethp001f6 [80fe::b256:ff03:13fe:e7b3] [807.330] 14221.14233> [WARNING:garnet/bin/mdns/service/mdns_interface_transceiver_v6.cc(29)] NET-291 IPV6_MULTICAST_LOOP not supported (ENOPROTOOPT), continuing anyway [807.330] 14221.14233> [WARNING:garnet/bin/mdns/service/mdns_interface_transceiver_v6.cc(50)] NET-2180 IPV6_JOIN_GROUP returned ENODEV, mDNS will not communicate via IPV6 [807.330] 14221.14233> mDNS: Verifying uniqueness of host name rash-moan-copy-slob.local. [808.311] 14221.14233> mDNS: Using unique host name rash-moan-copy-slob.local. Running tests sequentially. [tb] 2019-04-20 00:28:02.123 INFO [AndroidDevice|896X05XLX] The primary device under test is "896X05XLX". [android_device.py:create:92] [tb] 2019-04-20 00:28:04.279 INFO [AndroidDevice|896X05XLX] Screen is not awake, wake it up [android_device.py:wakeup_screen:1374] [tb] 2019-04-20 00:28:05.357 INFO Controller AndroidDevice: [{'serial': '896X05XLX', 'build_id': '5289084', 'build_type': 'userdebug', 'model': 'blueline', 'incremental_build_id': '5289084'}] [base_test.py:register_controller:396] [tb] 2019-04-20 00:28:05.366 INFO [SshConnection | 192.168.42.103] Starting master ssh connection. [connection.py:setup_master_ssh:141] [857.959] 23306.23318> setsockopt IP_TOS 32: Protocol not available: [tb] 2019-04-20 00:28:05.589 INFO [SshConnection | 192.168.42.103] Starting master ssh connection. [connection.py:setup_master_ssh:141] [858.164] 23882.23897> setsockopt IP_TOS 32: Protocol not available: [tb] 2019-04-20 00:28:06.820 INFO [SshConnection | 192.168.42.103] Starting master ssh connection. [connection.py:setup_master_ssh:141] [859.395] 24935.24950> setsockopt IP_TOS 32: Protocol not available: [tb] 2019-04-20 00:28:07.047 INFO Controller FuchsiaDevice: [{'ip': '192.168.42.103'}] [base_test.py:register_controller:396] [tb] 2019-04-20 00:28:07.877 INFO ==========> Sl4fSanityTest <========== [base_test.py:run:967] [tb] 2019-04-20 00:28:07.879 INFO Congratulations! Fuchsia controllers have been initialized successfully! [Sl4fSanityTest.py:setup_class:41] [tb] 2019-04-20 00:28:07.888 INFO [Test Case] test_example [base_test.py:exec_one_testcase:662] [tb] 2019-04-20 00:28:07.889 INFO Congratulations! You've run your first test. [Sl4fSanityTest.py:test_example:46] [tb] 2019-04-20 00:28:07.892 INFO [Test Case] test_example PASS [base_test.py:_on_pass:542] [tb] 2019-04-20 00:28:08.534 INFO Summary for test class Sl4fSanityTest: ControllerInfo {'AndroidDevice': [{'serial': '896X05XLX', 'build_id': '5289084', 'build_type': 'userdebug', 'model': 'blueline', 'incremental_build_id': '5289084'}], 'FuchsiaDevice': [{'ip': '192.168.42.103'}]}, Requested 1, Executed 1, Passed 1, Failed 0, Skipped 0, Blocked 0, Unknown 0, Errors 0 [base_test.py:run:1027] [tb] 2019-04-20 00:28:08.568 INFO [AndroidDevice|896X05XLX] The primary device under test is "896X05XLX". [android_device.py:create:92] [tb] 2019-04-20 00:28:11.415 INFO Controller AndroidDevice: [{'serial': '896X05XLX', 'build_id': '5289084', 'build_type': 'userdebug', 'model': 'blueline', 'incremental_build_id': '5289084'}] [base_test.py:register_controller:396] [tb] 2019-04-20 00:28:11.422 INFO [SshConnection | 192.168.42.103] Starting master ssh connection. [connection.py:setup_master_ssh:141] [864.011] 25628.25643> setsockopt IP_TOS 32: Protocol not available: [tb] 2019-04-20 00:28:11.649 INFO [SshConnection | 192.168.42.103] Starting master ssh connection. [connection.py:setup_master_ssh:141] [864.225] 26220.26235> setsockopt IP_TOS 32: Protocol not available: [tb] 2019-04-20 00:28:12.874 INFO [SshConnection | 192.168.42.103] Starting master ssh connection. [connection.py:setup_master_ssh:141] [865.452] 27288.27304> setsockopt IP_TOS 32: Protocol not available: [tb] 2019-04-20 00:28:13.110 INFO Controller FuchsiaDevice: [{'ip': '192.168.42.103'}] [base_test.py:register_controller:396] [tb] 2019-04-20 00:28:14.041 INFO There are: 1 fuchsia and 1 android devices. [BleFuchsiaAndroidTest.py:__init__:48] [tb] 2019-04-20 00:28:14.042 INFO ==========> BleFuchsiaAndroidTest <========== [base_test.py:run:967] [tb] 2019-04-20 00:28:14.043 INFO Setting up Android Devices [tb] 2019-04-20 00:28:14.089 INFO [AndroidDevice|896X05XLX] Reset state of bluetooth on device. [bt_test_utils.py:factory_reset_bluetooth:529] [tb] 2019-04-20 00:28:19.771 INFO State normalized {12} [tb] 2019-04-20 00:28:20.710 INFO [AndroidDevice|896X05XLX] Android Phone device found. [bt_test_utils.py:get_device_selector_dictionary:694] [tb] 2019-04-20 00:28:20.716 INFO [Test Case] test_fuchsia_adv_android_scan [base_test.py:exec_one_testcase:662] [tb] 2019-04-20 00:28:20.742 INFO [Test ID] BleFuchsiaAndroidTest:test_fuchsia_adv_android_scan:1555720100.7421122 [BluetoothBaseTest.py:_safe_wrap_test_case:95] [873.346] 03023.03045> bt-transport-usb: timed out: ZX_ERR_TIMED_OUT [tb] 2019-04-20 00:28:21.352 INFO Found scan result: {'data': {'CallbackType': 1, 'ID': 1, 'Result': {'advertiseFlags': 2, 'deviceInfo': {'address': '4D:F3:3D:1F:98:E4', 'name': 'testADV123', 'state': 10, 'type': 2}, 'deviceName': 'testADV123', 'manufacturerIdList': '[]', 'manufacturerSpecificDataList': '[]', 'rssi': -54, 'scanRecord': '2,1,2,11,9,116,101,115,116,65,68,86,49,50,51,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0', 'serviceDataList': '[]', 'serviceUuidList': '[]', 'serviceUuids': '', 'timestampNanos': 1579604310516886, 'txPowerLevel': -2147483648}, 'Type': 'onScanResult'}, 'name': 'BleScan1onScanResults', 'time': 1555720101324} [BleFuchsiaAndroidTest.py:test_fuchsia_adv_android_scan:151] [tb] 2019-04-20 00:28:21.390 INFO [Test Case] test_fuchsia_adv_android_scan PASS [base_test.py:_on_pass:542] [tb] 2019-04-20 00:28:21.403 INFO [Test Case] test_fuchsia_connect_android_periph [base_test.py:exec_one_testcase:662] [tb] 2019-04-20 00:28:21.418 INFO [Test ID] BleFuchsiaAndroidTest:test_fuchsia_connect_android_periph:1555720101.4177434 [BluetoothBaseTest.py:_safe_wrap_test_case:95] [tb] 2019-04-20 00:28:21.518 INFO Android device name: Pixel1234 [BleFuchsiaAndroidTest.py:test_fuchsia_connect_android_periph:98] [874.026] 03023.09420> [INFO:low_energy_discovery_manager.cc(91)] gap-le: start discovery [tb] 2019-04-20 00:28:22.538 INFO Successfully found advertisement! name, id: Pixel1234, 7d40c5655ddf3a98 [bt_test_utils.py:le_scan_for_device_by_name:43] [tb] 2019-04-20 00:28:22.695 INFO Connecting returned status: {'error': None, 'result': None, 'id': '3'} [BleFuchsiaAndroidTest.py:test_fuchsia_connect_android_periph:109] [875.195] 03023.09420> [INFO:low_energy_connection_manager.cc(751)] gap-le: new connection (LE link - handle: 0x0002, role: master, address: (LE rand) 43:C2:80:16:17:97, interval: 45.00 ms, latency: 0.00 ms, timeout: 420 ms) [tb] 2019-04-20 00:28:22.846 INFO Listing services returned: {'error': None, 'result': [{'primary': True, 'uuid_type': '00001801-0000-1000-8000-00805f9b34fb', 'id': 1}, {'primary': True, 'uuid_type': '00001800-0000-1000-8000-00805f9b34fb', 'id': 20}], 'id': '4'} [BleFuchsiaAndroidTest.py:test_fuchsia_connect_android_periph:112] [tb] 2019-04-20 00:28:22.854 INFO Disconnect status: {'error': None, 'result': None, 'id': '5'} [BleFuchsiaAndroidTest.py:test_fuchsia_connect_android_periph:115] [tb] 2019-04-20 00:28:22.891 INFO [Test Case] test_fuchsia_connect_android_periph PASS [base_test.py:_on_pass:542] [875.353] 03023.09420> [INFO:low_energy_connection_manager.cc(590)] gap-le: all refs dropped on connection: (LE link - handle: 0x0002, role: master, address: (LE rand) 43:C2:80:16:17:97, interval: 45.00 ms, latency: 0.00 ms, timeout: 420 ms) [875.397] 03023.09420> [INFO:low_energy_connection_manager.cc(848)] gap-le: link disconnected - status: "success", handle: 0x0002, reason: 0x16 [tb] 2019-04-20 00:28:22.910 INFO [Test Case] test_fuchsia_scan_android_adv [base_test.py:exec_one_testcase:662] [tb] 2019-04-20 00:28:22.929 INFO [Test ID] BleFuchsiaAndroidTest:test_fuchsia_scan_android_adv:1555720102.9277484 [BluetoothBaseTest.py:_safe_wrap_test_case:95] [tb] 2019-04-20 00:28:23.013 INFO Android device name: Pixel1234 [BleFuchsiaAndroidTest.py:test_fuchsia_scan_android_adv:75] [875.520] 03023.09420> [INFO:low_energy_discovery_manager.cc(91)] gap-le: start discovery [tb] 2019-04-20 00:28:24.033 INFO Successfully found advertisement! name, id: Pixel1234, d94f6f35d9f34b34 [bt_test_utils.py:le_scan_for_device_by_name:43] [tb] 2019-04-20 00:28:24.067 INFO [Test Case] test_fuchsia_scan_android_adv PASS [base_test.py:_on_pass:542] [tb] 2019-04-20 00:28:24.763 INFO Summary for test class BleFuchsiaAndroidTest: ControllerInfo {'AndroidDevice': [{'serial': '896X05XLX', 'build_id': '5289084', 'build_type': 'userdebug', 'model': 'blueline', 'incremental_build_id': '5289084'}], 'FuchsiaDevice': [{'ip': '192.168.42.103'}]}, Requested 3, Executed 3, Passed 3, Failed 0, Skipped 0, Blocked 0, Unknown 0, Errors 0 [base_test.py:run:1027] [tb] 2019-04-20 00:28:24.800 INFO [AndroidDevice|896X05XLX] The primary device under test is "896X05XLX". [android_device.py:create:92] [tb] 2019-04-20 00:28:27.621 INFO Controller AndroidDevice: [{'serial': '896X05XLX', 'build_id': '5289084', 'build_type': 'userdebug', 'model': 'blueline', 'incremental_build_id': '5289084'}] [base_test.py:register_controller:396] [tb] 2019-04-20 00:28:27.629 INFO [SshConnection | 192.168.42.103] Starting master ssh connection. [connection.py:setup_master_ssh:141] [880.219] 30992.31007> setsockopt IP_TOS 32: Protocol not available: [tb] 2019-04-20 00:28:27.851 INFO [SshConnection | 192.168.42.103] Starting master ssh connection. [connection.py:setup_master_ssh:141] [880.424] 31586.31602> setsockopt IP_TOS 32: Protocol not available: [tb] 2019-04-20 00:28:29.077 INFO [SshConnection | 192.168.42.103] Starting master ssh connection. [connection.py:setup_master_ssh:141] [881.647] 32663.32677> setsockopt IP_TOS 32: Protocol not available: [tb] 2019-04-20 00:28:29.306 INFO Controller FuchsiaDevice: [{'ip': '192.168.42.103'}] [base_test.py:register_controller:396] [tb] 2019-04-20 00:28:30.170 INFO ==========> GattServerSetupTest <========== [base_test.py:run:967] [tb] 2019-04-20 00:28:30.178 INFO [Test Case] test_alert_notification_service [base_test.py:exec_one_testcase:662] [tb] 2019-04-20 00:28:30.195 INFO [Test Case] test_alert_notification_service PASS [base_test.py:_on_pass:542] [tb] 2019-04-20 00:28:30.210 INFO [Test Case] test_automation_io_service [base_test.py:exec_one_testcase:662] [tb] 2019-04-20 00:28:30.225 INFO [Test Case] test_automation_io_service PASS [base_test.py:_on_pass:542] [tb] 2019-04-20 00:28:30.242 INFO [Test Case] test_battery_service [base_test.py:exec_one_testcase:662] [tb] 2019-04-20 00:28:30.256 INFO [Test Case] test_battery_service PASS [base_test.py:_on_pass:542] [tb] 2019-04-20 00:28:30.274 INFO [Test Case] test_blood_pressure_service [base_test.py:exec_one_testcase:662] [tb] 2019-04-20 00:28:30.289 INFO [Test Case] test_blood_pressure_service PASS [base_test.py:_on_pass:542] [tb] 2019-04-20 00:28:30.305 INFO [Test Case] test_body_composition_service [base_test.py:exec_one_testcase:662] [tb] 2019-04-20 00:28:30.319 INFO [Test Case] test_body_composition_service PASS [base_test.py:_on_pass:542] [tb] 2019-04-20 00:28:30.335 INFO [Test Case] test_bond_management_service [base_test.py:exec_one_testcase:662] [tb] 2019-04-20 00:28:30.348 INFO [Test Case] test_bond_management_service PASS [base_test.py:_on_pass:542] [tb] 2019-04-20 00:28:30.363 INFO [Test Case] test_continuous_glucose_monitoring_service [base_test.py:exec_one_testcase:662] [tb] 2019-04-20 00:28:30.374 INFO [Test Case] test_continuous_glucose_monitoring_service PASS [base_test.py:_on_pass:542] [tb] 2019-04-20 00:28:30.391 INFO [Test Case] test_current_time_service [base_test.py:exec_one_testcase:662] [tb] 2019-04-20 00:28:30.402 INFO [Test Case] test_current_time_service PASS [base_test.py:_on_pass:542] [tb] 2019-04-20 00:28:30.414 INFO [Test Case] test_cycling_power_service [base_test.py:exec_one_testcase:662] [tb] 2019-04-20 00:28:30.423 INFO [Test Case] test_cycling_power_service PASS [base_test.py:_on_pass:542] [tb] 2019-04-20 00:28:30.437 INFO [Test Case] test_cycling_speed_and_cadence_service [base_test.py:exec_one_testcase:662] [tb] 2019-04-20 00:28:30.446 INFO [Test Case] test_cycling_speed_and_cadence_service PASS [base_test.py:_on_pass:542] [tb] 2019-04-20 00:28:30.459 INFO [Test Case] test_device_information_service [base_test.py:exec_one_testcase:662] [tb] 2019-04-20 00:28:30.469 INFO [Test Case] test_device_information_service PASS [base_test.py:_on_pass:542] [tb] 2019-04-20 00:28:30.483 INFO [Test Case] test_duplicate_services [base_test.py:exec_one_testcase:662] [tb] 2019-04-20 00:28:30.491 INFO [Test Case] test_duplicate_services PASS [base_test.py:_on_pass:542] [tb] 2019-04-20 00:28:30.502 INFO [Test Case] test_environmental_sensing_service [base_test.py:exec_one_testcase:662] [tb] 2019-04-20 00:28:30.518 INFO [Test Case] test_environmental_sensing_service PASS [base_test.py:_on_pass:542] [tb] 2019-04-20 00:28:30.530 INFO [Test Case] test_fitness_machine_service [base_test.py:exec_one_testcase:662] [tb] 2019-04-20 00:28:30.540 INFO [Test Case] test_fitness_machine_service PASS [base_test.py:_on_pass:542] [tb] 2019-04-20 00:28:30.553 INFO [Test Case] test_glucose_service [base_test.py:exec_one_testcase:662] [tb] 2019-04-20 00:28:30.562 INFO [Test Case] test_glucose_service PASS [base_test.py:_on_pass:542] [tb] 2019-04-20 00:28:30.573 INFO [Test Case] test_health_thermometer_service [base_test.py:exec_one_testcase:662] [tb] 2019-04-20 00:28:30.582 INFO [Test Case] test_health_thermometer_service PASS [base_test.py:_on_pass:542] [tb] 2019-04-20 00:28:30.597 INFO [Test Case] test_heart_rate_service [base_test.py:exec_one_testcase:662] [tb] 2019-04-20 00:28:30.608 INFO [Test Case] test_heart_rate_service PASS [base_test.py:_on_pass:542] [tb] 2019-04-20 00:28:30.624 INFO [Test Case] test_http_proxy_service [base_test.py:exec_one_testcase:662] [tb] 2019-04-20 00:28:30.636 INFO [Test Case] test_http_proxy_service PASS [base_test.py:_on_pass:542] [tb] 2019-04-20 00:28:30.653 INFO [Test Case] test_human_interface_device_service [base_test.py:exec_one_testcase:662] [tb] 2019-04-20 00:28:30.665 INFO [Test Case] test_human_interface_device_service PASS [base_test.py:_on_pass:542] [tb] 2019-04-20 00:28:30.682 INFO [Test Case] test_immediate_alert_service [base_test.py:exec_one_testcase:662] [tb] 2019-04-20 00:28:30.696 INFO [Test Case] test_immediate_alert_service PASS [base_test.py:_on_pass:542] [tb] 2019-04-20 00:28:30.712 INFO [Test Case] test_indoor_positioning_service [base_test.py:exec_one_testcase:662] [tb] 2019-04-20 00:28:30.729 INFO [Test Case] test_indoor_positioning_service PASS [base_test.py:_on_pass:542] [tb] 2019-04-20 00:28:30.748 INFO [Test Case] test_insulin_delivery_service [base_test.py:exec_one_testcase:662] [tb] 2019-04-20 00:28:30.764 INFO [Test Case] test_insulin_delivery_service PASS [base_test.py:_on_pass:542] [tb] 2019-04-20 00:28:30.785 INFO [Test Case] test_internet_protocol_support_service [base_test.py:exec_one_testcase:662] [tb] 2019-04-20 00:28:30.800 INFO [Test Case] test_internet_protocol_support_service PASS [base_test.py:_on_pass:542] [tb] 2019-04-20 00:28:30.813 INFO [Test Case] test_link_loss_service [base_test.py:exec_one_testcase:662] [tb] 2019-04-20 00:28:30.825 INFO [Test Case] test_link_loss_service PASS [base_test.py:_on_pass:542] [tb] 2019-04-20 00:28:30.840 INFO [Test Case] test_location_and_navigation_service [base_test.py:exec_one_testcase:662] [tb] 2019-04-20 00:28:30.852 INFO [Test Case] test_location_and_navigation_service PASS [base_test.py:_on_pass:542] [tb] 2019-04-20 00:28:30.866 INFO [Test Case] test_mesh_provisioning_service [base_test.py:exec_one_testcase:662] [tb] 2019-04-20 00:28:30.880 INFO [Test Case] test_mesh_provisioning_service PASS [base_test.py:_on_pass:542] [tb] 2019-04-20 00:28:30.898 INFO [Test Case] test_mesh_proxy_service [base_test.py:exec_one_testcase:662] [tb] 2019-04-20 00:28:30.913 INFO [Test Case] test_mesh_proxy_service PASS [base_test.py:_on_pass:542] [tb] 2019-04-20 00:28:30.931 INFO [Test Case] test_next_dst_change_service [base_test.py:exec_one_testcase:662] [tb] 2019-04-20 00:28:30.944 INFO [Test Case] test_next_dst_change_service PASS [base_test.py:_on_pass:542] [tb] 2019-04-20 00:28:30.961 INFO [Test Case] test_object_transfer_service [base_test.py:exec_one_testcase:662] [tb] 2019-04-20 00:28:30.977 INFO [Test Case] test_object_transfer_service PASS [base_test.py:_on_pass:542] [tb] 2019-04-20 00:28:30.996 INFO [Test Case] test_phone_alert_status_service [base_test.py:exec_one_testcase:662] [tb] 2019-04-20 00:28:31.012 INFO [Test Case] test_phone_alert_status_service PASS [base_test.py:_on_pass:542] [tb] 2019-04-20 00:28:31.030 INFO [Test Case] test_primary_and_secondary_service [base_test.py:exec_one_testcase:662] [tb] 2019-04-20 00:28:31.045 INFO [Test Case] test_primary_and_secondary_service PASS [base_test.py:_on_pass:542] [tb] 2019-04-20 00:28:31.062 INFO [Test Case] test_pulse_oximeter_service [base_test.py:exec_one_testcase:662] [tb] 2019-04-20 00:28:31.077 INFO [Test Case] test_pulse_oximeter_service PASS [base_test.py:_on_pass:542] [tb] 2019-04-20 00:28:31.095 INFO [Test Case] test_reconnection_configuration_service [base_test.py:exec_one_testcase:662] [tb] 2019-04-20 00:28:31.109 INFO [Test Case] test_reconnection_configuration_service PASS [base_test.py:_on_pass:542] [tb] 2019-04-20 00:28:31.124 INFO [Test Case] test_reference_time_update_service [base_test.py:exec_one_testcase:662] [tb] 2019-04-20 00:28:31.136 INFO [Test Case] test_reference_time_update_service PASS [base_test.py:_on_pass:542] [tb] 2019-04-20 00:28:31.148 INFO [Test Case] test_running_speed_and_cadence_service [base_test.py:exec_one_testcase:662] [tb] 2019-04-20 00:28:31.157 INFO [Test Case] test_running_speed_and_cadence_service PASS [base_test.py:_on_pass:542] [tb] 2019-04-20 00:28:31.171 INFO [Test Case] test_scan_parameters_service [base_test.py:exec_one_testcase:662] [tb] 2019-04-20 00:28:31.181 INFO [Test Case] test_scan_parameters_service PASS [base_test.py:_on_pass:542] [tb] 2019-04-20 00:28:31.195 INFO [Test Case] test_single_primary_service [base_test.py:exec_one_testcase:662] [tb] 2019-04-20 00:28:31.204 INFO [Test Case] test_single_primary_service PASS [base_test.py:_on_pass:542] [tb] 2019-04-20 00:28:31.222 INFO [Test Case] test_single_secondary_service [base_test.py:exec_one_testcase:662] [tb] 2019-04-20 00:28:31.237 INFO [Test Case] test_single_secondary_service PASS [base_test.py:_on_pass:542] [tb] 2019-04-20 00:28:31.255 INFO [Test Case] test_transport_discovery_service [base_test.py:exec_one_testcase:662] [tb] 2019-04-20 00:28:31.270 INFO [Test Case] test_transport_discovery_service PASS [base_test.py:_on_pass:542] [tb] 2019-04-20 00:28:31.283 INFO [Test Case] test_tx_power_service [base_test.py:exec_one_testcase:662] [tb] 2019-04-20 00:28:31.294 INFO [Test Case] test_tx_power_service PASS [base_test.py:_on_pass:542] [tb] 2019-04-20 00:28:31.303 INFO [Test Case] test_user_data_service [base_test.py:exec_one_testcase:662] [tb] 2019-04-20 00:28:31.316 INFO [Test Case] test_user_data_service PASS [base_test.py:_on_pass:542] [tb] 2019-04-20 00:28:31.327 INFO [Test Case] test_weight_scale_service [base_test.py:exec_one_testcase:662] [tb] 2019-04-20 00:28:31.336 INFO [Test Case] test_weight_scale_service PASS [base_test.py:_on_pass:542] [tb] 2019-04-20 00:28:32.022 INFO Summary for test class GattServerSetupTest: ControllerInfo {'AndroidDevice': [{'serial': '896X05XLX', 'build_id': '5289084', 'build_type': 'userdebug', 'model': 'blueline', 'incremental_build_id': '5289084'}], 'FuchsiaDevice': [{'ip': '192.168.42.103'}]}, Requested 42, Executed 42, Passed 42, Failed 0, Skipped 0, Blocked 0, Unknown 0, Errors 0 [base_test.py:run:1027] [tb] 2019-04-20 00:28:32.068 INFO [AndroidDevice|896X05XLX] The primary device under test is "896X05XLX". [android_device.py:create:92] [tb] 2019-04-20 00:28:34.176 INFO [AndroidDevice|896X05XLX] Screen is not awake, wake it up [android_device.py:wakeup_screen:1374] [tb] 2019-04-20 00:28:35.206 INFO Controller AndroidDevice: [{'serial': '896X05XLX', 'build_id': '5289084', 'build_type': 'userdebug', 'model': 'blueline', 'incremental_build_id': '5289084'}] [base_test.py:register_controller:396] [tb] 2019-04-20 00:28:35.212 INFO [SshConnection | 192.168.42.103] Starting master ssh connection. [connection.py:setup_master_ssh:141] [887.792] 42840.42854> setsockopt IP_TOS 32: Protocol not available: [tb] 2019-04-20 00:28:35.437 INFO [SshConnection | 192.168.42.103] Starting master ssh connection. [connection.py:setup_master_ssh:141] [888.014] 43431.43446> setsockopt IP_TOS 32: Protocol not available: [tb] 2019-04-20 00:28:36.666 INFO [SshConnection | 192.168.42.103] Starting master ssh connection. [connection.py:setup_master_ssh:141] [889.234] 44515.44530> setsockopt IP_TOS 32: Protocol not available: [tb] 2019-04-20 00:28:36.905 INFO Controller FuchsiaDevice: [{'ip': '192.168.42.103'}] [base_test.py:register_controller:396] [tb] 2019-04-20 00:28:37.779 INFO Running testbed setup with one fuchsia devices [NetstackFuchsiaTest.py:__init__:31] [tb] 2019-04-20 00:28:37.781 INFO ==========> NetstackFuchsiaTest <========== [base_test.py:run:967] [tb] 2019-04-20 00:28:37.792 INFO [Test Case] test_fuchsia_publish_service [base_test.py:exec_one_testcase:662] [tb] 2019-04-20 00:28:37.810 INFO [Test Case] test_fuchsia_publish_service PASS [base_test.py:_on_pass:542] [tb] 2019-04-20 00:28:38.400 INFO Summary for test class NetstackFuchsiaTest: ControllerInfo {'AndroidDevice': [{'serial': '896X05XLX', 'build_id': '5289084', 'build_type': 'userdebug', 'model': 'blueline', 'incremental_build_id': '5289084'}], 'FuchsiaDevice': [{'ip': '192.168.42.103'}]}, Requested 1, Executed 1, Passed 1, Failed 0, Skipped 0, Blocked 0, Unknown 0, Errors 0 [base_test.py:run:1027] [tb] 2019-04-20 00:28:38.408 INFO Summary for test run tb@2019-04-20_00-28-00-612: ControllerInfo {'AndroidDevice': [{'serial': '896X05XLX', 'build_id': '5289084', 'build_type': 'userdebug', 'model': 'blueline', 'incremental_build_id': '5289084'}], 'FuchsiaDevice': [{'ip': '192.168.42.103'}]}, Requested 47, Executed 47, Passed 47, Failed 0, Skipped 0, Blocked 0, Unknown 0, Errors 0 /etc/connectivity/acts/tools/test/connectivity/acts/framework/acts/controllers/buds_lib/test_actions/bt_utils.py:201: SyntaxWarning: assertion is always true, perhaps remove parentheses? assert (True is pri_device.droid.bluetoothUnbond(target_address), Command succeeded!