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

DEBUG: config flag: /etc/botanist/config.json DEBUG: waiting for "summary.json" 2019/04/12 01:38:37 attempting to send <<netboot>>cmdline... 2019/04/12 01:38:37 done 2019/04/12 01:38:37 attempting to send <<image>>sparse.fvm... [0.000] 00000.00000> zbi: @ 0xffffff80012f2000 (17482848 bytes) [0.000] 00000.00000> UART: FIFO depth 16 [0.000] 00000.00000> PMM: boot reserve add [0x100000, 0x2c5fff] [0.000] 00000.00000> PMM: boot reserve add [0x12f2000, 0x239efff] [0.000] 00000.00000> PMM: arena too small to be useful (size 4096) [0.000] 00000.00000> PMM: pmm_add_arena failed to initialize arena [0.000] 00000.00000> MEM: Failed to add pmm range at 0x7ffff000 size 0x1000 [0.000] 00000.00000> PMM: boot reserve marking WIRED [0x100000, 0x2c5fff] [0.000] 00000.00000> PMM: boot reserve marking WIRED [0x12f2000, 0x239efff] [0.000] 00000.00000> welcome to Zircon [0.000] 00000.00000> KASLR: .text section at 0xffffffff00100000 [0.000] 00000.00000> INIT: cpu 0, calling hook 0xffffffff001aa428 (global_prng_seed) at level 0x30000, flags 0x1 [0.000] 00000.00000> initializing vm pre-heap [0.000] 00000.00000> VM: marking boot alloc used range [0x239f000, 0x239f100) [0.000] 00000.00000> INIT: cpu 0, calling hook 0xffffffff00147abc (elf_build_id) at level 0x4fffe, flags 0x1 [0.000] 00000.00000> INIT: cpu 0, calling hook 0xffffffff00147c48 (version) at level 0x4ffff, flags 0x1 [0.000] 00000.00000> version: [0.000] 00000.00000> arch: x86 [0.000] 00000.00000> platform: pc [0.000] 00000.00000> target: pc [0.000] 00000.00000> project: x64 [0.000] 00000.00000> buildid: git-13ee3dc5e4c46bf127977ad28645c47442ec517d [0.000] 00000.00000> ELF build ID: 5f3e39bd4ed89d3b8122947842f1eac846a04683 [0.000] 00000.00000> initializing heap [0.000] 00000.00000> INIT: cpu 0, calling hook 0xffffffff00102e1c (x86_resource_init) at level 0x50000, flags 0x1 [0.000] 00000.00000> INIT: cpu 0, calling hook 0xffffffff001a9630 (console) at level 0x50000, flags 0x1 [0.000] 00000.00000> initializing vm [0.000] 00000.00000> VM: reserving kernel region [0xffffffff00100000, 0xffffffff001ee000) flags 0x28 name 'kernel_code' [0.000] 00000.00000> VM: reserving kernel region [0xffffffff001ee000, 0xffffffff00232000) flags 0x8 name 'kernel_rodata' [0.000] 00000.00000> VM: reserving kernel region [0xffffffff00232000, 0xffffffff00242000) flags 0x18 name 'kernel_data' [0.000] 00000.00000> VM: reserving kernel region [0xffffffff00242000, 0xffffffff002c6000) flags 0x18 name 'kernel_bss' [0.000] 00000.00000> INIT: cpu 0, calling hook 0xffffffff00103ae0 (display_memtype) at level 0x60001, flags 0x1 [0.000] 00000.00000> INIT: cpu 0, calling hook 0xffffffff00138fa0 (acpi_tables) at level 0x60001, flags 0x1 [0.000] 00000.00000> INIT: cpu 0, calling hook 0xffffffff00101c40 (hpet) at level 0x60002, flags 0x1 [0.000] 00000.00000> INIT: cpu 0, calling hook 0xffffffff00102000 (apic) at level 0x60002, flags 0x1 [0.000] 00000.00000> x2APIC enabled [0.000] 00000.00000> INIT: cpu 0, calling hook 0xffffffff001061b4 (timer) at level 0x60003, flags 0x1 [0.000] 00000.00000> HPET frequency: 23999 ticks/ms [0.000] 00000.00000> TSC frequency: 2712000 ticks/ms [20.220] 00000.00000> timer features: constant_tsc 1 invariant_tsc 1 tsc_deadline 1 [20.220] 00000.00000> Using TSC as wallclock [20.220] 00000.00000> initializing kernel [20.220] 00000.00000> initializing mp [20.220] 00000.00000> initializing timers [20.220] 00000.00000> INIT: cpu 0, calling hook 0xffffffff0013c578 (debuglog) at level 0x7ffff, flags 0x1 [20.220] 00000.00000> INIT: cpu 0, calling hook 0xffffffff00195518 (thread_set_priority_experiment) at level 0x7ffff, flags 0x1 [20.220] 00000.00000> thread set priority experiment is : ENABLED [20.220] 00000.00000> INIT: cpu 0, calling hook 0xffffffff001aa67c (global_prng_thread_safe) at level 0x7ffff, flags 0x1 [20.220] 00000.00000> creating bootstrap completion thread [20.563] 00000.00000> top of bootstrap2() [20.563] 00000.00000> INIT: cpu 0, calling hook 0xffffffff0013151c (dpc) at level 0x80000, flags 0x1 [20.576] 00000.00000> INIT: cpu 0, calling hook 0xffffffff00152978 (libobject) at level 0x80000, flags 0x1 [20.576] 00000.00000> OOM: started thread [20.590] 00000.00000> Processor Model Info: type 0 family 0x6 model 0xe stepping 0x9 [20.590] 00000.00000> display_family 0x6 display_model 0x8e [20.590] 00000.00000> Vendor: Intel [20.590] 00000.00000> Microarch: Kaby Lake [20.590] 00000.00000> F/M/S: 6/8e/9 [20.590] 00000.00000> Brand: Intel(R) Core(TM) i5-7300U CPU @ 2.60GHz [20.590] 00000.00000> Features: fpu sse sse2 sse3 ssse3 sse4.1 sse4.2 mmx avx avx2 fxsr pcid xsave mon aesni clflush [20.590] 00000.00000> clflushopt fsgsbase tsc_adj smep smap erms rdrand rdseed syscall nx huge rdtscp [20.590] 00000.00000> invar_tsc tsc_deadline x2apic vmx pt hwp [20.590] 00000.00000> initializing platform [20.590] 00000.00000> INIT: cpu 0, calling hook 0xffffffff001101f4 (x86_perfmon) at level 0x90000, flags 0x1 [20.590] 00000.00000> PMU: version 4 [20.590] 00000.00000> UART: started IRQ driven RX [20.590] 00000.00000> UART: started IRQ driven TX [20.590] 00000.00000> cpu topology: [20.590] 00000.00000> 0: apic id 0x0 package 0 node 0 core 0 smt 0 BSP [20.590] 00000.00000> 1: apic id 0x2 package 0 node 0 core 1 smt 0 [20.590] 00000.00000> 2: apic id 0x1 package 0 node 0 core 0 smt 1 [20.590] 00000.00000> 3: apic id 0x3 package 0 node 0 core 1 smt 1 [20.590] 00000.00000> Found 4 cpus [20.590] 00000.00000> booting apic ids: 0x2 0x1 0x3 [20.605] 00000.00000> entering scheduler on cpu 2 [20.607] 00000.00000> entering scheduler on cpu 3 [20.607] 00000.00000> entering scheduler on cpu 1 [20.610] 00000.00000> smbios: manufacturer="Intel Corporation" product="NUC7i5DNKE" [20.610] 00000.00000> initializing target [20.610] 00000.00000> INIT: cpu 0, calling hook 0xffffffff001053a0 (x86_pcie_init) at level 0xa0000, flags 0x1 [20.610] 00000.00000> moving to last init level [20.610] 00000.00000> INIT: cpu 0, calling hook 0xffffffff00144140 (ktrace) at level 0xc0000, flags 0x1 [20.613] 00000.00000> ktrace: buffer at 0xffffff994d885000 (33554432 bytes) [20.613] 00000.00000> INIT: cpu 0, calling hook 0xffffffff00147ab4 (userboot) at level 0xc0000, flags 0x1 [20.613] 00000.00000> userboot: ramdisk 0x10ad000 @ 0xffffff80012f2000 [20.614] 00000.00000> userboot: userboot rodata 0 @ [0x712c93055000,0x712c93058000) [20.614] 00000.00000> userboot: userboot code 0x3000 @ [0x712c93058000,0x712c93063000) [20.614] 00000.00000> userboot: vdso/full rodata 0 @ [0x712c93063000,0x712c9306a000) [20.614] 00000.00000> userboot: vdso/full code 0x7000 @ [0x712c9306a000,0x712c9306b000) [20.614] 00000.00000> userboot: entry point @ 0x712c93058c10 [20.614] 00000.00000> INIT: cpu 0, calling hook 0xffffffff001aa030 (kernel_shell) at level 0xc0000, flags 0x1 [20.614] 01036.01043> userboot: option "netsvc.disable=true" [20.614] 01036.01043> userboot: option "zircon.system.disable-automount=true" [20.614] 01036.01043> userboot: option "zircon.autorun.boot=/boot/infra/setup" [20.614] 01036.01043> userboot: option "kernel.serial=legacy" [20.614] 01036.01043> userboot: option "http://192.168.42.1/multiboot/d4%3A5d%3Adf%3A1a%3A32%3A1a=" [20.614] 01036.01043> userboot: option "multiboot.boot_loader_name=iPXE+1.0.0++(d2063)" [20.653] 01036.01043> userboot: searching bootfs for 'bin/bootsvc' [20.653] 01036.01043> userboot: 'bin/bootsvc' has PT_INTERP "lib/ld.so.1" [20.653] 01036.01043> userboot: searching bootfs for 'lib/ld.so.1' [20.653] 01036.01043> userboot: userboot: loaded lib/ld.so.1 at 0x52eddad38000, entry point 0x52eddadbe0d3 [20.653] 01036.01043> userboot: userboot: loaded vDSO at 0x7d139a0d3000, entry point 0x0 [20.653] 01036.01043> userboot: process bin/bootsvc started. [20.653] 01036.01043> userboot: waiting for loader-service requests... [20.653] 01036.01043> userboot: searching bootfs for 'lib/libasync-default.so' [20.653] 01036.01043> userboot: searching bootfs for 'lib/libfdio.so' [20.653] 01036.01043> userboot: searching bootfs for 'lib/liblaunchpad.so' [20.653] 01036.01043> userboot: searching bootfs for 'lib/libtrace-engine.so' [20.653] 01050.01053> dso: id=18de7d58f51e8ba5c4f6afdd0cc8440f482c2b45 base=0x0000507d42a40000 name=<application> [20.653] 01050.01053> dso: id=c189f51f19d10785d93b5235ad1b46dca4451b00 base=0x00002fb9e004a000 name=libasync-default.so [20.653] 01050.01053> dso: id=40ab5fa3b61f12fef4a44477a687f608661cd450 base=0x00007d139a0d3000 name=<vDSO> [20.653] 01050.01053> dso: id=67a12284bce140fc32aaaeac223e0e8f85cb5085 base=0x000052eddad38000 name=libc.so [20.653] 01050.01053> dso: id=27787977e95f3b9563c9e0bd4d34ec92b7e9ad88 base=0x00007bb280485000 name=libfdio.so [20.653] 01050.01053> dso: id=6fc2232dc8c1bc5c6adb8ad50ca794b5a260ee4f base=0x000027bac1bbc000 name=liblaunchpad.so [20.653] 01050.01053> dso: id=c9042b83fe01206008fcefb16395238417248169 base=0x000004920b9f9000 name=libtrace-engine.so [20.653] 01050.01053> bootsvc: Starting... [20.653] 01036.01043> userboot: loader-service channel peer closed [20.653] 01036.01043> userboot: finished! [20.653] 01050.01053> bootsvc: Creating bootfs service... [20.654] 01050.01053> bootsvc: Processing bootdata... [20.654] 01050.01053> bootsvc: Loading boot cmdline overrides... [20.654] 01050.01053> bootsvc: Loading kernel VMOs... [20.654] 01050.01053> bootsvc: Creating loader service... [20.654] 01050.01053> bootsvc: Launching next process... [20.654] 01050.01096> bootsvc: launched bin/devmgr [20.655] 01104.01117> devmgr: main() [20.655] 01104.01117> cmdline: netsvc.disable=true [20.655] 01104.01117> cmdline: zircon.system.disable-automount=true [20.655] 01104.01117> cmdline: zircon.autorun.boot=/boot/infra/setup [20.655] 01104.01117> cmdline: kernel.serial=legacy [20.655] 01104.01117> cmdline: http://192.168.42.1/multiboot/d4%3A5d%3Adf%3A1a%3A32%3A1a= [20.655] 01104.01117> cmdline: multiboot.boot_loader_name=iPXE+1.0.0++(d2063) [20.655] 01104.01117> devmgr: coordinator_init() [20.655] 01104.01117> devmgr: init [20.655] 01104.01117> devmgr: svc init [20.655] 01104.01117> devmgr: launch /boot/bin/svchost (svchost) OK [20.655] 01104.01117> devmgr: vfs init [20.655] 01104.01117> devmgr: launch /boot/bin/fshost (fshost) OK [20.655] 01104.01221> devmgr: shell startup [20.657] 01182.01202> fshost: started. [20.657] 01104.01213> devmgr: launch /boot/bin/pwrbtn-monitor (pwrbtn-monitor) OK [20.658] 01104.01235> devmgr: launch /boot/bin/virtual-console (virtual-console) OK [20.658] 01104.01235> zircon.autorun.boot: starting '/boot/infra/setup'... [20.658] 01104.01235> devmgr: launch /boot/infra/setup (autorun:boot) OK [20.661] 01104.01117> devcoord: launch devhost 'devhost:sys': pid=2049 [20.661] 01104.01117> devcoord: launch devhost 'devhost:test': pid=2082 [20.661] 01104.01117> devcoord: launch devhost 'devhost:root': pid=2115 [20.662] 01104.01117> devcoord: launch devhost 'devhost:misc': pid=2168 [20.663] 02049.02073> devhost: trace provider registry begun [20.663] 02082.02105> devhost: trace provider registry begun [20.664] 02115.02153> devhost: trace provider registry begun [20.666] 02168.02217> devhost: trace provider registry begun [20.667] 01104.01221> devmgr: launch /boot/bin/sh (sh:console) OK [20.723] 02049.02073> acpi-bus: not using IOMMU [20.728] 02049.02073> acpi-pwrbtn: initialized [20.733] 02049.02073> WARNING: ACPI found bad _CRS address entry [20.740] 02049.02073> WARNING: ACPI found bad _CRS address entry [20.750] 02049.02073> acpi: published device pci(0x7c5ae2d26200), parent=proxy(0x7c5ae2d22540), handle=0x7c5ae2d5ec30 [20.752] 02049.02073> acpi: published device rtc(0x7c5ae2d21080), parent=acpi(0x7c5ae2d22780), handle=0x7c5ae2d775b0 [20.753] 02049.02073> acpi-ec: initialized [20.754] 02049.02073> acpi: failed to create NHLT VMO (res -10) [20.754] 02049.02073> acpi: failed to publish NHLT metadata [20.756] 02049.02073> [sysmem_init 28] async_get_default_dispatcher(): 0x7c5ae2d150a0 [20.756] 02049.02073> [sysmem_bind 40] sysmem_bind() [20.756] 02049.02073> acpi-bus: sysmem_register_protocol() intentionally ignored for now. [20.757] 02049.02073> PMU: 7 arch events [20.757] 02049.02073> PMU: arch event id range: 1-7 [20.757] 02049.02073> PMU: 102 model events [20.757] 02049.02073> PMU: model event id range: 1-241 [20.757] 02049.02073> Intel Processor Trace configuration for this chipset: [20.757] 02049.02073> mtc_freq_mask: 0x249 [20.757] 02049.02073> cyc_thresh_mask: 0x3fff [20.757] 02049.02073> psb_freq_mask: 0x3f [20.757] 02049.02073> num addr ranges: 2 [20.757] 01104.01117> devcoord: launch devhost 'devhost:pci#1:8086:5916': pid=2837 [20.757] 01104.01117> devcoord: launch devhost 'devhost:pci#3:8086:9d2f': pid=2883 [20.758] 01104.01117> devcoord: launch devhost 'devhost:pci#5:8086:9d60': pid=2945 [20.758] 01104.01117> devcoord: launch devhost 'devhost:pci#6:8086:9d61': pid=3016 [20.759] 02837.02860> devhost: trace provider registry begun [20.760] 02883.02917> devhost: trace provider registry begun [20.760] 01104.01117> devcoord: launch devhost 'devhost:pci#9:8086:9d03': pid=3102 [20.760] 02945.02978> devhost: trace provider registry begun [20.761] 01104.01117> devcoord: launch devhost 'devhost:pci#14:8086:9d71': pid=3234 [20.761] 03016.03056> devhost: trace provider registry begun [20.762] 03102.03165> devhost: trace provider registry begun [20.762] 01104.01117> devcoord: launch devhost 'devhost:pci#16:8086:156f': pid=3307 [20.763] 03102.03165> ahci: using MSI interrupt [20.763] 02945.02978> initialized intel serialio i2c driver, reg=0x699c4d840000 regsize=4096 [20.764] 03016.03056> initialized intel serialio i2c driver, reg=0x5423ecbea000 regsize=4096 [20.765] 03307.03369> devhost: trace provider registry begun [20.765] 03234.03279> devhost: trace provider registry begun [20.778] 01241.01544> vc: new input device /dev/class/input/000 [20.778] 03234.03279> [IHDA DSP 00:1f.3] Failed to fetch NHLT (res -25) [20.778] 03234.03279> devhost[00:1f.3/intel-hda-000/intel-sst-dsp-000] bind driver '/boot/driver/dsp.so' failed: -25 [20.778] 01104.01117> devcoord: rpc: bind-driver 'intel-sst-dsp-000' status -25 [20.788] 02883.03743> * found USB device (0x18d1:0xa002, USB 2.0) config 1 [20.788] 02883.03743> * found USB device (0x18d1:0xa003, USB 3.0) config 1 [20.870] 01241.01544> vc: new display device /dev/class/display-controller/000/virtcon [21.010] 02837.04142> i915: Found DP monitor [21.010] 02837.04142> i915: Display 1 connected [21.011] 02837.04142> i915: MST not supported [22.069] 01241.01544> vc: Successfully attached to display 1 [22.250] 02883.03743> * found USB device (0x0781:0x5571, USB 2.0) config 1 [22.251] 02883.02917> UMS: parent: 'ifc-000' [22.251] 02883.02917> UMS:Max lun is: 0 [22.501] 02883.03743> * found USB device (0x8087:0x0a2b, USB 2.0) config 1 [22.502] 02883.02917> devhost[00:14.0/xhci/usb-bus/002/002/ifc-001] bind driver '/boot/driver/bt-transport-usb.so' failed: -2 [22.502] 01104.01117> devcoord: rpc: bind-driver 'ifc-001' status -2 [22.767] 03016.03056> intel-i2c-controller: intel_serialio_i2c_slave_transfer: -21 [22.767] 03016.03056> i2c-hid: could not read HID descriptor: 0 [22.767] 03016.03056> devhost[00:15.1/i2c-bus-9d61/004c] bind driver '/boot/driver/i2c-hid.so' failed: -2 [22.767] 01104.01117> devcoord: rpc: bind-driver '004c' status -2 [22.768] 02945.02978> intel-i2c-controller: intel_serialio_i2c_slave_transfer: -21 [22.768] 02945.02978> i2c-hid: could not read HID descriptor: 0 [22.768] 02945.02978> devhost[00:15.0/i2c-bus-9d60/0020] bind driver '/boot/driver/i2c-hid.so' failed: -2 [22.768] 01104.01117> devcoord: rpc: bind-driver '0020' status -2 [22.781] 03102.03503> sata2: dev info [22.781] 03102.03503> serial=711430953080 8 [22.781] 03102.03503> firmware rev=1Q01A7 0 [22.781] 03102.03503> model id=IBIW NSS D [22.781] 03102.03503> major=0x3f0 ACS2 DMA 32 commands [22.781] 03102.03503> LBA48 234441648 sectors, sector size=512 [22.783] 04413.04427> paver:[InitializeGpt] Located GPT is invalid; Attempting to initialize [22.784] 01104.01117> devcoord: dc_bind_device() '/boot/driver/gpt.so' [22.784] 03102.03165> gpt: device_get_metadata failed (-25) [22.785] 04413.04427> paver:[Initialize] Successfully initialized EFI Device Partitioner [22.785] 01104.01117> devcoord: dc_bind_device() '' [22.785] 01182.01202> devmgr: /dev/class/block/000: GPT? [22.785] 01104.01117> devcoord: dc_bind_device() '/boot/driver/gpt.so' [22.786] 03102.03165> gpt: device_get_metadata failed (-25) [22.788] 04565.04584> 34+0 records in [22.788] 04565.04584> 34+0 records out [22.788] 04565.04584> 17408 bytes copied [22.789] 04674.04688> Failed to seek on output [22.789] 04674.04688> 0+0 records in [22.789] 04674.04688> 0+0 records out [22.789] 04674.04688> 0 bytes copied [22.790] 04744.04758> netifc: ? /dev/class/ethernet/000 [22.790] 04744.04758> netifc: create 512 eth buffers [22.790] 04744.04758> macaddr: d4:5d:df:1a:32:1a [22.790] 04744.04758> ip6addr: fe80::d65d:df4d:fe1a:321a [22.790] 04744.04758> snmaddr: ff02::1:ff1a:321a [22.790] 04744.04758> netsvc: using /dev/class/ethernet/000 [22.790] 04744.04758> _ _ _ [22.790] 04744.04758> | | | | | [22.790] 04744.04758> _______ __| | |__ ___ ___ | |_ [22.790] 04744.04758> |_ / _ \/ _` | '_ \ / _ \ / _ \| __| [22.790] 04744.04758> / / __/ (_| | |_) | (_) | (_) | |_ [22.790] 04744.04758> /___\___|\__,_|_.__/ \___/ \___/ \__| [22.790] 04744.04758> zedboot: version: 0.7.13 [22.790] 04744.04758> netsvc: nodename='ocean-bacon-sky-dawn' [22.790] 04744.04758> netsvc: will not advertise [22.790] 04744.04758> netsvc: start [23.253] 02883.04246> UMS: block size is: 0x00000200 [23.253] 02883.04246> UMS: total blocks is: 15630336 [23.253] 02883.04246> UMS: total size is: 8002732032 [23.253] 02883.04246> UMS: read-only: 0 removable: 1 [23.254] 01182.01202> devmgr: /dev/class/block/001: MBR? [23.254] 01104.01117> devcoord: dc_bind_device() '/boot/driver/mbr.so' [23.257] 01182.01202> devmgr: /dev/class/block/003: MBR? [23.257] 01104.01117> devcoord: dc_bind_device() '/boot/driver/mbr.so' [2476.938] 04744.04758> netsvc: handling tftp request failed (file might not exist) [2476.938] 04744.04758> netsvc: close, but no open file [2476.938] 04744.04758> netsvc: metrics: {"inorderblks": 0,"oooblks": 0,"ack": 0,"nack": 0,"timeouts": 0,"sas": 0,"inorderbytes": 0} [2476.938] 04744.04758> netsvc: tftp write of file <<netboot>>cmdline completed [2476.938] 04744.04758> netsvc: metrics: {"inorderblks": 1,"oooblks": 0,"ack": 1,"nack": 0,"timeouts": 0,"sas": 0,"inorderbytes": 55} [2476.938] 04744.04758> netsvc: Running FVM Paver [2476.940] 04744.04932> paver:[InitializeGpt] Located GPT is invalid; Attempting to initialize [2476.941] 01104.01117> devcoord: dc_bind_device() '' [2476.941] 01104.01117> devcoord: dc_bind_device() '/boot/driver/gpt.so' [2476.941] 03102.03165> gpt: device_get_metadata failed (-25) [2476.942] 01182.01202> devmgr: /dev/class/block/000: GPT? [2476.942] 01104.01117> devcoord: dc_bind_device() '/boot/driver/gpt.so' [2476.942] 03102.03165> devhost: rpc:bind-device failed: -20 [2476.942] 04744.04932> paver:[Initialize] Successfully initialized EFI Device Partitioner [2476.942] 04744.04932> paver:[PartitionPave] Paving partition. [2476.942] 04744.04932> paver:[FindFirstFit] Looking for space [2476.942] 04744.04932> paver:[FindFirstFit] Sorting [2476.942] 04744.04932> paver:[FindFirstFit] Partition[0] From Block [0, 34) ... (next partition starts at block 234441614) [2476.943] 04744.04932> paver:[FindFirstFit] There are 234441580 free blocks (16777216 requested) [2476.943] 04744.04932> paver:[AddPartition] Found space in GPT - OK 234441580 @ 34 [2476.943] 04744.04932> paver:[AddPartition] Final space in GPT - OK 16777216 @ 34 [2476.943] 04744.04932> paver:[AddPartition] Added partition, waiting for bind [2476.943] 01104.01117> devcoord: dc_bind_device() '' [2476.943] 01182.01202> devmgr: /dev/class/block/000: GPT? [2476.943] 01104.01117> devcoord: dc_bind_device() '/boot/driver/gpt.so' [2476.944] 03102.03165> gpt: device_get_metadata failed (-25) [2476.945] 04744.04932> paver:[AddPartition] Added partition, waiting for bind - OK [2476.945] 04744.04932> paver:[PartitionPave] Streaming partitions... [2476.945] 04912.04926> Found compressed file [2476.945] 04744.04932> paver:[FvmStreamPartitions] Header Validated - OK [2476.945] 04744.04932> paver:[FvmPartitionFormat] Initializing partition as FVM [2476.947] 01104.01117> devcoord: dc_bind_device() '/boot/driver/fvm.so' [2477.949] 04744.04932> paver:[FvmStreamPartitions] Partitions pre-validated successfully: Enough space exists to pave. [2477.949] 04744.04932> paver:[AllocatePartitions] Allocating partition blobfs consisting of 1 slices [2477.952] 04744.04932> paver:[AllocatePartitions] Allocating partition minfs consisting of 1 slices [2477.953] 04744.04932> paver:[AllocatePartitions] Creating zxcrypt volume [2477.955] 03102.03165> devhost_get_handles(0x5119204c09c0:block) open path='zxcrypt/block', r=-2 [2477.955] 01104.01117> devcoord: dc_bind_device() '/boot/driver/zxcrypt.so' [2477.955] 03102.03165> devhost_get_handles(0x5119204c09c0:block) open path='zxcrypt', r=-2 [2477.959] 04744.04932> paver:[FvmStreamPartitions] Partition space pre-allocated successfully. [2477.959] 04744.04932> paver:[FvmStreamPartitions] Streaming partition 0 [2477.959] 04744.04932> paver:[StreamFvmPartition] Writing extent 0... [2477.959] 04744.04938> netsvc: paver write progress 0.1% [2477.960] 04744.04932> paver:[StreamFvmPartition] 8192 bytes written, 8380416 zeroes left [2477.986] 04744.04932> paver:[StreamFvmPartition] Writing extent 1... [2477.986] 04744.04932> paver:[StreamFvmPartition] 8192 bytes written, 8380416 zeroes left [2478.003] 04744.04932> paver:[StreamFvmPartition] Writing extent 2... [2478.008] 04744.04932> paver:[StreamFvmPartition] 2097152 bytes written, 6291456 zeroes left [2478.020] 04744.04932> paver:[StreamFvmPartition] Writing extent 3... [2478.028] 04744.04932> paver:[StreamFvmPartition] 2097152 bytes written, 6291456 zeroes left [2478.040] 04744.04932> paver:[StreamFvmPartition] Writing extent 4... [2478.959] 04744.04938> netsvc: paver write progress 63.5% [2479.963] 04744.04938> netsvc: paver write progress 95.1% 2019/04/12 01:38:40 done 2019/04/12 01:38:40 attempting to send <<image>>efi.img... 2019/04/12 01:38:40 target is busy, retrying in one second [2480.109] 04744.04758> netsvc: tftp write of file <<image>>sparse.fvm completed [2480.109] 04744.04758> netsvc: metrics: {"inorderblks": 306357,"oooblks": 0,"ack": 1197,"nack": 0,"timeouts": 0,"sas": 0,"inorderbytes": 313709206} [2480.110] 04744.04932> paver:[StreamFvmPartition] 341639168 bytes written, 2293760 zeroes left [2480.115] 04744.04932> paver:[FvmStreamPartitions] Done streaming partition 0 [2480.115] 04744.04932> paver:[FvmStreamPartitions] Done flushing partition 0 [2480.115] 04744.04932> paver:[FvmStreamPartitions] Streaming partition 1 [2480.115] 04744.04932> paver:[StreamFvmPartition] Writing extent 0... [2480.115] 04744.04932> paver:[StreamFvmPartition] 8192 bytes written, 8380416 zeroes left [2480.154] 04744.04932> paver:[StreamFvmPartition] Writing extent 1... [2480.154] 04744.04932> paver:[StreamFvmPartition] 65536 bytes written, 8323072 zeroes left [2480.193] 04744.04932> paver:[StreamFvmPartition] Writing extent 2... [2480.193] 04744.04932> paver:[StreamFvmPartition] 65536 bytes written, 8323072 zeroes left [2480.237] 04744.04932> paver:[StreamFvmPartition] Writing extent 3... [2480.275] 04744.04932> paver:[StreamFvmPartition] Writing extent 4... [2480.285] 04744.04932> paver:[StreamFvmPartition] 2097152 bytes written, 14680064 zeroes left [2480.350] 04744.04932> paver:[StreamFvmPartition] Writing extent 5... [2480.350] 04744.04932> paver:[StreamFvmPartition] 57344 bytes written, 8331264 zeroes left [2480.386] 04744.04932> paver:[FvmStreamPartitions] Done streaming partition 1 [2480.386] 04744.04932> paver:[FvmStreamPartitions] Done flushing partition 1 [2480.387] 04912.04926> Reading FVM from compressed file: true [2480.387] 04912.04926> Remaining bytes read into compression buffer: 0 [2480.387] 04912.04926> Remaining bytes written to decompression buffer: 0 [2480.387] 04912.04926> Time reading bytes from sparse FVM file: 3472238301 (1 s) [2480.387] 04912.04926> Time reading bytes AND decompressing them: 3648109882 (1 s) [2480.387] 04744.04932> paver:[PartitionPave] Completed successfully 2019/04/12 01:38:41 attempting to send <<image>>efi.img... [2481.110] 04744.04758> netsvc: Running EFI Paver [2481.114] 04744.05808> paver:[Initialize] Successfully initialized EFI Device Partitioner [2481.114] 04744.05808> paver:[PartitionPave] Paving partition. [2481.114] 04744.05808> paver:[FindFirstFit] Looking for space [2481.114] 04744.05808> paver:[FindFirstFit] Partition seen with start 34, end 16777249 (length 16777216) [2481.114] 04744.05808> paver:[FindFirstFit] Sorting [2481.114] 04744.05808> paver:[FindFirstFit] Partition[0] From Block [0, 34) ... (next partition starts at block 34) [2481.114] 04744.05808> paver:[FindFirstFit] There are 0 free blocks (40960 requested) [2481.114] 04744.05808> paver:[FindFirstFit] Partition[1] From Block [34, 16777250) ... (next partition starts at block 234441614) [2481.114] 04744.05808> paver:[FindFirstFit] There are 217664364 free blocks (40960 requested) [2481.114] 04744.05808> paver:[AddPartition] Found space in GPT - OK 217664364 @ 16777250 [2481.114] 04744.05808> paver:[AddPartition] Final space in GPT - OK 40960 @ 16777250 [2481.115] 04744.05808> paver:[AddPartition] Added partition, waiting for bind [2481.115] 03102.03165> block: Joining un-closed FIFO server [2481.115] 03102.03165> block: Joining un-closed FIFO server [2481.115] 01104.01117> devcoord: dc_bind_device() '' 2019/04/12 01:38:41 done 2019/04/12 01:38:41 attempting to send <<image>>kernc.img... 2019/04/12 01:38:41 target is busy, retrying in one second [2481.126] 01182.01202> devmgr: /dev/class/block/000: GPT? [2481.126] 01104.01117> devcoord: dc_bind_device() '/boot/driver/gpt.so' [2481.126] 03102.03165> gpt: device_get_metadata failed (-25) [2481.127] 01182.01202> devmgr: /dev/class/block/008: FVM? [2481.127] 01104.01117> devcoord: dc_bind_device() '/boot/driver/fvm.so' [2481.127] 04744.05808> paver:[AddPartition] Added partition, waiting for bind - OK [2481.129] 04744.04758> netsvc: tftp write of file <<image>>efi.img completed [2481.129] 04744.04758> netsvc: metrics: {"inorderblks": 1093,"oooblks": 0,"ack": 5,"nack": 0,"timeouts": 0,"sas": 0,"inorderbytes": 1118208} [2481.177] 04744.05808> paver:[PartitionPave] Completed successfully 2019/04/12 01:38:42 attempting to send <<image>>kernc.img... [2482.130] 04744.04758> netsvc: Running KERN-C Paver [2482.134] 04744.06063> paver:[Initialize] Successfully initialized EFI Device Partitioner [2482.134] 04744.06063> paver:[RealMain] SKIPPING KERNC install on non-CROS device, pass --force if desired. 2019/04/12 01:38:42 done 2019/04/12 01:38:42 attempting to send <<image>>zircona.img... 2019/04/12 01:38:42 target is busy, retrying in one second [2482.257] 04744.04758> netsvc: tftp write of file <<image>>kernc.img completed [2482.257] 04744.04758> netsvc: metrics: {"inorderblks": 11561,"oooblks": 0,"ack": 46,"nack": 0,"timeouts": 0,"sas": 0,"inorderbytes": 11837440} 2019/04/12 01:38:43 attempting to send <<image>>zircona.img... [2483.257] 04744.04758> netsvc: Running ZIRCON-A Paver [2483.262] 04744.06192> paver:[Initialize] Successfully initialized EFI Device Partitioner [2483.262] 04744.06192> paver:[PartitionPave] Paving partition. [2483.262] 04744.06192> paver:[FindFirstFit] Looking for space [2483.262] 04744.06192> paver:[FindFirstFit] Partition seen with start 34, end 16777249 (length 16777216) [2483.262] 04744.06192> paver:[FindFirstFit] Partition seen with start 16777250, end 16818209 (length 40960) [2483.262] 04744.06192> paver:[FindFirstFit] Sorting [2483.262] 04744.06192> paver:[FindFirstFit] Partition[0] From Block [0, 34) ... (next partition starts at block 34) [2483.262] 04744.06192> paver:[FindFirstFit] There are 0 free blocks (32768 requested) [2483.262] 04744.06192> paver:[FindFirstFit] Partition[1] From Block [34, 16777250) ... (next partition starts at block 16777250) [2483.262] 04744.06192> paver:[FindFirstFit] There are 0 free blocks (32768 requested) [2483.262] 04744.06192> paver:[FindFirstFit] Partition[2] From Block [16777250, 16818210) ... (next partition starts at block 234441614) [2483.262] 04744.06192> paver:[FindFirstFit] There are 217623404 free blocks (32768 requested) [2483.262] 04744.06192> paver:[AddPartition] Found space in GPT - OK 217623404 @ 16818210 [2483.262] 04744.06192> paver:[AddPartition] Final space in GPT - OK 32768 @ 16818210 [2483.263] 04744.06192> paver:[AddPartition] Added partition, waiting for bind [2483.263] 03102.03165> block: Joining un-closed FIFO server [2483.263] 01104.01117> devcoord: dc_bind_device() '' [2483.274] 01182.01202> devmgr: /dev/class/block/000: GPT? [2483.274] 01104.01117> devcoord: dc_bind_device() '/boot/driver/gpt.so' [2483.274] 03102.03165> gpt: device_get_metadata failed (-25) [2483.275] 01182.01202> devmgr: /dev/class/block/012: FVM? [2483.276] 01104.01117> devcoord: dc_bind_device() '/boot/driver/fvm.so' [2483.276] 04744.06192> paver:[AddPartition] Added partition, waiting for bind - OK 2019/04/12 01:38:43 done 2019/04/12 01:38:43 attempting to send <<image>>zirconr.img... 2019/04/12 01:38:43 target is busy, retrying in one second [2483.393] 04744.04758> netsvc: tftp write of file <<image>>zircona.img completed [2483.393] 04744.04758> netsvc: metrics: {"inorderblks": 11484,"oooblks": 0,"ack": 45,"nack": 0,"timeouts": 0,"sas": 0,"inorderbytes": 11758856} [2483.812] 04744.06192> paver:[PartitionPave] Completed successfully 2019/04/12 01:38:44 attempting to send <<image>>zirconr.img... [2484.394] 04744.04758> netsvc: Running ZIRCON-R Paver [2484.398] 04744.06469> paver:[Initialize] Successfully initialized EFI Device Partitioner [2484.398] 04744.06469> paver:[PartitionPave] Paving partition. [2484.398] 04744.06469> paver:[FindFirstFit] Looking for space [2484.398] 04744.06469> paver:[FindFirstFit] Partition seen with start 34, end 16777249 (length 16777216) [2484.398] 04744.06469> paver:[FindFirstFit] Partition seen with start 16777250, end 16818209 (length 40960) [2484.398] 04744.06469> paver:[FindFirstFit] Partition seen with start 16818210, end 16850977 (length 32768) [2484.398] 04744.06469> paver:[FindFirstFit] Sorting [2484.398] 04744.06469> paver:[FindFirstFit] Partition[0] From Block [0, 34) ... (next partition starts at block 34) [2484.398] 04744.06469> paver:[FindFirstFit] There are 0 free blocks (49152 requested) [2484.398] 04744.06469> paver:[FindFirstFit] Partition[1] From Block [34, 16777250) ... (next partition starts at block 16777250) [2484.398] 04744.06469> paver:[FindFirstFit] There are 0 free blocks (49152 requested) [2484.398] 04744.06469> paver:[FindFirstFit] Partition[2] From Block [16777250, 16818210) ... (next partition starts at block 16818210) [2484.398] 04744.06469> paver:[FindFirstFit] There are 0 free blocks (49152 requested) [2484.398] 04744.06469> paver:[FindFirstFit] Partition[3] From Block [16818210, 16850978) ... (next partition starts at block 234441614) [2484.398] 04744.06469> paver:[FindFirstFit] There are 217590636 free blocks (49152 requested) [2484.398] 04744.06469> paver:[AddPartition] Found space in GPT - OK 217590636 @ 16850978 [2484.398] 04744.06469> paver:[AddPartition] Final space in GPT - OK 49152 @ 16850978 [2484.399] 04744.06469> paver:[AddPartition] Added partition, waiting for bind [2484.399] 03102.03165> block: Joining un-closed FIFO server [2484.399] 01104.01117> devcoord: dc_bind_device() '' [2484.411] 01182.01202> devmgr: /dev/class/block/000: GPT? [2484.411] 01104.01117> devcoord: dc_bind_device() '/boot/driver/gpt.so' [2484.411] 03102.03165> gpt: device_get_metadata failed (-25) [2484.412] 01182.01202> devmgr: /dev/class/block/017: FVM? [2484.412] 01104.01117> devcoord: dc_bind_device() '/boot/driver/fvm.so' [2484.412] 04744.06469> paver:[AddPartition] Added partition, waiting for bind - OK 2019/04/12 01:38:44 done 2019/04/12 01:38:44 attempting to send <<image>>authorized_keys... 2019/04/12 01:38:44 target is busy, retrying in one second [2484.522] 04744.04758> netsvc: tftp write of file <<image>>zirconr.img completed [2484.522] 04744.04758> netsvc: metrics: {"inorderblks": 10283,"oooblks": 0,"ack": 41,"nack": 0,"timeouts": 0,"sas": 0,"inorderbytes": 10529440} [2484.779] 04744.06469> paver:[PartitionPave] Completed successfully 2019/04/12 01:38:45 attempting to send <<image>>authorized_keys... 2019/04/12 01:38:45 done 2019/04/12 01:38:45 attempting to send <<netboot>>kernel.bin... 2019/04/12 01:38:45 target is busy, retrying in one second [2485.523] 04744.04758> netsvc: Installing SSH authorized_keys [2485.524] 04744.04758> netsvc: tftp write of file <<image>>authorized_keys completed [2485.524] 04744.04758> netsvc: metrics: {"inorderblks": 1,"oooblks": 0,"ack": 1,"nack": 0,"timeouts": 0,"sas": 0,"inorderbytes": 806} [2485.526] 04744.06763> paver:[Initialize] Successfully initialized EFI Device Partitioner [2485.527] 01104.01117> devcoord: dc_bind_device() '/boot/driver/zxcrypt.so' [2485.527] 03102.03165> devhost_get_handles(0x5119204c0840:block) open path='zxcrypt', r=-2 [2485.556] 04744.06763> paver:[DataFilePave] Wrote ssh/authorized_keys 2019/04/12 01:38:46 attempting to send <<netboot>>kernel.bin... 2019/04/12 01:38:46 done [0.000] 00000.00000> zbi: @ 0xffffff8006731000 (10257568 bytes) [0.000] 00000.00000> UART: FIFO depth 16 [0.000] 00000.00000> PMM: boot reserve add [0x100000, 0x2f8fff] [0.000] 00000.00000> PMM: boot reserve add [0x6731000, 0x70f9fff] [0.000] 00000.00000> PMM: arena too small to be useful (size 4096) [0.000] 00000.00000> PMM: pmm_add_arena failed to initialize arena [0.000] 00000.00000> MEM: Failed to add pmm range at 0x7ffff000 size 0x1000 [0.000] 00000.00000> PMM: boot reserve marking WIRED [0x100000, 0x2f8fff] [0.000] 00000.00000> PMM: boot reserve marking WIRED [0x6731000, 0x70f9fff] [0.000] 00000.00000> welcome to Zircon [0.000] 00000.00000> KASLR: .text section at 0xffffffff00100000 [0.000] 00000.00000> INIT: cpu 0, calling hook 0xffffffff00114e28 (global_prng_seed) at level 0x30000, flags 0x1 [0.000] 00000.00000> initializing vm pre-heap [0.000] 00000.00000> VM: marking boot alloc used range [0x70fa000, 0x70fa100) [0.000] 00000.00000> INIT: cpu 0, calling hook 0xffffffff001221d8 (elf_build_id) at level 0x4fffe, flags 0x1 [0.000] 00000.00000> INIT: cpu 0, calling hook 0xffffffff00122364 (version) at level 0x4ffff, flags 0x1 [0.000] 00000.00000> version: [0.000] 00000.00000> arch: x86 [0.000] 00000.00000> platform: XXX [0.000] 00000.00000> target: XXX [0.000] 00000.00000> project: x64 [0.000] 00000.00000> buildid: git-781fb6ce3d87072aa9f1fccebc05409821f99cc9-dirty [0.000] 00000.00000> ELF build ID: d514a2455b11a13bdea6fbceaa81e7c88508d267 [0.000] 00000.00000> initializing heap [0.000] 00000.00000> INIT: cpu 0, calling hook 0xffffffff00101fc0 (console) at level 0x50000, flags 0x1 [0.000] 00000.00000> INIT: cpu 0, calling hook 0xffffffff00181918 (x86_resource_init) at level 0x50000, flags 0x1 [0.000] 00000.00000> INIT: cpu 0, calling hook 0xffffffff00206408 (percpu_heap_init) at level 0x50000, flags 0x1 [0.000] 00000.00000> initializing vm [0.000] 00000.00000> VM: reserving kernel region [0xffffffff00100000, 0xffffffff00216000) flags 0x28 name 'kernel_code' [0.000] 00000.00000> VM: reserving kernel region [0xffffffff00216000, 0xffffffff00266000) flags 0x8 name 'kernel_rodata' [0.000] 00000.00000> VM: reserving kernel region [0xffffffff00266000, 0xffffffff0026e000) flags 0x18 name 'kernel_data' [0.000] 00000.00000> VM: reserving kernel region [0xffffffff0026e000, 0xffffffff002f9000) flags 0x18 name 'kernel_bss' [0.000] 00000.00000> INIT: cpu 0, calling hook 0xffffffff001825dc (display_memtype) at level 0x60001, flags 0x1 [0.000] 00000.00000> INIT: cpu 0, calling hook 0xffffffff00185644 (acpi_tables) at level 0x60001, flags 0x1 [0.000] 00000.00000> INIT: cpu 0, calling hook 0xffffffff0018071c (hpet) at level 0x60002, flags 0x1 [0.000] 00000.00000> INIT: cpu 0, calling hook 0xffffffff00180adc (apic) at level 0x60002, flags 0x1 [0.000] 00000.00000> x2APIC enabled [0.000] 00000.00000> INIT: cpu 0, calling hook 0xffffffff00184c34 (timer) at level 0x60003, flags 0x1 [0.000] 00000.00000> HPET frequency: 23999 ticks/ms [0.000] 00000.00000> TSC frequency: 2712000 ticks/ms [2486.939] 00000.00000> timer features: constant_tsc 1 invariant_tsc 1 tsc_deadline 1 [2486.939] 00000.00000> Using TSC as wallclock [2486.939] 00000.00000> initializing kernel [2486.939] 00000.00000> initializing mp [2486.939] 00000.00000> INIT: cpu 0, calling hook 0xffffffff0011507c (global_prng_thread_safe) at level 0x7ffff, flags 0x1 [2486.939] 00000.00000> creating bootstrap completion thread [2486.940] 00000.00000> top of bootstrap2() [2486.940] 00000.00000> INIT: cpu 0, calling hook 0xffffffff00130fec (libobject) at level 0x80000, flags 0x1 [2486.940] 00000.00000> OOM: started thread [2486.940] 00000.00000> INIT: cpu 0, calling hook 0xffffffff00203414 (dpc) at level 0x80000, flags 0x1 [2486.940] 00000.00000> Processor Model Info: type 0 family 0x6 model 0xe stepping 0x9 [2486.940] 00000.00000> display_family 0x6 display_model 0x8e [2486.940] 00000.00000> Vendor: Intel [2486.940] 00000.00000> Microarch: Kaby Lake [2486.940] 00000.00000> F/M/S: 6/8e/9 [2486.940] 00000.00000> patch_level: 8e [2486.940] 00000.00000> Brand: Intel(R) Core(TM) i5-7300U CPU @ 2.60GHz [2486.940] 00000.00000> Features: fpu sse sse2 sse3 ssse3 sse4.1 sse4.2 mmx avx avx2 fxsr pcid xsave mon aesni clflush [2486.940] 00000.00000> clflushopt fsgsbase tsc_adj smep smap erms rdrand rdseed syscall nx huge rdtscp [2486.940] 00000.00000> invar_tsc tsc_deadline x2apic vmx pt hwp [2486.940] 00000.00000> Properties: meltdown l1tf pcid_good [2486.940] 00000.00000> initializing platform [2486.940] 00000.00000> INIT: cpu 0, calling hook 0xffffffff0019e5d0 (x86_perfmon) at level 0x90000, flags 0x1 [2486.940] 00000.00000> PMU: version 4 [2486.940] 00000.00000> UART: started IRQ driven RX [2486.940] 00000.00000> UART: started IRQ driven TX [2486.940] 00000.00000> cpu topology: [2486.940] 00000.00000> 0: apic id 0x0 package 0 node 0 core 0 smt 0 BSP [2486.940] 00000.00000> 1: apic id 0x2 package 0 node 0 core 1 smt 0 [2486.940] 00000.00000> 2: apic id 0x1 package 0 node 0 core 0 smt 1 [2486.940] 00000.00000> 3: apic id 0x3 package 0 node 0 core 1 smt 1 [2486.940] 00000.00000> Found 4 cpus [2486.940] 00000.00000> booting apic ids: 0x2 0x1 0x3 [2486.954] 00000.00000> entering scheduler on cpu 2 [2486.956] 00000.00000> entering scheduler on cpu 3 [2486.956] 00000.00000> entering scheduler on cpu 1 [2486.958] 00000.00000> smbios: manufacturer="Intel Corporation" product="NUC7i5DNKE" [2486.958] 00000.00000> initializing target [2486.958] 00000.00000> INIT: cpu 0, calling hook 0xffffffff00183ee4 (x86_pcie_init) at level 0xa0000, flags 0x1 [2486.958] 00000.00000> moving to last init level [2486.958] 00000.00000> INIT: cpu 0, calling hook 0xffffffff00121430 (debuglog) at level 0xb0000, flags 0x1 [2486.958] 00000.00000> INIT: cpu 0, calling hook 0xffffffff00102ae8 (kernel_shell) at level 0xc0000, flags 0x1 [2486.958] 00000.00000> INIT: cpu 0, calling hook 0xffffffff001fe834 (ktrace) at level 0xc0000, flags 0x1 [2486.962] 00000.00000> ktrace: buffer at 0xffffff96f96f4000 (33554432 bytes) [2486.962] 00000.00000> INIT: cpu 0, calling hook 0xffffffff00212af0 (userboot) at level 0xc0000, flags 0x1 [2486.962] 00000.00000> userboot: ramdisk 0x9c9000 @ 0xffffff8006731000 [2486.962] 00000.00000> userboot: userboot rodata 0 @ [0x35c3bf8c0000,0x35c3bf8c3000) [2486.962] 00000.00000> userboot: userboot code 0x3000 @ [0x35c3bf8c3000,0x35c3bf8ce000) [2486.962] 00000.00000> userboot: vdso/full rodata 0 @ [0x35c3bf8ce000,0x35c3bf8d5000) [2486.962] 00000.00000> userboot: vdso/full code 0x7000 @ [0x35c3bf8d5000,0x35c3bf8d6000) [2486.962] 00000.00000> userboot: entry point @ 0x35c3bf8c3c90 [2486.962] 01036.01043> userboot: option "zircon.autorun.system=/boot/bin/sh+/boot/infra/runcmds" [2486.986] 01036.01043> userboot: searching bootfs for 'bin/bootsvc' [2486.986] 01036.01043> userboot: 'bin/bootsvc' has PT_INTERP "lib/ld.so.1" [2486.986] 01036.01043> userboot: searching bootfs for 'lib/ld.so.1' [2486.986] 01036.01043> userboot: userboot: loaded lib/ld.so.1 at 0x611f6895b000, entry point 0x611f68979080 [2486.986] 01036.01043> userboot: userboot: loaded vDSO at 0x5930245be000, entry point 0x5930245c58fa [2486.986] 01036.01043> userboot: process bin/bootsvc started. [2486.986] 01036.01043> userboot: waiting for loader-service requests... [2486.986] 01036.01043> userboot: searching bootfs for 'lib/libasync-default.so' [2486.986] 01036.01043> userboot: searching bootfs for 'lib/libfdio.so' [2486.986] 01036.01043> userboot: searching bootfs for 'lib/libtrace-engine.so' [2486.986] 01036.01043> userboot: searching bootfs for 'lib/liblaunchpad.so' [2486.987] 01050.01053> dso: id=d4f54ead2067d48fcdfd57326440cea9e896d6c9 base=0x0000165e49ee6000 name=<application> [2486.987] 01050.01053> dso: id=2243cedb3d53d07d9ab576656ff6a3ee4847fbc2 base=0x00005930245be000 name=<vDSO> [2486.987] 01050.01053> dso: id=90ee144ef27c5dc90dc67076e94910489f38d790 base=0x00000e81ed252000 name=libasync-default.so [2486.987] 01050.01053> dso: id=d1365ca8e591047a2e15272496e02356c1e0a066 base=0x00000c2375a43000 name=libfdio.so [2486.987] 01050.01053> dso: id=54b402f1f418a6f00e0a894c7758747c093b40cd base=0x00003a581768e000 name=libtrace-engine.so [2486.987] 01050.01053> dso: id=deb23e0aec1895ea2e463752805ff66cd6f1517c base=0x0000561cc376f000 name=liblaunchpad.so [2486.987] 01050.01053> dso: id=02872f27f30161aa9b37ffd99002e900a759ae2a base=0x0000611f6895b000 name=libc.so [2486.987] 01050.01053> bootsvc: Starting... [2486.987] 01036.01043> userboot: loader-service channel peer closed [2486.987] 01036.01043> userboot: finished! [2486.987] 01050.01053> bootsvc: Creating bootfs service... [2486.987] 01050.01053> bootsvc: Retrieving boot image... [2486.987] 01050.01053> bootsvc: Decommitted BOOTDATA VMO from 0 to 0x9c8000 [2486.987] 01050.01053> bootsvc: Loading boot arguments... [2486.987] 01050.01053> bootsvc: Creating svcfs service... [2486.987] 01050.01053> bootsvc: Loading kernel VMOs... [2486.987] 01050.01053> bootsvc: Creating loader service... [2486.987] 01050.01053> bootsvc: Launching next process... [2486.987] 01050.01108> bootsvc: Launched bin/devcoordinator [2486.989] 01115.01131> devcoordinator: launch /boot/bin/svchost (svchost) OK [2486.990] 01115.01131> devcoordinator: launch /boot/bin/fshost (fshost) OK [2486.992] 01115.01343> devcoordinator: launch /boot/bin/netsvc (netsvc) OK [2486.993] 01115.01323> devcoordinator: launch /boot/bin/pwrbtn-monitor (pwrbtn-monitor) OK [2486.993] 01115.01343> devcoordinator: launch /boot/bin/virtual-console (virtual-console) OK [2486.996] 01115.01131> devcoordinator: full system required, ignoring fallback drivers until /system is loaded [2486.996] 01115.01131> devcoordinator: launch devhost 'devhost:sys': pid=2185 [2486.997] 01115.01131> devcoordinator: launch devhost 'devhost:test': pid=2217 [2486.997] 01115.01131> devcoordinator: launch devhost 'devhost:root': pid=2264 [2486.997] 02185.02199> devhost: trace provider registry begun [2486.998] 01115.01131> devcoordinator: launch devhost 'devhost:misc': pid=2365 [2486.999] 02217.02239> devhost: trace provider registry begun [2486.999] 02264.02293> devhost: trace provider registry begun [2487.000] 02365.02387> devhost: trace provider registry begun [2487.000] 01115.01335> devcoordinator: launch /boot/bin/sh (sh:console) OK [2487.085] 02185.02199> acpi-bus: not using IOMMU [2487.092] 02185.02199> PMU: 7 arch events [2487.092] 02185.02199> PMU: arch event id range: 1-7 [2487.092] 02185.02199> PMU: 102 arch events [2487.092] 02185.02199> PMU: arch event id range: 1-241 [2487.092] 02185.02199> Intel Processor Trace configuration for this chipset: [2487.092] 02185.02199> mtc_freq_mask: 0x249 [2487.092] 02185.02199> cyc_thresh_mask: 0x3fff [2487.092] 02185.02199> psb_freq_mask: 0x3f [2487.092] 02185.02199> num addr ranges: 2 [2487.093] 02185.02199> [sysmem_init 28] async_get_default_dispatcher(): 0x1058fcee32d0 [2487.093] 02185.02199> [sysmem_bind 40] sysmem_bind() [2487.093] 02185.02877> acpi-pwrbtn: initialized [2487.093] 01738.01777> vc: new input device /dev/class/input/000 [2487.102] 02185.02877> WARNING: ACPI found bad _CRS address entry [2487.112] 02185.02877> WARNING: ACPI found bad _CRS address entry [2487.124] 02185.02877> acpi: published device pci(0x10583cf3a930), parent=sys(0x10597cede410), handle=0x1057fcef2210 [2487.124] 01115.01131> devcoordinator: launch devhost 'devhost:pci#1:8086:5916': pid=2973 [2487.124] 01115.01131> devcoordinator: launch devhost 'devhost:pci#3:8086:9d2f': pid=3020 [2487.125] 02973.02987> devhost: trace provider registry begun [2487.125] 01115.01131> devcoordinator: launch devhost 'devhost:pci#5:8086:9d60': pid=3088 [2487.126] 01115.01131> devcoordinator: launch devhost 'devhost:pci#6:8086:9d61': pid=3200 [2487.126] 01115.01131> devcoordinator: launch devhost 'devhost:pci#9:8086:9d03': pid=3270 [2487.127] 03020.03043> devhost: trace provider registry begun [2487.127] 01115.01131> devcoordinator: launch devhost 'devhost:pci#14:8086:9d71': pid=3362 [2487.127] 02185.02877> acpi: published device rtc(0x10583cf39850), parent=acpi(0x10597ceddc10), handle=0x1057fcf18b90 [2487.129] 01115.01131> devcoordinator: launch devhost 'devhost:pci#16:8086:156f': pid=3423 [2487.129] 02185.02877> acpi-ec: initialized [2487.129] 03088.03153> devhost: trace provider registry begun [2487.132] 02185.02877> acpi: failed to create NHLT VMO (res -10) [2487.132] 02185.02877> acpi: failed to publish NHLT metadata [2487.136] 03200.03214> devhost: trace provider registry begun [2487.137] 03088.03153> initialized intel serialio i2c driver, reg=0x24d7fbbce000 regsize=4096 [2487.137] 03362.03376> devhost: trace provider registry begun [2487.138] 03423.03462> devhost: trace provider registry begun [2487.138] 03270.03291> devhost: trace provider registry begun [2487.140] 03200.03214> initialized intel serialio i2c driver, reg=0xa2619d75000 regsize=4096 [2487.141] 03270.03291> ahci: using MSI interrupt [2487.150] 03362.03376> [IHDA DSP 00:1f.3] Failed to fetch NHLT (res -25) [2487.150] 03362.03376> [IHDA Controller 00:1f.3] Failed to initialize DSP device (res = -25) [2487.159] 03020.03868> * found USB device (0x18d1:0xa002, USB 2.0) config 1 [2487.160] 03020.03868> * found USB device (0x18d1:0xa003, USB 3.0) config 1 [2487.215] 01634.01661> netifc: ? /dev/class/ethernet/000 [2487.215] 01634.01661> netifc: create 512 eth buffers [2487.215] 01634.01661> macaddr: d4:5d:df:1a:32:1a [2487.215] 01634.01661> ip6addr: fe80::d65d:df4d:fe1a:321a [2487.215] 01634.01661> snmaddr: ff02::1:ff1a:321a [2487.215] 01634.01661> netsvc: using /dev/class/ethernet/000 [2487.215] 01634.01661> netsvc: nodename='ocean-bacon-sky-dawn' [2487.215] 01634.01661> netsvc: start [2487.241] 01738.01777> vc: new display device /dev/class/display-controller/000/virtcon [2487.281] 02973.04241> i915: Found DP monitor [2487.281] 02973.04241> i915: Display 1 connected [2487.282] 02973.04241> i915: MST not supported [2488.128] 01738.01777> vc: Successfully attached to display 1 [2488.622] 03020.03868> * found USB device (0x0781:0x5571, USB 2.0) config 1 [2488.873] 03020.03868> * found USB device (0x8087:0x0a2b, USB 2.0) config 1 [2489.150] 03088.03153> intel-i2c-controller: intel_serialio_i2c_slave_transfer: -21 [2489.150] 03088.03153> i2c-hid: could not read HID descriptor: 0 [2489.150] 03088.03153> devhost[00:15.0/i2c-bus-9d60/0020] bind driver '/boot/driver/i2c-hid.so' failed: -2 [2489.150] 01115.01131> devcoordinator: rpc: bind-driver '0020' status -2 [2489.150] 03200.03214> intel-i2c-controller: intel_serialio_i2c_slave_transfer: -21 [2489.150] 03200.03214> i2c-hid: could not read HID descriptor: 0 [2489.150] 03200.03214> devhost[00:15.1/i2c-bus-9d61/004c] bind driver '/boot/driver/i2c-hid.so' failed: -2 [2489.150] 01115.01131> devcoordinator: rpc: bind-driver '004c' status -2 [2489.163] 03270.04044> sata2: dev info [2489.163] 03270.04044> serial=711430953080 8 [2489.163] 03270.04044> firmware rev=1Q01A7 0 [2489.163] 03270.04044> model id=IBIW NSS D [2489.163] 03270.04044> major=0x3f0 ACS2 DMA 32 commands [2489.163] 03270.04044> LBA48 234441648 sectors, sector size=512 [2489.164] 01302.01315> fshost: /dev/class/block/000: GPT? [2489.164] 03270.03291> gpt: device_get_metadata failed (-25) [2489.165] 01302.01315> fshost: /dev/class/block/001: FVM? [2489.166] 01302.01315> fshost: not automounting efi [2489.168] 01302.01315> devcoordinator: launch /boot/bin/blobfs (blobfs:/blob) OK [2489.316] 01302.01315> fshost: starting 'bin/pkgsvr' 'c9c58f7c1d8ecbb904782ad62f692fc2b4c141005ad2dc6b5d8263f7cb370af6'... [2489.322] 01302.01315> devcoordinator: launch bin/pkgsvr (pkgfs) OK [2489.333] 04664.04868> pkgsvr: system: will be served from c9c58f7c1d8ecbb904782ad62f692fc2b4c141005ad2dc6b5d8263f7cb370af6 [2489.333] 04664.04868> pkgsvr: pkgfs serving index /data/pkgfs_index from blobfs /blob [2489.334] 01302.01315> fshost: /dev/class/block/006: zxcrypt? [2489.334] 03270.03291> devhost_get_handles(0x4160d935a910:block) open path='zxcrypt', r=-2 [2489.338] 01302.01315> fshost: mounting minfs [2489.339] 01302.01315> devcoordinator: launch /boot/bin/minfs (minfs:/data) OK [2489.368] 01115.01783> devcoordinator: launch /system/bin/appmgr (appmgr) OK [2489.368] 01115.01783> autorun: starting '/boot/bin/sh' '/boot/infra/runcmds'... [2489.369] 01115.04921> devcoordinator: adding system driver 'mt8167s_gpu' '/system/driver/libmsd_img_rgx_mtk.so' [2489.370] 01115.01783> devcoordinator: launch /boot/bin/sh (autorun:system) OK [2489.381] 01115.04921> devcoordinator: adding system driver 'gpu' '/system/driver/libmsd_intel.so' [2489.387] 01115.04921> devcoordinator: adding system driver 'virtual_audio' '/system/driver/virtual_audio_driver.so' [2489.391] 01115.04921> devcoordinator: adding system driver 'rtl88xx' '/system/driver/rtl88xx.so' [2489.404] 01115.04921> devcoordinator: adding system driver 'bt_host' '/system/driver/bt-host.so' [2489.408] 01115.04921> devcoordinator: adding system driver 'virtual_camera' '/system/driver/virtual_camera_driver.so' [2489.411] 01115.04921> devcoordinator: adding system driver 'brcmfmac' '/system/driver/brcmfmac.so' [2489.415] 01115.04921> devcoordinator: adding system driver 'wlan' '/system/driver/wlanif.so' [2489.434] 01115.04921> devcoordinator: adding system driver 'ralink' '/system/driver/ralink.so' [2489.438] 01115.04921> devcoordinator: adding system driver 'bt_hci_atheros' '/system/driver/bt-hci-atheros.so' [2489.443] 01115.04921> devcoordinator: adding system driver 'bt_hci_fake' '/system/driver/bt-hci-fake.so' [2489.448] 01115.04921> devcoordinator: adding system driver 'bt_hci_intel' '/system/driver/bt-hci-intel.so' [2489.471] 01115.04921> devcoordinator: adding system driver 'wlan' '/system/driver/wlan.so' [2489.476] 01115.04921> devcoordinator: adding system driver 'wlan' '/system/driver/wlanphy.so' [2489.477] 01115.04921> devcoordinator: adding system driver 'bt_hog' '/system/driver/bt-hog.so' [2489.479] 01115.04921> devcoordinator: adding system driver 'qmi_fake' '/system/driver/qmi-fake.so' [2489.484] 05193.05207> [INFO:namespace_builder.cc(93)] config-data for sysmgr [2489.488] 01115.04921> devcoordinator: adding system driver 'qmi_usb' '/system/driver/qmi-transport.so' [2489.491] 01115.04921> devcoordinator: adding system driver 'ath10k_pci' '/system/driver/ath10k.so' [2489.492] 01115.04921> devcoordinator: adding system driver 'iwlwifi_pci' '/system/driver/iwlwifi.so' [2489.492] 01115.04921> devcoordinator: adding system driver 'bt_hci_passthrough' '/system/driver/bt-hci-passthrough.so' [2489.497] 01115.04921> devcoordinator: adding system driver 'usb_video' '/system/driver/usb_video.so' [2489.498] 01115.01131> devcoordinator: driver 'usb_video' added [2489.498] 01115.01131> devcoordinator: driver 'iwlwifi_pci' added [2489.498] 01115.01131> devcoordinator: driver 'ath10k_pci' added [2489.498] 01115.01131> devcoordinator: driver 'qmi_usb' added [2489.498] 01115.01131> devcoordinator: driver 'qmi_fake' added [2489.498] 01115.01131> devcoordinator: driver 'bt_hog' added [2489.498] 01115.01131> devcoordinator: driver 'wlan' added [2489.498] 01115.01131> devcoordinator: driver 'wlan' added [2489.498] 01115.01131> devcoordinator: driver 'bt_hci_intel' added [2489.498] 01115.01131> devcoordinator: driver 'bt_hci_fake' added [2489.498] 01115.01131> devcoordinator: driver 'bt_hci_atheros' added [2489.498] 01115.01131> devcoordinator: driver 'ralink' added [2489.498] 01115.01131> devcoordinator: driver 'wlan' added [2489.498] 01115.01131> devcoordinator: driver 'brcmfmac' added [2489.498] 01115.01131> devcoordinator: driver 'bt_host' added [2489.498] 01115.01131> devcoordinator: driver 'rtl88xx' added [2489.498] 01115.01131> devcoordinator: driver 'gpu' added [2489.498] 01115.01131> devcoordinator: driver 'mt8167s_gpu' added [2489.498] 01115.01131> devcoordinator: driver 'bt_hci_passthrough' added [2489.498] 01115.01131> devcoordinator: fallback driver 'usb_composite' is available [2489.498] 01115.01131> devcoordinator: driver 'usb_composite' added [2489.498] 01115.01131> devcoordinator: fallback driver 'intel_disp' is available [2489.498] 01115.01131> devcoordinator: driver 'intel_disp' added [2489.501] 03020.03043> UMS: parent: 'ifc-000' [2489.501] 03020.03043> UMS:Max lun is: 0 [2489.502] 03020.03043> devhost[00:14.0/xhci/usb-bus/002/002/ifc-001] bind driver '/boot/driver/bt-transport-usb.so' failed: -2 [2489.502] 01115.01131> devcoordinator: rpc: bind-driver 'ifc-001' status -2 [2489.504] 03020.06084> UMS: block size is: 0x00000200 [2489.504] 03020.06084> UMS: total blocks is: 15630336 [2489.504] 03020.06084> UMS: total size is: 8002732032 [2489.504] 03020.06084> UMS: read-only: 0 removable: 1 [2489.529] 05817.05831> [ERROR:garnet/bin/sysmgr/app.cc(150)] Could not serve fuchsia.mdns.Controller: 0 [2489.529] 05817.05831> [ERROR:garnet/bin/sysmgr/app.cc(150)] Could not serve fuchsia.netstack.Netstack: 0 [2489.529] 05817.05831> [ERROR:garnet/bin/sysmgr/app.cc(150)] Could not serve fuchsia.wlan.service.Wlan: 0 [2489.529] 05817.05831> [ERROR:garnet/bin/sysmgr/app.cc(150)] Could not serve fuchsia.net.policy.Observer: 0 [2489.529] 05817.05831> [ERROR:garnet/bin/sysmgr/app.cc(150)] Could not serve fuchsia.amber.Control: 0 [2489.529] 05817.05831> [ERROR:garnet/bin/sysmgr/app.cc(150)] Could not serve fuchsia.amber.Events: 0 [2489.540] 03020.06358> btintel: firmware already loaded [2489.540] 03020.06377> hci_read_thread: failed to read from command channel ZX_ERR_PEER_CLOSED [2489.540] 03020.06377> hci_read_thread: failed to read from ACL channel ZX_ERR_PEER_CLOSED [2489.540] 03020.06377> bt-transport-usb: all channels closed - exiting [2489.541] 03020.06809> [INFO:command_channel.cc(149)] hci: initialized [2489.542] 01302.01315> fshost: /dev/class/block/008: MBR? [2489.545] 01302.01315> fshost: /dev/class/block/010: MBR? [2489.552] 05193.05207> [INFO:namespace_builder.cc(93)] config-data for amber [2489.563] 03020.06809> [INFO:acl_data_channel.cc(91)] hci: initialized [2489.576] 05193.05207> [INFO:namespace_builder.cc(93)] config-data for pkg_resolver [2489.643] 08072.08084> [INFO:cobalt_main.cc(217)] 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 [2489.643] 08072.08084> kfill_days=2, start_event_aggregator_worker=1. [2489.679] 05193.05207> [INFO:namespace_builder.cc(93)] config-data for wlancfg [2489.776] 09285.09297> [INFO:system_metrics_main.cc(23)] Cobalt SystemMetricsDaemon: System metrics daemon created. [2489.819] 05193.05207> [INFO:namespace_builder.cc(93)] config-data for crashpad_agent [2489.854] 11152.11168> [INFO:main.cc(35)] Trace Manager starting with config: /pkg/data/tracing.config [2489.857] 03020.06809> [WARN:bredr_discovery_manager.cc(482)] gap-bredr: write inquiry scan activity failed: [status: invalid HCI command parameters (HCI 0x12)] [2489.882] 11878.11892> wlanstack2 [I]: Starting [2489.949] 05193.05207> [WARNING:garnet/bin/appmgr/service_provider_dir_impl.cc(127)] Component fuchsia-pkg://fuchsia.com/vulkan_is_supported#meta/vulkan_is_supported.cmx is not allowed to connect to fuchsia.tracelink.Registry because this service [2489.949] 05193.05207> is not present in the component's sandbox. [2489.949] 05193.05207> Refer to https://fuchsia.googlesource.com/fuchsia/+/master/docs/the-book/sandboxing.md#services for more information. [2489.956] 10780.10798> [INFO:benchmarks.cc(24)] Graphics performance tests disabled [2489.956] 10780.10798> [INFO:benchmarking.cc(173)] writing summary.json to /tmp/infra-test-output/summary.json [2490.858] 08574.08586> Starting mDNS on interface ethp001f6 192.168.42.106 [2490.858] 08574.08586> [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 [2490.858] 08574.08586> Starting mDNS on interface ethp001f6 [80fe::5dd6:ffdf:1afe:1a32] [2490.858] 08574.08586> [WARNING:garnet/bin/mdns/service/mdns_interface_transceiver_v6.cc(29)] NET-291 IPV6_MULTICAST_LOOP not supported (ENOPROTOOPT), continuing anyway [2490.858] 08574.08586> [WARNING:garnet/bin/mdns/service/mdns_interface_transceiver_v6.cc(50)] NET-2180 IPV6_JOIN_GROUP returned ENODEV, mDNS will not communicate via IPV6 [2490.858] 08574.08586> mDNS: Verifying uniqueness of host name ocean-bacon-sky-dawn.local. [2491.631] 08574.08586> mDNS: Using unique host name ocean-bacon-sky-dawn.local. DEBUG: reading "summary.json" DEBUG: copying test output DEBUG: tarring test output...