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

DEBUG: config flag: /etc/botanist/config.json DEBUG: waiting for "summary.json" 2019/04/23 01:47:48 attempting to send <<netboot>>cmdline... 2019/04/23 01:47:48 done 2019/04/23 01:47:48 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 0x8afff000 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.169] 00000.00000> timer features: constant_tsc 1 invariant_tsc 1 tsc_deadline 1 [20.169] 00000.00000> Using TSC as wallclock [20.169] 00000.00000> initializing kernel [20.169] 00000.00000> initializing mp [20.169] 00000.00000> initializing timers [20.170] 00000.00000> INIT: cpu 0, calling hook 0xffffffff0013c578 (debuglog) at level 0x7ffff, flags 0x1 [20.170] 00000.00000> INIT: cpu 0, calling hook 0xffffffff00195518 (thread_set_priority_experiment) at level 0x7ffff, flags 0x1 [20.170] 00000.00000> thread set priority experiment is : ENABLED [20.170] 00000.00000> INIT: cpu 0, calling hook 0xffffffff001aa67c (global_prng_thread_safe) at level 0x7ffff, flags 0x1 [20.170] 00000.00000> creating bootstrap completion thread [20.513] 00000.00000> top of bootstrap2() [20.513] 00000.00000> INIT: cpu 0, calling hook 0xffffffff0013151c (dpc) at level 0x80000, flags 0x1 [20.526] 00000.00000> INIT: cpu 0, calling hook 0xffffffff00152978 (libobject) at level 0x80000, flags 0x1 [20.526] 00000.00000> OOM: started thread [20.540] 00000.00000> Processor Model Info: type 0 family 0x6 model 0xe stepping 0x9 [20.540] 00000.00000> display_family 0x6 display_model 0x8e [20.540] 00000.00000> Vendor: Intel [20.540] 00000.00000> Microarch: Kaby Lake [20.540] 00000.00000> F/M/S: 6/8e/9 [20.540] 00000.00000> Brand: Intel(R) Core(TM) i5-7300U CPU @ 2.60GHz [20.540] 00000.00000> Features: fpu sse sse2 sse3 ssse3 sse4.1 sse4.2 mmx avx avx2 fxsr pcid xsave mon aesni clflush [20.540] 00000.00000> clflushopt fsgsbase tsc_adj smep smap erms rdrand rdseed syscall nx huge rdtscp [20.540] 00000.00000> invar_tsc tsc_deadline x2apic vmx pt hwp [20.540] 00000.00000> initializing platform [20.540] 00000.00000> INIT: cpu 0, calling hook 0xffffffff001101f4 (x86_perfmon) at level 0x90000, flags 0x1 [20.540] 00000.00000> PMU: version 4 [20.540] 00000.00000> UART: started IRQ driven RX [20.540] 00000.00000> UART: started IRQ driven TX [20.540] 00000.00000> cpu topology: [20.540] 00000.00000> 0: apic id 0x0 package 0 node 0 core 0 smt 0 BSP [20.540] 00000.00000> 1: apic id 0x2 package 0 node 0 core 1 smt 0 [20.540] 00000.00000> 2: apic id 0x1 package 0 node 0 core 0 smt 1 [20.540] 00000.00000> 3: apic id 0x3 package 0 node 0 core 1 smt 1 [20.540] 00000.00000> Found 4 cpus [20.540] 00000.00000> booting apic ids: 0x2 0x1 0x3 [20.556] 00000.00000> entering scheduler on cpu 2 [20.557] 00000.00000> entering scheduler on cpu 1 [20.557] 00000.00000> entering scheduler on cpu 3 [20.560] 00000.00000> smbios: manufacturer="Intel Corporation" product="NUC7i5DNKE" [20.560] 00000.00000> initializing target [20.560] 00000.00000> INIT: cpu 0, calling hook 0xffffffff001053a0 (x86_pcie_init) at level 0xa0000, flags 0x1 [20.560] 00000.00000> moving to last init level [20.560] 00000.00000> INIT: cpu 0, calling hook 0xffffffff00144140 (ktrace) at level 0xc0000, flags 0x1 [20.563] 00000.00000> ktrace: buffer at 0xffffff9aa2ffb000 (33554432 bytes) [20.563] 00000.00000> INIT: cpu 0, calling hook 0xffffffff00147ab4 (userboot) at level 0xc0000, flags 0x1 [20.563] 00000.00000> userboot: ramdisk 0x10ad000 @ 0xffffff80012f2000 [20.564] 00000.00000> userboot: userboot rodata 0 @ [0x5187c8b38000,0x5187c8b3b000) [20.564] 00000.00000> userboot: userboot code 0x3000 @ [0x5187c8b3b000,0x5187c8b46000) [20.564] 00000.00000> userboot: vdso/full rodata 0 @ [0x5187c8b46000,0x5187c8b4d000) [20.564] 00000.00000> userboot: vdso/full code 0x7000 @ [0x5187c8b4d000,0x5187c8b4e000) [20.564] 00000.00000> userboot: entry point @ 0x5187c8b3bc10 [20.564] 00000.00000> INIT: cpu 0, calling hook 0xffffffff001aa030 (kernel_shell) at level 0xc0000, flags 0x1 [20.564] 01036.01043> userboot: option "netsvc.disable=true" [20.564] 01036.01043> userboot: option "zircon.system.disable-automount=true" [20.564] 01036.01043> userboot: option "zircon.autorun.boot=/boot/infra/setup" [20.564] 01036.01043> userboot: option "kernel.serial=legacy" [20.564] 01036.01043> userboot: option "http://192.168.42.1/multiboot/d4%3A5d%3Adf%3A07%3A5e%3A3f=" [20.564] 01036.01043> userboot: option "multiboot.boot_loader_name=iPXE+1.0.0++(d2063)" [20.603] 01036.01043> userboot: searching bootfs for 'bin/bootsvc' [20.603] 01036.01043> userboot: 'bin/bootsvc' has PT_INTERP "lib/ld.so.1" [20.603] 01036.01043> userboot: searching bootfs for 'lib/ld.so.1' [20.603] 01036.01043> userboot: userboot: loaded lib/ld.so.1 at 0x75bfec60d000, entry point 0x75bfec6930d3 [20.603] 01036.01043> userboot: userboot: loaded vDSO at 0x55d12a16c000, entry point 0x0 [20.603] 01036.01043> userboot: process bin/bootsvc started. [20.603] 01036.01043> userboot: waiting for loader-service requests... [20.603] 01036.01043> userboot: searching bootfs for 'lib/libasync-default.so' [20.603] 01036.01043> userboot: searching bootfs for 'lib/libfdio.so' [20.603] 01036.01043> userboot: searching bootfs for 'lib/liblaunchpad.so' [20.603] 01036.01043> userboot: searching bootfs for 'lib/libtrace-engine.so' [20.603] 01050.01053> dso: id=18de7d58f51e8ba5c4f6afdd0cc8440f482c2b45 base=0x000065ec2b068000 name=<application> [20.603] 01050.01053> dso: id=c189f51f19d10785d93b5235ad1b46dca4451b00 base=0x0000114767f13000 name=libasync-default.so [20.603] 01050.01053> dso: id=40ab5fa3b61f12fef4a44477a687f608661cd450 base=0x000055d12a16c000 name=<vDSO> [20.603] 01050.01053> dso: id=67a12284bce140fc32aaaeac223e0e8f85cb5085 base=0x000075bfec60d000 name=libc.so [20.603] 01050.01053> dso: id=27787977e95f3b9563c9e0bd4d34ec92b7e9ad88 base=0x000077878e191000 name=libfdio.so [20.603] 01050.01053> dso: id=6fc2232dc8c1bc5c6adb8ad50ca794b5a260ee4f base=0x00002ba41be53000 name=liblaunchpad.so [20.603] 01050.01053> dso: id=c9042b83fe01206008fcefb16395238417248169 base=0x000008bfa42e0000 name=libtrace-engine.so [20.603] 01050.01053> bootsvc: Starting... [20.603] 01036.01043> userboot: loader-service channel peer closed [20.603] 01036.01043> userboot: finished! [20.603] 01050.01053> bootsvc: Creating bootfs service... [20.604] 01050.01053> bootsvc: Processing bootdata... [20.604] 01050.01053> bootsvc: Loading boot cmdline overrides... [20.604] 01050.01053> bootsvc: Loading kernel VMOs... [20.604] 01050.01053> bootsvc: Creating loader service... [20.604] 01050.01053> bootsvc: Launching next process... [20.604] 01050.01096> bootsvc: launched bin/devmgr [20.605] 01104.01117> devmgr: main() [20.605] 01104.01117> cmdline: netsvc.disable=true [20.605] 01104.01117> cmdline: zircon.system.disable-automount=true [20.605] 01104.01117> cmdline: zircon.autorun.boot=/boot/infra/setup [20.605] 01104.01117> cmdline: kernel.serial=legacy [20.605] 01104.01117> cmdline: http://192.168.42.1/multiboot/d4%3A5d%3Adf%3A07%3A5e%3A3f= [20.605] 01104.01117> cmdline: multiboot.boot_loader_name=iPXE+1.0.0++(d2063) [20.605] 01104.01117> devmgr: coordinator_init() [20.605] 01104.01117> devmgr: init [20.605] 01104.01117> devmgr: svc init [20.605] 01104.01117> devmgr: launch /boot/bin/svchost (svchost) OK [20.605] 01104.01117> devmgr: vfs init [20.605] 01104.01117> devmgr: launch /boot/bin/fshost (fshost) OK [20.605] 01104.01221> devmgr: shell startup [20.607] 01182.01202> fshost: started. [20.608] 01104.01212> devmgr: launch /boot/bin/pwrbtn-monitor (pwrbtn-monitor) OK [20.608] 01104.01228> devmgr: launch /boot/bin/virtual-console (virtual-console) OK [20.608] 01104.01228> zircon.autorun.boot: starting '/boot/infra/setup'... [20.609] 01104.01228> devmgr: launch /boot/infra/setup (autorun:boot) OK [20.611] 01104.01117> devcoord: launch devhost 'devhost:sys': pid=2049 [20.611] 01104.01117> devcoord: launch devhost 'devhost:test': pid=2082 [20.611] 01104.01117> devcoord: launch devhost 'devhost:root': pid=2115 [20.612] 01104.01117> devcoord: launch devhost 'devhost:misc': pid=2168 [20.613] 02049.02073> devhost: trace provider registry begun [20.613] 02082.02106> devhost: trace provider registry begun [20.614] 02115.02151> devhost: trace provider registry begun [20.615] 02168.02224> devhost: trace provider registry begun [20.617] 01104.01221> devmgr: launch /boot/bin/sh (sh:console) OK [20.673] 02049.02073> acpi-bus: not using IOMMU [20.678] 02049.02073> acpi-pwrbtn: initialized [20.700] 02049.02073> acpi: published device pci(0x3d082781f200), parent=proxy(0x3d082781b540), handle=0x3d0827857c30 [20.701] 02049.02073> acpi: published device rtc(0x3d082781a080), parent=acpi(0x3d082781b780), handle=0x3d08278705b0 [20.702] 02049.02073> acpi-ec: initialized [20.704] 02049.02073> acpi: failed to create NHLT VMO (res -10) [20.704] 02049.02073> acpi: failed to publish NHLT metadata [20.706] 02049.02073> [sysmem_init 28] async_get_default_dispatcher(): 0x3d082780e0a0 [20.706] 02049.02073> [sysmem_bind 40] sysmem_bind() [20.706] 02049.02073> acpi-bus: sysmem_register_protocol() intentionally ignored for now. [20.706] 02049.02073> PMU: 7 arch events [20.706] 02049.02073> PMU: arch event id range: 1-7 [20.706] 02049.02073> PMU: 102 model events [20.706] 02049.02073> PMU: model event id range: 1-241 [20.706] 02049.02073> Intel Processor Trace configuration for this chipset: [20.706] 02049.02073> mtc_freq_mask: 0x249 [20.706] 02049.02073> cyc_thresh_mask: 0x3fff [20.706] 02049.02073> psb_freq_mask: 0x3f [20.706] 02049.02073> num addr ranges: 2 [20.707] 01104.01117> devcoord: launch devhost 'devhost:pci#1:8086:5916': pid=2839 [20.707] 01104.01117> devcoord: launch devhost 'devhost:pci#3:8086:9d2f': pid=2882 [20.707] 01104.01117> devcoord: launch devhost 'devhost:pci#5:8086:9d60': pid=2946 [20.708] 02839.02862> devhost: trace provider registry begun [20.708] 01104.01117> devcoord: launch devhost 'devhost:pci#6:8086:9d61': pid=3006 [20.708] 01104.01117> devcoord: launch devhost 'devhost:pci#9:8086:9d03': pid=3104 [20.709] 02882.02920> devhost: trace provider registry begun [20.709] 01104.01117> devcoord: launch devhost 'devhost:pci#14:8086:9d71': pid=3211 [20.710] 02946.02978> devhost: trace provider registry begun [20.710] 03006.03071> devhost: trace provider registry begun [20.710] 01104.01117> devcoord: launch devhost 'devhost:pci#16:8086:156f': pid=3300 [20.712] 03006.03071> initialized intel serialio i2c driver, reg=0x4dfb65b63000 regsize=4096 [20.712] 02946.02978> initialized intel serialio i2c driver, reg=0x1f53a1ca2000 regsize=4096 [20.713] 03211.03261> devhost: trace provider registry begun [20.713] 03300.03344> devhost: trace provider registry begun [20.714] 03104.03147> devhost: trace provider registry begun [20.716] 03104.03147> ahci: using MSI interrupt [20.727] 01245.01576> vc: new input device /dev/class/input/000 [20.727] 03211.03261> [IHDA DSP 00:1f.3] Failed to fetch NHLT (res -25) [20.727] 03211.03261> devhost[00:1f.3/intel-hda-000/intel-sst-dsp-000] bind driver '/boot/driver/dsp.so' failed: -25 [20.727] 01104.01117> devcoord: rpc: bind-driver 'intel-sst-dsp-000' status -25 [20.737] 02882.03777> * found USB device (0x18d1:0xa002, USB 2.0) config 1 [20.737] 02882.03777> * found USB device (0x18d1:0xa003, USB 3.0) config 1 [20.818] 01245.01576> vc: new display device /dev/class/display-controller/000/virtcon [20.958] 02839.04144> i915: Found DP monitor [20.959] 02839.04144> i915: Display 1 connected [20.959] 02839.04144> i915: MST not supported [22.017] 01245.01576> vc: Successfully attached to display 1 [22.199] 02882.03777> * found USB device (0x0781:0x5571, USB 2.0) config 1 [22.200] 02882.02920> UMS: parent: 'ifc-000' [22.200] 02882.02920> UMS:Max lun is: 0 [22.450] 02882.03777> * found USB device (0x8087:0x0a2b, USB 2.0) config 1 [22.451] 02882.02920> devhost[00:14.0/xhci/usb-bus/002/002/ifc-001] bind driver '/boot/driver/bt-transport-usb.so' failed: -2 [22.452] 01104.01117> devcoord: rpc: bind-driver 'ifc-001' status -2 [22.716] 03006.03071> intel-i2c-controller: intel_serialio_i2c_slave_transfer: -21 [22.716] 03006.03071> i2c-hid: could not read HID descriptor: 0 [22.716] 03006.03071> devhost[00:15.1/i2c-bus-9d61/004c] bind driver '/boot/driver/i2c-hid.so' failed: -2 [22.716] 01104.01117> devcoord: rpc: bind-driver '004c' status -2 [22.717] 02946.02978> intel-i2c-controller: intel_serialio_i2c_slave_transfer: -21 [22.717] 02946.02978> i2c-hid: could not read HID descriptor: 0 [22.717] 02946.02978> devhost[00:15.0/i2c-bus-9d60/0020] bind driver '/boot/driver/i2c-hid.so' failed: -2 [22.717] 01104.01117> devcoord: rpc: bind-driver '0020' status -2 [22.720] 03104.03690> sata2: dev info [22.720] 03104.03690> serial=715400411010 2 [22.720] 03104.03690> firmware rev=1P11A1E_ [22.720] 03104.03690> model id=IBIW NSS D [22.720] 03104.03690> major=0x3f0 ACS2 DMA 32 commands [22.720] 03104.03690> LBA48 250069680 sectors, sector size=512 [22.721] 01182.01202> devmgr: /dev/class/block/000: GPT? [22.721] 01104.01117> devcoord: dc_bind_device() '/boot/driver/gpt.so' [22.721] 03104.03147> gpt: device_get_metadata failed (-25) [22.722] 01182.01202> devmgr: /dev/class/block/001: FVM? [22.722] 01104.01117> devcoord: dc_bind_device() '/boot/driver/fvm.so' [22.725] 04415.04434> paver:[Initialize] Successfully initialized EFI Device Partitioner [22.727] 04415.04434> paver:[WipePartitions] Immediate reboot strongly recommended [22.727] 03104.03147> block: Joining un-closed FIFO server [22.727] 03104.03147> block: Joining un-closed FIFO server [22.727] 03104.03147> block: Joining un-closed FIFO server [22.727] 01104.01117> devcoord: dc_bind_device() '' [22.727] 01182.01202> devmgr: /dev/class/block/000: GPT? [22.727] 01104.01117> devcoord: dc_bind_device() '/boot/driver/gpt.so' [22.727] 03104.03147> gpt: device_get_metadata failed (-25) [22.730] 04719.04733> 34+0 records in [22.730] 04719.04733> 34+0 records out [22.730] 04719.04733> 17408 bytes copied [22.732] 04822.04836> 34+0 records in [22.732] 04822.04836> 34+0 records out [22.732] 04822.04836> 17408 bytes copied [22.733] 04926.04940> netifc: ? /dev/class/ethernet/000 [22.733] 04926.04940> netifc: create 512 eth buffers [22.733] 04926.04940> macaddr: d4:5d:df:07:5e:3f [22.733] 04926.04940> ip6addr: fe80::d65d:df4d:fe07:5e3f [22.733] 04926.04940> snmaddr: ff02::1:ff07:5e3f [22.733] 04926.04940> netsvc: using /dev/class/ethernet/000 [22.733] 04926.04940> _ _ _ [22.733] 04926.04940> | | | | | [22.733] 04926.04940> _______ __| | |__ ___ ___ | |_ [22.733] 04926.04940> |_ / _ \/ _` | '_ \ / _ \ / _ \| __| [22.733] 04926.04940> / / __/ (_| | |_) | (_) | (_) | |_ [22.733] 04926.04940> /___\___|\__,_|_.__/ \___/ \___/ \__| [22.733] 04926.04940> zedboot: version: 0.7.13 [22.733] 04926.04940> netsvc: nodename='upper-aroma-clock-plot' [22.733] 04926.04940> netsvc: will not advertise [22.733] 04926.04940> netsvc: start [23.203] 02882.04248> UMS: block size is: 0x00000200 [23.203] 02882.04248> UMS: total blocks is: 15630336 [23.203] 02882.04248> UMS: total size is: 8002732032 [23.203] 02882.04248> UMS: read-only: 0 removable: 1 [23.204] 01182.01202> devmgr: /dev/class/block/006: MBR? [23.204] 01104.01117> devcoord: dc_bind_device() '/boot/driver/mbr.so' [23.206] 01182.01202> devmgr: /dev/class/block/008: MBR? [23.206] 01104.01117> devcoord: dc_bind_device() '/boot/driver/mbr.so' [371.164] 04926.04940> netsvc: handling tftp request failed (file might not exist) [371.164] 04926.04940> netsvc: close, but no open file [371.164] 04926.04940> netsvc: metrics: {"inorderblks": 0,"oooblks": 0,"ack": 0,"nack": 0,"timeouts": 0,"sas": 0,"inorderbytes": 0} [371.165] 04926.04940> netsvc: tftp write of file <<netboot>>cmdline completed [371.165] 04926.04940> netsvc: metrics: {"inorderblks": 1,"oooblks": 0,"ack": 1,"nack": 0,"timeouts": 0,"sas": 0,"inorderbytes": 55} [371.165] 04926.04940> netsvc: Running FVM Paver [371.167] 04926.05114> paver:[InitializeGpt] Located GPT is invalid; Attempting to initialize [371.168] 01104.01117> devcoord: dc_bind_device() '' [371.168] 01104.01117> devcoord: dc_bind_device() '/boot/driver/gpt.so' [371.168] 03104.03147> gpt: device_get_metadata failed (-25) [371.168] 01182.01202> devmgr: /dev/class/block/000: GPT? [371.168] 01104.01117> devcoord: dc_bind_device() '/boot/driver/gpt.so' [371.168] 03104.03147> devhost: rpc:bind-device failed: -20 [371.169] 04926.05114> paver:[Initialize] Successfully initialized EFI Device Partitioner [371.169] 04926.05114> paver:[PartitionPave] Paving partition. [371.169] 04926.05114> paver:[FindFirstFit] Looking for space [371.169] 04926.05114> paver:[FindFirstFit] Sorting [371.169] 04926.05114> paver:[FindFirstFit] Partition[0] From Block [0, 34) ... (next partition starts at block 250069646) [371.169] 04926.05114> paver:[FindFirstFit] There are 250069612 free blocks (16777216 requested) [371.169] 04926.05114> paver:[AddPartition] Found space in GPT - OK 250069612 @ 34 [371.169] 04926.05114> paver:[AddPartition] Final space in GPT - OK 16777216 @ 34 [371.169] 04926.05114> paver:[AddPartition] Added partition, waiting for bind [371.169] 01104.01117> devcoord: dc_bind_device() '' [371.169] 01182.01202> devmgr: /dev/class/block/000: GPT? [371.169] 01104.01117> devcoord: dc_bind_device() '/boot/driver/gpt.so' [371.169] 03104.03147> gpt: device_get_metadata failed (-25) [371.170] 04926.05114> paver:[AddPartition] Added partition, waiting for bind - OK [371.170] 04926.05114> paver:[PartitionPave] Streaming partitions... [371.170] 05094.05108> Found compressed file [371.170] 04926.05114> paver:[FvmStreamPartitions] Header Validated - OK [371.170] 04926.05114> paver:[FvmPartitionFormat] Initializing partition as FVM [371.172] 01104.01117> devcoord: dc_bind_device() '/boot/driver/fvm.so' [372.174] 04926.05114> paver:[FvmStreamPartitions] Partitions pre-validated successfully: Enough space exists to pave. [372.174] 04926.05114> paver:[AllocatePartitions] Allocating partition blobfs consisting of 1 slices [372.177] 04926.05114> paver:[AllocatePartitions] Allocating partition minfs consisting of 1 slices [372.179] 04926.05114> paver:[AllocatePartitions] Creating zxcrypt volume [372.180] 03104.03147> devhost_get_handles(0x3e7950479900:block) open path='zxcrypt/block', r=-2 [372.180] 01104.01117> devcoord: dc_bind_device() '/boot/driver/zxcrypt.so' [372.181] 03104.03147> devhost_get_handles(0x3e7950479900:block) open path='zxcrypt', r=-2 [372.186] 04926.05114> paver:[FvmStreamPartitions] Partition space pre-allocated successfully. [372.187] 04926.05114> paver:[FvmStreamPartitions] Streaming partition 0 [372.187] 04926.05114> paver:[StreamFvmPartition] Writing extent 0... [372.187] 04926.05120> netsvc: paver write progress 0.1% [372.187] 04926.05114> paver:[StreamFvmPartition] 8192 bytes written, 8380416 zeroes left [372.238] 04926.05114> paver:[StreamFvmPartition] Writing extent 1... [372.239] 04926.05114> paver:[StreamFvmPartition] 8192 bytes written, 8380416 zeroes left [372.294] 04926.05114> paver:[StreamFvmPartition] Writing extent 2... [372.307] 04926.05114> paver:[StreamFvmPartition] 2097152 bytes written, 6291456 zeroes left [372.349] 04926.05114> paver:[StreamFvmPartition] Writing extent 3... [372.363] 04926.05114> paver:[StreamFvmPartition] 2097152 bytes written, 6291456 zeroes left [372.404] 04926.05114> paver:[StreamFvmPartition] Writing extent 4... [373.188] 04926.05120> netsvc: paver write progress 35.2% 2019/04/23 01:47:51 done 2019/04/23 01:47:51 attempting to send <<image>>bootloader.img... 2019/04/23 01:47:51 target is busy, retrying in one second [374.191] 04926.05120> netsvc: paver write progress 80.6% [374.203] 04926.04940> netsvc: tftp write of file <<image>>sparse.fvm completed [374.203] 04926.04940> netsvc: metrics: {"inorderblks": 300876,"oooblks": 0,"ack": 1176,"nack": 0,"timeouts": 0,"sas": 0,"inorderbytes": 308096816} [374.579] 04926.05114> paver:[StreamFvmPartition] 336093184 bytes written, 7839744 zeroes left [374.628] 04926.05114> paver:[FvmStreamPartitions] Done streaming partition 0 [374.628] 04926.05114> paver:[FvmStreamPartitions] Done flushing partition 0 [374.628] 04926.05114> paver:[FvmStreamPartitions] Streaming partition 1 [374.628] 04926.05114> paver:[StreamFvmPartition] Writing extent 0... [374.629] 04926.05114> paver:[StreamFvmPartition] 8192 bytes written, 8380416 zeroes left [374.680] 04926.05114> paver:[StreamFvmPartition] Writing extent 1... [374.681] 04926.05114> paver:[StreamFvmPartition] 65536 bytes written, 8323072 zeroes left [374.734] 04926.05114> paver:[StreamFvmPartition] Writing extent 2... [374.735] 04926.05114> paver:[StreamFvmPartition] 65536 bytes written, 8323072 zeroes left [374.789] 04926.05114> paver:[StreamFvmPartition] Writing extent 3... [374.845] 04926.05114> paver:[StreamFvmPartition] Writing extent 4... [374.858] 04926.05114> paver:[StreamFvmPartition] 2097152 bytes written, 14680064 zeroes left [374.955] 04926.05114> paver:[StreamFvmPartition] Writing extent 5... [374.957] 04926.05114> paver:[StreamFvmPartition] 57344 bytes written, 8331264 zeroes left [375.011] 04926.05114> paver:[FvmStreamPartitions] Done streaming partition 1 [375.011] 04926.05114> paver:[FvmStreamPartitions] Done flushing partition 1 [375.013] 05094.05108> Reading FVM from compressed file: true [375.013] 05094.05108> Remaining bytes read into compression buffer: 0 [375.013] 05094.05108> Remaining bytes written to decompression buffer: 0 [375.013] 05094.05108> Time reading bytes from sparse FVM file: 149954207 (0 s) [375.013] 05094.05108> Time reading bytes AND decompressing them: 333796984 (0 s) [375.013] 04926.05114> paver:[PartitionPave] Completed successfully 2019/04/23 01:47:52 attempting to send <<image>>bootloader.img... 2019/04/23 01:47:52 done 2019/04/23 01:47:52 attempting to send <<image>>zircona.img... [375.204] 04926.04940> netsvc: Running BOOTLOADER Paver [375.206] 04926.05988> paver:[Initialize] Successfully initialized EFI Device Partitioner [375.206] 04926.05988> paver:[RealMain] SKIPPING BOOTLOADER install on x64 device, pass --force if desired. [375.223] 04926.04940> netsvc: tftp write of file <<image>>bootloader.img completed [375.223] 04926.04940> netsvc: metrics: {"inorderblks": 1093,"oooblks": 0,"ack": 5,"nack": 0,"timeouts": 0,"sas": 0,"inorderbytes": 1118208} [375.223] 04926.04940> netsvc: Running ZIRCON-A Paver [375.226] 04926.06117> paver:[Initialize] Successfully initialized EFI Device Partitioner [375.226] 04926.06117> paver:[PartitionPave] Paving partition. [375.226] 04926.06117> paver:[FindFirstFit] Looking for space [375.226] 04926.06117> paver:[FindFirstFit] Partition seen with start 34, end 16777249 (length 16777216) [375.226] 04926.06117> paver:[FindFirstFit] Sorting [375.226] 04926.06117> paver:[FindFirstFit] Partition[0] From Block [0, 34) ... (next partition starts at block 34) [375.226] 04926.06117> paver:[FindFirstFit] There are 0 free blocks (32768 requested) [375.226] 04926.06117> paver:[FindFirstFit] Partition[1] From Block [34, 16777250) ... (next partition starts at block 250069646) [375.226] 04926.06117> paver:[FindFirstFit] There are 233292396 free blocks (32768 requested) [375.226] 04926.06117> paver:[AddPartition] Found space in GPT - OK 233292396 @ 16777250 [375.226] 04926.06117> paver:[AddPartition] Final space in GPT - OK 32768 @ 16777250 [375.226] 04926.06117> paver:[AddPartition] Added partition, waiting for bind [375.226] 03104.03147> block: Joining un-closed FIFO server [375.227] 03104.03147> block: Joining un-closed FIFO server [375.227] 01104.01117> devcoord: dc_bind_device() '' [375.227] 01182.01202> devmgr: /dev/class/block/000: GPT? [375.227] 01104.01117> devcoord: dc_bind_device() '/boot/driver/gpt.so' [375.227] 03104.03147> gpt: device_get_metadata failed (-25) [375.227] 01182.01202> devmgr: /dev/class/block/013: FVM? [375.227] 01104.01117> devcoord: dc_bind_device() '/boot/driver/fvm.so' [375.228] 04926.06117> paver:[AddPartition] Added partition, waiting for bind - OK 2019/04/23 01:47:52 done 2019/04/23 01:47:52 attempting to send <<image>>zirconr.img... 2019/04/23 01:47:52 target is busy, retrying in one second [375.359] 04926.04940> netsvc: tftp write of file <<image>>zircona.img completed [375.359] 04926.04940> netsvc: metrics: {"inorderblks": 11728,"oooblks": 0,"ack": 46,"nack": 0,"timeouts": 0,"sas": 0,"inorderbytes": 12009432} [375.432] 04926.06117> paver:[PartitionPave] Completed successfully 2019/04/23 01:47:53 attempting to send <<image>>zirconr.img... [376.360] 04926.04940> netsvc: Running ZIRCON-R Paver [376.363] 04926.06377> paver:[Initialize] Successfully initialized EFI Device Partitioner [376.363] 04926.06377> paver:[PartitionPave] Paving partition. [376.363] 04926.06377> paver:[FindFirstFit] Looking for space [376.363] 04926.06377> paver:[FindFirstFit] Partition seen with start 34, end 16777249 (length 16777216) [376.363] 04926.06377> paver:[FindFirstFit] Partition seen with start 16777250, end 16810017 (length 32768) [376.363] 04926.06377> paver:[FindFirstFit] Sorting [376.363] 04926.06377> paver:[FindFirstFit] Partition[0] From Block [0, 34) ... (next partition starts at block 34) [376.363] 04926.06377> paver:[FindFirstFit] There are 0 free blocks (49152 requested) [376.363] 04926.06377> paver:[FindFirstFit] Partition[1] From Block [34, 16777250) ... (next partition starts at block 16777250) [376.363] 04926.06377> paver:[FindFirstFit] There are 0 free blocks (49152 requested) [376.363] 04926.06377> paver:[FindFirstFit] Partition[2] From Block [16777250, 16810018) ... (next partition starts at block 250069646) [376.363] 04926.06377> paver:[FindFirstFit] There are 233259628 free blocks (49152 requested) [376.363] 04926.06377> paver:[AddPartition] Found space in GPT - OK 233259628 @ 16810018 [376.363] 04926.06377> paver:[AddPartition] Final space in GPT - OK 49152 @ 16810018 [376.364] 04926.06377> paver:[AddPartition] Added partition, waiting for bind [376.364] 03104.03147> block: Joining un-closed FIFO server [376.364] 01104.01117> devcoord: dc_bind_device() '' [376.364] 01182.01202> devmgr: /dev/class/block/000: GPT? [376.364] 01104.01117> devcoord: dc_bind_device() '/boot/driver/gpt.so' [376.364] 03104.03147> gpt: device_get_metadata failed (-25) [376.365] 01182.01202> devmgr: /dev/class/block/017: FVM? [376.365] 01104.01117> devcoord: dc_bind_device() '/boot/driver/fvm.so' [376.365] 04926.06377> paver:[AddPartition] Added partition, waiting for bind - OK 2019/04/23 01:47:53 done 2019/04/23 01:47:53 attempting to send <<image>>authorized_keys... 2019/04/23 01:47:53 target is busy, retrying in one second [376.486] 04926.04940> netsvc: tftp write of file <<image>>zirconr.img completed [376.486] 04926.04940> netsvc: metrics: {"inorderblks": 10463,"oooblks": 0,"ack": 41,"nack": 0,"timeouts": 0,"sas": 0,"inorderbytes": 10713672} [376.552] 04926.06377> paver:[PartitionPave] Completed successfully 2019/04/23 01:47:54 attempting to send <<image>>authorized_keys... 2019/04/23 01:47:54 done 2019/04/23 01:47:54 attempting to send <<netboot>>kernel.bin... 2019/04/23 01:47:54 target is busy, retrying in one second [377.487] 04926.04940> netsvc: Installing SSH authorized_keys [377.488] 04926.04940> netsvc: tftp write of file <<image>>authorized_keys completed [377.488] 04926.04940> netsvc: metrics: {"inorderblks": 1,"oooblks": 0,"ack": 1,"nack": 0,"timeouts": 0,"sas": 0,"inorderbytes": 806} [377.490] 04926.06654> paver:[Initialize] Successfully initialized EFI Device Partitioner [377.491] 01104.01117> devcoord: dc_bind_device() '/boot/driver/zxcrypt.so' [377.491] 03104.03147> devhost_get_handles(0x3e7950479900:block) open path='zxcrypt', r=-2 [377.516] 04926.06654> paver:[DataFilePave] Wrote ssh/authorized_keys 2019/04/23 01:47:55 attempting to send <<netboot>>kernel.bin... 2019/04/23 01:47:56 done [0.000] 00000.00000> zbi: @ 0xffffff80070d3000 (10479048 bytes) [0.000] 00000.00000> UART: FIFO depth 16 [0.000] 00000.00000> PMM: boot reserve add [0x100000, 0x300fff] [0.000] 00000.00000> PMM: boot reserve add [0x70d3000, 0x7ad1fff] [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 0x8afff000 size 0x1000 [0.000] 00000.00000> PMM: boot reserve marking WIRED [0x100000, 0x300fff] [0.000] 00000.00000> PMM: boot reserve marking WIRED [0x70d3000, 0x7ad1fff] [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 0xffffffff00115228 (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 [0x7ad2000, 0x7ad2100) [0.000] 00000.00000> INIT: cpu 0, calling hook 0xffffffff001225d8 (elf_build_id) at level 0x4fffe, flags 0x1 [0.000] 00000.00000> INIT: cpu 0, calling hook 0xffffffff00122764 (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-d6f7a34b16c2339f4ba590437fe1e14c0c5726b8-dirty [0.000] 00000.00000> ELF build ID: d05342ea7a5cce4b5cd80421e1fb927f486f677a [0.000] 00000.00000> initializing heap [0.000] 00000.00000> INIT: cpu 0, calling hook 0xffffffff00101fc4 (console) at level 0x50000, flags 0x1 [0.000] 00000.00000> INIT: cpu 0, calling hook 0xffffffff00182b6c (x86_resource_init) at level 0x50000, flags 0x1 [0.000] 00000.00000> initializing vm [0.000] 00000.00000> VM: reserving kernel region [0xffffffff00100000, 0xffffffff0021c000) flags 0x28 name 'kernel_code' [0.000] 00000.00000> VM: reserving kernel region [0xffffffff0021c000, 0xffffffff0026d000) flags 0x8 name 'kernel_rodata' [0.000] 00000.00000> VM: reserving kernel region [0xffffffff0026d000, 0xffffffff00275000) flags 0x18 name 'kernel_data' [0.000] 00000.00000> VM: reserving kernel region [0xffffffff00275000, 0xffffffff00301000) flags 0x18 name 'kernel_bss' [0.000] 00000.00000> INIT: cpu 0, calling hook 0xffffffff0018387c (display_memtype) at level 0x60001, flags 0x1 [0.000] 00000.00000> INIT: cpu 0, calling hook 0xffffffff00186d0c (acpi_tables) at level 0x60001, flags 0x1 [0.000] 00000.00000> INIT: cpu 0, calling hook 0xffffffff00181970 (hpet) at level 0x60002, flags 0x1 [0.000] 00000.00000> INIT: cpu 0, calling hook 0xffffffff00181d30 (apic) at level 0x60002, flags 0x1 [0.000] 00000.00000> x2APIC enabled [0.000] 00000.00000> INIT: cpu 0, calling hook 0xffffffff001a8364 (system_topology_init) at level 0x60002, flags 0x1 [0.000] 00000.00000> WARNING: more than 1000 levels of cache, couldn't find highest. [0.000] 00000.00000> WARNING: unable to find any cache levels. [0.000] 00000.00000> Could not find SRAT table. ACPICA returned: 5 [0.000] 00000.00000> INIT: cpu 0, calling hook 0xffffffff001862fc (timer) at level 0x60003, flags 0x1 [0.000] 00000.00000> HPET frequency: 23999 ticks/ms [0.000] 00000.00000> TSC frequency: 2712000 ticks/ms [378.910] 00000.00000> timer features: constant_tsc 1 invariant_tsc 1 tsc_deadline 1 [378.910] 00000.00000> Using TSC as wallclock [378.910] 00000.00000> INIT: cpu 0, calling hook 0xffffffff00208fbc (percpu_heap_init) at level 0x60003, flags 0x1 [378.910] 00000.00000> initializing kernel [378.910] 00000.00000> initializing mp [378.910] 00000.00000> INIT: cpu 0, calling hook 0xffffffff0011547c (global_prng_thread_safe) at level 0x7ffff, flags 0x1 [378.910] 00000.00000> creating bootstrap completion thread [378.910] 00000.00000> top of bootstrap2() [378.910] 00000.00000> INIT: cpu 0, calling hook 0xffffffff00131a94 (libobject) at level 0x80000, flags 0x1 [378.910] 00000.00000> OOM: started thread [378.910] 00000.00000> INIT: cpu 0, calling hook 0xffffffff00205f28 (dpc) at level 0x80000, flags 0x1 [378.910] 00000.00000> Processor Model Info: type 0 family 0x6 model 0xe stepping 0x9 [378.910] 00000.00000> display_family 0x6 display_model 0x8e [378.910] 00000.00000> Vendor: Intel [378.910] 00000.00000> Microarch: Kaby Lake [378.910] 00000.00000> F/M/S: 6/8e/9 [378.910] 00000.00000> patch_level: 8e [378.910] 00000.00000> Brand: Intel(R) Core(TM) i5-7300U CPU @ 2.60GHz [378.910] 00000.00000> Features: fpu sse sse2 sse3 ssse3 sse4.1 sse4.2 mmx avx avx2 fxsr pcid xsave mon aesni clflush [378.910] 00000.00000> clflushopt fsgsbase tsc_adj smep smap erms rdrand rdseed syscall nx huge rdtscp [378.910] 00000.00000> invar_tsc tsc_deadline x2apic vmx pt hwp [378.910] 00000.00000> Properties: meltdown l1tf pcid_good [378.910] 00000.00000> initializing platform [378.910] 00000.00000> INIT: cpu 0, calling hook 0xffffffff001a1a74 (x86_perfmon) at level 0x90000, flags 0x1 [378.910] 00000.00000> PMU: version 4 [378.910] 00000.00000> UART: started IRQ driven RX [378.910] 00000.00000> UART: started IRQ driven TX [378.910] 00000.00000> cpu topology: [378.910] 00000.00000> 0: apic id 0x0 BSP [378.910] 00000.00000> 1: apic id 0x1 [378.910] 00000.00000> 2: apic id 0x2 [378.910] 00000.00000> 3: apic id 0x3 [378.910] 00000.00000> Found 4 cpus [378.910] 00000.00000> booting apic ids: 0x1 0x2 0x3 [378.925] 00000.00000> entering scheduler on cpu 1 [378.926] 00000.00000> entering scheduler on cpu 2 [378.926] 00000.00000> entering scheduler on cpu 3 [378.929] 00000.00000> smbios: manufacturer="Intel Corporation" product="NUC7i5DNKE" [378.929] 00000.00000> initializing target [378.929] 00000.00000> INIT: cpu 0, calling hook 0xffffffff001855ac (x86_pcie_init) at level 0xa0000, flags 0x1 [378.929] 00000.00000> moving to last init level [378.929] 00000.00000> INIT: cpu 0, calling hook 0xffffffff00121830 (debuglog) at level 0xb0000, flags 0x1 [378.929] 00000.00000> INIT: cpu 0, calling hook 0xffffffff001751e8 (kcounters) at level 0xb0000, flags 0x1 [378.929] 00000.00000> INIT: cpu 0, calling hook 0xffffffff00102aec (kernel_shell) at level 0xc0000, flags 0x1 [378.929] 00000.00000> INIT: cpu 0, calling hook 0xffffffff00203160 (ktrace) at level 0xc0000, flags 0x1 [378.932] 00000.00000> ktrace: buffer at 0xffffff928d201000 (33554432 bytes) [378.933] 00000.00000> INIT: cpu 0, calling hook 0xffffffff00218c1c (userboot) at level 0xc0000, flags 0x1 [378.933] 00000.00000> userboot: ramdisk 0x9ff000 @ 0xffffff80070d3000 [378.933] 00000.00000> userboot: userboot rodata 0 @ [0x610ff66cb000,0x610ff66ce000) [378.933] 00000.00000> userboot: userboot code 0x3000 @ [0x610ff66ce000,0x610ff66d9000) [378.933] 00000.00000> userboot: vdso/full rodata 0 @ [0x610ff66d9000,0x610ff66e0000) [378.933] 00000.00000> userboot: vdso/full code 0x7000 @ [0x610ff66e0000,0x610ff66e1000) [378.933] 00000.00000> userboot: entry point @ 0x610ff66cec90 [378.933] 01036.01043> userboot: option "zircon.autorun.system=/boot/bin/sh+/boot/infra/runcmds" [378.957] 01036.01043> userboot: searching bootfs for 'bin/bootsvc' [378.957] 01036.01043> userboot: 'bin/bootsvc' has PT_INTERP "lib/ld.so.1" [378.957] 01036.01043> userboot: searching bootfs for 'lib/ld.so.1' [378.957] 01036.01043> userboot: userboot: loaded lib/ld.so.1 at 0x63ec1dbb4000, entry point 0x63ec1dbd23e0 [378.957] 01036.01043> userboot: userboot: loaded vDSO at 0x6b555c643000, entry point 0x6b555c64a907 [378.957] 01036.01043> userboot: process bin/bootsvc started. [378.957] 01036.01043> userboot: waiting for loader-service requests... [378.957] 01036.01043> userboot: searching bootfs for 'lib/libasync-default.so' [378.957] 01036.01043> userboot: searching bootfs for 'lib/libfdio.so' [378.957] 01036.01043> userboot: searching bootfs for 'lib/libtrace-engine.so' [378.957] 01036.01043> userboot: searching bootfs for 'lib/liblaunchpad.so' [378.957] 01050.01053> dso: id=043fa7983994a9e131e2d1ba5712e53b1adf4458 base=0x000016e25cdaf000 name=<application> [378.957] 01050.01053> dso: id=352446ffd1818c01938e67e4e7d79eec2cfff150 base=0x00006b555c643000 name=<vDSO> [378.957] 01050.01053> dso: id=0271cf194a0841671fa33b6dcb224cd39eea70be base=0x00000d64c44d3000 name=libasync-default.so [378.957] 01050.01053> dso: id=bfa452526f3279cc21a12a170ccf4becd19a30e0 base=0x00004a3a2b2c9000 name=libfdio.so [378.957] 01050.01053> dso: id=5757153c96da035b72f53e5244fb371456405a11 base=0x00003f6fde717000 name=libtrace-engine.so [378.957] 01050.01053> dso: id=397171e90426285a1ecfb086e2d6f0a769d6b9e3 base=0x00004f04476ba000 name=liblaunchpad.so [378.957] 01050.01053> dso: id=8d291ff8a7da56bd9183c8e0103f45f9903c5f10 base=0x000063ec1dbb4000 name=libc.so [378.957] 01050.01053> bootsvc: Starting... [378.957] 01036.01043> userboot: loader-service channel peer closed [378.957] 01036.01043> userboot: finished! [378.957] 01050.01053> bootsvc: Creating bootfs service... [378.958] 01050.01053> bootsvc: Retrieving boot image... [378.958] 01050.01053> bootsvc: Decommitted BOOTDATA VMO from 0 to 0x9fe000 [378.958] 01050.01053> bootsvc: Loading boot arguments... [378.958] 01050.01053> bootsvc: Creating svcfs service... [378.958] 01050.01053> bootsvc: Loading kernel VMOs... [378.958] 01050.01053> bootsvc: Creating loader service... [378.958] 01050.01053> bootsvc: Launching next process... [378.958] 01050.01108> bootsvc: Launched bin/devcoordinator [378.959] 01115.01130> devcoordinator: launch /boot/bin/svchost (svchost) OK [378.960] 01115.01130> devcoordinator: launch /boot/bin/fshost (fshost) OK [378.962] 01115.01323> devcoordinator: launch /boot/bin/pwrbtn-monitor (pwrbtn-monitor) OK [378.963] 01115.01345> devcoordinator: launch /boot/bin/netsvc (netsvc) OK [378.964] 01115.01345> devcoordinator: launch /boot/bin/virtual-console (virtual-console) OK [378.967] 01115.01130> devcoordinator: full system required, ignoring fallback drivers until /system is loaded [378.967] 01115.01130> devcoordinator: launch devhost 'devhost:sys': pid=2194 [378.967] 01115.01130> devcoordinator: launch devhost 'devhost:test': pid=2226 [378.968] 01115.01130> devcoordinator: launch devhost 'devhost:root': pid=2273 [378.968] 01115.01130> devcoordinator: launch devhost 'devhost:misc': pid=2332 [378.969] 02194.02208> devhost: trace provider registry begun [378.970] 02226.02248> devhost: trace provider registry begun [378.970] 02273.02302> devhost: trace provider registry begun [378.971] 02332.02363> devhost: trace provider registry begun [378.971] 01115.01335> devcoordinator: launch /boot/bin/sh (sh:console) OK [379.057] 02194.02208> acpi-bus: not using IOMMU [379.064] 02194.02208> PMU: 7 arch events [379.064] 02194.02208> PMU: arch event id range: 1-7 [379.064] 02194.02208> PMU: 102 arch events [379.064] 02194.02208> PMU: arch event id range: 1-241 [379.064] 02194.02208> Intel Processor Trace configuration for this chipset: [379.064] 02194.02208> mtc_freq_mask: 0x249 [379.064] 02194.02208> cyc_thresh_mask: 0x3fff [379.064] 02194.02208> psb_freq_mask: 0x3f [379.064] 02194.02208> num addr ranges: 2 [379.064] 02194.02208> [sysmem_init 28] async_get_default_dispatcher(): 0x6df7225562d0 [379.064] 02194.02208> [sysmem_bind 40] sysmem_bind() [379.064] 02194.02888> acpi-pwrbtn: initialized [379.067] 01708.01775> vc: new input device /dev/class/input/000 [379.095] 02194.02888> acpi: published device pci(0x6df6625c06d0), parent=sys(0x6df7a2563310), handle=0x6df62256e4d0 [379.095] 01115.01130> devcoordinator: launch devhost 'devhost:pci#1:8086:5916': pid=2984 [379.096] 01115.01130> devcoordinator: launch devhost 'devhost:pci#3:8086:9d2f': pid=3034 [379.096] 01115.01130> devcoordinator: launch devhost 'devhost:pci#5:8086:9d60': pid=3109 [379.097] 02984.02998> devhost: trace provider registry begun [379.097] 03034.03055> devhost: trace provider registry begun [379.098] 03109.03133> devhost: trace provider registry begun [379.098] 01115.01130> devcoordinator: launch devhost 'devhost:pci#6:8086:9d61': pid=3291 [379.098] 02194.02888> acpi: published device rtc(0x6df66257cff0), parent=acpi(0x6df7a2563d10), handle=0x6df622594050 [379.100] 01115.01130> devcoordinator: launch devhost 'devhost:pci#9:8086:9d03': pid=3376 [379.100] 02194.02888> acpi-ec: initialized [379.100] 03291.03305> devhost: trace provider registry begun [379.101] 01115.01130> devcoordinator: launch devhost 'devhost:pci#14:8086:9d71': pid=3486 [379.102] 01115.01130> devcoordinator: launch devhost 'devhost:pci#16:8086:156f': pid=3585 [379.102] 03376.03395> devhost: trace provider registry begun [379.103] 03376.03395> ahci: using MSI interrupt [379.103] 03486.03521> devhost: trace provider registry begun [379.103] 03291.03305> initialized intel serialio i2c driver, reg=0x6511c5c11000 regsize=4096 [379.103] 03109.03133> initialized intel serialio i2c driver, reg=0x45b7daf9000 regsize=4096 [379.104] 02194.02888> acpi: failed to create NHLT VMO (res -10) [379.104] 02194.02888> acpi: failed to publish NHLT metadata [379.105] 03585.03625> devhost: trace provider registry begun [379.113] 03486.03521> [IHDA DSP 00:1f.3] Failed to fetch NHLT (res -25) [379.113] 03486.03521> [IHDA Controller 00:1f.3] Failed to initialize DSP device (res = -25) [379.113] 03034.04027> * found USB device (0x18d1:0xa002, USB 2.0) config 1 [379.114] 03034.04027> * found USB device (0x18d1:0xa003, USB 3.0) config 1 [379.185] 01616.01643> netifc: ? /dev/class/ethernet/000 [379.185] 01616.01643> netifc: create 512 eth buffers [379.185] 01616.01643> macaddr: d4:5d:df:07:5e:3f [379.185] 01616.01643> ip6addr: fe80::d65d:df4d:fe07:5e3f [379.185] 01616.01643> snmaddr: ff02::1:ff07:5e3f [379.185] 01616.01643> netsvc: using /dev/class/ethernet/000 [379.185] 01616.01643> netsvc: nodename='upper-aroma-clock-plot' [379.185] 01616.01643> netsvc: start [379.213] 01708.01775> vc: new display device /dev/class/display-controller/000 [379.254] 02984.04252> i915: Found DP monitor [379.254] 02984.04252> i915: Display 1 connected [379.254] 02984.04252> i915: MST not supported [380.312] 01708.01775> vc: Successfully attached to display 1 [380.576] 03034.04027> * found USB device (0x0781:0x5571, USB 2.0) config 1 [380.827] 03034.04027> * found USB device (0x8087:0x0a2b, USB 2.0) config 1 [381.112] 03291.03305> intel-i2c-controller: intel_serialio_i2c_slave_transfer: -21 [381.112] 03291.03305> i2c-hid: could not read HID descriptor: 0 [381.112] 03291.03305> devhost[00:15.1/i2c-bus-9d61/004c] bind driver '/boot/driver/i2c-hid.so' failed: -2 [381.112] 01115.01130> devcoordinator: rpc: bind-driver '004c' status -2 [381.112] 03109.03133> intel-i2c-controller: intel_serialio_i2c_slave_transfer: -21 [381.112] 03109.03133> i2c-hid: could not read HID descriptor: 0 [381.112] 03109.03133> devhost[00:15.0/i2c-bus-9d60/0020] bind driver '/boot/driver/i2c-hid.so' failed: -2 [381.112] 01115.01130> devcoordinator: rpc: bind-driver '0020' status -2 [381.120] 03376.03776> sata2: dev info [381.120] 03376.03776> serial=715400411010 2 [381.120] 03376.03776> firmware rev=1P11A1E_ [381.120] 03376.03776> model id=IBIW NSS D [381.120] 03376.03776> major=0x3f0 ACS2 DMA 32 commands [381.120] 03376.03776> LBA48 250069680 sectors, sector size=512 [381.120] 01301.01315> fshost: /dev/class/block/000: GPT? [381.121] 03376.03395> gpt: device_get_metadata failed (-25) [381.121] 01301.01315> fshost: /dev/class/block/001: FVM? [381.124] 01301.01315> devcoordinator: launch /boot/bin/blobfs (blobfs:/blob) OK [381.263] 01301.01315> fshost: starting 'bin/pkgsvr' 'f1f5cd2f8b4353a56b914a7fec223797425b0d8a7206891ad25c98d093fcab5b'... [381.270] 01301.01315> devcoordinator: launch bin/pkgsvr (pkgfs) OK [381.282] 04662.04873> pkgsvr: system: will be served from f1f5cd2f8b4353a56b914a7fec223797425b0d8a7206891ad25c98d093fcab5b [381.282] 04662.04873> pkgsvr: pkgfs serving index /data/pkgfs_index from blobfs /blob [381.282] 01301.01315> fshost: /dev/class/block/005: zxcrypt? [381.282] 03376.03395> devhost_get_handles(0x601d09f21410:block) open path='zxcrypt', r=-2 [381.284] 01301.01315> fshost: mounting minfs [381.285] 01301.01315> devcoordinator: launch /boot/bin/minfs (minfs:/data) OK [381.294] 01115.01787> devcoordinator: launch /system/bin/appmgr (appmgr) OK [381.294] 01115.01787> autorun: starting '/boot/bin/sh' '/boot/infra/runcmds'... [381.303] 01115.04917> devcoordinator: adding system driver 'brcmfmac' '/system/driver/brcmfmac.so' [381.319] 01115.04917> devcoordinator: adding system driver 'wlan' '/system/driver/wlanif.so' [381.332] 01115.04917> devcoordinator: adding system driver 'wlan' '/system/driver/wlanphy.so' [381.332] 01115.01787> devcoordinator: launch /boot/bin/sh (autorun:system) OK [381.339] 01115.04917> devcoordinator: adding system driver 'ath10k_pci' '/system/driver/ath10k.so' [381.351] 01115.04917> devcoordinator: adding system driver 'mt8167s_gpu' '/system/driver/libmsd_img_rgx_mtk.so' [381.375] 01115.04917> devcoordinator: adding system driver 'wlan' '/system/driver/wlan.so' [381.382] 01115.04917> devcoordinator: adding system driver 'bt_hci_atheros' '/system/driver/bt-hci-atheros.so' [381.387] 01115.04917> devcoordinator: adding system driver 'bt_hog' '/system/driver/bt-hog.so' [381.390] 01115.04917> devcoordinator: adding system driver 'qmi_fake' '/system/driver/qmi-fake.so' [381.404] 01115.04917> devcoordinator: adding system driver 'bt_host' '/system/driver/bt-host.so' [381.408] 01115.04917> devcoordinator: adding system driver 'virtual_audio' '/system/driver/virtual_audio_driver.so' [381.412] 01115.04917> devcoordinator: adding system driver 'magma_pdev_gpu' '/system/driver/libmsd_arm.so' [381.416] 01115.04917> devcoordinator: adding system driver 'virtual_camera' '/system/driver/virtual_camera_driver.so' [381.422] 01115.04917> devcoordinator: adding system driver 'bt_hci_intel' '/system/driver/bt-hci-intel.so' [381.427] 01115.04917> devcoordinator: adding system driver 'bt_hci_fake' '/system/driver/bt-hci-fake.so' [381.429] 01115.04917> devcoordinator: adding system driver 'bt_hci_passthrough' '/system/driver/bt-hci-passthrough.so' [381.435] 01115.04917> devcoordinator: adding system driver 'usb_video' '/system/driver/usb_video.so' [381.441] 01115.04917> devcoordinator: adding system driver 'gpu' '/system/driver/libmsd_intel.so' [381.446] 05128.05206> [INFO:namespace_builder.cc(93)] config-data for sysmgr [381.451] 01115.04917> devcoordinator: adding system driver 'qmi_usb' '/system/driver/qmi-transport.so' [381.456] 01115.04917> devcoordinator: adding system driver 'iwlwifi_pci' '/system/driver/iwlwifi.so' [381.478] 01115.04917> devcoordinator: adding system driver 'ralink' '/system/driver/ralink.so' [381.483] 01115.04917> devcoordinator: adding system driver 'rtl88xx' '/system/driver/rtl88xx.so' [381.484] 01115.01130> devcoordinator: driver 'rtl88xx' added [381.484] 01115.01130> devcoordinator: driver 'ralink' added [381.484] 01115.01130> devcoordinator: driver 'iwlwifi_pci' added [381.484] 01115.01130> devcoordinator: driver 'qmi_usb' added [381.484] 01115.01130> devcoordinator: driver 'gpu' added [381.484] 01115.01130> devcoordinator: driver 'usb_video' added [381.484] 01115.01130> devcoordinator: driver 'bt_hci_fake' added [381.484] 01115.01130> devcoordinator: driver 'bt_hci_intel' added [381.484] 01115.01130> devcoordinator: driver 'magma_pdev_gpu' added [381.484] 01115.01130> devcoordinator: driver 'bt_host' added [381.484] 01115.01130> devcoordinator: driver 'qmi_fake' added [381.484] 01115.01130> devcoordinator: driver 'bt_hog' added [381.484] 01115.01130> devcoordinator: driver 'bt_hci_atheros' added [381.484] 01115.01130> devcoordinator: driver 'wlan' added [381.484] 01115.01130> devcoordinator: driver 'mt8167s_gpu' added [381.484] 01115.01130> devcoordinator: driver 'ath10k_pci' added [381.484] 01115.01130> devcoordinator: driver 'wlan' added [381.484] 01115.01130> devcoordinator: driver 'wlan' added [381.484] 01115.01130> devcoordinator: driver 'brcmfmac' added [381.484] 01115.01130> devcoordinator: driver 'bt_hci_passthrough' added [381.484] 01115.01130> devcoordinator: fallback driver 'usb_composite' is available [381.484] 01115.01130> devcoordinator: driver 'usb_composite' added [381.484] 01115.01130> devcoordinator: fallback driver 'intel_disp' is available [381.484] 01115.01130> devcoordinator: driver 'intel_disp' added [381.486] 03034.03055> UMS: parent: 'ifc-000' [381.486] 03034.03055> UMS:Max lun is: 0 [381.486] 03034.03055> devhost[00:14.0/xhci/usb-bus/002/002/ifc-001] bind driver '/boot/driver/bt-transport-usb.so' failed: -2 [381.486] 01115.01130> devcoordinator: rpc: bind-driver 'ifc-001' status -2 [381.489] 03034.06100> UMS: block size is: 0x00000200 [381.489] 03034.06100> UMS: total blocks is: 15630336 [381.489] 03034.06100> UMS: total size is: 8002732032 [381.489] 03034.06100> UMS: read-only: 0 removable: 1 [381.523] 03034.06531> btintel: firmware already loaded [381.523] 03034.06541> hci_read_thread: failed to read from command channel ZX_ERR_PEER_CLOSED [381.523] 03034.06541> hci_read_thread: failed to read from ACL channel ZX_ERR_PEER_CLOSED [381.523] 03034.06541> bt-transport-usb: all channels closed - exiting [381.524] 03034.06580> [INFO:command_channel.cc(149)] hci: initialized [381.525] 01301.01315> fshost: /dev/class/block/007: MBR? [381.528] 01301.01315> fshost: /dev/class/block/009: MBR? [381.546] 03034.06580> [INFO:acl_data_channel.cc(91)] hci: initialized [381.548] 05128.05206> [INFO:namespace_builder.cc(93)] config-data for amber [381.603] 05128.05206> [INFO:namespace_builder.cc(93)] config-data for pkg_resolver [381.681] 08142.08154> [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 [381.681] 08142.08154> kfill_days=2, start_event_aggregator_worker=1. [381.707] 05128.05206> [INFO:namespace_builder.cc(93)] config-data for wlancfg [381.729] 05128.05206> [INFO:namespace_builder.cc(93)] config-data for mdns [381.858] 05128.05206> [INFO:namespace_builder.cc(93)] config-data for crashpad_agent [381.881] 11384.11402> [INFO:main.cc(35)] Trace Manager starting with config: /pkg/data/tracing.config [381.888] 09643.09658> [INFO:system_metrics_main.cc(23)] Cobalt SystemMetricsDaemon: System metrics daemon created. [381.910] 03034.06580> [WARN:bredr_discovery_manager.cc(482)] gap-bredr: write inquiry scan activity failed: [status: invalid HCI command parameters (HCI 0x12)] [381.914] 11981.11993> wlanstack2 [I]: Starting [381.994] 05128.05206> [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 [381.994] 05128.05206> is not present in the component's sandbox. [381.994] 05128.05206> Refer to https://fuchsia.googlesource.com/fuchsia/+/master/docs/the-book/sandboxing.md#services for more information. [382.001] 11046.11060> [INFO:benchmarks.cc(24)] Graphics performance tests disabled [382.001] 11046.11060> [INFO:benchmarking.cc(173)] writing summary.json to /tmp/infra-test-output/summary.json [382.911] 09015.09027> Starting mDNS on interface ethp001f6 192.168.42.118 using port 5353 [382.911] 09015.09027> [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 [382.911] 09015.09027> Starting mDNS on interface ethp001f6 [80fe::5dd6:ffdf:7fe:3f5e] using port 5353 [382.911] 09015.09027> [WARNING:garnet/bin/mdns/service/mdns_interface_transceiver_v6.cc(29)] NET-291 IPV6_MULTICAST_LOOP not supported (ENOPROTOOPT), continuing anyway [382.912] 09015.09027> [WARNING:garnet/bin/mdns/service/mdns_interface_transceiver_v6.cc(50)] NET-2180 IPV6_JOIN_GROUP returned ENODEV, mDNS will not communicate via IPV6 [382.912] 09015.09027> mDNS: Verifying uniqueness of host name upper-aroma-clock-plot.local. [383.773] 09015.09027> mDNS: Using unique host name upper-aroma-clock-plot.local. DEBUG: reading "summary.json" DEBUG: copying test output DEBUG: tarring test output... [431.166] 01616.01643> netsvc: tftp read of file /tmp/infra-test-output/summary.json completed [431.166] 01616.01643> netsvc: metrics: {"inorderblks": 0,"oooblks": 0,"ack": 0,"nack": 0,"timeouts": 0,"sas": 0,"inorderbytes": 0}