DEBUG: config flag: /etc/botanist/config.json DEBUG: executing command: "/etc/connectivity/host_cmds.sh" environment of subprocess: [] 2019/04/26 04:25:36 attempting to send <<netboot>>cmdline... 2019/04/26 04:25:36 done 2019/04/26 04:25:36 attempting to send <<image>>sparse.fvm... 2019/04/26 04:25:38 done 2019/04/26 04:25:38 attempting to send <<image>>bootloader.img... 2019/04/26 04:25:38 target is busy, retrying in one second 2019/04/26 04:25:39 attempting to send <<image>>bootloader.img... 2019/04/26 04:25:39 done 2019/04/26 04:25:39 attempting to send <<image>>zircona.img... 2019/04/26 04:25:39 done 2019/04/26 04:25:39 attempting to send <<image>>zirconr.img... 2019/04/26 04:25:39 target is busy, retrying in one second [00000.000] 00000.00000> zbi: @ 0xffffff80012f2000 (17482848 bytes) [00000.000] 00000.00000> UART: FIFO depth 16 [00000.000] 00000.00000> PMM: boot reserve add [0x100000, 0x2c5fff] [00000.000] 00000.00000> PMM: boot reserve add [0x12f2000, 0x239efff] [00000.000] 00000.00000> PMM: arena too small to be useful (size 4096) [00000.000] 00000.00000> PMM: pmm_add_arena failed to initialize arena [00000.000] 00000.00000> MEM: Failed to add pmm range at 0x7ffff000 size 0x1000 [00000.000] 00000.00000> PMM: boot reserve marking WIRED [0x100000, 0x2c5fff] [00000.000] 00000.00000> PMM: boot reserve marking WIRED [0x12f2000, 0x239efff] [00000.000] 00000.00000> [00000.000] 00000.00000> welcome to Zircon [00000.000] 00000.00000> [00000.000] 00000.00000> KASLR: .text section at 0xffffffff00100000 [00000.000] 00000.00000> INIT: cpu 0, calling hook 0xffffffff001aa428 (global_prng_seed) at level 0x30000, flags 0x1 [00000.000] 00000.00000> initializing vm pre-heap [00000.000] 00000.00000> VM: marking boot alloc used range [0x239f000, 0x239f100) [00000.000] 00000.00000> INIT: cpu 0, calling hook 0xffffffff00147abc (elf_build_id) at level 0x4fffe, flags 0x1 [00000.000] 00000.00000> INIT: cpu 0, calling hook 0xffffffff00147c48 (version) at level 0x4ffff, flags 0x1 [00000.000] 00000.00000> version: [00000.000] 00000.00000> arch: x86 [00000.000] 00000.00000> platform: pc [00000.000] 00000.00000> target: pc [00000.000] 00000.00000> project: x64 [00000.000] 00000.00000> buildid: git-13ee3dc5e4c46bf127977ad28645c47442ec517d [00000.000] 00000.00000> ELF build ID: 5f3e39bd4ed89d3b8122947842f1eac846a04683 [00000.000] 00000.00000> initializing heap [00000.000] 00000.00000> INIT: cpu 0, calling hook 0xffffffff00102e1c (x86_resource_init) at level 0x50000, flags 0x1 [00000.000] 00000.00000> INIT: cpu 0, calling hook 0xffffffff001a9630 (console) at level 0x50000, flags 0x1 [00000.000] 00000.00000> initializing vm [00000.000] 00000.00000> VM: reserving kernel region [0xffffffff00100000, 0xffffffff001ee000) flags 0x28 name 'kernel_code' [00000.000] 00000.00000> VM: reserving kernel region [0xffffffff001ee000, 0xffffffff00232000) flags 0x8 name 'kernel_rodata' [00000.000] 00000.00000> VM: reserving kernel region [0xffffffff00232000, 0xffffffff00242000) flags 0x18 name 'kernel_data' [00000.000] 00000.00000> VM: reserving kernel region [0xffffffff00242000, 0xffffffff002c6000) flags 0x18 name 'kernel_bss' [00000.000] 00000.00000> INIT: cpu 0, calling hook 0xffffffff00103ae0 (display_memtype) at level 0x60001, flags 0x1 [00000.000] 00000.00000> INIT: cpu 0, calling hook 0xffffffff00138fa0 (acpi_tables) at level 0x60001, flags 0x1 [00000.000] 00000.00000> INIT: cpu 0, calling hook 0xffffffff00101c40 (hpet) at level 0x60002, flags 0x1 [00000.000] 00000.00000> INIT: cpu 0, calling hook 0xffffffff00102000 (apic) at level 0x60002, flags 0x1 [00000.000] 00000.00000> x2APIC enabled [00000.000] 00000.00000> INIT: cpu 0, calling hook 0xffffffff001061b4 (timer) at level 0x60003, flags 0x1 [00000.000] 00000.00000> HPET frequency: 23999 ticks/ms [00000.000] 00000.00000> TSC frequency: 2712000 ticks/ms [00018.394] 00000.00000> timer features: constant_tsc 1 invariant_tsc 1 tsc_deadline 1 [00018.394] 00000.00000> Using TSC as wallclock [00018.394] 00000.00000> initializing kernel [00018.394] 00000.00000> initializing mp [00018.394] 00000.00000> initializing timers [00018.394] 00000.00000> INIT: cpu 0, calling hook 0xffffffff0013c578 (debuglog) at level 0x7ffff, flags 0x1 [00018.394] 00000.00000> INIT: cpu 0, calling hook 0xffffffff00195518 (thread_set_priority_experiment) at level 0x7ffff, flags 0x1 [00018.394] 00000.00000> thread set priority experiment is : ENABLED [00018.394] 00000.00000> INIT: cpu 0, calling hook 0xffffffff001aa67c (global_prng_thread_safe) at level 0x7ffff, flags 0x1 [00018.394] 00000.00000> creating bootstrap completion thread [00018.737] 00000.00000> top of bootstrap2() [00018.737] 00000.00000> INIT: cpu 0, calling hook 0xffffffff0013151c (dpc) at level 0x80000, flags 0x1 [00018.751] 00000.00000> INIT: cpu 0, calling hook 0xffffffff00152978 (libobject) at level 0x80000, flags 0x1 [00018.751] 00000.00000> OOM: started thread [00018.764] 00000.00000> Processor Model Info: type 0 family 0x6 model 0xe stepping 0x9 [00018.764] 00000.00000> display_family 0x6 display_model 0x8e [00018.764] 00000.00000> Vendor: Intel [00018.764] 00000.00000> Microarch: Kaby Lake [00018.764] 00000.00000> F/M/S: 6/8e/9 [00018.764] 00000.00000> Brand: Intel(R) Core(TM) i5-7300U CPU @ 2.60GHz [00018.764] 00000.00000> Features: fpu sse sse2 sse3 ssse3 sse4.1 sse4.2 mmx avx avx2 fxsr pcid xsave mon aesni clflush [00018.764] 00000.00000> clflushopt fsgsbase tsc_adj smep smap erms rdrand rdseed syscall nx huge rdtscp [00018.764] 00000.00000> invar_tsc tsc_deadline x2apic vmx pt hwp [00018.764] 00000.00000> initializing platform [00018.764] 00000.00000> INIT: cpu 0, calling hook 0xffffffff001101f4 (x86_perfmon) at level 0x90000, flags 0x1 [00018.764] 00000.00000> PMU: version 4 [00018.764] 00000.00000> UART: started IRQ driven RX [00018.764] 00000.00000> UART: started IRQ driven TX [00018.764] 00000.00000> cpu topology: [00018.764] 00000.00000> 0: apic id 0x0 package 0 node 0 core 0 smt 0 BSP [00018.764] 00000.00000> 1: apic id 0x2 package 0 node 0 core 1 smt 0 [00018.764] 00000.00000> 2: apic id 0x1 package 0 node 0 core 0 smt 1 [00018.764] 00000.00000> 3: apic id 0x3 package 0 node 0 core 1 smt 1 [00018.764] 00000.00000> Found 4 cpus [00018.764] 00000.00000> booting apic ids: 0x2 0x1 0x3 [00018.780] 00000.00000> entering scheduler on cpu 2 [00018.781] 00000.00000> entering scheduler on cpu 3 [00018.781] 00000.00000> entering scheduler on cpu 1 [00018.784] 00000.00000> smbios: manufacturer="Intel Corporation" product="NUC7i5DNHE" [00018.784] 00000.00000> initializing target [00018.784] 00000.00000> INIT: cpu 0, calling hook 0xffffffff001053a0 (x86_pcie_init) at level 0xa0000, flags 0x1 [00018.784] 00000.00000> moving to last init level [00018.784] 00000.00000> INIT: cpu 0, calling hook 0xffffffff00144140 (ktrace) at level 0xc0000, flags 0x1 [00018.788] 00000.00000> ktrace: buffer at 0xffffff944f473000 (33554432 bytes) [00018.788] 00000.00000> INIT: cpu 0, calling hook 0xffffffff00147ab4 (userboot) at level 0xc0000, flags 0x1 [00018.788] 00000.00000> userboot: ramdisk 0x10ad000 @ 0xffffff80012f2000 [00018.788] 00000.00000> userboot: userboot rodata 0 @ [0x39cf3dd42000,0x39cf3dd45000) [00018.788] 00000.00000> userboot: userboot code 0x3000 @ [0x39cf3dd45000,0x39cf3dd50000) [00018.788] 00000.00000> userboot: vdso/full rodata 0 @ [0x39cf3dd50000,0x39cf3dd57000) [00018.788] 00000.00000> userboot: vdso/full code 0x7000 @ [0x39cf3dd57000,0x39cf3dd58000) [00018.788] 00000.00000> userboot: entry point @ 0x39cf3dd45c10 [00018.788] 00000.00000> INIT: cpu 0, calling hook 0xffffffff001aa030 (kernel_shell) at level 0xc0000, flags 0x1 [00018.788] 01036.01043> userboot: option "netsvc.disable=true" [00018.788] 01036.01043> userboot: option "zircon.system.disable-automount=true" [00018.788] 01036.01043> userboot: option "zircon.autorun.boot=/boot/infra/setup" [00018.788] 01036.01043> userboot: option "kernel.serial=legacy" [00018.788] 01036.01043> userboot: option "http://192.168.42.1/multiboot/d4%3A5d%3Adf%3A1a%3A42%3A46=" [00018.788] 01036.01043> userboot: option "multiboot.boot_loader_name=iPXE+1.0.0++(d2063)" [00018.827] 01036.01043> userboot: searching bootfs for 'bin/bootsvc' [00018.827] 01036.01043> userboot: 'bin/bootsvc' has PT_INTERP "lib/ld.so.1" [00018.827] 01036.01043> userboot: searching bootfs for 'lib/ld.so.1' [00018.827] 01036.01043> userboot: userboot: loaded lib/ld.so.1 at 0x64e573faa000, entry point 0x64e5740300d3 [00018.827] 01036.01043> userboot: userboot: loaded vDSO at 0x70842e7e0000, entry point 0x0 [00018.827] 01036.01043> userboot: process bin/bootsvc started. [00018.827] 01036.01043> userboot: waiting for loader-service requests... [00018.827] 01036.01043> userboot: searching bootfs for 'lib/libasync-default.so' [00018.827] 01036.01043> userboot: searching bootfs for 'lib/libfdio.so' [00018.827] 01036.01043> userboot: searching bootfs for 'lib/liblaunchpad.so' [00018.827] 01036.01043> userboot: searching bootfs for 'lib/libtrace-engine.so' [00018.827] 01050.01053> {{{reset}}} [00018.827] 01050.01053> {{{module:0:<application>:elf:18de7d58f51e8ba5c4f6afdd0cc8440f482c2b45}}} [00018.827] 01050.01053> {{{mmap:0x5bb2c56da000:0x2e000:load:0:rx:0}}} [00018.827] 01050.01053> {{{mmap:0x5bb2c5708000:0x4000:load:0:rw:0x2e000}}} [00018.828] 01050.01053> dso: id=18de7d58f51e8ba5c4f6afdd0cc8440f482c2b45 base=0x00005bb2c56da000 name=<application> [00018.828] 01050.01053> {{{module:0x3:libasync-default.so:elf:c189f51f19d10785d93b5235ad1b46dca4451b00}}} [00018.828] 01050.01053> {{{mmap:0x711ca1708000:0x1000:load:0x3:rx:0}}} [00018.828] 01050.01053> {{{mmap:0x711ca1709000:0x1000:load:0x3:rw:0x1000}}} [00018.828] 01050.01053> dso: id=c189f51f19d10785d93b5235ad1b46dca4451b00 base=0x0000711ca1708000 name=libasync-default.so [00018.828] 01050.01053> {{{module:0x2:<vDSO>:elf:40ab5fa3b61f12fef4a44477a687f608661cd450}}} [00018.828] 01050.01053> {{{mmap:0x70842e7e0000:0x7000:load:0x2:r:0}}} [00018.828] 01050.01053> {{{mmap:0x70842e7e7000:0x1000:load:0x2:rx:0x7000}}} [00018.828] 01050.01053> dso: id=40ab5fa3b61f12fef4a44477a687f608661cd450 base=0x000070842e7e0000 name=<vDSO> [00018.828] 01050.01053> {{{module:0x1:libc.so:elf:67a12284bce140fc32aaaeac223e0e8f85cb5085}}} [00018.828] 01050.01053> {{{mmap:0x64e573faa000:0xcb000:load:0x1:rx:0}}} [00018.828] 01050.01053> {{{mmap:0x64e574076000:0x6000:load:0x1:rw:0xcc000}}} [00018.828] 01050.01053> dso: id=67a12284bce140fc32aaaeac223e0e8f85cb5085 base=0x000064e573faa000 name=libc.so [00018.828] 01050.01053> {{{module:0x4:libfdio.so:elf:27787977e95f3b9563c9e0bd4d34ec92b7e9ad88}}} [00018.828] 01050.01053> {{{mmap:0x7ff5542c7000:0x24000:load:0x4:rx:0}}} [00018.828] 01050.01053> {{{mmap:0x7ff5542ec000:0x4000:load:0x4:rw:0x25000}}} [00018.828] 01050.01053> dso: id=27787977e95f3b9563c9e0bd4d34ec92b7e9ad88 base=0x00007ff5542c7000 name=libfdio.so [00018.828] 01050.01053> {{{module:0x5:liblaunchpad.so:elf:6fc2232dc8c1bc5c6adb8ad50ca794b5a260ee4f}}} [00018.828] 01050.01053> {{{mmap:0x728f9e5ab000:0x7000:load:0x5:rx:0}}} [00018.828] 01050.01053> {{{mmap:0x728f9e5b2000:0x2000:load:0x5:rw:0x7000}}} [00018.828] 01050.01053> dso: id=6fc2232dc8c1bc5c6adb8ad50ca794b5a260ee4f base=0x0000728f9e5ab000 name=liblaunchpad.so [00018.828] 01050.01053> {{{module:0x6:libtrace-engine.so:elf:c9042b83fe01206008fcefb16395238417248169}}} [00018.828] 01050.01053> {{{mmap:0x7a4c8fdc0000:0x9000:load:0x6:rx:0}}} [00018.828] 01050.01053> {{{mmap:0x7a4c8fdc9000:0x2000:load:0x6:rw:0x9000}}} [00018.828] 01050.01053> dso: id=c9042b83fe01206008fcefb16395238417248169 base=0x00007a4c8fdc0000 name=libtrace-engine.so [00018.828] 01050.01053> bootsvc: Starting... [00018.828] 01036.01043> userboot: loader-service channel peer closed [00018.828] 01050.01053> bootsvc: Creating bootfs service... [00018.828] 01036.01043> userboot: finished! [00018.828] 01050.01053> bootsvc: Processing bootdata... [00018.828] 01050.01053> bootsvc: Loading boot cmdline overrides... [00018.828] 01050.01053> bootsvc: Loading kernel VMOs... [00018.828] 01050.01053> bootsvc: Creating loader service... [00018.828] 01050.01053> bootsvc: Launching next process... [00018.829] 01050.01096> bootsvc: launched bin/devmgr [00018.829] 01104.01117> devmgr: main() [00018.829] 01104.01117> cmdline: netsvc.disable=true [00018.829] 01104.01117> cmdline: zircon.system.disable-automount=true [00018.829] 01104.01117> cmdline: zircon.autorun.boot=/boot/infra/setup [00018.829] 01104.01117> cmdline: kernel.serial=legacy [00018.829] 01104.01117> cmdline: http://192.168.42.1/multiboot/d4%3A5d%3Adf%3A1a%3A42%3A46= [00018.829] 01104.01117> cmdline: multiboot.boot_loader_name=iPXE+1.0.0++(d2063) [00018.829] 01104.01117> devmgr: coordinator_init() [00018.829] 01104.01117> devmgr: init [00018.829] 01104.01117> devmgr: svc init [00018.829] 01104.01117> devmgr: launch /boot/bin/svchost (svchost) OK [00018.829] 01104.01117> devmgr: vfs init [00018.830] 01104.01117> devmgr: launch /boot/bin/fshost (fshost) OK [00018.830] 01104.01220> devmgr: shell startup [00018.831] 01182.01202> fshost: started. [00018.832] 01104.01213> devmgr: launch /boot/bin/pwrbtn-monitor (pwrbtn-monitor) OK [00018.832] 01104.01234> devmgr: launch /boot/bin/virtual-console (virtual-console) OK [00018.832] 01104.01234> zircon.autorun.boot: starting '/boot/infra/setup'... [00018.833] 01104.01234> devmgr: launch /boot/infra/setup (autorun:boot) OK [00018.836] 01104.01117> devcoord: launch devhost 'devhost:sys': pid=2049 [00018.836] 01104.01117> devcoord: launch devhost 'devhost:test': pid=2082 [00018.836] 01104.01117> devcoord: launch devhost 'devhost:root': pid=2115 [00018.837] 01104.01117> devcoord: launch devhost 'devhost:misc': pid=2171 [00018.837] 02049.02073> devhost: trace provider registry begun [00018.838] 02082.02105> devhost: trace provider registry begun [00018.840] 02115.02154> devhost: trace provider registry begun [00018.841] 02171.02213> devhost: trace provider registry begun [00018.849] 01104.01220> devmgr: launch /boot/bin/sh (sh:console) OK [00018.907] 02049.02073> acpi-bus: not using IOMMU [00018.911] 02049.02073> acpi-pwrbtn: initialized [00018.917] 02049.02073> WARNING: ACPI found bad _CRS address entry [00018.923] 02049.02073> WARNING: ACPI found bad _CRS address entry [00018.934] 02049.02073> acpi: published device pci(0x500860288200), parent=proxy(0x500860284540), handle=0x5008602c0750 [00018.935] 02049.02073> acpi: published device rtc(0x500860283080), parent=acpi(0x500860284780), handle=0x5008602df330 [00018.936] 02049.02073> acpi-ec: initialized [00018.937] 02049.02073> acpi: failed to create NHLT VMO (res -10) [00018.937] 02049.02073> acpi: failed to publish NHLT metadata [00018.940] 02049.02073> [sysmem_init 28] async_get_default_dispatcher(): 0x5008602770a0 [00018.940] 02049.02073> [sysmem_bind 40] sysmem_bind() [00018.940] 02049.02073> acpi-bus: sysmem_register_protocol() intentionally ignored for now. [00018.941] 02049.02073> PMU: 7 arch events [00018.941] 02049.02073> PMU: arch event id range: 1-7 [00018.941] 02049.02073> PMU: 102 model events [00018.941] 02049.02073> PMU: model event id range: 1-241 [00018.941] 02049.02073> Intel Processor Trace configuration for this chipset: [00018.941] 02049.02073> mtc_freq_mask: 0x249 [00018.941] 02049.02073> cyc_thresh_mask: 0x3fff [00018.941] 02049.02073> psb_freq_mask: 0x3f [00018.941] 02049.02073> num addr ranges: 2 [00018.941] 01241.01573> vc: new input device /dev/class/input/000 [00018.941] 01104.01117> devcoord: launch devhost 'devhost:pci#1:8086:5916': pid=3047 [00018.941] 01104.01117> devcoord: launch devhost 'devhost:pci#3:8086:9d2f': pid=3098 [00018.942] 01104.01117> devcoord: launch devhost 'devhost:pci#5:8086:9d60': pid=3162 [00018.942] 01104.01117> devcoord: launch devhost 'devhost:pci#6:8086:9d61': pid=3215 [00018.943] 03047.03078> devhost: trace provider registry begun [00018.943] 01104.01117> devcoord: launch devhost 'devhost:pci#9:8086:9d03': pid=3313 [00018.943] 03098.03134> devhost: trace provider registry begun [00018.944] 01104.01117> devcoord: launch devhost 'devhost:pci#14:8086:9d71': pid=3420 [00018.944] 03162.03190> devhost: trace provider registry begun [00018.945] 01104.01117> devcoord: launch devhost 'devhost:pci#16:8086:156f': pid=3513 [00018.945] 03215.03268> devhost: trace provider registry begun [00018.946] 03313.03353> devhost: trace provider registry begun [00018.947] 03313.03353> ahci: using MSI interrupt [00018.947] 03162.03190> initialized intel serialio i2c driver, reg=0x421663b9d000 regsize=4096 [00018.948] 03215.03268> initialized intel serialio i2c driver, reg=0x1ba719fa0000 regsize=4096 [00018.948] 03420.03467> devhost: trace provider registry begun [00018.950] 03513.03549> devhost: trace provider registry begun [00018.953] 03098.03848> * found USB device (0x18d1:0xa002, USB 2.0) config 1 [00018.953] 03098.03848> * found USB device (0x18d1:0xa003, USB 3.0) config 1 [00018.960] 03420.03467> [IHDA DSP 00:1f.3] Failed to fetch NHLT (res -25) [00018.960] 03420.03467> devhost[00:1f.3/intel-hda-000/intel-sst-dsp-000] bind driver '/boot/driver/dsp.so' failed: -25 [00018.960] 01104.01117> devcoord: rpc: bind-driver 'intel-sst-dsp-000' status -25 [00019.051] 01241.01573> vc: new display device /dev/class/display-controller/000/virtcon [00019.191] 03047.04139> i915: Found DP monitor [00019.191] 03047.04139> i915: Display 1 connected [00019.192] 03047.04139> i915: MST not supported [00019.672] 03098.03848> * found USB device (0x0781:0x5583, USB 3.0) config 1 [00019.673] 03098.03134> UMS: parent: 'ifc-000' [00019.673] 03098.03134> UMS:Max lun is: 0 [00020.259] 01241.01573> vc: Successfully attached to display 1 [00020.426] 03098.03848> * found USB device (0x046d:0xc31c, USB 1.10) config 1 [00020.429] 01241.01573> vc: new input device /dev/class/input/001 [00020.435] 01241.01573> vc: new input device /dev/class/input/002 [00020.673] 03098.03848> * found USB device (0x0cf3:0xe300, USB 2.1) config 1 [00020.675] 03098.03134> devhost[00:14.0/xhci/usb-bus/003/003/ifc-001] bind driver '/boot/driver/bt-transport-usb.so' failed: -2 [00020.675] 01104.01117> devcoord: rpc: bind-driver 'ifc-001' status -2 [00020.676] 03098.04226> UMS: block size is: 0x00000200 [00020.676] 03098.04226> UMS: total blocks is: 30031250 [00020.676] 03098.04226> UMS: total size is: 15376000000 [00020.676] 03098.04226> UMS: read-only: 0 removable: 1 [00020.677] 01182.01202> devmgr: /dev/class/block/000: MBR? [00020.677] 01104.01117> devcoord: dc_bind_device() '/boot/driver/mbr.so' [00020.680] 01182.01202> devmgr: /dev/class/block/002: MBR? [00020.680] 01104.01117> devcoord: dc_bind_device() '/boot/driver/mbr.so' [00020.950] 03215.03268> intel-i2c-controller: intel_serialio_i2c_slave_transfer: -21 [00020.951] 03215.03268> i2c-hid: could not read HID descriptor: 0 [00020.951] 03215.03268> devhost[00:15.1/i2c-bus-9d61/004c] bind driver '/boot/driver/i2c-hid.so' failed: -2 [00020.951] 01104.01117> devcoord: rpc: bind-driver '004c' status -2 [00020.951] 03162.03190> intel-i2c-controller: intel_serialio_i2c_slave_transfer: -21 [00020.951] 03162.03190> i2c-hid: could not read HID descriptor: 0 [00020.951] 03162.03190> devhost[00:15.0/i2c-bus-9d60/0020] bind driver '/boot/driver/i2c-hid.so' failed: -2 [00020.951] 01104.01117> devcoord: rpc: bind-driver '0020' status -2 [00020.964] 03313.03786> sata2: dev info [00020.964] 03313.03786> serial=711430952084 9 [00020.964] 03313.03786> firmware rev=1Q01A7 0 [00020.964] 03313.03786> model id=IBIW NSS D [00020.964] 03313.03786> major=0x3f0 ACS2 DMA 32 commands [00020.964] 03313.03786> LBA48 234441648 sectors, sector size=512 [00020.965] 01182.01202> devmgr: /dev/class/block/003: GPT? [00020.966] 01104.01117> devcoord: dc_bind_device() '/boot/driver/gpt.so' [00020.966] 03313.03353> gpt: device_get_metadata failed (-25) [00020.967] 01182.01202> devmgr: /dev/class/block/004: FVM? [00020.967] 01104.01117> devcoord: dc_bind_device() '/boot/driver/fvm.so' [00020.969] 04586.04600> paver:[Initialize] Successfully initialized EFI Device Partitioner [00020.971] 04586.04600> paver:[WipePartitions] Immediate reboot strongly recommended [00020.971] 03313.03353> block: Joining un-closed FIFO server [00020.971] 03313.03353> block: Joining un-closed FIFO server [00020.971] 03313.03353> block: Joining un-closed FIFO server [00020.971] 01104.01117> devcoord: dc_bind_device() '' [00020.972] 01182.01202> devmgr: /dev/class/block/003: GPT? [00020.972] 01104.01117> devcoord: dc_bind_device() '/boot/driver/gpt.so' [00020.972] 03313.03353> gpt: device_get_metadata failed (-25) [00020.975] 04905.04919> 34+0 records in [00020.975] 04905.04919> 34+0 records out [00020.975] 04905.04919> 17408 bytes copied [00020.976] 05023.05037> Failed to seek on output [00020.976] 05023.05037> 0+0 records in [00020.976] 05023.05037> 0+0 records out [00020.976] 05023.05037> 0 bytes copied [00020.977] 05093.05107> netifc: ? /dev/class/ethernet/000 [00020.977] 05093.05107> netifc: create 512 eth buffers [00020.977] 05093.05107> macaddr: d4:5d:df:1a:42:46 [00020.977] 05093.05107> ip6addr: fe80::d65d:df4d:fe1a:4246 [00020.977] 05093.05107> snmaddr: ff02::1:ff1a:4246 [00020.977] 05093.05107> netsvc: using /dev/class/ethernet/000 [00020.977] 05093.05107> _ _ _ [00020.977] 05093.05107> | | | | | [00020.977] 05093.05107> _______ __| | |__ ___ ___ | |_ [00020.977] 05093.05107> |_ / _ \/ _` | '_ \ / _ \ / _ \| __| [00020.977] 05093.05107> / / __/ (_| | |_) | (_) | (_) | |_ [00020.977] 05093.05107> /___\___|\__,_|_.__/ \___/ \___/ \__| [00020.977] 05093.05107> [00020.977] 05093.05107> [00020.977] 05093.05107> zedboot: version: 0.7.13 [00020.977] 05093.05107> [00020.977] 05093.05107> netsvc: nodename='ocean-drank-wick-spot' [00020.977] 05093.05107> netsvc: will not advertise [00020.977] 05093.05107> netsvc: start [00242.273] 05093.05107> netsvc: tftp write of file <<netboot>>cmdline completed [00242.273] 05093.05107> netsvc: metrics: {"inorderblks": 1,"oooblks": 0,"ack": 1,"nack": 0,"timeouts": 0,"sas": 0,"inorderbytes": 55} [00242.273] 05093.05107> netsvc: Running FVM Paver [00242.275] 05093.05201> paver:[InitializeGpt] Located GPT is invalid; Attempting to initialize [00242.275] 01104.01117> devcoord: dc_bind_device() '' [00242.275] 01104.01117> devcoord: dc_bind_device() '/boot/driver/gpt.so' [00242.275] 03313.03353> gpt: device_get_metadata failed (-25) [00242.276] 01182.01202> devmgr: /dev/class/block/003: GPT? [00242.276] 01104.01117> devcoord: dc_bind_device() '/boot/driver/gpt.so' [00242.276] 03313.03353> devhost: rpc:bind-device failed: -20 [00242.277] 05093.05201> paver:[Initialize] Successfully initialized EFI Device Partitioner [00242.277] 05093.05201> paver:[PartitionPave] Paving partition. [00242.277] 05093.05201> paver:[FindFirstFit] Looking for space [00242.277] 05093.05201> paver:[FindFirstFit] Sorting [00242.277] 05093.05201> paver:[FindFirstFit] Partition[0] From Block [0, 34) ... (next partition starts at block 234441614) [00242.277] 05093.05201> paver:[FindFirstFit] There are 234441580 free blocks (16777216 requested) [00242.277] 05093.05201> paver:[AddPartition] Found space in GPT - OK 234441580 @ 34 [00242.277] 05093.05201> paver:[AddPartition] Final space in GPT - OK 16777216 @ 34 [00242.277] 05093.05201> paver:[AddPartition] Added partition, waiting for bind [00242.277] 01104.01117> devcoord: dc_bind_device() '' [00242.278] 01182.01202> devmgr: /dev/class/block/003: GPT? [00242.278] 01104.01117> devcoord: dc_bind_device() '/boot/driver/gpt.so' [00242.278] 03313.03353> gpt: device_get_metadata failed (-25) [00242.279] 05093.05201> paver:[AddPartition] Added partition, waiting for bind - OK [00242.279] 05093.05201> paver:[PartitionPave] Streaming partitions... [00242.279] 05181.05195> Found compressed file [00242.279] 05093.05201> paver:[FvmStreamPartitions] Header Validated - OK [00242.279] 05093.05201> paver:[FvmPartitionFormat] Initializing partition as FVM [00242.282] 01104.01117> devcoord: dc_bind_device() '/boot/driver/fvm.so' [00243.284] 05093.05201> paver:[FvmStreamPartitions] Partitions pre-validated successfully: Enough space exists to pave. [00243.284] 05093.05201> paver:[AllocatePartitions] Allocating partition blobfs consisting of 1 slices [00243.287] 05093.05201> paver:[AllocatePartitions] Allocating partition minfs consisting of 1 slices [00243.288] 05093.05201> paver:[AllocatePartitions] Creating zxcrypt volume [00243.290] 03313.03353> devhost_get_handles(0x136f5f008900:block) open path='zxcrypt/block', r=-2 [00243.290] 01104.01117> devcoord: dc_bind_device() '/boot/driver/zxcrypt.so' [00243.290] 03313.03353> devhost_get_handles(0x136f5f008900:block) open path='zxcrypt', r=-2 [00243.294] 05093.05201> paver:[FvmStreamPartitions] Partition space pre-allocated successfully. [00243.295] 05093.05201> paver:[FvmStreamPartitions] Streaming partition 0 [00243.295] 05093.05201> paver:[StreamFvmPartition] Writing extent 0... [00243.295] 05093.05207> netsvc: paver write progress 0.1% [00243.295] 05093.05201> paver:[StreamFvmPartition] 8192 bytes written, 8380416 zeroes left [00243.315] 05093.05201> paver:[StreamFvmPartition] Writing extent 1... [00243.315] 05093.05201> paver:[StreamFvmPartition] 8192 bytes written, 8380416 zeroes left [00243.332] 05093.05201> paver:[StreamFvmPartition] Writing extent 2... [00243.337] 05093.05201> paver:[StreamFvmPartition] 2097152 bytes written, 6291456 zeroes left [00243.354] 05093.05201> paver:[StreamFvmPartition] Writing extent 3... [00243.358] 05093.05201> paver:[StreamFvmPartition] 2097152 bytes written, 6291456 zeroes left [00243.371] 05093.05201> paver:[StreamFvmPartition] Writing extent 4... [00244.048] 05093.05107> netsvc: tftp write of file <<image>>sparse.fvm completed [00244.048] 05093.05107> netsvc: metrics: {"inorderblks": 172342,"oooblks": 0,"ack": 674,"nack": 0,"timeouts": 0,"sas": 0,"inorderbytes": 176477285} [00244.050] 05093.05201> paver:[StreamFvmPartition] 189751296 bytes written, 3186688 zeroes left [00244.056] 05093.05201> paver:[FvmStreamPartitions] Done streaming partition 0 [00244.056] 05093.05201> paver:[FvmStreamPartitions] Done flushing partition 0 [00244.056] 05093.05201> paver:[FvmStreamPartitions] Streaming partition 1 [00244.056] 05093.05201> paver:[StreamFvmPartition] Writing extent 0... [00244.056] 05093.05201> paver:[StreamFvmPartition] 8192 bytes written, 8380416 zeroes left [00244.095] 05093.05201> paver:[StreamFvmPartition] Writing extent 1... [00244.096] 05093.05201> paver:[StreamFvmPartition] 65536 bytes written, 8323072 zeroes left [00244.134] 05093.05201> paver:[StreamFvmPartition] Writing extent 2... [00244.134] 05093.05201> paver:[StreamFvmPartition] 65536 bytes written, 8323072 zeroes left [00244.170] 05093.05201> paver:[StreamFvmPartition] Writing extent 3... [00244.212] 05093.05201> paver:[StreamFvmPartition] Writing extent 4... [00244.222] 05093.05201> paver:[StreamFvmPartition] 2097152 bytes written, 14680064 zeroes left [00244.285] 05093.05201> paver:[StreamFvmPartition] Writing extent 5... [00244.285] 05093.05201> paver:[StreamFvmPartition] 57344 bytes written, 8331264 zeroes left [00244.323] 05093.05201> paver:[FvmStreamPartitions] Done streaming partition 1 [00244.323] 05093.05201> paver:[FvmStreamPartitions] Done flushing partition 1 [00244.325] 05181.05195> Reading FVM from compressed file: true [00244.325] 05181.05195> Remaining bytes read into compression buffer: 0 [00244.325] 05181.05195> Remaining bytes written to decompression buffer: 0 [00244.325] 05181.05195> Time reading bytes from sparse FVM file: 669616597 (0 s) [00244.325] 05181.05195> Time reading bytes AND decompressing them: 768126952 (0 s) [00244.325] 05093.05201> paver:[PartitionPave] Completed successfully [00245.049] 05093.05107> netsvc: Running BOOTLOADER Paver [00245.052] 05093.05943> paver:[Initialize] Successfully initialized EFI Device Partitioner [00245.052] 05093.05943> paver:[RealMain] SKIPPING BOOTLOADER install on x64 device, pass --force if desired. [00245.070] 05093.05107> netsvc: tftp write of file <<image>>bootloader.img completed [00245.070] 05093.05107> netsvc: metrics: {"inorderblks": 1093,"oooblks": 0,"ack": 5,"nack": 0,"timeouts": 0,"sas": 0,"inorderbytes": 1118208} [00245.070] 05093.05107> netsvc: Running ZIRCON-A Paver [00245.073] 05093.06084> paver:[Initialize] Successfully initialized EFI Device Partitioner [00245.073] 05093.06084> paver:[PartitionPave] Paving partition. [00245.073] 05093.06084> paver:[FindFirstFit] Looking for space [00245.073] 05093.06084> paver:[FindFirstFit] Partition seen with start 34, end 16777249 (length 16777216) [00245.073] 05093.06084> paver:[FindFirstFit] Sorting [00245.073] 05093.06084> paver:[FindFirstFit] Partition[0] From Block [0, 34) ... (next partition starts at block 34) [00245.073] 05093.06084> paver:[FindFirstFit] There are 0 free blocks (32768 requested) [00245.073] 05093.06084> paver:[FindFirstFit] Partition[1] From Block [34, 16777250) ... (next partition starts at block 234441614) [00245.073] 05093.06084> paver:[FindFirstFit] There are 217664364 free blocks (32768 requested) [00245.073] 05093.06084> paver:[AddPartition] Found space in GPT - OK 217664364 @ 16777250 [00245.073] 05093.06084> paver:[AddPartition] Final space in GPT - OK 32768 @ 16777250 [00245.074] 03313.03353> block: Joining un-closed FIFO server [00245.074] 05093.06084> paver:[AddPartition] Added partition, waiting for bind [00245.074] 03313.03353> block: Joining un-closed FIFO server [00245.074] 01104.01117> devcoord: dc_bind_device() '' [00245.074] 01182.01202> devmgr: /dev/class/block/003: GPT? [00245.074] 01104.01117> devcoord: dc_bind_device() '/boot/driver/gpt.so' [00245.074] 03313.03353> gpt: device_get_metadata failed (-25) [00245.076] 01182.01202> devmgr: /dev/class/block/013: FVM? [00245.076] 01104.01117> devcoord: dc_bind_device() '/boot/driver/fvm.so' [00245.076] 05093.06084> paver:[AddPartition] Added partition, waiting for bind - OK [00245.222] 05093.05107> netsvc: tftp write of file <<image>>zircona.img completed [00245.222] 05093.05107> netsvc: metrics: {"inorderblks": 13392,"oooblks": 0,"ack": 53,"nack": 0,"timeouts": 0,"sas": 0,"inorderbytes": 13712912} [00245.256] 05093.06084> paver:[PartitionPave] Completed successfully 2019/04/26 04:25:40 attempting to send <<image>>zirconr.img... [00246.222] 05093.05107> netsvc: Running ZIRCON-R Paver [00246.225] 05093.06357> paver:[Initialize] Successfully initialized EFI Device Partitioner [00246.226] 05093.06357> paver:[PartitionPave] Paving partition. [00246.226] 05093.06357> paver:[FindFirstFit] Looking for space [00246.226] 05093.06357> paver:[FindFirstFit] Partition seen with start 34, end 16777249 (length 16777216) [00246.226] 05093.06357> paver:[FindFirstFit] Partition seen with start 16777250, end 16810017 (length 32768) [00246.226] 05093.06357> paver:[FindFirstFit] Sorting [00246.226] 05093.06357> paver:[FindFirstFit] Partition[0] From Block [0, 34) ... (next partition starts at block 34) [00246.226] 05093.06357> paver:[FindFirstFit] There are 0 free blocks (49152 requested) [00246.226] 05093.06357> paver:[FindFirstFit] Partition[1] From Block [34, 16777250) ... (next partition starts at block 16777250) [00246.226] 05093.06357> paver:[FindFirstFit] There are 0 free blocks (49152 requested) [00246.226] 05093.06357> paver:[FindFirstFit] Partition[2] From Block [16777250, 16810018) ... (next partition starts at block 234441614) [00246.226] 05093.06357> paver:[FindFirstFit] There are 217631596 free blocks (49152 requested) [00246.226] 05093.06357> paver:[AddPartition] Found space in GPT - OK 217631596 @ 16810018 [00246.226] 05093.06357> paver:[AddPartition] Final space in GPT - OK 49152 @ 16810018 [00246.226] 05093.06357> paver:[AddPartition] Added partition, waiting for bind [00246.226] 03313.03353> block: Joining un-closed FIFO server [00246.226] 01104.01117> devcoord: dc_bind_device() '' [00246.227] 01182.01202> devmgr: /dev/class/block/003: GPT? [00246.227] 01104.01117> devcoord: dc_bind_device() '/boot/driver/gpt.so' [00246.227] 03313.03353> gpt: device_get_metadata failed (-25) [00246.228] 01182.01202> devmgr: /dev/class/block/017: FVM? [00246.228] 01104.01117> devcoord: dc_bind_device() '/boot/driver/fvm.so' [00246.228] 05093.06357> paver:[AddPartition] Added partition, waiting for bind - OK 2019/04/26 04:25:40 done 2019/04/26 04:25:40 attempting to send <<image>>authorized_keys... 2019/04/26 04:25:40 target is busy, retrying in one second [00246.370] 05093.05107> netsvc: tftp write of file <<image>>zirconr.img completed [00246.370] 05093.05107> netsvc: metrics: {"inorderblks": 12182,"oooblks": 0,"ack": 48,"nack": 0,"timeouts": 0,"sas": 0,"inorderbytes": 12473704} [00246.396] 05093.06357> paver:[PartitionPave] Completed successfully 2019/04/26 04:25:41 attempting to send <<image>>authorized_keys... 2019/04/26 04:25:41 done 2019/04/26 04:25:41 attempting to send <<netboot>>kernel.bin... 2019/04/26 04:25:41 target is busy, retrying in one second [00247.371] 05093.05107> netsvc: Installing SSH authorized_keys [00247.372] 05093.05107> netsvc: tftp write of file <<image>>authorized_keys completed [00247.372] 05093.05107> netsvc: metrics: {"inorderblks": 1,"oooblks": 0,"ack": 1,"nack": 0,"timeouts": 0,"sas": 0,"inorderbytes": 806} [00247.374] 05093.06646> paver:[Initialize] Successfully initialized EFI Device Partitioner [00247.374] 01104.01117> devcoord: dc_bind_device() '/boot/driver/zxcrypt.so' [00247.374] 03313.03353> devhost_get_handles(0x136f5f008900:block) open path='zxcrypt', r=-2 [00247.403] 05093.06646> paver:[DataFilePave] Wrote ssh/authorized_keys 2019/04/26 04:25:42 attempting to send <<netboot>>kernel.bin... 2019/04/26 04:25:42 done [00000.000] 00000.00000> zbi: @ 0xffffff80093d7000 (12199168 bytes) [00000.000] 00000.00000> UART: FIFO depth 16 [00000.000] 00000.00000> PMM: boot reserve add [0x100000, 0x2fcfff] [00000.000] 00000.00000> PMM: boot reserve add [0x93d7000, 0x9f79fff] [00000.000] 00000.00000> PMM: arena too small to be useful (size 4096) [00000.000] 00000.00000> PMM: pmm_add_arena failed to initialize arena [00000.000] 00000.00000> MEM: Failed to add pmm range at 0x7ffff000 size 0x1000 [00000.000] 00000.00000> PMM: boot reserve marking WIRED [0x100000, 0x2fcfff] [00000.000] 00000.00000> PMM: boot reserve marking WIRED [0x93d7000, 0x9f79fff] [00000.000] 00000.00000> [00000.000] 00000.00000> welcome to Zircon [00000.000] 00000.00000> [00000.000] 00000.00000> KASLR: .text section at 0xffffffff00100000 [00000.000] 00000.00000> INIT: cpu 0, calling hook 0xffffffff00115228 (global_prng_seed) at level 0x30000, flags 0x1 [00000.000] 00000.00000> initializing vm pre-heap [00000.000] 00000.00000> VM: marking boot alloc used range [0x2fd000, 0x2fd100) [00000.000] 00000.00000> INIT: cpu 0, calling hook 0xffffffff001225d8 (elf_build_id) at level 0x4fffe, flags 0x1 [00000.000] 00000.00000> INIT: cpu 0, calling hook 0xffffffff00122764 (version) at level 0x4ffff, flags 0x1 [00000.000] 00000.00000> version: [00000.000] 00000.00000> arch: x86 [00000.000] 00000.00000> platform: XXX [00000.000] 00000.00000> target: XXX [00000.000] 00000.00000> project: x64 [00000.000] 00000.00000> buildid: git-5a66c475af0001b5da83a0afc1778998bf850111-dirty [00000.000] 00000.00000> ELF build ID: 88b3706b30c820ad5108920cc78c200b5a575542 [00000.000] 00000.00000> initializing heap [00000.000] 00000.00000> INIT: cpu 0, calling hook 0xffffffff00101fc4 (console) at level 0x50000, flags 0x1 [00000.000] 00000.00000> INIT: cpu 0, calling hook 0xffffffff00182dc0 (x86_resource_init) at level 0x50000, flags 0x1 [00000.000] 00000.00000> initializing vm [00000.000] 00000.00000> VM: reserving kernel region [0xffffffff00100000, 0xffffffff00219000) flags 0x28 name 'kernel_code' [00000.000] 00000.00000> VM: reserving kernel region [0xffffffff00219000, 0xffffffff00269000) flags 0x8 name 'kernel_rodata' [00000.000] 00000.00000> VM: reserving kernel region [0xffffffff00269000, 0xffffffff00271000) flags 0x18 name 'kernel_data' [00000.000] 00000.00000> VM: reserving kernel region [0xffffffff00271000, 0xffffffff002fd000) flags 0x18 name 'kernel_bss' [00000.000] 00000.00000> INIT: cpu 0, calling hook 0xffffffff00183ad0 (display_memtype) at level 0x60001, flags 0x1 [00000.000] 00000.00000> INIT: cpu 0, calling hook 0xffffffff00186f5c (acpi_tables) at level 0x60001, flags 0x1 [00000.000] 00000.00000> INIT: cpu 0, calling hook 0xffffffff00181bc4 (hpet) at level 0x60002, flags 0x1 [00000.000] 00000.00000> INIT: cpu 0, calling hook 0xffffffff00181f84 (apic) at level 0x60002, flags 0x1 [00000.000] 00000.00000> x2APIC enabled [00000.000] 00000.00000> INIT: cpu 0, calling hook 0xffffffff001a85b4 (system_topology_init) at level 0x60002, flags 0x1 [00000.000] 00000.00000> WARNING: more than 1000 levels of cache, couldn't find highest. [00000.000] 00000.00000> WARNING: unable to find any cache levels. [00000.000] 00000.00000> Could not find SRAT table. ACPICA returned: 5 [00000.000] 00000.00000> INIT: cpu 0, calling hook 0xffffffff0018654c (timer) at level 0x60003, flags 0x1 [00000.000] 00000.00000> HPET frequency: 23999 ticks/ms [00000.000] 00000.00000> TSC frequency: 2712000 ticks/ms [00248.827] 00000.00000> timer features: constant_tsc 1 invariant_tsc 1 tsc_deadline 1 [00248.827] 00000.00000> Using TSC as wallclock [00248.827] 00000.00000> INIT: cpu 0, calling hook 0xffffffff0020967c (percpu_heap_init) at level 0x60003, flags 0x1 [00248.827] 00000.00000> initializing kernel [00248.827] 00000.00000> initializing mp [00248.827] 00000.00000> INIT: cpu 0, calling hook 0xffffffff0011547c (global_prng_thread_safe) at level 0x7ffff, flags 0x1 [00248.827] 00000.00000> creating bootstrap completion thread [00248.827] 00000.00000> top of bootstrap2() [00248.827] 00000.00000> INIT: cpu 0, calling hook 0xffffffff00131a94 (libobject) at level 0x80000, flags 0x1 [00248.827] 00000.00000> OOM: started thread [00248.827] 00000.00000> INIT: cpu 0, calling hook 0xffffffff00206630 (dpc) at level 0x80000, flags 0x1 [00248.827] 00000.00000> Processor Model Info: type 0 family 0x6 model 0xe stepping 0x9 [00248.827] 00000.00000> display_family 0x6 display_model 0x8e [00248.827] 00000.00000> Vendor: Intel [00248.827] 00000.00000> Microarch: Kaby Lake [00248.827] 00000.00000> F/M/S: 6/8e/9 [00248.827] 00000.00000> patch_level: 84 [00248.827] 00000.00000> Brand: Intel(R) Core(TM) i5-7300U CPU @ 2.60GHz [00248.827] 00000.00000> Features: fpu sse sse2 sse3 ssse3 sse4.1 sse4.2 mmx avx avx2 fxsr pcid xsave mon aesni clflush [00248.827] 00000.00000> clflushopt fsgsbase tsc_adj smep smap erms rdrand rdseed syscall nx huge rdtscp [00248.827] 00000.00000> invar_tsc tsc_deadline x2apic vmx pt hwp [00248.827] 00000.00000> Properties: meltdown l1tf pcid_good [00248.827] 00000.00000> initializing platform [00248.827] 00000.00000> INIT: cpu 0, calling hook 0xffffffff001a1cc4 (x86_perfmon) at level 0x90000, flags 0x1 [00248.827] 00000.00000> PMU: version 4 [00248.827] 00000.00000> UART: started IRQ driven RX [00248.827] 00000.00000> UART: started IRQ driven TX [00248.827] 00000.00000> cpu topology: [00248.827] 00000.00000> 0: apic id 0x0 BSP [00248.827] 00000.00000> 1: apic id 0x1 [00248.827] 00000.00000> 2: apic id 0x2 [00248.827] 00000.00000> 3: apic id 0x3 [00248.827] 00000.00000> Found 4 cpus [00248.827] 00000.00000> booting apic ids: 0x1 0x2 0x3 [00248.842] 00000.00000> entering scheduler on cpu 1 [00248.843] 00000.00000> entering scheduler on cpu 2 [00248.843] 00000.00000> entering scheduler on cpu 3 [00248.846] 00000.00000> smbios: manufacturer="Intel Corporation" product="NUC7i5DNHE" [00248.846] 00000.00000> initializing target [00248.846] 00000.00000> INIT: cpu 0, calling hook 0xffffffff001857fc (x86_pcie_init) at level 0xa0000, flags 0x1 [00248.846] 00000.00000> moving to last init level [00248.846] 00000.00000> INIT: cpu 0, calling hook 0xffffffff00121830 (debuglog) at level 0xb0000, flags 0x1 [00248.846] 00000.00000> INIT: cpu 0, calling hook 0xffffffff00175444 (kcounters) at level 0xb0000, flags 0x1 [00248.846] 00000.00000> INIT: cpu 0, calling hook 0xffffffff00102aec (kernel_shell) at level 0xc0000, flags 0x1 [00248.846] 00000.00000> INIT: cpu 0, calling hook 0xffffffff0020383c (ktrace) at level 0xc0000, flags 0x1 [00248.849] 00000.00000> ktrace: buffer at 0xffffff966efcf000 (33554432 bytes) [00248.849] 00000.00000> INIT: cpu 0, calling hook 0xffffffff00216470 (userboot) at level 0xc0000, flags 0x1 [00248.849] 00000.00000> userboot: ramdisk 0xba3000 @ 0xffffff80093d7000 [00248.850] 00000.00000> userboot: userboot rodata 0 @ [0x4a70168af000,0x4a70168b2000) [00248.850] 00000.00000> userboot: userboot code 0x3000 @ [0x4a70168b2000,0x4a70168bd000) [00248.850] 00000.00000> userboot: vdso/full rodata 0 @ [0x4a70168bd000,0x4a70168c4000) [00248.850] 00000.00000> userboot: vdso/full code 0x7000 @ [0x4a70168c4000,0x4a70168c5000) [00248.850] 00000.00000> userboot: entry point @ 0x4a70168b2c90 [00248.850] 01036.01043> userboot: option "zircon.autorun.system=/boot/bin/sh+/boot/infra/runcmds" [00248.878] 01036.01043> userboot: searching bootfs for 'bin/bootsvc' [00248.878] 01036.01043> userboot: 'bin/bootsvc' has PT_INTERP "lib/ld.so.1" [00248.878] 01036.01043> userboot: searching bootfs for 'lib/ld.so.1' [00248.878] 01036.01043> userboot: userboot: loaded lib/ld.so.1 at 0x737d25f64000, entry point 0x737d25f823e0 [00248.878] 01036.01043> userboot: userboot: loaded vDSO at 0x79b3fc2ce000, entry point 0x79b3fc2d5907 [00248.878] 01036.01043> userboot: process bin/bootsvc started. [00248.878] 01036.01043> userboot: waiting for loader-service requests... [00248.878] 01036.01043> userboot: searching bootfs for 'lib/libasync-default.so' [00248.878] 01036.01043> userboot: searching bootfs for 'lib/libfdio.so' [00248.878] 01036.01043> userboot: searching bootfs for 'lib/libtrace-engine.so' [00248.879] 01036.01043> userboot: searching bootfs for 'lib/liblaunchpad.so' [00248.879] 01050.01053> {{{reset}}} [00248.879] 01050.01053> {{{module:0:<application>:elf:b8a10fabd40dc946723955482070cd89ad5d6f6e}}} [00248.879] 01050.01053> {{{mmap:0x662b26a5b000:0x3a000:load:0:rx:0}}} [00248.879] 01050.01053> {{{mmap:0x662b26a95000:0x4000:load:0:rw:0x3a000}}} [00248.879] 01050.01053> dso: id=b8a10fabd40dc946723955482070cd89ad5d6f6e base=0x0000662b26a5b000 name=<application> [00248.879] 01050.01053> {{{module:0x2:<vDSO>:elf:2596d83da12ef9224f4df627b37dddb0f871b655}}} [00248.879] 01050.01053> {{{mmap:0x79b3fc2ce000:0x7000:load:0x2:r:0}}} [00248.879] 01050.01053> {{{mmap:0x79b3fc2d5000:0x1000:load:0x2:rx:0x7000}}} [00248.879] 01050.01053> dso: id=2596d83da12ef9224f4df627b37dddb0f871b655 base=0x000079b3fc2ce000 name=<vDSO> [00248.879] 01050.01053> {{{module:0x3:libasync-default.so:elf:a1ebd820a8fe8a159e7eb0ad92ab9f7dcf4c728e}}} [00248.879] 01050.01053> {{{mmap:0x4141c424d000:0x1000:load:0x3:rx:0}}} [00248.879] 01050.01053> {{{mmap:0x4141c424e000:0x1000:load:0x3:rw:0x1000}}} [00248.879] 01050.01053> dso: id=a1ebd820a8fe8a159e7eb0ad92ab9f7dcf4c728e base=0x00004141c424d000 name=libasync-default.so [00248.879] 01050.01053> {{{module:0x4:libfdio.so:elf:e0d689c514dd90434528ba82d0bd7b842ef42be6}}} [00248.879] 01050.01053> {{{mmap:0x1169ebb71000:0x32000:load:0x4:rx:0}}} [00248.879] 01050.01053> {{{mmap:0x1169ebba4000:0x4000:load:0x4:rw:0x33000}}} [00248.879] 01050.01053> dso: id=e0d689c514dd90434528ba82d0bd7b842ef42be6 base=0x00001169ebb71000 name=libfdio.so [00248.879] 01050.01053> {{{module:0x5:libtrace-engine.so:elf:5cf99e00b68e3cfa41dfd874cffe13a69dfd4c37}}} [00248.879] 01050.01053> {{{mmap:0x6aa0b108d000:0x9000:load:0x5:rx:0}}} [00248.879] 01050.01053> {{{mmap:0x6aa0b1096000:0x2000:load:0x5:rw:0x9000}}} [00248.879] 01050.01053> dso: id=5cf99e00b68e3cfa41dfd874cffe13a69dfd4c37 base=0x00006aa0b108d000 name=libtrace-engine.so [00248.879] 01050.01053> {{{module:0x6:liblaunchpad.so:elf:a1c266341f7802b66afac60326dec9b419057b49}}} [00248.879] 01050.01053> {{{mmap:0x357f8d9d9000:0x7000:load:0x6:rx:0}}} [00248.879] 01050.01053> {{{mmap:0x357f8d9e0000:0x2000:load:0x6:rw:0x7000}}} [00248.879] 01050.01053> dso: id=a1c266341f7802b66afac60326dec9b419057b49 base=0x0000357f8d9d9000 name=liblaunchpad.so [00248.879] 01050.01053> {{{module:0x1:libc.so:elf:8de7cb63945a526403ca2b041e14473d5b67c4f2}}} [00248.879] 01050.01053> {{{mmap:0x737d25f64000:0xa6000:load:0x1:rx:0}}} [00248.879] 01050.01053> {{{mmap:0x737d2600a000:0x5000:load:0x1:rw:0xa6000}}} [00248.879] 01050.01053> dso: id=8de7cb63945a526403ca2b041e14473d5b67c4f2 base=0x0000737d25f64000 name=libc.so [00248.879] 01050.01053> bootsvc: Starting... [00248.879] 01036.01043> userboot: loader-service channel peer closed [00248.879] 01036.01043> userboot: finished! [00248.879] 01050.01053> bootsvc: Creating bootfs service... [00248.879] 01050.01053> bootsvc: Retrieving boot image... [00248.879] 01050.01053> bootsvc: Decommitted BOOTDATA VMO from 0 to 0xba2000 [00248.879] 01050.01053> bootsvc: Loading boot arguments... [00248.879] 01050.01053> bootsvc: Creating svcfs service... [00248.879] 01050.01053> bootsvc: Loading kernel VMOs... [00248.879] 01050.01053> bootsvc: Creating loader service... [00248.879] 01050.01053> bootsvc: Launching next process... [00248.880] 01050.01108> bootsvc: Launched bin/devcoordinator [00248.881] 01115.01130> devcoordinator: launch /boot/bin/svchost (svchost) OK [00248.882] 01115.01130> devcoordinator: launch /boot/bin/fshost (fshost) OK [00248.884] 01115.01323> devcoordinator: launch /boot/bin/pwrbtn-monitor (pwrbtn-monitor) OK [00248.884] 01115.01348> devcoordinator: launch /boot/bin/netsvc (netsvc) OK [00248.884] 01115.01348> devcoordinator: launch /boot/bin/virtual-console (virtual-console) OK [00248.888] 01115.01130> devcoordinator: full system required, ignoring fallback drivers until /system is loaded [00248.888] 01115.01130> devcoordinator: launch devhost 'devhost:sys': pid=2179 [00248.888] 01115.01130> devcoordinator: launch devhost 'devhost:test': pid=2211 [00248.889] 01115.01130> devcoordinator: launch devhost 'devhost:root': pid=2258 [00248.889] 01115.01130> devcoordinator: launch devhost 'devhost:misc': pid=2308 [00248.889] 02179.02193> devhost: trace provider registry begun [00248.890] 02211.02233> devhost: trace provider registry begun [00248.890] 02258.02285> devhost: trace provider registry begun [00248.891] 02308.02341> devhost: trace provider registry begun [00248.892] 01115.01335> devcoordinator: launch /boot/bin/sh (sh:console) OK [00248.974] 02179.02193> acpi-bus: not using IOMMU [00248.981] 02179.02193> PMU: 7 arch events [00248.981] 02179.02193> PMU: arch event id range: 1-7 [00248.981] 02179.02193> PMU: 102 arch events [00248.981] 02179.02193> PMU: arch event id range: 1-241 [00248.981] 02179.02193> Intel Processor Trace configuration for this chipset: [00248.981] 02179.02193> mtc_freq_mask: 0x249 [00248.981] 02179.02193> cyc_thresh_mask: 0x3fff [00248.981] 02179.02193> psb_freq_mask: 0x3f [00248.981] 02179.02193> num addr ranges: 2 [00248.982] 02179.02193> [sysmem_init 28] async_get_default_dispatcher(): 0x32e9d5bcec10 [00248.982] 02179.02193> [sysmem_bind 40] sysmem_bind() [00248.982] 02179.02868> acpi-pwrbtn: initialized [00248.982] 01703.01728> vc: new input device /dev/class/input/000 [00248.991] 02179.02868> WARNING: ACPI found bad _CRS address entry [00249.001] 02179.02868> WARNING: ACPI found bad _CRS address entry [00249.013] 02179.02868> acpi: published device pci(0x32e915bec310), parent=sys(0x32ea55bd2310), handle=0x32e8d5be6810 [00249.013] 01115.01130> devcoordinator: launch devhost 'devhost:pci#1:8086:5916': pid=2964 [00249.014] 01115.01130> devcoordinator: launch devhost 'devhost:pci#3:8086:9d2f': pid=3022 [00249.014] 02964.02978> devhost: trace provider registry begun [00249.015] 03022.03048> devhost: trace provider registry begun [00249.015] 01115.01130> devcoordinator: launch devhost 'devhost:pci#5:8086:9d60': pid=3151 [00249.015] 01115.01130> devcoordinator: launch devhost 'devhost:pci#6:8086:9d61': pid=3214 [00249.016] 03151.03179> devhost: trace provider registry begun [00249.016] 01115.01130> devcoordinator: launch devhost 'devhost:pci#9:8086:9d03': pid=3316 [00249.016] 03214.03237> devhost: trace provider registry begun [00249.017] 02179.02868> acpi: published device rtc(0x32e915bec370), parent=acpi(0x32ea55bd1c10), handle=0x32e8d5c0e490 [00249.018] 02179.02868> acpi-ec: initialized [00249.018] 01115.01130> devcoordinator: launch devhost 'devhost:pci#14:8086:9d71': pid=3500 [00249.019] 01115.01130> devcoordinator: launch devhost 'devhost:pci#16:8086:156f': pid=3561 [00249.019] 03316.03367> devhost: trace provider registry begun [00249.022] 02179.02868> acpi: failed to create NHLT VMO (res -10) [00249.022] 02179.02868> acpi: failed to publish NHLT metadata [00249.026] 03316.03367> ahci: using MSI interrupt [00249.026] 03214.03237> initialized intel serialio i2c driver, reg=0x49bb51621000 regsize=4096 [00249.026] 03151.03179> initialized intel serialio i2c driver, reg=0x15fec25a7000 regsize=4096 [00249.029] 03500.03514> devhost: trace provider registry begun [00249.030] 03561.03595> devhost: trace provider registry begun [00249.032] 03500.03514> [IHDA DSP 00:1f.3] Failed to fetch NHLT (res -25) [00249.032] 03500.03514> [IHDA Controller 00:1f.3] Failed to initialize DSP device (res = -25) [00249.033] 03022.03938> * found USB device (0x18d1:0xa002, USB 2.0) config 1 [00249.033] 03022.03938> * found USB device (0x18d1:0xa003, USB 3.0) config 1 [00249.104] 01619.01643> netifc: ? /dev/class/ethernet/000 [00249.104] 01619.01643> netifc: create 512 eth buffers [00249.104] 01619.01643> macaddr: d4:5d:df:1a:42:46 [00249.104] 01619.01643> ip6addr: fe80::d65d:df4d:fe1a:4246 [00249.104] 01619.01643> snmaddr: ff02::1:ff1a:4246 [00249.104] 01619.01643> netsvc: using /dev/class/ethernet/000 [00249.104] 01619.01643> netsvc: nodename='ocean-drank-wick-spot' [00249.104] 01619.01643> netsvc: start [00249.132] 01703.01728> vc: new display device /dev/class/display-controller/000 [00249.173] 02964.04232> i915: Found DP monitor [00249.173] 02964.04232> i915: Display 1 connected [00249.173] 02964.04232> i915: MST not supported [00249.745] 03022.03938> * found USB device (0x0781:0x5583, USB 3.0) config 1 [00250.239] 01703.01728> vc: Successfully attached to display 1 [00250.499] 03022.03938> * found USB device (0x046d:0xc31c, USB 1.10) config 1 [00250.746] 03022.03938> * found USB device (0x0cf3:0xe300, USB 2.1) config 1 [00251.029] 03214.03237> intel-i2c-controller: intel_serialio_i2c_slave_transfer: -21 [00251.029] 03214.03237> i2c-hid: could not read HID descriptor: 0 [00251.029] 03214.03237> devhost[00:15.1/i2c-bus-9d61/004c] bind driver '/boot/driver/i2c-hid.so' failed: -2 [00251.030] 01115.01130> devcoordinator: rpc: bind-driver '004c' status -2 [00251.030] 03151.03179> intel-i2c-controller: intel_serialio_i2c_slave_transfer: -21 [00251.030] 03151.03179> i2c-hid: could not read HID descriptor: 0 [00251.030] 03151.03179> devhost[00:15.0/i2c-bus-9d60/0020] bind driver '/boot/driver/i2c-hid.so' failed: -2 [00251.030] 01115.01130> devcoordinator: rpc: bind-driver '0020' status -2 [00251.044] 03316.03852> sata2: dev info [00251.044] 03316.03852> serial=711430952084 9 [00251.044] 03316.03852> firmware rev=1Q01A7 0 [00251.044] 03316.03852> model id=IBIW NSS D [00251.044] 03316.03852> major=0x3f0 ACS2 DMA 32 commands [00251.044] 03316.03852> LBA48 234441648 sectors, sector size=512 [00251.045] 01301.01315> fshost: /dev/class/block/000: GPT? [00251.045] 03316.03367> gpt: device_get_metadata failed (-25) [00251.046] 01301.01315> fshost: /dev/class/block/001: FVM? [00251.049] 01301.01315> devcoordinator: launch /boot/bin/blobfs (blobfs:/blob) OK [00251.199] 01301.01315> fshost: starting 'bin/pkgsvr' 'b5f89b82a38b5d408cd9cee852c39609992c43416b6625dda4b296a445b4fc38'... [00251.206] 01301.01315> devcoordinator: launch bin/pkgsvr (pkgfs) OK [00251.217] 04666.04877> pkgsvr: system: will be served from b5f89b82a38b5d408cd9cee852c39609992c43416b6625dda4b296a445b4fc38 [00251.217] 04666.04877> pkgsvr: pkgfs serving index /data/pkgfs_index from blobfs /blob [00251.217] 01301.01315> fshost: /dev/class/block/005: zxcrypt? [00251.218] 03316.03367> devhost_get_handles(0x2dbe821f0310:block) open path='zxcrypt', r=-2 [00251.223] 01301.01315> fshost: mounting minfs [00251.224] 01301.01315> devcoordinator: launch /boot/bin/minfs (minfs:/data) OK [00251.225] 05076.05090> minfs: filesystem in clean state. [00251.233] 01115.04928> devcoordinator: adding system driver 'qmi_usb' '/system/driver/qmi-transport.so' [00251.269] 01115.01738> devcoordinator: launch /system/bin/appmgr (appmgr) OK [00251.269] 01115.01738> autorun: starting '/boot/bin/sh' '/boot/infra/runcmds'... [00251.270] 01115.01738> devcoordinator: launch /boot/bin/sh (autorun:system) OK [00251.285] 01115.04928> devcoordinator: adding system driver 'usb_video' '/system/driver/usb_video.so' [00251.295] 01115.04928> devcoordinator: adding system driver 'wlan' '/system/driver/wlanif.so' [00251.329] 01115.04928> devcoordinator: adding system driver 'bt_hci_intel' '/system/driver/bt-hci-intel.so' [00251.334] 01115.04928> devcoordinator: adding system driver 'bt_hci_passthrough' '/system/driver/bt-hci-passthrough.so' [00251.366] 01115.04928> devcoordinator: adding system driver 'bt_host' '/system/driver/bt-host.so' [00251.376] 01115.04928> devcoordinator: adding system driver 'rtl88xx' '/system/driver/rtl88xx.so' [00251.390] 01115.04928> devcoordinator: adding system driver 'wlan' '/system/driver/wlanphy.so' [00251.404] 01115.04928> devcoordinator: adding system driver 'bt_hci_fake' '/system/driver/bt-hci-fake.so' [00251.414] 01115.04928> devcoordinator: adding system driver 'magma_pdev_gpu' '/system/driver/libmsd_arm.so' [00251.431] 01115.04928> devcoordinator: adding system driver 'mt8167s_gpu' '/system/driver/libmsd_img_rgx_mtk.so' [00251.436] 01115.04928> devcoordinator: adding system driver 'ath10k_pci' '/system/driver/ath10k.so' [00251.438] 01115.04928> devcoordinator: adding system driver 'bt_hog' '/system/driver/bt-hog.so' [00251.441] 01115.04928> devcoordinator: adding system driver 'iwlwifi_pci' '/system/driver/iwlwifi.so' [00251.500] 01115.04928> devcoordinator: adding system driver 'ralink' '/system/driver/ralink.so' [00251.515] 01115.04928> devcoordinator: adding system driver 'virtual_camera' '/system/driver/virtual_camera_driver.so' [00251.577] 01115.04928> devcoordinator: adding system driver 'wlan' '/system/driver/wlan.so' [00251.591] 05220.05238> [INFO:namespace_builder.cc(44)] config-data for sysmgr [00251.617] 01115.04928> devcoordinator: adding system driver 'bt_hci_atheros' '/system/driver/bt-hci-atheros.so' [00251.627] 01115.04928> devcoordinator: adding system driver 'gpu' '/system/driver/libmsd_intel.so' [00251.636] 01115.04928> devcoordinator: adding system driver 'virtual_audio' '/system/driver/virtual_audio_driver.so' [00251.644] 01115.04928> devcoordinator: adding system driver 'brcmfmac' '/system/driver/brcmfmac.so' [00251.649] 01115.04928> devcoordinator: adding system driver 'qmi_fake' '/system/driver/qmi-fake.so' [00251.649] 01115.01130> devcoordinator: driver 'qmi_fake' added [00251.649] 01115.01130> devcoordinator: driver 'brcmfmac' added [00251.650] 01115.01130> devcoordinator: driver 'gpu' added [00251.650] 01115.01130> devcoordinator: driver 'bt_hci_atheros' added [00251.650] 01115.01130> devcoordinator: driver 'wlan' added [00251.650] 01115.01130> devcoordinator: driver 'ralink' added [00251.650] 01115.01130> devcoordinator: driver 'iwlwifi_pci' added [00251.650] 01115.01130> devcoordinator: driver 'bt_hog' added [00251.650] 01115.01130> devcoordinator: driver 'ath10k_pci' added [00251.651] 01115.01130> devcoordinator: launch devhost 'devhost:pci#11:168c:003e': pid=5990 [00251.651] 01115.01130> devcoordinator: driver 'mt8167s_gpu' added [00251.651] 01115.01130> devcoordinator: driver 'magma_pdev_gpu' added [00251.651] 01115.01130> devcoordinator: driver 'bt_hci_fake' added [00251.651] 01115.01130> devcoordinator: driver 'wlan' added [00251.651] 01115.01130> devcoordinator: driver 'rtl88xx' added [00251.651] 01115.01130> devcoordinator: driver 'bt_host' added [00251.651] 01115.01130> devcoordinator: driver 'bt_hci_intel' added [00251.651] 01115.01130> devcoordinator: driver 'wlan' added [00251.651] 01115.01130> devcoordinator: driver 'usb_video' added [00251.651] 01115.01130> devcoordinator: driver 'qmi_usb' added [00251.651] 01115.01130> devcoordinator: driver 'bt_hci_passthrough' added [00251.651] 01115.01130> devcoordinator: fallback driver 'usb_composite' is available [00251.651] 01115.01130> devcoordinator: driver 'usb_composite' added [00251.651] 01115.01130> devcoordinator: fallback driver 'intel_disp' is available [00251.651] 01115.01130> devcoordinator: driver 'intel_disp' added [00251.652] 05990.06010> devhost: trace provider registry begun [00251.653] 05990.06010> ath10k: Probed chip QCA6174 ver: 2.1 [00251.657] 03022.03048> UMS: parent: 'ifc-000' [00251.657] 03022.03048> UMS:Max lun is: 0 [00251.664] 03022.03048> devhost[00:14.0/xhci/usb-bus/003/003/ifc-001] bind driver '/boot/driver/bt-transport-usb.so' failed: -2 [00251.664] 01115.01130> devcoordinator: rpc: bind-driver 'ifc-001' status -2 [00251.667] 03022.06837> UMS: block size is: 0x00000200 [00251.667] 03022.06837> UMS: total blocks is: 30031250 [00251.667] 03022.06837> UMS: total size is: 15376000000 [00251.667] 03022.06837> UMS: read-only: 0 removable: 1 [00251.723] 03022.10612> btatheros: Making visible [00251.723] 03022.10612> btatheros: loaded successfully [00251.725] 03022.10723> [INFO:command_channel.cc(149)] hci: initialized [00251.725] 01301.01315> fshost: /dev/class/block/007: MBR? [00251.731] 01301.01315> fshost: /dev/class/block/009: MBR? [00251.742] 05220.05238> [INFO:namespace_builder.cc(44)] config-data for amber [00251.797] 03022.10723> [WARN:adapter.cc(273)] gap: controller is using legacy HCI version 4.1 [00251.803] 03022.10723> [INFO:acl_data_channel.cc(91)] hci: initialized [00251.818] 05220.05238> [INFO:namespace_builder.cc(44)] config-data for pkg_resolver [00251.901] 01703.01728> vc: new input device /dev/class/input/001 [00251.901] 01703.01728> vc: new input device /dev/class/input/002 [00251.943] 13589.13601> [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 [00251.943] 13589.13601> kfill_days=2, start_event_aggregator_worker=1. [00252.035] 05220.05238> [INFO:namespace_builder.cc(44)] config-data for mdns [00252.059] 05990.13468> devhost: rpc:load-firmware failed: -25 [00252.059] 05990.13468> devhost: rpc:load-firmware failed: -25 [00252.067] 05220.05238> [INFO:namespace_builder.cc(44)] config-data for wlancfg [00252.279] 05220.05238> [INFO:namespace_builder.cc(44)] config-data for crashpad_agent [00252.315] 16816.16828> [INFO:main.cc(35)] Trace Manager starting with config: /pkg/data/tracing.config [00252.334] 15617.15629> [INFO:system_metrics_main.cc(23)] Cobalt SystemMetricsDaemon: System metrics daemon created. [00252.429] 17288.17300> wlanstack2 [I]: Starting [00252.753] 05990.12975> ath10k: Unknown eventid: 0x1d019 [00252.756] 05990.12975> ath10k: Unknown eventid: 0x16006 [00252.761] 05990.06010> wlanphy: event loop started [00252.761] 05990.06010> wlanphy_bind [00252.762] 17288.17300> wlanstack2::device [I]: new phy #0: /dev/sys/pci/01:00.0/ath10k-wlanphy/wlanphy [00252.762] 14837.14862> wlancfg got event: OnPhyAdded { phy_id: 0 } [00252.762] 14837.14862> wlancfg: phy 0 added [00252.762] 17288.17300> wlanstack2::service [I]: query_phy(id = 0) [00252.762] 17288.17300> wlanstack2::service [I]: query_phy(id = 0): received a 'QueryResult' from device [00252.763] 14837.14862> wlancfg: received a PhyInfo from phy #0: path is /dev/sys/pci/01:00.0/ath10k-wlanphy/wlanphy [00252.763] 14837.14862> using default wlan config entry for phy [00252.763] 14837.14862> wlancfg: Creating Client iface for phy 0 [00252.764] 17288.17300> wlanstack2::service [I]: iface #0 started (phy id: 0, local id: 0) [00252.764] 17288.17300> wlanstack2::service [I]: iface's driver does not support SME channels [00252.769] 05990.06010> wlan_bind [00252.770] 05990.06010> ath10k: adding a station interface (vdev_id=0) ... [00252.772] 05990.06010> wlan: [I] Initialize a client MLME. [00252.772] 05990.18166> wlan: [I] starting MainLoop [00252.773] 05990.06010> wlan: [I] channel opened [00252.774] 17288.17300> wlanstack2::device [I]: new iface #0 with role 'Client': /dev/sys/pci/01:00.0/ath10k-wlanphy/ath10k-wlanmac/wlan [00252.774] 14837.14862> wlancfg got event: OnIfaceAdded { iface_id: 0 } [00252.774] 14837.14862> wlancfg: new iface 0 added successfully [00252.775] 14837.14862> wlancfg: Starting auto-connect loop with 0 saved networks [00253.359] 14517.14529> Starting mDNS on interface ethp001f6 [80fe::5dd6:ffdf:1afe:4642] using port 5356 [00253.359] 14517.14529> [WARNING:garnet/bin/mdns/service/mdns_interface_transceiver_v6.cc(29)] NET-291 IPV6_MULTICAST_LOOP not supported (ENOPROTOOPT), continuing anyway [00253.359] 14517.14529> [WARNING:garnet/bin/mdns/service/mdns_interface_transceiver_v6.cc(50)] NET-2180 IPV6_JOIN_GROUP returned ENODEV, mDNS will not communicate via IPV6 [00253.359] 14517.14529> Starting mDNS on interface ethp001f6 [2ff::100:1aff:4642] using port 5356 [00253.359] 14517.14529> [WARNING:garnet/bin/mdns/service/mdns_interface_transceiver_v6.cc(29)] NET-291 IPV6_MULTICAST_LOOP not supported (ENOPROTOOPT), continuing anyway [00253.360] 14517.14529> [WARNING:garnet/bin/mdns/service/mdns_interface_transceiver_v6.cc(50)] NET-2180 IPV6_JOIN_GROUP returned ENODEV, mDNS will not communicate via IPV6 [00256.823] 14517.14529> Starting mDNS on interface ethp001f6 192.168.42.101 using port 5356 [00256.823] 14517.14529> [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 [00256.823] 14517.14529> Starting mDNS on interface ethp001f6 [2ff::100:1aff:4642] using port 5356 [00256.823] 14517.14529> [WARNING:garnet/bin/mdns/service/mdns_interface_transceiver_v6.cc(29)] NET-291 IPV6_MULTICAST_LOOP not supported (ENOPROTOOPT), continuing anyway [00256.823] 14517.14529> [WARNING:garnet/bin/mdns/service/mdns_interface_transceiver_v6.cc(50)] NET-2180 IPV6_JOIN_GROUP returned ENODEV, mDNS will not communicate via IPV6 [00256.823] 14517.14529> Starting mDNS on interface ethp001f6 [80fe::5dd6:ffdf:1afe:4642] using port 5356 [00256.824] 14517.14529> [WARNING:garnet/bin/mdns/service/mdns_interface_transceiver_v6.cc(29)] NET-291 IPV6_MULTICAST_LOOP not supported (ENOPROTOOPT), continuing anyway [00256.824] 14517.14529> [WARNING:garnet/bin/mdns/service/mdns_interface_transceiver_v6.cc(50)] NET-2180 IPV6_JOIN_GROUP returned ENODEV, mDNS will not communicate via IPV6 [00256.824] 14517.14529> mDNS: Verifying uniqueness of host name ocean-drank-wick-spot.local. [00257.584] 14517.14529> mDNS: Using unique host name ocean-drank-wick-spot.local. Running tests sequentially. [tb] 2019-04-26 04:26:39.314 INFO [SshConnection | 192.168.42.101] Starting master ssh connection. [connection.py:setup_master_ssh:141] [00305.029] 23576.23588> setsockopt IP_TOS 32: Protocol not available: [tb] 2019-04-26 04:26:39.555 INFO [SshConnection | 192.168.42.101] Starting master ssh connection. [connection.py:setup_master_ssh:141] [00305.263] 24150.24164> setsockopt IP_TOS 32: Protocol not available: [tb] 2019-04-26 04:26:40.800 INFO [SshConnection | 192.168.42.101] Starting master ssh connection. [connection.py:setup_master_ssh:141] [00306.507] 25186.25202> setsockopt IP_TOS 32: Protocol not available: [tb] 2019-04-26 04:26:41.053 INFO Controller FuchsiaDevice: [{'ip': '192.168.42.101'}] [base_test.py:register_controller:396] [tb] 2019-04-26 04:26:41.057 INFO ==========> Sl4fSanityTest <========== [base_test.py:run:967] [tb] 2019-04-26 04:26:41.059 INFO Congratulations! Fuchsia controllers have been initialized successfully! [Sl4fSanityTest.py:setup_class:41] [tb] 2019-04-26 04:26:41.061 INFO [Test Case] test_example [base_test.py:exec_one_testcase:662] [tb] 2019-04-26 04:26:41.063 INFO Congratulations! You've run your first test. [Sl4fSanityTest.py:test_example:46] [tb] 2019-04-26 04:26:41.067 INFO [Test Case] test_example PASS [base_test.py:_on_pass:542] [tb] 2019-04-26 04:26:41.071 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-26 04:26:41.079 INFO [SshConnection | 192.168.42.101] Starting master ssh connection. [connection.py:setup_master_ssh:141] [00306.780] 25743.25758> setsockopt IP_TOS 32: Protocol not available: [tb] 2019-04-26 04:26:41.320 INFO [SshConnection | 192.168.42.101] Starting master ssh connection. [connection.py:setup_master_ssh:141] [00307.028] 26323.26339> setsockopt IP_TOS 32: Protocol not available: [tb] 2019-04-26 04:26:42.567 INFO [SshConnection | 192.168.42.101] Starting master ssh connection. [connection.py:setup_master_ssh:141] [00308.270] 27385.27398> setsockopt IP_TOS 32: Protocol not available: [tb] 2019-04-26 04:26:42.816 INFO Controller FuchsiaDevice: [{'ip': '192.168.42.101'}] [base_test.py:register_controller:396] [tb] 2019-04-26 04:26:42.821 INFO ==========> WlanScanTest <========== [base_test.py:run:967] [tb] 2019-04-26 04:26:42.823 INFO [Test Case] test_basic_scan_request [base_test.py:exec_one_testcase:662] [00308.427] 05990.18166> ath10k: starting a hardware scan [tb] 2019-04-26 04:26:48.339 INFO scan contained 56 results [WlanScanTest.py:test_basic_scan_request:86] [tb] 2019-04-26 04:26:48.342 INFO scan time: 5516 ms [WlanScanTest.py:test_basic_scan_request:89] [tb] 2019-04-26 04:26:48.355 INFO [Test Case] test_basic_scan_request PASS [base_test.py:_on_pass:542] [tb] 2019-04-26 04:26:48.357 INFO [Test Case] test_scan_while_connected_open_network [base_test.py:exec_one_testcase:662] [tb] 2019-04-26 04:26:48.359 INFO got the ssid! GoogleGuest [WlanScanTest.py:test_scan_while_connected_open_network:101] [00313.962] 05990.18166> ath10k: starting a hardware scan [00319.463] 05990.18166> ath10k: setting channel (pri: 153, sec: 0, bw: CBW40BELOW) [00319.463] 05990.18166> ath10k: basic setting: phymode 11na-ht40 center_freq=5755 [tb] 2019-04-26 04:26:54.005 INFO connection to network successful [WlanScanTest.py:check_connect_response:58] [00319.516] 05990.18166> ath10k: configuring BSS [00319.516] 05990.18166> ath10k: basic setting: phymode 11na-ht40 center_freq=5755 [00319.597] 05990.18166> ath10k: as a client, configuring an association with an AP [04:BD:88:3F:5C:11] [00319.597] 05990.18166> ath10k: mac peer 04:BD:88:3F:5C:11 phymode 11ac-vht40 [00319.597] 05990.18166> ath10k: setting peer smps mode to none [00319.597] 05990.18166> ath10k: successfully associated with bssid 04:BD:88:3F:5C:11 [00319.599] 05990.18166> wlan: [I] NIC 00:0e:8e:8b:40:ec associated with "GoogleGuest"(04:bd:88:3f:5c:11) in channel 153 CBW40B, 5 GHz, 802.11ac VHT [00319.602] 14517.14529> Starting mDNS on interface ethp001f6 [80fe::5dd6:ffdf:1afe:4642] using port 5356 [00319.602] 14517.14529> [WARNING:garnet/bin/mdns/service/mdns_interface_transceiver_v6.cc(29)] NET-291 IPV6_MULTICAST_LOOP not supported (ENOPROTOOPT), continuing anyway [00319.602] 14517.14529> [WARNING:garnet/bin/mdns/service/mdns_interface_transceiver_v6.cc(50)] NET-2180 IPV6_JOIN_GROUP returned ENODEV, mDNS will not communicate via IPV6 [00319.602] 14517.14529> Starting mDNS on interface ethp001f6 [2ff::100:1aff:4642] using port 5356 [00319.603] 14517.14529> [WARNING:garnet/bin/mdns/service/mdns_interface_transceiver_v6.cc(29)] NET-291 IPV6_MULTICAST_LOOP not supported (ENOPROTOOPT), continuing anyway [00319.603] 14517.14529> [WARNING:garnet/bin/mdns/service/mdns_interface_transceiver_v6.cc(50)] NET-2180 IPV6_JOIN_GROUP returned ENODEV, mDNS will not communicate via IPV6 [00319.603] 14517.14529> Starting mDNS on interface wlanp01 [80fe::e02:ff8e:8bfe:ec40] using port 5356 [00319.603] 14517.14529> [WARNING:garnet/bin/mdns/service/mdns_interface_transceiver_v6.cc(29)] NET-291 IPV6_MULTICAST_LOOP not supported (ENOPROTOOPT), continuing anyway [00319.604] 14517.14529> [WARNING:garnet/bin/mdns/service/mdns_interface_transceiver_v6.cc(50)] NET-2180 IPV6_JOIN_GROUP returned ENODEV, mDNS will not communicate via IPV6 [00319.604] 14517.14529> Starting mDNS on interface wlanp01 [2ff::100:8bff:ec40] using port 5356 [00319.604] 14517.14529> [WARNING:garnet/bin/mdns/service/mdns_interface_transceiver_v6.cc(29)] NET-291 IPV6_MULTICAST_LOOP not supported (ENOPROTOOPT), continuing anyway [00319.604] 14517.14529> [WARNING:garnet/bin/mdns/service/mdns_interface_transceiver_v6.cc(50)] NET-2180 IPV6_JOIN_GROUP returned ENODEV, mDNS will not communicate via IPV6 [00319.614] 05990.18166> ath10k: starting a hardware scan [00321.543] 14517.14529> Starting mDNS on interface ethp001f6 [2ff::100:1aff:4642] using port 5356 [00321.543] 14517.14529> [WARNING:garnet/bin/mdns/service/mdns_interface_transceiver_v6.cc(29)] NET-291 IPV6_MULTICAST_LOOP not supported (ENOPROTOOPT), continuing anyway [00321.543] 14517.14529> [WARNING:garnet/bin/mdns/service/mdns_interface_transceiver_v6.cc(50)] NET-2180 IPV6_JOIN_GROUP returned ENODEV, mDNS will not communicate via IPV6 [00321.544] 14517.14529> Starting mDNS on interface ethp001f6 [80fe::5dd6:ffdf:1afe:4642] using port 5356 [00321.544] 14517.14529> [WARNING:garnet/bin/mdns/service/mdns_interface_transceiver_v6.cc(29)] NET-291 IPV6_MULTICAST_LOOP not supported (ENOPROTOOPT), continuing anyway [00321.544] 14517.14529> [WARNING:garnet/bin/mdns/service/mdns_interface_transceiver_v6.cc(50)] NET-2180 IPV6_JOIN_GROUP returned ENODEV, mDNS will not communicate via IPV6 [00321.544] 14517.14529> Starting mDNS on interface wlanp01 100.110.68.14 using port 5356 [00321.545] 14517.14529> [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 [00321.545] 14517.14529> Starting mDNS on interface wlanp01 [2ff::100:8bff:ec40] using port 5356 [00321.545] 14517.14529> [WARNING:garnet/bin/mdns/service/mdns_interface_transceiver_v6.cc(29)] NET-291 IPV6_MULTICAST_LOOP not supported (ENOPROTOOPT), continuing anyway [00321.545] 14517.14529> [WARNING:garnet/bin/mdns/service/mdns_interface_transceiver_v6.cc(50)] NET-2180 IPV6_JOIN_GROUP returned ENODEV, mDNS will not communicate via IPV6 [00321.545] 14517.14529> Starting mDNS on interface wlanp01 [80fe::e02:ff8e:8bfe:ec40] using port 5356 [00321.546] 14517.14529> [WARNING:garnet/bin/mdns/service/mdns_interface_transceiver_v6.cc(29)] NET-291 IPV6_MULTICAST_LOOP not supported (ENOPROTOOPT), continuing anyway [00321.546] 14517.14529> [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-26 04:27:03.590 INFO scan contained 58 results [WlanScanTest.py:test_basic_scan_request:86] [tb] 2019-04-26 04:27:03.592 INFO scan time: 9584 ms [WlanScanTest.py:test_basic_scan_request:89] [tb] 2019-04-26 04:27:03.606 INFO [Test Case] test_scan_while_connected_open_network PASS [base_test.py:_on_pass:542] [tb] 2019-04-26 04:27:03.608 INFO [Test Case] test_scan_while_connected_wpa2_network [base_test.py:exec_one_testcase:662] [tb] 2019-04-26 04:27:03.610 INFO got the ssid! acts hotspot [WlanScanTest.py:test_scan_while_connected_wpa2_network:114] [00329.198] 05990.18166> wlan: [I] deauthenticating from "GoogleGuest" (04:bd:88:3f:5c:11), reason=36 [00329.198] 05990.18166> ath10k: as a client, clearing the association with an AP [04:BD:88:3F:5C:11] [00329.198] 17288.17300> wlan_sme::client::state [W]: Unexpected MLME message while Idle: DeauthenticateConf { resp: DeauthenticateConfirm { peer_sta_address: [4, 189, 136, 63, 92, 17] } } [00329.200] 14517.14529> Starting mDNS on interface ethp001f6 [80fe::5dd6:ffdf:1afe:4642] using port 5356 [00329.210] 14517.14529> [WARNING:garnet/bin/mdns/service/mdns_interface_transceiver_v6.cc(29)] NET-291 IPV6_MULTICAST_LOOP not supported (ENOPROTOOPT), continuing anyway [00329.210] 14517.14529> [WARNING:garnet/bin/mdns/service/mdns_interface_transceiver_v6.cc(50)] NET-2180 IPV6_JOIN_GROUP returned ENODEV, mDNS will not communicate via IPV6 [00329.210] 14517.14529> Starting mDNS on interface ethp001f6 [2ff::100:1aff:4642] using port 5356 [00329.211] 14517.14529> [WARNING:garnet/bin/mdns/service/mdns_interface_transceiver_v6.cc(29)] NET-291 IPV6_MULTICAST_LOOP not supported (ENOPROTOOPT), continuing anyway [00329.211] 14517.14529> [WARNING:garnet/bin/mdns/service/mdns_interface_transceiver_v6.cc(50)] NET-2180 IPV6_JOIN_GROUP returned ENODEV, mDNS will not communicate via IPV6 [00329.213] 05990.18166> ath10k: starting a hardware scan [00337.105] 17288.17300> wlan_rsn::rsna::esssa [I]: spawned ESSSA for: Supplicant [00337.106] 05990.18166> ath10k: setting channel (pri: 3, sec: 0, bw: CBW20) [00337.111] 05990.18166> ath10k: basic setting: phymode 11ng-ht20 center_freq=2422 [00337.165] 05990.18166> ath10k: configuring BSS [00337.165] 05990.18166> ath10k: basic setting: phymode 11ng-ht20 center_freq=2422 [tb] 2019-04-26 04:27:11.686 INFO connection to network successful [WlanScanTest.py:check_connect_response:58] [00337.259] 05990.18166> ath10k: as a client, configuring an association with an AP [40:4E:36:D1:DC:10] [00337.259] 05990.18166> ath10k: mac peer 40:4E:36:D1:DC:10 phymode 11b [00337.259] 05990.18166> ath10k: successfully associated with bssid 40:4E:36:D1:DC:10 [00337.259] 17288.17300> wlan_rsn::rsna::esssa [I]: resetting ESSSA [00337.259] 17288.17300> wlan_rsn::rsna::esssa [I]: establishing ESSSA... [00337.259] 17288.17300> wlan_rsn::rsna::esssa [I]: established PMKSA [00337.260] 05990.18166> 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 [00337.266] 17288.17300> wlan_rsn::rsna::esssa [I]: established PTKSA [00337.275] 17288.17300> wlan_rsn::rsna::esssa [I]: established GTKSA [00337.275] 17288.17300> wlan_rsn::rsna::esssa [I]: established ESSSA [00337.275] 05990.18166> 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) [00337.276] 05990.18166> 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) [00337.280] 14517.14529> Starting mDNS on interface ethp001f6 [80fe::5dd6:ffdf:1afe:4642] using port 5356 [00337.280] 14517.14529> [WARNING:garnet/bin/mdns/service/mdns_interface_transceiver_v6.cc(29)] NET-291 IPV6_MULTICAST_LOOP not supported (ENOPROTOOPT), continuing anyway [00337.280] 14517.14529> [WARNING:garnet/bin/mdns/service/mdns_interface_transceiver_v6.cc(50)] NET-2180 IPV6_JOIN_GROUP returned ENODEV, mDNS will not communicate via IPV6 [00337.280] 14517.14529> Starting mDNS on interface ethp001f6 [2ff::100:1aff:4642] using port 5356 [00337.281] 14517.14529> [WARNING:garnet/bin/mdns/service/mdns_interface_transceiver_v6.cc(29)] NET-291 IPV6_MULTICAST_LOOP not supported (ENOPROTOOPT), continuing anyway [00337.281] 14517.14529> [WARNING:garnet/bin/mdns/service/mdns_interface_transceiver_v6.cc(50)] NET-2180 IPV6_JOIN_GROUP returned ENODEV, mDNS will not communicate via IPV6 [00337.281] 14517.14529> Starting mDNS on interface wlanp01 [80fe::e02:ff8e:8bfe:ec40] using port 5356 [00337.281] 14517.14529> [WARNING:garnet/bin/mdns/service/mdns_interface_transceiver_v6.cc(29)] NET-291 IPV6_MULTICAST_LOOP not supported (ENOPROTOOPT), continuing anyway [00337.281] 14517.14529> [WARNING:garnet/bin/mdns/service/mdns_interface_transceiver_v6.cc(50)] NET-2180 IPV6_JOIN_GROUP returned ENODEV, mDNS will not communicate via IPV6 [00337.282] 14517.14529> Starting mDNS on interface wlanp01 [2ff::100:8bff:ec40] using port 5356 [00337.282] 14517.14529> [WARNING:garnet/bin/mdns/service/mdns_interface_transceiver_v6.cc(29)] NET-291 IPV6_MULTICAST_LOOP not supported (ENOPROTOOPT), continuing anyway [00337.282] 14517.14529> [WARNING:garnet/bin/mdns/service/mdns_interface_transceiver_v6.cc(50)] NET-2180 IPV6_JOIN_GROUP returned ENODEV, mDNS will not communicate via IPV6 [00337.292] 05990.18166> ath10k: starting a hardware scan [00341.433] 14517.14529> Starting mDNS on interface ethp001f6 [80fe::5dd6:ffdf:1afe:4642] using port 5356 [00341.433] 14517.14529> [WARNING:garnet/bin/mdns/service/mdns_interface_transceiver_v6.cc(29)] NET-291 IPV6_MULTICAST_LOOP not supported (ENOPROTOOPT), continuing anyway [00341.433] 14517.14529> [WARNING:garnet/bin/mdns/service/mdns_interface_transceiver_v6.cc(50)] NET-2180 IPV6_JOIN_GROUP returned ENODEV, mDNS will not communicate via IPV6 [00341.434] 14517.14529> Starting mDNS on interface ethp001f6 [2ff::100:1aff:4642] using port 5356 [00341.434] 14517.14529> [WARNING:garnet/bin/mdns/service/mdns_interface_transceiver_v6.cc(29)] NET-291 IPV6_MULTICAST_LOOP not supported (ENOPROTOOPT), continuing anyway [00341.434] 14517.14529> [WARNING:garnet/bin/mdns/service/mdns_interface_transceiver_v6.cc(50)] NET-2180 IPV6_JOIN_GROUP returned ENODEV, mDNS will not communicate via IPV6 [00341.434] 14517.14529> Starting mDNS on interface wlanp01 192.168.43.147 using port 5356 [00341.435] 14517.14529> [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 [00341.435] 14517.14529> Starting mDNS on interface wlanp01 [80fe::e02:ff8e:8bfe:ec40] using port 5356 [00341.435] 14517.14529> [WARNING:garnet/bin/mdns/service/mdns_interface_transceiver_v6.cc(29)] NET-291 IPV6_MULTICAST_LOOP not supported (ENOPROTOOPT), continuing anyway [00341.435] 14517.14529> [WARNING:garnet/bin/mdns/service/mdns_interface_transceiver_v6.cc(50)] NET-2180 IPV6_JOIN_GROUP returned ENODEV, mDNS will not communicate via IPV6 [00341.435] 14517.14529> Starting mDNS on interface wlanp01 [2ff::100:8bff:ec40] using port 5356 [00341.436] 14517.14529> [WARNING:garnet/bin/mdns/service/mdns_interface_transceiver_v6.cc(29)] NET-291 IPV6_MULTICAST_LOOP not supported (ENOPROTOOPT), continuing anyway [00341.436] 14517.14529> [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-26 04:27:21.323 INFO scan contained 62 results [WlanScanTest.py:test_basic_scan_request:86] [tb] 2019-04-26 04:27:21.326 INFO scan time: 9637 ms [WlanScanTest.py:test_basic_scan_request:89] [tb] 2019-04-26 04:27:21.338 INFO [Test Case] test_scan_while_connected_wpa2_network PASS [base_test.py:_on_pass:542] [tb] 2019-04-26 04:27:21.342 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-26 04:27:21.345 INFO Summary for test run tb@2019-04-26_04-26-36-890: 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), [00346.934] 05990.18166> wlan: [I] deauthenticating from "acts hotspot" (40:4e:36:d1:dc:10), reason=36 [00346.934] 05990.18166> ath10k: as a client, clearing the association with an AP [40:4E:36:D1:DC:10] [00346.934] 17288.17300> wlan_sme::client::state [W]: Unexpected MLME message while Idle: DeauthenticateConf { resp: DeauthenticateConfirm { peer_sta_address: [64, 78, 54, 209, 220, 16] } } [00346.935] 14517.14529> Starting mDNS on interface ethp001f6 [80fe::5dd6:ffdf:1afe:4642] using port 5356 [00346.937] 14517.14529> [WARNING:garnet/bin/mdns/service/mdns_interface_transceiver_v6.cc(29)] NET-291 IPV6_MULTICAST_LOOP not supported (ENOPROTOOPT), continuing anyway [00346.938] 14517.14529> [WARNING:garnet/bin/mdns/service/mdns_interface_transceiver_v6.cc(50)] NET-2180 IPV6_JOIN_GROUP returned ENODEV, mDNS will not communicate via IPV6 [00346.938] 14517.14529> Starting mDNS on interface ethp001f6 [2ff::100:1aff:4642] using port 5356 [00346.938] 14517.14529> [WARNING:garnet/bin/mdns/service/mdns_interface_transceiver_v6.cc(29)] NET-291 IPV6_MULTICAST_LOOP not supported (ENOPROTOOPT), continuing anyway [00346.938] 14517.14529> [WARNING:garnet/bin/mdns/service/mdns_interface_transceiver_v6.cc(50)] NET-2180 IPV6_JOIN_GROUP returned ENODEV, mDNS will not communicate via IPV6 Command succeeded!