DEBUG: config flag: /etc/botanist/config.json
DEBUG: waiting for "summary.json"
2019/05/24 01:25:07 attempting to send <<netboot>>cmdline...
2019/05/24 01:25:07 done
2019/05/24 01:25:07 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 0x8afff000 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
[00019.885] 00000.00000> timer features: constant_tsc 1 invariant_tsc 1 tsc_deadline 1
[00019.885] 00000.00000> Using TSC as wallclock
[00019.885] 00000.00000> initializing kernel
[00019.885] 00000.00000> initializing mp
[00019.885] 00000.00000> initializing timers
[00019.885] 00000.00000> INIT: cpu 0, calling hook 0xffffffff0013c578 (debuglog) at level 0x7ffff, flags 0x1
[00019.885] 00000.00000> INIT: cpu 0, calling hook 0xffffffff00195518 (thread_set_priority_experiment) at level 0x7ffff, flags 0x1
[00019.885] 00000.00000> thread set priority experiment is : ENABLED
[00019.885] 00000.00000> INIT: cpu 0, calling hook 0xffffffff001aa67c (global_prng_thread_safe) at level 0x7ffff, flags 0x1
[00019.885] 00000.00000> creating bootstrap completion thread
[00020.227] 00000.00000> top of bootstrap2()
[00020.227] 00000.00000> INIT: cpu 0, calling hook 0xffffffff0013151c (dpc) at level 0x80000, flags 0x1
[00020.240] 00000.00000> INIT: cpu 0, calling hook 0xffffffff00152978 (libobject) at level 0x80000, flags 0x1
[00020.240] 00000.00000> OOM: started thread
[00020.253] 00000.00000> Processor Model Info: type 0 family 0x6 model 0xe stepping 0x9
[00020.253] 00000.00000> display_family 0x6 display_model 0x8e
[00020.253] 00000.00000> Vendor: Intel
[00020.253] 00000.00000> Microarch: Kaby Lake
[00020.253] 00000.00000> F/M/S: 6/8e/9
[00020.253] 00000.00000> Brand: Intel(R) Core(TM) i5-7300U CPU @ 2.60GHz
[00020.253] 00000.00000> Features: fpu sse sse2 sse3 ssse3 sse4.1 sse4.2 mmx avx avx2 fxsr pcid xsave mon aesni clflush
[00020.253] 00000.00000> clflushopt fsgsbase tsc_adj smep smap erms rdrand rdseed syscall nx huge rdtscp
[00020.253] 00000.00000> invar_tsc tsc_deadline x2apic vmx pt hwp
[00020.253] 00000.00000> initializing platform
[00020.253] 00000.00000> INIT: cpu 0, calling hook 0xffffffff001101f4 (x86_perfmon) at level 0x90000, flags 0x1
[00020.253] 00000.00000> PMU: version 4
[00020.253] 00000.00000> UART: started IRQ driven RX
[00020.253] 00000.00000> UART: started IRQ driven TX
[00020.253] 00000.00000> cpu topology:
[00020.253] 00000.00000> 0: apic id 0x0 package 0 node 0 core 0 smt 0 BSP
[00020.254] 00000.00000> 1: apic id 0x2 package 0 node 0 core 1 smt 0
[00020.254] 00000.00000> 2: apic id 0x1 package 0 node 0 core 0 smt 1
[00020.254] 00000.00000> 3: apic id 0x3 package 0 node 0 core 1 smt 1
[00020.254] 00000.00000> Found 4 cpus
[00020.254] 00000.00000> booting apic ids: 0x2 0x1 0x3
[00020.269] 00000.00000> entering scheduler on cpu 2
[00020.270] 00000.00000> entering scheduler on cpu 3
[00020.270] 00000.00000> entering scheduler on cpu 1
[00020.273] 00000.00000> smbios: manufacturer="Intel Corporation" product="NUC7i5DNHE"
[00020.273] 00000.00000> initializing target
[00020.273] 00000.00000> INIT: cpu 0, calling hook 0xffffffff001053a0 (x86_pcie_init) at level 0xa0000, flags 0x1
[00020.273] 00000.00000> moving to last init level
[00020.273] 00000.00000> INIT: cpu 0, calling hook 0xffffffff00144140 (ktrace) at level 0xc0000, flags 0x1
[00020.276] 00000.00000> ktrace: buffer at 0xffffff9a897b7000 (33554432 bytes)
[00020.276] 00000.00000> INIT: cpu 0, calling hook 0xffffffff00147ab4 (userboot) at level 0xc0000, flags 0x1
[00020.276] 00000.00000> userboot: ramdisk 0x10ad000 @ 0xffffff80012f2000
[00020.277] 00000.00000> userboot: userboot rodata 0 @ [0x5ca9e15d4000,0x5ca9e15d7000)
[00020.277] 00000.00000> userboot: userboot code 0x3000 @ [0x5ca9e15d7000,0x5ca9e15e2000)
[00020.277] 00000.00000> userboot: vdso/full rodata 0 @ [0x5ca9e15e2000,0x5ca9e15e9000)
[00020.277] 00000.00000> userboot: vdso/full code 0x7000 @ [0x5ca9e15e9000,0x5ca9e15ea000)
[00020.277] 00000.00000> userboot: entry point @ 0x5ca9e15d7c10
[00020.277] 00000.00000> INIT: cpu 0, calling hook 0xffffffff001aa030 (kernel_shell) at level 0xc0000, flags 0x1
[00020.277] 01036.01043> userboot: option "netsvc.disable=true"
[00020.277] 01036.01043> userboot: option "zircon.system.disable-automount=true"
[00020.277] 01036.01043> userboot: option "zircon.autorun.boot=/boot/infra/setup"
[00020.277] 01036.01043> userboot: option "kernel.serial=legacy"
[00020.277] 01036.01043> userboot: option "
http://192.168.42.1/multiboot/54%3Ab2%3A03%3A13%3A37%3Aa9="
[00020.277] 01036.01043> userboot: option "multiboot.boot_loader_name=iPXE+1.0.0++(d2063)"
[00020.316] 01036.01043> userboot: searching bootfs for 'bin/bootsvc'
[00020.316] 01036.01043> userboot: 'bin/bootsvc' has PT_INTERP "lib/ld.so.1"
[00020.316] 01036.01043> userboot: searching bootfs for 'lib/ld.so.1'
[00020.316] 01036.01043> userboot: userboot: loaded lib/ld.so.1 at 0x5058408f9000, entry point 0x50584097f0d3
[00020.316] 01036.01043> userboot: userboot: loaded vDSO at 0x45d88b73a000, entry point 0x0
[00020.316] 01036.01043> userboot: process bin/bootsvc started.
[00020.316] 01036.01043> userboot: waiting for loader-service requests...
[00020.316] 01036.01043> userboot: searching bootfs for 'lib/libasync-default.so'
[00020.316] 01036.01043> userboot: searching bootfs for 'lib/libfdio.so'
[00020.316] 01036.01043> userboot: searching bootfs for 'lib/liblaunchpad.so'
[00020.316] 01036.01043> userboot: searching bootfs for 'lib/libtrace-engine.so'
[00020.316] 01050.01053> {{{reset}}}
[00020.316] 01050.01053> {{{module:0:<application>:elf:18de7d58f51e8ba5c4f6afdd0cc8440f482c2b45}}}
[00020.316] 01050.01053> {{{mmap:0x63041eddd000:0x2e000:load:0:rx:0}}}
[00020.316] 01050.01053> {{{mmap:0x63041ee0b000:0x4000:load:0:rw:0x2e000}}}
[00020.316] 01050.01053> dso: id=18de7d58f51e8ba5c4f6afdd0cc8440f482c2b45 base=0x000063041eddd000 name=<application>
[00020.316] 01050.01053> {{{module:0x3:libasync-default.so:elf:c189f51f19d10785d93b5235ad1b46dca4451b00}}}
[00020.316] 01050.01053> {{{mmap:0x598295a38000:0x1000:load:0x3:rx:0}}}
[00020.316] 01050.01053> {{{mmap:0x598295a39000:0x1000:load:0x3:rw:0x1000}}}
[00020.316] 01050.01053> dso: id=c189f51f19d10785d93b5235ad1b46dca4451b00 base=0x0000598295a38000 name=libasync-default.so
[00020.316] 01050.01053> {{{module:0x2:<vDSO>:elf:40ab5fa3b61f12fef4a44477a687f608661cd450}}}
[00020.316] 01050.01053> {{{mmap:0x45d88b73a000:0x7000:load:0x2:r:0}}}
[00020.316] 01050.01053> {{{mmap:0x45d88b741000:0x1000:load:0x2:rx:0x7000}}}
[00020.316] 01050.01053> dso: id=40ab5fa3b61f12fef4a44477a687f608661cd450 base=0x000045d88b73a000 name=<vDSO>
[00020.316] 01050.01053> {{{module:0x1:libc.so:elf:67a12284bce140fc32aaaeac223e0e8f85cb5085}}}
[00020.316] 01050.01053> {{{mmap:0x5058408f9000:0xcb000:load:0x1:rx:0}}}
[00020.316] 01050.01053> {{{mmap:0x5058409c5000:0x6000:load:0x1:rw:0xcc000}}}
[00020.316] 01050.01053> dso: id=67a12284bce140fc32aaaeac223e0e8f85cb5085 base=0x00005058408f9000 name=libc.so
[00020.316] 01050.01053> {{{module:0x4:libfdio.so:elf:27787977e95f3b9563c9e0bd4d34ec92b7e9ad88}}}
[00020.316] 01050.01053> {{{mmap:0x5311615e3000:0x24000:load:0x4:rx:0}}}
[00020.316] 01050.01053> {{{mmap:0x531161608000:0x4000:load:0x4:rw:0x25000}}}
[00020.316] 01050.01053> dso: id=27787977e95f3b9563c9e0bd4d34ec92b7e9ad88 base=0x00005311615e3000 name=libfdio.so
[00020.316] 01050.01053> {{{module:0x5:liblaunchpad.so:elf:6fc2232dc8c1bc5c6adb8ad50ca794b5a260ee4f}}}
[00020.316] 01050.01053> {{{mmap:0x7e4355e77000:0x7000:load:0x5:rx:0}}}
[00020.316] 01050.01053> {{{mmap:0x7e4355e7e000:0x2000:load:0x5:rw:0x7000}}}
[00020.316] 01050.01053> dso: id=6fc2232dc8c1bc5c6adb8ad50ca794b5a260ee4f base=0x00007e4355e77000 name=liblaunchpad.so
[00020.316] 01050.01053> {{{module:0x6:libtrace-engine.so:elf:c9042b83fe01206008fcefb16395238417248169}}}
[00020.316] 01050.01053> {{{mmap:0x517e833b6000:0x9000:load:0x6:rx:0}}}
[00020.316] 01050.01053> {{{mmap:0x517e833bf000:0x2000:load:0x6:rw:0x9000}}}
[00020.316] 01050.01053> dso: id=c9042b83fe01206008fcefb16395238417248169 base=0x0000517e833b6000 name=libtrace-engine.so
[00020.317] 01050.01053> bootsvc: Starting...
[00020.317] 01036.01043> userboot: loader-service channel peer closed
[00020.317] 01036.01043> userboot: finished!
[00020.317] 01050.01053> bootsvc: Creating bootfs service...
[00020.317] 01050.01053> bootsvc: Processing bootdata...
[00020.317] 01050.01053> bootsvc: Loading boot cmdline overrides...
[00020.317] 01050.01053> bootsvc: Loading kernel VMOs...
[00020.317] 01050.01053> bootsvc: Creating loader service...
[00020.317] 01050.01053> bootsvc: Launching next process...
[00020.317] 01050.01096> bootsvc: launched bin/devmgr
[00020.318] 01104.01117> devmgr: main()
[00020.318] 01104.01117> cmdline: netsvc.disable=true
[00020.318] 01104.01117> cmdline: zircon.system.disable-automount=true
[00020.318] 01104.01117> cmdline: zircon.autorun.boot=/boot/infra/setup
[00020.318] 01104.01117> cmdline: kernel.serial=legacy
[00020.318] 01104.01117> cmdline:
http://192.168.42.1/multiboot/54%3Ab2%3A03%3A13%3A37%3Aa9=
[00020.318] 01104.01117> cmdline: multiboot.boot_loader_name=iPXE+1.0.0++(d2063)
[00020.318] 01104.01117> devmgr: coordinator_init()
[00020.318] 01104.01117> devmgr: init
[00020.318] 01104.01117> devmgr: svc init
[00020.318] 01104.01117> devmgr: launch /boot/bin/svchost (svchost) OK
[00020.318] 01104.01117> devmgr: vfs init
[00020.318] 01104.01117> devmgr: launch /boot/bin/fshost (fshost) OK
[00020.318] 01104.01220> devmgr: shell startup
[00020.320] 01182.01202> fshost: started.
[00020.320] 01104.01213> devmgr: launch /boot/bin/pwrbtn-monitor (pwrbtn-monitor) OK
[00020.321] 01104.01233> devmgr: launch /boot/bin/virtual-console (virtual-console) OK
[00020.321] 01104.01233> zircon.autorun.boot: starting '/boot/infra/setup'...
[00020.322] 01104.01233> devmgr: launch /boot/infra/setup (autorun:boot) OK
[00020.324] 01104.01117> devcoord: launch devhost 'devhost:sys': pid=2049
[00020.324] 01104.01117> devcoord: launch devhost 'devhost:test': pid=2082
[00020.324] 01104.01117> devcoord: launch devhost 'devhost:root': pid=2115
[00020.325] 01104.01117> devcoord: launch devhost 'devhost:misc': pid=2171
[00020.325] 02049.02073> devhost: trace provider registry begun
[00020.327] 02082.02105> devhost: trace provider registry begun
[00020.328] 02115.02152> devhost: trace provider registry begun
[00020.328] 02171.02215> devhost: trace provider registry begun
[00020.330] 01104.01220> devmgr: launch /boot/bin/sh (sh:console) OK
[00020.386] 02049.02073> acpi-bus: not using IOMMU
[00020.390] 02049.02073> acpi-pwrbtn: initialized
[00020.413] 02049.02073> acpi: published device pci(0x33aee8208200), parent=proxy(0x33aee8204540), handle=0x33aee8240c30
[00020.414] 02049.02073> acpi: published device rtc(0x33aee8203080), parent=acpi(0x33aee8204780), handle=0x33aee82595b0
[00020.415] 02049.02073> acpi-ec: initialized
[00020.417] 02049.02073> acpi: failed to create NHLT VMO (res -10)
[00020.417] 02049.02073> acpi: failed to publish NHLT metadata
[00020.419] 02049.02073> [sysmem_init 28] async_get_default_dispatcher(): 0x33aee81f70a0
[00020.419] 02049.02073> [sysmem_bind 40] sysmem_bind()
[00020.419] 02049.02073> acpi-bus: sysmem_register_protocol() intentionally ignored for now.
[00020.419] 02049.02073> PMU: 7 arch events
[00020.419] 02049.02073> PMU: arch event id range: 1-7
[00020.419] 02049.02073> PMU: 102 model events
[00020.419] 02049.02073> PMU: model event id range: 1-241
[00020.419] 02049.02073> Intel Processor Trace configuration for this chipset:
[00020.419] 02049.02073> mtc_freq_mask: 0x249
[00020.419] 02049.02073> cyc_thresh_mask: 0x3fff
[00020.419] 02049.02073> psb_freq_mask: 0x3f
[00020.419] 02049.02073> num addr ranges: 2
[00020.419] 01104.01117> devcoord: launch devhost 'devhost:pci#1:8086:5916': pid=2840
[00020.420] 01104.01117> devcoord: launch devhost 'devhost:pci#3:8086:9d2f': pid=2882
[00020.420] 01104.01117> devcoord: launch devhost 'devhost:pci#5:8086:9d60': pid=2944
[00020.421] 01104.01117> devcoord: launch devhost 'devhost:pci#6:8086:9d61': pid=3006
[00020.421] 02840.02863> devhost: trace provider registry begun
[00020.422] 01104.01117> devcoord: launch devhost 'devhost:pci#9:8086:9d03': pid=3092
[00020.422] 02882.02919> devhost: trace provider registry begun
[00020.423] 01104.01117> devcoord: launch devhost 'devhost:pci#14:8086:9d71': pid=3215
[00020.423] 02944.02984> devhost: trace provider registry begun
[00020.423] 03006.03047> devhost: trace provider registry begun
[00020.423] 01104.01117> devcoord: launch devhost 'devhost:pci#16:8086:156f': pid=3305
[00020.425] 03092.03151> devhost: trace provider registry begun
[00020.425] 02944.02984> initialized intel serialio i2c driver, reg=0x2c344e0f000 regsize=4096
[00020.426] 03006.03047> initialized intel serialio i2c driver, reg=0x2319c9b20000 regsize=4096
[00020.426] 03305.03349> devhost: trace provider registry begun
[00020.426] 03215.03272> devhost: trace provider registry begun
[00020.428] 03092.03151> ahci: using MSI interrupt
[00020.432] 02882.03682> * found USB device (0x18d1:0xa002, USB 2.0) config 1
[00020.432] 02882.03682> * found USB device (0x18d1:0xa003, USB 3.0) config 1
[00020.440] 01242.01554> vc: new input device /dev/class/input/000
[00020.440] 03215.03272> [IHDA DSP 00:1f.3] Failed to fetch NHLT (res -25)
[00020.440] 03215.03272> devhost[00:1f.3/intel-hda-000/intel-sst-dsp-000] bind driver '/boot/driver/dsp.so' failed: -25
[00020.441] 01104.01117> devcoord: rpc: bind-driver 'intel-sst-dsp-000' status -25
[00020.530] 01242.01554> vc: new display device /dev/class/display-controller/000/virtcon
[00020.670] 02840.04142> i915: MST not supported
[00021.170] 02840.04142> i915: Found DP monitor
[00021.170] 02840.04142> i915: Display 1 connected
[00021.730] 01242.01554> vc: Successfully attached to display 1
[00021.894] 02882.03682> * found USB device (0x0781:0x5571, USB 2.10) config 1
[00021.895] 02882.02919> UMS: parent: 'ifc-000'
[00021.895] 02882.02919> UMS:Max lun is: 0
[00022.145] 02882.03682> * found USB device (0x8087:0x0a2b, USB 2.0) config 1
[00022.146] 02882.02919> devhost[00:14.0/xhci/usb-bus/002/002/ifc-001] bind driver '/boot/driver/bt-transport-usb.so' failed: -2
[00022.146] 01104.01117> devcoord: rpc: bind-driver 'ifc-001' status -2
[00022.429] 03006.03047> intel-i2c-controller: intel_serialio_i2c_slave_transfer: -21
[00022.429] 03006.03047> i2c-hid: could not read HID descriptor: 0
[00022.429] 03006.03047> devhost[00:15.1/i2c-bus-9d61/004c] bind driver '/boot/driver/i2c-hid.so' failed: -2
[00022.429] 01104.01117> devcoord: rpc: bind-driver '004c' status -2
[00022.430] 02944.02984> intel-i2c-controller: intel_serialio_i2c_slave_transfer: -21
[00022.430] 02944.02984> i2c-hid: could not read HID descriptor: 0
[00022.430] 02944.02984> devhost[00:15.0/i2c-bus-9d60/0020] bind driver '/boot/driver/i2c-hid.so' failed: -2
[00022.430] 01104.01117> devcoord: rpc: bind-driver '0020' status -2
[00022.444] 03092.03720> sata2: dev info
[00022.444] 03092.03720> serial=AA000000000000001193
[00022.444] 03092.03720> firmware rev=0R08A1 0
[00022.444] 03092.03720> model id=ETMAT 8MSP1582 G
[00022.444] 03092.03720> major=0x3f0 ACS2 DMA 32 commands
[00022.444] 03092.03720> LBA48 250069680 sectors, sector size=512
[00022.445] 01182.01202> devmgr: /dev/class/block/000: GPT?
[00022.445] 01104.01117> devcoord: dc_bind_device() '/boot/driver/gpt.so'
[00022.446] 03092.03151> gpt: device_get_metadata failed (-25)
[00022.447] 01182.01202> devmgr: /dev/class/block/001: FVM?
[00022.447] 01104.01117> devcoord: dc_bind_device() '/boot/driver/fvm.so'
[00022.449] 04413.04427> paver:[Initialize] Successfully initialized EFI Device Partitioner
[00022.451] 04413.04427> paver:[WipePartitions] Immediate reboot strongly recommended
[00022.452] 03092.03151> block: Joining un-closed FIFO server
[00022.452] 03092.03151> block: Joining un-closed FIFO server
[00022.452] 03092.03151> block: Joining un-closed FIFO server
[00022.452] 01104.01117> devcoord: dc_bind_device() ''
[00022.453] 01182.01202> devmgr: /dev/class/block/000: GPT?
[00022.453] 01104.01117> devcoord: dc_bind_device() '/boot/driver/gpt.so'
[00022.453] 03092.03151> gpt: device_get_metadata failed (-25)
[00022.454] 03092.04753> gpt: bad header magic
[00022.455] 04702.04716> 34+0 records in
[00022.455] 04702.04716> 34+0 records out
[00022.455] 04702.04716> 17408 bytes copied
[00022.457] 04819.04833> 34+0 records in
[00022.457] 04819.04833> 34+0 records out
[00022.457] 04819.04833> 17408 bytes copied
[00022.458] 04923.04937> netifc: ? /dev/class/ethernet/000
[00022.458] 04923.04937> netifc: create 512 eth buffers
[00022.458] 04923.04937> macaddr: 54:b2:03:13:37:a9
[00022.458] 04923.04937> ip6addr: fe80::56b2:34d:fe13:37a9
[00022.458] 04923.04937> snmaddr: ff02::1:ff13:37a9
[00022.458] 04923.04937> netsvc: using /dev/class/ethernet/000
[00022.458] 04923.04937> _ _ _
[00022.458] 04923.04937> | | | | |
[00022.458] 04923.04937> _______ __| | |__ ___ ___ | |_
[00022.458] 04923.04937> |_ / _ \/ _` | '_ \ / _ \ / _ \| __|
[00022.458] 04923.04937> / / __/ (_| | |_) | (_) | (_) | |_
[00022.458] 04923.04937> /___\___|\__,_|_.__/ \___/ \___/ \__|
[00022.458] 04923.04937>
[00022.458] 04923.04937>
[00022.458] 04923.04937> zedboot: version: 0.7.13
[00022.458] 04923.04937>
[00022.458] 04923.04937> netsvc: nodename='jam-tutor-plank-yelp'
[00022.458] 04923.04937> netsvc: will not advertise
[00022.458] 04923.04937> netsvc: start
[00022.897] 02882.04246> UMS: block size is: 0x00000200
[00022.897] 02882.04246> UMS: total blocks is: 15630336
[00022.897] 02882.04246> UMS: total size is: 8002732032
[00022.897] 02882.04246> UMS: read-only: 0 removable: 1
[00022.898] 01182.01202> devmgr: /dev/class/block/006: MBR?
[00022.898] 01104.01117> devcoord: dc_bind_device() '/boot/driver/mbr.so'
[00022.901] 01182.01202> devmgr: /dev/class/block/008: MBR?
[00022.901] 01104.01117> devcoord: dc_bind_device() '/boot/driver/mbr.so'
[00117.337] 04923.04937> netsvc: handling tftp request failed (file might not exist)
[00117.337] 04923.04937> netsvc: close, but no open file
[00117.337] 04923.04937> netsvc: metrics: {"inorderblks": 0,"oooblks": 0,"ack": 0,"nack": 0,"timeouts": 0,"sas": 0,"inorderbytes": 0}
[00117.337] 04923.04937> netsvc: tftp write of file <<netboot>>cmdline completed
[00117.338] 04923.04937> netsvc: metrics: {"inorderblks": 1,"oooblks": 0,"ack": 1,"nack": 0,"timeouts": 0,"sas": 0,"inorderbytes": 55}
[00117.338] 04923.04937> netsvc: Running FVM Paver
[00117.340] 04923.05111> paver:[InitializeGpt] Located GPT is invalid; Attempting to initialize
[00117.340] 01104.01117> devcoord: dc_bind_device() '/boot/driver/gpt.so'
[00117.340] 03092.03151> gpt: device_get_metadata failed (-25)
[00117.342] 04923.05111> paver:[Initialize] Successfully initialized EFI Device Partitioner
[00117.342] 04923.05111> paver:[PartitionPave] Paving partition.
[00117.342] 04923.05111> paver:[FindFirstFit] Looking for space
[00117.342] 04923.05111> paver:[FindFirstFit] Sorting
[00117.342] 04923.05111> paver:[FindFirstFit] Partition[0] From Block [0, 34) ... (next partition starts at block 250069646)
[00117.342] 04923.05111> paver:[FindFirstFit] There are 250069612 free blocks (16777216 requested)
[00117.342] 04923.05111> paver:[AddPartition] Found space in GPT - OK 250069612 @ 34
[00117.342] 04923.05111> paver:[AddPartition] Final space in GPT - OK 16777216 @ 34
[00117.342] 04923.05111> paver:[AddPartition] Added partition, waiting for bind
[00117.342] 01104.01117> devcoord: dc_bind_device() ''
[00117.344] 01182.01202> devmgr: /dev/class/block/000: GPT?
[00117.344] 01104.01117> devcoord: dc_bind_device() '/boot/driver/gpt.so'
[00117.344] 03092.03151> gpt: device_get_metadata failed (-25)
[00117.344] 04923.05111> paver:[AddPartition] Added partition, waiting for bind - OK
[00117.344] 04923.05111> paver:[PartitionPave] Streaming partitions...
[00117.344] 05091.05105> Found compressed file
[00117.345] 04923.05111> paver:[FvmStreamPartitions] Header Validated - OK
[00117.345] 04923.05111> paver:[FvmPartitionFormat] Initializing partition as FVM
[00117.347] 01104.01117> devcoord: dc_bind_device() '/boot/driver/fvm.so'
[00118.349] 04923.05111> paver:[FvmStreamPartitions] Partitions pre-validated successfully: Enough space exists to pave.
[00118.349] 04923.05111> paver:[AllocatePartitions] Allocating partition blobfs consisting of 1 slices
[00118.353] 04923.05111> paver:[AllocatePartitions] Allocating partition minfs consisting of 1 slices
[00118.354] 04923.05111> paver:[AllocatePartitions] Creating zxcrypt volume
[00118.356] 03092.03151> devhost_get_handles(0x79d21a214900:block) open path='zxcrypt/block', r=-2
[00118.356] 01104.01117> devcoord: dc_bind_device() '/boot/driver/zxcrypt.so'
[00118.356] 03092.03151> devhost_get_handles(0x79d21a214900:block) open path='zxcrypt', r=-2
[00118.360] 04923.05111> paver:[FvmStreamPartitions] Partition space pre-allocated successfully.
[00118.360] 04923.05111> paver:[FvmStreamPartitions] Streaming partition 0
[00118.360] 04923.05111> paver:[StreamFvmPartition] Writing extent 0...
[00118.360] 04923.05117> netsvc: paver write progress 0.1%
[00118.360] 04923.05111> paver:[StreamFvmPartition] 8192 bytes written, 8380416 zeroes left
[00118.387] 04923.05111> paver:[StreamFvmPartition] Writing extent 1...
[00118.387] 04923.05111> paver:[StreamFvmPartition] 8192 bytes written, 8380416 zeroes left
[00118.403] 04923.05111> paver:[StreamFvmPartition] Writing extent 2...
[00118.408] 04923.05111> paver:[StreamFvmPartition] 2097152 bytes written, 6291456 zeroes left
[00118.420] 04923.05111> paver:[StreamFvmPartition] Writing extent 3...
[00118.425] 04923.05111> paver:[StreamFvmPartition] 2097152 bytes written, 6291456 zeroes left
[00118.437] 04923.05111> paver:[StreamFvmPartition] Writing extent 4...
[00119.360] 04923.05117> netsvc: paver write progress 61.9%
[00120.360] 04923.05117> netsvc: paver write progress 92.7%
2019/05/24 01:25:10 done
2019/05/24 01:25:10 attempting to send <<image>>bootloader.img...
2019/05/24 01:25:10 target is busy, retrying in one second
[00120.597] 04923.04937> netsvc: tftp write of file <<image>>sparse.fvm completed
[00120.597] 04923.04937> netsvc: metrics: {"inorderblks": 319526,"oooblks": 0,"ack": 1249,"nack": 0,"timeouts": 0,"sas": 0,"inorderbytes": 327194421}
[00120.597] 04923.05111> paver:[StreamFvmPartition] 355762176 bytes written, 4947968 zeroes left
[00120.607] 04923.05111> paver:[FvmStreamPartitions] Done streaming partition 0
[00120.607] 04923.05111> paver:[FvmStreamPartitions] Done flushing partition 0
[00120.607] 04923.05111> paver:[FvmStreamPartitions] Streaming partition 1
[00120.607] 04923.05111> paver:[StreamFvmPartition] Writing extent 0...
[00120.607] 04923.05111> paver:[StreamFvmPartition] 8192 bytes written, 8380416 zeroes left
[00120.646] 04923.05111> paver:[StreamFvmPartition] Writing extent 1...
[00120.646] 04923.05111> paver:[StreamFvmPartition] 65536 bytes written, 8323072 zeroes left
[00120.692] 04923.05111> paver:[StreamFvmPartition] Writing extent 2...
[00120.692] 04923.05111> paver:[StreamFvmPartition] 65536 bytes written, 8323072 zeroes left
[00120.728] 04923.05111> paver:[StreamFvmPartition] Writing extent 3...
[00120.766] 04923.05111> paver:[StreamFvmPartition] Writing extent 4...
[00120.775] 04923.05111> paver:[StreamFvmPartition] 2097152 bytes written, 14680064 zeroes left
[00120.843] 04923.05111> paver:[StreamFvmPartition] Writing extent 5...
[00120.843] 04923.05111> paver:[StreamFvmPartition] 57344 bytes written, 8331264 zeroes left
[00120.879] 04923.05111> paver:[FvmStreamPartitions] Done streaming partition 1
[00120.879] 04923.05111> paver:[FvmStreamPartitions] Done flushing partition 1
[00120.880] 05091.05105> Reading FVM from compressed file: true
[00120.880] 05091.05105> Remaining bytes read into compression buffer: 0
[00120.880] 05091.05105> Remaining bytes written to decompression buffer: 0
[00120.880] 05091.05105> Time reading bytes from sparse FVM file: 3715372638 (1 s)
[00120.880] 05091.05105> Time reading bytes AND decompressing them: 3900309674 (1 s)
[00120.880] 04923.05111> paver:[PartitionPave] Completed successfully
2019/05/24 01:25:11 attempting to send <<image>>bootloader.img...
2019/05/24 01:25:11 done
2019/05/24 01:25:11 attempting to send <<image>>zircona.img...
2019/05/24 01:25:11 target is busy, retrying in one second
[00121.598] 04923.04937> netsvc: Running BOOTLOADER Paver
[00121.602] 04923.05998> paver:[Initialize] Successfully initialized EFI Device Partitioner
[00121.602] 04923.05998> paver:[RealMain] SKIPPING BOOTLOADER install on x64 device, pass --force if desired.
[00121.612] 04923.04937> netsvc: tftp write of file <<image>>bootloader.img completed
[00121.612] 04923.04937> netsvc: metrics: {"inorderblks": 1093,"oooblks": 0,"ack": 5,"nack": 0,"timeouts": 0,"sas": 0,"inorderbytes": 1118208}
2019/05/24 01:25:12 attempting to send <<image>>zircona.img...
[00122.612] 04923.04937> netsvc: Running ZIRCON-A Paver
[00122.615] 04923.06127> paver:[Initialize] Successfully initialized EFI Device Partitioner
[00122.615] 04923.06127> paver:[PartitionPave] Paving partition.
[00122.615] 04923.06127> paver:[FindFirstFit] Looking for space
[00122.615] 04923.06127> paver:[FindFirstFit] Partition seen with start 34, end 16777249 (length 16777216)
[00122.615] 04923.06127> paver:[FindFirstFit] Sorting
[00122.615] 04923.06127> paver:[FindFirstFit] Partition[0] From Block [0, 34) ... (next partition starts at block 34)
[00122.615] 04923.06127> paver:[FindFirstFit] There are 0 free blocks (32768 requested)
[00122.615] 04923.06127> paver:[FindFirstFit] Partition[1] From Block [34, 16777250) ... (next partition starts at block 250069646)
[00122.615] 04923.06127> paver:[FindFirstFit] There are 233292396 free blocks (32768 requested)
[00122.615] 04923.06127> paver:[AddPartition] Found space in GPT - OK 233292396 @ 16777250
[00122.615] 04923.06127> paver:[AddPartition] Final space in GPT - OK 32768 @ 16777250
[00122.616] 04923.06127> paver:[AddPartition] Added partition, waiting for bind
[00122.616] 03092.03151> block: Joining un-closed FIFO server
[00122.616] 03092.03151> block: Joining un-closed FIFO server
[00122.616] 01104.01117> devcoord: dc_bind_device() ''
[00122.617] 01182.01202> devmgr: /dev/class/block/000: GPT?
[00122.617] 01104.01117> devcoord: dc_bind_device() '/boot/driver/gpt.so'
[00122.617] 03092.03151> gpt: device_get_metadata failed (-25)
[00122.618] 01182.01202> devmgr: /dev/class/block/013: FVM?
[00122.618] 01104.01117> devcoord: dc_bind_device() '/boot/driver/fvm.so'
[00122.618] 04923.06127> paver:[AddPartition] Added partition, waiting for bind - OK
2019/05/24 01:25:12 done
2019/05/24 01:25:12 attempting to send <<image>>zirconr.img...
2019/05/24 01:25:12 target is busy, retrying in one second
[00122.743] 04923.04937> netsvc: tftp write of file <<image>>zircona.img completed
[00122.743] 04923.04937> netsvc: metrics: {"inorderblks": 12428,"oooblks": 0,"ack": 49,"nack": 0,"timeouts": 0,"sas": 0,"inorderbytes": 12725592}
[00122.767] 04923.06127> paver:[PartitionPave] Completed successfully
2019/05/24 01:25:13 attempting to send <<image>>zirconr.img...
[00123.744] 04923.04937> netsvc: Running ZIRCON-R Paver
[00123.746] 04923.06388> paver:[Initialize] Successfully initialized EFI Device Partitioner
[00123.746] 04923.06388> paver:[PartitionPave] Paving partition.
[00123.746] 04923.06388> paver:[FindFirstFit] Looking for space
[00123.746] 04923.06388> paver:[FindFirstFit] Partition seen with start 34, end 16777249 (length 16777216)
[00123.746] 04923.06388> paver:[FindFirstFit] Partition seen with start 16777250, end 16810017 (length 32768)
[00123.746] 04923.06388> paver:[FindFirstFit] Sorting
[00123.747] 04923.06388> paver:[FindFirstFit] Partition[0] From Block [0, 34) ... (next partition starts at block 34)
[00123.747] 04923.06388> paver:[FindFirstFit] There are 0 free blocks (49152 requested)
[00123.747] 04923.06388> paver:[FindFirstFit] Partition[1] From Block [34, 16777250) ... (next partition starts at block 16777250)
[00123.747] 04923.06388> paver:[FindFirstFit] There are 0 free blocks (49152 requested)
[00123.747] 04923.06388> paver:[FindFirstFit] Partition[2] From Block [16777250, 16810018) ... (next partition starts at block 250069646)
[00123.747] 04923.06388> paver:[FindFirstFit] There are 233259628 free blocks (49152 requested)
[00123.747] 04923.06388> paver:[AddPartition] Found space in GPT - OK 233259628 @ 16810018
[00123.747] 04923.06388> paver:[AddPartition] Final space in GPT - OK 49152 @ 16810018
[00123.747] 04923.06388> paver:[AddPartition] Added partition, waiting for bind
[00123.747] 03092.03151> block: Joining un-closed FIFO server
[00123.747] 01104.01117> devcoord: dc_bind_device() ''
[00123.748] 01182.01202> devmgr: /dev/class/block/000: GPT?
[00123.748] 01104.01117> devcoord: dc_bind_device() '/boot/driver/gpt.so'
[00123.748] 03092.03151> gpt: device_get_metadata failed (-25)
[00123.749] 01182.01202> devmgr: /dev/class/block/017: FVM?
[00123.749] 01104.01117> devcoord: dc_bind_device() '/boot/driver/fvm.so'
[00123.749] 04923.06388> paver:[AddPartition] Added partition, waiting for bind - OK
2019/05/24 01:25:13 done
2019/05/24 01:25:13 attempting to send <<image>>authorized_keys...
2019/05/24 01:25:13 target is busy, retrying in one second
[00123.862] 04923.04937> netsvc: tftp write of file <<image>>zirconr.img completed
[00123.862] 04923.04937> netsvc: metrics: {"inorderblks": 11309,"oooblks": 0,"ack": 45,"nack": 0,"timeouts": 0,"sas": 0,"inorderbytes": 11580280}
[00123.895] 04923.06388> paver:[PartitionPave] Completed successfully
2019/05/24 01:25:14 attempting to send <<image>>authorized_keys...
2019/05/24 01:25:14 done
2019/05/24 01:25:14 attempting to send <<netboot>>kernel.bin...
2019/05/24 01:25:14 target is busy, retrying in one second
[00124.862] 04923.04937> netsvc: Installing SSH authorized_keys
[00124.863] 04923.04937> netsvc: tftp write of file <<image>>authorized_keys completed
[00124.863] 04923.04937> netsvc: metrics: {"inorderblks": 1,"oooblks": 0,"ack": 1,"nack": 0,"timeouts": 0,"sas": 0,"inorderbytes": 806}
[00124.865] 04923.06665> paver:[Initialize] Successfully initialized EFI Device Partitioner
[00124.866] 01104.01117> devcoord: dc_bind_device() '/boot/driver/zxcrypt.so'
[00124.866] 03092.03151> devhost_get_handles(0x79d21a214900:block) open path='zxcrypt', r=-2
[00124.893] 04923.06665> paver:[DataFilePave] Wrote ssh/authorized_keys
2019/05/24 01:25:15 attempting to send <<netboot>>kernel.bin...
2019/05/24 01:25:15 done
[00000.000] 00000.00000> zbi: @ 0xffffff80096af000 (11133648 bytes)
[00000.000] 00000.00000> UART: FIFO depth 16
[00000.000] 00000.00000> PMM: boot reserve add [0x100000, 0x311fff]
[00000.000] 00000.00000> PMM: boot reserve add [0x96af000, 0xa14dfff]
[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 0x8afff000 size 0x1000
[00000.000] 00000.00000> PMM: boot reserve marking WIRED [0x100000, 0x311fff]
[00000.000] 00000.00000> PMM: boot reserve marking WIRED [0x96af000, 0xa14dfff]
[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 0xffffffff001183f4 (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 [0x312000, 0x312100)
[00000.000] 00000.00000> INIT: cpu 0, calling hook 0xffffffff00125650 (elf_build_id) at level 0x4fffe, flags 0x1
[00000.000] 00000.00000> INIT: cpu 0, calling hook 0xffffffff001257dc (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-9eee4cf740601a3441852c1ae11956f10d7ede2d-dirty
[00000.000] 00000.00000> ELF build ID: 18e90720d4cfbc1b669551a05daecb3b31893ca0
[00000.000] 00000.00000> initializing heap
[00000.000] 00000.00000> INIT: cpu 0, calling hook 0xffffffff00101f78 (console) at level 0x50000, flags 0x1
[00000.000] 00000.00000> INIT: cpu 0, calling hook 0xffffffff00187280 (x86_resource_init) at level 0x50000, flags 0x1
[00000.000] 00000.00000> initializing vm
[00000.000] 00000.00000> VM: reserving kernel region [0xffffffff00100000, 0xffffffff00229000) flags 0x28 name 'kernel_code'
[00000.000] 00000.00000> VM: reserving kernel region [0xffffffff00229000, 0xffffffff0027c000) flags 0x8 name 'kernel_rodata'
[00000.000] 00000.00000> VM: reserving kernel region [0xffffffff0027c000, 0xffffffff00284000) flags 0x18 name 'kernel_data'
[00000.000] 00000.00000> VM: reserving kernel region [0xffffffff00284000, 0xffffffff00312000) flags 0x18 name 'kernel_bss'
[00000.000] 00000.00000> INIT: cpu 0, calling hook 0xffffffff00187fa4 (display_memtype) at level 0x60001, flags 0x1
[00000.000] 00000.00000> INIT: cpu 0, calling hook 0xffffffff0018b4cc (acpi_tables) at level 0x60001, flags 0x1
[00000.000] 00000.00000> INIT: cpu 0, calling hook 0xffffffff00185fa8 (hpet) at level 0x60002, flags 0x1
[00000.000] 00000.00000> INIT: cpu 0, calling hook 0xffffffff001863c4 (apic) at level 0x60002, flags 0x1
[00000.000] 00000.00000> x2APIC enabled
[00000.000] 00000.00000> INIT: cpu 0, calling hook 0xffffffff001ad240 (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 0xffffffff0018aabc (timer) at level 0x60003, flags 0x1
[00000.000] 00000.00000> HPET frequency: 23999 ticks/ms
[00000.000] 00000.00000> TSC frequency: 2712000 ticks/ms
[00126.274] 00000.00000> timer features: constant_tsc 1 invariant_tsc 1 tsc_deadline 1
[00126.274] 00000.00000> Using TSC as wallclock
[00126.274] 00000.00000> INIT: cpu 0, calling hook 0xffffffff0021905c (percpu_heap_init) at level 0x60003, flags 0x1
[00126.274] 00000.00000> initializing kernel
[00126.274] 00000.00000> initializing mp
[00126.274] 00000.00000> INIT: cpu 0, calling hook 0xffffffff00118648 (global_prng_thread_safe) at level 0x7ffff, flags 0x1
[00126.274] 00000.00000> creating bootstrap completion thread
[00126.274] 00000.00000> top of bootstrap2()
[00126.274] 00000.00000> INIT: cpu 0, calling hook 0xffffffff00134cac (libobject) at level 0x80000, flags 0x1
[00126.274] 00000.00000> OOM: started thread
[00126.274] 00000.00000> INIT: cpu 0, calling hook 0xffffffff00215e6c (dpc) at level 0x80000, flags 0x1
[00126.274] 00000.00000> Processor Model Info: type 0 family 0x6 model 0xe stepping 0x9
[00126.274] 00000.00000> display_family 0x6 display_model 0x8e
[00126.274] 00000.00000> Vendor: Intel
[00126.274] 00000.00000> Microarch: Kaby Lake
[00126.274] 00000.00000> F/M/S: 6/8e/9
[00126.274] 00000.00000> patch_level: 8e
[00126.274] 00000.00000> Brand: Intel(R) Core(TM) i5-7300U CPU @ 2.60GHz
[00126.274] 00000.00000> Features: fpu sse sse2 sse3 ssse3 sse4.1 sse4.2 mmx avx avx2 fxsr pcid xsave mon aesni clflush
[00126.274] 00000.00000> clflushopt fsgsbase tsc_adj smep smap erms rdrand rdseed syscall nx huge rdtscp
[00126.274] 00000.00000> invar_tsc tsc_deadline x2apic vmx pt hwp
[00126.274] 00000.00000> Properties: meltdown l1tf pcid_good
[00126.274] 00000.00000> initializing platform
[00126.274] 00000.00000> INIT: cpu 0, calling hook 0xffffffff001a68c4 (x86_perfmon) at level 0x90000, flags 0x1
[00126.274] 00000.00000> PMU: version 4
[00126.274] 00000.00000> UART: started IRQ driven RX
[00126.274] 00000.00000> UART: started IRQ driven TX
[00126.274] 00000.00000> cpu topology:
[00126.274] 00000.00000> 0: apic id 0x0 BSP
[00126.274] 00000.00000> 1: apic id 0x1
[00126.274] 00000.00000> 2: apic id 0x2
[00126.274] 00000.00000> 3: apic id 0x3
[00126.274] 00000.00000> Found 4 cpus
[00126.274] 00000.00000> booting apic ids: 0x1 0x2 0x3
[00126.289] 00000.00000> entering scheduler on cpu 1
[00126.291] 00000.00000> entering scheduler on cpu 2
[00126.291] 00000.00000> entering scheduler on cpu 3
[00126.293] 00000.00000> smbios: manufacturer="Intel Corporation" product="NUC7i5DNHE"
[00126.293] 00000.00000> initializing target
[00126.293] 00000.00000> INIT: cpu 0, calling hook 0xffffffff00189c60 (x86_pcie_init) at level 0xa0000, flags 0x1
[00126.293] 00000.00000> moving to last init level
[00126.293] 00000.00000> INIT: cpu 0, calling hook 0xffffffff001248a8 (debuglog) at level 0xb0000, flags 0x1
[00126.293] 00000.00000> INIT: cpu 0, calling hook 0xffffffff00179884 (kcounters) at level 0xb0000, flags 0x1
[00126.293] 00000.00000> INIT: cpu 0, calling hook 0xffffffff00102aa0 (kernel_shell) at level 0xc0000, flags 0x1
[00126.293] 00000.00000> INIT: cpu 0, calling hook 0xffffffff00212890 (ktrace) at level 0xc0000, flags 0x1
[00126.297] 00000.00000> ktrace: buffer at 0xffffff9711815000 (33554432 bytes)
[00126.297] 00000.00000> INIT: cpu 0, calling hook 0xffffffff00225ea0 (userboot) at level 0xc0000, flags 0x1
[00126.297] 00000.00000> userboot: ramdisk 0xa9f000 @ 0xffffff80096af000
[00126.297] 00000.00000> userboot: userboot rodata 0 @ [0x2d3d4e197000,0x2d3d4e19a000)
[00126.297] 00000.00000> userboot: userboot code 0x3000 @ [0x2d3d4e19a000,0x2d3d4e1a5000)
[00126.297] 00000.00000> userboot: vdso/full rodata 0 @ [0x2d3d4e1a5000,0x2d3d4e1ac000)
[00126.297] 00000.00000> userboot: vdso/full code 0x7000 @ [0x2d3d4e1ac000,0x2d3d4e1ad000)
[00126.297] 00000.00000> userboot: entry point @ 0x2d3d4e19ac90
[00126.297] 01036.01043> userboot: option "zircon.autorun.system=/boot/bin/sh+/boot/infra/runcmds"
[00126.322] 01036.01043> userboot: searching bootfs for 'bin/bootsvc'
[00126.322] 01036.01043> userboot: 'bin/bootsvc' has PT_INTERP "lib/ld.so.1"
[00126.322] 01036.01043> userboot: searching bootfs for 'lib/ld.so.1'
[00126.322] 01036.01043> userboot: userboot: loaded lib/ld.so.1 at 0x7c6bf44f8000, entry point 0x7c6bf4516880
[00126.322] 01036.01043> userboot: userboot: loaded vDSO at 0x6e887a165000, entry point 0x6e887a16c947
[00126.322] 01036.01043> userboot: process bin/bootsvc started.
[00126.322] 01036.01043> userboot: waiting for loader-service requests...
[00126.322] 01036.01043> userboot: searching bootfs for 'lib/libfdio.so'
[00126.322] 01036.01043> userboot: searching bootfs for 'lib/libtrace-engine.so'
[00126.322] 01036.01043> userboot: searching bootfs for 'lib/libasync-default.so'
[00126.322] 01036.01043> userboot: searching bootfs for 'lib/liblaunchpad.so'
[00126.322] 01036.01043> userboot: searching bootfs for 'lib/libc++.so.2'
[00126.322] 01036.01043> userboot: searching bootfs for 'lib/libc++abi.so.1'
[00126.322] 01036.01043> userboot: searching bootfs for 'lib/libunwind.so.1'
[00126.323] 01050.01053> {{{reset}}}
[00126.323] 01050.01053> {{{module:0:<application>:elf:cb41ad5ff525119d5fb38913fececc6a4a9a91fe}}}
[00126.323] 01050.01053> {{{mmap:0x294088882000:0x3b000:load:0:rx:0}}}
[00126.323] 01050.01053> {{{mmap:0x2940888be000:0x4000:load:0:rw:0x3c000}}}
[00126.323] 01050.01053> dso: id=cb41ad5ff525119d5fb38913fececc6a4a9a91fe base=0x0000294088882000 name=<application>
[00126.323] 01050.01053> {{{module:0x2:<vDSO>:elf:2ddcbe6a7f3c2077addc9a53695676646bee1abf}}}
[00126.323] 01050.01053> {{{mmap:0x6e887a165000:0x7000:load:0x2:r:0}}}
[00126.323] 01050.01053> {{{mmap:0x6e887a16c000:0x1000:load:0x2:rx:0x7000}}}
[00126.323] 01050.01053> dso: id=2ddcbe6a7f3c2077addc9a53695676646bee1abf base=0x00006e887a165000 name=<vDSO>
[00126.323] 01050.01053> {{{module:0x3:libfdio.so:elf:5f05a9dbbc82442cfe83235ad3b42ba339cb2cff}}}
[00126.323] 01050.01053> {{{mmap:0x6a171daca000:0x39000:load:0x3:rx:0}}}
[00126.323] 01050.01053> {{{mmap:0x6a171db03000:0x6000:load:0x3:rw:0x39000}}}
[00126.323] 01050.01053> dso: id=5f05a9dbbc82442cfe83235ad3b42ba339cb2cff base=0x00006a171daca000 name=libfdio.so
[00126.323] 01050.01053> {{{module:0x4:libtrace-engine.so:elf:36b9f8765d0109090c021638f2101b253564162e}}}
[00126.323] 01050.01053> {{{mmap:0x4978a7b1a000:0x9000:load:0x4:rx:0}}}
[00126.323] 01050.01053> {{{mmap:0x4978a7b23000:0x2000:load:0x4:rw:0x9000}}}
[00126.323] 01050.01053> dso: id=36b9f8765d0109090c021638f2101b253564162e base=0x00004978a7b1a000 name=libtrace-engine.so
[00126.323] 01050.01053> {{{module:0x5:libasync-default.so:elf:ecb2bce2176d0a131210570fb2d3e094fa6e1d49}}}
[00126.323] 01050.01053> {{{mmap:0x23957846a000:0x1000:load:0x5:rx:0}}}
[00126.323] 01050.01053> {{{mmap:0x23957846b000:0x1000:load:0x5:rw:0x1000}}}
[00126.323] 01050.01053> dso: id=ecb2bce2176d0a131210570fb2d3e094fa6e1d49 base=0x000023957846a000 name=libasync-default.so
[00126.323] 01050.01053> {{{module:0x6:liblaunchpad.so:elf:4aa3c1bd360c85e919db0aeb1ff6d7adb1818ed0}}}
[00126.323] 01050.01053> {{{mmap:0x62bfde9a5000:0x7000:load:0x6:rx:0}}}
[00126.323] 01050.01053> {{{mmap:0x62bfde9ac000:0x2000:load:0x6:rw:0x7000}}}
[00126.323] 01050.01053> dso: id=4aa3c1bd360c85e919db0aeb1ff6d7adb1818ed0 base=0x000062bfde9a5000 name=liblaunchpad.so
[00126.323] 01050.01053> {{{module:0x1:libc.so:elf:2d3da7ba6f1127c094f287551e1f1415d351c2ac}}}
[00126.323] 01050.01053> {{{mmap:0x7c6bf44f8000:0xa6000:load:0x1:rx:0}}}
[00126.323] 01050.01053> {{{mmap:0x7c6bf459e000:0x5000:load:0x1:rw:0xa6000}}}
[00126.323] 01050.01053> dso: id=2d3da7ba6f1127c094f287551e1f1415d351c2ac base=0x00007c6bf44f8000 name=libc.so
[00126.323] 01050.01053> {{{module:0x7:libc++.so.2:elf:c40e3db9703e022b}}}
[00126.323] 01050.01053> {{{mmap:0x55de106c9000:0x53000:load:0x7:r:0}}}
[00126.323] 01050.01053> {{{mmap:0x55de1071c000:0x7e000:load:0x7:rx:0x53000}}}
[00126.323] 01050.01053> {{{mmap:0x55de1079a000:0x5000:load:0x7:rw:0xd1000}}}
[00126.323] 01050.01053> {{{mmap:0x55de1079f000:0x3000:load:0x7:rw:0xd6000}}}
[00126.323] 01050.01053> dso: id=c40e3db9703e022b base=0x000055de106c9000 name=libc++.so.2
[00126.323] 01050.01053> {{{module:0x8:libc++abi.so.1:elf:7dd43029d9b84d36}}}
[00126.323] 01050.01053> {{{mmap:0x37c208751000:0x16000:load:0x8:r:0}}}
[00126.323] 01050.01053> {{{mmap:0x37c208767000:0x23000:load:0x8:rx:0x16000}}}
[00126.323] 01050.01053> {{{mmap:0x37c20878a000:0x3000:load:0x8:rw:0x39000}}}
[00126.323] 01050.01053> {{{mmap:0x37c20878d000:0x1000:load:0x8:rw:0x3c000}}}
[00126.323] 01050.01053> dso: id=7dd43029d9b84d36 base=0x000037c208751000 name=libc++abi.so.1
[00126.323] 01050.01053> {{{module:0x9:libunwind.so.1:elf:53013261665bb49a}}}
[00126.323] 01050.01053> {{{mmap:0x20c419133000:0x6000:load:0x9:r:0}}}
[00126.323] 01050.01053> {{{mmap:0x20c419139000:0x8000:load:0x9:rx:0x6000}}}
[00126.323] 01050.01053> {{{mmap:0x20c419141000:0x1000:load:0x9:rw:0xe000}}}
[00126.323] 01050.01053> {{{mmap:0x20c419142000:0x1000:load:0x9:rw:0xf000}}}
[00126.323] 01050.01053> dso: id=53013261665bb49a base=0x000020c419133000 name=libunwind.so.1
[00126.323] 01050.01053> bootsvc: Starting...
[00126.323] 01036.01043> userboot: loader-service channel peer closed
[00126.324] 01036.01043> userboot: finished!
[00126.324] 01050.01053> bootsvc: Creating bootfs service...
[00126.324] 01050.01053> bootsvc: Retrieving boot image...
[00126.324] 01050.01053> bootsvc: Decommitted BOOTDATA VMO from 0 to 0xa9e000
[00126.324] 01050.01053> bootsvc: Loading boot arguments...
[00126.324] 01050.01053> bootsvc: Creating svcfs service...
[00126.324] 01050.01053> bootsvc: Loading kernel VMOs...
[00126.324] 01050.01053> bootsvc: Creating loader service...
[00126.324] 01050.01053> bootsvc: Launching next process...
[00126.324] 01050.01118> bootsvc: bootsvc.next = bin/devcoordinator
[00126.324] 01050.01118> bootsvc: Launched bin/devcoordinator
[00126.326] 01125.01140> devcoordinator: launch /boot/bin/svchost (svchost) OK
[00126.328] 01125.01140> devcoordinator: launch /boot/bin/fshost (fshost) OK
[00126.331] 01125.01364> devcoordinator: launch /boot/bin/pwrbtn-monitor (pwrbtn-monitor) OK
[00126.331] 01125.01384> devcoordinator: launch /boot/bin/miscsvc (miscsvc) OK
[00126.332] 01125.01384> devcoordinator: launch /boot/bin/netsvc (netsvc) OK
[00126.333] 01125.01384> devcoordinator: launch /boot/bin/virtual-console (virtual-console) OK
[00126.338] 01125.01140> devcoordinator: full system required, ignoring fallback drivers until /system is loaded
[00126.338] 01125.01140> devcoordinator: launch devhost 'devhost:sys': pid=2471
[00126.338] 01125.01140> devcoordinator: launch devhost 'devhost:test': pid=2503
[00126.338] 01125.01140> devcoordinator: launch devhost 'devhost:root': pid=2553
[00126.339] 01125.01140> devcoordinator: launch devhost 'devhost:misc': pid=2637
[00126.350] 01125.01372> devcoordinator: launch /boot/bin/sh (sh:console) OK
[00126.427] 02471.02485> acpi-bus: not using IOMMU
[00126.435] 02471.02485> PMU: 7 arch events
[00126.435] 02471.02485> PMU: arch event id range: 1-7
[00126.435] 02471.02485> PMU: 102 arch events
[00126.435] 02471.02485> PMU: arch event id range: 1-241
[00126.435] 02471.02485> Intel Processor Trace configuration for this chipset:
[00126.435] 02471.02485> mtc_freq_mask: 0x249
[00126.435] 02471.02485> cyc_thresh_mask: 0x3fff
[00126.435] 02471.02485> psb_freq_mask: 0x3f
[00126.435] 02471.02485> num addr ranges: 2
[00126.435] 02471.02485> [sysmem_init 28] async_get_default_dispatcher(): 0x7c19a97fc310
[00126.435] 02471.02485> [sysmem_bind 40] sysmem_bind()
[00126.435] 02471.03279> acpi-pwrbtn: initialized
[00126.435] 01961.02014> vc: new input device /dev/class/input/000
[00126.467] 02471.03279> acpi: published device pci(0x7c18e9820750), parent=sys(0x7c1a29808010), handle=0x7c18a9810ed0
[00126.467] 01125.01140> devcoordinator: launch devhost 'devhost:pci#1:8086:5916': pid=3373
[00126.468] 01125.01140> devcoordinator: launch devhost 'devhost:pci#3:8086:9d2f': pid=3431
[00126.468] 01125.01140> devcoordinator: launch devhost 'devhost:pci#5:8086:9d60': pid=3499
[00126.470] 01125.01140> devcoordinator: launch devhost 'devhost:pci#6:8086:9d61': pid=3587
[00126.470] 02471.03279> acpi: published device serial(0x7c18e981f850), parent=acpi(0x7c1a29808210), handle=0x7c18a9812c50
[00126.472] 01125.01140> devcoordinator: launch devhost 'devhost:pci#9:8086:9d03': pid=3699
[00126.472] 02471.03279> acpi: published device rtc(0x7c18e981f5b0), parent=acpi(0x7c1a29808210), handle=0x7c18a9836290
[00126.473] 01125.01140> devcoordinator: launch devhost 'devhost:pci#14:8086:9d71': pid=3868
[00126.474] 01125.01140> devcoordinator: launch devhost 'devhost:pci#16:8086:156f': pid=3990
[00126.475] 02471.03279> acpi-ec: initialized
[00126.477] 02471.03279> acpi: failed to create NHLT VMO (res -10)
[00126.477] 02471.03279> acpi: failed to publish NHLT metadata
[00126.497] 03499.03522> initialized intel serialio i2c driver, reg=0x2229c163c000 regsize=4096
[00126.501] 03699.03757> ahci: using MSI interrupt
[00126.502] 03587.03621> initialized intel serialio i2c driver, reg=0x4a387b515000 regsize=4096
[00126.503] 03431.04296> * found USB device (0x18d1:0xa002, USB 2.0) config 1
[00126.510] 03431.04296> * found USB device (0x18d1:0xa003, USB 3.0) config 1
[00126.520] 03868.03908> [IHDA DSP 00:1f.3] Failed to fetch NHLT (res -25)
[00126.520] 03868.03908> [IHDA Controller 00:1f.3] Failed to initialize DSP device (res = -25)
[00126.593] 01845.01877> netifc: ? /dev/class/ethernet/000
[00126.593] 01845.01877> netifc: create 512 eth buffers
[00126.593] 01845.01877> macaddr: 54:b2:03:13:37:a9
[00126.593] 01845.01877> ip6addr: fe80::56b2:34d:fe13:37a9
[00126.593] 01845.01877> snmaddr: ff02::1:ff13:37a9
[00126.593] 01845.01877> netsvc: using /dev/class/ethernet/000
[00126.593] 01845.01877> netsvc: nodename='jam-tutor-plank-yelp'
[00126.593] 01845.01877> netsvc: start
[00126.602] 01961.02014> vc: new display device /dev/class/display-controller/000
[00126.642] 03373.04834> i915: MST not supported
[00127.142] 03373.04834> i915: Found DP monitor
[00127.142] 03373.04834> i915: Display 1 connected
[00127.700] 01961.02014> vc: Successfully attached to display 1
[00127.984] 03431.04296> * found USB device (0x0781:0x5571, USB 2.10) config 1
[00128.234] 03431.04296> * found USB device (0x8087:0x0a2b, USB 2.0) config 1
[00128.521] 03587.03621> intel-i2c-controller: intel_serialio_i2c_slave_transfer: -21
[00128.521] 03587.03621> i2c-hid: could not read HID descriptor: 0
[00128.521] 03587.03621> devhost[00:15.1/i2c-bus-9d61/004c] bind driver '/boot/driver/i2c-hid.so' failed: -2
[00128.521] 01125.01140> devcoordinator: rpc: bind-driver '004c' status -2
[00128.521] 03499.03522> intel-i2c-controller: intel_serialio_i2c_slave_transfer: -21
[00128.521] 03499.03522> i2c-hid: could not read HID descriptor: 0
[00128.521] 03499.03522> devhost[00:15.0/i2c-bus-9d60/0020] bind driver '/boot/driver/i2c-hid.so' failed: -2
[00128.522] 01125.01140> devcoordinator: rpc: bind-driver '0020' status -2
[00128.543] 03699.04611> sata2: dev info
[00128.543] 03699.04611> serial=AA000000000000001139
[00128.543] 03699.04611> firmware rev=R0801A0
[00128.543] 03699.04611> model id=TEAM TM8PS5128G
[00128.543] 03699.04611> major=0x3f0 ACS2 DMA 32 commands
[00128.543] 03699.04611> LBA48 250069680 sectors, sector size=512
[00128.545] 01342.01356> fshost: Binding: /boot/driver/gpt.so
[00128.545] 03699.03757> DeviceControllerBind running: /boot/driver/gpt.so
[00128.545] 01125.01140> devcoordinator: rpc: bind-device 'block'
[00128.545] 03699.03757> DeviceControllerBind finished: /boot/driver/gpt.so ZX_OK
[00128.545] 03699.03757> gpt: device_get_metadata failed (-25)
[00128.546] 01342.01356> fshost: Binding: /boot/driver/fvm.so
[00128.546] 03699.03757> DeviceControllerBind running: /boot/driver/fvm.so
[00128.546] 01125.01140> devcoordinator: rpc: bind-device 'block'
[00128.546] 03699.03757> DeviceControllerBind finished: /boot/driver/fvm.so ZX_OK
[00128.547] 01342.01356> fshost: (/dev/class/block/002) failed: ZX_ERR_NOT_SUPPORTED
[00128.547] 01342.01356> fshost: (/dev/class/block/003) failed: ZX_ERR_NOT_SUPPORTED
[00128.549] 01342.01356> fshost: BlockDevice::MountFilesystem(blobfs)
[00128.549] 01342.01356> devcoordinator: launch /boot/bin/blobfs (blobfs:/blob) OK
[00128.694] 01342.01356> fshost: starting 'bin/pkgsvr' 'e847ff05c85a0c72599442f8d1b1c6ce460f2910c79a2503ee1f87c39efec7a9'...
[00128.701] 01342.01356> devcoordinator: launch bin/pkgsvr (pkgfs) OK
[00128.712] 05281.05491> pkgsvr: system: will be served from e847ff05c85a0c72599442f8d1b1c6ce460f2910c79a2503ee1f87c39efec7a9
[00128.712] 05281.05491> pkgsvr: pkgfs serving index /data/pkgfs_index from blobfs /blob
[00128.712] 01342.01356> fshost: unsealing zxcrypt
[00128.713] 03699.03757> DeviceControllerBind running: /boot/driver/zxcrypt.so
[00128.713] 01125.01140> devcoordinator: rpc: bind-device 'block'
[00128.713] 03699.03757> DeviceControllerBind finished: /boot/driver/zxcrypt.so ZX_OK
[00128.715] 01342.01356> fshost: mounting minfs
[00128.715] 01342.01356> fshost: BlockDevice::MountFilesystem(minfs)
[00128.715] 01342.01356> devcoordinator: launch /boot/bin/minfs (minfs:/data) OK
[00128.717] 05661.05675> minfs: filesystem in clean state.
[00128.739] 01125.02022> devcoordinator: launch /system/bin/appmgr (appmgr) OK
[00128.739] 01125.02022> autorun: starting '/boot/bin/sh' '/boot/infra/runcmds'...
[00128.739] 01125.05535> devcoordinator: adding system driver 'bt_hci_intel' '/system/driver/bt-hci-intel.so'
[00128.740] 01125.02022> devcoordinator: launch /boot/bin/sh (autorun:system) OK
[00128.741] 01125.05535> devcoordinator: adding system driver 'iwlwifi_pci' '/system/driver/iwlwifi.so'
[00128.747] 01125.05535> devcoordinator: adding system driver 'gpu' '/system/driver/libmsd_intel.so'
[00128.752] 01125.05535> devcoordinator: adding system driver 'virtual_audio' '/system/driver/virtual_audio_driver.so'
[00128.756] 01125.05535> devcoordinator: adding system driver 'bt_hci_fake' '/system/driver/bt-hci-fake.so'
[00128.766] 01125.05535> devcoordinator: adding system driver 'mt8167s_gpu' '/system/driver/libmsd_img_rgx_mt8167.so'
[00128.767] 01125.05535> devcoordinator: adding system driver 'bt_hci_passthrough' '/system/driver/bt-hci-passthrough.so'
[00128.771] 01125.05535> devcoordinator: adding system driver 'magma_pdev_gpu' '/system/driver/libmsd_arm.so'
[00128.791] 01125.05535> devcoordinator: adding system driver 'ralink' '/system/driver/ralink.so'
[00128.794] 01125.05535> devcoordinator: adding system driver 'wlan' '/system/driver/wlanif.so'
[00128.799] 01125.05535> devcoordinator: adding system driver 'usb_video' '/system/driver/usb_video.so'
[00128.804] 01125.05535> devcoordinator: adding system driver 'brcmfmac' '/system/driver/brcmfmac.so'
[00128.808] 01125.05535> devcoordinator: adding system driver 'bt_hci_atheros' '/system/driver/bt-hci-atheros.so'
[00128.810] 01125.05535> devcoordinator: adding system driver 'ath10k_pci' '/system/driver/ath10k.so'
[00128.811] 01125.05535> devcoordinator: adding system driver 'bt_hog' '/system/driver/bt-hog.so'
[00128.814] 01125.05535> devcoordinator: adding system driver 'qmi_fake' '/system/driver/qmi-fake.so'
[00128.836] 01125.05535> devcoordinator: adding system driver 'wlan' '/system/driver/wlan.so'
[00128.839] 01125.05535> devcoordinator: adding system driver 'rtl88xx' '/system/driver/rtl88xx.so'
[00128.843] 01125.05535> devcoordinator: adding system driver 'virtual_camera' '/system/driver/virtual_camera_driver.so'
[00128.865] 01125.05535> devcoordinator: adding system driver 'bt_host' '/system/driver/bt-host.so'
[00128.871] 01125.05535> devcoordinator: adding system driver 'wlan' '/system/driver/wlanphy.so'
[00128.875] 01125.05535> devcoordinator: adding system driver 'qmi_usb' '/system/driver/qmi-transport.so'
[00128.876] 01125.01140> devcoordinator: driver 'qmi_usb' added
[00128.876] 01125.01140> devcoordinator: driver 'wlan' added
[00128.876] 01125.01140> devcoordinator: driver 'bt_host' added
[00128.876] 01125.01140> devcoordinator: driver 'rtl88xx' added
[00128.876] 01125.01140> devcoordinator: driver 'wlan' added
[00128.876] 01125.01140> devcoordinator: driver 'qmi_fake' added
[00128.876] 01125.01140> devcoordinator: driver 'bt_hog' added
[00128.876] 01125.01140> devcoordinator: driver 'ath10k_pci' added
[00128.876] 01125.01140> devcoordinator: driver 'bt_hci_atheros' added
[00128.876] 01125.01140> devcoordinator: driver 'brcmfmac' added
[00128.876] 01125.01140> devcoordinator: driver 'usb_video' added
[00128.876] 01125.01140> devcoordinator: driver 'wlan' added
[00128.876] 01125.01140> devcoordinator: driver 'ralink' added
[00128.876] 01125.01140> devcoordinator: driver 'magma_pdev_gpu' added
[00128.876] 01125.01140> devcoordinator: driver 'mt8167s_gpu' added
[00128.876] 01125.01140> devcoordinator: driver 'bt_hci_fake' added
[00128.876] 01125.01140> devcoordinator: driver 'gpu' added
[00128.876] 01125.01140> devcoordinator: driver 'iwlwifi_pci' added
[00128.876] 01125.01140> devcoordinator: driver 'bt_hci_intel' added
[00128.876] 01125.01140> devcoordinator: driver 'bt_hci_passthrough' added
[00128.876] 01125.01140> devcoordinator: fallback driver 'usb_composite' is available
[00128.876] 01125.01140> devcoordinator: driver 'usb_composite' added
[00128.876] 01125.01140> devcoordinator: fallback driver 'intel_disp' is available
[00128.876] 01125.01140> devcoordinator: driver 'intel_disp' added
[00128.878] 03431.03456> UMS: parent: 'ifc-000'
[00128.878] 03431.03456> UMS:Max lun is: 0
[00128.879] 03431.03456> devhost[00:14.0/xhci/usb-bus/002/002/ifc-001] bind driver '/boot/driver/bt-transport-usb.so' failed: -2
[00128.879] 01125.01140> devcoordinator: rpc: bind-driver 'ifc-001' status -2
[00128.881] 03431.06645> UMS: block size is: 0x00000200
[00128.881] 03431.06645> UMS: total blocks is: 15630336
[00128.881] 03431.06645> UMS: total size is: 8002732032
[00128.881] 03431.06645> UMS: read-only: 0 removable: 1
[00128.918] 03431.06862> btintel: firmware already loaded
[00128.918] 03431.06871> hci_read_thread: failed to read from ACL channel ZX_ERR_PEER_CLOSED
[00128.918] 03431.06871> hci_read_thread: failed to read from command channel ZX_ERR_PEER_CLOSED
[00128.918] 03431.06871> bt-transport-usb: all channels closed - exiting
[00128.919] 03431.07248> [INFO:command_channel.cc(148)] hci: initialized
[00128.919] 01342.01356> fshost: Binding: /boot/driver/mbr.so
[00128.919] 03431.03456> DeviceControllerBind running: /boot/driver/mbr.so
[00128.919] 01125.01140> devcoordinator: rpc: bind-device 'block'
[00128.919] 03431.03456> DeviceControllerBind finished: /boot/driver/mbr.so ZX_OK
[00128.922] 01342.01356> fshost: (/dev/class/block/008) failed: ZX_ERR_NOT_FOUND
[00128.923] 01342.01356> fshost: Binding: /boot/driver/mbr.so
[00128.923] 03431.03456> DeviceControllerBind running: /boot/driver/mbr.so
[00128.923] 01125.01140> devcoordinator: rpc: bind-device 'block'
[00128.923] 03431.03456> DeviceControllerBind finished: /boot/driver/mbr.so ZX_OK
[00128.937] 07539.07557> [00128.937896][223028319][0][netstack] INFO: netstack.go(679): NIC lo added [sniff = false]
[00128.938] 07539.07843> [00128.938494][223028319][0][netstack] WARNING: main.go(148): OnInterfacesChanged failed: ErrBadHandle: zx.Channel.Write
[00128.939] 03431.07248> [INFO:acl_data_channel.cc(90)] hci: initialized
[00129.163] 11248.11265> [INFO:main.cc(35)] Trace Manager starting with config: /pkg/data/tracing.config
[00129.197] 07539.07885> [00129.197145][223028319][0][netstack] WARNING: netstack.go(551): getNodeName: device settings error: key not set
[00129.197] 03431.07248> [WARN:bredr_discovery_manager.cc(479)] gap-bredr: write inquiry scan activity failed: [status: invalid HCI command parameters (HCI 0x12)]
[00129.204] 07539.07885> [00129.204387][223028319][0][netstack] WARNING: netstack.go(551): getNodeName: device settings error: key not set
[00129.224] 07539.07849> [00129.224800][223028319][0][netstack] INFO: netstack.go(679): NIC ethp001f6 added [sniff = false]
[00129.224] 07539.07849> [00129.224869][223028319][0][netstack] INFO: netstack.go(705): NIC ethp001f6: link-local IPv6: fe80::56b2:3ff:fe13:37a9
[00129.225] 07539.07853> [00129.224993][223028319][0][netstack] WARNING: netstack.go(551): getNodeName: device settings error: key not set
[00129.225] 07539.08345> [00129.225146][223028319][0][netstack] INFO: netstack.go(445): NIC ethp001f6: stopped
[00129.248] 12212.12228> wlanstack2 [I]: Starting
[00129.306] 12894.12906> [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
[00129.306] 12894.12906> kfill_days=2, start_event_aggregator_worker=1.
[00129.331] 05799.05813> [WARNING:garnet/bin/appmgr/service_provider_dir_impl.cc(127)] Component fuchsia-pkg://fuchsia.com/vulkan_is_supported#meta/vulkan_is_supported.cmx is not allowed to connect to fuchsia.tracelink.Registry because this service
[00129.331] 05799.05813> is not present in the component's sandbox.
[00129.331] 05799.05813> Refer to
https://fuchsia.googlesource.com/fuchsia/+/master/docs/the-book/sandboxing.md#services for more information.
[00129.337] 09656.09700> [INFO:system_metrics_main.cc(23)] Cobalt SystemMetricsDaemon: System metrics daemon created.
[00129.339] 10708.10722> [INFO:benchmarks.cc(24)] Graphics performance tests disabled
[00129.355] 10708.10722> [INFO:benchmarking.cc(124)] Running "/bin/run fuchsia-pkg://fuchsia.com/topaz_input_latency_benchmarks#meta/run_button_flutter_benchmark.cmx --out_file /tmp/infra-test-output/benchmarking_temp_file_0 --benchmark_label fuchsi
[00129.355] 10708.10722> a.input_latency.button_flutter"
[00129.369] 13883.13898> Starting!
[00129.373] 13883.13898> == fuchsia.input_latency.button_flutter: Killing processes...
[00129.375] 14155.14168> no tasks found
[00129.377] 14236.14248> no tasks found
[00129.379] 14312.14324> no tasks found
[00129.380] 14388.14400> no tasks found
[00129.381] 14464.14476> no tasks found
[00129.383] 14540.14552> no tasks found
[00129.383] 13883.13898> == fuchsia.input_latency.button_flutter: Starting app...
[00129.437] 14885.14897> [WARNING:src/lib/cobalt/cpp/cobalt_logger_impl.cc(39)] Disconnecting connection to cobalt with events still pending... Events will be lost.
[00129.455] 15374.15386> [INFO:input_interpreter.cc(421)] Can't process HID report descriptor for 000; All parsing attempts failed.
[00129.468] 14885.14897> [INFO:session_user_provider_impl.cc(116)] AccountListener registered.
[00129.469] 14885.14897> [INFO:presentation_container.cc(133)] Setting shadow technique to 0
[00129.579] 16003.16015> [INFO:display_watcher.cc(40)] Scenic: Acquired display controller /dev/class/display-controller/000.(000)
[00129.764] 16154.16782> [INFO:component.cc(247)] Using snapshot without framework for fuchsia-pkg://fuchsia.com/button_flutter#meta/button_flutter.cmx
[00129.838] 16003.16015> [INFO:input_system.cc(203)] Scenic input system initialized.
[00129.838] 15374.15386> [WARNING:garnet/bin/ui/root_presenter/displays/display_configuration.cc(79)] RootPresenter: unrecognized display.
[00129.838] 16003.16015> [INFO:input_system.cc(556)] Scenic: Parallel dispatch is turned OFF
[00129.838] 16003.16015> [INFO:default_frame_scheduler.cc(237)] ScheduleUpdateForSession session_id: 1 presentation_time: 0
[00129.838] 16003.16015> [INFO:default_frame_scheduler.cc(115)] RequestFrame
[00129.838] 16003.16015> [INFO:default_frame_scheduler.cc(237)] ScheduleUpdateForSession session_id: 1 presentation_time: 0
[00129.838] 16003.16015> [INFO:default_frame_scheduler.cc(115)] RequestFrame
[00129.838] 16003.16015> [INFO:default_frame_scheduler.cc(237)] ScheduleUpdateForSession session_id: 1 presentation_time: 0
[00129.838] 16003.16015> [INFO:default_frame_scheduler.cc(115)] RequestFrame
[00129.838] 16003.16015> [INFO:default_frame_scheduler.cc(237)] ScheduleUpdateForSession session_id: 1 presentation_time: 0
[00129.838] 16003.16015> [INFO:default_frame_scheduler.cc(115)] RequestFrame
[00129.838] 16003.16015> [INFO:default_frame_scheduler.cc(237)] ScheduleUpdateForSession session_id: 2 presentation_time: 0
[00129.838] 16003.16015> [INFO:default_frame_scheduler.cc(115)] RequestFrame
[00129.855] 16003.16015> [INFO:default_frame_scheduler.cc(148)] MaybeRenderFrame presentation_time=129863007793 wakeup_time=129855007793 frame_number=0
[00129.855] 16003.16015> [INFO:default_frame_scheduler.cc(250)] ApplyScheduledSessionUpdates presentation_time=129863007793 frame_number=0
[00129.857] 05799.05813> [ERROR:garnet/bin/appmgr/service_provider_dir_impl.cc(101)] Cannot serve service fuchsia.modular.Clipboard for component fuchsia-pkg://fuchsia.com/button_flutter#meta/button_flutter.cmx: ZX_ERR_NOT_FOUND
[00129.864] 16003.16015> [INFO:default_frame_scheduler.cc(189)] Calling RenderFrame presentation_time=129863007793 frame_number=0
[00129.872] 16154.16782> [WARNING:third_party/flutter/shell/common/persistent_cache.cc(69)] Could not acquire the persistent cache directory. Caching of GPU resources on disk is disabled.
[00129.877] 16154.16782> [ERROR:topaz/runtime/flutter_runner/platform_view.cc(70)] Interface error on: Clipboard
[00129.885] 16003.16015> [INFO:default_frame_scheduler.cc(281)] DefaultFrameScheduler::OnFramePresented frame_number=0
[00129.969] 16154.16848> [INFO:paragraph.cc(294)] Could not find font collection for families "".
[00130.054] 16003.16015> [INFO:default_frame_scheduler.cc(237)] ScheduleUpdateForSession session_id: 2 presentation_time: 0
[00130.054] 16003.16015> [INFO:default_frame_scheduler.cc(115)] RequestFrame
[00130.060] 16003.16015> [INFO:default_frame_scheduler.cc(148)] MaybeRenderFrame presentation_time=130068920013 wakeup_time=130060920013 frame_number=1
[00130.060] 16003.16015> [INFO:default_frame_scheduler.cc(250)] ApplyScheduledSessionUpdates presentation_time=130068920013 frame_number=1
[00130.061] 16003.16015> [INFO:default_frame_scheduler.cc(189)] Calling RenderFrame presentation_time=130068920013 frame_number=1
[00130.068] 16003.16015> [INFO:default_frame_scheduler.cc(281)] DefaultFrameScheduler::OnFramePresented frame_number=1
[00130.271] 07539.07849> [00130.271435][223028319][0][netstack] INFO: netstack.go(466): NIC ethp001f6: starting
[00130.271] 08994.09006> Starting mDNS on interface ethp001f6 fe80::56b2:3ff:fe13:37a9 using port 5356
[00130.271] 07539.07853> [00130.271771][223028319][0][netstack] INFO: socket_conv.go(523): unimplemented setsockopt: SOL_IPV6 name=19 optVal=00
[00130.271] 08994.09006> [WARNING:src/connectivity/network/mdns/service/mdns_interface_transceiver_v6.cc(29)] NET-291 IPV6_MULTICAST_LOOP not supported (ENOPROTOOPT), continuing anyway
[00130.271] 08994.09006> [WARNING:src/connectivity/network/mdns/service/mdns_interface_transceiver_v6.cc(50)] NET-2180 IPV6_JOIN_GROUP returned ENODEV, mDNS will not communicate via IPV6
[00130.271] 08994.09006> Starting mDNS on interface ethp001f6 ff02::1:ff13:37a9 using port 5356
[00130.272] 07539.07849> [00130.272008][223028319][0][netstack] INFO: socket_conv.go(523): unimplemented setsockopt: SOL_IPV6 name=19 optVal=00
[00130.272] 08994.09006> [WARNING:src/connectivity/network/mdns/service/mdns_interface_transceiver_v6.cc(29)] NET-291 IPV6_MULTICAST_LOOP not supported (ENOPROTOOPT), continuing anyway
[00130.272] 08994.09006> [WARNING:src/connectivity/network/mdns/service/mdns_interface_transceiver_v6.cc(50)] NET-2180 IPV6_JOIN_GROUP returned ENODEV, mDNS will not communicate via IPV6
[00132.419] 13883.13898> == fuchsia.input_latency.button_flutter: Tracing...
[00132.419] 13883.13898> /tmp/trace-2019-05-24T01:25:18.json
[00132.429] 11248.11265> [INFO:trace_manager.cc(96)] Starting trace with 12 MB buffers, buffering mode=oneshot
[00132.430] 03373.06538> Session for process 3373: engine is already started. Is there perchance two providers in this app?
[00132.430] 16003.16408> Session for process 16003: engine is already started. Is there perchance two providers in this app?
[00132.430] 11248.11265> [ERROR:garnet/bin/trace_manager/tracee.cc(361)] #15 {3373:devhost:pci#1:8086:5916}: header corrupt, bad magic: 0x0
[00132.430] 11248.11265> [ERROR:garnet/bin/trace_manager/trace_session.cc(174)] Problem reading provider output, skipping
[00132.430] 16154.16166> Session: error starting engine, status=-20(ZX_ERR_BAD_STATE)
[00132.430] 11248.11265> [ERROR:garnet/bin/trace_manager/tracee.cc(361)] #23 {16003:scenic.cmx}: header corrupt, bad magic: 0x0
[00132.431] 11248.11265> [ERROR:garnet/bin/trace_manager/trace_session.cc(174)] Problem reading provider output, skipping
[00132.431] 11248.11265> [ERROR:garnet/bin/trace_manager/tracee.cc(361)] #25 {16154:flutter_runner}: header corrupt, bad magic: 0x0
[00132.431] 11248.11265> [ERROR:garnet/bin/trace_manager/trace_session.cc(174)] Problem reading provider output, skipping
[00132.431] 18897.18913> Starting trace; will stop in 80 seconds...
[00134.319] 07539.19197> [00134.319366][223028319][0][netstack] INFO: netstack.go(381): NIC ethp001f6: DHCP acquired IP 192.168.42.112 for 240h0m0s
[00134.319] 07539.19197> [00134.319404][223028319][0][netstack] INFO: netstack.go(382): NIC ethp001f6: Adding DNS servers: [8.8.8.8]
[00134.319] 07539.19197> [00134.319425][223028319][0][netstack] INFO: netstack.go(395): adding routes [{Destination:0.0.0.0 Mask:0.0.0.0 Gateway:192.168.42.1 NIC:2} {Destination::: Mask::: Gateway: NIC:2} {Destination:192.168.42.0 Mask:255.255.255.0
[00134.319] 07539.19197> Gateway: NIC:2}] with metric=<not-set> dynamic=true
[00134.319] 08994.09006> Starting mDNS on interface ethp001f6 192.168.42.112 using port 5356
[00134.319] 08994.09006> [WARNING:src/connectivity/network/mdns/service/mdns_interface_transceiver_v4.cc(68)] NET-2177 IP_TTL not supported (ENOPROTOOPT), continuing anyway. May cause spurious IP traffic
[00134.319] 08994.09006> Starting mDNS on interface ethp001f6 fe80::56b2:3ff:fe13:37a9 using port 5356
[00134.319] 07539.19197> [00134.319915][223028319][0][netstack] INFO: socket_conv.go(523): unimplemented setsockopt: SOL_IPV6 name=19 optVal=00
[00134.319] 08994.09006> [WARNING:src/connectivity/network/mdns/service/mdns_interface_transceiver_v6.cc(29)] NET-291 IPV6_MULTICAST_LOOP not supported (ENOPROTOOPT), continuing anyway
[00134.319] 08994.09006> [WARNING:src/connectivity/network/mdns/service/mdns_interface_transceiver_v6.cc(50)] NET-2180 IPV6_JOIN_GROUP returned ENODEV, mDNS will not communicate via IPV6
[00134.320] 08994.09006> Starting mDNS on interface ethp001f6 ff02::1:ff13:37a9 using port 5356
[00134.320] 07539.19197> [00134.320137][223028319][0][netstack] INFO: socket_conv.go(523): unimplemented setsockopt: SOL_IPV6 name=19 optVal=00
[00134.320] 08994.09006> [WARNING:src/connectivity/network/mdns/service/mdns_interface_transceiver_v6.cc(29)] NET-291 IPV6_MULTICAST_LOOP not supported (ENOPROTOOPT), continuing anyway
[00134.320] 08994.09006> [WARNING:src/connectivity/network/mdns/service/mdns_interface_transceiver_v6.cc(50)] NET-2180 IPV6_JOIN_GROUP returned ENODEV, mDNS will not communicate via IPV6
[00134.320] 08994.09006> mDNS: Verifying uniqueness of host name jam-tutor-plank-yelp.local.
[00135.129] 08994.09006> mDNS: Using unique host name jam-tutor-plank-yelp.local.
[00136.458] 16003.16015> [INFO:default_frame_scheduler.cc(237)] ScheduleUpdateForSession session_id: 2 presentation_time: 0
[00136.459] 16003.16015> [INFO:default_frame_scheduler.cc(115)] RequestFrame
[00136.460] 16003.16015> [INFO:default_frame_scheduler.cc(148)] MaybeRenderFrame presentation_time=136468931385 wakeup_time=136460931385 frame_number=2
[00136.460] 16003.16015> [INFO:default_frame_scheduler.cc(250)] ApplyScheduledSessionUpdates presentation_time=136468931385 frame_number=2
[00136.461] 16003.16015> [INFO:default_frame_scheduler.cc(189)] Calling RenderFrame presentation_time=136468931385 frame_number=2
[00136.469] 16003.16015> [INFO:default_frame_scheduler.cc(281)] DefaultFrameScheduler::OnFramePresented frame_number=2
[00136.502] 16003.16015> [INFO:default_frame_scheduler.cc(281)] DefaultFrameScheduler::OnFramePresented frame_number=3
[00177.339] 01845.01877> netsvc: handling tftp request failed (file might not exist)
[00177.339] 01845.01877> netsvc: metrics: {"inorderblks": 0,"oooblks": 0,"ack": 0,"nack": 0,"timeouts": 0,"sas": 0,"inorderbytes": 0}
[00212.286] 15374.15386> [INFO:input_device_impl.cc(17)] Device disconnected
[00212.431] 18897.18913> Stopping trace...
[00212.431] 11248.11265> [INFO:trace_manager.cc(135)] Stopping trace
[00212.447] 11248.11265> [WARNING:garnet/bin/trace_manager/tracee.cc(369)] #5 {3373:devhost:pci#1:8086:5916}: 180805 records were dropped
[00212.447] 18897.18913> [WARNING:garnet/lib/trace_converters/chromium_exporter.cc(473)] #5 buffer overflowed, records were likely dropped
[00213.954] 11248.11265> [INFO:tracee.cc(435)] #5 {3373:devhost:pci#1:8086:5916} trace stats
[00213.954] 11248.11265> [INFO:tracee.cc(436)] Wrapped count: 0
[00213.954] 11248.11265> [INFO:tracee.cc(437)] # records dropped: 180805
[00213.954] 11248.11265> [INFO:tracee.cc(438)] Durable buffer: 0x0, size 0x0
[00213.954] 11248.11265> [INFO:tracee.cc(441)] Non-durable buffer: 0xbfff80,0x0, size 0xbfff80
[00214.041] 11248.11265> [INFO:tracee.cc(435)] #21 {15374:root_presenter.cmx} trace stats
[00214.041] 11248.11265> [INFO:tracee.cc(436)] Wrapped count: 0
[00214.041] 11248.11265> [INFO:tracee.cc(437)] # records dropped: 0
[00214.041] 11248.11265> [INFO:tracee.cc(438)] Durable buffer: 0x0, size 0x0
[00214.041] 11248.11265> [INFO:tracee.cc(441)] Non-durable buffer: 0xd048,0x0, size 0xbfff80
[00215.531] 11248.11265> [INFO:tracee.cc(435)] #22 {16003:scenic.cmx} trace stats
[00215.531] 11248.11265> [INFO:tracee.cc(436)] Wrapped count: 0
[00215.531] 11248.11265> [INFO:tracee.cc(437)] # records dropped: 0
[00215.531] 11248.11265> [INFO:tracee.cc(438)] Durable buffer: 0x0, size 0x0
[00215.531] 11248.11265> [INFO:tracee.cc(441)] Non-durable buffer: 0xba07f8,0x0, size 0xbfff80
[00216.011] 11248.11265> [INFO:tracee.cc(435)] #26 {16154:io.flutter.product_runner.jit} trace stats
[00216.011] 11248.11265> [INFO:tracee.cc(436)] Wrapped count: 0
[00216.011] 11248.11265> [INFO:tracee.cc(437)] # records dropped: 0
[00216.011] 11248.11265> [INFO:tracee.cc(438)] Durable buffer: 0x0, size 0x0
[00216.011] 11248.11265> [INFO:tracee.cc(441)] Non-durable buffer: 0x3a02a8,0x0, size 0xbfff80
[00216.026] 11248.11265> [INFO:trace_manager.cc(138)] Stopped trace
[00216.046] 18897.18913> Trace file written to /tmp/trace-2019-05-24T01:25:18.json
[00216.047] 13883.13898> == fuchsia.input_latency.button_flutter: Processing trace...
[00223.201] 140503.140711> Computed 146 total input latency values
[00223.201] 140503.140711> Total input latency mean: 27.65ms
[00223.201] 140503.140711> Total input latency median: 27.73ms
[00223.201] 140503.140711> Total input latency max: 34.15ms
[00223.218] 10708.10722> [INFO:benchmarking.cc(173)] writing summary.json to /tmp/infra-test-output/summary.json
DEBUG: reading "summary.json"
DEBUG: copying test output
DEBUG: tarring test output...
[00237.341] 01845.01877> netsvc: tftp read of file /tmp/infra-test-output/summary.json completed
[00237.341] 01845.01877> netsvc: metrics: {"inorderblks": 0,"oooblks": 0,"ack": 0,"nack": 0,"timeouts": 0,"sas": 0,"inorderbytes": 0}
[00237.342] 01845.01877> netsvc: closing still-open '/tmp/infra-test-output/summary.json', replacing with '/tmp/infra-test-output/benchmarking_temp_file_0'
[00237.342] 01845.01877> netsvc: tftp read of file /tmp/infra-test-output/benchmarking_temp_file_0 completed
[00237.342] 01845.01877> netsvc: metrics: {"inorderblks": 0,"oooblks": 0,"ack": 0,"nack": 0,"timeouts": 0,"sas": 0,"inorderbytes": 0}
[00237.342] 01845.01877> netsvc: closing still-open '/tmp/infra-test-output/benchmarking_temp_file_0', replacing with '/tmp/infra-test-output/benchmarking_temp_file_0.catapult_json'
[00237.343] 01845.01877> netsvc: tftp read of file /tmp/infra-test-output/benchmarking_temp_file_0.catapult_json completed