DEBUG: config flag: /etc/botanist/config.json DEBUG: executing command: "/etc/connectivity/host_cmds.sh" environment of subprocess: [] 2019/04/20 00:47:42 attempting to send <<netboot>>cmdline... 2019/04/20 00:47:42 done 2019/04/20 00:47:42 attempting to send <<image>>sparse.fvm... [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 0x7ffff000 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 [18.408] 00000.00000> timer features: constant_tsc 1 invariant_tsc 1 tsc_deadline 1 [18.408] 00000.00000> Using TSC as wallclock [18.408] 00000.00000> initializing kernel [18.408] 00000.00000> initializing mp [18.408] 00000.00000> initializing timers [18.408] 00000.00000> INIT: cpu 0, calling hook 0xffffffff0013c578 (debuglog) at level 0x7ffff, flags 0x1 [18.408] 00000.00000> INIT: cpu 0, calling hook 0xffffffff00195518 (thread_set_priority_experiment) at level 0x7ffff, flags 0x1 [18.408] 00000.00000> thread set priority experiment is : ENABLED [18.408] 00000.00000> INIT: cpu 0, calling hook 0xffffffff001aa67c (global_prng_thread_safe) at level 0x7ffff, flags 0x1 [18.408] 00000.00000> creating bootstrap completion thread [18.751] 00000.00000> top of bootstrap2() [18.751] 00000.00000> INIT: cpu 0, calling hook 0xffffffff0013151c (dpc) at level 0x80000, flags 0x1 [18.764] 00000.00000> INIT: cpu 0, calling hook 0xffffffff00152978 (libobject) at level 0x80000, flags 0x1 [18.764] 00000.00000> OOM: started thread [18.777] 00000.00000> Processor Model Info: type 0 family 0x6 model 0xe stepping 0x9 [18.777] 00000.00000> display_family 0x6 display_model 0x8e [18.777] 00000.00000> Vendor: Intel [18.777] 00000.00000> Microarch: Kaby Lake [18.777] 00000.00000> F/M/S: 6/8e/9 [18.777] 00000.00000> Brand: Intel(R) Core(TM) i5-7300U CPU @ 2.60GHz [18.777] 00000.00000> Features: fpu sse sse2 sse3 ssse3 sse4.1 sse4.2 mmx avx avx2 fxsr pcid xsave mon aesni clflush [18.777] 00000.00000> clflushopt fsgsbase tsc_adj smep smap erms rdrand rdseed syscall nx huge rdtscp [18.777] 00000.00000> invar_tsc tsc_deadline x2apic vmx pt hwp [18.777] 00000.00000> initializing platform [18.777] 00000.00000> INIT: cpu 0, calling hook 0xffffffff001101f4 (x86_perfmon) at level 0x90000, flags 0x1 [18.777] 00000.00000> PMU: version 4 [18.778] 00000.00000> UART: started IRQ driven RX [18.778] 00000.00000> UART: started IRQ driven TX [18.778] 00000.00000> cpu topology: [18.778] 00000.00000> 0: apic id 0x0 package 0 node 0 core 0 smt 0 BSP [18.778] 00000.00000> 1: apic id 0x2 package 0 node 0 core 1 smt 0 [18.778] 00000.00000> 2: apic id 0x1 package 0 node 0 core 0 smt 1 [18.778] 00000.00000> 3: apic id 0x3 package 0 node 0 core 1 smt 1 [18.778] 00000.00000> Found 4 cpus [18.778] 00000.00000> booting apic ids: 0x2 0x1 0x3 [18.793] 00000.00000> entering scheduler on cpu 2 [18.794] 00000.00000> entering scheduler on cpu 1 [18.794] 00000.00000> entering scheduler on cpu 3 [18.797] 00000.00000> smbios: manufacturer="Intel Corporation" product="NUC7i5DNHE" [18.797] 00000.00000> initializing target [18.797] 00000.00000> INIT: cpu 0, calling hook 0xffffffff001053a0 (x86_pcie_init) at level 0xa0000, flags 0x1 [18.797] 00000.00000> moving to last init level [18.797] 00000.00000> INIT: cpu 0, calling hook 0xffffffff00144140 (ktrace) at level 0xc0000, flags 0x1 [18.801] 00000.00000> ktrace: buffer at 0xffffff9e28341000 (33554432 bytes) [18.801] 00000.00000> INIT: cpu 0, calling hook 0xffffffff00147ab4 (userboot) at level 0xc0000, flags 0x1 [18.801] 00000.00000> userboot: ramdisk 0x10ad000 @ 0xffffff80012f2000 [18.801] 00000.00000> userboot: userboot rodata 0 @ [0xac07398f000,0xac073992000) [18.801] 00000.00000> userboot: userboot code 0x3000 @ [0xac073992000,0xac07399d000) [18.801] 00000.00000> userboot: vdso/full rodata 0 @ [0xac07399d000,0xac0739a4000) [18.801] 00000.00000> userboot: vdso/full code 0x7000 @ [0xac0739a4000,0xac0739a5000) [18.801] 00000.00000> userboot: entry point @ 0xac073992c10 [18.801] 00000.00000> INIT: cpu 0, calling hook 0xffffffff001aa030 (kernel_shell) at level 0xc0000, flags 0x1 [18.801] 01036.01043> userboot: option "netsvc.disable=true" [18.801] 01036.01043> userboot: option "zircon.system.disable-automount=true" [18.801] 01036.01043> userboot: option "zircon.autorun.boot=/boot/infra/setup" [18.801] 01036.01043> userboot: option "kernel.serial=legacy" [18.801] 01036.01043> userboot: option "http://192.168.42.1/multiboot/d4%3A5d%3Adf%3A1a%3A42%3A46=" [18.801] 01036.01043> userboot: option "multiboot.boot_loader_name=iPXE+1.0.0++(d2063)" [18.841] 01036.01043> userboot: searching bootfs for 'bin/bootsvc' [18.841] 01036.01043> userboot: 'bin/bootsvc' has PT_INTERP "lib/ld.so.1" [18.841] 01036.01043> userboot: searching bootfs for 'lib/ld.so.1' [18.841] 01036.01043> userboot: userboot: loaded lib/ld.so.1 at 0x6ef5c1735000, entry point 0x6ef5c17bb0d3 [18.841] 01036.01043> userboot: userboot: loaded vDSO at 0x4baa9f8aa000, entry point 0x0 [18.841] 01036.01043> userboot: process bin/bootsvc started. [18.841] 01036.01043> userboot: waiting for loader-service requests... [18.841] 01036.01043> userboot: searching bootfs for 'lib/libasync-default.so' [18.841] 01036.01043> userboot: searching bootfs for 'lib/libfdio.so' [18.841] 01036.01043> userboot: searching bootfs for 'lib/liblaunchpad.so' [18.841] 01036.01043> userboot: searching bootfs for 'lib/libtrace-engine.so' [18.841] 01050.01053> dso: id=18de7d58f51e8ba5c4f6afdd0cc8440f482c2b45 base=0x0000628f9d778000 name=<application> [18.841] 01050.01053> dso: id=c189f51f19d10785d93b5235ad1b46dca4451b00 base=0x0000088271a68000 name=libasync-default.so [18.841] 01050.01053> dso: id=40ab5fa3b61f12fef4a44477a687f608661cd450 base=0x00004baa9f8aa000 name=<vDSO> [18.841] 01050.01053> dso: id=67a12284bce140fc32aaaeac223e0e8f85cb5085 base=0x00006ef5c1735000 name=libc.so [18.841] 01050.01053> dso: id=27787977e95f3b9563c9e0bd4d34ec92b7e9ad88 base=0x000014b5fb450000 name=libfdio.so [18.841] 01050.01053> dso: id=6fc2232dc8c1bc5c6adb8ad50ca794b5a260ee4f base=0x00001dab4a411000 name=liblaunchpad.so [18.841] 01050.01053> dso: id=c9042b83fe01206008fcefb16395238417248169 base=0x0000558ea89b8000 name=libtrace-engine.so [18.841] 01050.01053> bootsvc: Starting... [18.841] 01036.01043> userboot: loader-service channel peer closed [18.841] 01036.01043> userboot: finished! [18.841] 01050.01053> bootsvc: Creating bootfs service... [18.842] 01050.01053> bootsvc: Processing bootdata... [18.842] 01050.01053> bootsvc: Loading boot cmdline overrides... [18.842] 01050.01053> bootsvc: Loading kernel VMOs... [18.842] 01050.01053> bootsvc: Creating loader service... [18.842] 01050.01053> bootsvc: Launching next process... [18.842] 01050.01096> bootsvc: launched bin/devmgr [18.843] 01104.01117> devmgr: main() [18.843] 01104.01117> cmdline: netsvc.disable=true [18.843] 01104.01117> cmdline: zircon.system.disable-automount=true [18.843] 01104.01117> cmdline: zircon.autorun.boot=/boot/infra/setup [18.843] 01104.01117> cmdline: kernel.serial=legacy [18.843] 01104.01117> cmdline: http://192.168.42.1/multiboot/d4%3A5d%3Adf%3A1a%3A42%3A46= [18.843] 01104.01117> cmdline: multiboot.boot_loader_name=iPXE+1.0.0++(d2063) [18.843] 01104.01117> devmgr: coordinator_init() [18.843] 01104.01117> devmgr: init [18.843] 01104.01117> devmgr: svc init [18.843] 01104.01117> devmgr: launch /boot/bin/svchost (svchost) OK [18.843] 01104.01117> devmgr: vfs init [18.843] 01104.01117> devmgr: launch /boot/bin/fshost (fshost) OK [18.843] 01104.01222> devmgr: shell startup [18.845] 01182.01202> fshost: started. [18.845] 01104.01212> devmgr: launch /boot/bin/pwrbtn-monitor (pwrbtn-monitor) OK [18.846] 01104.01241> devmgr: launch /boot/bin/virtual-console (virtual-console) OK [18.846] 01104.01241> zircon.autorun.boot: starting '/boot/infra/setup'... [18.846] 01104.01241> devmgr: launch /boot/infra/setup (autorun:boot) OK [18.849] 01104.01117> devcoord: launch devhost 'devhost:sys': pid=2049 [18.850] 01104.01117> devcoord: launch devhost 'devhost:test': pid=2082 [18.850] 01104.01117> devcoord: launch devhost 'devhost:root': pid=2115 [18.850] 01104.01117> devcoord: launch devhost 'devhost:misc': pid=2168 [18.851] 02049.02073> devhost: trace provider registry begun [18.852] 02082.02106> devhost: trace provider registry begun [18.852] 02115.02151> devhost: trace provider registry begun [18.854] 02168.02224> devhost: trace provider registry begun [18.862] 01104.01222> devmgr: launch /boot/bin/sh (sh:console) OK [18.921] 02049.02073> acpi-bus: not using IOMMU [18.925] 02049.02073> acpi-pwrbtn: initialized [18.931] 02049.02073> WARNING: ACPI found bad _CRS address entry [18.938] 02049.02073> WARNING: ACPI found bad _CRS address entry [18.949] 02049.02073> acpi: published device pci(0x28f49df42200), parent=proxy(0x28f49df3e540), handle=0x28f49df7a750 [18.951] 02049.02073> acpi: published device rtc(0x28f49df3d080), parent=acpi(0x28f49df3e780), handle=0x28f49df99330 [18.951] 02049.02073> acpi-ec: initialized [18.953] 02049.02073> acpi: failed to create NHLT VMO (res -10) [18.953] 02049.02073> acpi: failed to publish NHLT metadata [18.955] 02049.02073> [sysmem_init 28] async_get_default_dispatcher(): 0x28f49df310a0 [18.955] 02049.02073> [sysmem_bind 40] sysmem_bind() [18.955] 02049.02073> acpi-bus: sysmem_register_protocol() intentionally ignored for now. [18.956] 02049.02073> PMU: 7 arch events [18.956] 02049.02073> PMU: arch event id range: 1-7 [18.956] 02049.02073> PMU: 102 model events [18.956] 02049.02073> PMU: model event id range: 1-241 [18.956] 02049.02073> Intel Processor Trace configuration for this chipset: [18.956] 02049.02073> mtc_freq_mask: 0x249 [18.956] 02049.02073> cyc_thresh_mask: 0x3fff [18.956] 02049.02073> psb_freq_mask: 0x3f [18.956] 02049.02073> num addr ranges: 2 [18.957] 01104.01117> devcoord: launch devhost 'devhost:pci#1:8086:5916': pid=2994 [18.958] 01251.01527> vc: new input device /dev/class/input/000 [18.958] 01104.01117> devcoord: launch devhost 'devhost:pci#3:8086:9d2f': pid=3074 [18.958] 01104.01117> devcoord: launch devhost 'devhost:pci#5:8086:9d60': pid=3151 [18.959] 01104.01117> devcoord: launch devhost 'devhost:pci#6:8086:9d61': pid=3199 [18.960] 02994.03038> devhost: trace provider registry begun [18.960] 01104.01117> devcoord: launch devhost 'devhost:pci#9:8086:9d03': pid=3279 [18.961] 03074.03123> devhost: trace provider registry begun [18.961] 01104.01117> devcoord: launch devhost 'devhost:pci#14:8086:9d71': pid=3406 [18.962] 03199.03242> devhost: trace provider registry begun [18.962] 01104.01117> devcoord: launch devhost 'devhost:pci#16:8086:156f': pid=3488 [18.962] 03151.03183> devhost: trace provider registry begun [18.965] 03279.03325> devhost: trace provider registry begun [18.965] 03199.03242> initialized intel serialio i2c driver, reg=0x6784fa7f8000 regsize=4096 [18.966] 03151.03183> initialized intel serialio i2c driver, reg=0x3493241e4000 regsize=4096 [18.968] 03279.03325> ahci: using MSI interrupt [18.968] 03406.03455> devhost: trace provider registry begun [18.969] 03488.03554> devhost: trace provider registry begun [18.970] 03074.03851> * found USB device (0x18d1:0xa002, USB 2.0) config 1 [18.970] 03074.03851> * found USB device (0x18d1:0xa003, USB 3.0) config 1 [18.978] 03406.03455> [IHDA DSP 00:1f.3] Failed to fetch NHLT (res -25) [18.978] 03406.03455> devhost[00:1f.3/intel-hda-000/intel-sst-dsp-000] bind driver '/boot/driver/dsp.so' failed: -25 [18.978] 01104.01117> devcoord: rpc: bind-driver 'intel-sst-dsp-000' status -25 [19.071] 01251.01527> vc: new display device /dev/class/display-controller/000/virtcon [19.211] 02994.04139> i915: Found DP monitor [19.211] 02994.04139> i915: Display 1 connected [19.212] 02994.04139> i915: MST not supported [19.710] 03074.03851> * found USB device (0x0781:0x5583, USB 3.0) config 1 [19.711] 03074.03123> UMS: parent: 'ifc-000' [19.711] 03074.03123> UMS:Max lun is: 0 [20.279] 01251.01527> vc: Successfully attached to display 1 [20.436] 03074.03851> * found USB device (0x046d:0xc31c, USB 1.10) config 1 [20.440] 01251.01527> vc: new input device /dev/class/input/001 [20.445] 01251.01527> vc: new input device /dev/class/input/002 [20.683] 03074.03851> * found USB device (0x0cf3:0xe300, USB 2.1) config 1 [20.685] 03074.03123> devhost[00:14.0/xhci/usb-bus/003/003/ifc-001] bind driver '/boot/driver/bt-transport-usb.so' failed: -2 [20.685] 01104.01117> devcoord: rpc: bind-driver 'ifc-001' status -2 [20.714] 03074.04226> UMS: block size is: 0x00000200 [20.714] 03074.04226> UMS: total blocks is: 30031250 [20.714] 03074.04226> UMS: total size is: 15376000000 [20.714] 03074.04226> UMS: read-only: 0 removable: 1 [20.715] 01182.01202> devmgr: /dev/class/block/000: MBR? [20.715] 01104.01117> devcoord: dc_bind_device() '/boot/driver/mbr.so' [20.717] 01182.01202> devmgr: /dev/class/block/002: MBR? [20.717] 01104.01117> devcoord: dc_bind_device() '/boot/driver/mbr.so' [20.968] 03199.03242> intel-i2c-controller: intel_serialio_i2c_slave_transfer: -21 [20.968] 03199.03242> i2c-hid: could not read HID descriptor: 0 [20.968] 03199.03242> devhost[00:15.1/i2c-bus-9d61/004c] bind driver '/boot/driver/i2c-hid.so' failed: -2 [20.968] 01104.01117> devcoord: rpc: bind-driver '004c' status -2 [20.968] 03151.03183> intel-i2c-controller: intel_serialio_i2c_slave_transfer: -21 [20.968] 03151.03183> i2c-hid: could not read HID descriptor: 0 [20.968] 03151.03183> devhost[00:15.0/i2c-bus-9d60/0020] bind driver '/boot/driver/i2c-hid.so' failed: -2 [20.968] 01104.01117> devcoord: rpc: bind-driver '0020' status -2 [20.973] 03279.03798> sata2: dev info [20.973] 03279.03798> serial=711430952084 9 [20.973] 03279.03798> firmware rev=1Q01A7 0 [20.973] 03279.03798> model id=IBIW NSS D [20.973] 03279.03798> major=0x3f0 ACS2 DMA 32 commands [20.973] 03279.03798> LBA48 234441648 sectors, sector size=512 [20.975] 04585.04599> paver:[InitializeGpt] Located GPT is invalid; Attempting to initialize [20.976] 01104.01117> devcoord: dc_bind_device() '/boot/driver/gpt.so' [20.976] 03279.03325> gpt: device_get_metadata failed (-25) [20.977] 04585.04599> paver:[Initialize] Successfully initialized EFI Device Partitioner [20.977] 01104.01117> devcoord: dc_bind_device() '' [20.978] 01182.01202> devmgr: /dev/class/block/003: GPT? [20.978] 01104.01117> devcoord: dc_bind_device() '/boot/driver/gpt.so' [20.978] 03279.03325> gpt: device_get_metadata failed (-25) [20.980] 04745.04768> 34+0 records in [20.980] 04745.04768> 34+0 records out [20.980] 04745.04768> 17408 bytes copied [20.981] 04858.04872> Failed to seek on output [20.981] 04858.04872> 0+0 records in [20.981] 04858.04872> 0+0 records out [20.981] 04858.04872> 0 bytes copied [20.982] 04928.04942> netifc: ? /dev/class/ethernet/000 [20.982] 04928.04942> netifc: create 512 eth buffers [20.982] 04928.04942> macaddr: d4:5d:df:1a:42:46 [20.982] 04928.04942> ip6addr: fe80::d65d:df4d:fe1a:4246 [20.982] 04928.04942> snmaddr: ff02::1:ff1a:4246 [20.982] 04928.04942> netsvc: using /dev/class/ethernet/000 [20.982] 04928.04942> _ _ _ [20.982] 04928.04942> | | | | | [20.982] 04928.04942> _______ __| | |__ ___ ___ | |_ [20.982] 04928.04942> |_ / _ \/ _` | '_ \ / _ \ / _ \| __| [20.982] 04928.04942> / / __/ (_| | |_) | (_) | (_) | |_ [20.982] 04928.04942> /___\___|\__,_|_.__/ \___/ \___/ \__| [20.982] 04928.04942> zedboot: version: 0.7.13 [20.982] 04928.04942> netsvc: nodename='ocean-drank-wick-spot' [20.982] 04928.04942> netsvc: will not advertise [20.982] 04928.04942> netsvc: start [752.870] 04928.04942> netsvc: tftp write of file <<netboot>>cmdline completed [752.870] 04928.04942> netsvc: metrics: {"inorderblks": 1,"oooblks": 0,"ack": 1,"nack": 0,"timeouts": 0,"sas": 0,"inorderbytes": 55} [752.871] 04928.04942> netsvc: Running FVM Paver [752.873] 04928.05036> paver:[InitializeGpt] Located GPT is invalid; Attempting to initialize [752.873] 01104.01117> devcoord: dc_bind_device() '' [752.873] 01104.01117> devcoord: dc_bind_device() '/boot/driver/gpt.so' [752.873] 03279.03325> gpt: device_get_metadata failed (-25) [752.874] 01182.01202> devmgr: /dev/class/block/003: GPT? [752.874] 01104.01117> devcoord: dc_bind_device() '/boot/driver/gpt.so' [752.874] 03279.03325> devhost: rpc:bind-device failed: -20 [752.875] 04928.05036> paver:[Initialize] Successfully initialized EFI Device Partitioner [752.875] 04928.05036> paver:[PartitionPave] Paving partition. [752.875] 04928.05036> paver:[FindFirstFit] Looking for space [752.875] 04928.05036> paver:[FindFirstFit] Sorting [752.875] 04928.05036> paver:[FindFirstFit] Partition[0] From Block [0, 34) ... (next partition starts at block 234441614) [752.875] 04928.05036> paver:[FindFirstFit] There are 234441580 free blocks (16777216 requested) [752.875] 04928.05036> paver:[AddPartition] Found space in GPT - OK 234441580 @ 34 [752.875] 04928.05036> paver:[AddPartition] Final space in GPT - OK 16777216 @ 34 [752.875] 04928.05036> paver:[AddPartition] Added partition, waiting for bind [752.875] 01104.01117> devcoord: dc_bind_device() '' [752.876] 01182.01202> devmgr: /dev/class/block/003: GPT? [752.876] 01104.01117> devcoord: dc_bind_device() '/boot/driver/gpt.so' [752.876] 03279.03325> gpt: device_get_metadata failed (-25) [752.877] 04928.05036> paver:[AddPartition] Added partition, waiting for bind - OK [752.877] 04928.05036> paver:[PartitionPave] Streaming partitions... [752.877] 05016.05030> Found compressed file [752.877] 04928.05036> paver:[FvmStreamPartitions] Header Validated - OK [752.877] 04928.05036> paver:[FvmPartitionFormat] Initializing partition as FVM [752.879] 01104.01117> devcoord: dc_bind_device() '/boot/driver/fvm.so' [753.882] 04928.05036> paver:[FvmStreamPartitions] Partitions pre-validated successfully: Enough space exists to pave. [753.882] 04928.05036> paver:[AllocatePartitions] Allocating partition blobfs consisting of 1 slices [753.885] 04928.05036> paver:[AllocatePartitions] Allocating partition minfs consisting of 1 slices [753.886] 04928.05036> paver:[AllocatePartitions] Creating zxcrypt volume [753.888] 03279.03325> devhost_get_handles(0x772de20739c0:block) open path='zxcrypt/block', r=-2 [753.888] 01104.01117> devcoord: dc_bind_device() '/boot/driver/zxcrypt.so' [753.888] 03279.03325> devhost_get_handles(0x772de20739c0:block) open path='zxcrypt', r=-2 [753.892] 04928.05036> paver:[FvmStreamPartitions] Partition space pre-allocated successfully. [753.892] 04928.05036> paver:[FvmStreamPartitions] Streaming partition 0 [753.892] 04928.05036> paver:[StreamFvmPartition] Writing extent 0... [753.892] 04928.05042> netsvc: paver write progress 0.2% [753.893] 04928.05036> paver:[StreamFvmPartition] 8192 bytes written, 8380416 zeroes left [753.910] 04928.05036> paver:[StreamFvmPartition] Writing extent 1... [753.910] 04928.05036> paver:[StreamFvmPartition] 8192 bytes written, 8380416 zeroes left [753.930] 04928.05036> paver:[StreamFvmPartition] Writing extent 2... [753.935] 04928.05036> paver:[StreamFvmPartition] 2097152 bytes written, 6291456 zeroes left [753.947] 04928.05036> paver:[StreamFvmPartition] Writing extent 3... [753.952] 04928.05036> paver:[StreamFvmPartition] 2097152 bytes written, 6291456 zeroes left [753.969] 04928.05036> paver:[StreamFvmPartition] Writing extent 4... 2019/04/20 00:47:44 done 2019/04/20 00:47:44 attempting to send <<image>>bootloader.img... 2019/04/20 00:47:44 target is busy, retrying in one second [754.655] 04928.04942> netsvc: tftp write of file <<image>>sparse.fvm completed [754.655] 04928.04942> netsvc: metrics: {"inorderblks": 165704,"oooblks": 0,"ack": 648,"nack": 0,"timeouts": 0,"sas": 0,"inorderbytes": 169680796} [754.656] 04928.05036> paver:[StreamFvmPartition] 182951936 bytes written, 1597440 zeroes left [754.659] 04928.05036> paver:[FvmStreamPartitions] Done streaming partition 0 [754.659] 04928.05036> paver:[FvmStreamPartitions] Done flushing partition 0 [754.659] 04928.05036> paver:[FvmStreamPartitions] Streaming partition 1 [754.659] 04928.05036> paver:[StreamFvmPartition] Writing extent 0... [754.659] 04928.05036> paver:[StreamFvmPartition] 8192 bytes written, 8380416 zeroes left [754.699] 04928.05036> paver:[StreamFvmPartition] Writing extent 1... [754.700] 04928.05036> paver:[StreamFvmPartition] 65536 bytes written, 8323072 zeroes left [754.738] 04928.05036> paver:[StreamFvmPartition] Writing extent 2... [754.739] 04928.05036> paver:[StreamFvmPartition] 65536 bytes written, 8323072 zeroes left [754.774] 04928.05036> paver:[StreamFvmPartition] Writing extent 3... [754.815] 04928.05036> paver:[StreamFvmPartition] Writing extent 4... [754.825] 04928.05036> paver:[StreamFvmPartition] 2097152 bytes written, 14680064 zeroes left [754.894] 04928.05036> paver:[StreamFvmPartition] Writing extent 5... [754.894] 04928.05036> paver:[StreamFvmPartition] 57344 bytes written, 8331264 zeroes left [754.930] 04928.05036> paver:[FvmStreamPartitions] Done streaming partition 1 [754.930] 04928.05036> paver:[FvmStreamPartitions] Done flushing partition 1 [754.931] 05016.05030> Reading FVM from compressed file: true [754.931] 05016.05030> Remaining bytes read into compression buffer: 0 [754.931] 05016.05030> Remaining bytes written to decompression buffer: 0 [754.931] 05016.05030> Time reading bytes from sparse FVM file: 743178202 (0 s) [754.931] 05016.05030> Time reading bytes AND decompressing them: 839110969 (0 s) [754.931] 04928.05036> paver:[PartitionPave] Completed successfully 2019/04/20 00:47:45 attempting to send <<image>>bootloader.img... 2019/04/20 00:47:45 done 2019/04/20 00:47:45 attempting to send <<image>>zircona.img... [755.656] 04928.04942> netsvc: Running BOOTLOADER Paver [755.659] 04928.05772> paver:[Initialize] Successfully initialized EFI Device Partitioner [755.659] 04928.05772> paver:[RealMain] SKIPPING BOOTLOADER install on x64 device, pass --force if desired. [755.676] 04928.04942> netsvc: tftp write of file <<image>>bootloader.img completed [755.676] 04928.04942> netsvc: metrics: {"inorderblks": 1093,"oooblks": 0,"ack": 5,"nack": 0,"timeouts": 0,"sas": 0,"inorderbytes": 1118208} [755.676] 04928.04942> netsvc: Running ZIRCON-A Paver [755.680] 04928.05913> paver:[Initialize] Successfully initialized EFI Device Partitioner [755.680] 04928.05913> paver:[PartitionPave] Paving partition. [755.680] 04928.05913> paver:[FindFirstFit] Looking for space [755.680] 04928.05913> paver:[FindFirstFit] Partition seen with start 34, end 16777249 (length 16777216) [755.680] 04928.05913> paver:[FindFirstFit] Sorting [755.680] 04928.05913> paver:[FindFirstFit] Partition[0] From Block [0, 34) ... (next partition starts at block 34) [755.680] 04928.05913> paver:[FindFirstFit] There are 0 free blocks (32768 requested) [755.680] 04928.05913> paver:[FindFirstFit] Partition[1] From Block [34, 16777250) ... (next partition starts at block 234441614) [755.680] 04928.05913> paver:[FindFirstFit] There are 217664364 free blocks (32768 requested) [755.680] 04928.05913> paver:[AddPartition] Found space in GPT - OK 217664364 @ 16777250 [755.680] 04928.05913> paver:[AddPartition] Final space in GPT - OK 32768 @ 16777250 [755.680] 04928.05913> paver:[AddPartition] Added partition, waiting for bind [755.680] 03279.03325> block: Joining un-closed FIFO server [755.680] 03279.03325> block: Joining un-closed FIFO server [755.681] 01104.01117> devcoord: dc_bind_device() '' [755.681] 01182.01202> devmgr: /dev/class/block/003: GPT? [755.681] 01104.01117> devcoord: dc_bind_device() '/boot/driver/gpt.so' [755.681] 03279.03325> gpt: device_get_metadata failed (-25) [755.682] 01182.01202> devmgr: /dev/class/block/008: FVM? [755.682] 01104.01117> devcoord: dc_bind_device() '/boot/driver/fvm.so' [755.682] 04928.05913> paver:[AddPartition] Added partition, waiting for bind - OK 2019/04/20 00:47:45 done 2019/04/20 00:47:45 attempting to send <<image>>zirconr.img... 2019/04/20 00:47:45 target is busy, retrying in one second [755.828] 04928.04942> netsvc: tftp write of file <<image>>zircona.img completed [755.828] 04928.04942> netsvc: metrics: {"inorderblks": 13900,"oooblks": 0,"ack": 55,"nack": 0,"timeouts": 0,"sas": 0,"inorderbytes": 14233280} [755.861] 04928.05913> paver:[PartitionPave] Completed successfully 2019/04/20 00:47:46 attempting to send <<image>>zirconr.img... [756.829] 04928.04942> netsvc: Running ZIRCON-R Paver [756.832] 04928.06186> paver:[Initialize] Successfully initialized EFI Device Partitioner [756.832] 04928.06186> paver:[PartitionPave] Paving partition. [756.832] 04928.06186> paver:[FindFirstFit] Looking for space [756.832] 04928.06186> paver:[FindFirstFit] Partition seen with start 34, end 16777249 (length 16777216) [756.832] 04928.06186> paver:[FindFirstFit] Partition seen with start 16777250, end 16810017 (length 32768) [756.832] 04928.06186> paver:[FindFirstFit] Sorting [756.832] 04928.06186> paver:[FindFirstFit] Partition[0] From Block [0, 34) ... (next partition starts at block 34) [756.832] 04928.06186> paver:[FindFirstFit] There are 0 free blocks (49152 requested) [756.832] 04928.06186> paver:[FindFirstFit] Partition[1] From Block [34, 16777250) ... (next partition starts at block 16777250) [756.832] 04928.06186> paver:[FindFirstFit] There are 0 free blocks (49152 requested) [756.832] 04928.06186> paver:[FindFirstFit] Partition[2] From Block [16777250, 16810018) ... (next partition starts at block 234441614) [756.832] 04928.06186> paver:[FindFirstFit] There are 217631596 free blocks (49152 requested) [756.832] 04928.06186> paver:[AddPartition] Found space in GPT - OK 217631596 @ 16810018 [756.832] 04928.06186> paver:[AddPartition] Final space in GPT - OK 49152 @ 16810018 [756.833] 04928.06186> paver:[AddPartition] Added partition, waiting for bind [756.833] 03279.03325> block: Joining un-closed FIFO server [756.833] 01104.01117> devcoord: dc_bind_device() '' [756.833] 01182.01202> devmgr: /dev/class/block/003: GPT? [756.833] 01104.01117> devcoord: dc_bind_device() '/boot/driver/gpt.so' [756.833] 03279.03325> gpt: device_get_metadata failed (-25) [756.834] 01182.01202> devmgr: /dev/class/block/012: FVM? [756.834] 01104.01117> devcoord: dc_bind_device() '/boot/driver/fvm.so' [756.835] 04928.06186> paver:[AddPartition] Added partition, waiting for bind - OK 2019/04/20 00:47:46 done 2019/04/20 00:47:46 attempting to send <<image>>authorized_keys... 2019/04/20 00:47:46 target is busy, retrying in one second [756.977] 04928.04942> netsvc: tftp write of file <<image>>zirconr.img completed [756.977] 04928.04942> netsvc: metrics: {"inorderblks": 12589,"oooblks": 0,"ack": 50,"nack": 0,"timeouts": 0,"sas": 0,"inorderbytes": 12890296} [757.008] 04928.06186> paver:[PartitionPave] Completed successfully 2019/04/20 00:47:47 attempting to send <<image>>authorized_keys... 2019/04/20 00:47:47 done 2019/04/20 00:47:47 attempting to send <<netboot>>kernel.bin... 2019/04/20 00:47:47 target is busy, retrying in one second [757.978] 04928.04942> netsvc: Installing SSH authorized_keys [757.978] 04928.04942> netsvc: tftp write of file <<image>>authorized_keys completed [757.978] 04928.04942> netsvc: metrics: {"inorderblks": 1,"oooblks": 0,"ack": 1,"nack": 0,"timeouts": 0,"sas": 0,"inorderbytes": 806} [757.980] 04928.06476> paver:[Initialize] Successfully initialized EFI Device Partitioner [757.981] 01104.01117> devcoord: dc_bind_device() '/boot/driver/zxcrypt.so' [757.981] 03279.03325> devhost_get_handles(0x772de20739c0:block) open path='zxcrypt', r=-2 [758.009] 04928.06476> paver:[DataFilePave] Wrote ssh/authorized_keys 2019/04/20 00:47:48 attempting to send <<netboot>>kernel.bin... 2019/04/20 00:47:48 done [0.000] 00000.00000> zbi: @ 0xffffff8006728000 (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 [0x6728000, 0x7346fff] [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 0x7ffff000 size 0x1000 [0.000] 00000.00000> PMM: boot reserve marking WIRED [0x100000, 0x2fffff] [0.000] 00000.00000> PMM: boot reserve marking WIRED [0x6728000, 0x7346fff] [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 [0x7347000, 0x7347100) [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-4c4ef74431fea26725fc448731c7b805fa6e01e8-dirty [0.000] 00000.00000> ELF build ID: ff7678e5c3082166aded0b609e1f216d061af11a [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 [759.416] 00000.00000> timer features: constant_tsc 1 invariant_tsc 1 tsc_deadline 1 [759.416] 00000.00000> Using TSC as wallclock [759.416] 00000.00000> INIT: cpu 0, calling hook 0xffffffff00208930 (percpu_heap_init) at level 0x60003, flags 0x1 [759.416] 00000.00000> initializing kernel [759.416] 00000.00000> initializing mp [759.416] 00000.00000> INIT: cpu 0, calling hook 0xffffffff00115118 (global_prng_thread_safe) at level 0x7ffff, flags 0x1 [759.416] 00000.00000> creating bootstrap completion thread [759.416] 00000.00000> top of bootstrap2() [759.416] 00000.00000> INIT: cpu 0, calling hook 0xffffffff00131734 (libobject) at level 0x80000, flags 0x1 [759.417] 00000.00000> OOM: started thread [759.417] 00000.00000> INIT: cpu 0, calling hook 0xffffffff0020589c (dpc) at level 0x80000, flags 0x1 [759.417] 00000.00000> Processor Model Info: type 0 family 0x6 model 0xe stepping 0x9 [759.417] 00000.00000> display_family 0x6 display_model 0x8e [759.417] 00000.00000> Vendor: Intel [759.417] 00000.00000> Microarch: Kaby Lake [759.417] 00000.00000> F/M/S: 6/8e/9 [759.417] 00000.00000> patch_level: 84 [759.417] 00000.00000> Brand: Intel(R) Core(TM) i5-7300U CPU @ 2.60GHz [759.417] 00000.00000> Features: fpu sse sse2 sse3 ssse3 sse4.1 sse4.2 mmx avx avx2 fxsr pcid xsave mon aesni clflush [759.417] 00000.00000> clflushopt fsgsbase tsc_adj smep smap erms rdrand rdseed syscall nx huge rdtscp [759.417] 00000.00000> invar_tsc tsc_deadline x2apic vmx pt hwp [759.417] 00000.00000> Properties: meltdown l1tf pcid_good [759.417] 00000.00000> initializing platform [759.417] 00000.00000> INIT: cpu 0, calling hook 0xffffffff001a157c (x86_perfmon) at level 0x90000, flags 0x1 [759.417] 00000.00000> PMU: version 4 [759.417] 00000.00000> UART: started IRQ driven RX [759.417] 00000.00000> UART: started IRQ driven TX [759.417] 00000.00000> cpu topology: [759.417] 00000.00000> 0: apic id 0x0 BSP [759.417] 00000.00000> 1: apic id 0x1 [759.417] 00000.00000> 2: apic id 0x2 [759.417] 00000.00000> 3: apic id 0x3 [759.417] 00000.00000> Found 4 cpus [759.417] 00000.00000> booting apic ids: 0x1 0x2 0x3 [759.431] 00000.00000> entering scheduler on cpu 1 [759.433] 00000.00000> entering scheduler on cpu 2 [759.433] 00000.00000> entering scheduler on cpu 3 [759.435] 00000.00000> smbios: manufacturer="Intel Corporation" product="NUC7i5DNHE" [759.435] 00000.00000> initializing target [759.435] 00000.00000> INIT: cpu 0, calling hook 0xffffffff001850b8 (x86_pcie_init) at level 0xa0000, flags 0x1 [759.435] 00000.00000> moving to last init level [759.435] 00000.00000> INIT: cpu 0, calling hook 0xffffffff001214cc (debuglog) at level 0xb0000, flags 0x1 [759.435] 00000.00000> INIT: cpu 0, calling hook 0xffffffff00174d40 (kcounters) at level 0xb0000, flags 0x1 [759.435] 00000.00000> INIT: cpu 0, calling hook 0xffffffff00102aec (kernel_shell) at level 0xc0000, flags 0x1 [759.435] 00000.00000> INIT: cpu 0, calling hook 0xffffffff00202ad4 (ktrace) at level 0xc0000, flags 0x1 [759.439] 00000.00000> ktrace: buffer at 0xffffff909a497000 (33554432 bytes) [759.439] 00000.00000> INIT: cpu 0, calling hook 0xffffffff002184f8 (userboot) at level 0xc0000, flags 0x1 [759.439] 00000.00000> userboot: ramdisk 0xc1f000 @ 0xffffff8006728000 [759.439] 00000.00000> userboot: userboot rodata 0 @ [0x67b8ba5b1000,0x67b8ba5b4000) [759.439] 00000.00000> userboot: userboot code 0x3000 @ [0x67b8ba5b4000,0x67b8ba5bf000) [759.439] 00000.00000> userboot: vdso/full rodata 0 @ [0x67b8ba5bf000,0x67b8ba5c6000) [759.439] 00000.00000> userboot: vdso/full code 0x7000 @ [0x67b8ba5c6000,0x67b8ba5c7000) [759.439] 00000.00000> userboot: entry point @ 0x67b8ba5b4c90 [759.439] 01036.01043> userboot: option "zircon.autorun.system=/boot/bin/sh+/boot/infra/runcmds" [759.469] 01036.01043> userboot: searching bootfs for 'bin/bootsvc' [759.469] 01036.01043> userboot: 'bin/bootsvc' has PT_INTERP "lib/ld.so.1" [759.469] 01036.01043> userboot: searching bootfs for 'lib/ld.so.1' [759.469] 01036.01043> userboot: userboot: loaded lib/ld.so.1 at 0x6fdd938e0000, entry point 0x6fdd938fe3d0 [759.469] 01036.01043> userboot: userboot: loaded vDSO at 0x54ff8b5c0000, entry point 0x54ff8b5c78fa [759.469] 01036.01043> userboot: process bin/bootsvc started. [759.469] 01036.01043> userboot: waiting for loader-service requests... [759.470] 01036.01043> userboot: searching bootfs for 'lib/libasync-default.so' [759.470] 01036.01043> userboot: searching bootfs for 'lib/libfdio.so' [759.470] 01036.01043> userboot: searching bootfs for 'lib/libtrace-engine.so' [759.470] 01036.01043> userboot: searching bootfs for 'lib/liblaunchpad.so' [759.470] 01050.01053> dso: id=367d3374904876b8f143f2ed5e4dfb0248fef748 base=0x000034747c2ad000 name=<application> [759.470] 01050.01053> dso: id=71712e0a455898a51e34d40a4013786ab1fa5335 base=0x000054ff8b5c0000 name=<vDSO> [759.470] 01050.01053> dso: id=8c511b4202cf569c8fdde14ca97222102ba3a9e0 base=0x000065bc5496f000 name=libasync-default.so [759.470] 01050.01053> dso: id=3efa72b2e3bd2e4271f835d34a81d9719d6e08a7 base=0x00004d5b75bbe000 name=libfdio.so [759.470] 01050.01053> dso: id=95bc229c3cf2ab8a51f12c33a311105ff8976120 base=0x000079fc1bc23000 name=libtrace-engine.so [759.470] 01050.01053> dso: id=5b0854856213eae6bab93c982f39551f8f9591c5 base=0x000065f0dc605000 name=liblaunchpad.so [759.470] 01050.01053> dso: id=5d417db61b3a48a58a8fa1ffbfc2e71b830e0857 base=0x00006fdd938e0000 name=libc.so [759.470] 01050.01053> bootsvc: Starting... [759.470] 01036.01043> userboot: loader-service channel peer closed [759.470] 01036.01043> userboot: finished! [759.470] 01050.01053> bootsvc: Creating bootfs service... [759.471] 01050.01053> bootsvc: Retrieving boot image... [759.471] 01050.01053> bootsvc: Decommitted BOOTDATA VMO from 0 to 0xc1e000 [759.471] 01050.01053> bootsvc: Loading boot arguments... [759.471] 01050.01053> bootsvc: Creating svcfs service... [759.471] 01050.01053> bootsvc: Loading kernel VMOs... [759.471] 01050.01053> bootsvc: Creating loader service... [759.471] 01050.01053> bootsvc: Launching next process... [759.471] 01050.01108> bootsvc: Launched bin/devcoordinator [759.472] 01115.01130> devcoordinator: launch /boot/bin/svchost (svchost) OK [759.473] 01115.01130> devcoordinator: launch /boot/bin/fshost (fshost) OK [759.475] 01115.01321> devcoordinator: launch /boot/bin/pwrbtn-monitor (pwrbtn-monitor) OK [759.475] 01115.01345> devcoordinator: launch /boot/bin/netsvc (netsvc) OK [759.476] 01115.01345> devcoordinator: launch /boot/bin/virtual-console (virtual-console) OK [759.479] 01115.01130> devcoordinator: full system required, ignoring fallback drivers until /system is loaded [759.479] 01115.01130> devcoordinator: launch devhost 'devhost:sys': pid=2187 [759.479] 01115.01130> devcoordinator: launch devhost 'devhost:test': pid=2219 [759.480] 01115.01130> devcoordinator: launch devhost 'devhost:root': pid=2257 [759.480] 01115.01130> devcoordinator: launch devhost 'devhost:misc': pid=2325 [759.481] 02187.02201> devhost: trace provider registry begun [759.481] 02219.02241> devhost: trace provider registry begun [759.482] 02257.02281> devhost: trace provider registry begun [759.482] 02325.02353> devhost: trace provider registry begun [759.483] 01115.01333> devcoordinator: launch /boot/bin/sh (sh:console) OK [759.567] 02187.02201> acpi-bus: not using IOMMU [759.575] 02187.02201> PMU: 7 arch events [759.575] 02187.02201> PMU: arch event id range: 1-7 [759.575] 02187.02201> PMU: 102 arch events [759.575] 02187.02201> PMU: arch event id range: 1-241 [759.575] 02187.02201> Intel Processor Trace configuration for this chipset: [759.575] 02187.02201> mtc_freq_mask: 0x249 [759.575] 02187.02201> cyc_thresh_mask: 0x3fff [759.575] 02187.02201> psb_freq_mask: 0x3f [759.575] 02187.02201> num addr ranges: 2 [759.575] 02187.02201> [sysmem_init 28] async_get_default_dispatcher(): 0x5a2ead427a90 [759.575] 02187.02201> [sysmem_bind 40] sysmem_bind() [759.575] 02187.02876> acpi-pwrbtn: initialized [759.575] 01705.01733> vc: new input device /dev/class/input/000 [759.584] 02187.02876> WARNING: ACPI found bad _CRS address entry [759.594] 02187.02876> WARNING: ACPI found bad _CRS address entry [759.606] 02187.02876> acpi: published device pci(0x5a2ded43bbf0), parent=sys(0x5a2f2d424610), handle=0x5a2dad43ea10 [759.607] 01115.01130> devcoordinator: launch devhost 'devhost:pci#1:8086:5916': pid=2972 [759.607] 01115.01130> devcoordinator: launch devhost 'devhost:pci#3:8086:9d2f': pid=3025 [759.607] 01115.01130> devcoordinator: launch devhost 'devhost:pci#5:8086:9d60': pid=3097 [759.608] 02972.02986> devhost: trace provider registry begun [759.608] 01115.01130> devcoordinator: launch devhost 'devhost:pci#6:8086:9d61': pid=3192 [759.609] 03097.03120> devhost: trace provider registry begun [759.609] 01115.01130> devcoordinator: launch devhost 'devhost:pci#9:8086:9d03': pid=3286 [759.610] 02187.02876> acpi: published device rtc(0x5a2ded43c010), parent=acpi(0x5a2f2d425110), handle=0x5a2dad466b50 [759.610] 03192.03217> devhost: trace provider registry begun [759.611] 03025.03048> devhost: trace provider registry begun [759.611] 01115.01130> devcoordinator: launch devhost 'devhost:pci#14:8086:9d71': pid=3477 [759.612] 03286.03329> devhost: trace provider registry begun [759.612] 01115.01130> devcoordinator: launch devhost 'devhost:pci#16:8086:156f': pid=3572 [759.612] 02187.02876> acpi-ec: initialized [759.613] 03477.03502> devhost: trace provider registry begun [759.614] 03286.03329> ahci: using MSI interrupt [759.615] 03097.03120> initialized intel serialio i2c driver, reg=0x457d5d7b6000 regsize=4096 [759.615] 03192.03217> initialized intel serialio i2c driver, reg=0x425f42dd2000 regsize=4096 [759.615] 03572.03604> devhost: trace provider registry begun [759.615] 02187.02876> acpi: failed to create NHLT VMO (res -10) [759.615] 02187.02876> acpi: failed to publish NHLT metadata [759.624] 03025.03896> * found USB device (0x18d1:0xa002, USB 2.0) config 1 [759.624] 03025.03896> * found USB device (0x18d1:0xa003, USB 3.0) config 1 [759.625] 03477.03502> [IHDA DSP 00:1f.3] Failed to fetch NHLT (res -25) [759.625] 03477.03502> [IHDA Controller 00:1f.3] Failed to initialize DSP device (res = -25) [759.697] 01622.01648> netifc: ? /dev/class/ethernet/000 [759.697] 01622.01648> netifc: create 512 eth buffers [759.697] 01622.01648> macaddr: d4:5d:df:1a:42:46 [759.697] 01622.01648> ip6addr: fe80::d65d:df4d:fe1a:4246 [759.697] 01622.01648> snmaddr: ff02::1:ff1a:4246 [759.697] 01622.01648> netsvc: using /dev/class/ethernet/000 [759.697] 01622.01648> netsvc: nodename='ocean-drank-wick-spot' [759.697] 01622.01648> netsvc: start [759.723] 01705.01733> vc: new display device /dev/class/display-controller/000 [759.764] 02972.04240> i915: Found DP monitor [759.764] 02972.04240> i915: Display 1 connected [759.764] 02972.04240> i915: MST not supported [760.336] 03025.03896> * found USB device (0x0781:0x5583, USB 3.0) config 1 [760.831] 01705.01733> vc: Successfully attached to display 1 [761.089] 03025.03896> * found USB device (0x046d:0xc31c, USB 1.10) config 1 [761.337] 03025.03896> * found USB device (0x0cf3:0xe300, USB 2.1) config 1 [761.623] 03192.03217> intel-i2c-controller: intel_serialio_i2c_slave_transfer: -21 [761.623] 03192.03217> i2c-hid: could not read HID descriptor: 0 [761.623] 03192.03217> devhost[00:15.1/i2c-bus-9d61/004c] bind driver '/boot/driver/i2c-hid.so' failed: -2 [761.624] 03097.03120> intel-i2c-controller: intel_serialio_i2c_slave_transfer: -21 [761.624] 03097.03120> i2c-hid: could not read HID descriptor: 0 [761.624] 03097.03120> devhost[00:15.0/i2c-bus-9d60/0020] bind driver '/boot/driver/i2c-hid.so' failed: -2 [761.626] 01115.01130> devcoordinator: rpc: bind-driver '004c' status -2 [761.626] 01115.01130> devcoordinator: rpc: bind-driver '0020' status -2 [761.630] 03286.03816> sata2: dev info [761.630] 03286.03816> serial=711430952084 9 [761.630] 03286.03816> firmware rev=1Q01A7 0 [761.630] 03286.03816> model id=IBIW NSS D [761.630] 03286.03816> major=0x3f0 ACS2 DMA 32 commands [761.630] 03286.03816> LBA48 234441648 sectors, sector size=512 [761.631] 01299.01313> fshost: /dev/class/block/000: GPT? [761.631] 03286.03329> gpt: device_get_metadata failed (-25) [761.632] 01299.01313> fshost: /dev/class/block/001: FVM? [761.635] 01299.01313> devcoordinator: launch /boot/bin/blobfs (blobfs:/blob) OK [761.780] 01299.01313> fshost: starting 'bin/pkgsvr' 'd2e434555923a7fdbe89177bdd848aa88198d9cb4819fc7671f96d561ae359c2'... [761.787] 01299.01313> devcoordinator: launch bin/pkgsvr (pkgfs) OK [761.798] 04674.04888> pkgsvr: system: will be served from d2e434555923a7fdbe89177bdd848aa88198d9cb4819fc7671f96d561ae359c2 [761.798] 04674.04888> pkgsvr: pkgfs serving index /data/pkgfs_index from blobfs /blob [761.805] 01299.01313> fshost: /dev/class/block/005: zxcrypt? [761.805] 03286.03329> devhost_get_handles(0x5ba166b19c10:block) open path='zxcrypt', r=-2 [761.814] 01299.01313> fshost: mounting minfs [761.817] 01299.01313> devcoordinator: launch /boot/bin/minfs (minfs:/data) OK [761.876] 01115.04928> devcoordinator: adding system driver 'wlan' '/system/driver/wlan.so' [761.880] 01115.01754> devcoordinator: launch /system/bin/appmgr (appmgr) OK [761.880] 01115.01754> autorun: starting '/boot/bin/sh' '/boot/infra/runcmds'... [761.900] 01115.04928> devcoordinator: adding system driver 'mt8167s_gpu' '/system/driver/libmsd_img_rgx_mtk.so' [761.905] 01115.01754> devcoordinator: launch /boot/bin/sh (autorun:system) OK [761.934] 01115.04928> devcoordinator: adding system driver 'bt_host' '/system/driver/bt-host.so' [761.957] 01115.04928> devcoordinator: adding system driver 'qmi_usb' '/system/driver/qmi-transport.so' [761.970] 01115.04928> devcoordinator: adding system driver 'wlan' '/system/driver/wlanif.so' [761.996] 01115.04928> devcoordinator: adding system driver 'bt_hci_atheros' '/system/driver/bt-hci-atheros.so' [762.053] 01115.04928> devcoordinator: adding system driver 'ralink' '/system/driver/ralink.so' [762.055] 01115.04928> devcoordinator: adding system driver 'bt_hci_passthrough' '/system/driver/bt-hci-passthrough.so' [762.058] 01115.04928> devcoordinator: adding system driver 'iwlwifi_pci' '/system/driver/iwlwifi.so' [762.072] 01115.04928> devcoordinator: adding system driver 'magma_pdev_gpu' '/system/driver/libmsd_arm.so' [762.084] 01115.04928> devcoordinator: adding system driver 'usb_video' '/system/driver/usb_video.so' [762.096] 01115.04928> devcoordinator: adding system driver 'wlan' '/system/driver/wlanphy.so' [762.104] 01115.04928> devcoordinator: adding system driver 'brcmfmac' '/system/driver/brcmfmac.so' [762.130] 01115.04928> devcoordinator: adding system driver 'bt_hci_intel' '/system/driver/bt-hci-intel.so' [762.139] 01115.04928> devcoordinator: adding system driver 'gpu' '/system/driver/libmsd_intel.so' [762.152] 05227.05247> [INFO:namespace_builder.cc(93)] config-data for sysmgr [762.165] 01115.04928> devcoordinator: adding system driver 'virtual_camera' '/system/driver/virtual_camera_driver.so' [762.180] 01115.04928> devcoordinator: adding system driver 'bt_hci_fake' '/system/driver/bt-hci-fake.so' [762.194] 01115.04928> devcoordinator: adding system driver 'rtl88xx' '/system/driver/rtl88xx.so' [762.199] 01115.04928> devcoordinator: adding system driver 'ath10k_pci' '/system/driver/ath10k.so' [762.202] 01115.04928> devcoordinator: adding system driver 'bt_hog' '/system/driver/bt-hog.so' [762.207] 01115.04928> devcoordinator: adding system driver 'qmi_fake' '/system/driver/qmi-fake.so' [762.215] 01115.04928> devcoordinator: adding system driver 'virtual_audio' '/system/driver/virtual_audio_driver.so' [762.215] 01115.01130> devcoordinator: driver 'qmi_fake' added [762.215] 01115.01130> devcoordinator: driver 'bt_hog' added [762.215] 01115.01130> devcoordinator: driver 'ath10k_pci' added [762.219] 01115.01130> devcoordinator: launch devhost 'devhost:pci#11:168c:003e': pid=6063 [762.219] 01115.01130> devcoordinator: driver 'rtl88xx' added [762.219] 01115.01130> devcoordinator: driver 'bt_hci_fake' added [762.219] 01115.01130> devcoordinator: driver 'gpu' added [762.219] 01115.01130> devcoordinator: driver 'bt_hci_intel' added [762.219] 01115.01130> devcoordinator: driver 'brcmfmac' added [762.219] 01115.01130> devcoordinator: driver 'wlan' added [762.219] 01115.01130> devcoordinator: driver 'usb_video' added [762.219] 01115.01130> devcoordinator: driver 'magma_pdev_gpu' added [762.219] 01115.01130> devcoordinator: driver 'iwlwifi_pci' added [762.219] 01115.01130> devcoordinator: driver 'ralink' added [762.219] 01115.01130> devcoordinator: driver 'bt_hci_atheros' added [762.219] 01115.01130> devcoordinator: driver 'wlan' added [762.219] 01115.01130> devcoordinator: driver 'qmi_usb' added [762.219] 01115.01130> devcoordinator: driver 'bt_host' added [762.219] 01115.01130> devcoordinator: driver 'mt8167s_gpu' added [762.219] 01115.01130> devcoordinator: driver 'wlan' added [762.219] 01115.01130> devcoordinator: driver 'bt_hci_passthrough' added [762.219] 01115.01130> devcoordinator: fallback driver 'usb_composite' is available [762.219] 01115.01130> devcoordinator: driver 'usb_composite' added [762.219] 01115.01130> devcoordinator: fallback driver 'intel_disp' is available [762.219] 01115.01130> devcoordinator: driver 'intel_disp' added [762.222] 03025.03048> UMS: parent: 'ifc-000' [762.226] 03025.03048> UMS:Max lun is: 0 [762.228] 06063.06081> devhost: trace provider registry begun [762.229] 06063.06081> ath10k: Probed chip QCA6174 ver: 2.1 [762.229] 03025.06351> UMS: block size is: 0x00000200 [762.229] 03025.06351> UMS: total blocks is: 30031250 [762.229] 03025.06351> UMS: total size is: 15376000000 [762.229] 03025.06351> UMS: read-only: 0 removable: 1 [762.240] 03025.03048> devhost[00:14.0/xhci/usb-bus/003/003/ifc-001] bind driver '/boot/driver/bt-transport-usb.so' failed: -2 [762.243] 01115.01130> devcoordinator: rpc: bind-driver 'ifc-001' status -2 [762.293] 03025.10094> btatheros: Making visible [762.293] 03025.10094> btatheros: loaded successfully [762.294] 03025.10166> [INFO:command_channel.cc(149)] hci: initialized [762.295] 01299.01313> fshost: /dev/class/block/007: MBR? [762.297] 01299.01313> fshost: /dev/class/block/009: MBR? [762.344] 05227.05247> [INFO:namespace_builder.cc(93)] config-data for amber [762.358] 03025.10166> [WARN:adapter.cc(274)] gap: controller is using legacy HCI version 4.1 [762.366] 03025.10166> [INFO:acl_data_channel.cc(91)] hci: initialized [762.464] 05227.05247> [INFO:namespace_builder.cc(93)] config-data for pkg_resolver [762.474] 01705.01733> vc: new input device /dev/class/input/001 [762.487] 01705.01733> vc: new input device /dev/class/input/002 [762.606] 13670.13682> [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 [762.606] 13670.13682> kfill_days=2, start_event_aggregator_worker=1. [762.622] 06063.13301> devhost: rpc:load-firmware failed: -25 [762.622] 06063.13301> devhost: rpc:load-firmware failed: -25 [762.671] 05227.05247> [INFO:namespace_builder.cc(93)] config-data for mdns [762.751] 05227.05247> [INFO:namespace_builder.cc(93)] config-data for wlancfg [762.931] 05227.05247> [INFO:namespace_builder.cc(93)] config-data for crashpad_agent [762.961] 16763.16777> [INFO:main.cc(35)] Trace Manager starting with config: /pkg/data/tracing.config [762.992] 15916.15928> [INFO:system_metrics_main.cc(23)] Cobalt SystemMetricsDaemon: System metrics daemon created. [763.049] 17202.17214> wlanstack2 [I]: Starting [763.325] 06063.12681> ath10k: Unknown eventid: 0x1d019 [763.328] 06063.12681> ath10k: Unknown eventid: 0x16006 [763.333] 06063.06081> wlanphy: event loop started [763.333] 06063.06081> wlanphy_bind [763.333] 17202.17214> wlanstack2::device [I]: new phy #0: /dev/sys/pci/01:00.0/ath10k-wlanphy/wlanphy [763.334] 14843.14855> wlancfg got event: OnPhyAdded { phy_id: 0 } [763.334] 14843.14855> wlancfg: phy 0 added [763.334] 17202.17214> wlanstack2::service [I]: query_phy(id = 0) [763.334] 17202.17214> wlanstack2::service [I]: query_phy(id = 0): received a 'QueryResult' from device [763.335] 14843.14855> wlancfg: received a PhyInfo from phy #0: path is /dev/sys/pci/01:00.0/ath10k-wlanphy/wlanphy [763.335] 14843.14855> using default wlan config entry for phy [763.335] 14843.14855> wlancfg: Creating Client iface for phy 0 [763.340] 06063.06081> wlan_bind [763.342] 06063.06081> ath10k: adding a station interface (vdev_id=0) ... [763.344] 06063.06081> wlan: [I] Initialize a client MLME. [763.344] 06063.18160> wlan: [I] starting MainLoop [763.345] 06063.06081> wlan: [I] channel opened [763.346] 17202.17214> wlanstack2::device [I]: new iface #0 with role 'Client': /dev/sys/pci/01:00.0/ath10k-wlanphy/ath10k-wlanmac/wlan [763.346] 14843.14855> wlancfg got event: OnIfaceAdded { iface_id: 0 } [763.346] 14843.14855> wlancfg: new iface 0 added successfully [763.347] 14843.14855> wlancfg: Starting auto-connect loop with 0 saved networks [763.997] 14381.14393> Starting mDNS on interface ethp001f6 [80fe::5dd6:ffdf:1afe:4642] [763.997] 14381.14393> [WARNING:garnet/bin/mdns/service/mdns_interface_transceiver_v6.cc(29)] NET-291 IPV6_MULTICAST_LOOP not supported (ENOPROTOOPT), continuing anyway [763.997] 14381.14393> [WARNING:garnet/bin/mdns/service/mdns_interface_transceiver_v6.cc(50)] NET-2180 IPV6_JOIN_GROUP returned ENODEV, mDNS will not communicate via IPV6 [767.422] 14381.14393> Starting mDNS on interface ethp001f6 192.168.42.101 [767.422] 14381.14393> [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 [767.422] 14381.14393> Starting mDNS on interface ethp001f6 [80fe::5dd6:ffdf:1afe:4642] [767.422] 14381.14393> [WARNING:garnet/bin/mdns/service/mdns_interface_transceiver_v6.cc(29)] NET-291 IPV6_MULTICAST_LOOP not supported (ENOPROTOOPT), continuing anyway [767.422] 14381.14393> [WARNING:garnet/bin/mdns/service/mdns_interface_transceiver_v6.cc(50)] NET-2180 IPV6_JOIN_GROUP returned ENODEV, mDNS will not communicate via IPV6 [767.422] 14381.14393> mDNS: Verifying uniqueness of host name ocean-drank-wick-spot.local. [768.184] 14381.14393> mDNS: Using unique host name ocean-drank-wick-spot.local. Running tests sequentially. [tb] 2019-04-20 00:48:45.213 INFO [SshConnection | 192.168.42.101] Starting master ssh connection. [connection.py:setup_master_ssh:141] [815.651] 23446.23458> setsockopt IP_TOS 32: Protocol not available: [tb] 2019-04-20 00:48:45.453 INFO [SshConnection | 192.168.42.101] Starting master ssh connection. [connection.py:setup_master_ssh:141] [815.883] 24021.24035> setsockopt IP_TOS 32: Protocol not available: [tb] 2019-04-20 00:48:46.699 INFO [SshConnection | 192.168.42.101] Starting master ssh connection. [connection.py:setup_master_ssh:141] [817.126] 25070.25083> setsockopt IP_TOS 32: Protocol not available: [tb] 2019-04-20 00:48:46.952 INFO Controller FuchsiaDevice: [{'ip': '192.168.42.101'}] [base_test.py:register_controller:396] [tb] 2019-04-20 00:48:46.957 INFO ==========> Sl4fSanityTest <========== [base_test.py:run:967] [tb] 2019-04-20 00:48:46.959 INFO Congratulations! Fuchsia controllers have been initialized successfully! [Sl4fSanityTest.py:setup_class:41] [tb] 2019-04-20 00:48:46.962 INFO [Test Case] test_example [base_test.py:exec_one_testcase:662] [tb] 2019-04-20 00:48:46.964 INFO Congratulations! You've run your first test. [Sl4fSanityTest.py:test_example:46] [tb] 2019-04-20 00:48:46.968 INFO [Test Case] test_example PASS [base_test.py:_on_pass:542] [tb] 2019-04-20 00:48:46.972 INFO Summary for test class Sl4fSanityTest: ControllerInfo {'FuchsiaDevice': [{'ip': '192.168.42.101'}]}, 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:48:46.980 INFO [SshConnection | 192.168.42.101] Starting master ssh connection. [connection.py:setup_master_ssh:141] [817.404] 25625.25638> setsockopt IP_TOS 32: Protocol not available: [tb] 2019-04-20 00:48:47.222 INFO [SshConnection | 192.168.42.101] Starting master ssh connection. [connection.py:setup_master_ssh:141] [817.650] 26209.26224> setsockopt IP_TOS 32: Protocol not available: [tb] 2019-04-20 00:48:48.468 INFO [SshConnection | 192.168.42.101] Starting master ssh connection. [connection.py:setup_master_ssh:141] [818.897] 27257.27272> setsockopt IP_TOS 32: Protocol not available: [tb] 2019-04-20 00:48:48.717 INFO Controller FuchsiaDevice: [{'ip': '192.168.42.101'}] [base_test.py:register_controller:396] [tb] 2019-04-20 00:48:48.721 INFO ==========> WlanScanTest <========== [base_test.py:run:967] [tb] 2019-04-20 00:48:48.723 INFO [Test Case] test_basic_scan_request [base_test.py:exec_one_testcase:662] [819.045] 06063.18160> ath10k: starting a hardware scan [tb] 2019-04-20 00:48:54.240 INFO scan contained 57 results [WlanScanTest.py:test_basic_scan_request:86] [tb] 2019-04-20 00:48:54.243 INFO scan time: 5517 ms [WlanScanTest.py:test_basic_scan_request:89] [tb] 2019-04-20 00:48:54.258 INFO [Test Case] test_basic_scan_request PASS [base_test.py:_on_pass:542] [tb] 2019-04-20 00:48:54.260 INFO [Test Case] test_scan_while_connected_open_network [base_test.py:exec_one_testcase:662] [tb] 2019-04-20 00:48:54.262 INFO got the ssid! GoogleGuest [WlanScanTest.py:test_scan_while_connected_open_network:101] [824.585] 06063.18160> ath10k: starting a hardware scan [830.084] 06063.18160> ath10k: setting channel (pri: 40, sec: 0, bw: CBW40BELOW) [830.084] 06063.18160> ath10k: basic setting: phymode 11na-ht40 center_freq=5190 [tb] 2019-04-20 00:48:59.873 INFO connection to network successful [WlanScanTest.py:check_connect_response:58] [830.133] 06063.18160> ath10k: configuring BSS [830.133] 06063.18160> ath10k: basic setting: phymode 11na-ht40 center_freq=5190 [830.184] 06063.18160> ath10k: as a client, configuring an association with an AP [04:BD:88:3F:60:31] [830.184] 06063.18160> ath10k: mac peer 04:BD:88:3F:60:31 phymode 11ac-vht40 [830.185] 06063.18160> ath10k: setting peer smps mode to none [830.185] 06063.18160> ath10k: successfully associated with bssid 04:BD:88:3F:60:31 [830.186] 06063.18160> wlan: [I] NIC 00:0e:8e:8b:40:ec associated with "GoogleGuest"(04:bd:88:3f:60:31) in channel 40 CBW40B, 5 GHz, 802.11ac VHT [830.187] 14381.14393> Starting mDNS on interface ethp001f6 [80fe::5dd6:ffdf:1afe:4642] [830.188] 14381.14393> [WARNING:garnet/bin/mdns/service/mdns_interface_transceiver_v6.cc(29)] NET-291 IPV6_MULTICAST_LOOP not supported (ENOPROTOOPT), continuing anyway [830.188] 14381.14393> [WARNING:garnet/bin/mdns/service/mdns_interface_transceiver_v6.cc(50)] NET-2180 IPV6_JOIN_GROUP returned ENODEV, mDNS will not communicate via IPV6 [830.188] 14381.14393> Starting mDNS on interface wlanp01 [80fe::e02:ff8e:8bfe:ec40] [830.190] 14381.14393> [WARNING:garnet/bin/mdns/service/mdns_interface_transceiver_v6.cc(29)] NET-291 IPV6_MULTICAST_LOOP not supported (ENOPROTOOPT), continuing anyway [830.191] 14381.14393> [WARNING:garnet/bin/mdns/service/mdns_interface_transceiver_v6.cc(50)] NET-2180 IPV6_JOIN_GROUP returned ENODEV, mDNS will not communicate via IPV6 [830.196] 06063.18160> ath10k: starting a hardware scan [831.435] 14381.14393> Starting mDNS on interface ethp001f6 [80fe::5dd6:ffdf:1afe:4642] [831.435] 14381.14393> [WARNING:garnet/bin/mdns/service/mdns_interface_transceiver_v6.cc(29)] NET-291 IPV6_MULTICAST_LOOP not supported (ENOPROTOOPT), continuing anyway [831.435] 14381.14393> [WARNING:garnet/bin/mdns/service/mdns_interface_transceiver_v6.cc(50)] NET-2180 IPV6_JOIN_GROUP returned ENODEV, mDNS will not communicate via IPV6 [831.435] 14381.14393> Starting mDNS on interface wlanp01 100.110.68.14 [831.436] 14381.14393> [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 [831.436] 14381.14393> Starting mDNS on interface wlanp01 [80fe::e02:ff8e:8bfe:ec40] [831.436] 14381.14393> [WARNING:garnet/bin/mdns/service/mdns_interface_transceiver_v6.cc(29)] NET-291 IPV6_MULTICAST_LOOP not supported (ENOPROTOOPT), continuing anyway [831.436] 14381.14393> [WARNING:garnet/bin/mdns/service/mdns_interface_transceiver_v6.cc(50)] NET-2180 IPV6_JOIN_GROUP returned ENODEV, mDNS will not communicate via IPV6 [tb] 2019-04-20 00:49:09.500 INFO scan contained 55 results [WlanScanTest.py:test_basic_scan_request:86] [tb] 2019-04-20 00:49:09.503 INFO scan time: 9626 ms [WlanScanTest.py:test_basic_scan_request:89] [tb] 2019-04-20 00:49:09.520 INFO [Test Case] test_scan_while_connected_open_network PASS [base_test.py:_on_pass:542] [tb] 2019-04-20 00:49:09.522 INFO [Test Case] test_scan_while_connected_wpa2_network [base_test.py:exec_one_testcase:662] [tb] 2019-04-20 00:49:09.524 INFO got the ssid! acts hotspot [WlanScanTest.py:test_scan_while_connected_wpa2_network:114] [839.831] 06063.18160> wlan: [I] deauthenticating from "GoogleGuest" (04:bd:88:3f:60:31), reason=36 [839.831] 06063.18160> ath10k: as a client, clearing the association with an AP [04:BD:88:3F:60:31] [839.831] 17202.17214> wlan_sme::client::state [W]: Unexpected MLME message while Idle: DeauthenticateConf { resp: DeauthenticateConfirm { peer_sta_address: [4, 189, 136, 63, 96, 49] } } [839.831] 14381.14393> Starting mDNS on interface ethp001f6 [80fe::5dd6:ffdf:1afe:4642] [839.832] 14381.14393> [WARNING:garnet/bin/mdns/service/mdns_interface_transceiver_v6.cc(29)] NET-291 IPV6_MULTICAST_LOOP not supported (ENOPROTOOPT), continuing anyway [839.832] 14381.14393> [WARNING:garnet/bin/mdns/service/mdns_interface_transceiver_v6.cc(50)] NET-2180 IPV6_JOIN_GROUP returned ENODEV, mDNS will not communicate via IPV6 [839.846] 06063.18160> ath10k: starting a hardware scan [847.630] 17202.17214> wlan_rsn::rsna::esssa [I]: spawned ESSSA for: Supplicant [847.630] 06063.18160> ath10k: setting channel (pri: 3, sec: 0, bw: CBW20) [847.630] 06063.18160> ath10k: basic setting: phymode 11ng-ht20 center_freq=2422 [847.685] 06063.18160> ath10k: configuring BSS [847.685] 06063.18160> ath10k: basic setting: phymode 11ng-ht20 center_freq=2422 [tb] 2019-04-20 00:49:17.474 INFO connection to network successful [WlanScanTest.py:check_connect_response:58] [847.756] 06063.18160> ath10k: as a client, configuring an association with an AP [40:4E:36:D1:DC:10] [847.756] 06063.18160> ath10k: mac peer 40:4E:36:D1:DC:10 phymode 11b [847.756] 06063.18160> ath10k: successfully associated with bssid 40:4E:36:D1:DC:10 [847.756] 17202.17214> wlan_rsn::rsna::esssa [I]: resetting ESSSA [847.756] 17202.17214> wlan_rsn::rsna::esssa [I]: establishing ESSSA... [847.756] 17202.17214> wlan_rsn::rsna::esssa [I]: established PMKSA [847.757] 06063.18160> wlan: [I] NIC 00:0e:8e:8b:40:ec associated with "acts hotspot"(40:4e:36:d1:dc:10) in channel 3 CBW20, 2 GHz, 802.11n HT [847.773] 17202.17214> wlan_rsn::rsna::esssa [I]: established PTKSA [847.784] 17202.17214> wlan_rsn::rsna::esssa [I]: established GTKSA [847.784] 17202.17214> wlan_rsn::rsna::esssa [I]: established ESSSA [847.785] 06063.18160> ath10k: attempting to set key (bssid: 0, prot: rx/tx, cipher: CCMP128, type: pairwise, len: 16, addr: 40:4e:36:d1:dc:10 key_idx: 0) [847.785] 06063.18160> ath10k: attempting to set key (bssid: 0, prot: rx/tx, cipher: CCMP128, type: group, len: 16, addr: ff:ff:ff:ff:ff:ff key_idx: 2) [847.785] 14381.14393> Starting mDNS on interface ethp001f6 [80fe::5dd6:ffdf:1afe:4642] [847.786] 14381.14393> [WARNING:garnet/bin/mdns/service/mdns_interface_transceiver_v6.cc(29)] NET-291 IPV6_MULTICAST_LOOP not supported (ENOPROTOOPT), continuing anyway [847.786] 14381.14393> [WARNING:garnet/bin/mdns/service/mdns_interface_transceiver_v6.cc(50)] NET-2180 IPV6_JOIN_GROUP returned ENODEV, mDNS will not communicate via IPV6 [847.787] 14381.14393> Starting mDNS on interface wlanp01 [80fe::e02:ff8e:8bfe:ec40] [847.787] 14381.14393> [WARNING:garnet/bin/mdns/service/mdns_interface_transceiver_v6.cc(29)] NET-291 IPV6_MULTICAST_LOOP not supported (ENOPROTOOPT), continuing anyway [847.787] 14381.14393> [WARNING:garnet/bin/mdns/service/mdns_interface_transceiver_v6.cc(50)] NET-2180 IPV6_JOIN_GROUP returned ENODEV, mDNS will not communicate via IPV6 [847.796] 06063.18160> ath10k: starting a hardware scan [855.978] 14381.14393> Starting mDNS on interface ethp001f6 [80fe::5dd6:ffdf:1afe:4642] [855.979] 14381.14393> [WARNING:garnet/bin/mdns/service/mdns_interface_transceiver_v6.cc(29)] NET-291 IPV6_MULTICAST_LOOP not supported (ENOPROTOOPT), continuing anyway [855.979] 14381.14393> [WARNING:garnet/bin/mdns/service/mdns_interface_transceiver_v6.cc(50)] NET-2180 IPV6_JOIN_GROUP returned ENODEV, mDNS will not communicate via IPV6 [855.979] 14381.14393> Starting mDNS on interface wlanp01 192.168.43.147 [855.980] 14381.14393> [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 [855.980] 14381.14393> Starting mDNS on interface wlanp01 [80fe::e02:ff8e:8bfe:ec40] [855.980] 14381.14393> [WARNING:garnet/bin/mdns/service/mdns_interface_transceiver_v6.cc(29)] NET-291 IPV6_MULTICAST_LOOP not supported (ENOPROTOOPT), continuing anyway [855.980] 14381.14393> [WARNING:garnet/bin/mdns/service/mdns_interface_transceiver_v6.cc(50)] NET-2180 IPV6_JOIN_GROUP returned ENODEV, mDNS will not communicate via IPV6 [tb] 2019-04-20 00:49:27.178 INFO scan contained 59 results [WlanScanTest.py:test_basic_scan_request:86] [tb] 2019-04-20 00:49:27.180 INFO scan time: 9704 ms [WlanScanTest.py:test_basic_scan_request:89] [tb] 2019-04-20 00:49:27.193 INFO [Test Case] test_scan_while_connected_wpa2_network PASS [base_test.py:_on_pass:542] [857.505] 06063.18160> wlan: [I] deauthenticating from "acts hotspot" (40:4e:36:d1:dc:10), reason=36 [857.505] 06063.18160> ath10k: as a client, clearing the association with an AP [40:4E:36:D1:DC:10] [857.506] 17202.17214> wlan_sme::client::state [W]: Unexpected MLME message while Idle: DeauthenticateConf { resp: DeauthenticateConfirm { peer_sta_address: [64, 78, 54, 209, 220, 16] } } [857.506] 14381.14393> Starting mDNS on interface ethp001f6 [80fe::5dd6:ffdf:1afe:4642] [857.507] 14381.14393> [WARNING:garnet/bin/mdns/service/mdns_interface_transceiver_v6.cc(29)] NET-291 IPV6_MULTICAST_LOOP not supported (ENOPROTOOPT), continuing anyway [857.507] 14381.14393> [WARNING:garnet/bin/mdns/service/mdns_interface_transceiver_v6.cc(50)] NET-2180 IPV6_JOIN_GROUP returned ENODEV, mDNS will not communicate via IPV6 [tb] 2019-04-20 00:49:27.197 INFO Summary for test class WlanScanTest: ControllerInfo {'FuchsiaDevice': [{'ip': '192.168.42.101'}]}, 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:49:27.200 INFO Summary for test run tb@2019-04-20_00-48-42-773: ControllerInfo {'FuchsiaDevice': [{'ip': '192.168.42.101'}]}, Requested 4, Executed 4, Passed 4, 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!