DEBUG: config flag: /etc/botanist/config.json
DEBUG: executing command: "/etc/connectivity/host_cmds.sh"
environment of subprocess:
[]
2019/04/20 02:52:58 attempting to send <<netboot>>cmdline...
2019/04/20 02:52:58 done
2019/04/20 02:52:58 attempting to send <<image>>sparse.fvm...
[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.377] 00000.00000> timer features: constant_tsc 1 invariant_tsc 1 tsc_deadline 1
[00018.377] 00000.00000> Using TSC as wallclock
[00018.377] 00000.00000> initializing kernel
[00018.377] 00000.00000> initializing mp
[00018.377] 00000.00000> initializing timers
[00018.377] 00000.00000> INIT: cpu 0, calling hook 0xffffffff0013c578 (debuglog) at level 0x7ffff, flags 0x1
[00018.377] 00000.00000> INIT: cpu 0, calling hook 0xffffffff00195518 (thread_set_priority_experiment) at level 0x7ffff, flags 0x1
[00018.377] 00000.00000> thread set priority experiment is : ENABLED
[00018.377] 00000.00000> INIT: cpu 0, calling hook 0xffffffff001aa67c (global_prng_thread_safe) at level 0x7ffff, flags 0x1
[00018.377] 00000.00000> creating bootstrap completion thread
[00018.720] 00000.00000> top of bootstrap2()
[00018.720] 00000.00000> INIT: cpu 0, calling hook 0xffffffff0013151c (dpc) at level 0x80000, flags 0x1
[00018.733] 00000.00000> INIT: cpu 0, calling hook 0xffffffff00152978 (libobject) at level 0x80000, flags 0x1
[00018.733] 00000.00000> OOM: started thread
[00018.747] 00000.00000> Processor Model Info: type 0 family 0x6 model 0xe stepping 0x9
[00018.747] 00000.00000> display_family 0x6 display_model 0x8e
[00018.747] 00000.00000> Vendor: Intel
[00018.747] 00000.00000> Microarch: Kaby Lake
[00018.747] 00000.00000> F/M/S: 6/8e/9
[00018.747] 00000.00000> Brand: Intel(R) Core(TM) i5-7300U CPU @ 2.60GHz
[00018.747] 00000.00000> Features: fpu sse sse2 sse3 ssse3 sse4.1 sse4.2 mmx avx avx2 fxsr pcid xsave mon aesni clflush
[00018.747] 00000.00000> clflushopt fsgsbase tsc_adj smep smap erms rdrand rdseed syscall nx huge rdtscp
[00018.747] 00000.00000> invar_tsc tsc_deadline x2apic vmx pt hwp
[00018.747] 00000.00000> initializing platform
[00018.747] 00000.00000> INIT: cpu 0, calling hook 0xffffffff001101f4 (x86_perfmon) at level 0x90000, flags 0x1
[00018.747] 00000.00000> PMU: version 4
[00018.747] 00000.00000> UART: started IRQ driven RX
[00018.747] 00000.00000> UART: started IRQ driven TX
[00018.747] 00000.00000> cpu topology:
[00018.747] 00000.00000> 0: apic id 0x0 package 0 node 0 core 0 smt 0 BSP
[00018.747] 00000.00000> 1: apic id 0x2 package 0 node 0 core 1 smt 0
[00018.747] 00000.00000> 2: apic id 0x1 package 0 node 0 core 0 smt 1
[00018.747] 00000.00000> 3: apic id 0x3 package 0 node 0 core 1 smt 1
[00018.747] 00000.00000> Found 4 cpus
[00018.747] 00000.00000> booting apic ids: 0x2 0x1 0x3
[00018.762] 00000.00000> entering scheduler on cpu 2
[00018.763] 00000.00000> entering scheduler on cpu 1
[00018.763] 00000.00000> entering scheduler on cpu 3
[00018.766] 00000.00000> smbios: manufacturer="Intel Corporation" product="NUC7i5DNHE"
[00018.766] 00000.00000> initializing target
[00018.766] 00000.00000> INIT: cpu 0, calling hook 0xffffffff001053a0 (x86_pcie_init) at level 0xa0000, flags 0x1
[00018.766] 00000.00000> moving to last init level
[00018.766] 00000.00000> INIT: cpu 0, calling hook 0xffffffff00144140 (ktrace) at level 0xc0000, flags 0x1
[00018.770] 00000.00000> ktrace: buffer at 0xffffff9668726000 (33554432 bytes)
[00018.770] 00000.00000> INIT: cpu 0, calling hook 0xffffffff00147ab4 (userboot) at level 0xc0000, flags 0x1
[00018.770] 00000.00000> userboot: ramdisk 0x10ad000 @ 0xffffff80012f2000
[00018.770] 00000.00000> userboot: userboot rodata 0 @ [0x1735be4ff000,0x1735be502000)
[00018.770] 00000.00000> userboot: userboot code 0x3000 @ [0x1735be502000,0x1735be50d000)
[00018.770] 00000.00000> userboot: vdso/full rodata 0 @ [0x1735be50d000,0x1735be514000)
[00018.770] 00000.00000> userboot: vdso/full code 0x7000 @ [0x1735be514000,0x1735be515000)
[00018.770] 00000.00000> userboot: entry point @ 0x1735be502c10
[00018.770] 00000.00000> INIT: cpu 0, calling hook 0xffffffff001aa030 (kernel_shell) at level 0xc0000, flags 0x1
[00018.770] 01036.01043> userboot: option "netsvc.disable=true"
[00018.770] 01036.01043> userboot: option "zircon.system.disable-automount=true"
[00018.770] 01036.01043> userboot: option "zircon.autorun.boot=/boot/infra/setup"
[00018.770] 01036.01043> userboot: option "kernel.serial=legacy"
[00018.770] 01036.01043> userboot: option "
http://192.168.42.1/multiboot/d4%3A5d%3Adf%3A1a%3A42%3A46="
[00018.770] 01036.01043> userboot: option "multiboot.boot_loader_name=iPXE+1.0.0++(d2063)"
[00018.809] 01036.01043> userboot: searching bootfs for 'bin/bootsvc'
[00018.809] 01036.01043> userboot: 'bin/bootsvc' has PT_INTERP "lib/ld.so.1"
[00018.809] 01036.01043> userboot: searching bootfs for 'lib/ld.so.1'
[00018.809] 01036.01043> userboot: userboot: loaded lib/ld.so.1 at 0x5b35254a4000, entry point 0x5b352552a0d3
[00018.809] 01036.01043> userboot: userboot: loaded vDSO at 0x7cad23afb000, entry point 0x0
[00018.809] 01036.01043> userboot: process bin/bootsvc started.
[00018.809] 01036.01043> userboot: waiting for loader-service requests...
[00018.810] 01036.01043> userboot: searching bootfs for 'lib/libasync-default.so'
[00018.810] 01036.01043> userboot: searching bootfs for 'lib/libfdio.so'
[00018.810] 01036.01043> userboot: searching bootfs for 'lib/liblaunchpad.so'
[00018.810] 01036.01043> userboot: searching bootfs for 'lib/libtrace-engine.so'
[00018.810] 01050.01053> {{{reset}}}
[00018.810] 01050.01053> {{{module:0:<application>:elf:18de7d58f51e8ba5c4f6afdd0cc8440f482c2b45}}}
[00018.810] 01050.01053> {{{mmap:0x5dadeedfd000:0x2e000:load:0:rx:0}}}
[00018.810] 01050.01053> {{{mmap:0x5dadeee2b000:0x4000:load:0:rw:0x2e000}}}
[00018.810] 01050.01053> dso: id=18de7d58f51e8ba5c4f6afdd0cc8440f482c2b45 base=0x00005dadeedfd000 name=<application>
[00018.810] 01050.01053> {{{module:0x3:libasync-default.so:elf:c189f51f19d10785d93b5235ad1b46dca4451b00}}}
[00018.810] 01050.01053> {{{mmap:0x7a6233ede000:0x1000:load:0x3:rx:0}}}
[00018.810] 01050.01053> {{{mmap:0x7a6233edf000:0x1000:load:0x3:rw:0x1000}}}
[00018.810] 01050.01053> dso: id=c189f51f19d10785d93b5235ad1b46dca4451b00 base=0x00007a6233ede000 name=libasync-default.so
[00018.810] 01050.01053> {{{module:0x2:<vDSO>:elf:40ab5fa3b61f12fef4a44477a687f608661cd450}}}
[00018.810] 01050.01053> {{{mmap:0x7cad23afb000:0x7000:load:0x2:r:0}}}
[00018.810] 01050.01053> {{{mmap:0x7cad23b02000:0x1000:load:0x2:rx:0x7000}}}
[00018.810] 01050.01053> dso: id=40ab5fa3b61f12fef4a44477a687f608661cd450 base=0x00007cad23afb000 name=<vDSO>
[00018.810] 01050.01053> {{{module:0x1:libc.so:elf:67a12284bce140fc32aaaeac223e0e8f85cb5085}}}
[00018.810] 01050.01053> {{{mmap:0x5b35254a4000:0xcb000:load:0x1:rx:0}}}
[00018.810] 01050.01053> {{{mmap:0x5b3525570000:0x6000:load:0x1:rw:0xcc000}}}
[00018.810] 01050.01053> dso: id=67a12284bce140fc32aaaeac223e0e8f85cb5085 base=0x00005b35254a4000 name=libc.so
[00018.810] 01050.01053> {{{module:0x4:libfdio.so:elf:27787977e95f3b9563c9e0bd4d34ec92b7e9ad88}}}
[00018.810] 01050.01053> {{{mmap:0x6b1a669c8000:0x24000:load:0x4:rx:0}}}
[00018.810] 01050.01053> {{{mmap:0x6b1a669ed000:0x4000:load:0x4:rw:0x25000}}}
[00018.810] 01050.01053> dso: id=27787977e95f3b9563c9e0bd4d34ec92b7e9ad88 base=0x00006b1a669c8000 name=libfdio.so
[00018.810] 01050.01053> {{{module:0x5:liblaunchpad.so:elf:6fc2232dc8c1bc5c6adb8ad50ca794b5a260ee4f}}}
[00018.810] 01050.01053> {{{mmap:0x18b65ceb7000:0x7000:load:0x5:rx:0}}}
[00018.810] 01050.01053> {{{mmap:0x18b65cebe000:0x2000:load:0x5:rw:0x7000}}}
[00018.810] 01050.01053> dso: id=6fc2232dc8c1bc5c6adb8ad50ca794b5a260ee4f base=0x000018b65ceb7000 name=liblaunchpad.so
[00018.810] 01050.01053> {{{module:0x6:libtrace-engine.so:elf:c9042b83fe01206008fcefb16395238417248169}}}
[00018.810] 01050.01053> {{{mmap:0x1bc6dd6bd000:0x9000:load:0x6:rx:0}}}
[00018.810] 01050.01053> {{{mmap:0x1bc6dd6c6000:0x2000:load:0x6:rw:0x9000}}}
[00018.810] 01050.01053> dso: id=c9042b83fe01206008fcefb16395238417248169 base=0x00001bc6dd6bd000 name=libtrace-engine.so
[00018.810] 01050.01053> bootsvc: Starting...
[00018.810] 01036.01043> userboot: loader-service channel peer closed
[00018.810] 01036.01043> userboot: finished!
[00018.810] 01050.01053> bootsvc: Creating bootfs service...
[00018.811] 01050.01053> bootsvc: Processing bootdata...
[00018.811] 01050.01053> bootsvc: Loading boot cmdline overrides...
[00018.811] 01050.01053> bootsvc: Loading kernel VMOs...
[00018.811] 01050.01053> bootsvc: Creating loader service...
[00018.811] 01050.01053> bootsvc: Launching next process...
[00018.811] 01050.01096> bootsvc: launched bin/devmgr
[00018.811] 01104.01117> devmgr: main()
[00018.811] 01104.01117> cmdline: netsvc.disable=true
[00018.811] 01104.01117> cmdline: zircon.system.disable-automount=true
[00018.811] 01104.01117> cmdline: zircon.autorun.boot=/boot/infra/setup
[00018.811] 01104.01117> cmdline: kernel.serial=legacy
[00018.811] 01104.01117> cmdline:
http://192.168.42.1/multiboot/d4%3A5d%3Adf%3A1a%3A42%3A46=
[00018.811] 01104.01117> cmdline: multiboot.boot_loader_name=iPXE+1.0.0++(d2063)
[00018.811] 01104.01117> devmgr: coordinator_init()
[00018.812] 01104.01117> devmgr: init
[00018.812] 01104.01117> devmgr: svc init
[00018.812] 01104.01117> devmgr: launch /boot/bin/svchost (svchost) OK
[00018.812] 01104.01117> devmgr: vfs init
[00018.812] 01104.01117> devmgr: launch /boot/bin/fshost (fshost) OK
[00018.812] 01104.01222> devmgr: shell startup
[00018.813] 01182.01202> fshost: started.
[00018.814] 01104.01212> devmgr: launch /boot/bin/pwrbtn-monitor (pwrbtn-monitor) OK
[00018.814] 01104.01230> devmgr: launch /boot/bin/virtual-console (virtual-console) OK
[00018.814] 01104.01230> zircon.autorun.boot: starting '/boot/infra/setup'...
[00018.815] 01104.01230> devmgr: launch /boot/infra/setup (autorun:boot) OK
[00018.817] 01104.01117> devcoord: launch devhost 'devhost:sys': pid=2049
[00018.818] 01104.01117> devcoord: launch devhost 'devhost:test': pid=2082
[00018.818] 01104.01117> devcoord: launch devhost 'devhost:root': pid=2117
[00018.818] 01104.01117> devcoord: launch devhost 'devhost:misc': pid=2168
[00018.819] 02049.02073> devhost: trace provider registry begun
[00018.820] 02082.02106> devhost: trace provider registry begun
[00018.821] 02117.02151> devhost: trace provider registry begun
[00018.822] 02168.02194> devhost: trace provider registry begun
[00018.823] 01104.01222> devmgr: launch /boot/bin/sh (sh:console) OK
[00018.888] 02049.02073> acpi-bus: not using IOMMU
[00018.893] 02049.02073> acpi-pwrbtn: initialized
[00018.899] 02049.02073> WARNING: ACPI found bad _CRS address entry
[00018.905] 02049.02073> WARNING: ACPI found bad _CRS address entry
[00018.916] 02049.02073> acpi: published device pci(0x25a1ba420200), parent=proxy(0x25a1ba41c540), handle=0x25a1ba458750
[00018.917] 02049.02073> acpi: published device rtc(0x25a1ba41b080), parent=acpi(0x25a1ba41c780), handle=0x25a1ba477330
[00018.918] 02049.02073> acpi-ec: initialized
[00018.920] 02049.02073> acpi: failed to create NHLT VMO (res -10)
[00018.920] 02049.02073> acpi: failed to publish NHLT metadata
[00018.922] 02049.02073> [sysmem_init 28] async_get_default_dispatcher(): 0x25a1ba40f0a0
[00018.922] 02049.02073> [sysmem_bind 40] sysmem_bind()
[00018.922] 02049.02073> acpi-bus: sysmem_register_protocol() intentionally ignored for now.
[00018.923] 02049.02073> PMU: 7 arch events
[00018.923] 02049.02073> PMU: arch event id range: 1-7
[00018.923] 02049.02073> PMU: 102 model events
[00018.923] 02049.02073> PMU: model event id range: 1-241
[00018.923] 02049.02073> Intel Processor Trace configuration for this chipset:
[00018.923] 02049.02073> mtc_freq_mask: 0x249
[00018.923] 02049.02073> cyc_thresh_mask: 0x3fff
[00018.923] 02049.02073> psb_freq_mask: 0x3f
[00018.923] 02049.02073> num addr ranges: 2
[00018.923] 01240.01564> vc: new input device /dev/class/input/000
[00018.923] 01104.01117> devcoord: launch devhost 'devhost:pci#1:8086:5916': pid=3021
[00018.924] 01104.01117> devcoord: launch devhost 'devhost:pci#3:8086:9d2f': pid=3089
[00018.924] 01104.01117> devcoord: launch devhost 'devhost:pci#5:8086:9d60': pid=3145
[00018.925] 01104.01117> devcoord: launch devhost 'devhost:pci#6:8086:9d61': pid=3222
[00018.926] 03089.03121> devhost: trace provider registry begun
[00018.926] 03021.03062> devhost: trace provider registry begun
[00018.926] 01104.01117> devcoord: launch devhost 'devhost:pci#9:8086:9d03': pid=3301
[00018.926] 01104.01117> devcoord: launch devhost 'devhost:pci#14:8086:9d71': pid=3411
[00018.927] 03145.03194> devhost: trace provider registry begun
[00018.928] 03222.03258> devhost: trace provider registry begun
[00018.928] 01104.01117> devcoord: launch devhost 'devhost:pci#16:8086:156f': pid=3482
[00018.928] 03301.03356> devhost: trace provider registry begun
[00018.930] 03301.03356> ahci: using MSI interrupt
[00018.930] 03411.03447> devhost: trace provider registry begun
[00018.931] 03145.03194> initialized intel serialio i2c driver, reg=0x157c33698000 regsize=4096
[00018.931] 03222.03258> initialized intel serialio i2c driver, reg=0x3192ffca4000 regsize=4096
[00018.933] 03482.03583> devhost: trace provider registry begun
[00018.943] 03089.03850> * found USB device (0x18d1:0xa002, USB 2.0) config 1
[00018.943] 03089.03850> * found USB device (0x18d1:0xa003, USB 3.0) config 1
[00018.943] 03411.03447> [IHDA DSP 00:1f.3] Failed to fetch NHLT (res -25)
[00018.943] 03411.03447> devhost[00:1f.3/intel-hda-000/intel-sst-dsp-000] bind driver '/boot/driver/dsp.so' failed: -25
[00018.943] 01104.01117> devcoord: rpc: bind-driver 'intel-sst-dsp-000' status -25
[00019.035] 01240.01564> vc: new display device /dev/class/display-controller/000/virtcon
[00019.175] 03021.04139> i915: Found DP monitor
[00019.175] 03021.04139> i915: Display 1 connected
[00019.176] 03021.04139> i915: MST not supported
[00019.655] 03089.03850> * found USB device (0x0781:0x5583, USB 3.0) config 1
[00019.656] 03089.03121> UMS: parent: 'ifc-000'
[00019.656] 03089.03121> UMS:Max lun is: 0
[00020.243] 01240.01564> vc: Successfully attached to display 1
[00020.428] 03089.03850> * found USB device (0x046d:0xc31c, USB 1.10) config 1
[00020.432] 01240.01564> vc: new input device /dev/class/input/001
[00020.437] 01240.01564> vc: new input device /dev/class/input/002
[00020.659] 03089.04226> UMS: block size is: 0x00000200
[00020.659] 03089.04226> UMS: total blocks is: 30031250
[00020.659] 03089.04226> UMS: total size is: 15376000000
[00020.659] 03089.04226> UMS: read-only: 0 removable: 1
[00020.660] 01182.01202> devmgr: /dev/class/block/000: MBR?
[00020.660] 01104.01117> devcoord: dc_bind_device() '/boot/driver/mbr.so'
[00020.662] 01182.01202> devmgr: /dev/class/block/002: MBR?
[00020.662] 01104.01117> devcoord: dc_bind_device() '/boot/driver/mbr.so'
[00020.675] 03089.03850> * found USB device (0x0cf3:0xe300, USB 2.1) config 1
[00020.677] 03089.03121> devhost[00:14.0/xhci/usb-bus/003/003/ifc-001] bind driver '/boot/driver/bt-transport-usb.so' failed: -2
[00020.677] 01104.01117> devcoord: rpc: bind-driver 'ifc-001' status -2
[00020.934] 03222.03258> intel-i2c-controller: intel_serialio_i2c_slave_transfer: -21
[00020.934] 03222.03258> i2c-hid: could not read HID descriptor: 0
[00020.934] 03222.03258> devhost[00:15.1/i2c-bus-9d61/004c] bind driver '/boot/driver/i2c-hid.so' failed: -2
[00020.934] 01104.01117> devcoord: rpc: bind-driver '004c' status -2
[00020.934] 03145.03194> intel-i2c-controller: intel_serialio_i2c_slave_transfer: -21
[00020.934] 03145.03194> i2c-hid: could not read HID descriptor: 0
[00020.934] 03145.03194> devhost[00:15.0/i2c-bus-9d60/0020] bind driver '/boot/driver/i2c-hid.so' failed: -2
[00020.934] 01104.01117> devcoord: rpc: bind-driver '0020' status -2
[00020.947] 03301.03763> sata2: dev info
[00020.947] 03301.03763> serial=711430952084 9
[00020.947] 03301.03763> firmware rev=1Q01A7 0
[00020.947] 03301.03763> model id=IBIW NSS D
[00020.947] 03301.03763> major=0x3f0 ACS2 DMA 32 commands
[00020.947] 03301.03763> LBA48 234441648 sectors, sector size=512
[00020.950] 04586.04600> paver:[InitializeGpt] Located GPT is invalid; Attempting to initialize
[00020.950] 01104.01117> devcoord: dc_bind_device() '/boot/driver/gpt.so'
[00020.950] 03301.03356> gpt: device_get_metadata failed (-25)
[00020.952] 04586.04600> paver:[Initialize] Successfully initialized EFI Device Partitioner
[00020.952] 01104.01117> devcoord: dc_bind_device() ''
[00020.952] 01182.01202> devmgr: /dev/class/block/003: GPT?
[00020.952] 01104.01117> devcoord: dc_bind_device() '/boot/driver/gpt.so'
[00020.952] 03301.03356> gpt: device_get_metadata failed (-25)
[00020.955] 04748.04769> 34+0 records in
[00020.955] 04748.04769> 34+0 records out
[00020.955] 04748.04769> 17408 bytes copied
[00020.956] 04859.04873> Failed to seek on output
[00020.956] 04859.04873> 0+0 records in
[00020.956] 04859.04873> 0+0 records out
[00020.956] 04859.04873> 0 bytes copied
[00020.956] 04929.04943> netifc: ? /dev/class/ethernet/000
[00020.957] 04929.04943> netifc: create 512 eth buffers
[00020.957] 04929.04943> macaddr: d4:5d:df:1a:42:46
[00020.957] 04929.04943> ip6addr: fe80::d65d:df4d:fe1a:4246
[00020.957] 04929.04943> snmaddr: ff02::1:ff1a:4246
[00020.957] 04929.04943> netsvc: using /dev/class/ethernet/000
[00020.957] 04929.04943> _ _ _
[00020.957] 04929.04943> | | | | |
[00020.957] 04929.04943> _______ __| | |__ ___ ___ | |_
[00020.957] 04929.04943> |_ / _ \/ _` | '_ \ / _ \ / _ \| __|
[00020.957] 04929.04943> / / __/ (_| | |_) | (_) | (_) | |_
[00020.957] 04929.04943> /___\___|\__,_|_.__/ \___/ \___/ \__|
[00020.957] 04929.04943>
[00020.957] 04929.04943>
[00020.957] 04929.04943> zedboot: version: 0.7.13
[00020.957] 04929.04943>
[00020.957] 04929.04943> netsvc: nodename='ocean-drank-wick-spot'
[00020.957] 04929.04943> netsvc: will not advertise
[00020.957] 04929.04943> netsvc: start
[00864.475] 04929.04943> netsvc: tftp write of file <<netboot>>cmdline completed
[00864.475] 04929.04943> netsvc: metrics: {"inorderblks": 1,"oooblks": 0,"ack": 1,"nack": 0,"timeouts": 0,"sas": 0,"inorderbytes": 55}
[00864.475] 04929.04943> netsvc: Running FVM Paver
[00864.477] 04929.05037> paver:[InitializeGpt] Located GPT is invalid; Attempting to initialize
[00864.478] 01104.01117> devcoord: dc_bind_device() ''
[00864.478] 01104.01117> devcoord: dc_bind_device() '/boot/driver/gpt.so'
[00864.478] 03301.03356> gpt: device_get_metadata failed (-25)
[00864.478] 01182.01202> devmgr: /dev/class/block/003: GPT?
[00864.479] 01104.01117> devcoord: dc_bind_device() '/boot/driver/gpt.so'
[00864.479] 03301.03356> devhost: rpc:bind-device failed: -20
[00864.479] 04929.05037> paver:[Initialize] Successfully initialized EFI Device Partitioner
[00864.479] 04929.05037> paver:[PartitionPave] Paving partition.
[00864.479] 04929.05037> paver:[FindFirstFit] Looking for space
[00864.479] 04929.05037> paver:[FindFirstFit] Sorting
[00864.479] 04929.05037> paver:[FindFirstFit] Partition[0] From Block [0, 34) ... (next partition starts at block 234441614)
[00864.479] 04929.05037> paver:[FindFirstFit] There are 234441580 free blocks (16777216 requested)
[00864.479] 04929.05037> paver:[AddPartition] Found space in GPT - OK 234441580 @ 34
[00864.479] 04929.05037> paver:[AddPartition] Final space in GPT - OK 16777216 @ 34
[00864.480] 01104.01117> devcoord: dc_bind_device() ''
[00864.480] 04929.05037> paver:[AddPartition] Added partition, waiting for bind
[00864.481] 01182.01202> devmgr: /dev/class/block/003: GPT?
[00864.481] 01104.01117> devcoord: dc_bind_device() '/boot/driver/gpt.so'
[00864.481] 03301.03356> gpt: device_get_metadata failed (-25)
[00864.482] 04929.05037> paver:[AddPartition] Added partition, waiting for bind - OK
[00864.482] 04929.05037> paver:[PartitionPave] Streaming partitions...
[00864.482] 05017.05031> Found compressed file
[00864.482] 04929.05037> paver:[FvmStreamPartitions] Header Validated - OK
[00864.482] 04929.05037> paver:[FvmPartitionFormat] Initializing partition as FVM
[00864.484] 01104.01117> devcoord: dc_bind_device() '/boot/driver/fvm.so'
[00865.486] 04929.05037> paver:[FvmStreamPartitions] Partitions pre-validated successfully: Enough space exists to pave.
[00865.486] 04929.05037> paver:[AllocatePartitions] Allocating partition blobfs consisting of 1 slices
[00865.490] 04929.05037> paver:[AllocatePartitions] Allocating partition minfs consisting of 1 slices
[00865.491] 04929.05037> paver:[AllocatePartitions] Creating zxcrypt volume
[00865.492] 03301.03356> devhost_get_handles(0x7accca0a59c0:block) open path='zxcrypt/block', r=-2
[00865.492] 01104.01117> devcoord: dc_bind_device() '/boot/driver/zxcrypt.so'
[00865.493] 03301.03356> devhost_get_handles(0x7accca0a59c0:block) open path='zxcrypt', r=-2
[00865.497] 04929.05037> paver:[FvmStreamPartitions] Partition space pre-allocated successfully.
[00865.497] 04929.05037> paver:[FvmStreamPartitions] Streaming partition 0
[00865.497] 04929.05037> paver:[StreamFvmPartition] Writing extent 0...
[00865.497] 04929.05043> netsvc: paver write progress 0.2%
[00865.497] 04929.05037> paver:[StreamFvmPartition] 8192 bytes written, 8380416 zeroes left
[00865.521] 04929.05037> paver:[StreamFvmPartition] Writing extent 1...
[00865.521] 04929.05037> paver:[StreamFvmPartition] 8192 bytes written, 8380416 zeroes left
[00865.538] 04929.05037> paver:[StreamFvmPartition] Writing extent 2...
[00865.542] 04929.05037> paver:[StreamFvmPartition] 2097152 bytes written, 6291456 zeroes left
[00865.555] 04929.05037> paver:[StreamFvmPartition] Writing extent 3...
[00865.562] 04929.05037> paver:[StreamFvmPartition] 2097152 bytes written, 6291456 zeroes left
[00865.575] 04929.05037> paver:[StreamFvmPartition] Writing extent 4...
2019/04/20 02:53:00 done
2019/04/20 02:53:00 attempting to send <<image>>bootloader.img...
2019/04/20 02:53:00 target is busy, retrying in one second
[00866.210] 04929.04943> netsvc: tftp write of file <<image>>sparse.fvm completed
[00866.210] 04929.04943> netsvc: metrics: {"inorderblks": 164918,"oooblks": 0,"ack": 645,"nack": 0,"timeouts": 0,"sas": 0,"inorderbytes": 168875087}
[00866.211] 04929.05037> paver:[StreamFvmPartition] 182108160 bytes written, 2441216 zeroes left
[00866.216] 04929.05037> paver:[FvmStreamPartitions] Done streaming partition 0
[00866.216] 04929.05037> paver:[FvmStreamPartitions] Done flushing partition 0
[00866.216] 04929.05037> paver:[FvmStreamPartitions] Streaming partition 1
[00866.216] 04929.05037> paver:[StreamFvmPartition] Writing extent 0...
[00866.216] 04929.05037> paver:[StreamFvmPartition] 8192 bytes written, 8380416 zeroes left
[00866.257] 04929.05037> paver:[StreamFvmPartition] Writing extent 1...
[00866.258] 04929.05037> paver:[StreamFvmPartition] 65536 bytes written, 8323072 zeroes left
[00866.296] 04929.05037> paver:[StreamFvmPartition] Writing extent 2...
[00866.297] 04929.05037> paver:[StreamFvmPartition] 65536 bytes written, 8323072 zeroes left
[00866.334] 04929.05037> paver:[StreamFvmPartition] Writing extent 3...
[00866.372] 04929.05037> paver:[StreamFvmPartition] Writing extent 4...
[00866.382] 04929.05037> paver:[StreamFvmPartition] 2097152 bytes written, 14680064 zeroes left
[00866.446] 04929.05037> paver:[StreamFvmPartition] Writing extent 5...
[00866.447] 04929.05037> paver:[StreamFvmPartition] 57344 bytes written, 8331264 zeroes left
[00866.482] 04929.05037> paver:[FvmStreamPartitions] Done streaming partition 1
[00866.482] 04929.05037> paver:[FvmStreamPartitions] Done flushing partition 1
[00866.484] 05017.05031> Reading FVM from compressed file: true
[00866.484] 05017.05031> Remaining bytes read into compression buffer: 0
[00866.484] 05017.05031> Remaining bytes written to decompression buffer: 0
[00866.484] 05017.05031> Time reading bytes from sparse FVM file: 603861839 (0 s)
[00866.484] 05017.05031> Time reading bytes AND decompressing them: 701544350 (0 s)
[00866.484] 04929.05037> paver:[PartitionPave] Completed successfully
2019/04/20 02:53:01 attempting to send <<image>>bootloader.img...
2019/04/20 02:53:01 done
2019/04/20 02:53:01 attempting to send <<image>>zircona.img...
[00867.211] 04929.04943> netsvc: Running BOOTLOADER Paver
[00867.214] 04929.05773> paver:[Initialize] Successfully initialized EFI Device Partitioner
[00867.214] 04929.05773> paver:[RealMain] SKIPPING BOOTLOADER install on x64 device, pass --force if desired.
[00867.230] 04929.04943> netsvc: tftp write of file <<image>>bootloader.img completed
[00867.230] 04929.04943> netsvc: metrics: {"inorderblks": 1093,"oooblks": 0,"ack": 5,"nack": 0,"timeouts": 0,"sas": 0,"inorderbytes": 1118208}
[00867.230] 04929.04943> netsvc: Running ZIRCON-A Paver
[00867.233] 04929.05914> paver:[Initialize] Successfully initialized EFI Device Partitioner
[00867.233] 04929.05914> paver:[PartitionPave] Paving partition.
[00867.233] 04929.05914> paver:[FindFirstFit] Looking for space
[00867.233] 04929.05914> paver:[FindFirstFit] Partition seen with start 34, end 16777249 (length 16777216)
[00867.233] 04929.05914> paver:[FindFirstFit] Sorting
[00867.233] 04929.05914> paver:[FindFirstFit] Partition[0] From Block [0, 34) ... (next partition starts at block 34)
[00867.233] 04929.05914> paver:[FindFirstFit] There are 0 free blocks (32768 requested)
[00867.233] 04929.05914> paver:[FindFirstFit] Partition[1] From Block [34, 16777250) ... (next partition starts at block 234441614)
[00867.233] 04929.05914> paver:[FindFirstFit] There are 217664364 free blocks (32768 requested)
[00867.233] 04929.05914> paver:[AddPartition] Found space in GPT - OK 217664364 @ 16777250
[00867.233] 04929.05914> paver:[AddPartition] Final space in GPT - OK 32768 @ 16777250
[00867.234] 03301.03356> block: Joining un-closed FIFO server
[00867.234] 04929.05914> paver:[AddPartition] Added partition, waiting for bind
[00867.234] 03301.03356> block: Joining un-closed FIFO server
[00867.234] 01104.01117> devcoord: dc_bind_device() ''
[00867.235] 01182.01202> devmgr: /dev/class/block/003: GPT?
[00867.235] 01104.01117> devcoord: dc_bind_device() '/boot/driver/gpt.so'
[00867.235] 03301.03356> gpt: device_get_metadata failed (-25)
[00867.236] 01182.01202> devmgr: /dev/class/block/008: FVM?
[00867.236] 01104.01117> devcoord: dc_bind_device() '/boot/driver/fvm.so'
[00867.236] 04929.05914> paver:[AddPartition] Added partition, waiting for bind - OK
2019/04/20 02:53:01 done
2019/04/20 02:53:01 attempting to send <<image>>zirconr.img...
2019/04/20 02:53:01 target is busy, retrying in one second
[00867.391] 04929.04943> netsvc: tftp write of file <<image>>zircona.img completed
[00867.391] 04929.04943> netsvc: metrics: {"inorderblks": 13901,"oooblks": 0,"ack": 55,"nack": 0,"timeouts": 0,"sas": 0,"inorderbytes": 14234040}
[00867.426] 04929.05914> paver:[PartitionPave] Completed successfully
2019/04/20 02:53:02 attempting to send <<image>>zirconr.img...
[00868.392] 04929.04943> netsvc: Running ZIRCON-R Paver
[00868.395] 04929.06187> paver:[Initialize] Successfully initialized EFI Device Partitioner
[00868.395] 04929.06187> paver:[PartitionPave] Paving partition.
[00868.395] 04929.06187> paver:[FindFirstFit] Looking for space
[00868.395] 04929.06187> paver:[FindFirstFit] Partition seen with start 34, end 16777249 (length 16777216)
[00868.395] 04929.06187> paver:[FindFirstFit] Partition seen with start 16777250, end 16810017 (length 32768)
[00868.395] 04929.06187> paver:[FindFirstFit] Sorting
[00868.395] 04929.06187> paver:[FindFirstFit] Partition[0] From Block [0, 34) ... (next partition starts at block 34)
[00868.395] 04929.06187> paver:[FindFirstFit] There are 0 free blocks (49152 requested)
[00868.395] 04929.06187> paver:[FindFirstFit] Partition[1] From Block [34, 16777250) ... (next partition starts at block 16777250)
[00868.395] 04929.06187> paver:[FindFirstFit] There are 0 free blocks (49152 requested)
[00868.395] 04929.06187> paver:[FindFirstFit] Partition[2] From Block [16777250, 16810018) ... (next partition starts at block 234441614)
[00868.395] 04929.06187> paver:[FindFirstFit] There are 217631596 free blocks (49152 requested)
[00868.395] 04929.06187> paver:[AddPartition] Found space in GPT - OK 217631596 @ 16810018
[00868.395] 04929.06187> paver:[AddPartition] Final space in GPT - OK 49152 @ 16810018
[00868.396] 04929.06187> paver:[AddPartition] Added partition, waiting for bind
[00868.396] 03301.03356> block: Joining un-closed FIFO server
[00868.396] 01104.01117> devcoord: dc_bind_device() ''
[00868.397] 01182.01202> devmgr: /dev/class/block/003: GPT?
[00868.397] 01104.01117> devcoord: dc_bind_device() '/boot/driver/gpt.so'
[00868.397] 03301.03356> gpt: device_get_metadata failed (-25)
[00868.398] 01182.01202> devmgr: /dev/class/block/012: FVM?
[00868.398] 01104.01117> devcoord: dc_bind_device() '/boot/driver/fvm.so'
[00868.398] 04929.06187> paver:[AddPartition] Added partition, waiting for bind - OK
2019/04/20 02:53:03 done
2019/04/20 02:53:03 attempting to send <<image>>authorized_keys...
2019/04/20 02:53:03 target is busy, retrying in one second
[00868.553] 04929.04943> netsvc: tftp write of file <<image>>zirconr.img completed
[00868.553] 04929.04943> netsvc: metrics: {"inorderblks": 12590,"oooblks": 0,"ack": 50,"nack": 0,"timeouts": 0,"sas": 0,"inorderbytes": 12891216}
[00868.583] 04929.06187> paver:[PartitionPave] Completed successfully
2019/04/20 02:53:04 attempting to send <<image>>authorized_keys...
2019/04/20 02:53:04 done
2019/04/20 02:53:04 attempting to send <<netboot>>kernel.bin...
2019/04/20 02:53:04 target is busy, retrying in one second
[00869.553] 04929.04943> netsvc: Installing SSH authorized_keys
[00869.554] 04929.04943> netsvc: tftp write of file <<image>>authorized_keys completed
[00869.554] 04929.04943> netsvc: metrics: {"inorderblks": 1,"oooblks": 0,"ack": 1,"nack": 0,"timeouts": 0,"sas": 0,"inorderbytes": 806}
[00869.556] 04929.06477> paver:[Initialize] Successfully initialized EFI Device Partitioner
[00869.557] 01104.01117> devcoord: dc_bind_device() '/boot/driver/zxcrypt.so'
[00869.557] 03301.03356> devhost_get_handles(0x7accca0a59c0:block) open path='zxcrypt', r=-2
[00869.586] 04929.06477> paver:[DataFilePave] Wrote ssh/authorized_keys
2019/04/20 02:53:05 attempting to send <<netboot>>kernel.bin...
2019/04/20 02:53:05 done
[00000.000] 00000.00000> zbi: @ 0xffffff8006720000 (12707752 bytes)
[00000.000] 00000.00000> UART: FIFO depth 16
[00000.000] 00000.00000> PMM: boot reserve add [0x100000, 0x2fffff]
[00000.000] 00000.00000> PMM: boot reserve add [0x6720000, 0x733efff]
[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, 0x2fffff]
[00000.000] 00000.00000> PMM: boot reserve marking WIRED [0x6720000, 0x733efff]
[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 0xffffffff00114ec4 (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 [0x733f000, 0x733f100)
[00000.000] 00000.00000> INIT: cpu 0, calling hook 0xffffffff00122274 (elf_build_id) at level 0x4fffe, flags 0x1
[00000.000] 00000.00000> INIT: cpu 0, calling hook 0xffffffff00122400 (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-77bb9431c1bc18aaa78895879af3afea1700c9f8-dirty
[00000.000] 00000.00000> ELF build ID: 89f12e3de0e2e9d7350700668c15399834c8282d
[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 0xffffffff001826c4 (x86_resource_init) at level 0x50000, flags 0x1
[00000.000] 00000.00000> initializing vm
[00000.000] 00000.00000> VM: reserving kernel region [0xffffffff00100000, 0xffffffff0021b000) flags 0x28 name 'kernel_code'
[00000.000] 00000.00000> VM: reserving kernel region [0xffffffff0021b000, 0xffffffff0026c000) flags 0x8 name 'kernel_rodata'
[00000.000] 00000.00000> VM: reserving kernel region [0xffffffff0026c000, 0xffffffff00274000) flags 0x18 name 'kernel_data'
[00000.000] 00000.00000> VM: reserving kernel region [0xffffffff00274000, 0xffffffff00300000) flags 0x18 name 'kernel_bss'
[00000.000] 00000.00000> INIT: cpu 0, calling hook 0xffffffff00183388 (display_memtype) at level 0x60001, flags 0x1
[00000.000] 00000.00000> INIT: cpu 0, calling hook 0xffffffff00186818 (acpi_tables) at level 0x60001, flags 0x1
[00000.000] 00000.00000> INIT: cpu 0, calling hook 0xffffffff001814c8 (hpet) at level 0x60002, flags 0x1
[00000.000] 00000.00000> INIT: cpu 0, calling hook 0xffffffff00181888 (apic) at level 0x60002, flags 0x1
[00000.000] 00000.00000> x2APIC enabled
[00000.000] 00000.00000> INIT: cpu 0, calling hook 0xffffffff001a7e6c (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 0xffffffff00185e08 (timer) at level 0x60003, flags 0x1
[00000.000] 00000.00000> HPET frequency: 23999 ticks/ms
[00000.000] 00000.00000> TSC frequency: 2712000 ticks/ms
[00870.996] 00000.00000> timer features: constant_tsc 1 invariant_tsc 1 tsc_deadline 1
[00870.996] 00000.00000> Using TSC as wallclock
[00870.996] 00000.00000> INIT: cpu 0, calling hook 0xffffffff00208930 (percpu_heap_init) at level 0x60003, flags 0x1
[00870.996] 00000.00000> initializing kernel
[00870.996] 00000.00000> initializing mp
[00870.996] 00000.00000> INIT: cpu 0, calling hook 0xffffffff00115118 (global_prng_thread_safe) at level 0x7ffff, flags 0x1
[00870.996] 00000.00000> creating bootstrap completion thread
[00870.996] 00000.00000> top of bootstrap2()
[00870.996] 00000.00000> INIT: cpu 0, calling hook 0xffffffff00131734 (libobject) at level 0x80000, flags 0x1
[00870.996] 00000.00000> OOM: started thread
[00870.996] 00000.00000> INIT: cpu 0, calling hook 0xffffffff0020589c (dpc) at level 0x80000, flags 0x1
[00870.996] 00000.00000> Processor Model Info: type 0 family 0x6 model 0xe stepping 0x9
[00870.996] 00000.00000> display_family 0x6 display_model 0x8e
[00870.996] 00000.00000> Vendor: Intel
[00870.996] 00000.00000> Microarch: Kaby Lake
[00870.996] 00000.00000> F/M/S: 6/8e/9
[00870.996] 00000.00000> patch_level: 84
[00870.996] 00000.00000> Brand: Intel(R) Core(TM) i5-7300U CPU @ 2.60GHz
[00870.996] 00000.00000> Features: fpu sse sse2 sse3 ssse3 sse4.1 sse4.2 mmx avx avx2 fxsr pcid xsave mon aesni clflush
[00870.996] 00000.00000> clflushopt fsgsbase tsc_adj smep smap erms rdrand rdseed syscall nx huge rdtscp
[00870.996] 00000.00000> invar_tsc tsc_deadline x2apic vmx pt hwp
[00870.996] 00000.00000> Properties: meltdown l1tf pcid_good
[00870.996] 00000.00000> initializing platform
[00870.996] 00000.00000> INIT: cpu 0, calling hook 0xffffffff001a157c (x86_perfmon) at level 0x90000, flags 0x1
[00870.996] 00000.00000> PMU: version 4
[00870.997] 00000.00000> UART: started IRQ driven RX
[00870.997] 00000.00000> UART: started IRQ driven TX
[00870.997] 00000.00000> cpu topology:
[00870.997] 00000.00000> 0: apic id 0x0 BSP
[00870.997] 00000.00000> 1: apic id 0x1
[00870.997] 00000.00000> 2: apic id 0x2
[00870.997] 00000.00000> 3: apic id 0x3
[00870.997] 00000.00000> Found 4 cpus
[00870.997] 00000.00000> booting apic ids: 0x1 0x2 0x3
[00871.011] 00000.00000> entering scheduler on cpu 1
[00871.013] 00000.00000> entering scheduler on cpu 3
[00871.013] 00000.00000> entering scheduler on cpu 2
[00871.015] 00000.00000> smbios: manufacturer="Intel Corporation" product="NUC7i5DNHE"
[00871.015] 00000.00000> initializing target
[00871.015] 00000.00000> INIT: cpu 0, calling hook 0xffffffff001850b8 (x86_pcie_init) at level 0xa0000, flags 0x1
[00871.015] 00000.00000> moving to last init level
[00871.015] 00000.00000> INIT: cpu 0, calling hook 0xffffffff001214cc (debuglog) at level 0xb0000, flags 0x1
[00871.015] 00000.00000> INIT: cpu 0, calling hook 0xffffffff00174d40 (kcounters) at level 0xb0000, flags 0x1
[00871.015] 00000.00000> INIT: cpu 0, calling hook 0xffffffff00102aec (kernel_shell) at level 0xc0000, flags 0x1
[00871.015] 00000.00000> INIT: cpu 0, calling hook 0xffffffff00202ad4 (ktrace) at level 0xc0000, flags 0x1
[00871.019] 00000.00000> ktrace: buffer at 0xffffff9e806f8000 (33554432 bytes)
[00871.019] 00000.00000> INIT: cpu 0, calling hook 0xffffffff002184f8 (userboot) at level 0xc0000, flags 0x1
[00871.019] 00000.00000> userboot: ramdisk 0xc1f000 @ 0xffffff8006720000
[00871.019] 00000.00000> userboot: userboot rodata 0 @ [0x180a95db3000,0x180a95db6000)
[00871.019] 00000.00000> userboot: userboot code 0x3000 @ [0x180a95db6000,0x180a95dc1000)
[00871.019] 00000.00000> userboot: vdso/full rodata 0 @ [0x180a95dc1000,0x180a95dc8000)
[00871.019] 00000.00000> userboot: vdso/full code 0x7000 @ [0x180a95dc8000,0x180a95dc9000)
[00871.019] 00000.00000> userboot: entry point @ 0x180a95db6c90
[00871.019] 01036.01043> userboot: option "zircon.autorun.system=/boot/bin/sh+/boot/infra/runcmds"
[00871.049] 01036.01043> userboot: searching bootfs for 'bin/bootsvc'
[00871.049] 01036.01043> userboot: 'bin/bootsvc' has PT_INTERP "lib/ld.so.1"
[00871.049] 01036.01043> userboot: searching bootfs for 'lib/ld.so.1'
[00871.049] 01036.01043> userboot: userboot: loaded lib/ld.so.1 at 0x526caf7f6000, entry point 0x526caf8143d0
[00871.049] 01036.01043> userboot: userboot: loaded vDSO at 0x491b59cb1000, entry point 0x491b59cb88fa
[00871.049] 01036.01043> userboot: process bin/bootsvc started.
[00871.049] 01036.01043> userboot: waiting for loader-service requests...
[00871.050] 01036.01043> userboot: searching bootfs for 'lib/libasync-default.so'
[00871.050] 01036.01043> userboot: searching bootfs for 'lib/libfdio.so'
[00871.050] 01036.01043> userboot: searching bootfs for 'lib/libtrace-engine.so'
[00871.050] 01036.01043> userboot: searching bootfs for 'lib/liblaunchpad.so'
[00871.050] 01050.01053> {{{reset}}}
[00871.050] 01050.01053> {{{module:0:<application>:elf:367d3374904876b8f143f2ed5e4dfb0248fef748}}}
[00871.050] 01050.01053> {{{mmap:0x1db1063dc000:0x3a000:load:0:rx:0}}}
[00871.050] 01050.01053> {{{mmap:0x1db106416000:0x4000:load:0:rw:0x3a000}}}
[00871.050] 01050.01053> dso: id=367d3374904876b8f143f2ed5e4dfb0248fef748 base=0x00001db1063dc000 name=<application>
[00871.050] 01050.01053> {{{module:0x2:<vDSO>:elf:71712e0a455898a51e34d40a4013786ab1fa5335}}}
[00871.050] 01050.01053> {{{mmap:0x491b59cb1000:0x7000:load:0x2:r:0}}}
[00871.050] 01050.01053> {{{mmap:0x491b59cb8000:0x1000:load:0x2:rx:0x7000}}}
[00871.050] 01050.01053> dso: id=71712e0a455898a51e34d40a4013786ab1fa5335 base=0x0000491b59cb1000 name=<vDSO>
[00871.050] 01050.01053> {{{module:0x3:libasync-default.so:elf:8c511b4202cf569c8fdde14ca97222102ba3a9e0}}}
[00871.050] 01050.01053> {{{mmap:0x642631e07000:0x1000:load:0x3:rx:0}}}
[00871.050] 01050.01053> {{{mmap:0x642631e08000:0x1000:load:0x3:rw:0x1000}}}
[00871.050] 01050.01053> dso: id=8c511b4202cf569c8fdde14ca97222102ba3a9e0 base=0x0000642631e07000 name=libasync-default.so
[00871.050] 01050.01053> {{{module:0x4:libfdio.so:elf:3efa72b2e3bd2e4271f835d34a81d9719d6e08a7}}}
[00871.050] 01050.01053> {{{mmap:0x412f87eb7000:0x32000:load:0x4:rx:0}}}
[00871.050] 01050.01053> {{{mmap:0x412f87eea000:0x4000:load:0x4:rw:0x33000}}}
[00871.050] 01050.01053> dso: id=3efa72b2e3bd2e4271f835d34a81d9719d6e08a7 base=0x0000412f87eb7000 name=libfdio.so
[00871.050] 01050.01053> {{{module:0x5:libtrace-engine.so:elf:95bc229c3cf2ab8a51f12c33a311105ff8976120}}}
[00871.050] 01050.01053> {{{mmap:0x752f0d393000:0x9000:load:0x5:rx:0}}}
[00871.050] 01050.01053> {{{mmap:0x752f0d39c000:0x2000:load:0x5:rw:0x9000}}}
[00871.050] 01050.01053> dso: id=95bc229c3cf2ab8a51f12c33a311105ff8976120 base=0x0000752f0d393000 name=libtrace-engine.so
[00871.050] 01050.01053> {{{module:0x6:liblaunchpad.so:elf:5b0854856213eae6bab93c982f39551f8f9591c5}}}
[00871.050] 01050.01053> {{{mmap:0x57fe55799000:0x7000:load:0x6:rx:0}}}
[00871.050] 01050.01053> {{{mmap:0x57fe557a0000:0x2000:load:0x6:rw:0x7000}}}
[00871.050] 01050.01053> dso: id=5b0854856213eae6bab93c982f39551f8f9591c5 base=0x000057fe55799000 name=liblaunchpad.so
[00871.050] 01050.01053> {{{module:0x1:libc.so:elf:5d417db61b3a48a58a8fa1ffbfc2e71b830e0857}}}
[00871.050] 01050.01053> {{{mmap:0x526caf7f6000:0xa6000:load:0x1:rx:0}}}
[00871.050] 01050.01053> {{{mmap:0x526caf89c000:0x5000:load:0x1:rw:0xa6000}}}
[00871.050] 01050.01053> dso: id=5d417db61b3a48a58a8fa1ffbfc2e71b830e0857 base=0x0000526caf7f6000 name=libc.so
[00871.050] 01050.01053> bootsvc: Starting...
[00871.050] 01036.01043> userboot: loader-service channel peer closed
[00871.050] 01036.01043> userboot: finished!
[00871.050] 01050.01053> bootsvc: Creating bootfs service...
[00871.050] 01050.01053> bootsvc: Retrieving boot image...
[00871.051] 01050.01053> bootsvc: Decommitted BOOTDATA VMO from 0 to 0xc1e000
[00871.051] 01050.01053> bootsvc: Loading boot arguments...
[00871.051] 01050.01053> bootsvc: Creating svcfs service...
[00871.051] 01050.01053> bootsvc: Loading kernel VMOs...
[00871.051] 01050.01053> bootsvc: Creating loader service...
[00871.051] 01050.01053> bootsvc: Launching next process...
[00871.051] 01050.01108> bootsvc: Launched bin/devcoordinator
[00871.052] 01115.01130> devcoordinator: launch /boot/bin/svchost (svchost) OK
[00871.053] 01115.01130> devcoordinator: launch /boot/bin/fshost (fshost) OK
[00871.055] 01115.01321> devcoordinator: launch /boot/bin/pwrbtn-monitor (pwrbtn-monitor) OK
[00871.055] 01115.01341> devcoordinator: launch /boot/bin/netsvc (netsvc) OK
[00871.056] 01115.01341> devcoordinator: launch /boot/bin/virtual-console (virtual-console) OK
[00871.060] 01115.01130> devcoordinator: full system required, ignoring fallback drivers until /system is loaded
[00871.060] 01115.01130> devcoordinator: launch devhost 'devhost:sys': pid=2187
[00871.060] 01115.01130> devcoordinator: launch devhost 'devhost:test': pid=2219
[00871.061] 01115.01130> devcoordinator: launch devhost 'devhost:root': pid=2281
[00871.061] 01115.01130> devcoordinator: launch devhost 'devhost:misc': pid=2342
[00871.061] 02187.02201> devhost: trace provider registry begun
[00871.062] 02219.02241> devhost: trace provider registry begun
[00871.063] 02281.02310> devhost: trace provider registry begun
[00871.063] 02342.02380> devhost: trace provider registry begun
[00871.064] 01115.01333> devcoordinator: launch /boot/bin/sh (sh:console) OK
[00871.147] 02187.02201> acpi-bus: not using IOMMU
[00871.155] 02187.02201> PMU: 7 arch events
[00871.155] 02187.02201> PMU: arch event id range: 1-7
[00871.155] 02187.02201> PMU: 102 arch events
[00871.155] 02187.02201> PMU: arch event id range: 1-241
[00871.155] 02187.02201> Intel Processor Trace configuration for this chipset:
[00871.155] 02187.02201> mtc_freq_mask: 0x249
[00871.155] 02187.02201> cyc_thresh_mask: 0x3fff
[00871.155] 02187.02201> psb_freq_mask: 0x3f
[00871.155] 02187.02201> num addr ranges: 2
[00871.155] 02187.02201> [sysmem_init 28] async_get_default_dispatcher(): 0x7b334b1f1910
[00871.155] 02187.02201> [sysmem_bind 40] sysmem_bind()
[00871.155] 02187.02876> acpi-pwrbtn: initialized
[00871.155] 01722.01750> vc: new input device /dev/class/input/000
[00871.165] 02187.02876> WARNING: ACPI found bad _CRS address entry
[00871.174] 02187.02876> WARNING: ACPI found bad _CRS address entry
[00871.186] 02187.02876> acpi: published device pci(0x7b328b2053d0), parent=sys(0x7b33cb1ed710), handle=0x7b324b1f69d0
[00871.187] 01115.01130> devcoordinator: launch devhost 'devhost:pci#1:8086:5916': pid=2972
[00871.187] 01115.01130> devcoordinator: launch devhost 'devhost:pci#3:8086:9d2f': pid=3025
[00871.188] 02972.02986> devhost: trace provider registry begun
[00871.188] 01115.01130> devcoordinator: launch devhost 'devhost:pci#5:8086:9d60': pid=3134
[00871.189] 03025.03048> devhost: trace provider registry begun
[00871.189] 01115.01130> devcoordinator: launch devhost 'devhost:pci#6:8086:9d61': pid=3231
[00871.190] 03134.03152> devhost: trace provider registry begun
[00871.190] 01115.01130> devcoordinator: launch devhost 'devhost:pci#9:8086:9d03': pid=3328
[00871.190] 02187.02876> acpi: published device rtc(0x7b328b205010), parent=acpi(0x7b33cb1ec710), handle=0x7b324b21e190
[00871.191] 03231.03258> devhost: trace provider registry begun
[00871.192] 01115.01130> devcoordinator: launch devhost 'devhost:pci#14:8086:9d71': pid=3474
[00871.192] 01115.01130> devcoordinator: launch devhost 'devhost:pci#16:8086:156f': pid=3540
[00871.192] 02187.02876> acpi-ec: initialized
[00871.193] 03328.03368> devhost: trace provider registry begun
[00871.195] 02187.02876> acpi: failed to create NHLT VMO (res -10)
[00871.195] 02187.02876> acpi: failed to publish NHLT metadata
[00871.197] 03231.03258> initialized intel serialio i2c driver, reg=0x15713a47f000 regsize=4096
[00871.197] 03134.03152> initialized intel serialio i2c driver, reg=0x1edeaa71b000 regsize=4096
[00871.198] 03474.03499> devhost: trace provider registry begun
[00871.198] 03540.03574> devhost: trace provider registry begun
[00871.202] 03328.03368> ahci: using MSI interrupt
[00871.205] 03025.03946> * found USB device (0x18d1:0xa002, USB 2.0) config 1
[00871.205] 03025.03946> * found USB device (0x18d1:0xa003, USB 3.0) config 1
[00871.205] 03474.03499> [IHDA DSP 00:1f.3] Failed to fetch NHLT (res -25)
[00871.205] 03474.03499> [IHDA Controller 00:1f.3] Failed to initialize DSP device (res = -25)
[00871.277] 01626.01653> netifc: ? /dev/class/ethernet/000
[00871.277] 01626.01653> netifc: create 512 eth buffers
[00871.277] 01626.01653> macaddr: d4:5d:df:1a:42:46
[00871.277] 01626.01653> ip6addr: fe80::d65d:df4d:fe1a:4246
[00871.277] 01626.01653> snmaddr: ff02::1:ff1a:4246
[00871.277] 01626.01653> netsvc: using /dev/class/ethernet/000
[00871.277] 01626.01653> netsvc: nodename='ocean-drank-wick-spot'
[00871.277] 01626.01653> netsvc: start
[00871.304] 01722.01750> vc: new display device /dev/class/display-controller/000
[00871.345] 02972.04240> i915: Found DP monitor
[00871.345] 02972.04240> i915: Display 1 connected
[00871.345] 02972.04240> i915: MST not supported
[00871.824] 01722.01750> vc: Successfully attached to display 1
[00871.920] 03025.03946> * found USB device (0x0781:0x5583, USB 3.0) config 1
[00872.670] 03025.03946> * found USB device (0x046d:0xc31c, USB 1.10) config 1
[00872.918] 03025.03946> * found USB device (0x0cf3:0xe300, USB 2.1) config 1
[00873.203] 03231.03258> intel-i2c-controller: intel_serialio_i2c_slave_transfer: -21
[00873.203] 03231.03258> i2c-hid: could not read HID descriptor: 0
[00873.203] 03231.03258> devhost[00:15.1/i2c-bus-9d61/004c] bind driver '/boot/driver/i2c-hid.so' failed: -2
[00873.203] 01115.01130> devcoordinator: rpc: bind-driver '004c' status -2
[00873.204] 03134.03152> intel-i2c-controller: intel_serialio_i2c_slave_transfer: -21
[00873.204] 03134.03152> i2c-hid: could not read HID descriptor: 0
[00873.204] 03134.03152> devhost[00:15.0/i2c-bus-9d60/0020] bind driver '/boot/driver/i2c-hid.so' failed: -2
[00873.204] 01115.01130> devcoordinator: rpc: bind-driver '0020' status -2
[00873.217] 03328.03927> sata2: dev info
[00873.217] 03328.03927> serial=711430952084 9
[00873.217] 03328.03927> firmware rev=1Q01A7 0
[00873.217] 03328.03927> model id=IBIW NSS D
[00873.217] 03328.03927> major=0x3f0 ACS2 DMA 32 commands
[00873.217] 03328.03927> LBA48 234441648 sectors, sector size=512
[00873.218] 01299.01313> fshost: /dev/class/block/000: GPT?
[00873.219] 03328.03368> gpt: device_get_metadata failed (-25)
[00873.220] 01299.01313> fshost: /dev/class/block/001: FVM?
[00873.223] 01299.01313> devcoordinator: launch /boot/bin/blobfs (blobfs:/blob) OK
[00873.367] 01299.01313> fshost: starting 'bin/pkgsvr' '3592a64994a12d7da3bceff719644f5d19dd15a869af63655bcf68e378ed71d4'...
[00873.374] 01299.01313> devcoordinator: launch bin/pkgsvr (pkgfs) OK
[00873.384] 04674.04888> pkgsvr: system: will be served from 3592a64994a12d7da3bceff719644f5d19dd15a869af63655bcf68e378ed71d4
[00873.384] 04674.04888> pkgsvr: pkgfs serving index /data/pkgfs_index from blobfs /blob
[00873.387] 01299.01313> fshost: /dev/class/block/005: zxcrypt?
[00873.388] 03328.03368> devhost_get_handles(0x7f9e3ca82f10:block) open path='zxcrypt', r=-2
[00873.393] 01299.01313> fshost: mounting minfs
[00873.396] 01299.01313> devcoordinator: launch /boot/bin/minfs (minfs:/data) OK
[00873.421] 01115.01761> devcoordinator: launch /system/bin/appmgr (appmgr) OK
[00873.421] 01115.01761> autorun: starting '/boot/bin/sh' '/boot/infra/runcmds'...
[00873.453] 01115.04928> devcoordinator: adding system driver 'bt_host' '/system/driver/bt-host.so'
[00873.459] 01115.01761> devcoordinator: launch /boot/bin/sh (autorun:system) OK
[00873.465] 01115.04928> devcoordinator: adding system driver 'usb_video' '/system/driver/usb_video.so'
[00873.485] 01115.04928> devcoordinator: adding system driver 'wlan' '/system/driver/wlanphy.so'
[00873.498] 01115.04928> devcoordinator: adding system driver 'brcmfmac' '/system/driver/brcmfmac.so'
[00873.513] 01115.04928> devcoordinator: adding system driver 'magma_pdev_gpu' '/system/driver/libmsd_arm.so'
[00873.538] 01115.04928> devcoordinator: adding system driver 'bt_hci_atheros' '/system/driver/bt-hci-atheros.so'
[00873.543] 01115.04928> devcoordinator: adding system driver 'bt_hog' '/system/driver/bt-hog.so'
[00873.548] 01115.04928> devcoordinator: adding system driver 'ath10k_pci' '/system/driver/ath10k.so'
[00873.566] 01115.04928> devcoordinator: adding system driver 'mt8167s_gpu' '/system/driver/libmsd_img_rgx_mtk.so'
[00873.623] 01115.04928> devcoordinator: adding system driver 'ralink' '/system/driver/ralink.so'
[00873.635] 01115.04928> devcoordinator: adding system driver 'bt_hci_fake' '/system/driver/bt-hci-fake.so'
[00873.638] 01115.04928> devcoordinator: adding system driver 'iwlwifi_pci' '/system/driver/iwlwifi.so'
[00873.657] 01115.04928> devcoordinator: adding system driver 'virtual_camera' '/system/driver/virtual_camera_driver.so'
[00873.672] 05199.05213> [INFO:namespace_builder.cc(93)] config-data for sysmgr
[00873.728] 01115.04928> devcoordinator: adding system driver 'wlan' '/system/driver/wlan.so'
[00873.731] 01115.04928> devcoordinator: adding system driver 'bt_hci_passthrough' '/system/driver/bt-hci-passthrough.so'
[00873.756] 01115.04928> devcoordinator: adding system driver 'bt_hci_intel' '/system/driver/bt-hci-intel.so'
[00873.766] 01115.04928> devcoordinator: adding system driver 'qmi_usb' '/system/driver/qmi-transport.so'
[00873.778] 01115.04928> devcoordinator: adding system driver 'wlan' '/system/driver/wlanif.so'
[00873.783] 01115.04928> devcoordinator: adding system driver 'qmi_fake' '/system/driver/qmi-fake.so'
[00873.792] 01115.04928> devcoordinator: adding system driver 'rtl88xx' '/system/driver/rtl88xx.so'
[00873.800] 01115.04928> devcoordinator: adding system driver 'virtual_audio' '/system/driver/virtual_audio_driver.so'
[00873.809] 01115.04928> devcoordinator: adding system driver 'gpu' '/system/driver/libmsd_intel.so'
[00873.810] 01115.01130> devcoordinator: driver 'gpu' added
[00873.810] 01115.01130> devcoordinator: driver 'rtl88xx' added
[00873.810] 01115.01130> devcoordinator: driver 'qmi_fake' added
[00873.810] 01115.01130> devcoordinator: driver 'wlan' added
[00873.810] 01115.01130> devcoordinator: driver 'qmi_usb' added
[00873.810] 01115.01130> devcoordinator: driver 'bt_hci_intel' added
[00873.810] 01115.01130> devcoordinator: driver 'wlan' added
[00873.810] 01115.01130> devcoordinator: driver 'iwlwifi_pci' added
[00873.810] 01115.01130> devcoordinator: driver 'bt_hci_fake' added
[00873.810] 01115.01130> devcoordinator: driver 'ralink' added
[00873.810] 01115.01130> devcoordinator: driver 'mt8167s_gpu' added
[00873.810] 01115.01130> devcoordinator: driver 'ath10k_pci' added
[00873.813] 01115.01130> devcoordinator: launch devhost 'devhost:pci#11:168c:003e': pid=6120
[00873.813] 01115.01130> devcoordinator: driver 'bt_hog' added
[00873.813] 01115.01130> devcoordinator: driver 'bt_hci_atheros' added
[00873.813] 01115.01130> devcoordinator: driver 'magma_pdev_gpu' added
[00873.813] 01115.01130> devcoordinator: driver 'brcmfmac' added
[00873.813] 01115.01130> devcoordinator: driver 'wlan' added
[00873.813] 01115.01130> devcoordinator: driver 'usb_video' added
[00873.813] 01115.01130> devcoordinator: driver 'bt_host' added
[00873.813] 01115.01130> devcoordinator: driver 'bt_hci_passthrough' added
[00873.813] 01115.01130> devcoordinator: fallback driver 'usb_composite' is available
[00873.813] 01115.01130> devcoordinator: driver 'usb_composite' added
[00873.819] 01115.01130> devcoordinator: fallback driver 'intel_disp' is available
[00873.819] 01115.01130> devcoordinator: driver 'intel_disp' added
[00873.821] 06120.06139> devhost: trace provider registry begun
[00873.821] 06120.06139> ath10k: Probed chip QCA6174 ver: 2.1
[00873.825] 03025.03048> UMS: parent: 'ifc-000'
[00873.825] 03025.03048> UMS:Max lun is: 0
[00873.831] 03025.06939> UMS: block size is: 0x00000200
[00873.831] 03025.06939> UMS: total blocks is: 30031250
[00873.831] 03025.06939> UMS: total size is: 15376000000
[00873.831] 03025.06939> UMS: read-only: 0 removable: 1
[00873.836] 03025.03048> devhost[00:14.0/xhci/usb-bus/003/003/ifc-001] bind driver '/boot/driver/bt-transport-usb.so' failed: -2
[00873.836] 01115.01130> devcoordinator: rpc: bind-driver 'ifc-001' status -2
[00873.900] 05199.05213> [INFO:namespace_builder.cc(93)] config-data for amber
[00873.900] 03025.10236> btatheros: Making visible
[00873.903] 03025.10236> btatheros: loaded successfully
[00873.906] 03025.10556> [INFO:command_channel.cc(149)] hci: initialized
[00873.910] 01299.01313> fshost: /dev/class/block/007: MBR?
[00873.924] 01299.01313> fshost: /dev/class/block/009: MBR?
[00873.971] 03025.10556> [WARN:adapter.cc(274)] gap: controller is using legacy HCI version 4.1
[00874.012] 03025.10556> [INFO:acl_data_channel.cc(91)] hci: initialized
[00874.015] 05199.05213> [INFO:namespace_builder.cc(93)] config-data for pkg_resolver
[00874.078] 01722.01750> vc: new input device /dev/class/input/001
[00874.093] 01722.01750> vc: new input device /dev/class/input/002
[00874.143] 13654.13666> [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
[00874.143] 13654.13666> kfill_days=2, start_event_aggregator_worker=1.
[00874.197] 05199.05213> [INFO:namespace_builder.cc(93)] config-data for mdns
[00874.264] 06120.13602> devhost: rpc:load-firmware failed: -25
[00874.264] 06120.13602> devhost: rpc:load-firmware failed: -25
[00874.265] 05199.05213> [INFO:namespace_builder.cc(93)] config-data for wlancfg
[00874.462] 05199.05213> [INFO:namespace_builder.cc(93)] config-data for crashpad_agent
[00874.516] 16788.16800> [INFO:main.cc(35)] Trace Manager starting with config: /pkg/data/tracing.config
[00874.517] 15358.15371> [INFO:system_metrics_main.cc(23)] Cobalt SystemMetricsDaemon: System metrics daemon created.
[00874.619] 17220.17232> wlanstack2 [I]: Starting
[00874.953] 06120.13006> ath10k: Unknown eventid: 0x1d019
[00874.956] 06120.13006> ath10k: Unknown eventid: 0x16006
[00874.961] 06120.06139> wlanphy: event loop started
[00874.961] 06120.06139> wlanphy_bind
[00874.962] 17220.17232> wlanstack2::device [I]: new phy #0: /dev/sys/pci/01:00.0/ath10k-wlanphy/wlanphy
[00874.962] 14856.14870> wlancfg got event: OnPhyAdded { phy_id: 0 }
[00874.962] 14856.14870> wlancfg: phy 0 added
[00874.962] 17220.17232> wlanstack2::service [I]: query_phy(id = 0)
[00874.963] 17220.17232> wlanstack2::service [I]: query_phy(id = 0): received a 'QueryResult' from device
[00874.963] 14856.14870> wlancfg: received a PhyInfo from phy #0: path is /dev/sys/pci/01:00.0/ath10k-wlanphy/wlanphy
[00874.963] 14856.14870> using default wlan config entry for phy
[00874.963] 14856.14870> wlancfg: Creating Client iface for phy 0
[00874.969] 06120.06139> wlan_bind
[00874.971] 06120.06139> ath10k: adding a station interface (vdev_id=0) ...
[00874.972] 06120.06139> wlan: [I] Initialize a client MLME.
[00874.973] 06120.18078> wlan: [I] starting MainLoop
[00874.973] 06120.06139> wlan: [I] channel opened
[00874.974] 17220.17232> wlanstack2::device [I]: new iface #0 with role 'Client': /dev/sys/pci/01:00.0/ath10k-wlanphy/ath10k-wlanmac/wlan
[00874.975] 14856.14870> wlancfg got event: OnIfaceAdded { iface_id: 0 }
[00874.975] 14856.14870> wlancfg: new iface 0 added successfully
[00874.975] 14856.14870> wlancfg: Starting auto-connect loop with 0 saved networks
[00875.532] 14340.14352> Starting mDNS on interface ethp001f6 [80fe::5dd6:ffdf:1afe:4642]
[00875.532] 14340.14352> [WARNING:garnet/bin/mdns/service/mdns_interface_transceiver_v6.cc(29)] NET-291 IPV6_MULTICAST_LOOP not supported (ENOPROTOOPT), continuing anyway
[00875.532] 14340.14352> [WARNING:garnet/bin/mdns/service/mdns_interface_transceiver_v6.cc(50)] NET-2180 IPV6_JOIN_GROUP returned ENODEV, mDNS will not communicate via IPV6
[00879.003] 14340.14352> Starting mDNS on interface ethp001f6 192.168.42.101
[00879.003] 14340.14352> [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
[00879.004] 14340.14352> Starting mDNS on interface ethp001f6 [80fe::5dd6:ffdf:1afe:4642]
[00879.004] 14340.14352> [WARNING:garnet/bin/mdns/service/mdns_interface_transceiver_v6.cc(29)] NET-291 IPV6_MULTICAST_LOOP not supported (ENOPROTOOPT), continuing anyway
[00879.004] 14340.14352> [WARNING:garnet/bin/mdns/service/mdns_interface_transceiver_v6.cc(50)] NET-2180 IPV6_JOIN_GROUP returned ENODEV, mDNS will not communicate via IPV6
[00879.004] 14340.14352> mDNS: Verifying uniqueness of host name ocean-drank-wick-spot.local.
[00879.883] 14340.14352> mDNS: Using unique host name ocean-drank-wick-spot.local.
Running tests sequentially.
[tb] 2019-04-20 02:54:01.625 [22mINFO[0m [SshConnection | 192.168.42.101] Starting master ssh connection. [connection.py:setup_master_ssh:141]
[00927.252] 23422.23434> setsockopt IP_TOS 32: Protocol not available:
[tb] 2019-04-20 02:54:01.866 [22mINFO[0m [SshConnection | 192.168.42.101] Starting master ssh connection. [connection.py:setup_master_ssh:141]
[00927.483] 23998.24013> setsockopt IP_TOS 32: Protocol not available:
[tb] 2019-04-20 02:54:03.110 [22mINFO[0m [SshConnection | 192.168.42.101] Starting master ssh connection. [connection.py:setup_master_ssh:141]
[00928.728] 25051.25064> setsockopt IP_TOS 32: Protocol not available:
[tb] 2019-04-20 02:54:03.361 [22mINFO[0m Controller FuchsiaDevice: [{'ip': '192.168.42.101'}] [base_test.py:register_controller:396]
[tb] 2019-04-20 02:54:03.364 [22mINFO[0m ==========> Sl4fSanityTest <========== [base_test.py:run:967]
[tb] 2019-04-20 02:54:03.366 [22mINFO[0m Congratulations! Fuchsia controllers have been initialized successfully! [Sl4fSanityTest.py:setup_class:41]
[tb] 2019-04-20 02:54:03.368 [22mINFO[0m [Test Case] test_example [base_test.py:exec_one_testcase:662]
[tb] 2019-04-20 02:54:03.369 [22mINFO[0m Congratulations! You've run your first test. [Sl4fSanityTest.py:test_example:46]
[tb] 2019-04-20 02:54:03.372 [22mINFO[0m [Test Case] test_example PASS [base_test.py:_on_pass:542]
[tb] 2019-04-20 02:54:03.376 [22mINFO[0m 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 02:54:03.383 [22mINFO[0m [SshConnection | 192.168.42.101] Starting master ssh connection. [connection.py:setup_master_ssh:141]
[00929.001] 25598.25614> setsockopt IP_TOS 32: Protocol not available:
[tb] 2019-04-20 02:54:03.626 [22mINFO[0m [SshConnection | 192.168.42.101] Starting master ssh connection. [connection.py:setup_master_ssh:141]
[00929.247] 26180.26194> setsockopt IP_TOS 32: Protocol not available:
[tb] 2019-04-20 02:54:04.872 [22mINFO[0m [SshConnection | 192.168.42.101] Starting master ssh connection. [connection.py:setup_master_ssh:141]
[00930.491] 27245.27260> setsockopt IP_TOS 32: Protocol not available:
[tb] 2019-04-20 02:54:05.122 [22mINFO[0m Controller FuchsiaDevice: [{'ip': '192.168.42.101'}] [base_test.py:register_controller:396]
[tb] 2019-04-20 02:54:05.127 [22mINFO[0m ==========> WlanScanTest <========== [base_test.py:run:967]
[tb] 2019-04-20 02:54:05.129 [22mINFO[0m [Test Case] test_basic_scan_request [base_test.py:exec_one_testcase:662]
[00930.645] 06120.18078> ath10k: starting a hardware scan
[tb] 2019-04-20 02:54:10.646 [22mINFO[0m scan contained 54 results [WlanScanTest.py:test_basic_scan_request:86]
[tb] 2019-04-20 02:54:10.649 [22mINFO[0m scan time: 5517 ms [WlanScanTest.py:test_basic_scan_request:89]
[tb] 2019-04-20 02:54:10.662 [22mINFO[0m [Test Case] test_basic_scan_request PASS [base_test.py:_on_pass:542]
[tb] 2019-04-20 02:54:10.665 [22mINFO[0m [Test Case] test_scan_while_connected_open_network [base_test.py:exec_one_testcase:662]
[tb] 2019-04-20 02:54:10.667 [22mINFO[0m got the ssid! GoogleGuest [WlanScanTest.py:test_scan_while_connected_open_network:101]
[00936.186] 06120.18078> ath10k: starting a hardware scan
[00941.685] 06120.18078> ath10k: setting channel (pri: 153, sec: 0, bw: CBW40BELOW)
[00941.685] 06120.18078> ath10k: basic setting: phymode 11na-ht40 center_freq=5755
[00941.738] 06120.18078> ath10k: configuring BSS
[00941.738] 06120.18078> ath10k: basic setting: phymode 11na-ht40 center_freq=5755
[tb] 2019-04-20 02:54:18.827 [31m[1mERROR[0m Connect call failed, aborting test [base_test.py:_on_fail:516][base_test.py:_exec_procedure_func:634][base_test.py:exec_one_testcase:697]
[tb] 2019-04-20 02:54:18.830 [22mINFO[0m [Test Case] test_scan_while_connected_open_network FAIL [base_test.py:_on_fail:517]
[tb] 2019-04-20 02:54:18.833 [22mINFO[0m [Test Case] test_scan_while_connected_wpa2_network [base_test.py:exec_one_testcase:662]
[tb] 2019-04-20 02:54:18.836 [22mINFO[0m got the ssid! acts hotspot [WlanScanTest.py:test_scan_while_connected_wpa2_network:114]
[00944.320] 17220.17232> wlan_sme::client::state [E]: Associate request failed with result code RefusedTemporarily
[00944.352] 06120.18078> ath10k: starting a hardware scan
[00951.943] 17220.17232> wlan_rsn::rsna::esssa [I]: spawned ESSSA for: Supplicant
[00951.943] 06120.18078> ath10k: setting channel (pri: 3, sec: 0, bw: CBW20)
[00951.943] 06120.18078> ath10k: basic setting: phymode 11ng-ht20 center_freq=2422
[00951.994] 06120.18078> ath10k: configuring BSS
[00951.994] 06120.18078> ath10k: basic setting: phymode 11ng-ht20 center_freq=2422
[00952.061] 06120.18078> ath10k: as a client, configuring an association with an AP [40:4E:36:D1:DC:10]
[00952.061] 06120.18078> ath10k: mac peer 40:4E:36:D1:DC:10 phymode 11b
[00952.061] 06120.18078> ath10k: successfully associated with bssid 40:4E:36:D1:DC:10
[00952.061] 17220.17232> wlan_rsn::rsna::esssa [I]: resetting ESSSA
[00952.061] 17220.17232> wlan_rsn::rsna::esssa [I]: establishing ESSSA...
[00952.061] 17220.17232> wlan_rsn::rsna::esssa [I]: established PMKSA
[00952.061] 06120.18078> 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
[00952.082] 17220.17232> wlan_rsn::rsna::esssa [I]: established PTKSA
[tb] 2019-04-20 02:54:26.590 [22mINFO[0m connection to network successful [WlanScanTest.py:check_connect_response:58]
[00952.094] 17220.17232> wlan_rsn::rsna::esssa [I]: established GTKSA
[00952.094] 17220.17232> wlan_rsn::rsna::esssa [I]: established ESSSA
[00952.094] 06120.18078> 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)
[00952.094] 06120.18078> 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)
[00952.095] 14340.14352> Starting mDNS on interface ethp001f6 [80fe::5dd6:ffdf:1afe:4642]
[00952.096] 14340.14352> [WARNING:garnet/bin/mdns/service/mdns_interface_transceiver_v6.cc(29)] NET-291 IPV6_MULTICAST_LOOP not supported (ENOPROTOOPT), continuing anyway
[00952.096] 14340.14352> [WARNING:garnet/bin/mdns/service/mdns_interface_transceiver_v6.cc(50)] NET-2180 IPV6_JOIN_GROUP returned ENODEV, mDNS will not communicate via IPV6
[00952.096] 14340.14352> Starting mDNS on interface wlanp01 [80fe::e02:ff8e:8bfe:ec40]
[00952.097] 14340.14352> [WARNING:garnet/bin/mdns/service/mdns_interface_transceiver_v6.cc(29)] NET-291 IPV6_MULTICAST_LOOP not supported (ENOPROTOOPT), continuing anyway
[00952.097] 14340.14352> [WARNING:garnet/bin/mdns/service/mdns_interface_transceiver_v6.cc(50)] NET-2180 IPV6_JOIN_GROUP returned ENODEV, mDNS will not communicate via IPV6
[00952.107] 06120.18078> ath10k: starting a hardware scan
[00956.261] 14340.14352> Starting mDNS on interface ethp001f6 [80fe::5dd6:ffdf:1afe:4642]
[00956.261] 14340.14352> [WARNING:garnet/bin/mdns/service/mdns_interface_transceiver_v6.cc(29)] NET-291 IPV6_MULTICAST_LOOP not supported (ENOPROTOOPT), continuing anyway
[00956.261] 14340.14352> [WARNING:garnet/bin/mdns/service/mdns_interface_transceiver_v6.cc(50)] NET-2180 IPV6_JOIN_GROUP returned ENODEV, mDNS will not communicate via IPV6
[00956.262] 14340.14352> Starting mDNS on interface wlanp01 192.168.43.147
[00956.262] 14340.14352> [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
[00956.262] 14340.14352> Starting mDNS on interface wlanp01 [80fe::e02:ff8e:8bfe:ec40]
[00956.262] 14340.14352> [WARNING:garnet/bin/mdns/service/mdns_interface_transceiver_v6.cc(29)] NET-291 IPV6_MULTICAST_LOOP not supported (ENOPROTOOPT), continuing anyway
[00956.263] 14340.14352> [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 02:54:36.237 [22mINFO[0m scan contained 58 results [WlanScanTest.py:test_basic_scan_request:86]
[tb] 2019-04-20 02:54:36.239 [22mINFO[0m scan time: 9646 ms [WlanScanTest.py:test_basic_scan_request:89]
[tb] 2019-04-20 02:54:36.253 [22mINFO[0m [Test Case] test_scan_while_connected_wpa2_network PASS [base_test.py:_on_pass:542]
[tb] 2019-04-20 02:54:36.257 [22mINFO[0m Summary for test class WlanScanTest: ControllerInfo {'FuchsiaDevice': [{'ip': '192.168.42.101'}]}, Requested 3, Executed 3, Passed 2, Failed 1, Skipped 0, Blocked 0, Unknown 0, Errors 0 [base_test.py:run:1027]
[tb] 2019-04-20 02:54:36.259 [22mINFO[0m Summary for test run tb@2019-04-20_02-53-59-186: ControllerInfo {'FuchsiaDevice': [{'ip': '192.168.42.101'}]}, Requested 4, Executed 4, Passed 3, Failed 1, 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),
[00961.758] 06120.18078> wlan: [I] deauthenticating from "acts hotspot" (40:4e:36:d1:dc:10), reason=36
[00961.758] 06120.18078> ath10k: as a client, clearing the association with an AP [40:4E:36:D1:DC:10]
[00961.758] 17220.17232> wlan_sme::client::state [W]: Unexpected MLME message while Idle: DeauthenticateConf { resp: DeauthenticateConfirm { peer_sta_address: [64, 78, 54, 209, 220, 16] } }
[00961.759] 14340.14352> Starting mDNS on interface ethp001f6 [80fe::5dd6:ffdf:1afe:4642]
[00961.760] 14340.14352> [WARNING:garnet/bin/mdns/service/mdns_interface_transceiver_v6.cc(29)] NET-291 IPV6_MULTICAST_LOOP not supported (ENOPROTOOPT), continuing anyway
[00961.760] 14340.14352> [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 failed! exit status 1