Back to build
Raw log | Switch to full mode | Login

2 files remaining... DEBUG: config flag: /etc/botanist/config.json 2019/04/20 00:23:25 attempting to send <<netboot>>cmdline... DEBUG: executing command: "/etc/connectivity/host_cmds.sh" environment of subprocess: [] 2019/04/20 00:23:25 attempting to send <<netboot>>cmdline... 2019/04/20 00:23:25 done 2019/04/20 00:23:25 attempting to send <<image>>sparse.fvm... 2019/04/20 00:23:25 done 2019/04/20 00:23:25 attempting to send <<image>>sparse.fvm... [00000.000] 00000.00000> zbi: @ 0xffffff80012f2000 (17482848 bytes) [00000.000] 00000.00000> UART: FIFO depth 16 [00000.000] 00000.00000> PMM: boot reserve add [0x100000, 0x2c5fff] [00000.000] 00000.00000> PMM: boot reserve add [0x12f2000, 0x239efff] [00000.000] 00000.00000> PMM: arena too small to be useful (size 4096) [00000.000] 00000.00000> PMM: pmm_add_arena failed to initialize arena [00000.000] 00000.00000> MEM: Failed to add pmm range at 0x7ffff000 size 0x1000 [00000.000] 00000.00000> PMM: boot reserve marking WIRED [0x100000, 0x2c5fff] [00000.000] 00000.00000> PMM: boot reserve marking WIRED [0x12f2000, 0x239efff] [00000.000] 00000.00000> [00000.000] 00000.00000> welcome to Zircon [00000.000] 00000.00000> [00000.000] 00000.00000> KASLR: .text section at 0xffffffff00100000 [00000.000] 00000.00000> INIT: cpu 0, calling hook 0xffffffff001aa428 (global_prng_seed) at level 0x30000, flags 0x1 [00000.000] 00000.00000> initializing vm pre-heap [00000.000] 00000.00000> VM: marking boot alloc used range [0x239f000, 0x239f100) [00000.000] 00000.00000> INIT: cpu 0, calling hook 0xffffffff00147abc (elf_build_id) at level 0x4fffe, flags 0x1 [00000.000] 00000.00000> INIT: cpu 0, calling hook 0xffffffff00147c48 (version) at level 0x4ffff, flags 0x1 [00000.000] 00000.00000> version: [00000.000] 00000.00000> arch: x86 [00000.000] 00000.00000> platform: pc [00000.000] 00000.00000> target: pc [00000.000] 00000.00000> project: x64 [00000.000] 00000.00000> buildid: git-13ee3dc5e4c46bf127977ad28645c47442ec517d [00000.000] 00000.00000> ELF build ID: 5f3e39bd4ed89d3b8122947842f1eac846a04683 [00000.000] 00000.00000> initializing heap [00000.000] 00000.00000> INIT: cpu 0, calling hook 0xffffffff00102e1c (x86_resource_init) at level 0x50000, flags 0x1 [00000.000] 00000.00000> INIT: cpu 0, calling hook 0xffffffff001a9630 (console) at level 0x50000, flags 0x1 [00000.000] 00000.00000> initializing vm [00000.000] 00000.00000> VM: reserving kernel region [0xffffffff00100000, 0xffffffff001ee000) flags 0x28 name 'kernel_code' [00000.000] 00000.00000> VM: reserving kernel region [0xffffffff001ee000, 0xffffffff00232000) flags 0x8 name 'kernel_rodata' [00000.000] 00000.00000> VM: reserving kernel region [0xffffffff00232000, 0xffffffff00242000) flags 0x18 name 'kernel_data' [00000.000] 00000.00000> VM: reserving kernel region [0xffffffff00242000, 0xffffffff002c6000) flags 0x18 name 'kernel_bss' [00000.000] 00000.00000> INIT: cpu 0, calling hook 0xffffffff00103ae0 (display_memtype) at level 0x60001, flags 0x1 [00000.000] 00000.00000> INIT: cpu 0, calling hook 0xffffffff00138fa0 (acpi_tables) at level 0x60001, flags 0x1 [00000.000] 00000.00000> INIT: cpu 0, calling hook 0xffffffff00101c40 (hpet) at level 0x60002, flags 0x1 [00000.000] 00000.00000> INIT: cpu 0, calling hook 0xffffffff00102000 (apic) at level 0x60002, flags 0x1 [00000.000] 00000.00000> x2APIC enabled [00000.000] 00000.00000> INIT: cpu 0, calling hook 0xffffffff001061b4 (timer) at level 0x60003, flags 0x1 [00000.000] 00000.00000> HPET frequency: 23999 ticks/ms [00000.000] 00000.00000> TSC frequency: 2712000 ticks/ms [00030.455] 00000.00000> timer features: constant_tsc 1 invariant_tsc 1 tsc_deadline 1 [00030.455] 00000.00000> Using TSC as wallclock [00030.455] 00000.00000> initializing kernel [00030.455] 00000.00000> initializing mp [00030.455] 00000.00000> initializing timers [00030.455] 00000.00000> INIT: cpu 0, calling hook 0xffffffff0013c578 (debuglog) at level 0x7ffff, flags 0x1 [00030.455] 00000.00000> INIT: cpu 0, calling hook 0xffffffff00195518 (thread_set_priority_experiment) at level 0x7ffff, flags 0x1 [00030.455] 00000.00000> thread set priority experiment is : ENABLED [00030.455] 00000.00000> INIT: cpu 0, calling hook 0xffffffff001aa67c (global_prng_thread_safe) at level 0x7ffff, flags 0x1 [00030.455] 00000.00000> creating bootstrap completion thread [00030.797] 00000.00000> top of bootstrap2() [00030.797] 00000.00000> INIT: cpu 0, calling hook 0xffffffff0013151c (dpc) at level 0x80000, flags 0x1 [00030.810] 00000.00000> INIT: cpu 0, calling hook 0xffffffff00152978 (libobject) at level 0x80000, flags 0x1 [00030.810] 00000.00000> OOM: started thread [00030.823] 00000.00000> Processor Model Info: type 0 family 0x6 model 0xe stepping 0x9 [00030.823] 00000.00000> display_family 0x6 display_model 0x8e [00030.823] 00000.00000> Vendor: Intel [00030.823] 00000.00000> Microarch: Kaby Lake [00030.823] 00000.00000> F/M/S: 6/8e/9 [00030.823] 00000.00000> Brand: Intel(R) Core(TM) i5-7300U CPU @ 2.60GHz [00030.823] 00000.00000> Features: fpu sse sse2 sse3 ssse3 sse4.1 sse4.2 mmx avx avx2 fxsr pcid xsave mon aesni clflush [00030.823] 00000.00000> clflushopt fsgsbase tsc_adj smep smap erms rdrand rdseed syscall nx huge rdtscp [00030.823] 00000.00000> invar_tsc tsc_deadline x2apic vmx pt hwp [00030.823] 00000.00000> initializing platform [00030.823] 00000.00000> INIT: cpu 0, calling hook 0xffffffff001101f4 (x86_perfmon) at level 0x90000, flags 0x1 [00030.823] 00000.00000> PMU: version 4 [00030.823] 00000.00000> UART: started IRQ driven RX [00030.823] 00000.00000> UART: started IRQ driven TX [00030.823] 00000.00000> cpu topology: [00030.823] 00000.00000> 0: apic id 0x0 package 0 node 0 core 0 smt 0 BSP [00030.823] 00000.00000> 1: apic id 0x2 package 0 node 0 core 1 smt 0 [00030.823] 00000.00000> 2: apic id 0x1 package 0 node 0 core 0 smt 1 [00030.823] 00000.00000> 3: apic id 0x3 package 0 node 0 core 1 smt 1 [00030.823] 00000.00000> Found 4 cpus [00030.823] 00000.00000> booting apic ids: 0x2 0x1 0x3 [00030.839] 00000.00000> entering scheduler on cpu 2 [00030.840] 00000.00000> entering scheduler on cpu 1 [00030.840] 00000.00000> entering scheduler on cpu 3 [00030.843] 00000.00000> smbios: manufacturer="Intel Corporation" product="NUC7i5DNHE" [00030.843] 00000.00000> initializing target [00030.843] 00000.00000> INIT: cpu 0, calling hook 0xffffffff001053a0 (x86_pcie_init) at level 0xa0000, flags 0x1 [00030.843] 00000.00000> moving to last init level [00030.843] 00000.00000> INIT: cpu 0, calling hook 0xffffffff00144140 (ktrace) at level 0xc0000, flags 0x1 [00030.846] 00000.00000> ktrace: buffer at 0xffffff9d91365000 (33554432 bytes) [00030.846] 00000.00000> INIT: cpu 0, calling hook 0xffffffff00147ab4 (userboot) at level 0xc0000, flags 0x1 [00030.846] 00000.00000> userboot: ramdisk 0x10ad000 @ 0xffffff80012f2000 [00030.847] 00000.00000> userboot: userboot rodata 0 @ [0x72cf20bbc000,0x72cf20bbf000) [00030.847] 00000.00000> userboot: userboot code 0x3000 @ [0x72cf20bbf000,0x72cf20bca000) [00030.847] 00000.00000> userboot: vdso/full rodata 0 @ [0x72cf20bca000,0x72cf20bd1000) [00030.847] 00000.00000> userboot: vdso/full code 0x7000 @ [0x72cf20bd1000,0x72cf20bd2000) [00030.847] 00000.00000> userboot: entry point @ 0x72cf20bbfc10 [00030.847] 00000.00000> INIT: cpu 0, calling hook 0xffffffff001aa030 (kernel_shell) at level 0xc0000, flags 0x1 [00030.847] 01036.01043> userboot: option "netsvc.disable=true" [00030.847] 01036.01043> userboot: option "zircon.system.disable-automount=true" [00030.847] 01036.01043> userboot: option "zircon.autorun.boot=/boot/infra/setup" [00030.847] 01036.01043> userboot: option "kernel.serial=legacy" [00030.847] 01036.01043> userboot: option "http://192.168.42.1/multiboot/d4%3A5d%3Adf%3A1a%3A42%3A86=" [00030.847] 01036.01043> userboot: option "multiboot.boot_loader_name=iPXE+1.0.0++(d2063)" [00030.886] 01036.01043> userboot: searching bootfs for 'bin/bootsvc' [00030.886] 01036.01043> userboot: 'bin/bootsvc' has PT_INTERP "lib/ld.so.1" [00030.886] 01036.01043> userboot: searching bootfs for 'lib/ld.so.1' [00030.886] 01036.01043> userboot: userboot: loaded lib/ld.so.1 at 0x4bc6514ef000, entry point 0x4bc6515750d3 [00030.886] 01036.01043> userboot: userboot: loaded vDSO at 0x7f7ad0e77000, entry point 0x0 [00030.886] 01036.01043> userboot: process bin/bootsvc started. [00030.886] 01036.01043> userboot: waiting for loader-service requests... [00030.886] 01036.01043> userboot: searching bootfs for 'lib/libasync-default.so' [00030.886] 01036.01043> userboot: searching bootfs for 'lib/libfdio.so' [00030.886] 01036.01043> userboot: searching bootfs for 'lib/liblaunchpad.so' [00030.886] 01036.01043> userboot: searching bootfs for 'lib/libtrace-engine.so' [00030.886] 01050.01053> {{{reset}}} [00030.886] 01050.01053> {{{module:0:<application>:elf:18de7d58f51e8ba5c4f6afdd0cc8440f482c2b45}}} [00030.886] 01050.01053> {{{mmap:0x4dabbf80e000:0x2e000:load:0:rx:0}}} [00030.886] 01050.01053> {{{mmap:0x4dabbf83c000:0x4000:load:0:rw:0x2e000}}} [00030.886] 01050.01053> dso: id=18de7d58f51e8ba5c4f6afdd0cc8440f482c2b45 base=0x00004dabbf80e000 name=<application> [00030.886] 01050.01053> {{{module:0x3:libasync-default.so:elf:c189f51f19d10785d93b5235ad1b46dca4451b00}}} [00030.886] 01050.01053> {{{mmap:0x1ce20ce58000:0x1000:load:0x3:rx:0}}} [00030.886] 01050.01053> {{{mmap:0x1ce20ce59000:0x1000:load:0x3:rw:0x1000}}} [00030.886] 01050.01053> dso: id=c189f51f19d10785d93b5235ad1b46dca4451b00 base=0x00001ce20ce58000 name=libasync-default.so [00030.886] 01050.01053> {{{module:0x2:<vDSO>:elf:40ab5fa3b61f12fef4a44477a687f608661cd450}}} [00030.886] 01050.01053> {{{mmap:0x7f7ad0e77000:0x7000:load:0x2:r:0}}} [00030.886] 01050.01053> {{{mmap:0x7f7ad0e7e000:0x1000:load:0x2:rx:0x7000}}} [00030.886] 01050.01053> dso: id=40ab5fa3b61f12fef4a44477a687f608661cd450 base=0x00007f7ad0e77000 name=<vDSO> [00030.886] 01050.01053> {{{module:0x1:libc.so:elf:67a12284bce140fc32aaaeac223e0e8f85cb5085}}} [00030.886] 01050.01053> {{{mmap:0x4bc6514ef000:0xcb000:load:0x1:rx:0}}} [00030.886] 01050.01053> {{{mmap:0x4bc6515bb000:0x6000:load:0x1:rw:0xcc000}}} [00030.886] 01050.01053> dso: id=67a12284bce140fc32aaaeac223e0e8f85cb5085 base=0x00004bc6514ef000 name=libc.so [00030.886] 01050.01053> {{{module:0x4:libfdio.so:elf:27787977e95f3b9563c9e0bd4d34ec92b7e9ad88}}} [00030.886] 01050.01053> {{{mmap:0x32ae284a2000:0x24000:load:0x4:rx:0}}} [00030.886] 01050.01053> {{{mmap:0x32ae284c7000:0x4000:load:0x4:rw:0x25000}}} [00030.886] 01050.01053> dso: id=27787977e95f3b9563c9e0bd4d34ec92b7e9ad88 base=0x000032ae284a2000 name=libfdio.so [00030.886] 01050.01053> {{{module:0x5:liblaunchpad.so:elf:6fc2232dc8c1bc5c6adb8ad50ca794b5a260ee4f}}} [00030.886] 01050.01053> {{{mmap:0x5dafb49bd000:0x7000:load:0x5:rx:0}}} [00030.886] 01050.01053> {{{mmap:0x5dafb49c4000:0x2000:load:0x5:rw:0x7000}}} [00030.886] 01050.01053> dso: id=6fc2232dc8c1bc5c6adb8ad50ca794b5a260ee4f base=0x00005dafb49bd000 name=liblaunchpad.so [00030.886] 01050.01053> {{{module:0x6:libtrace-engine.so:elf:c9042b83fe01206008fcefb16395238417248169}}} [00030.886] 01050.01053> {{{mmap:0x628951412000:0x9000:load:0x6:rx:0}}} [00030.886] 01050.01053> {{{mmap:0x62895141b000:0x2000:load:0x6:rw:0x9000}}} [00030.886] 01050.01053> dso: id=c9042b83fe01206008fcefb16395238417248169 base=0x0000628951412000 name=libtrace-engine.so [00030.886] 01050.01053> bootsvc: Starting... [00030.886] 01036.01043> userboot: loader-service channel peer closed [00030.886] 01036.01043> userboot: finished! [00030.886] 01050.01053> bootsvc: Creating bootfs service... [00030.887] 01050.01053> bootsvc: Processing bootdata... [00030.887] 01050.01053> bootsvc: Loading boot cmdline overrides... [00030.887] 01050.01053> bootsvc: Loading kernel VMOs... [00030.887] 01050.01053> bootsvc: Creating loader service... [00030.887] 01050.01053> bootsvc: Launching next process... [00030.887] 01050.01096> bootsvc: launched bin/devmgr [00030.888] 01104.01117> devmgr: main() [00030.888] 01104.01117> cmdline: netsvc.disable=true [00030.888] 01104.01117> cmdline: zircon.system.disable-automount=true [00030.888] 01104.01117> cmdline: zircon.autorun.boot=/boot/infra/setup [00030.888] 01104.01117> cmdline: kernel.serial=legacy [00030.888] 01104.01117> cmdline: http://192.168.42.1/multiboot/d4%3A5d%3Adf%3A1a%3A42%3A86= [00030.888] 01104.01117> cmdline: multiboot.boot_loader_name=iPXE+1.0.0++(d2063) [00030.888] 01104.01117> devmgr: coordinator_init() [00030.888] 01104.01117> devmgr: init [00030.888] 01104.01117> devmgr: svc init [00030.888] 01104.01117> devmgr: launch /boot/bin/svchost (svchost) OK [00030.888] 01104.01117> devmgr: vfs init [00030.888] 01104.01117> devmgr: launch /boot/bin/fshost (fshost) OK [00030.888] 01104.01220> devmgr: shell startup [00030.889] 01182.01202> fshost: started. [00030.890] 01104.01212> devmgr: launch /boot/bin/pwrbtn-monitor (pwrbtn-monitor) OK [00030.891] 01104.01235> devmgr: launch /boot/bin/virtual-console (virtual-console) OK [00030.891] 01104.01235> zircon.autorun.boot: starting '/boot/infra/setup'... [00030.892] 01104.01235> devmgr: launch /boot/infra/setup (autorun:boot) OK [00030.894] 01104.01117> devcoord: launch devhost 'devhost:sys': pid=2049 [00030.894] 01104.01117> devcoord: launch devhost 'devhost:test': pid=2082 [00030.894] 01104.01117> devcoord: launch devhost 'devhost:root': pid=2115 [00030.895] 01104.01117> devcoord: launch devhost 'devhost:misc': pid=2170 [00030.896] 02049.02073> devhost: trace provider registry begun [00030.897] 02082.02106> devhost: trace provider registry begun [00030.898] 02115.02151> devhost: trace provider registry begun [00030.899] 02170.02209> devhost: trace provider registry begun [00030.907] 01104.01220> devmgr: launch /boot/bin/sh (sh:console) OK [00030.965] 02049.02073> acpi-bus: not using IOMMU [00030.970] 02049.02073> acpi-pwrbtn: initialized [00030.976] 02049.02073> WARNING: ACPI found bad _CRS address entry [00030.982] 02049.02073> WARNING: ACPI found bad _CRS address entry [00030.993] 02049.02073> acpi: published device pci(0x23f3100d4200), parent=proxy(0x23f3100d0540), handle=0x23f31010c750 [00030.994] 02049.02073> acpi: published device rtc(0x23f3100cf080), parent=acpi(0x23f3100d0780), handle=0x23f31012b330 [00030.995] 02049.02073> acpi-ec: initialized [00030.997] 02049.02073> acpi: failed to create NHLT VMO (res -10) [00030.997] 02049.02073> acpi: failed to publish NHLT metadata [00030.999] 02049.02073> [sysmem_init 28] async_get_default_dispatcher(): 0x23f3100c30a0 [00030.999] 02049.02073> [sysmem_bind 40] sysmem_bind() [00030.999] 02049.02073> acpi-bus: sysmem_register_protocol() intentionally ignored for now. [00031.000] 02049.02073> PMU: 7 arch events [00031.000] 02049.02073> PMU: arch event id range: 1-7 [00031.000] 02049.02073> PMU: 102 model events [00031.000] 02049.02073> PMU: model event id range: 1-241 [00031.000] 02049.02073> Intel Processor Trace configuration for this chipset: [00031.000] 02049.02073> mtc_freq_mask: 0x249 [00031.000] 02049.02073> cyc_thresh_mask: 0x3fff [00031.000] 02049.02073> psb_freq_mask: 0x3f [00031.000] 02049.02073> num addr ranges: 2 [00031.000] 01243.01564> vc: new input device /dev/class/input/000 [00031.001] 01104.01117> devcoord: launch devhost 'devhost:pci#1:8086:5916': pid=3033 [00031.001] 01104.01117> devcoord: launch devhost 'devhost:pci#3:8086:9d2f': pid=3087 [00031.002] 01104.01117> devcoord: launch devhost 'devhost:pci#5:8086:9d60': pid=3160 [00031.002] 03033.03062> devhost: trace provider registry begun [00031.002] 01104.01117> devcoord: launch devhost 'devhost:pci#6:8086:9d61': pid=3236 [00031.003] 03087.03139> devhost: trace provider registry begun [00031.003] 01104.01117> devcoord: launch devhost 'devhost:pci#9:8086:9d03': pid=3327 [00031.003] 03160.03205> devhost: trace provider registry begun [00031.003] 01104.01117> devcoord: launch devhost 'devhost:pci#14:8086:9d71': pid=3447 [00031.004] 03236.03275> devhost: trace provider registry begun [00031.004] 01104.01117> devcoord: launch devhost 'devhost:pci#16:8086:156f': pid=3515 [00031.005] 03327.03384> devhost: trace provider registry begun [00031.006] 03160.03205> initialized intel serialio i2c driver, reg=0x249038050000 regsize=4096 [00031.007] 03236.03275> initialized intel serialio i2c driver, reg=0x121292ec9000 regsize=4096 [00031.008] 03327.03384> ahci: using MSI interrupt [00031.009] 03515.03571> devhost: trace provider registry begun [00031.009] 03447.03493> devhost: trace provider registry begun [00031.010] 03087.03847> * found USB device (0x18d1:0xa002, USB 2.0) config 1 [00031.010] 03087.03847> * found USB device (0x18d1:0xa003, USB 3.0) config 1 [00031.012] 03447.03493> [IHDA DSP 00:1f.3] Failed to fetch NHLT (res -25) [00031.012] 03447.03493> devhost[00:1f.3/intel-hda-000/intel-sst-dsp-000] bind driver '/boot/driver/dsp.so' failed: -25 [00031.012] 01104.01117> devcoord: rpc: bind-driver 'intel-sst-dsp-000' status -25 [00031.111] 01243.01564> vc: new display device /dev/class/display-controller/000/virtcon [00031.252] 03033.04139> i915: MST not supported [00031.724] 03087.03847> * found USB device (0x0781:0x5583, USB 3.0) config 1 [00031.724] 03087.03139> UMS: parent: 'ifc-000' [00031.724] 03087.03139> UMS:Max lun is: 0 [00031.756] 03033.04139> i915: MST not supported [00032.474] 03087.03847> * found USB device (0x0cf3:0xe300, USB 2.1) config 1 [00032.476] 03087.03139> devhost[00:14.0/xhci/usb-bus/002/002/ifc-001] bind driver '/boot/driver/bt-transport-usb.so' failed: -2 [00032.476] 01104.01117> devcoord: rpc: bind-driver 'ifc-001' status -2 [00032.727] 03087.04226> UMS: block size is: 0x00000200 [00032.727] 03087.04226> UMS: total blocks is: 30031250 [00032.727] 03087.04226> UMS: total size is: 15376000000 [00032.727] 03087.04226> UMS: read-only: 0 removable: 1 [00032.728] 01182.01202> devmgr: /dev/class/block/000: MBR? [00032.728] 01104.01117> devcoord: dc_bind_device() '/boot/driver/mbr.so' [00032.731] 01182.01202> devmgr: /dev/class/block/002: MBR? [00032.731] 01104.01117> devcoord: dc_bind_device() '/boot/driver/mbr.so' [00032.803] 03033.04139> i915: No displays detected [00033.008] 03236.03275> intel-i2c-controller: intel_serialio_i2c_slave_transfer: -21 [00033.008] 03236.03275> i2c-hid: could not read HID descriptor: 0 [00033.008] 03236.03275> devhost[00:15.1/i2c-bus-9d61/004c] bind driver '/boot/driver/i2c-hid.so' failed: -2 [00033.008] 01104.01117> devcoord: rpc: bind-driver '004c' status -2 [00033.009] 03160.03205> intel-i2c-controller: intel_serialio_i2c_slave_transfer: -21 [00033.009] 03160.03205> i2c-hid: could not read HID descriptor: 0 [00033.009] 03160.03205> devhost[00:15.0/i2c-bus-9d60/0020] bind driver '/boot/driver/i2c-hid.so' failed: -2 [00033.009] 01104.01117> devcoord: rpc: bind-driver '0020' status -2 [00033.023] 03327.03764> sata2: dev info [00033.023] 03327.03764> serial=711430953015 6 [00033.023] 03327.03764> firmware rev=1Q01A7 0 [00033.023] 03327.03764> model id=IBIW NSS D [00033.023] 03327.03764> major=0x3f0 ACS2 DMA 32 commands [00033.023] 03327.03764> LBA48 234441648 sectors, sector size=512 [00033.025] 04480.04494> paver:[InitializeGpt] Located GPT is invalid; Attempting to initialize [00033.026] 01104.01117> devcoord: dc_bind_device() '/boot/driver/gpt.so' [00033.026] 03327.03384> gpt: device_get_metadata failed (-25) [00033.027] 04480.04494> paver:[Initialize] Successfully initialized EFI Device Partitioner [00033.027] 01104.01117> devcoord: dc_bind_device() '' [00033.027] 01182.01202> devmgr: /dev/class/block/003: GPT? [00033.027] 01104.01117> devcoord: dc_bind_device() '/boot/driver/gpt.so' [00033.027] 03327.03384> gpt: device_get_metadata failed (-25) [00033.030] 04642.04662> 34+0 records in [00033.030] 04642.04662> 34+0 records out [00033.030] 04642.04662> 17408 bytes copied [00033.031] 04753.04767> Failed to seek on output [00033.031] 04753.04767> 0+0 records in [00033.031] 04753.04767> 0+0 records out [00033.031] 04753.04767> 0 bytes copied [00033.032] 04823.04837> netifc: ? /dev/class/ethernet/000 [00033.032] 04823.04837> netifc: create 512 eth buffers [00033.032] 04823.04837> macaddr: d4:5d:df:1a:42:86 [00033.032] 04823.04837> ip6addr: fe80::d65d:df4d:fe1a:4286 [00033.032] 04823.04837> snmaddr: ff02::1:ff1a:4286 [00033.032] 04823.04837> netsvc: using /dev/class/ethernet/000 [00033.032] 04823.04837> _ _ _ [00033.032] 04823.04837> | | | | | [00033.032] 04823.04837> _______ __| | |__ ___ ___ | |_ [00033.032] 04823.04837> |_ / _ \/ _` | '_ \ / _ \ / _ \| __| [00033.032] 04823.04837> / / __/ (_| | |_) | (_) | (_) | |_ [00033.032] 04823.04837> /___\___|\__,_|_.__/ \___/ \___/ \__| [00033.032] 04823.04837> [00033.032] 04823.04837> [00033.032] 04823.04837> zedboot: version: 0.7.13 [00033.032] 04823.04837> [00033.032] 04823.04837> netsvc: nodename='ocean-drank-wick-plug' [00033.032] 04823.04837> netsvc: will not advertise [00033.032] 04823.04837> netsvc: start [00755.601] 04823.04837> netsvc: tftp write of file <<netboot>>cmdline completed [00755.601] 04823.04837> netsvc: metrics: {"inorderblks": 1,"oooblks": 0,"ack": 1,"nack": 0,"timeouts": 0,"sas": 0,"inorderbytes": 55} [00755.601] 04823.04837> netsvc: Running FVM Paver [00755.603] 04823.04931> paver:[InitializeGpt] Located GPT is invalid; Attempting to initialize [00755.604] 01104.01117> devcoord: dc_bind_device() '' [00755.604] 01104.01117> devcoord: dc_bind_device() '/boot/driver/gpt.so' [00755.604] 03327.03384> gpt: device_get_metadata failed (-25) [00755.604] 01182.01202> devmgr: /dev/class/block/003: GPT? [00755.604] 01104.01117> devcoord: dc_bind_device() '/boot/driver/gpt.so' [00755.604] 03327.03384> devhost: rpc:bind-device failed: -20 [00755.605] 04823.04931> paver:[Initialize] Successfully initialized EFI Device Partitioner [00755.605] 04823.04931> paver:[PartitionPave] Paving partition. [00755.605] 04823.04931> paver:[FindFirstFit] Looking for space [00755.605] 04823.04931> paver:[FindFirstFit] Sorting [00755.605] 04823.04931> paver:[FindFirstFit] Partition[0] From Block [0, 34) ... (next partition starts at block 234441614) [00755.605] 04823.04931> paver:[FindFirstFit] There are 234441580 free blocks (16777216 requested) [00755.605] 04823.04931> paver:[AddPartition] Found space in GPT - OK 234441580 @ 34 [00755.605] 04823.04931> paver:[AddPartition] Final space in GPT - OK 16777216 @ 34 [00755.606] 04823.04931> paver:[AddPartition] Added partition, waiting for bind [00755.606] 01104.01117> devcoord: dc_bind_device() '' [00755.606] 01182.01202> devmgr: /dev/class/block/003: GPT? [00755.606] 01104.01117> devcoord: dc_bind_device() '/boot/driver/gpt.so' [00755.606] 03327.03384> gpt: device_get_metadata failed (-25) [00755.607] 04823.04931> paver:[AddPartition] Added partition, waiting for bind - OK [00755.607] 04823.04931> paver:[PartitionPave] Streaming partitions... [00755.607] 04911.04925> Found compressed file [00755.607] 04823.04931> paver:[FvmStreamPartitions] Header Validated - OK [00755.607] 04823.04931> paver:[FvmPartitionFormat] Initializing partition as FVM [00755.610] 01104.01117> devcoord: dc_bind_device() '/boot/driver/fvm.so' [00756.612] 04823.04931> paver:[FvmStreamPartitions] Partitions pre-validated successfully: Enough space exists to pave. [00756.612] 04823.04931> paver:[AllocatePartitions] Allocating partition blobfs consisting of 1 slices [00756.615] 04823.04931> paver:[AllocatePartitions] Allocating partition minfs consisting of 1 slices [00756.616] 04823.04931> paver:[AllocatePartitions] Creating zxcrypt volume [00756.618] 03327.03384> devhost_get_handles(0x20ca199979c0:block) open path='zxcrypt/block', r=-2 [00756.618] 01104.01117> devcoord: dc_bind_device() '/boot/driver/zxcrypt.so' [00756.618] 03327.03384> devhost_get_handles(0x20ca199979c0:block) open path='zxcrypt', r=-2 [00756.622] 04823.04931> paver:[FvmStreamPartitions] Partition space pre-allocated successfully. [00756.622] 04823.04931> paver:[FvmStreamPartitions] Streaming partition 0 [00756.622] 04823.04931> paver:[StreamFvmPartition] Writing extent 0... [00756.622] 04823.04937> netsvc: paver write progress 0.2% [00756.622] 04823.04931> paver:[StreamFvmPartition] 8192 bytes written, 8380416 zeroes left [00756.640] 04823.04931> paver:[StreamFvmPartition] Writing extent 1... [00756.640] 04823.04931> paver:[StreamFvmPartition] 8192 bytes written, 8380416 zeroes left [00756.661] 04823.04931> paver:[StreamFvmPartition] Writing extent 2... [00756.665] 04823.04931> paver:[StreamFvmPartition] 2097152 bytes written, 6291456 zeroes left [00756.678] 04823.04931> paver:[StreamFvmPartition] Writing extent 3... [00756.683] 04823.04931> paver:[StreamFvmPartition] 2097152 bytes written, 6291456 zeroes left [00756.699] 04823.04931> paver:[StreamFvmPartition] Writing extent 4... [00757.622] 04823.04937> netsvc: paver write progress 12.5% [00758.622] 04823.04937> netsvc: paver write progress 18.6% [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 [00021.407] 00000.00000> timer features: constant_tsc 1 invariant_tsc 1 tsc_deadline 1 [00021.407] 00000.00000> Using TSC as wallclock [00021.407] 00000.00000> initializing kernel [00021.407] 00000.00000> initializing mp [00021.407] 00000.00000> initializing timers [00021.407] 00000.00000> INIT: cpu 0, calling hook 0xffffffff0013c578 (debuglog) at level 0x7ffff, flags 0x1 [00021.407] 00000.00000> INIT: cpu 0, calling hook 0xffffffff00195518 (thread_set_priority_experiment) at level 0x7ffff, flags 0x1 [00021.407] 00000.00000> thread set priority experiment is : ENABLED [00021.407] 00000.00000> INIT: cpu 0, calling hook 0xffffffff001aa67c (global_prng_thread_safe) at level 0x7ffff, flags 0x1 [00021.407] 00000.00000> creating bootstrap completion thread [00021.750] 00000.00000> top of bootstrap2() [00021.750] 00000.00000> INIT: cpu 0, calling hook 0xffffffff0013151c (dpc) at level 0x80000, flags 0x1 [00021.763] 00000.00000> INIT: cpu 0, calling hook 0xffffffff00152978 (libobject) at level 0x80000, flags 0x1 [00021.763] 00000.00000> OOM: started thread [00021.777] 00000.00000> Processor Model Info: type 0 family 0x6 model 0xe stepping 0x9 [00021.777] 00000.00000> display_family 0x6 display_model 0x8e [00021.777] 00000.00000> Vendor: Intel [00021.777] 00000.00000> Microarch: Kaby Lake [00021.777] 00000.00000> F/M/S: 6/8e/9 [00021.777] 00000.00000> Brand: Intel(R) Core(TM) i5-7300U CPU @ 2.60GHz [00021.777] 00000.00000> Features: fpu sse sse2 sse3 ssse3 sse4.1 sse4.2 mmx avx avx2 fxsr pcid xsave mon aesni clflush [00021.777] 00000.00000> clflushopt fsgsbase tsc_adj smep smap erms rdrand rdseed syscall nx huge rdtscp [00021.777] 00000.00000> invar_tsc tsc_deadline x2apic vmx pt hwp [00021.777] 00000.00000> initializing platform [00021.777] 00000.00000> INIT: cpu 0, calling hook 0xffffffff001101f4 (x86_perfmon) at level 0x90000, flags 0x1 [00021.777] 00000.00000> PMU: version 4 [00021.777] 00000.00000> UART: started IRQ driven RX [00021.777] 00000.00000> UART: started IRQ driven TX [00021.777] 00000.00000> cpu topology: [00021.777] 00000.00000> 0: apic id 0x0 package 0 node 0 core 0 smt 0 BSP [00021.777] 00000.00000> 1: apic id 0x2 package 0 node 0 core 1 smt 0 [00021.777] 00000.00000> 2: apic id 0x1 package 0 node 0 core 0 smt 1 [00021.777] 00000.00000> 3: apic id 0x3 package 0 node 0 core 1 smt 1 [00021.777] 00000.00000> Found 4 cpus [00021.777] 00000.00000> booting apic ids: 0x2 0x1 0x3 [00021.792] 00000.00000> entering scheduler on cpu 2 [00021.793] 00000.00000> entering scheduler on cpu 3 [00021.793] 00000.00000> entering scheduler on cpu 1 [00021.796] 00000.00000> smbios: manufacturer="Intel Corporation" product="NUC7i5DNHE" [00021.796] 00000.00000> initializing target [00021.796] 00000.00000> INIT: cpu 0, calling hook 0xffffffff001053a0 (x86_pcie_init) at level 0xa0000, flags 0x1 [00021.796] 00000.00000> moving to last init level [00021.796] 00000.00000> INIT: cpu 0, calling hook 0xffffffff00144140 (ktrace) at level 0xc0000, flags 0x1 [00021.800] 00000.00000> ktrace: buffer at 0xffffff98b58e3000 (33554432 bytes) [00021.800] 00000.00000> INIT: cpu 0, calling hook 0xffffffff00147ab4 (userboot) at level 0xc0000, flags 0x1 [00021.800] 00000.00000> userboot: ramdisk 0x10ad000 @ 0xffffff80012f2000 [00021.800] 00000.00000> userboot: userboot rodata 0 @ [0x2605b387000,0x2605b38a000) [00021.800] 00000.00000> userboot: userboot code 0x3000 @ [0x2605b38a000,0x2605b395000) [00021.800] 00000.00000> userboot: vdso/full rodata 0 @ [0x2605b395000,0x2605b39c000) [00021.800] 00000.00000> userboot: vdso/full code 0x7000 @ [0x2605b39c000,0x2605b39d000) [00021.800] 00000.00000> userboot: entry point @ 0x2605b38ac10 [00021.800] 00000.00000> INIT: cpu 0, calling hook 0xffffffff001aa030 (kernel_shell) at level 0xc0000, flags 0x1 [00021.800] 01036.01043> userboot: option "netsvc.disable=true" [00021.800] 01036.01043> userboot: option "zircon.system.disable-automount=true" [00021.800] 01036.01043> userboot: option "zircon.autorun.boot=/boot/infra/setup" [00021.800] 01036.01043> userboot: option "kernel.serial=legacy" [00021.800] 01036.01043> userboot: option "http://192.168.42.1/multiboot/d4%3A5d%3Adf%3A1a%3A43%3A25=" [00021.800] 01036.01043> userboot: option "multiboot.boot_loader_name=iPXE+1.0.0++(d2063)" [00021.840] 01036.01043> userboot: searching bootfs for 'bin/bootsvc' [00021.840] 01036.01043> userboot: 'bin/bootsvc' has PT_INTERP "lib/ld.so.1" [00021.840] 01036.01043> userboot: searching bootfs for 'lib/ld.so.1' [00021.840] 01036.01043> userboot: userboot: loaded lib/ld.so.1 at 0x62f63d770000, entry point 0x62f63d7f60d3 [00021.840] 01036.01043> userboot: userboot: loaded vDSO at 0x548b2b419000, entry point 0x0 [00021.840] 01036.01043> userboot: process bin/bootsvc started. [00021.840] 01036.01043> userboot: waiting for loader-service requests... [00021.840] 01036.01043> userboot: searching bootfs for 'lib/libasync-default.so' [00021.840] 01036.01043> userboot: searching bootfs for 'lib/libfdio.so' [00021.840] 01036.01043> userboot: searching bootfs for 'lib/liblaunchpad.so' [00021.840] 01036.01043> userboot: searching bootfs for 'lib/libtrace-engine.so' [00021.840] 01050.01053> {{{reset}}} [00021.840] 01050.01053> {{{module:0:<application>:elf:18de7d58f51e8ba5c4f6afdd0cc8440f482c2b45}}} [00021.840] 01050.01053> {{{mmap:0x76e01c1ee000:0x2e000:load:0:rx:0}}} [00021.840] 01050.01053> {{{mmap:0x76e01c21c000:0x4000:load:0:rw:0x2e000}}} [00021.840] 01050.01053> dso: id=18de7d58f51e8ba5c4f6afdd0cc8440f482c2b45 base=0x000076e01c1ee000 name=<application> [00021.840] 01050.01053> {{{module:0x3:libasync-default.so:elf:c189f51f19d10785d93b5235ad1b46dca4451b00}}} [00021.840] 01050.01053> {{{mmap:0x1fa8d219f000:0x1000:load:0x3:rx:0}}} [00021.840] 01050.01053> {{{mmap:0x1fa8d21a0000:0x1000:load:0x3:rw:0x1000}}} [00021.840] 01050.01053> dso: id=c189f51f19d10785d93b5235ad1b46dca4451b00 base=0x00001fa8d219f000 name=libasync-default.so [00021.840] 01050.01053> {{{module:0x2:<vDSO>:elf:40ab5fa3b61f12fef4a44477a687f608661cd450}}} [00021.840] 01050.01053> {{{mmap:0x548b2b419000:0x7000:load:0x2:r:0}}} [00021.840] 01050.01053> {{{mmap:0x548b2b420000:0x1000:load:0x2:rx:0x7000}}} [00021.840] 01050.01053> dso: id=40ab5fa3b61f12fef4a44477a687f608661cd450 base=0x0000548b2b419000 name=<vDSO> [00021.840] 01050.01053> {{{module:0x1:libc.so:elf:67a12284bce140fc32aaaeac223e0e8f85cb5085}}} [00021.840] 01050.01053> {{{mmap:0x62f63d770000:0xcb000:load:0x1:rx:0}}} [00021.840] 01050.01053> {{{mmap:0x62f63d83c000:0x6000:load:0x1:rw:0xcc000}}} [00021.840] 01050.01053> dso: id=67a12284bce140fc32aaaeac223e0e8f85cb5085 base=0x000062f63d770000 name=libc.so [00021.840] 01050.01053> {{{module:0x4:libfdio.so:elf:27787977e95f3b9563c9e0bd4d34ec92b7e9ad88}}} [00021.840] 01050.01053> {{{mmap:0x4b1bc944b000:0x24000:load:0x4:rx:0}}} [00021.840] 01050.01053> {{{mmap:0x4b1bc9470000:0x4000:load:0x4:rw:0x25000}}} [00021.840] 01050.01053> dso: id=27787977e95f3b9563c9e0bd4d34ec92b7e9ad88 base=0x00004b1bc944b000 name=libfdio.so [00021.840] 01050.01053> {{{module:0x5:liblaunchpad.so:elf:6fc2232dc8c1bc5c6adb8ad50ca794b5a260ee4f}}} [00021.840] 01050.01053> {{{mmap:0x4f9defc0a000:0x7000:load:0x5:rx:0}}} [00021.840] 01050.01053> {{{mmap:0x4f9defc11000:0x2000:load:0x5:rw:0x7000}}} [00021.840] 01050.01053> dso: id=6fc2232dc8c1bc5c6adb8ad50ca794b5a260ee4f base=0x00004f9defc0a000 name=liblaunchpad.so [00021.840] 01050.01053> {{{module:0x6:libtrace-engine.so:elf:c9042b83fe01206008fcefb16395238417248169}}} [00021.840] 01050.01053> {{{mmap:0x5cc3766d2000:0x9000:load:0x6:rx:0}}} [00021.840] 01050.01053> {{{mmap:0x5cc3766db000:0x2000:load:0x6:rw:0x9000}}} [00021.840] 01050.01053> dso: id=c9042b83fe01206008fcefb16395238417248169 base=0x00005cc3766d2000 name=libtrace-engine.so [00021.840] 01050.01053> bootsvc: Starting... [00021.840] 01036.01043> userboot: loader-service channel peer closed [00021.840] 01036.01043> userboot: finished! [00021.840] 01050.01053> bootsvc: Creating bootfs service... [00021.841] 01050.01053> bootsvc: Processing bootdata... [00021.841] 01050.01053> bootsvc: Loading boot cmdline overrides... [00021.841] 01050.01053> bootsvc: Loading kernel VMOs... [00021.841] 01050.01053> bootsvc: Creating loader service... [00021.841] 01050.01053> bootsvc: Launching next process... [00021.841] 01050.01096> bootsvc: launched bin/devmgr [00021.842] 01104.01117> devmgr: main() [00021.842] 01104.01117> cmdline: netsvc.disable=true [00021.842] 01104.01117> cmdline: zircon.system.disable-automount=true [00021.842] 01104.01117> cmdline: zircon.autorun.boot=/boot/infra/setup [00021.842] 01104.01117> cmdline: kernel.serial=legacy [00021.842] 01104.01117> cmdline: http://192.168.42.1/multiboot/d4%3A5d%3Adf%3A1a%3A43%3A25= [00021.842] 01104.01117> cmdline: multiboot.boot_loader_name=iPXE+1.0.0++(d2063) [00021.842] 01104.01117> devmgr: coordinator_init() [00021.842] 01104.01117> devmgr: init [00021.842] 01104.01117> devmgr: svc init [00021.842] 01104.01117> devmgr: launch /boot/bin/svchost (svchost) OK [00021.842] 01104.01117> devmgr: vfs init [00021.842] 01104.01117> devmgr: launch /boot/bin/fshost (fshost) OK [00021.842] 01104.01221> devmgr: shell startup [00021.843] 01182.01202> fshost: started. [00021.844] 01104.01212> devmgr: launch /boot/bin/pwrbtn-monitor (pwrbtn-monitor) OK [00021.844] 01104.01242> devmgr: launch /boot/bin/virtual-console (virtual-console) OK [00021.844] 01104.01242> zircon.autorun.boot: starting '/boot/infra/setup'... [00021.845] 01104.01242> devmgr: launch /boot/infra/setup (autorun:boot) OK [00021.848] 01104.01117> devcoord: launch devhost 'devhost:sys': pid=2048 [00021.848] 01104.01117> devcoord: launch devhost 'devhost:test': pid=2081 [00021.848] 01104.01117> devcoord: launch devhost 'devhost:root': pid=2114 [00021.849] 01104.01117> devcoord: launch devhost 'devhost:misc': pid=2165 [00021.850] 02048.02072> devhost: trace provider registry begun [00021.850] 02081.02105> devhost: trace provider registry begun [00021.851] 02114.02152> devhost: trace provider registry begun [00021.851] 02165.02201> devhost: trace provider registry begun [00021.853] 01104.01221> devmgr: launch /boot/bin/sh (sh:console) OK [00021.918] 02048.02072> acpi-bus: not using IOMMU [00021.922] 02048.02072> acpi-pwrbtn: initialized [00021.928] 02048.02072> WARNING: ACPI found bad _CRS address entry [00021.934] 02048.02072> WARNING: ACPI found bad _CRS address entry [00021.945] 02048.02072> acpi: published device pci(0x5982cc3a2200), parent=proxy(0x5982cc39e540), handle=0x5982cc3da750 [00021.946] 02048.02072> acpi: published device rtc(0x5982cc39d080), parent=acpi(0x5982cc39e780), handle=0x5982cc3f9330 [00021.947] 02048.02072> acpi-ec: initialized [00021.948] 02048.02072> acpi: failed to create NHLT VMO (res -10) [00021.948] 02048.02072> acpi: failed to publish NHLT metadata [00021.951] 02048.02072> [sysmem_init 28] async_get_default_dispatcher(): 0x5982cc3910a0 [00021.951] 02048.02072> [sysmem_bind 40] sysmem_bind() [00021.951] 02048.02072> acpi-bus: sysmem_register_protocol() intentionally ignored for now. [00021.951] 02048.02072> PMU: 7 arch events [00021.951] 02048.02072> PMU: arch event id range: 1-7 [00021.951] 02048.02072> PMU: 102 model events [00021.951] 02048.02072> PMU: model event id range: 1-241 [00021.951] 02048.02072> Intel Processor Trace configuration for this chipset: [00021.951] 02048.02072> mtc_freq_mask: 0x249 [00021.951] 02048.02072> cyc_thresh_mask: 0x3fff [00021.951] 02048.02072> psb_freq_mask: 0x3f [00021.951] 02048.02072> num addr ranges: 2 [00021.952] 01104.01117> devcoord: launch devhost 'devhost:pci#1:8086:5916': pid=2941 [00021.953] 01104.01117> devcoord: launch devhost 'devhost:pci#3:8086:9d2f': pid=3009 [00021.954] 01256.01532> vc: new input device /dev/class/input/000 [00021.954] 01104.01117> devcoord: launch devhost 'devhost:pci#5:8086:9d60': pid=3128 [00021.954] 01104.01117> devcoord: launch devhost 'devhost:pci#6:8086:9d61': pid=3197 [00021.955] 02941.02979> devhost: trace provider registry begun [00021.955] 01104.01117> devcoord: launch devhost 'devhost:pci#9:8086:9d03': pid=3269 [00021.956] 01104.01117> devcoord: launch devhost 'devhost:pci#14:8086:9d71': pid=3377 [00021.956] 03009.03093> devhost: trace provider registry begun [00021.957] 01104.01117> devcoord: launch devhost 'devhost:pci#16:8086:156f': pid=3463 [00021.957] 03128.03172> devhost: trace provider registry begun [00021.959] 03197.03234> devhost: trace provider registry begun [00021.959] 03128.03172> initialized intel serialio i2c driver, reg=0x681af781c000 regsize=4096 [00021.962] 03197.03234> initialized intel serialio i2c driver, reg=0x6245c3526000 regsize=4096 [00021.971] 03377.03435> devhost: trace provider registry begun [00021.972] 03463.03501> devhost: trace provider registry begun [00021.972] 03009.03624> * found USB device (0x18d1:0xa002, USB 2.0) config 1 [00021.972] 03009.03624> * found USB device (0x18d1:0xa003, USB 3.0) config 1 [00021.973] 03269.03323> devhost: trace provider registry begun [00021.973] 03269.03323> ahci: using MSI interrupt [00021.976] 03377.03435> [IHDA DSP 00:1f.3] Failed to fetch NHLT (res -25) [00021.976] 03377.03435> devhost[00:1f.3/intel-hda-000/intel-sst-dsp-000] bind driver '/boot/driver/dsp.so' failed: -25 [00021.976] 01104.01117> devcoord: rpc: bind-driver 'intel-sst-dsp-000' status -25 [00022.062] 01256.01532> vc: new display device /dev/class/display-controller/000/virtcon [00022.203] 02941.04138> i915: MST not supported [00022.685] 03009.03624> * found USB device (0x0781:0x5583, USB 3.0) config 1 [00022.686] 03009.03093> UMS: parent: 'ifc-000' [00022.686] 03009.03093> UMS:Max lun is: 0 [00022.707] 02941.04138> i915: MST not supported [00023.436] 03009.03624> * found USB device (0x0cf3:0xe300, USB 2.1) config 1 [00023.437] 03009.03093> devhost[00:14.0/xhci/usb-bus/002/002/ifc-001] bind driver '/boot/driver/bt-transport-usb.so' failed: -2 [00023.437] 01104.01117> devcoord: rpc: bind-driver 'ifc-001' status -2 [00023.686] 02941.04138> i915: No displays detected [00023.689] 03009.04225> UMS: block size is: 0x00000200 [00023.689] 03009.04225> UMS: total blocks is: 30031250 [00023.689] 03009.04225> UMS: total size is: 15376000000 [00023.689] 03009.04225> UMS: read-only: 0 removable: 1 [00023.690] 01182.01202> devmgr: /dev/class/block/000: MBR? [00023.690] 01104.01117> devcoord: dc_bind_device() '/boot/driver/mbr.so' [00023.693] 01182.01202> devmgr: /dev/class/block/002: MBR? [00023.693] 01104.01117> devcoord: dc_bind_device() '/boot/driver/mbr.so' [00023.962] 03128.03172> intel-i2c-controller: intel_serialio_i2c_slave_transfer: -21 [00023.962] 03128.03172> i2c-hid: could not read HID descriptor: 0 [00023.962] 03128.03172> devhost[00:15.0/i2c-bus-9d60/0020] bind driver '/boot/driver/i2c-hid.so' failed: -2 [00023.962] 01104.01117> devcoord: rpc: bind-driver '0020' status -2 [00023.971] 03197.03234> intel-i2c-controller: intel_serialio_i2c_slave_transfer: -21 [00023.971] 03197.03234> i2c-hid: could not read HID descriptor: 0 [00023.971] 03197.03234> devhost[00:15.1/i2c-bus-9d61/004c] bind driver '/boot/driver/i2c-hid.so' failed: -2 [00023.971] 01104.01117> devcoord: rpc: bind-driver '004c' status -2 [00023.988] 03269.04013> sata2: dev info [00023.988] 03269.04013> serial=711430953055 2 [00023.988] 03269.04013> firmware rev=1Q01A7 0 [00023.988] 03269.04013> model id=IBIW NSS D [00023.988] 03269.04013> major=0x3f0 ACS2 DMA 32 commands [00023.988] 03269.04013> LBA48 234441648 sectors, sector size=512 [00023.989] 01182.01202> devmgr: /dev/class/block/003: GPT? [00023.989] 01104.01117> devcoord: dc_bind_device() '/boot/driver/gpt.so' [00023.989] 03269.03323> gpt: device_get_metadata failed (-25) [00023.991] 01182.01202> devmgr: /dev/class/block/004: FVM? [00023.991] 01104.01117> devcoord: dc_bind_device() '/boot/driver/fvm.so' [00023.993] 04479.04493> paver:[Initialize] Successfully initialized EFI Device Partitioner [00023.995] 04479.04493> paver:[WipePartitions] Immediate reboot strongly recommended [00023.995] 03269.03323> block: Joining un-closed FIFO server [00023.995] 03269.03323> block: Joining un-closed FIFO server [00023.995] 03269.03323> block: Joining un-closed FIFO server [00023.995] 01104.01117> devcoord: dc_bind_device() '' [00023.996] 01182.01202> devmgr: /dev/class/block/003: GPT? [00023.996] 01104.01117> devcoord: dc_bind_device() '/boot/driver/gpt.so' [00023.996] 03269.03323> gpt: device_get_metadata failed (-25) [00023.999] 04798.04812> 34+0 records in [00023.999] 04798.04812> 34+0 records out [00023.999] 04798.04812> 17408 bytes copied [00023.999] 04916.04930> Failed to seek on output [00023.999] 04916.04930> 0+0 records in [00023.999] 04916.04930> 0+0 records out [00023.999] 04916.04930> 0 bytes copied [00024.000] 04986.05000> netifc: ? /dev/class/ethernet/000 [00024.000] 04986.05000> netifc: create 512 eth buffers [00024.001] 04986.05000> macaddr: d4:5d:df:1a:43:25 [00024.001] 04986.05000> ip6addr: fe80::d65d:df4d:fe1a:4325 [00024.001] 04986.05000> snmaddr: ff02::1:ff1a:4325 [00024.001] 04986.05000> netsvc: using /dev/class/ethernet/000 [00024.001] 04986.05000> _ _ _ [00024.001] 04986.05000> | | | | | [00024.001] 04986.05000> _______ __| | |__ ___ ___ | |_ [00024.001] 04986.05000> |_ / _ \/ _` | '_ \ / _ \ / _ \| __| [00024.001] 04986.05000> / / __/ (_| | |_) | (_) | (_) | |_ [00024.001] 04986.05000> /___\___|\__,_|_.__/ \___/ \___/ \__| [00024.001] 04986.05000> [00024.001] 04986.05000> [00024.001] 04986.05000> zedboot: version: 0.7.13 [00024.001] 04986.05000> [00024.001] 04986.05000> netsvc: nodename='siren-bats-wick-hasty' [00024.001] 04986.05000> netsvc: will not advertise [00024.001] 04986.05000> netsvc: start [00933.381] 04986.05000> netsvc: tftp write of file <<netboot>>cmdline completed [00933.381] 04986.05000> netsvc: metrics: {"inorderblks": 1,"oooblks": 0,"ack": 1,"nack": 0,"timeouts": 0,"sas": 0,"inorderbytes": 55} [00933.381] 04986.05000> netsvc: Running FVM Paver [00933.383] 04986.05094> paver:[InitializeGpt] Located GPT is invalid; Attempting to initialize [00933.384] 01104.01117> devcoord: dc_bind_device() '' [00933.384] 01104.01117> devcoord: dc_bind_device() '/boot/driver/gpt.so' [00933.384] 03269.03323> gpt: device_get_metadata failed (-25) [00933.384] 01182.01202> devmgr: /dev/class/block/003: GPT? [00933.384] 01104.01117> devcoord: dc_bind_device() '/boot/driver/gpt.so' [00933.384] 03269.03323> devhost: rpc:bind-device failed: -20 [00933.385] 04986.05094> paver:[Initialize] Successfully initialized EFI Device Partitioner [00933.385] 04986.05094> paver:[PartitionPave] Paving partition. [00933.385] 04986.05094> paver:[FindFirstFit] Looking for space [00933.385] 04986.05094> paver:[FindFirstFit] Sorting [00933.385] 04986.05094> paver:[FindFirstFit] Partition[0] From Block [0, 34) ... (next partition starts at block 234441614) [00933.385] 04986.05094> paver:[FindFirstFit] There are 234441580 free blocks (16777216 requested) [00933.385] 04986.05094> paver:[AddPartition] Found space in GPT - OK 234441580 @ 34 [00933.385] 04986.05094> paver:[AddPartition] Final space in GPT - OK 16777216 @ 34 [00933.386] 04986.05094> paver:[AddPartition] Added partition, waiting for bind [00933.386] 01104.01117> devcoord: dc_bind_device() '' [00933.386] 01182.01202> devmgr: /dev/class/block/003: GPT? [00933.386] 01104.01117> devcoord: dc_bind_device() '/boot/driver/gpt.so' [00933.386] 03269.03323> gpt: device_get_metadata failed (-25) [00933.387] 04986.05094> paver:[AddPartition] Added partition, waiting for bind - OK [00933.387] 04986.05094> paver:[PartitionPave] Streaming partitions... [00933.387] 05074.05088> Found compressed file [00933.387] 04986.05094> paver:[FvmStreamPartitions] Header Validated - OK [00933.388] 04986.05094> paver:[FvmPartitionFormat] Initializing partition as FVM [00933.390] 01104.01117> devcoord: dc_bind_device() '/boot/driver/fvm.so' [00934.392] 04986.05094> paver:[FvmStreamPartitions] Partitions pre-validated successfully: Enough space exists to pave. [00934.392] 04986.05094> paver:[AllocatePartitions] Allocating partition blobfs consisting of 1 slices [00934.395] 04986.05094> paver:[AllocatePartitions] Allocating partition minfs consisting of 1 slices [00934.396] 04986.05094> paver:[AllocatePartitions] Creating zxcrypt volume [00934.398] 03269.03323> devhost_get_handles(0x7944eacae900:block) open path='zxcrypt/block', r=-2 [00934.398] 01104.01117> devcoord: dc_bind_device() '/boot/driver/zxcrypt.so' [00934.399] 03269.03323> devhost_get_handles(0x7944eacae900:block) open path='zxcrypt', r=-2 [00934.402] 04986.05094> paver:[FvmStreamPartitions] Partition space pre-allocated successfully. [00934.402] 04986.05094> paver:[FvmStreamPartitions] Streaming partition 0 [00934.402] 04986.05094> paver:[StreamFvmPartition] Writing extent 0... [00934.402] 04986.05100> netsvc: paver write progress 0.2% [00934.403] 04986.05094> paver:[StreamFvmPartition] 8192 bytes written, 8380416 zeroes left [00934.420] 04986.05094> paver:[StreamFvmPartition] Writing extent 1... [00934.420] 04986.05094> paver:[StreamFvmPartition] 8192 bytes written, 8380416 zeroes left [00934.441] 04986.05094> paver:[StreamFvmPartition] Writing extent 2... [00934.446] 04986.05094> paver:[StreamFvmPartition] 2097152 bytes written, 6291456 zeroes left [00934.459] 04986.05094> paver:[StreamFvmPartition] Writing extent 3... [00934.463] 04986.05094> paver:[StreamFvmPartition] 2097152 bytes written, 6291456 zeroes left [00934.476] 04986.05094> paver:[StreamFvmPartition] Writing extent 4... [00935.402] 04986.05100> netsvc: paver write progress 37.1% [00936.403] 04986.05100> netsvc: paver write progress 55.2% [00937.404] 04986.05100> netsvc: paver write progress 71.7% [00759.622] 04823.04937> netsvc: paver write progress 24.6% [00938.409] 04986.05100> netsvc: paver write progress 88.2% [00760.623] 04823.04937> netsvc: paver write progress 30.7% 2019/04/20 00:23:31 done 2019/04/20 00:23:31 attempting to send <<image>>bootloader.img... 2019/04/20 00:23:31 target is busy, retrying in one second [00939.233] 04986.05000> netsvc: tftp write of file <<image>>sparse.fvm completed [00939.233] 04986.05000> netsvc: metrics: {"inorderblks": 165707,"oooblks": 0,"ack": 648,"nack": 0,"timeouts": 0,"sas": 0,"inorderbytes": 169683313} [00939.235] 04986.05094> paver:[StreamFvmPartition] 182951936 bytes written, 1597440 zeroes left [00939.237] 04986.05094> paver:[FvmStreamPartitions] Done streaming partition 0 [00939.237] 04986.05094> paver:[FvmStreamPartitions] Done flushing partition 0 [00939.237] 04986.05094> paver:[FvmStreamPartitions] Streaming partition 1 [00939.237] 04986.05094> paver:[StreamFvmPartition] Writing extent 0... [00939.237] 04986.05094> paver:[StreamFvmPartition] 8192 bytes written, 8380416 zeroes left [00939.276] 04986.05094> paver:[StreamFvmPartition] Writing extent 1... [00939.276] 04986.05094> paver:[StreamFvmPartition] 65536 bytes written, 8323072 zeroes left [00939.318] 04986.05094> paver:[StreamFvmPartition] Writing extent 2... [00939.319] 04986.05094> paver:[StreamFvmPartition] 65536 bytes written, 8323072 zeroes left [00939.355] 04986.05094> paver:[StreamFvmPartition] Writing extent 3... [00939.395] 04986.05094> paver:[StreamFvmPartition] Writing extent 4... [00939.405] 04986.05094> paver:[StreamFvmPartition] 2097152 bytes written, 14680064 zeroes left [00939.468] 04986.05094> paver:[StreamFvmPartition] Writing extent 5... [00939.468] 04986.05094> paver:[StreamFvmPartition] 57344 bytes written, 8331264 zeroes left [00761.623] 04823.04937> netsvc: paver write progress 37.3% [00939.509] 04986.05094> paver:[FvmStreamPartitions] Done streaming partition 1 [00939.509] 04986.05094> paver:[FvmStreamPartitions] Done flushing partition 1 [00939.510] 05074.05088> Reading FVM from compressed file: true [00939.510] 05074.05088> Remaining bytes read into compression buffer: 0 [00939.510] 05074.05088> Remaining bytes written to decompression buffer: 0 [00939.510] 05074.05088> Time reading bytes from sparse FVM file: 11799981854 (4 s) [00939.510] 05074.05088> Time reading bytes AND decompressing them: 11888770429 (4 s) [00939.510] 04986.05094> paver:[PartitionPave] Completed successfully 2019/04/20 00:23:32 attempting to send <<image>>bootloader.img... [00940.234] 04986.05000> netsvc: Running BOOTLOADER Paver [00940.237] 04986.05828> paver:[Initialize] Successfully initialized EFI Device Partitioner [00940.237] 04986.05828> paver:[RealMain] SKIPPING BOOTLOADER install on x64 device, pass --force if desired. 2019/04/20 00:23:32 done 2019/04/20 00:23:32 attempting to send <<image>>zircona.img... [00940.282] 04986.05000> netsvc: tftp write of file <<image>>bootloader.img completed [00940.282] 04986.05000> netsvc: metrics: {"inorderblks": 1093,"oooblks": 0,"ack": 5,"nack": 0,"timeouts": 0,"sas": 0,"inorderbytes": 1118208} [00940.283] 04986.05000> netsvc: Running ZIRCON-A Paver [00940.286] 04986.05969> paver:[Initialize] Successfully initialized EFI Device Partitioner [00940.286] 04986.05969> paver:[PartitionPave] Paving partition. [00940.286] 04986.05969> paver:[FindFirstFit] Looking for space [00940.286] 04986.05969> paver:[FindFirstFit] Partition seen with start 34, end 16777249 (length 16777216) [00940.286] 04986.05969> paver:[FindFirstFit] Sorting [00940.286] 04986.05969> paver:[FindFirstFit] Partition[0] From Block [0, 34) ... (next partition starts at block 34) [00940.286] 04986.05969> paver:[FindFirstFit] There are 0 free blocks (32768 requested) [00940.286] 04986.05969> paver:[FindFirstFit] Partition[1] From Block [34, 16777250) ... (next partition starts at block 234441614) [00940.286] 04986.05969> paver:[FindFirstFit] There are 217664364 free blocks (32768 requested) [00940.286] 04986.05969> paver:[AddPartition] Found space in GPT - OK 217664364 @ 16777250 [00940.286] 04986.05969> paver:[AddPartition] Final space in GPT - OK 32768 @ 16777250 [00940.286] 03269.03323> block: Joining un-closed FIFO server [00940.286] 04986.05969> paver:[AddPartition] Added partition, waiting for bind [00940.286] 03269.03323> block: Joining un-closed FIFO server [00940.287] 01104.01117> devcoord: dc_bind_device() '' [00940.287] 01182.01202> devmgr: /dev/class/block/003: GPT? [00940.287] 01104.01117> devcoord: dc_bind_device() '/boot/driver/gpt.so' [00940.287] 03269.03323> gpt: device_get_metadata failed (-25) [00940.288] 01182.01202> devmgr: /dev/class/block/013: FVM? [00940.288] 01104.01117> devcoord: dc_bind_device() '/boot/driver/fvm.so' [00940.288] 04986.05969> paver:[AddPartition] Added partition, waiting for bind - OK [00762.623] 04823.04937> netsvc: paver write progress 43.9% 2019/04/20 00:23:32 done 2019/04/20 00:23:32 attempting to send <<image>>zirconr.img... 2019/04/20 00:23:32 target is busy, retrying in one second [00940.877] 04986.05000> netsvc: tftp write of file <<image>>zircona.img completed [00940.877] 04986.05000> netsvc: metrics: {"inorderblks": 13900,"oooblks": 0,"ack": 55,"nack": 0,"timeouts": 0,"sas": 0,"inorderbytes": 14233280} [00940.910] 04986.05969> paver:[PartitionPave] Completed successfully [00763.623] 04823.04937> netsvc: paver write progress 50.5% 2019/04/20 00:23:33 attempting to send <<image>>zirconr.img... [00941.878] 04986.05000> netsvc: Running ZIRCON-R Paver [00941.881] 04986.06242> paver:[Initialize] Successfully initialized EFI Device Partitioner [00941.881] 04986.06242> paver:[PartitionPave] Paving partition. [00941.881] 04986.06242> paver:[FindFirstFit] Looking for space [00941.881] 04986.06242> paver:[FindFirstFit] Partition seen with start 34, end 16777249 (length 16777216) [00941.881] 04986.06242> paver:[FindFirstFit] Partition seen with start 16777250, end 16810017 (length 32768) [00941.881] 04986.06242> paver:[FindFirstFit] Sorting [00941.881] 04986.06242> paver:[FindFirstFit] Partition[0] From Block [0, 34) ... (next partition starts at block 34) [00941.881] 04986.06242> paver:[FindFirstFit] There are 0 free blocks (49152 requested) [00941.881] 04986.06242> paver:[FindFirstFit] Partition[1] From Block [34, 16777250) ... (next partition starts at block 16777250) [00941.881] 04986.06242> paver:[FindFirstFit] There are 0 free blocks (49152 requested) [00941.881] 04986.06242> paver:[FindFirstFit] Partition[2] From Block [16777250, 16810018) ... (next partition starts at block 234441614) [00941.881] 04986.06242> paver:[FindFirstFit] There are 217631596 free blocks (49152 requested) [00941.881] 04986.06242> paver:[AddPartition] Found space in GPT - OK 217631596 @ 16810018 [00941.881] 04986.06242> paver:[AddPartition] Final space in GPT - OK 49152 @ 16810018 [00941.881] 04986.06242> paver:[AddPartition] Added partition, waiting for bind [00941.881] 03269.03323> block: Joining un-closed FIFO server [00941.882] 01104.01117> devcoord: dc_bind_device() '' [00941.882] 01182.01202> devmgr: /dev/class/block/003: GPT? [00941.882] 01104.01117> devcoord: dc_bind_device() '/boot/driver/gpt.so' [00941.882] 03269.03323> gpt: device_get_metadata failed (-25) [00941.883] 01182.01202> devmgr: /dev/class/block/017: FVM? [00941.883] 01104.01117> devcoord: dc_bind_device() '/boot/driver/fvm.so' [00941.883] 04986.06242> paver:[AddPartition] Added partition, waiting for bind - OK 2019/04/20 00:23:34 done 2019/04/20 00:23:34 attempting to send <<image>>authorized_keys... 2019/04/20 00:23:34 target is busy, retrying in one second [00942.419] 04986.05000> netsvc: tftp write of file <<image>>zirconr.img completed [00942.419] 04986.05000> netsvc: metrics: {"inorderblks": 12589,"oooblks": 0,"ack": 50,"nack": 0,"timeouts": 0,"sas": 0,"inorderbytes": 12890296} [00942.445] 04986.06242> paver:[PartitionPave] Completed successfully [00764.623] 04823.04937> netsvc: paver write progress 57.0% [00765.623] 04823.04937> netsvc: paver write progress 63.7% 2019/04/20 00:23:35 attempting to send <<image>>authorized_keys... 2019/04/20 00:23:35 done 2019/04/20 00:23:35 attempting to send <<netboot>>kernel.bin... 2019/04/20 00:23:35 target is busy, retrying in one second [00943.420] 04986.05000> netsvc: Installing SSH authorized_keys [00943.421] 04986.05000> netsvc: tftp write of file <<image>>authorized_keys completed [00943.421] 04986.05000> netsvc: metrics: {"inorderblks": 1,"oooblks": 0,"ack": 1,"nack": 0,"timeouts": 0,"sas": 0,"inorderbytes": 725} [00943.423] 04986.06532> paver:[Initialize] Successfully initialized EFI Device Partitioner [00943.423] 01104.01117> devcoord: dc_bind_device() '/boot/driver/zxcrypt.so' [00943.424] 03269.03323> devhost_get_handles(0x7944eacae900:block) open path='zxcrypt', r=-2 [00943.453] 04986.06532> paver:[DataFilePave] Wrote ssh/authorized_keys [00766.623] 04823.04937> netsvc: paver write progress 70.3% 2019/04/20 00:23:36 attempting to send <<netboot>>kernel.bin... 2019/04/20 00:23:36 done [00767.623] 04823.04937> netsvc: paver write progress 76.8% [00768.624] 04823.04937> netsvc: paver write progress 83.5% [00769.624] 04823.04937> netsvc: paver write progress 90.1% [00770.624] 04823.04937> netsvc: paver write progress 96.8% 2019/04/20 00:23:40 done 2019/04/20 00:23:40 attempting to send <<image>>bootloader.img... 2019/04/20 00:23:40 target is busy, retrying in one second [00771.104] 04823.04931> paver:[StreamFvmPartition] 182951936 bytes written, 1597440 zeroes left [00771.106] 04823.04837> netsvc: tftp write of file <<image>>sparse.fvm completed [00771.106] 04823.04837> netsvc: metrics: {"inorderblks": 165707,"oooblks": 0,"ack": 648,"nack": 0,"timeouts": 0,"sas": 0,"inorderbytes": 169683313} [00771.107] 04823.04931> paver:[FvmStreamPartitions] Done streaming partition 0 [00771.107] 04823.04931> paver:[FvmStreamPartitions] Done flushing partition 0 [00771.107] 04823.04931> paver:[FvmStreamPartitions] Streaming partition 1 [00771.107] 04823.04931> paver:[StreamFvmPartition] Writing extent 0... [00771.107] 04823.04931> paver:[StreamFvmPartition] 8192 bytes written, 8380416 zeroes left [00771.150] 04823.04931> paver:[StreamFvmPartition] Writing extent 1... [00771.150] 04823.04931> paver:[StreamFvmPartition] 65536 bytes written, 8323072 zeroes left [00771.189] 04823.04931> paver:[StreamFvmPartition] Writing extent 2... [00771.189] 04823.04931> paver:[StreamFvmPartition] 65536 bytes written, 8323072 zeroes left [00771.225] 04823.04931> paver:[StreamFvmPartition] Writing extent 3... [00771.263] 04823.04931> paver:[StreamFvmPartition] Writing extent 4... [00771.273] 04823.04931> paver:[StreamFvmPartition] 2097152 bytes written, 14680064 zeroes left [00771.340] 04823.04931> paver:[StreamFvmPartition] Writing extent 5... [00771.340] 04823.04931> paver:[StreamFvmPartition] 57344 bytes written, 8331264 zeroes left [00771.376] 04823.04931> paver:[FvmStreamPartitions] Done streaming partition 1 [00771.376] 04823.04931> paver:[FvmStreamPartitions] Done flushing partition 1 [00771.377] 04911.04925> Reading FVM from compressed file: true [00771.377] 04911.04925> Remaining bytes read into compression buffer: 0 [00771.377] 04911.04925> Remaining bytes written to decompression buffer: 0 [00771.377] 04911.04925> Time reading bytes from sparse FVM file: 37956149704 (13 s) [00771.377] 04911.04925> Time reading bytes AND decompressing them: 38042595457 (14 s) [00771.377] 04823.04931> paver:[PartitionPave] Completed successfully 2019/04/20 00:23:41 attempting to send <<image>>bootloader.img... [00772.108] 04823.04837> netsvc: Running BOOTLOADER Paver [00772.111] 04823.05667> paver:[Initialize] Successfully initialized EFI Device Partitioner [00772.111] 04823.05667> paver:[RealMain] SKIPPING BOOTLOADER install on x64 device, pass --force if desired. 2019/04/20 00:23:41 done 2019/04/20 00:23:41 attempting to send <<image>>zircona.img... [00772.207] 04823.04837> netsvc: tftp write of file <<image>>bootloader.img completed [00772.207] 04823.04837> netsvc: metrics: {"inorderblks": 1093,"oooblks": 0,"ack": 5,"nack": 0,"timeouts": 0,"sas": 0,"inorderbytes": 1118208} [00772.208] 04823.04837> netsvc: Running ZIRCON-A Paver [00772.211] 04823.05808> paver:[Initialize] Successfully initialized EFI Device Partitioner [00772.211] 04823.05808> paver:[PartitionPave] Paving partition. [00772.211] 04823.05808> paver:[FindFirstFit] Looking for space [00772.211] 04823.05808> paver:[FindFirstFit] Partition seen with start 34, end 16777249 (length 16777216) [00772.211] 04823.05808> paver:[FindFirstFit] Sorting [00772.211] 04823.05808> paver:[FindFirstFit] Partition[0] From Block [0, 34) ... (next partition starts at block 34) [00772.211] 04823.05808> paver:[FindFirstFit] There are 0 free blocks (32768 requested) [00772.211] 04823.05808> paver:[FindFirstFit] Partition[1] From Block [34, 16777250) ... (next partition starts at block 234441614) [00772.211] 04823.05808> paver:[FindFirstFit] There are 217664364 free blocks (32768 requested) [00772.211] 04823.05808> paver:[AddPartition] Found space in GPT - OK 217664364 @ 16777250 [00772.211] 04823.05808> paver:[AddPartition] Final space in GPT - OK 32768 @ 16777250 [00772.211] 03327.03384> block: Joining un-closed FIFO server [00772.211] 04823.05808> paver:[AddPartition] Added partition, waiting for bind [00772.211] 03327.03384> block: Joining un-closed FIFO server [00772.211] 01104.01117> devcoord: dc_bind_device() '' [00772.212] 01182.01202> devmgr: /dev/class/block/003: GPT? [00772.212] 01104.01117> devcoord: dc_bind_device() '/boot/driver/gpt.so' [00772.212] 03327.03384> gpt: device_get_metadata failed (-25) [00772.213] 01182.01202> devmgr: /dev/class/block/008: FVM? [00772.213] 01104.01117> devcoord: dc_bind_device() '/boot/driver/fvm.so' [00772.213] 04823.05808> paver:[AddPartition] Added partition, waiting for bind - OK [00773.208] 04823.05814> netsvc: paver write progress 79.4% 2019/04/20 00:23:43 done 2019/04/20 00:23:43 attempting to send <<image>>zirconr.img... 2019/04/20 00:23:43 target is busy, retrying in one second [00773.466] 04823.04837> netsvc: tftp write of file <<image>>zircona.img completed [00773.466] 04823.04837> netsvc: metrics: {"inorderblks": 13900,"oooblks": 0,"ack": 55,"nack": 0,"timeouts": 0,"sas": 0,"inorderbytes": 14233280} [00773.500] 04823.05808> paver:[PartitionPave] Completed successfully 2019/04/20 00:23:44 attempting to send <<image>>zirconr.img... [00774.468] 04823.04837> netsvc: Running ZIRCON-R Paver [00774.471] 04823.06081> paver:[Initialize] Successfully initialized EFI Device Partitioner [00774.471] 04823.06081> paver:[PartitionPave] Paving partition. [00774.471] 04823.06081> paver:[FindFirstFit] Looking for space [00774.471] 04823.06081> paver:[FindFirstFit] Partition seen with start 34, end 16777249 (length 16777216) [00774.471] 04823.06081> paver:[FindFirstFit] Partition seen with start 16777250, end 16810017 (length 32768) [00774.471] 04823.06081> paver:[FindFirstFit] Sorting [00774.471] 04823.06081> paver:[FindFirstFit] Partition[0] From Block [0, 34) ... (next partition starts at block 34) [00774.471] 04823.06081> paver:[FindFirstFit] There are 0 free blocks (49152 requested) [00774.471] 04823.06081> paver:[FindFirstFit] Partition[1] From Block [34, 16777250) ... (next partition starts at block 16777250) [00774.471] 04823.06081> paver:[FindFirstFit] There are 0 free blocks (49152 requested) [00774.471] 04823.06081> paver:[FindFirstFit] Partition[2] From Block [16777250, 16810018) ... (next partition starts at block 234441614) [00774.471] 04823.06081> paver:[FindFirstFit] There are 217631596 free blocks (49152 requested) [00774.471] 04823.06081> paver:[AddPartition] Found space in GPT - OK 217631596 @ 16810018 [00774.471] 04823.06081> paver:[AddPartition] Final space in GPT - OK 49152 @ 16810018 [00774.471] 04823.06081> paver:[AddPartition] Added partition, waiting for bind [00774.471] 03327.03384> block: Joining un-closed FIFO server [00774.472] 01104.01117> devcoord: dc_bind_device() '' [00774.472] 01182.01202> devmgr: /dev/class/block/003: GPT? [00774.472] 01104.01117> devcoord: dc_bind_device() '/boot/driver/gpt.so' [00774.472] 03327.03384> gpt: device_get_metadata failed (-25) [00774.473] 01182.01202> devmgr: /dev/class/block/012: FVM? [00774.473] 01104.01117> devcoord: dc_bind_device() '/boot/driver/fvm.so' [00774.473] 04823.06081> paver:[AddPartition] Added partition, waiting for bind - OK [00775.468] 04823.06087> netsvc: paver write progress 87.9% 2019/04/20 00:23:45 done 2019/04/20 00:23:45 attempting to send <<image>>authorized_keys... 2019/04/20 00:23:45 target is busy, retrying in one second [00775.607] 04823.04837> netsvc: tftp write of file <<image>>zirconr.img completed [00775.607] 04823.04837> netsvc: metrics: {"inorderblks": 12589,"oooblks": 0,"ack": 50,"nack": 0,"timeouts": 0,"sas": 0,"inorderbytes": 12890296} [00775.638] 04823.06081> paver:[PartitionPave] Completed successfully [00000.000] 00000.00000> zbi: @ 0xffffff8005cc9000 (12706992 bytes) [00000.000] 00000.00000> UART: FIFO depth 16 [00000.000] 00000.00000> PMM: boot reserve add [0x100000, 0x2fffff] [00000.000] 00000.00000> PMM: boot reserve add [0x5cc9000, 0x68e7fff] [00000.000] 00000.00000> PMM: arena too small to be useful (size 4096) [00000.000] 00000.00000> PMM: pmm_add_arena failed to initialize arena [00000.000] 00000.00000> MEM: Failed to add pmm range at 0x7ffff000 size 0x1000 [00000.000] 00000.00000> PMM: boot reserve marking WIRED [0x100000, 0x2fffff] [00000.000] 00000.00000> PMM: boot reserve marking WIRED [0x5cc9000, 0x68e7fff] [00000.000] 00000.00000> [00000.000] 00000.00000> welcome to Zircon [00000.000] 00000.00000> [00000.000] 00000.00000> KASLR: .text section at 0xffffffff00100000 [00000.000] 00000.00000> INIT: cpu 0, calling hook 0xffffffff00114ec4 (global_prng_seed) at level 0x30000, flags 0x1 [00000.000] 00000.00000> initializing vm pre-heap [00000.000] 00000.00000> VM: marking boot alloc used range [0x68e8000, 0x68e8100) [00000.000] 00000.00000> INIT: cpu 0, calling hook 0xffffffff00122274 (elf_build_id) at level 0x4fffe, flags 0x1 [00000.000] 00000.00000> INIT: cpu 0, calling hook 0xffffffff00122400 (version) at level 0x4ffff, flags 0x1 [00000.000] 00000.00000> version: [00000.000] 00000.00000> arch: x86 [00000.000] 00000.00000> platform: XXX [00000.000] 00000.00000> target: XXX [00000.000] 00000.00000> project: x64 [00000.000] 00000.00000> buildid: git-94e2c4380a7d2d27cbed602ea615e94237be4004-dirty [00000.000] 00000.00000> ELF build ID: 2cbba575d5db32065a4e99bcd19ee2534429d77f [00000.000] 00000.00000> initializing heap [00000.000] 00000.00000> INIT: cpu 0, calling hook 0xffffffff00101fc4 (console) at level 0x50000, flags 0x1 [00000.000] 00000.00000> INIT: cpu 0, calling hook 0xffffffff001826c4 (x86_resource_init) at level 0x50000, flags 0x1 [00000.000] 00000.00000> initializing vm [00000.000] 00000.00000> VM: reserving kernel region [0xffffffff00100000, 0xffffffff0021b000) flags 0x28 name 'kernel_code' [00000.000] 00000.00000> VM: reserving kernel region [0xffffffff0021b000, 0xffffffff0026c000) flags 0x8 name 'kernel_rodata' [00000.000] 00000.00000> VM: reserving kernel region [0xffffffff0026c000, 0xffffffff00274000) flags 0x18 name 'kernel_data' [00000.000] 00000.00000> VM: reserving kernel region [0xffffffff00274000, 0xffffffff00300000) flags 0x18 name 'kernel_bss' [00000.000] 00000.00000> INIT: cpu 0, calling hook 0xffffffff00183388 (display_memtype) at level 0x60001, flags 0x1 [00000.000] 00000.00000> INIT: cpu 0, calling hook 0xffffffff00186818 (acpi_tables) at level 0x60001, flags 0x1 [00000.000] 00000.00000> INIT: cpu 0, calling hook 0xffffffff001814c8 (hpet) at level 0x60002, flags 0x1 [00000.000] 00000.00000> INIT: cpu 0, calling hook 0xffffffff00181888 (apic) at level 0x60002, flags 0x1 [00000.000] 00000.00000> x2APIC enabled [00000.000] 00000.00000> INIT: cpu 0, calling hook 0xffffffff001a7e6c (system_topology_init) at level 0x60002, flags 0x1 [00000.000] 00000.00000> WARNING: more than 1000 levels of cache, couldn't find highest. [00000.000] 00000.00000> WARNING: unable to find any cache levels. [00000.000] 00000.00000> Could not find SRAT table. ACPICA returned: 5 [00000.000] 00000.00000> INIT: cpu 0, calling hook 0xffffffff00185e08 (timer) at level 0x60003, flags 0x1 [00000.000] 00000.00000> HPET frequency: 23999 ticks/ms [00000.000] 00000.00000> TSC frequency: 2712000 ticks/ms [00945.289] 00000.00000> timer features: constant_tsc 1 invariant_tsc 1 tsc_deadline 1 [00945.289] 00000.00000> Using TSC as wallclock [00945.289] 00000.00000> INIT: cpu 0, calling hook 0xffffffff00208930 (percpu_heap_init) at level 0x60003, flags 0x1 [00945.289] 00000.00000> initializing kernel [00945.289] 00000.00000> initializing mp [00945.289] 00000.00000> INIT: cpu 0, calling hook 0xffffffff00115118 (global_prng_thread_safe) at level 0x7ffff, flags 0x1 [00945.289] 00000.00000> creating bootstrap completion thread [00945.289] 00000.00000> top of bootstrap2() [00945.289] 00000.00000> INIT: cpu 0, calling hook 0xffffffff00131734 (libobject) at level 0x80000, flags 0x1 [00945.289] 00000.00000> OOM: started thread [00945.289] 00000.00000> INIT: cpu 0, calling hook 0xffffffff0020589c (dpc) at level 0x80000, flags 0x1 [00945.289] 00000.00000> Processor Model Info: type 0 family 0x6 model 0xe stepping 0x9 [00945.289] 00000.00000> display_family 0x6 display_model 0x8e [00945.289] 00000.00000> Vendor: Intel [00945.289] 00000.00000> Microarch: Kaby Lake [00945.289] 00000.00000> F/M/S: 6/8e/9 [00945.289] 00000.00000> patch_level: 84 [00945.289] 00000.00000> Brand: Intel(R) Core(TM) i5-7300U CPU @ 2.60GHz [00945.289] 00000.00000> Features: fpu sse sse2 sse3 ssse3 sse4.1 sse4.2 mmx avx avx2 fxsr pcid xsave mon aesni clflush [00945.289] 00000.00000> clflushopt fsgsbase tsc_adj smep smap erms rdrand rdseed syscall nx huge rdtscp [00945.289] 00000.00000> invar_tsc tsc_deadline x2apic vmx pt hwp [00945.289] 00000.00000> Properties: meltdown l1tf pcid_good [00945.289] 00000.00000> initializing platform [00945.289] 00000.00000> INIT: cpu 0, calling hook 0xffffffff001a157c (x86_perfmon) at level 0x90000, flags 0x1 [00945.289] 00000.00000> PMU: version 4 [00945.289] 00000.00000> UART: started IRQ driven RX [00945.289] 00000.00000> UART: started IRQ driven TX [00945.289] 00000.00000> cpu topology: [00945.289] 00000.00000> 0: apic id 0x0 BSP [00945.289] 00000.00000> 1: apic id 0x1 [00945.289] 00000.00000> 2: apic id 0x2 [00945.289] 00000.00000> 3: apic id 0x3 [00945.289] 00000.00000> Found 4 cpus [00945.289] 00000.00000> booting apic ids: 0x1 0x2 0x3 [00945.304] 00000.00000> entering scheduler on cpu 1 [00945.305] 00000.00000> entering scheduler on cpu 2 [00945.305] 00000.00000> entering scheduler on cpu 3 [00945.308] 00000.00000> smbios: manufacturer="Intel Corporation" product="NUC7i5DNHE" [00945.308] 00000.00000> initializing target [00945.308] 00000.00000> INIT: cpu 0, calling hook 0xffffffff001850b8 (x86_pcie_init) at level 0xa0000, flags 0x1 [00945.308] 00000.00000> moving to last init level [00945.308] 00000.00000> INIT: cpu 0, calling hook 0xffffffff001214cc (debuglog) at level 0xb0000, flags 0x1 [00945.308] 00000.00000> INIT: cpu 0, calling hook 0xffffffff00174d40 (kcounters) at level 0xb0000, flags 0x1 [00945.308] 00000.00000> INIT: cpu 0, calling hook 0xffffffff00102aec (kernel_shell) at level 0xc0000, flags 0x1 [00945.308] 00000.00000> INIT: cpu 0, calling hook 0xffffffff00202ad4 (ktrace) at level 0xc0000, flags 0x1 [00945.311] 00000.00000> ktrace: buffer at 0xffffff988da2e000 (33554432 bytes) [00945.311] 00000.00000> INIT: cpu 0, calling hook 0xffffffff002184f8 (userboot) at level 0xc0000, flags 0x1 [00945.311] 00000.00000> userboot: ramdisk 0xc1f000 @ 0xffffff8005cc9000 [00945.312] 00000.00000> userboot: userboot rodata 0 @ [0x7f4efb4ad000,0x7f4efb4b0000) [00945.312] 00000.00000> userboot: userboot code 0x3000 @ [0x7f4efb4b0000,0x7f4efb4bb000) [00945.312] 00000.00000> userboot: vdso/full rodata 0 @ [0x7f4efb4bb000,0x7f4efb4c2000) [00945.312] 00000.00000> userboot: vdso/full code 0x7000 @ [0x7f4efb4c2000,0x7f4efb4c3000) [00945.312] 00000.00000> userboot: entry point @ 0x7f4efb4b0c90 [00945.312] 01036.01043> userboot: option "zircon.autorun.system=/boot/bin/sh+/boot/infra/runcmds" [00945.342] 01036.01043> userboot: searching bootfs for 'bin/bootsvc' [00945.342] 01036.01043> userboot: 'bin/bootsvc' has PT_INTERP "lib/ld.so.1" [00945.342] 01036.01043> userboot: searching bootfs for 'lib/ld.so.1' [00945.342] 01036.01043> userboot: userboot: loaded lib/ld.so.1 at 0x4ab196f3a000, entry point 0x4ab196f583d0 [00945.342] 01036.01043> userboot: userboot: loaded vDSO at 0x6ab34e9a1000, entry point 0x6ab34e9a88fa [00945.342] 01036.01043> userboot: process bin/bootsvc started. [00945.342] 01036.01043> userboot: waiting for loader-service requests... [00945.342] 01036.01043> userboot: searching bootfs for 'lib/libasync-default.so' [00945.342] 01036.01043> userboot: searching bootfs for 'lib/libfdio.so' [00945.342] 01036.01043> userboot: searching bootfs for 'lib/libtrace-engine.so' [00945.342] 01036.01043> userboot: searching bootfs for 'lib/liblaunchpad.so' [00945.342] 01050.01053> {{{reset}}} [00945.342] 01050.01053> {{{module:0:<application>:elf:367d3374904876b8f143f2ed5e4dfb0248fef748}}} [00945.342] 01050.01053> {{{mmap:0x576472e2d000:0x3a000:load:0:rx:0}}} [00945.342] 01050.01053> {{{mmap:0x576472e67000:0x4000:load:0:rw:0x3a000}}} [00945.342] 01050.01053> dso: id=367d3374904876b8f143f2ed5e4dfb0248fef748 base=0x0000576472e2d000 name=<application> [00945.342] 01050.01053> {{{module:0x2:<vDSO>:elf:71712e0a455898a51e34d40a4013786ab1fa5335}}} [00945.342] 01050.01053> {{{mmap:0x6ab34e9a1000:0x7000:load:0x2:r:0}}} [00945.342] 01050.01053> {{{mmap:0x6ab34e9a8000:0x1000:load:0x2:rx:0x7000}}} [00945.342] 01050.01053> dso: id=71712e0a455898a51e34d40a4013786ab1fa5335 base=0x00006ab34e9a1000 name=<vDSO> [00945.342] 01050.01053> {{{module:0x3:libasync-default.so:elf:8c511b4202cf569c8fdde14ca97222102ba3a9e0}}} [00945.342] 01050.01053> {{{mmap:0x3f7991625000:0x1000:load:0x3:rx:0}}} [00945.342] 01050.01053> {{{mmap:0x3f7991626000:0x1000:load:0x3:rw:0x1000}}} [00945.342] 01050.01053> dso: id=8c511b4202cf569c8fdde14ca97222102ba3a9e0 base=0x00003f7991625000 name=libasync-default.so [00945.342] 01050.01053> {{{module:0x4:libfdio.so:elf:3efa72b2e3bd2e4271f835d34a81d9719d6e08a7}}} [00945.342] 01050.01053> {{{mmap:0x2680565e0000:0x32000:load:0x4:rx:0}}} [00945.342] 01050.01053> {{{mmap:0x268056613000:0x4000:load:0x4:rw:0x33000}}} [00945.342] 01050.01053> dso: id=3efa72b2e3bd2e4271f835d34a81d9719d6e08a7 base=0x00002680565e0000 name=libfdio.so [00945.342] 01050.01053> {{{module:0x5:libtrace-engine.so:elf:95bc229c3cf2ab8a51f12c33a311105ff8976120}}} [00945.342] 01050.01053> {{{mmap:0x7c8e60f59000:0x9000:load:0x5:rx:0}}} [00945.342] 01050.01053> {{{mmap:0x7c8e60f62000:0x2000:load:0x5:rw:0x9000}}} [00945.342] 01050.01053> dso: id=95bc229c3cf2ab8a51f12c33a311105ff8976120 base=0x00007c8e60f59000 name=libtrace-engine.so [00945.342] 01050.01053> {{{module:0x6:liblaunchpad.so:elf:5b0854856213eae6bab93c982f39551f8f9591c5}}} [00945.342] 01050.01053> {{{mmap:0x5cdd40b72000:0x7000:load:0x6:rx:0}}} [00945.342] 01050.01053> {{{mmap:0x5cdd40b79000:0x2000:load:0x6:rw:0x7000}}} [00945.342] 01050.01053> dso: id=5b0854856213eae6bab93c982f39551f8f9591c5 base=0x00005cdd40b72000 name=liblaunchpad.so [00945.342] 01050.01053> {{{module:0x1:libc.so:elf:5d417db61b3a48a58a8fa1ffbfc2e71b830e0857}}} [00945.342] 01050.01053> {{{mmap:0x4ab196f3a000:0xa6000:load:0x1:rx:0}}} [00945.342] 01050.01053> {{{mmap:0x4ab196fe0000:0x5000:load:0x1:rw:0xa6000}}} [00945.342] 01050.01053> dso: id=5d417db61b3a48a58a8fa1ffbfc2e71b830e0857 base=0x00004ab196f3a000 name=libc.so [00945.342] 01050.01053> bootsvc: Starting... [00945.342] 01036.01043> userboot: loader-service channel peer closed [00945.342] 01036.01043> userboot: finished! [00945.342] 01050.01053> bootsvc: Creating bootfs service... [00945.343] 01050.01053> bootsvc: Retrieving boot image... [00945.343] 01050.01053> bootsvc: Decommitted BOOTDATA VMO from 0 to 0xc1e000 [00945.343] 01050.01053> bootsvc: Loading boot arguments... [00945.343] 01050.01053> bootsvc: Creating svcfs service... [00945.343] 01050.01053> bootsvc: Loading kernel VMOs... [00945.343] 01050.01053> bootsvc: Creating loader service... [00945.343] 01050.01053> bootsvc: Launching next process... [00945.343] 01050.01108> bootsvc: Launched bin/devcoordinator [00945.344] 01115.01130> devcoordinator: launch /boot/bin/svchost (svchost) OK [00945.345] 01115.01130> devcoordinator: launch /boot/bin/fshost (fshost) OK [00945.347] 01115.01321> devcoordinator: launch /boot/bin/pwrbtn-monitor (pwrbtn-monitor) OK [00945.347] 01115.01348> devcoordinator: launch /boot/bin/netsvc (netsvc) OK [00945.348] 01115.01348> devcoordinator: launch /boot/bin/virtual-console (virtual-console) OK [00945.351] 01115.01130> devcoordinator: full system required, ignoring fallback drivers until /system is loaded [00945.352] 01115.01130> devcoordinator: launch devhost 'devhost:sys': pid=2187 [00945.352] 01115.01130> devcoordinator: launch devhost 'devhost:test': pid=2219 [00945.352] 01115.01130> devcoordinator: launch devhost 'devhost:root': pid=2266 [00945.353] 02187.02201> devhost: trace provider registry begun [00945.353] 01115.01130> devcoordinator: launch devhost 'devhost:misc': pid=2324 [00945.353] 02219.02241> devhost: trace provider registry begun [00945.354] 02266.02295> devhost: trace provider registry begun [00945.355] 02324.02387> devhost: trace provider registry begun [00945.355] 01115.01333> devcoordinator: launch /boot/bin/sh (sh:console) OK [00945.439] 02187.02201> acpi-bus: not using IOMMU [00945.446] 02187.02201> PMU: 7 arch events [00945.446] 02187.02201> PMU: arch event id range: 1-7 [00945.446] 02187.02201> PMU: 102 arch events [00945.446] 02187.02201> PMU: arch event id range: 1-241 [00945.446] 02187.02201> Intel Processor Trace configuration for this chipset: [00945.446] 02187.02201> mtc_freq_mask: 0x249 [00945.446] 02187.02201> cyc_thresh_mask: 0x3fff [00945.446] 02187.02201> psb_freq_mask: 0x3f [00945.446] 02187.02201> num addr ranges: 2 [00945.446] 02187.02201> [sysmem_init 28] async_get_default_dispatcher(): 0x77dbd2df2cd0 [00945.446] 02187.02201> [sysmem_bind 40] sysmem_bind() [00945.446] 02187.02876> acpi-pwrbtn: initialized [00945.446] 01722.01738> vc: new input device /dev/class/input/000 [00945.456] 02187.02876> WARNING: ACPI found bad _CRS address entry [00945.465] 02187.02876> WARNING: ACPI found bad _CRS address entry [00945.477] 02187.02876> acpi: published device pci(0x77db12e0bf50), parent=sys(0x77dc52df9c10), handle=0x77dad2e05610 [00945.478] 01115.01130> devcoordinator: launch devhost 'devhost:pci#1:8086:5916': pid=2972 [00945.478] 01115.01130> devcoordinator: launch devhost 'devhost:pci#3:8086:9d2f': pid=3025 [00945.479] 02972.02986> devhost: trace provider registry begun [00945.479] 01115.01130> devcoordinator: launch devhost 'devhost:pci#5:8086:9d60': pid=3097 [00945.480] 03097.03153> devhost: trace provider registry begun [00945.480] 01115.01130> devcoordinator: launch devhost 'devhost:pci#6:8086:9d61': pid=3206 [00945.480] 02187.02876> acpi: published device rtc(0x77db12e0bbf0), parent=acpi(0x77dc52df9410), handle=0x77dad2e2d110 [00945.481] 01115.01130> devcoordinator: launch devhost 'devhost:pci#9:8086:9d03': pid=3335 [00945.482] 03025.03048> devhost: trace provider registry begun [00945.482] 01115.01130> devcoordinator: launch devhost 'devhost:pci#14:8086:9d71': pid=3441 [00945.482] 02187.02876> acpi-ec: initialized [00945.482] 03206.03252> devhost: trace provider registry begun [00945.483] 01115.01130> devcoordinator: launch devhost 'devhost:pci#16:8086:156f': pid=3560 [00945.483] 03335.03349> devhost: trace provider registry begun [00945.485] 03335.03349> ahci: using MSI interrupt [00945.485] 03097.03153> initialized intel serialio i2c driver, reg=0x1f65da509000 regsize=4096 [00945.485] 03441.03485> devhost: trace provider registry begun [00945.485] 03560.03593> devhost: trace provider registry begun [00945.486] 03206.03252> initialized intel serialio i2c driver, reg=0x39617831d000 regsize=4096 [00945.486] 02187.02876> acpi: failed to create NHLT VMO (res -10) [00945.486] 02187.02876> acpi: failed to publish NHLT metadata [00945.495] 03025.03950> * found USB device (0x18d1:0xa002, USB 2.0) config 1 [00945.495] 03025.03950> * found USB device (0x18d1:0xa003, USB 3.0) config 1 [00945.495] 03441.03485> [IHDA DSP 00:1f.3] Failed to fetch NHLT (res -25) [00945.495] 03441.03485> [IHDA Controller 00:1f.3] Failed to initialize DSP device (res = -25) [00945.565] 01626.01649> netifc: ? /dev/class/ethernet/000 [00945.565] 01626.01649> netifc: create 512 eth buffers [00945.565] 01626.01649> macaddr: d4:5d:df:1a:43:25 [00945.565] 01626.01649> ip6addr: fe80::d65d:df4d:fe1a:4325 [00945.565] 01626.01649> snmaddr: ff02::1:ff1a:4325 [00945.565] 01626.01649> netsvc: using /dev/class/ethernet/000 [00945.565] 01626.01649> netsvc: nodename='siren-bats-wick-hasty' [00945.566] 01626.01649> netsvc: start [00945.598] 01722.01738> vc: new display device /dev/class/display-controller/000 [00945.639] 02972.04240> i915: MST not supported [00945.980] 02972.04240> i915: MST not supported [00946.207] 03025.03950> * found USB device (0x0781:0x5583, USB 3.0) config 1 [00946.865] 02972.04240> i915: No displays detected [00946.958] 03025.03950> * found USB device (0x0cf3:0xe300, USB 2.1) config 1 [00947.493] 03206.03252> intel-i2c-controller: intel_serialio_i2c_slave_transfer: -21 [00947.493] 03206.03252> i2c-hid: could not read HID descriptor: 0 [00947.493] 03206.03252> devhost[00:15.1/i2c-bus-9d61/004c] bind driver '/boot/driver/i2c-hid.so' failed: -2 [00947.493] 01115.01130> devcoordinator: rpc: bind-driver '004c' status -2 [00947.494] 03097.03153> intel-i2c-controller: intel_serialio_i2c_slave_transfer: -21 [00947.494] 03097.03153> i2c-hid: could not read HID descriptor: 0 [00947.494] 03097.03153> devhost[00:15.0/i2c-bus-9d60/0020] bind driver '/boot/driver/i2c-hid.so' failed: -2 [00947.494] 01115.01130> devcoordinator: rpc: bind-driver '0020' status -2 [00947.497] 03335.03919> sata2: dev info [00947.497] 03335.03919> serial=711430953055 2 [00947.497] 03335.03919> firmware rev=1Q01A7 0 [00947.497] 03335.03919> model id=IBIW NSS D [00947.497] 03335.03919> major=0x3f0 ACS2 DMA 32 commands [00947.497] 03335.03919> LBA48 234441648 sectors, sector size=512 [00947.498] 01299.01313> fshost: /dev/class/block/000: GPT? [00947.499] 03335.03349> gpt: device_get_metadata failed (-25) [00947.500] 01299.01313> fshost: /dev/class/block/001: FVM? [00947.502] 01299.01313> devcoordinator: launch /boot/bin/blobfs (blobfs:/blob) OK [00947.649] 01299.01313> fshost: starting 'bin/pkgsvr' '6d681bd767656569a52148e49e336fd0debf11fc78dfbfccaae817947e91ea5e'... [00947.655] 01299.01313> devcoordinator: launch bin/pkgsvr (pkgfs) OK [00947.665] 04631.04845> pkgsvr: system: will be served from 6d681bd767656569a52148e49e336fd0debf11fc78dfbfccaae817947e91ea5e [00947.665] 04631.04845> pkgsvr: pkgfs serving index /data/pkgfs_index from blobfs /blob [00947.665] 01299.01313> fshost: /dev/class/block/005: zxcrypt? [00947.666] 03335.03349> devhost_get_handles(0x56c26c6cc10:block) open path='zxcrypt', r=-2 [00947.668] 01299.01313> fshost: mounting minfs [00947.668] 01299.01313> devcoordinator: launch /boot/bin/minfs (minfs:/data) OK [00947.705] 01115.04885> devcoordinator: adding system driver 'magma_pdev_gpu' '/system/driver/libmsd_arm.so' [00947.705] 01115.01746> devcoordinator: launch /system/bin/appmgr (appmgr) OK [00947.705] 01115.01746> autorun: starting '/boot/bin/sh' '/boot/infra/runcmds'... [00947.705] 01115.01746> devcoordinator: launch /boot/bin/sh (autorun:system) OK [00947.722] 01115.04885> devcoordinator: adding system driver 'mt8167s_gpu' '/system/driver/libmsd_img_rgx_mtk.so' [00947.732] 01115.04885> devcoordinator: adding system driver 'gpu' '/system/driver/libmsd_intel.so' [00947.741] 01115.04885> devcoordinator: adding system driver 'iwlwifi_pci' '/system/driver/iwlwifi.so' [00947.752] 01115.04885> devcoordinator: adding system driver 'rtl88xx' '/system/driver/rtl88xx.so' [00947.760] 01115.04885> devcoordinator: adding system driver 'virtual_audio' '/system/driver/virtual_audio_driver.so' [00947.817] 01115.04885> devcoordinator: adding system driver 'wlan' '/system/driver/wlan.so' [00947.831] 01115.04885> devcoordinator: adding system driver 'virtual_camera' '/system/driver/virtual_camera_driver.so' [00947.839] 01115.04885> devcoordinator: adding system driver 'brcmfmac' '/system/driver/brcmfmac.so' [00947.868] 01115.04885> devcoordinator: adding system driver 'bt_host' '/system/driver/bt-host.so' [00947.879] 01115.04885> devcoordinator: adding system driver 'usb_video' '/system/driver/usb_video.so' [00947.904] 01115.04885> devcoordinator: adding system driver 'bt_hci_atheros' '/system/driver/bt-hci-atheros.so' [00947.906] 01115.04885> devcoordinator: adding system driver 'bt_hci_passthrough' '/system/driver/bt-hci-passthrough.so' [00947.908] 01115.04885> devcoordinator: adding system driver 'bt_hog' '/system/driver/bt-hog.so' [00947.921] 01115.04885> devcoordinator: adding system driver 'bt_hci_fake' '/system/driver/bt-hci-fake.so' [00947.925] 01115.04885> devcoordinator: adding system driver 'qmi_fake' '/system/driver/qmi-fake.so' [00947.929] 01115.04885> devcoordinator: adding system driver 'ath10k_pci' '/system/driver/ath10k.so' [00947.942] 05181.05200> [INFO:namespace_builder.cc(93)] config-data for sysmgr [00947.999] 01115.04885> devcoordinator: adding system driver 'ralink' '/system/driver/ralink.so' [00948.011] 01115.04885> devcoordinator: adding system driver 'wlan' '/system/driver/wlanphy.so' [00948.036] 01115.04885> devcoordinator: adding system driver 'bt_hci_intel' '/system/driver/bt-hci-intel.so' [00948.046] 01115.04885> devcoordinator: adding system driver 'qmi_usb' '/system/driver/qmi-transport.so' [00948.055] 01115.04885> devcoordinator: adding system driver 'wlan' '/system/driver/wlanif.so' [00948.056] 01115.01130> devcoordinator: driver 'wlan' added [00948.056] 01115.01130> devcoordinator: driver 'qmi_usb' added [00948.056] 01115.01130> devcoordinator: driver 'bt_hci_intel' added [00948.056] 01115.01130> devcoordinator: driver 'wlan' added [00948.056] 01115.01130> devcoordinator: driver 'ralink' added [00948.056] 01115.01130> devcoordinator: driver 'ath10k_pci' added [00948.056] 01115.01130> devcoordinator: launch devhost 'devhost:pci#11:168c:003e': pid=5924 [00948.056] 01115.01130> devcoordinator: driver 'qmi_fake' added [00948.056] 01115.01130> devcoordinator: driver 'bt_hci_fake' added [00948.056] 01115.01130> devcoordinator: driver 'bt_hog' added [00948.056] 01115.01130> devcoordinator: driver 'bt_hci_atheros' added [00948.056] 01115.01130> devcoordinator: driver 'usb_video' added [00948.056] 01115.01130> devcoordinator: driver 'bt_host' added [00948.056] 01115.01130> devcoordinator: driver 'brcmfmac' added [00948.056] 01115.01130> devcoordinator: driver 'wlan' added [00948.056] 01115.01130> devcoordinator: driver 'rtl88xx' added [00948.056] 01115.01130> devcoordinator: driver 'iwlwifi_pci' added [00948.056] 01115.01130> devcoordinator: driver 'gpu' added [00948.056] 01115.01130> devcoordinator: driver 'mt8167s_gpu' added [00948.056] 01115.01130> devcoordinator: driver 'magma_pdev_gpu' added [00948.056] 01115.01130> devcoordinator: driver 'bt_hci_passthrough' added [00948.056] 01115.01130> devcoordinator: fallback driver 'usb_composite' is available [00948.056] 01115.01130> devcoordinator: driver 'usb_composite' added [00948.057] 01115.01130> devcoordinator: fallback driver 'intel_disp' is available [00948.057] 01115.01130> devcoordinator: driver 'intel_disp' added [00948.058] 05924.05938> devhost: trace provider registry begun [00948.059] 05924.05938> ath10k: Probed chip QCA6174 ver: 2.1 [00948.060] 03025.03048> UMS: parent: 'ifc-000' [00948.060] 03025.03048> UMS:Max lun is: 0 [00948.061] 03025.03048> devhost[00:14.0/xhci/usb-bus/002/002/ifc-001] bind driver '/boot/driver/bt-transport-usb.so' failed: -2 [00948.061] 01115.01130> devcoordinator: rpc: bind-driver 'ifc-001' status -2 [00948.064] 03025.06441> UMS: block size is: 0x00000200 [00948.064] 03025.06441> UMS: total blocks is: 30031250 [00948.064] 03025.06441> UMS: total size is: 15376000000 [00948.064] 03025.06441> UMS: read-only: 0 removable: 1 [00948.092] 03025.09313> btatheros: Making visible [00948.092] 03025.09313> btatheros: loaded successfully [00948.093] 03025.09426> [INFO:command_channel.cc(149)] hci: initialized [00948.094] 01299.01313> fshost: /dev/class/block/007: MBR? [00948.097] 01299.01313> fshost: /dev/class/block/009: MBR? [00948.151] 05181.05200> [INFO:namespace_builder.cc(93)] config-data for amber [00948.157] 03025.09426> [WARN:adapter.cc(274)] gap: controller is using legacy HCI version 4.1 [00948.167] 03025.09426> [INFO:acl_data_channel.cc(91)] hci: initialized [00948.222] 05181.05200> [INFO:namespace_builder.cc(93)] config-data for pkg_resolver [00948.351] 13662.13674> [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 [00948.351] 13662.13674> kfill_days=2, start_event_aggregator_worker=1. [00948.405] 05181.05200> [INFO:namespace_builder.cc(93)] config-data for mdns [00948.433] 05924.13585> devhost: rpc:load-firmware failed: -25 [00948.433] 05924.13585> devhost: rpc:load-firmware failed: -25 [00948.481] 05181.05200> [INFO:namespace_builder.cc(93)] config-data for wlancfg [00948.681] 05181.05200> [INFO:namespace_builder.cc(93)] config-data for crashpad_agent [00948.709] 16620.16634> [INFO:main.cc(35)] Trace Manager starting with config: /pkg/data/tracing.config [00948.729] 14886.14904> [INFO:system_metrics_main.cc(23)] Cobalt SystemMetricsDaemon: System metrics daemon created. [00948.837] 17261.17275> wlanstack2 [I]: Starting [00949.125] 05924.12949> ath10k: Unknown eventid: 0x1d019 [00949.128] 05924.12949> ath10k: Unknown eventid: 0x16006 [00949.133] 05924.05938> wlanphy: event loop started [00949.133] 05924.05938> wlanphy_bind [00949.134] 17261.17275> wlanstack2::device [I]: new phy #0: /dev/sys/pci/01:00.0/ath10k-wlanphy/wlanphy [00949.134] 14704.14717> wlancfg got event: OnPhyAdded { phy_id: 0 } [00949.134] 14704.14717> wlancfg: phy 0 added [00949.134] 17261.17275> wlanstack2::service [I]: query_phy(id = 0) [00949.135] 17261.17275> wlanstack2::service [I]: query_phy(id = 0): received a 'QueryResult' from device [00949.135] 14704.14717> wlancfg: received a PhyInfo from phy #0: path is /dev/sys/pci/01:00.0/ath10k-wlanphy/wlanphy [00949.135] 14704.14717> using default wlan config entry for phy [00949.135] 14704.14717> wlancfg: Creating Client iface for phy 0 [00949.141] 05924.05938> wlan_bind [00949.143] 05924.05938> ath10k: adding a station interface (vdev_id=0) ... [00949.144] 05924.05938> wlan: [I] Initialize a client MLME. [00949.145] 05924.18059> wlan: [I] starting MainLoop [00949.145] 05924.05938> wlan: [I] channel opened [00949.146] 17261.17275> wlanstack2::device [I]: new iface #0 with role 'Client': /dev/sys/pci/01:00.0/ath10k-wlanphy/ath10k-wlanmac/wlan [00949.146] 14704.14717> wlancfg got event: OnIfaceAdded { iface_id: 0 } [00949.146] 14704.14717> wlancfg: new iface 0 added successfully [00949.147] 14704.14717> wlancfg: Starting auto-connect loop with 0 saved networks [00949.252] 14214.14226> Starting mDNS on interface ethp001f6 [80fe::5dd6:ffdf:1afe:2543] [00949.252] 14214.14226> [WARNING:garnet/bin/mdns/service/mdns_interface_transceiver_v6.cc(29)] NET-291 IPV6_MULTICAST_LOOP not supported (ENOPROTOOPT), continuing anyway [00949.252] 14214.14226> [WARNING:garnet/bin/mdns/service/mdns_interface_transceiver_v6.cc(50)] NET-2180 IPV6_JOIN_GROUP returned ENODEV, mDNS will not communicate via IPV6 [00953.319] 14214.14226> Starting mDNS on interface ethp001f6 192.168.42.102 [00953.319] 14214.14226> [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 [00953.319] 14214.14226> Starting mDNS on interface ethp001f6 [80fe::5dd6:ffdf:1afe:2543] [00953.319] 14214.14226> [WARNING:garnet/bin/mdns/service/mdns_interface_transceiver_v6.cc(29)] NET-291 IPV6_MULTICAST_LOOP not supported (ENOPROTOOPT), continuing anyway [00953.319] 14214.14226> [WARNING:garnet/bin/mdns/service/mdns_interface_transceiver_v6.cc(50)] NET-2180 IPV6_JOIN_GROUP returned ENODEV, mDNS will not communicate via IPV6 [00953.319] 14214.14226> mDNS: Verifying uniqueness of host name siren-bats-wick-hasty.local. 2019/04/20 00:23:46 attempting to send <<image>>authorized_keys... 2019/04/20 00:23:46 done 2019/04/20 00:23:46 attempting to send <<netboot>>kernel.bin... 2019/04/20 00:23:46 target is busy, retrying in one second [00776.608] 04823.04837> netsvc: Installing SSH authorized_keys [00776.608] 04823.04837> netsvc: tftp write of file <<image>>authorized_keys completed [00776.608] 04823.04837> netsvc: metrics: {"inorderblks": 1,"oooblks": 0,"ack": 1,"nack": 0,"timeouts": 0,"sas": 0,"inorderbytes": 725} [00776.610] 04823.06371> paver:[Initialize] Successfully initialized EFI Device Partitioner [00776.611] 01104.01117> devcoord: dc_bind_device() '/boot/driver/zxcrypt.so' [00776.611] 03327.03384> devhost_get_handles(0x20ca199979c0:block) open path='zxcrypt', r=-2 [00776.640] 04823.06371> paver:[DataFilePave] Wrote ssh/authorized_keys 2019/04/20 00:23:47 attempting to send <<netboot>>kernel.bin... 2019/04/20 00:23:48 done [00954.245] 14214.14226> mDNS: Using unique host name siren-bats-wick-hasty.local. [00000.000] 00000.00000> zbi: @ 0xffffff800ff89000 (12706992 bytes) [00000.000] 00000.00000> UART: FIFO depth 16 [00000.000] 00000.00000> PMM: boot reserve add [0x100000, 0x2fffff] [00000.000] 00000.00000> PMM: boot reserve add [0xff89000, 0x10ba7fff] [00000.000] 00000.00000> PMM: arena too small to be useful (size 4096) [00000.000] 00000.00000> PMM: pmm_add_arena failed to initialize arena [00000.000] 00000.00000> MEM: Failed to add pmm range at 0x7ffff000 size 0x1000 [00000.000] 00000.00000> PMM: boot reserve marking WIRED [0x100000, 0x2fffff] [00000.000] 00000.00000> PMM: boot reserve marking WIRED [0xff89000, 0x10ba7fff] [00000.000] 00000.00000> [00000.000] 00000.00000> welcome to Zircon [00000.000] 00000.00000> [00000.000] 00000.00000> KASLR: .text section at 0xffffffff00100000 [00000.000] 00000.00000> INIT: cpu 0, calling hook 0xffffffff00114ec4 (global_prng_seed) at level 0x30000, flags 0x1 [00000.000] 00000.00000> initializing vm pre-heap [00000.000] 00000.00000> VM: marking boot alloc used range [0x300000, 0x300100) [00000.000] 00000.00000> INIT: cpu 0, calling hook 0xffffffff00122274 (elf_build_id) at level 0x4fffe, flags 0x1 [00000.000] 00000.00000> INIT: cpu 0, calling hook 0xffffffff00122400 (version) at level 0x4ffff, flags 0x1 [00000.000] 00000.00000> version: [00000.000] 00000.00000> arch: x86 [00000.000] 00000.00000> platform: XXX [00000.000] 00000.00000> target: XXX [00000.000] 00000.00000> project: x64 [00000.000] 00000.00000> buildid: git-94e2c4380a7d2d27cbed602ea615e94237be4004-dirty [00000.000] 00000.00000> ELF build ID: 2cbba575d5db32065a4e99bcd19ee2534429d77f [00000.000] 00000.00000> initializing heap [00000.000] 00000.00000> INIT: cpu 0, calling hook 0xffffffff00101fc4 (console) at level 0x50000, flags 0x1 [00000.000] 00000.00000> INIT: cpu 0, calling hook 0xffffffff001826c4 (x86_resource_init) at level 0x50000, flags 0x1 [00000.000] 00000.00000> initializing vm [00000.000] 00000.00000> VM: reserving kernel region [0xffffffff00100000, 0xffffffff0021b000) flags 0x28 name 'kernel_code' [00000.000] 00000.00000> VM: reserving kernel region [0xffffffff0021b000, 0xffffffff0026c000) flags 0x8 name 'kernel_rodata' [00000.000] 00000.00000> VM: reserving kernel region [0xffffffff0026c000, 0xffffffff00274000) flags 0x18 name 'kernel_data' [00000.000] 00000.00000> VM: reserving kernel region [0xffffffff00274000, 0xffffffff00300000) flags 0x18 name 'kernel_bss' [00000.000] 00000.00000> INIT: cpu 0, calling hook 0xffffffff00183388 (display_memtype) at level 0x60001, flags 0x1 [00000.000] 00000.00000> INIT: cpu 0, calling hook 0xffffffff00186818 (acpi_tables) at level 0x60001, flags 0x1 [00000.000] 00000.00000> INIT: cpu 0, calling hook 0xffffffff001814c8 (hpet) at level 0x60002, flags 0x1 [00000.000] 00000.00000> INIT: cpu 0, calling hook 0xffffffff00181888 (apic) at level 0x60002, flags 0x1 [00000.000] 00000.00000> x2APIC enabled [00000.000] 00000.00000> INIT: cpu 0, calling hook 0xffffffff001a7e6c (system_topology_init) at level 0x60002, flags 0x1 [00000.000] 00000.00000> WARNING: more than 1000 levels of cache, couldn't find highest. [00000.000] 00000.00000> WARNING: unable to find any cache levels. [00000.000] 00000.00000> Could not find SRAT table. ACPICA returned: 5 [00000.000] 00000.00000> INIT: cpu 0, calling hook 0xffffffff00185e08 (timer) at level 0x60003, flags 0x1 [00000.000] 00000.00000> HPET frequency: 23999 ticks/ms [00000.000] 00000.00000> TSC frequency: 2712000 ticks/ms [00779.142] 00000.00000> timer features: constant_tsc 1 invariant_tsc 1 tsc_deadline 1 [00779.142] 00000.00000> Using TSC as wallclock [00779.142] 00000.00000> INIT: cpu 0, calling hook 0xffffffff00208930 (percpu_heap_init) at level 0x60003, flags 0x1 [00779.142] 00000.00000> initializing kernel [00779.142] 00000.00000> initializing mp [00779.142] 00000.00000> INIT: cpu 0, calling hook 0xffffffff00115118 (global_prng_thread_safe) at level 0x7ffff, flags 0x1 [00779.142] 00000.00000> creating bootstrap completion thread [00779.142] 00000.00000> top of bootstrap2() [00779.142] 00000.00000> INIT: cpu 0, calling hook 0xffffffff00131734 (libobject) at level 0x80000, flags 0x1 [00779.142] 00000.00000> OOM: started thread [00779.142] 00000.00000> INIT: cpu 0, calling hook 0xffffffff0020589c (dpc) at level 0x80000, flags 0x1 [00779.142] 00000.00000> Processor Model Info: type 0 family 0x6 model 0xe stepping 0x9 [00779.142] 00000.00000> display_family 0x6 display_model 0x8e [00779.142] 00000.00000> Vendor: Intel [00779.142] 00000.00000> Microarch: Kaby Lake [00779.142] 00000.00000> F/M/S: 6/8e/9 [00779.142] 00000.00000> patch_level: 84 [00779.142] 00000.00000> Brand: Intel(R) Core(TM) i5-7300U CPU @ 2.60GHz [00779.142] 00000.00000> Features: fpu sse sse2 sse3 ssse3 sse4.1 sse4.2 mmx avx avx2 fxsr pcid xsave mon aesni clflush [00779.142] 00000.00000> clflushopt fsgsbase tsc_adj smep smap erms rdrand rdseed syscall nx huge rdtscp [00779.142] 00000.00000> invar_tsc tsc_deadline x2apic vmx pt hwp [00779.142] 00000.00000> Properties: meltdown l1tf pcid_good [00779.142] 00000.00000> initializing platform [00779.142] 00000.00000> INIT: cpu 0, calling hook 0xffffffff001a157c (x86_perfmon) at level 0x90000, flags 0x1 [00779.142] 00000.00000> PMU: version 4 [00779.142] 00000.00000> UART: started IRQ driven RX [00779.142] 00000.00000> UART: started IRQ driven TX [00779.142] 00000.00000> cpu topology: [00779.142] 00000.00000> 0: apic id 0x0 BSP [00779.142] 00000.00000> 1: apic id 0x1 [00779.142] 00000.00000> 2: apic id 0x2 [00779.142] 00000.00000> 3: apic id 0x3 [00779.142] 00000.00000> Found 4 cpus [00779.143] 00000.00000> booting apic ids: 0x1 0x2 0x3 [00779.157] 00000.00000> entering scheduler on cpu 1 [00779.159] 00000.00000> entering scheduler on cpu 2 [00779.159] 00000.00000> entering scheduler on cpu 3 [00779.161] 00000.00000> smbios: manufacturer="Intel Corporation" product="NUC7i5DNHE" [00779.161] 00000.00000> initializing target [00779.161] 00000.00000> INIT: cpu 0, calling hook 0xffffffff001850b8 (x86_pcie_init) at level 0xa0000, flags 0x1 [00779.161] 00000.00000> moving to last init level [00779.161] 00000.00000> INIT: cpu 0, calling hook 0xffffffff001214cc (debuglog) at level 0xb0000, flags 0x1 [00779.161] 00000.00000> INIT: cpu 0, calling hook 0xffffffff00174d40 (kcounters) at level 0xb0000, flags 0x1 [00779.161] 00000.00000> INIT: cpu 0, calling hook 0xffffffff00102aec (kernel_shell) at level 0xc0000, flags 0x1 [00779.161] 00000.00000> INIT: cpu 0, calling hook 0xffffffff00202ad4 (ktrace) at level 0xc0000, flags 0x1 [00779.165] 00000.00000> ktrace: buffer at 0xffffff9a01a00000 (33554432 bytes) [00779.165] 00000.00000> INIT: cpu 0, calling hook 0xffffffff002184f8 (userboot) at level 0xc0000, flags 0x1 [00779.165] 00000.00000> userboot: ramdisk 0xc1f000 @ 0xffffff800ff89000 [00779.165] 00000.00000> userboot: userboot rodata 0 @ [0x79ef578ae000,0x79ef578b1000) [00779.165] 00000.00000> userboot: userboot code 0x3000 @ [0x79ef578b1000,0x79ef578bc000) [00779.165] 00000.00000> userboot: vdso/full rodata 0 @ [0x79ef578bc000,0x79ef578c3000) [00779.165] 00000.00000> userboot: vdso/full code 0x7000 @ [0x79ef578c3000,0x79ef578c4000) [00779.165] 00000.00000> userboot: entry point @ 0x79ef578b1c90 [00779.165] 01036.01043> userboot: option "zircon.autorun.system=/boot/bin/sh+/boot/infra/runcmds" [00779.195] 01036.01043> userboot: searching bootfs for 'bin/bootsvc' [00779.195] 01036.01043> userboot: 'bin/bootsvc' has PT_INTERP "lib/ld.so.1" [00779.195] 01036.01043> userboot: searching bootfs for 'lib/ld.so.1' [00779.195] 01036.01043> userboot: userboot: loaded lib/ld.so.1 at 0x5a2965aff000, entry point 0x5a2965b1d3d0 [00779.195] 01036.01043> userboot: userboot: loaded vDSO at 0x7921531ea000, entry point 0x7921531f18fa [00779.195] 01036.01043> userboot: process bin/bootsvc started. [00779.195] 01036.01043> userboot: waiting for loader-service requests... [00779.195] 01036.01043> userboot: searching bootfs for 'lib/libasync-default.so' [00779.195] 01036.01043> userboot: searching bootfs for 'lib/libfdio.so' [00779.195] 01036.01043> userboot: searching bootfs for 'lib/libtrace-engine.so' [00779.195] 01036.01043> userboot: searching bootfs for 'lib/liblaunchpad.so' [00779.196] 01050.01053> {{{reset}}} [00779.196] 01050.01053> {{{module:0:<application>:elf:367d3374904876b8f143f2ed5e4dfb0248fef748}}} [00779.196] 01050.01053> {{{mmap:0x1d46d80dc000:0x3a000:load:0:rx:0}}} [00779.196] 01050.01053> {{{mmap:0x1d46d8116000:0x4000:load:0:rw:0x3a000}}} [00779.196] 01050.01053> dso: id=367d3374904876b8f143f2ed5e4dfb0248fef748 base=0x00001d46d80dc000 name=<application> [00779.196] 01050.01053> {{{module:0x2:<vDSO>:elf:71712e0a455898a51e34d40a4013786ab1fa5335}}} [00779.196] 01050.01053> {{{mmap:0x7921531ea000:0x7000:load:0x2:r:0}}} [00779.196] 01050.01053> {{{mmap:0x7921531f1000:0x1000:load:0x2:rx:0x7000}}} [00779.196] 01050.01053> dso: id=71712e0a455898a51e34d40a4013786ab1fa5335 base=0x00007921531ea000 name=<vDSO> [00779.196] 01050.01053> {{{module:0x3:libasync-default.so:elf:8c511b4202cf569c8fdde14ca97222102ba3a9e0}}} [00779.196] 01050.01053> {{{mmap:0x3b0bba49000:0x1000:load:0x3:rx:0}}} [00779.196] 01050.01053> {{{mmap:0x3b0bba4a000:0x1000:load:0x3:rw:0x1000}}} [00779.196] 01050.01053> dso: id=8c511b4202cf569c8fdde14ca97222102ba3a9e0 base=0x000003b0bba49000 name=libasync-default.so [00779.196] 01050.01053> {{{module:0x4:libfdio.so:elf:3efa72b2e3bd2e4271f835d34a81d9719d6e08a7}}} [00779.196] 01050.01053> {{{mmap:0x29370f506000:0x32000:load:0x4:rx:0}}} [00779.196] 01050.01053> {{{mmap:0x29370f539000:0x4000:load:0x4:rw:0x33000}}} [00779.196] 01050.01053> dso: id=3efa72b2e3bd2e4271f835d34a81d9719d6e08a7 base=0x000029370f506000 name=libfdio.so [00779.196] 01050.01053> {{{module:0x5:libtrace-engine.so:elf:95bc229c3cf2ab8a51f12c33a311105ff8976120}}} [00779.196] 01050.01053> {{{mmap:0x67ccdc298000:0x9000:load:0x5:rx:0}}} [00779.196] 01050.01053> {{{mmap:0x67ccdc2a1000:0x2000:load:0x5:rw:0x9000}}} [00779.196] 01050.01053> dso: id=95bc229c3cf2ab8a51f12c33a311105ff8976120 base=0x000067ccdc298000 name=libtrace-engine.so [00779.196] 01050.01053> {{{module:0x6:liblaunchpad.so:elf:5b0854856213eae6bab93c982f39551f8f9591c5}}} [00779.196] 01050.01053> {{{mmap:0x24c5d578f000:0x7000:load:0x6:rx:0}}} [00779.196] 01050.01053> {{{mmap:0x24c5d5796000:0x2000:load:0x6:rw:0x7000}}} [00779.196] 01050.01053> dso: id=5b0854856213eae6bab93c982f39551f8f9591c5 base=0x000024c5d578f000 name=liblaunchpad.so [00779.196] 01050.01053> {{{module:0x1:libc.so:elf:5d417db61b3a48a58a8fa1ffbfc2e71b830e0857}}} [00779.196] 01050.01053> {{{mmap:0x5a2965aff000:0xa6000:load:0x1:rx:0}}} [00779.196] 01050.01053> {{{mmap:0x5a2965ba5000:0x5000:load:0x1:rw:0xa6000}}} [00779.196] 01050.01053> dso: id=5d417db61b3a48a58a8fa1ffbfc2e71b830e0857 base=0x00005a2965aff000 name=libc.so [00779.196] 01050.01053> bootsvc: Starting... [00779.196] 01036.01043> userboot: loader-service channel peer closed [00779.196] 01036.01043> userboot: finished! [00779.196] 01050.01053> bootsvc: Creating bootfs service... [00779.196] 01050.01053> bootsvc: Retrieving boot image... [00779.196] 01050.01053> bootsvc: Decommitted BOOTDATA VMO from 0 to 0xc1e000 [00779.196] 01050.01053> bootsvc: Loading boot arguments... [00779.196] 01050.01053> bootsvc: Creating svcfs service... [00779.196] 01050.01053> bootsvc: Loading kernel VMOs... [00779.196] 01050.01053> bootsvc: Creating loader service... [00779.196] 01050.01053> bootsvc: Launching next process... [00779.197] 01050.01108> bootsvc: Launched bin/devcoordinator [00779.198] 01115.01130> devcoordinator: launch /boot/bin/svchost (svchost) OK [00779.199] 01115.01130> devcoordinator: launch /boot/bin/fshost (fshost) OK [00779.201] 01115.01321> devcoordinator: launch /boot/bin/pwrbtn-monitor (pwrbtn-monitor) OK [00779.201] 01115.01350> devcoordinator: launch /boot/bin/netsvc (netsvc) OK [00779.202] 01115.01350> devcoordinator: launch /boot/bin/virtual-console (virtual-console) OK [00779.205] 01115.01130> devcoordinator: full system required, ignoring fallback drivers until /system is loaded [00779.206] 01115.01130> devcoordinator: launch devhost 'devhost:sys': pid=2187 [00779.206] 01115.01130> devcoordinator: launch devhost 'devhost:test': pid=2219 [00779.206] 01115.01130> devcoordinator: launch devhost 'devhost:root': pid=2266 [00779.207] 01115.01130> devcoordinator: launch devhost 'devhost:misc': pid=2331 [00779.207] 02187.02201> devhost: trace provider registry begun [00779.208] 02219.02241> devhost: trace provider registry begun [00779.209] 02266.02295> devhost: trace provider registry begun [00779.209] 02331.02380> devhost: trace provider registry begun [00779.209] 01115.01333> devcoordinator: launch /boot/bin/sh (sh:console) OK [00779.294] 02187.02201> acpi-bus: not using IOMMU [00779.301] 02187.02201> PMU: 7 arch events [00779.301] 02187.02201> PMU: arch event id range: 1-7 [00779.301] 02187.02201> PMU: 102 arch events [00779.301] 02187.02201> PMU: arch event id range: 1-241 [00779.301] 02187.02201> Intel Processor Trace configuration for this chipset: [00779.301] 02187.02201> mtc_freq_mask: 0x249 [00779.301] 02187.02201> cyc_thresh_mask: 0x3fff [00779.301] 02187.02201> psb_freq_mask: 0x3f [00779.301] 02187.02201> num addr ranges: 2 [00779.301] 02187.02201> [sysmem_init 28] async_get_default_dispatcher(): 0x151c0add08d0 [00779.301] 02187.02201> [sysmem_bind 40] sysmem_bind() [00779.301] 02187.02876> acpi-pwrbtn: initialized [00779.305] 01713.01742> vc: new input device /dev/class/input/000 [00779.311] 02187.02876> WARNING: ACPI found bad _CRS address entry [00779.321] 02187.02876> WARNING: ACPI found bad _CRS address entry [00779.333] 02187.02876> acpi: published device pci(0x151b4addce30), parent=sys(0x151c8adcc310), handle=0x151b0addfa90 [00779.333] 01115.01130> devcoordinator: launch devhost 'devhost:pci#1:8086:5916': pid=2972 [00779.334] 01115.01130> devcoordinator: launch devhost 'devhost:pci#3:8086:9d2f': pid=3030 [00779.336] 02972.02986> devhost: trace provider registry begun [00779.336] 01115.01130> devcoordinator: launch devhost 'devhost:pci#5:8086:9d60': pid=3095 [00779.336] 01115.01130> devcoordinator: launch devhost 'devhost:pci#6:8086:9d61': pid=3189 [00779.337] 02187.02876> acpi: published device rtc(0x151b4addcef0), parent=acpi(0x151c8adcdb10), handle=0x151b0ae07910 [00779.338] 03030.03055> devhost: trace provider registry begun [00779.338] 01115.01130> devcoordinator: launch devhost 'devhost:pci#9:8086:9d03': pid=3297 [00779.338] 03095.03146> devhost: trace provider registry begun [00779.338] 02187.02876> acpi-ec: initialized [00779.339] 03189.03219> devhost: trace provider registry begun [00779.339] 01115.01130> devcoordinator: launch devhost 'devhost:pci#14:8086:9d71': pid=3501 [00779.340] 03297.03348> devhost: trace provider registry begun [00779.341] 02187.02876> acpi: failed to create NHLT VMO (res -10) [00779.341] 02187.02876> acpi: failed to publish NHLT metadata [00779.345] 01115.01130> devcoordinator: launch devhost 'devhost:pci#16:8086:156f': pid=3621 [00779.346] 03501.03522> devhost: trace provider registry begun [00779.346] 03297.03348> ahci: using MSI interrupt [00779.347] 03189.03219> initialized intel serialio i2c driver, reg=0x2e1bac5c4000 regsize=4096 [00779.347] 03095.03146> initialized intel serialio i2c driver, reg=0x51b986b3c000 regsize=4096 [00779.348] 03621.03642> devhost: trace provider registry begun [00779.353] 03030.03995> * found USB device (0x18d1:0xa002, USB 2.0) config 1 [00779.353] 03030.03995> * found USB device (0x18d1:0xa003, USB 3.0) config 1 [00779.355] 03501.03522> [IHDA DSP 00:1f.3] Failed to fetch NHLT (res -25) [00779.355] 03501.03522> [IHDA Controller 00:1f.3] Failed to initialize DSP device (res = -25) [00779.423] 01622.01646> netifc: ? /dev/class/ethernet/000 [00779.423] 01622.01646> netifc: create 512 eth buffers [00779.423] 01622.01646> macaddr: d4:5d:df:1a:42:86 [00779.423] 01622.01646> ip6addr: fe80::d65d:df4d:fe1a:4286 [00779.423] 01622.01646> snmaddr: ff02::1:ff1a:4286 [00779.423] 01622.01646> netsvc: using /dev/class/ethernet/000 [00779.423] 01622.01646> netsvc: nodename='ocean-drank-wick-plug' [00779.423] 01622.01646> netsvc: start [00779.452] 01713.01742> vc: new display device /dev/class/display-controller/000 [00779.492] 02972.04240> i915: MST not supported [00779.996] 02972.04240> i915: MST not supported [00780.065] 03030.03995> * found USB device (0x0781:0x5583, USB 3.0) config 1 [00780.816] 03030.03995> * found USB device (0x0cf3:0xe300, USB 2.1) config 1 [00781.044] 02972.04240> i915: No displays detected [00781.351] 03189.03219> intel-i2c-controller: intel_serialio_i2c_slave_transfer: -21 [00781.351] 03189.03219> i2c-hid: could not read HID descriptor: 0 [00781.351] 03189.03219> devhost[00:15.1/i2c-bus-9d61/004c] bind driver '/boot/driver/i2c-hid.so' failed: -2 [00781.351] 01115.01130> devcoordinator: rpc: bind-driver '004c' status -2 [00781.351] 03095.03146> intel-i2c-controller: intel_serialio_i2c_slave_transfer: -21 [00781.351] 03095.03146> i2c-hid: could not read HID descriptor: 0 [00781.351] 03095.03146> devhost[00:15.0/i2c-bus-9d60/0020] bind driver '/boot/driver/i2c-hid.so' failed: -2 [00781.351] 01115.01130> devcoordinator: rpc: bind-driver '0020' status -2 [00781.365] 03297.03862> sata2: dev info [00781.365] 03297.03862> serial=711430953015 6 [00781.365] 03297.03862> firmware rev=1Q01A7 0 [00781.365] 03297.03862> model id=IBIW NSS D [00781.365] 03297.03862> major=0x3f0 ACS2 DMA 32 commands [00781.365] 03297.03862> LBA48 234441648 sectors, sector size=512 [00781.366] 01299.01313> fshost: /dev/class/block/000: GPT? [00781.366] 03297.03348> gpt: device_get_metadata failed (-25) [00781.367] 01299.01313> fshost: /dev/class/block/001: FVM? [00781.369] 01299.01313> devcoordinator: launch /boot/bin/blobfs (blobfs:/blob) OK [00781.513] 01299.01313> fshost: starting 'bin/pkgsvr' '6d681bd767656569a52148e49e336fd0debf11fc78dfbfccaae817947e91ea5e'... [00781.519] 01299.01313> devcoordinator: launch bin/pkgsvr (pkgfs) OK [00781.529] 04631.04845> pkgsvr: system: will be served from 6d681bd767656569a52148e49e336fd0debf11fc78dfbfccaae817947e91ea5e [00781.529] 04631.04845> pkgsvr: pkgfs serving index /data/pkgfs_index from blobfs /blob [00781.530] 01299.01313> fshost: /dev/class/block/005: zxcrypt? [00781.530] 03297.03348> devhost_get_handles(0x78abe4a7a010:block) open path='zxcrypt', r=-2 [00781.532] 01299.01313> fshost: mounting minfs [00781.533] 01299.01313> devcoordinator: launch /boot/bin/minfs (minfs:/data) OK [00781.554] 01115.01756> devcoordinator: launch /system/bin/appmgr (appmgr) OK [00781.554] 01115.01756> autorun: starting '/boot/bin/sh' '/boot/infra/runcmds'... [00781.579] 01115.04885> devcoordinator: adding system driver 'bt_hci_atheros' '/system/driver/bt-hci-atheros.so' [00781.582] 01115.04885> devcoordinator: adding system driver 'bt_hog' '/system/driver/bt-hog.so' [00781.582] 01115.01756> devcoordinator: launch /boot/bin/sh (autorun:system) OK [00781.591] 01115.04885> devcoordinator: adding system driver 'iwlwifi_pci' '/system/driver/iwlwifi.so' [00781.606] 01115.04885> devcoordinator: adding system driver 'wlan' '/system/driver/wlanphy.so' [00781.618] 01115.04885> devcoordinator: adding system driver 'bt_hci_fake' '/system/driver/bt-hci-fake.so' [00781.635] 01115.04885> devcoordinator: adding system driver 'mt8167s_gpu' '/system/driver/libmsd_img_rgx_mtk.so' [00781.693] 01115.04885> devcoordinator: adding system driver 'ralink' '/system/driver/ralink.so' [00781.718] 01115.04885> devcoordinator: adding system driver 'bt_hci_intel' '/system/driver/bt-hci-intel.so' [00781.727] 01115.04885> devcoordinator: adding system driver 'gpu' '/system/driver/libmsd_intel.so' [00781.729] 01115.04885> devcoordinator: adding system driver 'bt_hci_passthrough' '/system/driver/bt-hci-passthrough.so' [00781.739] 01115.04885> devcoordinator: adding system driver 'qmi_usb' '/system/driver/qmi-transport.so' [00781.742] 01115.04885> devcoordinator: adding system driver 'ath10k_pci' '/system/driver/ath10k.so' [00781.753] 01115.04885> devcoordinator: adding system driver 'usb_video' '/system/driver/usb_video.so' [00781.782] 01115.04885> devcoordinator: adding system driver 'bt_host' '/system/driver/bt-host.so' [00781.796] 01115.04885> devcoordinator: adding system driver 'virtual_camera' '/system/driver/virtual_camera_driver.so' [00781.804] 01115.04885> devcoordinator: adding system driver 'brcmfmac' '/system/driver/brcmfmac.so' [00781.812] 01115.04885> devcoordinator: adding system driver 'rtl88xx' '/system/driver/rtl88xx.so' [00781.820] 01115.04885> devcoordinator: adding system driver 'virtual_audio' '/system/driver/virtual_audio_driver.so' [00781.833] 05153.05167> [INFO:namespace_builder.cc(93)] config-data for sysmgr [00781.841] 01115.04885> devcoordinator: adding system driver 'magma_pdev_gpu' '/system/driver/libmsd_arm.so' [00781.898] 01115.04885> devcoordinator: adding system driver 'wlan' '/system/driver/wlan.so' [00781.907] 01115.04885> devcoordinator: adding system driver 'wlan' '/system/driver/wlanif.so' [00781.911] 01115.04885> devcoordinator: adding system driver 'qmi_fake' '/system/driver/qmi-fake.so' [00781.912] 01115.01130> devcoordinator: driver 'qmi_fake' added [00781.912] 01115.01130> devcoordinator: driver 'wlan' added [00781.912] 01115.01130> devcoordinator: driver 'wlan' added [00781.912] 01115.01130> devcoordinator: driver 'magma_pdev_gpu' added [00781.912] 01115.01130> devcoordinator: driver 'rtl88xx' added [00781.912] 01115.01130> devcoordinator: driver 'brcmfmac' added [00781.912] 01115.01130> devcoordinator: driver 'bt_host' added [00781.912] 01115.01130> devcoordinator: driver 'usb_video' added [00781.912] 01115.01130> devcoordinator: driver 'ath10k_pci' added [00781.912] 01115.01130> devcoordinator: launch devhost 'devhost:pci#11:168c:003e': pid=5926 [00781.912] 01115.01130> devcoordinator: driver 'qmi_usb' added [00781.912] 01115.01130> devcoordinator: driver 'gpu' added [00781.912] 01115.01130> devcoordinator: driver 'bt_hci_intel' added [00781.912] 01115.01130> devcoordinator: driver 'ralink' added [00781.912] 01115.01130> devcoordinator: driver 'mt8167s_gpu' added [00781.912] 01115.01130> devcoordinator: driver 'bt_hci_fake' added [00781.912] 01115.01130> devcoordinator: driver 'wlan' added [00781.912] 01115.01130> devcoordinator: driver 'iwlwifi_pci' added [00781.912] 01115.01130> devcoordinator: driver 'bt_hog' added [00781.912] 01115.01130> devcoordinator: driver 'bt_hci_atheros' added [00781.912] 01115.01130> devcoordinator: driver 'bt_hci_passthrough' added [00781.912] 01115.01130> devcoordinator: fallback driver 'usb_composite' is available [00781.912] 01115.01130> devcoordinator: driver 'usb_composite' added [00781.912] 01115.01130> devcoordinator: fallback driver 'intel_disp' is available [00781.912] 01115.01130> devcoordinator: driver 'intel_disp' added [00781.914] 05926.05944> devhost: trace provider registry begun [00781.915] 05926.05944> ath10k: Probed chip QCA6174 ver: 2.1 [00781.915] 03030.03055> UMS: parent: 'ifc-000' [00781.915] 03030.03055> UMS:Max lun is: 0 [00781.916] 03030.03055> devhost[00:14.0/xhci/usb-bus/002/002/ifc-001] bind driver '/boot/driver/bt-transport-usb.so' failed: -2 [00781.916] 01115.01130> devcoordinator: rpc: bind-driver 'ifc-001' status -2 [00781.918] 03030.06219> UMS: block size is: 0x00000200 [00781.918] 03030.06219> UMS: total blocks is: 30031250 [00781.918] 03030.06219> UMS: total size is: 15376000000 [00781.918] 03030.06219> UMS: read-only: 0 removable: 1 [00781.944] 03030.09060> btatheros: Making visible [00781.944] 03030.09060> btatheros: loaded successfully [00781.945] 03030.09165> [INFO:command_channel.cc(149)] hci: initialized [00781.946] 01299.01313> fshost: /dev/class/block/007: MBR? [00781.949] 01299.01313> fshost: /dev/class/block/009: MBR? [00781.994] 05153.05167> [INFO:namespace_builder.cc(93)] config-data for amber [00782.010] 03030.09165> [WARN:adapter.cc(274)] gap: controller is using legacy HCI version 4.1 [00782.021] 03030.09165> [INFO:acl_data_channel.cc(91)] hci: initialized [00782.074] 05153.05167> [INFO:namespace_builder.cc(93)] config-data for pkg_resolver [00782.192] 13666.13678> [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 [00782.192] 13666.13678> kfill_days=2, start_event_aggregator_worker=1. [00782.248] 05153.05167> [INFO:namespace_builder.cc(93)] config-data for wlancfg [00782.288] 05926.13589> devhost: rpc:load-firmware failed: -25 [00782.288] 05926.13589> devhost: rpc:load-firmware failed: -25 [00782.319] 05153.05167> [INFO:namespace_builder.cc(93)] config-data for mdns [00782.502] 05153.05167> [INFO:namespace_builder.cc(93)] config-data for crashpad_agent [00782.544] 16646.16660> [INFO:main.cc(35)] Trace Manager starting with config: /pkg/data/tracing.config [00782.607] 15679.15695> [INFO:system_metrics_main.cc(23)] Cobalt SystemMetricsDaemon: System metrics daemon created. [00782.619] 17055.17067> wlanstack2 [I]: Starting [00783.133] 05926.13166> ath10k: Unknown eventid: 0x1d019 [00783.136] 05926.13166> ath10k: Unknown eventid: 0x16006 [00783.141] 05926.05944> wlanphy: event loop started [00783.141] 05926.05944> wlanphy_bind [00783.142] 17055.17067> wlanstack2::device [I]: new phy #0: /dev/sys/pci/01:00.0/ath10k-wlanphy/wlanphy [00783.142] 14251.14263> wlancfg got event: OnPhyAdded { phy_id: 0 } [00783.142] 14251.14263> wlancfg: phy 0 added [00783.142] 17055.17067> wlanstack2::service [I]: query_phy(id = 0) [00783.142] 17055.17067> wlanstack2::service [I]: query_phy(id = 0): received a 'QueryResult' from device [00783.143] 14251.14263> wlancfg: received a PhyInfo from phy #0: path is /dev/sys/pci/01:00.0/ath10k-wlanphy/wlanphy [00783.143] 14251.14263> using default wlan config entry for phy [00783.143] 14251.14263> wlancfg: Creating Client iface for phy 0 [00783.148] 05926.05944> wlan_bind [00783.150] 05926.05944> ath10k: adding a station interface (vdev_id=0) ... [00783.152] 05926.05944> wlan: [I] Initialize a client MLME. [00783.152] 05926.18052> wlan: [I] starting MainLoop [00783.153] 05926.05944> wlan: [I] channel opened [00783.153] 17055.17067> wlanstack2::device [I]: new iface #0 with role 'Client': /dev/sys/pci/01:00.0/ath10k-wlanphy/ath10k-wlanmac/wlan [00783.154] 14251.14263> wlancfg got event: OnIfaceAdded { iface_id: 0 } [00783.154] 14251.14263> wlancfg: new iface 0 added successfully [00783.155] 14251.14263> wlancfg: Starting auto-connect loop with 0 saved networks [00800.691] 14654.14666> Starting mDNS on interface ethp001f6 [80fe::5dd6:ffdf:1afe:8642] [00800.691] 14654.14666> [WARNING:garnet/bin/mdns/service/mdns_interface_transceiver_v6.cc(29)] NET-291 IPV6_MULTICAST_LOOP not supported (ENOPROTOOPT), continuing anyway [00800.691] 14654.14666> [WARNING:garnet/bin/mdns/service/mdns_interface_transceiver_v6.cc(50)] NET-2180 IPV6_JOIN_GROUP returned ENODEV, mDNS will not communicate via IPV6 [00804.752] 14654.14666> Starting mDNS on interface ethp001f6 192.168.42.101 [00804.753] 14654.14666> [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 [00804.753] 14654.14666> Starting mDNS on interface ethp001f6 [80fe::5dd6:ffdf:1afe:8642] [00804.753] 14654.14666> [WARNING:garnet/bin/mdns/service/mdns_interface_transceiver_v6.cc(29)] NET-291 IPV6_MULTICAST_LOOP not supported (ENOPROTOOPT), continuing anyway [00804.753] 14654.14666> [WARNING:garnet/bin/mdns/service/mdns_interface_transceiver_v6.cc(50)] NET-2180 IPV6_JOIN_GROUP returned ENODEV, mDNS will not communicate via IPV6 [00804.753] 14654.14666> mDNS: Verifying uniqueness of host name ocean-drank-wick-plug.local. [00805.670] 14654.14666> mDNS: Using unique host name ocean-drank-wick-plug.local. Running tests sequentially. [tb] 2019-04-20 00:24:26.935 INFO [SshConnection | 192.168.42.101] Starting master ssh connection. [connection.py:setup_master_ssh:141] [00817.236] 23424.23436> setsockopt IP_TOS 32: Protocol not available: [tb] 2019-04-20 00:24:27.156 INFO [SshConnection | 192.168.42.101] Starting master ssh connection. [connection.py:setup_master_ssh:141] [00817.465] 23998.24011> setsockopt IP_TOS 32: Protocol not available: [tb] 2019-04-20 00:24:28.378 INFO [SshConnection | 192.168.42.101] Starting master ssh connection. [connection.py:setup_master_ssh:141] [00818.672] 25060.25074> setsockopt IP_TOS 32: Protocol not available: [tb] 2019-04-20 00:24:28.606 INFO [SshConnection | 192.168.42.102] Starting master ssh connection. [connection.py:setup_master_ssh:141] [00996.704] 23308.23320> setsockopt IP_TOS 32: Protocol not available: [tb] 2019-04-20 00:24:28.834 INFO [SshConnection | 192.168.42.102] Starting master ssh connection. [connection.py:setup_master_ssh:141] [00996.919] 23883.23896> setsockopt IP_TOS 32: Protocol not available: [tb] 2019-04-20 00:24:30.066 INFO [SshConnection | 192.168.42.102] Starting master ssh connection. [connection.py:setup_master_ssh:141] [00998.148] 24937.24952> setsockopt IP_TOS 32: Protocol not available: [tb] 2019-04-20 00:24:30.305 INFO Controller FuchsiaDevice: [{'ip': '192.168.42.101'}, {'ip': '192.168.42.102'}] [base_test.py:register_controller:396] [tb] 2019-04-20 00:24:30.308 INFO ==========> Sl4fSanityTest <========== [base_test.py:run:967] [tb] 2019-04-20 00:24:30.310 INFO Congratulations! Fuchsia controllers have been initialized successfully! [Sl4fSanityTest.py:setup_class:41] [tb] 2019-04-20 00:24:30.312 INFO [Test Case] test_example [base_test.py:exec_one_testcase:662] [tb] 2019-04-20 00:24:30.313 INFO Congratulations! You've run your first test. [Sl4fSanityTest.py:test_example:46] [tb] 2019-04-20 00:24:30.316 INFO [Test Case] test_example PASS [base_test.py:_on_pass:542] [tb] 2019-04-20 00:24:30.318 INFO Summary for test class Sl4fSanityTest: ControllerInfo {'FuchsiaDevice': [{'ip': '192.168.42.101'}, {'ip': '192.168.42.102'}]}, Requested 1, Executed 1, Passed 1, Failed 0, Skipped 0, Blocked 0, Unknown 0, Errors 0 [base_test.py:run:1027] [tb] 2019-04-20 00:24:30.324 INFO [SshConnection | 192.168.42.101] Starting master ssh connection. [connection.py:setup_master_ssh:141] [00820.637] 25635.25650> setsockopt IP_TOS 32: Protocol not available: [tb] 2019-04-20 00:24:30.548 INFO [SshConnection | 192.168.42.101] Starting master ssh connection. [connection.py:setup_master_ssh:141] [00820.858] 26218.26231> setsockopt IP_TOS 32: Protocol not available: [tb] 2019-04-20 00:24:31.774 INFO [SshConnection | 192.168.42.101] Starting master ssh connection. [connection.py:setup_master_ssh:141] [00822.068] 27274.27290> setsockopt IP_TOS 32: Protocol not available: [tb] 2019-04-20 00:24:32.017 INFO [SshConnection | 192.168.42.102] Starting master ssh connection. [connection.py:setup_master_ssh:141] [01000.116] 25520.25532> setsockopt IP_TOS 32: Protocol not available: [tb] 2019-04-20 00:24:32.243 INFO [SshConnection | 192.168.42.102] Starting master ssh connection. [connection.py:setup_master_ssh:141] [01000.333] 26096.26109> setsockopt IP_TOS 32: Protocol not available: [tb] 2019-04-20 00:24:33.467 INFO [SshConnection | 192.168.42.102] Starting master ssh connection. [connection.py:setup_master_ssh:141] [01001.548] 27156.27169> setsockopt IP_TOS 32: Protocol not available: [tb] 2019-04-20 00:24:33.693 INFO Controller FuchsiaDevice: [{'ip': '192.168.42.101'}, {'ip': '192.168.42.102'}] [base_test.py:register_controller:396] [tb] 2019-04-20 00:24:33.694 INFO Running testbed setup with two fuchsia devices [BleFuchsiaTest.py:__init__:38] [tb] 2019-04-20 00:24:33.695 INFO ==========> BleFuchsiaTest <========== [base_test.py:run:967] [tb] 2019-04-20 00:24:33.695 INFO [Test Case] test_fuchsia_gatt_fuchsia_periph [base_test.py:exec_one_testcase:662] [00824.004] 03030.03055> bt-transport-usb: timed out: ZX_ERR_TIMED_OUT [tb] 2019-04-20 00:24:33.842 INFO Publish result: {'id': '0', 'error': None, 'result': None} [BleFuchsiaTest.py:test_fuchsia_gatt_fuchsia_periph:93] [tb] 2019-04-20 00:24:33.855 INFO Fuchsia advertising name: testADV1234 [BleFuchsiaTest.py:test_fuchsia_gatt_fuchsia_periph:102] [01001.963] 03025.03048> bt-transport-usb: timed out: ZX_ERR_TIMED_OUT [01002.027] 03025.09426> [INFO:low_energy_discovery_manager.cc(91)] gap-le: start discovery [tb] 2019-04-20 00:24:35.030 INFO Successfully found advertisement! name, id: testADV1234, b6c2b1646094b9d5 [bt_test_utils.py:le_scan_for_device_by_name:43] [tb] 2019-04-20 00:24:35.660 INFO Connecting returned status: {'id': '3', 'error': None, 'result': None} [BleFuchsiaTest.py:test_fuchsia_gatt_fuchsia_periph:115] [01003.670] 03025.09426> [INFO:low_energy_connection_manager.cc(751)] gap-le: new connection (LE link - handle: 0x0002, role: master, address: (LE rand) 4C:87:CD:8D:A7:1E, interval: 45.00 ms, latency: 0.00 ms, timeout: 420 ms) [tb] 2019-04-20 00:24:36.002 INFO Listing services returned: {'id': '4', 'error': None, 'result': [{'id': 1, 'uuid_type': '00001801-0000-1000-8000-00805f9b34fb', 'primary': True}, {'id': 5, 'uuid_type': '0000180f-0000-1000-8000-00805fffffff', 'primary': True}]} [BleFuchsiaTest.py:test_fuchsia_gatt_fuchsia_periph:118] [tb] 2019-04-20 00:24:36.009 INFO Disconnect status: {'id': '5', 'error': None, 'result': None} [BleFuchsiaTest.py:test_fuchsia_gatt_fuchsia_periph:121] [tb] 2019-04-20 00:24:36.033 INFO [Test Case] test_fuchsia_gatt_fuchsia_periph PASS [base_test.py:_on_pass:542] [tb] 2019-04-20 00:24:36.034 INFO [Test Case] test_fuchsia_publish_service [base_test.py:exec_one_testcase:662] [tb] 2019-04-20 00:24:36.041 INFO Publish result: {'id': '3', 'error': None, 'result': None} [BleFuchsiaTest.py:test_fuchsia_publish_service:56] [tb] 2019-04-20 00:24:36.056 INFO [Test Case] test_fuchsia_publish_service PASS [base_test.py:_on_pass:542] [tb] 2019-04-20 00:24:36.057 INFO [Test Case] test_fuchsia_scan_fuchsia_adv [base_test.py:exec_one_testcase:662] [01004.020] 03025.09426> [INFO:low_energy_connection_manager.cc(590)] gap-le: all refs dropped on connection: (LE link - handle: 0x0002, role: master, address: (LE rand) 4C:87:CD:8D:A7:1E, interval: 45.00 ms, latency: 0.00 ms, timeout: 420 ms) [01004.063] 03025.09426> [INFO:low_energy_connection_manager.cc(848)] gap-le: link disconnected - status: "success", handle: 0x0002, reason: 0x16 [tb] 2019-04-20 00:24:36.067 INFO Fuchsia advertising name: testADV1234 [BleFuchsiaTest.py:test_fuchsia_scan_fuchsia_adv:69] [00826.246] 03030.09165> [INFO:low_energy_connection_manager.cc(590)] gap-le: all refs dropped on connection: (LE link - handle: 0x0002, role: slave, address: (LE publ) 00:0E:8E:89:3F:A6, interval: 45.00 ms, latency: 0.00 ms, timeout: 420 ms) [00826.276] 03030.09187> [WARN:acl_data_channel.cc(243)] hci: controller reported sent packets on unknown connection handle! [00826.281] 03030.09165> [INFO:low_energy_connection_manager.cc(848)] gap-le: link disconnected - status: "success", handle: 0x0002, reason: 0x16 [01004.084] 03025.09426> [INFO:low_energy_discovery_manager.cc(91)] gap-le: start discovery [tb] 2019-04-20 00:24:38.091 INFO Successfully found advertisement! name, id: testADV1234, b6c2b1646094b9d5 [bt_test_utils.py:le_scan_for_device_by_name:43] [tb] 2019-04-20 00:24:38.116 INFO [Test Case] test_fuchsia_scan_fuchsia_adv PASS [base_test.py:_on_pass:542] [tb] 2019-04-20 00:24:38.118 INFO Summary for test class BleFuchsiaTest: ControllerInfo {'FuchsiaDevice': [{'ip': '192.168.42.101'}, {'ip': '192.168.42.102'}]}, Requested 3, Executed 3, Passed 3, Failed 0, Skipped 0, Blocked 0, Unknown 0, Errors 0 [base_test.py:run:1027] [tb] 2019-04-20 00:24:38.134 INFO Summary for test run tb@2019-04-20_00-24-25-460: ControllerInfo {'FuchsiaDevice': [{'ip': '192.168.42.101'}, {'ip': '192.168.42.102'}]}, Requested 4, Executed 4, Passed 4, Failed 0, Skipped 0, Blocked 0, Unknown 0, Errors 0 /etc/connectivity/acts/tools/test/connectivity/acts/framework/acts/controllers/buds_lib/test_actions/bt_utils.py:201: SyntaxWarning: assertion is always true, perhaps remove parentheses? assert (True is pri_device.droid.bluetoothUnbond(target_address), Command succeeded! [00000.000] 00000.00000> zbi: @ 0xffffff80012f2000 (17482848 bytes) [00000.000] 00000.00000> UART: FIFO depth 16 [00000.000] 00000.00000> PMM: boot reserve add [0x100000, 0x2c5fff] [00000.000] 00000.00000> PMM: boot reserve add [0x12f2000, 0x239efff] [00000.000] 00000.00000> PMM: arena too small to be useful (size 4096) [00000.000] 00000.00000> PMM: pmm_add_arena failed to initialize arena [00000.000] 00000.00000> MEM: Failed to add pmm range at 0x7ffff000 size 0x1000 [00000.000] 00000.00000> PMM: boot reserve marking WIRED [0x100000, 0x2c5fff] [00000.000] 00000.00000> PMM: boot reserve marking WIRED [0x12f2000, 0x239efff] [00000.000] 00000.00000> [00000.000] 00000.00000> welcome to Zircon [00000.000] 00000.00000> [00000.000] 00000.00000> KASLR: .text section at 0xffffffff00100000 [00000.000] 00000.00000> INIT: cpu 0, calling hook 0xffffffff001aa428 (global_prng_seed) at level 0x30000, flags 0x1 [00000.000] 00000.00000> initializing vm pre-heap