DEBUG: config flag: /etc/botanist/config.json
DEBUG: waiting for "summary.json"
2019/04/22 22:48:57 attempting to send <<netboot>>cmdline...
2019/04/22 22:48:57 done
2019/04/22 22:48:57 attempting to send <<image>>sparse.fvm...
[0.000] 00000.00000> zbi: @ 0xffffff80012f2000 (17482848 bytes)
[0.000] 00000.00000> UART: FIFO depth 16
[0.000] 00000.00000> PMM: boot reserve add [0x100000, 0x2c5fff]
[0.000] 00000.00000> PMM: boot reserve add [0x12f2000, 0x239efff]
[0.000] 00000.00000> PMM: arena too small to be useful (size 4096)
[0.000] 00000.00000> PMM: pmm_add_arena failed to initialize arena
[0.000] 00000.00000> MEM: Failed to add pmm range at 0x7ffff000 size 0x1000
[0.000] 00000.00000> PMM: boot reserve marking WIRED [0x100000, 0x2c5fff]
[0.000] 00000.00000> PMM: boot reserve marking WIRED [0x12f2000, 0x239efff]
[0.000] 00000.00000> welcome to Zircon
[0.000] 00000.00000> KASLR: .text section at 0xffffffff00100000
[0.000] 00000.00000> INIT: cpu 0, calling hook 0xffffffff001aa428 (global_prng_seed) at level 0x30000, flags 0x1
[0.000] 00000.00000> initializing vm pre-heap
[0.000] 00000.00000> VM: marking boot alloc used range [0x239f000, 0x239f100)
[0.000] 00000.00000> INIT: cpu 0, calling hook 0xffffffff00147abc (elf_build_id) at level 0x4fffe, flags 0x1
[0.000] 00000.00000> INIT: cpu 0, calling hook 0xffffffff00147c48 (version) at level 0x4ffff, flags 0x1
[0.000] 00000.00000> version:
[0.000] 00000.00000> arch: x86
[0.000] 00000.00000> platform: pc
[0.000] 00000.00000> target: pc
[0.000] 00000.00000> project: x64
[0.000] 00000.00000> buildid: git-13ee3dc5e4c46bf127977ad28645c47442ec517d
[0.000] 00000.00000> ELF build ID: 5f3e39bd4ed89d3b8122947842f1eac846a04683
[0.000] 00000.00000> initializing heap
[0.000] 00000.00000> INIT: cpu 0, calling hook 0xffffffff00102e1c (x86_resource_init) at level 0x50000, flags 0x1
[0.000] 00000.00000> INIT: cpu 0, calling hook 0xffffffff001a9630 (console) at level 0x50000, flags 0x1
[0.000] 00000.00000> initializing vm
[0.000] 00000.00000> VM: reserving kernel region [0xffffffff00100000, 0xffffffff001ee000) flags 0x28 name 'kernel_code'
[0.000] 00000.00000> VM: reserving kernel region [0xffffffff001ee000, 0xffffffff00232000) flags 0x8 name 'kernel_rodata'
[0.000] 00000.00000> VM: reserving kernel region [0xffffffff00232000, 0xffffffff00242000) flags 0x18 name 'kernel_data'
[0.000] 00000.00000> VM: reserving kernel region [0xffffffff00242000, 0xffffffff002c6000) flags 0x18 name 'kernel_bss'
[0.000] 00000.00000> INIT: cpu 0, calling hook 0xffffffff00103ae0 (display_memtype) at level 0x60001, flags 0x1
[0.000] 00000.00000> INIT: cpu 0, calling hook 0xffffffff00138fa0 (acpi_tables) at level 0x60001, flags 0x1
[0.000] 00000.00000> INIT: cpu 0, calling hook 0xffffffff00101c40 (hpet) at level 0x60002, flags 0x1
[0.000] 00000.00000> INIT: cpu 0, calling hook 0xffffffff00102000 (apic) at level 0x60002, flags 0x1
[0.000] 00000.00000> x2APIC enabled
[0.000] 00000.00000> INIT: cpu 0, calling hook 0xffffffff001061b4 (timer) at level 0x60003, flags 0x1
[0.000] 00000.00000> HPET frequency: 23999 ticks/ms
[0.000] 00000.00000> TSC frequency: 2712000 ticks/ms
[20.350] 00000.00000> timer features: constant_tsc 1 invariant_tsc 1 tsc_deadline 1
[20.350] 00000.00000> Using TSC as wallclock
[20.350] 00000.00000> initializing kernel
[20.350] 00000.00000> initializing mp
[20.350] 00000.00000> initializing timers
[20.350] 00000.00000> INIT: cpu 0, calling hook 0xffffffff0013c578 (debuglog) at level 0x7ffff, flags 0x1
[20.350] 00000.00000> INIT: cpu 0, calling hook 0xffffffff00195518 (thread_set_priority_experiment) at level 0x7ffff, flags 0x1
[20.350] 00000.00000> thread set priority experiment is : ENABLED
[20.350] 00000.00000> INIT: cpu 0, calling hook 0xffffffff001aa67c (global_prng_thread_safe) at level 0x7ffff, flags 0x1
[20.350] 00000.00000> creating bootstrap completion thread
[20.693] 00000.00000> top of bootstrap2()
[20.693] 00000.00000> INIT: cpu 0, calling hook 0xffffffff0013151c (dpc) at level 0x80000, flags 0x1
[20.706] 00000.00000> INIT: cpu 0, calling hook 0xffffffff00152978 (libobject) at level 0x80000, flags 0x1
[20.706] 00000.00000> OOM: started thread
[20.719] 00000.00000> Processor Model Info: type 0 family 0x6 model 0xe stepping 0x9
[20.719] 00000.00000> display_family 0x6 display_model 0x8e
[20.719] 00000.00000> Vendor: Intel
[20.719] 00000.00000> Microarch: Kaby Lake
[20.719] 00000.00000> F/M/S: 6/8e/9
[20.719] 00000.00000> Brand: Intel(R) Core(TM) i5-7300U CPU @ 2.60GHz
[20.719] 00000.00000> Features: fpu sse sse2 sse3 ssse3 sse4.1 sse4.2 mmx avx avx2 fxsr pcid xsave mon aesni clflush
[20.719] 00000.00000> clflushopt fsgsbase tsc_adj smep smap erms rdrand rdseed syscall nx huge rdtscp
[20.719] 00000.00000> invar_tsc tsc_deadline x2apic vmx pt hwp
[20.719] 00000.00000> initializing platform
[20.719] 00000.00000> INIT: cpu 0, calling hook 0xffffffff001101f4 (x86_perfmon) at level 0x90000, flags 0x1
[20.719] 00000.00000> PMU: version 4
[20.719] 00000.00000> UART: started IRQ driven RX
[20.719] 00000.00000> UART: started IRQ driven TX
[20.719] 00000.00000> cpu topology:
[20.719] 00000.00000> 0: apic id 0x0 package 0 node 0 core 0 smt 0 BSP
[20.719] 00000.00000> 1: apic id 0x2 package 0 node 0 core 1 smt 0
[20.719] 00000.00000> 2: apic id 0x1 package 0 node 0 core 0 smt 1
[20.719] 00000.00000> 3: apic id 0x3 package 0 node 0 core 1 smt 1
[20.719] 00000.00000> Found 4 cpus
[20.719] 00000.00000> booting apic ids: 0x2 0x1 0x3
[20.735] 00000.00000> entering scheduler on cpu 2
[20.736] 00000.00000> entering scheduler on cpu 3
[20.736] 00000.00000> entering scheduler on cpu 1
[20.739] 00000.00000> smbios: manufacturer="Intel Corporation" product="NUC7i5DNKE"
[20.739] 00000.00000> initializing target
[20.739] 00000.00000> INIT: cpu 1, calling hook 0xffffffff001053a0 (x86_pcie_init) at level 0xa0000, flags 0x1
[20.739] 00000.00000> moving to last init level
[20.739] 00000.00000> INIT: cpu 1, calling hook 0xffffffff00144140 (ktrace) at level 0xc0000, flags 0x1
[20.742] 00000.00000> ktrace: buffer at 0xffffff94bba1e000 (33554432 bytes)
[20.742] 00000.00000> INIT: cpu 1, calling hook 0xffffffff00147ab4 (userboot) at level 0xc0000, flags 0x1
[20.742] 00000.00000> userboot: ramdisk 0x10ad000 @ 0xffffff80012f2000
[20.743] 00000.00000> userboot: userboot rodata 0 @ [0xf07b7dd2000,0xf07b7dd5000)
[20.743] 00000.00000> userboot: userboot code 0x3000 @ [0xf07b7dd5000,0xf07b7de0000)
[20.743] 00000.00000> userboot: vdso/full rodata 0 @ [0xf07b7de0000,0xf07b7de7000)
[20.743] 00000.00000> userboot: vdso/full code 0x7000 @ [0xf07b7de7000,0xf07b7de8000)
[20.743] 00000.00000> userboot: entry point @ 0xf07b7dd5c10
[20.743] 00000.00000> INIT: cpu 1, calling hook 0xffffffff001aa030 (kernel_shell) at level 0xc0000, flags 0x1
[20.743] 01036.01043> userboot: option "netsvc.disable=true"
[20.743] 01036.01043> userboot: option "zircon.system.disable-automount=true"
[20.743] 01036.01043> userboot: option "zircon.autorun.boot=/boot/infra/setup"
[20.743] 01036.01043> userboot: option "kernel.serial=legacy"
[20.743] 01036.01043> userboot: option "
http://192.168.42.1/multiboot/d4%3A5d%3Adf%3A1a%3A32%3A35="
[20.743] 01036.01043> userboot: option "multiboot.boot_loader_name=iPXE+1.0.0++(d2063)"
[20.782] 01036.01043> userboot: searching bootfs for 'bin/bootsvc'
[20.782] 01036.01043> userboot: 'bin/bootsvc' has PT_INTERP "lib/ld.so.1"
[20.782] 01036.01043> userboot: searching bootfs for 'lib/ld.so.1'
[20.782] 01036.01043> userboot: userboot: loaded lib/ld.so.1 at 0x5078917eb000, entry point 0x5078918710d3
[20.782] 01036.01043> userboot: userboot: loaded vDSO at 0x41d449369000, entry point 0x0
[20.782] 01036.01043> userboot: process bin/bootsvc started.
[20.782] 01036.01043> userboot: waiting for loader-service requests...
[20.782] 01036.01043> userboot: searching bootfs for 'lib/libasync-default.so'
[20.782] 01036.01043> userboot: searching bootfs for 'lib/libfdio.so'
[20.782] 01036.01043> userboot: searching bootfs for 'lib/liblaunchpad.so'
[20.783] 01036.01043> userboot: searching bootfs for 'lib/libtrace-engine.so'
[20.783] 01050.01053> dso: id=18de7d58f51e8ba5c4f6afdd0cc8440f482c2b45 base=0x000062fce23d1000 name=<application>
[20.783] 01050.01053> dso: id=c189f51f19d10785d93b5235ad1b46dca4451b00 base=0x0000667af60d4000 name=libasync-default.so
[20.783] 01050.01053> dso: id=40ab5fa3b61f12fef4a44477a687f608661cd450 base=0x000041d449369000 name=<vDSO>
[20.783] 01050.01053> dso: id=67a12284bce140fc32aaaeac223e0e8f85cb5085 base=0x00005078917eb000 name=libc.so
[20.783] 01050.01053> dso: id=27787977e95f3b9563c9e0bd4d34ec92b7e9ad88 base=0x0000419cbf78e000 name=libfdio.so
[20.783] 01050.01053> dso: id=6fc2232dc8c1bc5c6adb8ad50ca794b5a260ee4f base=0x00006a2108861000 name=liblaunchpad.so
[20.783] 01050.01053> dso: id=c9042b83fe01206008fcefb16395238417248169 base=0x00006608e7363000 name=libtrace-engine.so
[20.783] 01050.01053> bootsvc: Starting...
[20.783] 01036.01043> userboot: loader-service channel peer closed
[20.783] 01036.01043> userboot: finished!
[20.783] 01050.01053> bootsvc: Creating bootfs service...
[20.784] 01050.01053> bootsvc: Processing bootdata...
[20.784] 01050.01053> bootsvc: Loading boot cmdline overrides...
[20.784] 01050.01053> bootsvc: Loading kernel VMOs...
[20.784] 01050.01053> bootsvc: Creating loader service...
[20.784] 01050.01053> bootsvc: Launching next process...
[20.784] 01050.01096> bootsvc: launched bin/devmgr
[20.784] 01104.01117> devmgr: main()
[20.784] 01104.01117> cmdline: netsvc.disable=true
[20.784] 01104.01117> cmdline: zircon.system.disable-automount=true
[20.784] 01104.01117> cmdline: zircon.autorun.boot=/boot/infra/setup
[20.784] 01104.01117> cmdline: kernel.serial=legacy
[20.784] 01104.01117> cmdline:
http://192.168.42.1/multiboot/d4%3A5d%3Adf%3A1a%3A32%3A35=
[20.784] 01104.01117> cmdline: multiboot.boot_loader_name=iPXE+1.0.0++(d2063)
[20.784] 01104.01117> devmgr: coordinator_init()
[20.784] 01104.01117> devmgr: init
[20.784] 01104.01117> devmgr: svc init
[20.785] 01104.01117> devmgr: launch /boot/bin/svchost (svchost) OK
[20.785] 01104.01117> devmgr: vfs init
[20.785] 01104.01117> devmgr: launch /boot/bin/fshost (fshost) OK
[20.785] 01104.01221> devmgr: shell startup
[20.786] 01182.01202> fshost: started.
[20.787] 01104.01212> devmgr: launch /boot/bin/pwrbtn-monitor (pwrbtn-monitor) OK
[20.787] 01104.01233> devmgr: launch /boot/bin/virtual-console (virtual-console) OK
[20.787] 01104.01233> zircon.autorun.boot: starting '/boot/infra/setup'...
[20.788] 01104.01233> devmgr: launch /boot/infra/setup (autorun:boot) OK
[20.790] 01104.01117> devcoord: launch devhost 'devhost:sys': pid=2049
[20.791] 01104.01117> devcoord: launch devhost 'devhost:test': pid=2082
[20.791] 01104.01117> devcoord: launch devhost 'devhost:root': pid=2115
[20.791] 01104.01117> devcoord: launch devhost 'devhost:misc': pid=2171
[20.792] 02049.02073> devhost: trace provider registry begun
[20.792] 02082.02105> devhost: trace provider registry begun
[20.793] 02115.02152> devhost: trace provider registry begun
[20.794] 02171.02226> devhost: trace provider registry begun
[20.795] 01104.01221> devmgr: launch /boot/bin/sh (sh:console) OK
[20.850] 02049.02073> acpi-bus: not using IOMMU
[20.854] 02049.02073> acpi-pwrbtn: initialized
[20.860] 02049.02073> WARNING: ACPI found bad _CRS address entry
[20.866] 02049.02073> WARNING: ACPI found bad _CRS address entry
[20.876] 02049.02073> acpi: published device pci(0x76a34b3f3200), parent=proxy(0x76a34b3ef540), handle=0x76a34b42bc30
[20.878] 02049.02073> acpi: published device rtc(0x76a34b3ee080), parent=acpi(0x76a34b3ef780), handle=0x76a34b4445b0
[20.879] 02049.02073> acpi-ec: initialized
[20.880] 02049.02073> acpi: failed to create NHLT VMO (res -10)
[20.880] 02049.02073> acpi: failed to publish NHLT metadata
[20.882] 02049.02073> [sysmem_init 28] async_get_default_dispatcher(): 0x76a34b3e20a0
[20.882] 02049.02073> [sysmem_bind 40] sysmem_bind()
[20.882] 02049.02073> acpi-bus: sysmem_register_protocol() intentionally ignored for now.
[20.883] 02049.02073> PMU: 7 arch events
[20.883] 02049.02073> PMU: arch event id range: 1-7
[20.883] 02049.02073> PMU: 102 model events
[20.883] 02049.02073> PMU: model event id range: 1-241
[20.883] 02049.02073> Intel Processor Trace configuration for this chipset:
[20.883] 02049.02073> mtc_freq_mask: 0x249
[20.883] 02049.02073> cyc_thresh_mask: 0x3fff
[20.883] 02049.02073> psb_freq_mask: 0x3f
[20.883] 02049.02073> num addr ranges: 2
[20.883] 01104.01117> devcoord: launch devhost 'devhost:pci#1:8086:5916': pid=2840
[20.883] 01104.01117> devcoord: launch devhost 'devhost:pci#3:8086:9d2f': pid=2883
[20.884] 01104.01117> devcoord: launch devhost 'devhost:pci#5:8086:9d60': pid=2947
[20.884] 01104.01117> devcoord: launch devhost 'devhost:pci#6:8086:9d61': pid=3011
[20.884] 02840.02863> devhost: trace provider registry begun
[20.885] 01104.01117> devcoord: launch devhost 'devhost:pci#9:8086:9d03': pid=3107
[20.885] 02883.02919> devhost: trace provider registry begun
[20.885] 02947.02985> devhost: trace provider registry begun
[20.886] 01104.01117> devcoord: launch devhost 'devhost:pci#14:8086:9d71': pid=3215
[20.887] 01104.01117> devcoord: launch devhost 'devhost:pci#16:8086:156f': pid=3302
[20.887] 03011.03059> devhost: trace provider registry begun
[20.888] 03107.03142> devhost: trace provider registry begun
[20.888] 02947.02985> initialized intel serialio i2c driver, reg=0x47b04b76c000 regsize=4096
[20.890] 03011.03059> initialized intel serialio i2c driver, reg=0x63df08fcc000 regsize=4096
[20.891] 03215.03266> devhost: trace provider registry begun
[20.891] 03107.03142> ahci: using MSI interrupt
[20.902] 02883.03547> * found USB device (0x18d1:0xa002, USB 2.0) config 1
[20.902] 03302.03354> devhost: trace provider registry begun
[20.902] 03215.03266> [IHDA DSP 00:1f.3] Failed to fetch NHLT (res -25)
[20.902] 03215.03266> devhost[00:1f.3/intel-hda-000/intel-sst-dsp-000] bind driver '/boot/driver/dsp.so' failed: -25
[20.902] 01104.01117> devcoord: rpc: bind-driver 'intel-sst-dsp-000' status -25
[20.903] 01240.01554> vc: new input device /dev/class/input/000
[20.911] 02883.03547> * found USB device (0x18d1:0xa003, USB 3.0) config 1
[20.992] 01240.01554> vc: new display device /dev/class/display-controller/000/virtcon
[21.133] 02840.04142> i915: MST not supported
[21.632] 02840.04142> i915: Found DP monitor
[21.632] 02840.04142> i915: Display 1 connected
[22.192] 01240.01554> vc: Successfully attached to display 1
[22.373] 02883.03547> * found USB device (0x0781:0x5571, USB 2.0) config 1
[22.374] 02883.02919> UMS: parent: 'ifc-000'
[22.374] 02883.02919> UMS:Max lun is: 0
[22.624] 02883.03547> * found USB device (0x8087:0x0a2b, USB 2.0) config 1
[22.626] 02883.02919> devhost[00:14.0/xhci/usb-bus/002/002/ifc-001] bind driver '/boot/driver/bt-transport-usb.so' failed: -2
[22.626] 01104.01117> devcoord: rpc: bind-driver 'ifc-001' status -2
[22.891] 02947.02985> intel-i2c-controller: intel_serialio_i2c_slave_transfer: -21
[22.891] 02947.02985> i2c-hid: could not read HID descriptor: 0
[22.891] 02947.02985> devhost[00:15.0/i2c-bus-9d60/0020] bind driver '/boot/driver/i2c-hid.so' failed: -2
[22.891] 01104.01117> devcoord: rpc: bind-driver '0020' status -2
[22.891] 03011.03059> intel-i2c-controller: intel_serialio_i2c_slave_transfer: -21
[22.891] 03011.03059> i2c-hid: could not read HID descriptor: 0
[22.891] 03011.03059> devhost[00:15.1/i2c-bus-9d61/004c] bind driver '/boot/driver/i2c-hid.so' failed: -2
[22.891] 01104.01117> devcoord: rpc: bind-driver '004c' status -2
[22.906] 03107.03630> sata2: dev info
[22.906] 03107.03630> serial=711430951002 0
[22.906] 03107.03630> firmware rev=1Q01A7 0
[22.906] 03107.03630> model id=IBIW NSS D
[22.906] 03107.03630> major=0x3f0 ACS2 DMA 32 commands
[22.906] 03107.03630> LBA48 234441648 sectors, sector size=512
[22.907] 01182.01202> devmgr: /dev/class/block/000: GPT?
[22.907] 01104.01117> devcoord: dc_bind_device() '/boot/driver/gpt.so'
[22.907] 03107.03142> gpt: device_get_metadata failed (-25)
[22.908] 01182.01202> devmgr: /dev/class/block/001: FVM?
[22.908] 01104.01117> devcoord: dc_bind_device() '/boot/driver/fvm.so'
[22.910] 04413.04427> paver:[Initialize] Successfully initialized EFI Device Partitioner
[22.912] 04413.04427> paver:[WipePartitions] Immediate reboot strongly recommended
[22.912] 03107.03142> block: Joining un-closed FIFO server
[22.912] 03107.03142> block: Joining un-closed FIFO server
[22.912] 03107.03142> block: Joining un-closed FIFO server
[22.912] 01104.01117> devcoord: dc_bind_device() ''
[22.913] 01182.01202> devmgr: /dev/class/block/000: GPT?
[22.913] 01104.01117> devcoord: dc_bind_device() '/boot/driver/gpt.so'
[22.913] 03107.03142> gpt: device_get_metadata failed (-25)
[22.915] 04702.04716> 34+0 records in
[22.915] 04702.04716> 34+0 records out
[22.915] 04702.04716> 17408 bytes copied
[22.916] 04820.04834> Failed to seek on output
[22.916] 04820.04834> 0+0 records in
[22.916] 04820.04834> 0+0 records out
[22.916] 04820.04834> 0 bytes copied
[22.916] 04890.04904> netifc: ? /dev/class/ethernet/000
[22.917] 04890.04904> netifc: create 512 eth buffers
[22.917] 04890.04904> macaddr: d4:5d:df:1a:32:35
[22.917] 04890.04904> ip6addr: fe80::d65d:df4d:fe1a:3235
[22.917] 04890.04904> snmaddr: ff02::1:ff1a:3235
[22.917] 04890.04904> netsvc: using /dev/class/ethernet/000
[22.917] 04890.04904> _ _ _
[22.917] 04890.04904> | | | | |
[22.917] 04890.04904> _______ __| | |__ ___ ___ | |_
[22.917] 04890.04904> |_ / _ \/ _` | '_ \ / _ \ / _ \| __|
[22.917] 04890.04904> / / __/ (_| | |_) | (_) | (_) | |_
[22.917] 04890.04904> /___\___|\__,_|_.__/ \___/ \___/ \__|
[22.917] 04890.04904> zedboot: version: 0.7.13
[22.917] 04890.04904> netsvc: nodename='ocean-bats-sky-poppy'
[22.917] 04890.04904> netsvc: will not advertise
[22.917] 04890.04904> netsvc: start
[23.377] 02883.04246> UMS: block size is: 0x00000200
[23.377] 02883.04246> UMS: total blocks is: 15630336
[23.377] 02883.04246> UMS: total size is: 8002732032
[23.377] 02883.04246> UMS: read-only: 0 removable: 1
[23.378] 01182.01202> devmgr: /dev/class/block/006: MBR?
[23.378] 01104.01117> devcoord: dc_bind_device() '/boot/driver/mbr.so'
[23.380] 01182.01202> devmgr: /dev/class/block/008: MBR?
[23.380] 01104.01117> devcoord: dc_bind_device() '/boot/driver/mbr.so'
[1722.205] 04890.04904> netsvc: handling tftp request failed (file might not exist)
[1722.205] 04890.04904> netsvc: close, but no open file
[1722.205] 04890.04904> netsvc: metrics: {"inorderblks": 0,"oooblks": 0,"ack": 0,"nack": 0,"timeouts": 0,"sas": 0,"inorderbytes": 0}
[1722.205] 04890.04904> netsvc: tftp write of file <<netboot>>cmdline completed
[1722.205] 04890.04904> netsvc: metrics: {"inorderblks": 1,"oooblks": 0,"ack": 1,"nack": 0,"timeouts": 0,"sas": 0,"inorderbytes": 55}
[1722.206] 04890.04904> netsvc: Running FVM Paver
[1722.207] 04890.05078> paver:[InitializeGpt] Located GPT is invalid; Attempting to initialize
[1722.208] 01104.01117> devcoord: dc_bind_device() ''
[1722.208] 01104.01117> devcoord: dc_bind_device() '/boot/driver/gpt.so'
[1722.208] 03107.03142> gpt: device_get_metadata failed (-25)
[1722.208] 01182.01202> devmgr: /dev/class/block/000: GPT?
[1722.208] 01104.01117> devcoord: dc_bind_device() '/boot/driver/gpt.so'
[1722.208] 03107.03142> devhost: rpc:bind-device failed: -20
[1722.209] 04890.05078> paver:[Initialize] Successfully initialized EFI Device Partitioner
[1722.209] 04890.05078> paver:[PartitionPave] Paving partition.
[1722.209] 04890.05078> paver:[FindFirstFit] Looking for space
[1722.209] 04890.05078> paver:[FindFirstFit] Sorting
[1722.209] 04890.05078> paver:[FindFirstFit] Partition[0] From Block [0, 34) ... (next partition starts at block 234441614)
[1722.209] 04890.05078> paver:[FindFirstFit] There are 234441580 free blocks (16777216 requested)
[1722.209] 04890.05078> paver:[AddPartition] Found space in GPT - OK 234441580 @ 34
[1722.209] 04890.05078> paver:[AddPartition] Final space in GPT - OK 16777216 @ 34
[1722.209] 04890.05078> paver:[AddPartition] Added partition, waiting for bind
[1722.209] 01104.01117> devcoord: dc_bind_device() ''
[1722.210] 01182.01202> devmgr: /dev/class/block/000: GPT?
[1722.210] 01104.01117> devcoord: dc_bind_device() '/boot/driver/gpt.so'
[1722.210] 03107.03142> gpt: device_get_metadata failed (-25)
[1722.211] 04890.05078> paver:[AddPartition] Added partition, waiting for bind - OK
[1722.211] 04890.05078> paver:[PartitionPave] Streaming partitions...
[1722.211] 05058.05072> Found compressed file
[1722.211] 04890.05078> paver:[FvmStreamPartitions] Header Validated - OK
[1722.212] 04890.05078> paver:[FvmPartitionFormat] Initializing partition as FVM
[1722.214] 01104.01117> devcoord: dc_bind_device() '/boot/driver/fvm.so'
[1723.216] 04890.05078> paver:[FvmStreamPartitions] Partitions pre-validated successfully: Enough space exists to pave.
[1723.216] 04890.05078> paver:[AllocatePartitions] Allocating partition blobfs consisting of 1 slices
[1723.219] 04890.05078> paver:[AllocatePartitions] Allocating partition minfs consisting of 1 slices
[1723.221] 04890.05078> paver:[AllocatePartitions] Creating zxcrypt volume
[1723.222] 03107.03142> devhost_get_handles(0x7e8a761d1900:block) open path='zxcrypt/block', r=-2
[1723.222] 01104.01117> devcoord: dc_bind_device() '/boot/driver/zxcrypt.so'
[1723.223] 03107.03142> devhost_get_handles(0x7e8a761d1900:block) open path='zxcrypt', r=-2
[1723.226] 04890.05078> paver:[FvmStreamPartitions] Partition space pre-allocated successfully.
[1723.227] 04890.05078> paver:[FvmStreamPartitions] Streaming partition 0
[1723.227] 04890.05078> paver:[StreamFvmPartition] Writing extent 0...
[1723.227] 04890.05084> netsvc: paver write progress 0.1%
[1723.227] 04890.05078> paver:[StreamFvmPartition] 8192 bytes written, 8380416 zeroes left
[1723.244] 04890.05078> paver:[StreamFvmPartition] Writing extent 1...
[1723.244] 04890.05078> paver:[StreamFvmPartition] 8192 bytes written, 8380416 zeroes left
[1723.271] 04890.05078> paver:[StreamFvmPartition] Writing extent 2...
[1723.276] 04890.05078> paver:[StreamFvmPartition] 2097152 bytes written, 6291456 zeroes left
[1723.288] 04890.05078> paver:[StreamFvmPartition] Writing extent 3...
[1723.293] 04890.05078> paver:[StreamFvmPartition] 2097152 bytes written, 6291456 zeroes left
[1723.308] 04890.05078> paver:[StreamFvmPartition] Writing extent 4...
[1724.227] 04890.05084> netsvc: paver write progress 67.1%
[1725.227] 04890.05084> netsvc: paver write progress 99.3%
2019/04/22 22:49:00 done
2019/04/22 22:49:00 attempting to send <<image>>bootloader.img...
2019/04/22 22:49:00 target is busy, retrying in one second
[1725.248] 04890.04904> netsvc: tftp write of file <<image>>sparse.fvm completed
[1725.248] 04890.04904> netsvc: metrics: {"inorderblks": 300488,"oooblks": 0,"ack": 1174,"nack": 0,"timeouts": 0,"sas": 0,"inorderbytes": 307699360}
[1725.249] 04890.05078> paver:[StreamFvmPartition] 335699968 bytes written, 8232960 zeroes left
[1725.266] 04890.05078> paver:[FvmStreamPartitions] Done streaming partition 0
[1725.266] 04890.05078> paver:[FvmStreamPartitions] Done flushing partition 0
[1725.266] 04890.05078> paver:[FvmStreamPartitions] Streaming partition 1
[1725.266] 04890.05078> paver:[StreamFvmPartition] Writing extent 0...
[1725.266] 04890.05078> paver:[StreamFvmPartition] 8192 bytes written, 8380416 zeroes left
[1725.305] 04890.05078> paver:[StreamFvmPartition] Writing extent 1...
[1725.305] 04890.05078> paver:[StreamFvmPartition] 65536 bytes written, 8323072 zeroes left
[1725.343] 04890.05078> paver:[StreamFvmPartition] Writing extent 2...
[1725.344] 04890.05078> paver:[StreamFvmPartition] 65536 bytes written, 8323072 zeroes left
[1725.386] 04890.05078> paver:[StreamFvmPartition] Writing extent 3...
[1725.424] 04890.05078> paver:[StreamFvmPartition] Writing extent 4...
[1725.434] 04890.05078> paver:[StreamFvmPartition] 2097152 bytes written, 14680064 zeroes left
[1725.499] 04890.05078> paver:[StreamFvmPartition] Writing extent 5...
[1725.499] 04890.05078> paver:[StreamFvmPartition] 57344 bytes written, 8331264 zeroes left
[1725.535] 04890.05078> paver:[FvmStreamPartitions] Done streaming partition 1
[1725.535] 04890.05078> paver:[FvmStreamPartitions] Done flushing partition 1
[1725.536] 05058.05072> Reading FVM from compressed file: true
[1725.536] 05058.05072> Remaining bytes read into compression buffer: 0
[1725.536] 05058.05072> Remaining bytes written to decompression buffer: 0
[1725.536] 05058.05072> Time reading bytes from sparse FVM file: 3168431862 (1 s)
[1725.536] 05058.05072> Time reading bytes AND decompressing them: 3347189022 (1 s)
[1725.536] 04890.05078> paver:[PartitionPave] Completed successfully
2019/04/22 22:49:01 attempting to send <<image>>bootloader.img...
2019/04/22 22:49:01 done
2019/04/22 22:49:01 attempting to send <<image>>zircona.img...
[1726.249] 04890.04904> netsvc: Running BOOTLOADER Paver
[1726.252] 04890.05952> paver:[Initialize] Successfully initialized EFI Device Partitioner
[1726.252] 04890.05952> paver:[RealMain] SKIPPING BOOTLOADER install on x64 device, pass --force if desired.
[1726.266] 04890.04904> netsvc: tftp write of file <<image>>bootloader.img completed
[1726.266] 04890.04904> netsvc: metrics: {"inorderblks": 1093,"oooblks": 0,"ack": 5,"nack": 0,"timeouts": 0,"sas": 0,"inorderbytes": 1118208}
[1726.266] 04890.04904> netsvc: Running ZIRCON-A Paver
[1726.269] 04890.06081> paver:[Initialize] Successfully initialized EFI Device Partitioner
[1726.269] 04890.06081> paver:[PartitionPave] Paving partition.
[1726.269] 04890.06081> paver:[FindFirstFit] Looking for space
[1726.269] 04890.06081> paver:[FindFirstFit] Partition seen with start 34, end 16777249 (length 16777216)
[1726.269] 04890.06081> paver:[FindFirstFit] Sorting
[1726.269] 04890.06081> paver:[FindFirstFit] Partition[0] From Block [0, 34) ... (next partition starts at block 34)
[1726.269] 04890.06081> paver:[FindFirstFit] There are 0 free blocks (32768 requested)
[1726.269] 04890.06081> paver:[FindFirstFit] Partition[1] From Block [34, 16777250) ... (next partition starts at block 234441614)
[1726.269] 04890.06081> paver:[FindFirstFit] There are 217664364 free blocks (32768 requested)
[1726.269] 04890.06081> paver:[AddPartition] Found space in GPT - OK 217664364 @ 16777250
[1726.269] 04890.06081> paver:[AddPartition] Final space in GPT - OK 32768 @ 16777250
[1726.269] 04890.06081> paver:[AddPartition] Added partition, waiting for bind
[1726.269] 03107.03142> block: Joining un-closed FIFO server
[1726.269] 03107.03142> block: Joining un-closed FIFO server
[1726.270] 01104.01117> devcoord: dc_bind_device() ''
[1726.280] 01182.01202> devmgr: /dev/class/block/000: GPT?
[1726.280] 01104.01117> devcoord: dc_bind_device() '/boot/driver/gpt.so'
[1726.280] 03107.03142> gpt: device_get_metadata failed (-25)
[1726.281] 01182.01202> devmgr: /dev/class/block/013: FVM?
[1726.281] 01104.01117> devcoord: dc_bind_device() '/boot/driver/fvm.so'
[1726.282] 04890.06081> paver:[AddPartition] Added partition, waiting for bind - OK
2019/04/22 22:49:01 done
2019/04/22 22:49:01 attempting to send <<image>>zirconr.img...
2019/04/22 22:49:01 target is busy, retrying in one second
[1726.392] 04890.04904> netsvc: tftp write of file <<image>>zircona.img completed
[1726.392] 04890.04904> netsvc: metrics: {"inorderblks": 11738,"oooblks": 0,"ack": 46,"nack": 0,"timeouts": 0,"sas": 0,"inorderbytes": 12019040}
[1726.533] 04890.06081> paver:[PartitionPave] Completed successfully
2019/04/22 22:49:02 attempting to send <<image>>zirconr.img...
[1727.393] 04890.04904> netsvc: Running ZIRCON-R Paver
[1727.398] 04890.06341> paver:[Initialize] Successfully initialized EFI Device Partitioner
[1727.398] 04890.06341> paver:[PartitionPave] Paving partition.
[1727.398] 04890.06341> paver:[FindFirstFit] Looking for space
[1727.398] 04890.06341> paver:[FindFirstFit] Partition seen with start 34, end 16777249 (length 16777216)
[1727.398] 04890.06341> paver:[FindFirstFit] Partition seen with start 16777250, end 16810017 (length 32768)
[1727.398] 04890.06341> paver:[FindFirstFit] Sorting
[1727.398] 04890.06341> paver:[FindFirstFit] Partition[0] From Block [0, 34) ... (next partition starts at block 34)
[1727.398] 04890.06341> paver:[FindFirstFit] There are 0 free blocks (49152 requested)
[1727.398] 04890.06341> paver:[FindFirstFit] Partition[1] From Block [34, 16777250) ... (next partition starts at block 16777250)
[1727.398] 04890.06341> paver:[FindFirstFit] There are 0 free blocks (49152 requested)
[1727.398] 04890.06341> paver:[FindFirstFit] Partition[2] From Block [16777250, 16810018) ... (next partition starts at block 234441614)
[1727.398] 04890.06341> paver:[FindFirstFit] There are 217631596 free blocks (49152 requested)
[1727.398] 04890.06341> paver:[AddPartition] Found space in GPT - OK 217631596 @ 16810018
[1727.398] 04890.06341> paver:[AddPartition] Final space in GPT - OK 49152 @ 16810018
[1727.399] 04890.06341> paver:[AddPartition] Added partition, waiting for bind
[1727.399] 03107.03142> block: Joining un-closed FIFO server
[1727.399] 01104.01117> devcoord: dc_bind_device() ''
[1727.411] 01182.01202> devmgr: /dev/class/block/000: GPT?
[1727.411] 01104.01117> devcoord: dc_bind_device() '/boot/driver/gpt.so'
[1727.411] 03107.03142> gpt: device_get_metadata failed (-25)
[1727.412] 01182.01202> devmgr: /dev/class/block/017: FVM?
[1727.412] 01104.01117> devcoord: dc_bind_device() '/boot/driver/fvm.so'
[1727.412] 04890.06341> paver:[AddPartition] Added partition, waiting for bind - OK
2019/04/22 22:49:03 done
2019/04/22 22:49:03 attempting to send <<image>>authorized_keys...
2019/04/22 22:49:03 target is busy, retrying in one second
[1727.518] 04890.04904> netsvc: tftp write of file <<image>>zirconr.img completed
[1727.518] 04890.04904> netsvc: metrics: {"inorderblks": 10428,"oooblks": 0,"ack": 41,"nack": 0,"timeouts": 0,"sas": 0,"inorderbytes": 10678152}
[1727.998] 04890.06341> paver:[PartitionPave] Completed successfully
2019/04/22 22:49:04 attempting to send <<image>>authorized_keys...
2019/04/22 22:49:04 done
2019/04/22 22:49:04 attempting to send <<netboot>>kernel.bin...
2019/04/22 22:49:04 target is busy, retrying in one second
[1728.519] 04890.04904> netsvc: Installing SSH authorized_keys
[1728.519] 04890.04904> netsvc: tftp write of file <<image>>authorized_keys completed
[1728.519] 04890.04904> netsvc: metrics: {"inorderblks": 1,"oooblks": 0,"ack": 1,"nack": 0,"timeouts": 0,"sas": 0,"inorderbytes": 806}
[1728.524] 04890.06618> paver:[Initialize] Successfully initialized EFI Device Partitioner
[1728.525] 01104.01117> devcoord: dc_bind_device() '/boot/driver/zxcrypt.so'
[1728.525] 03107.03142> devhost_get_handles(0x7e8a761d1900:block) open path='zxcrypt', r=-2
[1728.554] 04890.06618> paver:[DataFilePave] Wrote ssh/authorized_keys
2019/04/22 22:49:05 attempting to send <<netboot>>kernel.bin...
2019/04/22 22:49:05 done
[0.000] 00000.00000> zbi: @ 0xffffff80066ea000 (10492752 bytes)
[0.000] 00000.00000> UART: FIFO depth 16
[0.000] 00000.00000> PMM: boot reserve add [0x100000, 0x2fffff]
[0.000] 00000.00000> PMM: boot reserve add [0x66ea000, 0x70ebfff]
[0.000] 00000.00000> PMM: arena too small to be useful (size 4096)
[0.000] 00000.00000> PMM: pmm_add_arena failed to initialize arena
[0.000] 00000.00000> MEM: Failed to add pmm range at 0x7ffff000 size 0x1000
[0.000] 00000.00000> PMM: boot reserve marking WIRED [0x100000, 0x2fffff]
[0.000] 00000.00000> PMM: boot reserve marking WIRED [0x66ea000, 0x70ebfff]
[0.000] 00000.00000> welcome to Zircon
[0.000] 00000.00000> KASLR: .text section at 0xffffffff00100000
[0.000] 00000.00000> INIT: cpu 0, calling hook 0xffffffff00114ec4 (global_prng_seed) at level 0x30000, flags 0x1
[0.000] 00000.00000> initializing vm pre-heap
[0.000] 00000.00000> VM: marking boot alloc used range [0x70ec000, 0x70ec100)
[0.000] 00000.00000> INIT: cpu 0, calling hook 0xffffffff00122274 (elf_build_id) at level 0x4fffe, flags 0x1
[0.000] 00000.00000> INIT: cpu 0, calling hook 0xffffffff00122400 (version) at level 0x4ffff, flags 0x1
[0.000] 00000.00000> version:
[0.000] 00000.00000> arch: x86
[0.000] 00000.00000> platform: XXX
[0.000] 00000.00000> target: XXX
[0.000] 00000.00000> project: x64
[0.000] 00000.00000> buildid: git-81c2b7094a8c41bd54b142dcff3def917d049aee-dirty
[0.000] 00000.00000> ELF build ID: d799d27c7b40858131aaa202c40c5ca9572cd9c6
[0.000] 00000.00000> initializing heap
[0.000] 00000.00000> INIT: cpu 0, calling hook 0xffffffff00101fc4 (console) at level 0x50000, flags 0x1
[0.000] 00000.00000> INIT: cpu 0, calling hook 0xffffffff001826cc (x86_resource_init) at level 0x50000, flags 0x1
[0.000] 00000.00000> initializing vm
[0.000] 00000.00000> VM: reserving kernel region [0xffffffff00100000, 0xffffffff0021b000) flags 0x28 name 'kernel_code'
[0.000] 00000.00000> VM: reserving kernel region [0xffffffff0021b000, 0xffffffff0026c000) flags 0x8 name 'kernel_rodata'
[0.000] 00000.00000> VM: reserving kernel region [0xffffffff0026c000, 0xffffffff00274000) flags 0x18 name 'kernel_data'
[0.000] 00000.00000> VM: reserving kernel region [0xffffffff00274000, 0xffffffff00300000) flags 0x18 name 'kernel_bss'
[0.000] 00000.00000> INIT: cpu 0, calling hook 0xffffffff00183390 (display_memtype) at level 0x60001, flags 0x1
[0.000] 00000.00000> INIT: cpu 0, calling hook 0xffffffff00186820 (acpi_tables) at level 0x60001, flags 0x1
[0.000] 00000.00000> INIT: cpu 0, calling hook 0xffffffff001814d0 (hpet) at level 0x60002, flags 0x1
[0.000] 00000.00000> INIT: cpu 0, calling hook 0xffffffff00181890 (apic) at level 0x60002, flags 0x1
[0.000] 00000.00000> x2APIC enabled
[0.000] 00000.00000> INIT: cpu 0, calling hook 0xffffffff001a7e74 (system_topology_init) at level 0x60002, flags 0x1
[0.000] 00000.00000> WARNING: more than 1000 levels of cache, couldn't find highest.
[0.000] 00000.00000> WARNING: unable to find any cache levels.
[0.000] 00000.00000> Could not find SRAT table. ACPICA returned: 5
[0.000] 00000.00000> INIT: cpu 0, calling hook 0xffffffff00185e10 (timer) at level 0x60003, flags 0x1
[0.000] 00000.00000> HPET frequency: 23999 ticks/ms
[0.000] 00000.00000> TSC frequency: 2712000 ticks/ms
[1729.928] 00000.00000> timer features: constant_tsc 1 invariant_tsc 1 tsc_deadline 1
[1729.928] 00000.00000> Using TSC as wallclock
[1729.928] 00000.00000> INIT: cpu 0, calling hook 0xffffffff00208908 (percpu_heap_init) at level 0x60003, flags 0x1
[1729.928] 00000.00000> initializing kernel
[1729.928] 00000.00000> initializing mp
[1729.928] 00000.00000> INIT: cpu 0, calling hook 0xffffffff00115118 (global_prng_thread_safe) at level 0x7ffff, flags 0x1
[1729.928] 00000.00000> creating bootstrap completion thread
[1729.928] 00000.00000> top of bootstrap2()
[1729.928] 00000.00000> INIT: cpu 0, calling hook 0xffffffff00131734 (libobject) at level 0x80000, flags 0x1
[1729.928] 00000.00000> OOM: started thread
[1729.928] 00000.00000> INIT: cpu 0, calling hook 0xffffffff00205874 (dpc) at level 0x80000, flags 0x1
[1729.928] 00000.00000> Processor Model Info: type 0 family 0x6 model 0xe stepping 0x9
[1729.928] 00000.00000> display_family 0x6 display_model 0x8e
[1729.928] 00000.00000> Vendor: Intel
[1729.928] 00000.00000> Microarch: Kaby Lake
[1729.928] 00000.00000> F/M/S: 6/8e/9
[1729.928] 00000.00000> patch_level: 8e
[1729.928] 00000.00000> Brand: Intel(R) Core(TM) i5-7300U CPU @ 2.60GHz
[1729.928] 00000.00000> Features: fpu sse sse2 sse3 ssse3 sse4.1 sse4.2 mmx avx avx2 fxsr pcid xsave mon aesni clflush
[1729.928] 00000.00000> clflushopt fsgsbase tsc_adj smep smap erms rdrand rdseed syscall nx huge rdtscp
[1729.928] 00000.00000> invar_tsc tsc_deadline x2apic vmx pt hwp
[1729.928] 00000.00000> Properties: meltdown l1tf pcid_good
[1729.928] 00000.00000> initializing platform
[1729.928] 00000.00000> INIT: cpu 0, calling hook 0xffffffff001a1584 (x86_perfmon) at level 0x90000, flags 0x1
[1729.928] 00000.00000> PMU: version 4
[1729.928] 00000.00000> UART: started IRQ driven RX
[1729.928] 00000.00000> UART: started IRQ driven TX
[1729.928] 00000.00000> cpu topology:
[1729.928] 00000.00000> 0: apic id 0x0 BSP
[1729.928] 00000.00000> 1: apic id 0x1
[1729.928] 00000.00000> 2: apic id 0x2
[1729.928] 00000.00000> 3: apic id 0x3
[1729.928] 00000.00000> Found 4 cpus
[1729.928] 00000.00000> booting apic ids: 0x1 0x2 0x3
[1729.942] 00000.00000> entering scheduler on cpu 1
[1729.944] 00000.00000> entering scheduler on cpu 3
[1729.944] 00000.00000> entering scheduler on cpu 2
[1729.946] 00000.00000> smbios: manufacturer="Intel Corporation" product="NUC7i5DNKE"
[1729.946] 00000.00000> initializing target
[1729.946] 00000.00000> INIT: cpu 0, calling hook 0xffffffff001850c0 (x86_pcie_init) at level 0xa0000, flags 0x1
[1729.946] 00000.00000> moving to last init level
[1729.946] 00000.00000> INIT: cpu 0, calling hook 0xffffffff001214cc (debuglog) at level 0xb0000, flags 0x1
[1729.946] 00000.00000> INIT: cpu 0, calling hook 0xffffffff00174d48 (kcounters) at level 0xb0000, flags 0x1
[1729.946] 00000.00000> INIT: cpu 0, calling hook 0xffffffff00102aec (kernel_shell) at level 0xc0000, flags 0x1
[1729.946] 00000.00000> INIT: cpu 0, calling hook 0xffffffff00202aac (ktrace) at level 0xc0000, flags 0x1
[1729.950] 00000.00000> ktrace: buffer at 0xffffff91a48d7000 (33554432 bytes)
[1729.950] 00000.00000> INIT: cpu 0, calling hook 0xffffffff002184d0 (userboot) at level 0xc0000, flags 0x1
[1729.950] 00000.00000> userboot: ramdisk 0xa02000 @ 0xffffff80066ea000
[1729.950] 00000.00000> userboot: userboot rodata 0 @ [0x6dd1ce987000,0x6dd1ce98a000)
[1729.950] 00000.00000> userboot: userboot code 0x3000 @ [0x6dd1ce98a000,0x6dd1ce995000)
[1729.950] 00000.00000> userboot: vdso/full rodata 0 @ [0x6dd1ce995000,0x6dd1ce99c000)
[1729.950] 00000.00000> userboot: vdso/full code 0x7000 @ [0x6dd1ce99c000,0x6dd1ce99d000)
[1729.950] 00000.00000> userboot: entry point @ 0x6dd1ce98ac90
[1729.950] 01036.01043> userboot: option "zircon.autorun.system=/boot/bin/sh+/boot/infra/runcmds"
[1729.974] 01036.01043> userboot: searching bootfs for 'bin/bootsvc'
[1729.974] 01036.01043> userboot: 'bin/bootsvc' has PT_INTERP "lib/ld.so.1"
[1729.974] 01036.01043> userboot: searching bootfs for 'lib/ld.so.1'
[1729.974] 01036.01043> userboot: userboot: loaded lib/ld.so.1 at 0x7c08b2db5000, entry point 0x7c08b2dd33e0
[1729.974] 01036.01043> userboot: userboot: loaded vDSO at 0x4a66ab3cc000, entry point 0x4a66ab3d3907
[1729.974] 01036.01043> userboot: process bin/bootsvc started.
[1729.974] 01036.01043> userboot: waiting for loader-service requests...
[1729.975] 01036.01043> userboot: searching bootfs for 'lib/libasync-default.so'
[1729.975] 01036.01043> userboot: searching bootfs for 'lib/libfdio.so'
[1729.975] 01036.01043> userboot: searching bootfs for 'lib/libtrace-engine.so'
[1729.975] 01036.01043> userboot: searching bootfs for 'lib/liblaunchpad.so'
[1729.975] 01050.01053> dso: id=043fa7983994a9e131e2d1ba5712e53b1adf4458 base=0x00005a9ed2a51000 name=<application>
[1729.975] 01050.01053> dso: id=352446ffd1818c01938e67e4e7d79eec2cfff150 base=0x00004a66ab3cc000 name=<vDSO>
[1729.975] 01050.01053> dso: id=0271cf194a0841671fa33b6dcb224cd39eea70be base=0x00007a5800117000 name=libasync-default.so
[1729.975] 01050.01053> dso: id=bfa452526f3279cc21a12a170ccf4becd19a30e0 base=0x000019571214a000 name=libfdio.so
[1729.975] 01050.01053> dso: id=5757153c96da035b72f53e5244fb371456405a11 base=0x00005f03db85c000 name=libtrace-engine.so
[1729.975] 01050.01053> dso: id=397171e90426285a1ecfb086e2d6f0a769d6b9e3 base=0x000052f22e768000 name=liblaunchpad.so
[1729.975] 01050.01053> dso: id=8d291ff8a7da56bd9183c8e0103f45f9903c5f10 base=0x00007c08b2db5000 name=libc.so
[1729.975] 01050.01053> bootsvc: Starting...
[1729.975] 01036.01043> userboot: loader-service channel peer closed
[1729.975] 01036.01043> userboot: finished!
[1729.975] 01050.01053> bootsvc: Creating bootfs service...
[1729.976] 01050.01053> bootsvc: Retrieving boot image...
[1729.976] 01050.01053> bootsvc: Decommitted BOOTDATA VMO from 0 to 0xa01000
[1729.976] 01050.01053> bootsvc: Loading boot arguments...
[1729.976] 01050.01053> bootsvc: Creating svcfs service...
[1729.976] 01050.01053> bootsvc: Loading kernel VMOs...
[1729.976] 01050.01053> bootsvc: Creating loader service...
[1729.976] 01050.01053> bootsvc: Launching next process...
[1729.976] 01050.01108> bootsvc: Launched bin/devcoordinator
[1729.977] 01115.01130> devcoordinator: launch /boot/bin/svchost (svchost) OK
[1729.978] 01115.01130> devcoordinator: launch /boot/bin/fshost (fshost) OK
[1729.980] 01115.01321> devcoordinator: launch /boot/bin/pwrbtn-monitor (pwrbtn-monitor) OK
[1729.980] 01115.01343> devcoordinator: launch /boot/bin/netsvc (netsvc) OK
[1729.981] 01115.01343> devcoordinator: launch /boot/bin/virtual-console (virtual-console) OK
[1729.984] 01115.01130> devcoordinator: full system required, ignoring fallback drivers until /system is loaded
[1729.984] 01115.01130> devcoordinator: launch devhost 'devhost:sys': pid=2187
[1729.985] 01115.01130> devcoordinator: launch devhost 'devhost:test': pid=2219
[1729.985] 01115.01130> devcoordinator: launch devhost 'devhost:root': pid=2279
[1729.986] 01115.01130> devcoordinator: launch devhost 'devhost:misc': pid=2330
[1729.986] 02187.02201> devhost: trace provider registry begun
[1729.986] 02219.02241> devhost: trace provider registry begun
[1729.987] 02279.02309> devhost: trace provider registry begun
[1729.988] 02330.02366> devhost: trace provider registry begun
[1729.989] 01115.01333> devcoordinator: launch /boot/bin/sh (sh:console) OK
[1730.073] 02187.02201> acpi-bus: not using IOMMU
[1730.080] 02187.02201> PMU: 7 arch events
[1730.080] 02187.02201> PMU: arch event id range: 1-7
[1730.080] 02187.02201> PMU: 102 arch events
[1730.080] 02187.02201> PMU: arch event id range: 1-241
[1730.080] 02187.02201> Intel Processor Trace configuration for this chipset:
[1730.080] 02187.02201> mtc_freq_mask: 0x249
[1730.080] 02187.02201> cyc_thresh_mask: 0x3fff
[1730.080] 02187.02201> psb_freq_mask: 0x3f
[1730.080] 02187.02201> num addr ranges: 2
[1730.080] 02187.02201> [sysmem_init 28] async_get_default_dispatcher(): 0x34636199e850
[1730.080] 02187.02201> [sysmem_bind 40] sysmem_bind()
[1730.080] 02187.02879> acpi-pwrbtn: initialized
[1730.081] 01706.01768> vc: new input device /dev/class/input/000
[1730.090] 02187.02879> WARNING: ACPI found bad _CRS address entry
[1730.100] 02187.02879> WARNING: ACPI found bad _CRS address entry
[1730.112] 02187.02879> acpi: published device pci(0x3462a1991a30), parent=sys(0x3463e199eb10), handle=0x3462619b0ad0
[1730.112] 01115.01130> devcoordinator: launch devhost 'devhost:pci#1:8086:5916': pid=2975
[1730.113] 01115.01130> devcoordinator: launch devhost 'devhost:pci#3:8086:9d2f': pid=3028
[1730.113] 02975.02989> devhost: trace provider registry begun
[1730.113] 01115.01130> devcoordinator: launch devhost 'devhost:pci#5:8086:9d60': pid=3100
[1730.114] 03028.03051> devhost: trace provider registry begun
[1730.115] 01115.01130> devcoordinator: launch devhost 'devhost:pci#6:8086:9d61': pid=3206
[1730.115] 02187.02879> acpi: published device rtc(0x3462a19955d0), parent=acpi(0x3463e199d010), handle=0x3462619d68d0
[1730.115] 03100.03155> devhost: trace provider registry begun
[1730.116] 01115.01130> devcoordinator: launch devhost 'devhost:pci#9:8086:9d03': pid=3365
[1730.116] 03206.03261> devhost: trace provider registry begun
[1730.117] 03365.03386> devhost: trace provider registry begun
[1730.117] 01115.01130> devcoordinator: launch devhost 'devhost:pci#14:8086:9d71': pid=3484
[1730.117] 02187.02879> acpi-ec: initialized
[1730.117] 01115.01130> devcoordinator: launch devhost 'devhost:pci#16:8086:156f': pid=3592
[1730.119] 03484.03530> devhost: trace provider registry begun
[1730.119] 03100.03155> initialized intel serialio i2c driver, reg=0x685192a89000 regsize=4096
[1730.120] 03592.03617> devhost: trace provider registry begun
[1730.121] 02187.02879> acpi: failed to create NHLT VMO (res -10)
[1730.121] 02187.02879> acpi: failed to publish NHLT metadata
[1730.123] 03365.03386> ahci: using MSI interrupt
[1730.126] 03206.03261> initialized intel serialio i2c driver, reg=0x2f24c7802000 regsize=4096
[1730.128] 03484.03530> [IHDA DSP 00:1f.3] Failed to fetch NHLT (res -25)
[1730.128] 03484.03530> [IHDA Controller 00:1f.3] Failed to initialize DSP device (res = -25)
[1730.133] 03028.04028> * found USB device (0x18d1:0xa002, USB 2.0) config 1
[1730.133] 03028.04028> * found USB device (0x18d1:0xa003, USB 3.0) config 1
[1730.201] 01623.01642> netifc: ? /dev/class/ethernet/000
[1730.201] 01623.01642> netifc: create 512 eth buffers
[1730.201] 01623.01642> macaddr: d4:5d:df:1a:32:35
[1730.201] 01623.01642> ip6addr: fe80::d65d:df4d:fe1a:3235
[1730.201] 01623.01642> snmaddr: ff02::1:ff1a:3235
[1730.201] 01623.01642> netsvc: using /dev/class/ethernet/000
[1730.201] 01623.01642> netsvc: nodename='ocean-bats-sky-poppy'
[1730.201] 01623.01642> netsvc: start
[1730.228] 01706.01768> vc: new display device /dev/class/display-controller/000
[1730.268] 02975.04243> i915: MST not supported
[1730.768] 02975.04243> i915: Found DP monitor
[1730.768] 02975.04243> i915: Display 1 connected
[1731.327] 01706.01768> vc: Successfully attached to display 1
[1731.595] 03028.04028> * found USB device (0x0781:0x5571, USB 2.0) config 1
[1731.846] 03028.04028> * found USB device (0x8087:0x0a2b, USB 2.0) config 1
[1732.128] 03100.03155> intel-i2c-controller: intel_serialio_i2c_slave_transfer: -21
[1732.128] 03100.03155> i2c-hid: could not read HID descriptor: 0
[1732.128] 03100.03155> devhost[00:15.0/i2c-bus-9d60/0020] bind driver '/boot/driver/i2c-hid.so' failed: -2
[1732.128] 01115.01130> devcoordinator: rpc: bind-driver '0020' status -2
[1732.129] 03206.03261> intel-i2c-controller: intel_serialio_i2c_slave_transfer: -21
[1732.129] 03206.03261> i2c-hid: could not read HID descriptor: 0
[1732.129] 03206.03261> devhost[00:15.1/i2c-bus-9d61/004c] bind driver '/boot/driver/i2c-hid.so' failed: -2
[1732.129] 01115.01130> devcoordinator: rpc: bind-driver '004c' status -2
[1732.140] 03365.03875> sata2: dev info
[1732.140] 03365.03875> serial=711430951002 0
[1732.140] 03365.03875> firmware rev=1Q01A7 0
[1732.140] 03365.03875> model id=IBIW NSS D
[1732.140] 03365.03875> major=0x3f0 ACS2 DMA 32 commands
[1732.140] 03365.03875> LBA48 234441648 sectors, sector size=512
[1732.141] 01299.01313> fshost: /dev/class/block/000: GPT?
[1732.141] 03365.03386> gpt: device_get_metadata failed (-25)
[1732.142] 01299.01313> fshost: /dev/class/block/001: FVM?
[1732.146] 01299.01313> devcoordinator: launch /boot/bin/blobfs (blobfs:/blob) OK
[1732.294] 01299.01313> fshost: starting 'bin/pkgsvr' '354b580fbdfd8806954c0148d27c3c0fce2c4f95f7f24bbe59812c6d86a4b8da'...
[1732.301] 01299.01313> devcoordinator: launch bin/pkgsvr (pkgfs) OK
[1732.312] 04653.04864> pkgsvr: system: will be served from 354b580fbdfd8806954c0148d27c3c0fce2c4f95f7f24bbe59812c6d86a4b8da
[1732.312] 04653.04864> pkgsvr: pkgfs serving index /data/pkgfs_index from blobfs /blob
[1732.312] 01299.01313> fshost: /dev/class/block/005: zxcrypt?
[1732.313] 03365.03386> devhost_get_handles(0x517291bdac10:block) open path='zxcrypt', r=-2
[1732.317] 01299.01313> fshost: mounting minfs
[1732.317] 01299.01313> devcoordinator: launch /boot/bin/minfs (minfs:/data) OK
[1732.339] 01115.04908> devcoordinator: adding system driver 'bt_hog' '/system/driver/bt-hog.so'
[1732.345] 01115.04908> devcoordinator: adding system driver 'iwlwifi_pci' '/system/driver/iwlwifi.so'
[1732.348] 01115.01778> devcoordinator: launch /system/bin/appmgr (appmgr) OK
[1732.348] 01115.01778> autorun: starting '/boot/bin/sh' '/boot/infra/runcmds'...
[1732.354] 01115.04908> devcoordinator: adding system driver 'virtual_camera' '/system/driver/virtual_camera_driver.so'
[1732.355] 01115.01778> devcoordinator: launch /boot/bin/sh (autorun:system) OK
[1732.375] 01115.04908> devcoordinator: adding system driver 'bt_host' '/system/driver/bt-host.so'
[1732.378] 01115.04908> devcoordinator: adding system driver 'bt_hci_passthrough' '/system/driver/bt-hci-passthrough.so'
[1732.399] 01115.04908> devcoordinator: adding system driver 'ralink' '/system/driver/ralink.so'
[1732.407] 01115.04908> devcoordinator: adding system driver 'wlan' '/system/driver/wlanphy.so'
[1732.409] 01115.04908> devcoordinator: adding system driver 'qmi_fake' '/system/driver/qmi-fake.so'
[1732.414] 01115.04908> devcoordinator: adding system driver 'usb_video' '/system/driver/usb_video.so'
[1732.418] 01115.04908> devcoordinator: adding system driver 'wlan' '/system/driver/wlanif.so'
[1732.422] 01115.04908> devcoordinator: adding system driver 'gpu' '/system/driver/libmsd_intel.so'
[1732.431] 01115.04908> devcoordinator: adding system driver 'mt8167s_gpu' '/system/driver/libmsd_img_rgx_mtk.so'
[1732.453] 01115.04908> devcoordinator: adding system driver 'wlan' '/system/driver/wlan.so'
[1732.458] 01115.04908> devcoordinator: adding system driver 'brcmfmac' '/system/driver/brcmfmac.so'
[1732.462] 01115.04908> devcoordinator: adding system driver 'bt_hci_intel' '/system/driver/bt-hci-intel.so'
[1732.467] 01115.04908> devcoordinator: adding system driver 'rtl88xx' '/system/driver/rtl88xx.so'
[1732.470] 01115.04908> devcoordinator: adding system driver 'ath10k_pci' '/system/driver/ath10k.so'
[1732.475] 01115.04908> devcoordinator: adding system driver 'bt_hci_atheros' '/system/driver/bt-hci-atheros.so'
[1732.479] 05193.05209> [INFO:namespace_builder.cc(93)] config-data for sysmgr
[1732.485] 01115.04908> devcoordinator: adding system driver 'bt_hci_fake' '/system/driver/bt-hci-fake.so'
[1732.491] 01115.04908> devcoordinator: adding system driver 'magma_pdev_gpu' '/system/driver/libmsd_arm.so'
[1732.495] 01115.04908> devcoordinator: adding system driver 'qmi_usb' '/system/driver/qmi-transport.so'
[1732.500] 01115.04908> devcoordinator: adding system driver 'virtual_audio' '/system/driver/virtual_audio_driver.so'
[1732.501] 01115.01130> devcoordinator: driver 'qmi_usb' added
[1732.501] 01115.01130> devcoordinator: driver 'magma_pdev_gpu' added
[1732.501] 01115.01130> devcoordinator: driver 'bt_hci_fake' added
[1732.501] 01115.01130> devcoordinator: driver 'bt_hci_atheros' added
[1732.501] 01115.01130> devcoordinator: driver 'ath10k_pci' added
[1732.501] 01115.01130> devcoordinator: driver 'rtl88xx' added
[1732.501] 01115.01130> devcoordinator: driver 'bt_hci_intel' added
[1732.501] 01115.01130> devcoordinator: driver 'brcmfmac' added
[1732.501] 01115.01130> devcoordinator: driver 'wlan' added
[1732.501] 01115.01130> devcoordinator: driver 'mt8167s_gpu' added
[1732.501] 01115.01130> devcoordinator: driver 'gpu' added
[1732.501] 01115.01130> devcoordinator: driver 'wlan' added
[1732.501] 01115.01130> devcoordinator: driver 'usb_video' added
[1732.501] 01115.01130> devcoordinator: driver 'qmi_fake' added
[1732.501] 01115.01130> devcoordinator: driver 'wlan' added
[1732.501] 01115.01130> devcoordinator: driver 'ralink' added
[1732.501] 01115.01130> devcoordinator: driver 'bt_host' added
[1732.501] 01115.01130> devcoordinator: driver 'iwlwifi_pci' added
[1732.501] 01115.01130> devcoordinator: driver 'bt_hog' added
[1732.501] 01115.01130> devcoordinator: driver 'bt_hci_passthrough' added
[1732.501] 01115.01130> devcoordinator: fallback driver 'usb_composite' is available
[1732.501] 01115.01130> devcoordinator: driver 'usb_composite' added
[1732.502] 01115.01130> devcoordinator: fallback driver 'intel_disp' is available
[1732.502] 01115.01130> devcoordinator: driver 'intel_disp' added
[1732.505] 03028.03051> UMS: parent: 'ifc-000'
[1732.505] 03028.03051> UMS:Max lun is: 0
[1732.505] 03028.03051> devhost[00:14.0/xhci/usb-bus/002/002/ifc-001] bind driver '/boot/driver/bt-transport-usb.so' failed: -2
[1732.507] 03028.06122> UMS: block size is: 0x00000200
[1732.507] 03028.06122> UMS: total blocks is: 15630336
[1732.507] 03028.06122> UMS: total size is: 8002732032
[1732.507] 03028.06122> UMS: read-only: 0 removable: 1
[1732.508] 01115.01130> devcoordinator: rpc: bind-driver 'ifc-001' status -2
[1732.537] 03028.06324> btintel: firmware already loaded
[1732.537] 03028.06334> hci_read_thread: failed to read from command channel ZX_ERR_PEER_CLOSED
[1732.537] 03028.06334> hci_read_thread: failed to read from ACL channel ZX_ERR_PEER_CLOSED
[1732.537] 03028.06334> bt-transport-usb: all channels closed - exiting
[1732.538] 03028.06773> [INFO:command_channel.cc(149)] hci: initialized
[1732.539] 01299.01313> fshost: /dev/class/block/007: MBR?
[1732.542] 01299.01313> fshost: /dev/class/block/009: MBR?
[1732.559] 03028.06773> [INFO:acl_data_channel.cc(91)] hci: initialized
[1732.562] 05193.05209> [INFO:namespace_builder.cc(93)] config-data for amber
[1732.621] 05193.05209> [INFO:namespace_builder.cc(93)] config-data for pkg_resolver
[1732.683] 08118.08130> [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
[1732.683] 08118.08130> kfill_days=2, start_event_aggregator_worker=1.
[1732.707] 05193.05209> [INFO:namespace_builder.cc(93)] config-data for mdns
[1732.721] 05193.05209> [INFO:namespace_builder.cc(93)] config-data for wlancfg
[1732.852] 05193.05209> [INFO:namespace_builder.cc(93)] config-data for crashpad_agent
[1732.893] 11408.11420> [INFO:main.cc(35)] Trace Manager starting with config: /pkg/data/tracing.config
[1732.906] 09957.09972> [INFO:system_metrics_main.cc(23)] Cobalt SystemMetricsDaemon: System metrics daemon created.
[1732.917] 03028.06773> [WARN:bredr_discovery_manager.cc(482)] gap-bredr: write inquiry scan activity failed: [status: invalid HCI command parameters (HCI 0x12)]
[1732.958] 12032.12044> wlanstack2 [I]: Starting
[1733.046] 05193.05209> [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
[1733.046] 05193.05209> is not present in the component's sandbox.
[1733.046] 05193.05209> Refer to
https://fuchsia.googlesource.com/fuchsia/+/master/docs/the-book/sandboxing.md#services for more information.
[1733.053] 10859.10873> [INFO:benchmarks.cc(24)] Graphics performance tests disabled
[1733.053] 10859.10873> [INFO:benchmarking.cc(173)] writing summary.json to /tmp/infra-test-output/summary.json
[1733.920] 08670.08682> Starting mDNS on interface ethp001f6 192.168.42.108
[1733.920] 08670.08682> [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
[1733.920] 08670.08682> Starting mDNS on interface ethp001f6 [80fe::5dd6:ffdf:1afe:3532]
[1733.920] 08670.08682> [WARNING:garnet/bin/mdns/service/mdns_interface_transceiver_v6.cc(29)] NET-291 IPV6_MULTICAST_LOOP not supported (ENOPROTOOPT), continuing anyway
[1733.920] 08670.08682> [WARNING:garnet/bin/mdns/service/mdns_interface_transceiver_v6.cc(50)] NET-2180 IPV6_JOIN_GROUP returned ENODEV, mDNS will not communicate via IPV6
[1733.920] 08670.08682> mDNS: Verifying uniqueness of host name ocean-bats-sky-poppy.local.
[1734.830] 08670.08682> mDNS: Using unique host name ocean-bats-sky-poppy.local.
DEBUG: reading "summary.json"
DEBUG: copying test output
DEBUG: tarring test output...