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

@@@STEP_TEXT@1 out of 8 aggregated steps failed: Swarming task failed: 2019/04/19 19:49:41 attempting to send <<image>>sparse.fvm... [00000.000] 00000.00000> zbi: @ 0xffffff80012f2000 (17482848 bytes) [00000.000] 00000.00000> UART: FIFO depth 16 [00000.000] 00000.00000> PMM: boot reserve add [0x100000, 0x2c5fff] [00000.000] 00000.00000> PMM: boot reserve add [0x12f2000, 0x239efff] [00000.000] 00000.00000> PMM: arena too small to be useful (size 4096) [00000.000] 00000.00000> PMM: pmm_add_arena failed to initialize arena [00000.000] 00000.00000> MEM: Failed to add pmm range at 0x8afff000 size 0x1000 [00000.000] 00000.00000> PMM: boot reserve marking WIRED [0x100000, 0x2c5fff] [00000.000] 00000.00000> PMM: boot reserve marking WIRED [0x12f2000, 0x239efff] [00000.000] 00000.00000> [00000.000] 00000.00000> welcome to Zircon [00000.000] 00000.00000> [00000.000] 00000.00000> KASLR: .text section at 0xffffffff00100000 [00000.000] 00000.00000> INIT: cpu 0, calling hook 0xffffffff001aa428 (global_prng_seed) at level 0x30000, flags 0x1 [00000.000] 00000.00000> initializing vm pre-heap [00000.000] 00000.00000> VM: marking boot alloc used range [0x239f000, 0x239f100) [00000.000] 00000.00000> INIT: cpu 0, calling hook 0xffffffff00147abc (elf_build_id) at level 0x4fffe, flags 0x1 [00000.000] 00000.00000> INIT: cpu 0, calling hook 0xffffffff00147c48 (version) at level 0x4ffff, flags 0x1 [00000.000] 00000.00000> version: [00000.000] 00000.00000> arch: x86 [00000.000] 00000.00000> platform: pc [00000.000] 00000.00000> target: pc [00000.000] 00000.00000> project: x64 [00000.000] 00000.00000> buildid: git-13ee3dc5e4c46bf127977ad28645c47442ec517d [00000.000] 00000.00000> ELF build ID: 5f3e39bd4ed89d3b8122947842f1eac846a04683 [00000.000] 00000.00000> initializing heap [00000.000] 00000.00000> INIT: cpu 0, calling hook 0xffffffff00102e1c (x86_resource_init) at level 0x50000, flags 0x1 [00000.000] 00000.00000> INIT: cpu 0, calling hook 0xffffffff001a9630 (console) at level 0x50000, flags 0x1 [00000.000] 00000.00000> initializing vm [00000.000] 00000.00000> VM: reserving kernel region [0xffffffff00100000, 0xffffffff001ee000) flags 0x28 name 'kernel_code' [00000.000] 00000.00000> VM: reserving kernel region [0xffffffff001ee000, 0xffffffff00232000) flags 0x8 name 'kernel_rodata' [00000.000] 00000.00000> VM: reserving kernel region [0xffffffff00232000, 0xffffffff00242000) flags 0x18 name 'kernel_data' [00000.000] 00000.00000> VM: reserving kernel region [0xffffffff00242000, 0xffffffff002c6000) flags 0x18 name 'kernel_bss' [00000.000] 00000.00000> INIT: cpu 0, calling hook 0xffffffff00103ae0 (display_memtype) at level 0x60001, flags 0x1 [00000.000] 00000.00000> INIT: cpu 0, calling hook 0xffffffff00138fa0 (acpi_tables) at level 0x60001, flags 0x1 [00000.000] 00000.00000> INIT: cpu 0, calling hook 0xffffffff00101c40 (hpet) at level 0x60002, flags 0x1 [00000.000] 00000.00000> INIT: cpu 0, calling hook 0xffffffff00102000 (apic) at level 0x60002, flags 0x1 [00000.000] 00000.00000> x2APIC enabled [00000.000] 00000.00000> INIT: cpu 0, calling hook 0xffffffff001061b4 (timer) at level 0x60003, flags 0x1 [00000.000] 00000.00000> HPET frequency: 23999 ticks/ms [00000.000] 00000.00000> TSC frequency: 2712000 ticks/ms [00021.647] 00000.00000> timer features: constant_tsc 1 invariant_tsc 1 tsc_deadline 1 [00021.647] 00000.00000> Using TSC as wallclock [00021.647] 00000.00000> initializing kernel [00021.647] 00000.00000> initializing mp [00021.647] 00000.00000> initializing timers [00021.647] 00000.00000> INIT: cpu 0, calling hook 0xffffffff0013c578 (debuglog) at level 0x7ffff, flags 0x1 [00021.647] 00000.00000> INIT: cpu 0, calling hook 0xffffffff00195518 (thread_set_priority_experiment) at level 0x7ffff, flags 0x1 [00021.647] 00000.00000> thread set priority experiment is : ENABLED [00021.647] 00000.00000> INIT: cpu 0, calling hook 0xffffffff001aa67c (global_prng_thread_safe) at level 0x7ffff, flags 0x1 [00021.647] 00000.00000> creating bootstrap completion thread [00021.989] 00000.00000> top of bootstrap2() [00021.989] 00000.00000> INIT: cpu 0, calling hook 0xffffffff0013151c (dpc) at level 0x80000, flags 0x1 [00022.002] 00000.00000> INIT: cpu 0, calling hook 0xffffffff00152978 (libobject) at level 0x80000, flags 0x1 [00022.002] 00000.00000> OOM: started thread [00022.016] 00000.00000> Processor Model Info: type 0 family 0x6 model 0xe stepping 0x9 [00022.016] 00000.00000> display_family 0x6 display_model 0x8e [00022.016] 00000.00000> Vendor: Intel [00022.016] 00000.00000> Microarch: Kaby Lake [00022.016] 00000.00000> F/M/S: 6/8e/9 [00022.016] 00000.00000> Brand: Intel(R) Core(TM) i5-7300U CPU @ 2.60GHz [00022.016] 00000.00000> Features: fpu sse sse2 sse3 ssse3 sse4.1 sse4.2 mmx avx avx2 fxsr pcid xsave mon aesni clflush [00022.016] 00000.00000> clflushopt fsgsbase tsc_adj smep smap erms rdrand rdseed syscall nx huge rdtscp [00022.016] 00000.00000> invar_tsc tsc_deadline x2apic vmx pt hwp [00022.016] 00000.00000> initializing platform [00022.016] 00000.00000> INIT: cpu 0, calling hook 0xffffffff001101f4 (x86_perfmon) at level 0x90000, flags 0x1 [00022.016] 00000.00000> PMU: version 4 [00022.016] 00000.00000> UART: started IRQ driven RX [00022.016] 00000.00000> UART: started IRQ driven TX [00022.016] 00000.00000> cpu topology: [00022.016] 00000.00000> 0: apic id 0x0 package 0 node 0 core 0 smt 0 BSP [00022.016] 00000.00000> 1: apic id 0x2 package 0 node 0 core 1 smt 0 [00022.016] 00000.00000> 2: apic id 0x1 package 0 node 0 core 0 smt 1 [00022.016] 00000.00000> 3: apic id 0x3 package 0 node 0 core 1 smt 1 [00022.016] 00000.00000> Found 4 cpus [00022.016] 00000.00000> booting apic ids: 0x2 0x1 0x3 [00022.031] 00000.00000> entering scheduler on cpu 2 [00022.033] 00000.00000> entering scheduler on cpu 3 [00022.033] 00000.00000> entering scheduler on cpu 1 [00022.035] 00000.00000> smbios: manufacturer="Intel Corporation" product="NUC7i5DNHE" [00022.035] 00000.00000> initializing target [00022.035] 00000.00000> INIT: cpu 1, calling hook 0xffffffff001053a0 (x86_pcie_init) at level 0xa0000, flags 0x1 [00022.035] 00000.00000> moving to last init level [00022.035] 00000.00000> INIT: cpu 1, calling hook 0xffffffff00144140 (ktrace) at level 0xc0000, flags 0x1 [00022.039] 00000.00000> ktrace: buffer at 0xffffff9d6f533000 (33554432 bytes) [00022.039] 00000.00000> INIT: cpu 1, calling hook 0xffffffff00147ab4 (userboot) at level 0xc0000, flags 0x1 [00022.039] 00000.00000> userboot: ramdisk 0x10ad000 @ 0xffffff80012f2000 [00022.039] 00000.00000> userboot: userboot rodata 0 @ [0x63878b4a2000,0x63878b4a5000) [00022.039] 00000.00000> userboot: userboot code 0x3000 @ [0x63878b4a5000,0x63878b4b0000) [00022.039] 00000.00000> userboot: vdso/full rodata 0 @ [0x63878b4b0000,0x63878b4b7000) [00022.039] 00000.00000> userboot: vdso/full code 0x7000 @ [0x63878b4b7000,0x63878b4b8000) [00022.039] 00000.00000> userboot: entry point @ 0x63878b4a5c10 [00022.039] 00000.00000> INIT: cpu 1, calling hook 0xffffffff001aa030 (kernel_shell) at level 0xc0000, flags 0x1 [00022.039] 01036.01043> userboot: option "netsvc.disable=true" [00022.039] 01036.01043> userboot: option "zircon.system.disable-automount=true" [00022.039] 01036.01043> userboot: option "zircon.autorun.boot=/boot/infra/setup" [00022.039] 01036.01043> userboot: option "kernel.serial=legacy" [00022.039] 01036.01043> userboot: option "http://192.168.42.1/multiboot/54%3Ab2%3A03%3A13%3A37%3A3b=" [00022.039] 01036.01043> userboot: option "multiboot.boot_loader_name=iPXE+1.0.0++(d2063)" [00022.078] 01036.01043> userboot: searching bootfs for 'bin/bootsvc' [00022.078] 01036.01043> userboot: 'bin/bootsvc' has PT_INTERP "lib/ld.so.1" [00022.078] 01036.01043> userboot: searching bootfs for 'lib/ld.so.1' [00022.078] 01036.01043> userboot: userboot: loaded lib/ld.so.1 at 0x6cb8efadf000, entry point 0x6cb8efb650d3 [00022.078] 01036.01043> userboot: userboot: loaded vDSO at 0x5ad4a338e000, entry point 0x0 [00022.079] 01036.01043> userboot: process bin/bootsvc started. [00022.079] 01036.01043> userboot: waiting for loader-service requests... [00022.079] 01036.01043> userboot: searching bootfs for 'lib/libasync-default.so' [00022.079] 01036.01043> userboot: searching bootfs for 'lib/libfdio.so' [00022.079] 01036.01043> userboot: searching bootfs for 'lib/liblaunchpad.so' [00022.079] 01036.01043> userboot: searching bootfs for 'lib/libtrace-engine.so' [00022.079] 01050.01053> {{{reset}}} [00022.079] 01050.01053> {{{module:0:<application>:elf:18de7d58f51e8ba5c4f6afdd0cc8440f482c2b45}}} [00022.079] 01050.01053> {{{mmap:0x2b535704c000:0x2e000:load:0:rx:0}}} [00022.079] 01050.01053> {{{mmap:0x2b535707a000:0x4000:load:0:rw:0x2e000}}} [00022.079] 01050.01053> dso: id=18de7d58f51e8ba5c4f6afdd0cc8440f482c2b45 base=0x00002b535704c000 name=<application> [00022.079] 01050.01053> {{{module:0x3:libasync-default.so:elf:c189f51f19d10785d93b5235ad1b46dca4451b00}}} [00022.079] 01050.01053> {{{mmap:0x6afcd5be1000:0x1000:load:0x3:rx:0}}} [00022.079] 01050.01053> {{{mmap:0x6afcd5be2000:0x1000:load:0x3:rw:0x1000}}} [00022.079] 01050.01053> dso: id=c189f51f19d10785d93b5235ad1b46dca4451b00 base=0x00006afcd5be1000 name=libasync-default.so [00022.079] 01050.01053> {{{module:0x2:<vDSO>:elf:40ab5fa3b61f12fef4a44477a687f608661cd450}}} [00022.079] 01050.01053> {{{mmap:0x5ad4a338e000:0x7000:load:0x2:r:0}}} [00022.079] 01050.01053> {{{mmap:0x5ad4a3395000:0x1000:load:0x2:rx:0x7000}}} [00022.079] 01050.01053> dso: id=40ab5fa3b61f12fef4a44477a687f608661cd450 base=0x00005ad4a338e000 name=<vDSO> [00022.079] 01050.01053> {{{module:0x1:libc.so:elf:67a12284bce140fc32aaaeac223e0e8f85cb5085}}} [00022.079] 01050.01053> {{{mmap:0x6cb8efadf000:0xcb000:load:0x1:rx:0}}} [00022.079] 01050.01053> {{{mmap:0x6cb8efbab000:0x6000:load:0x1:rw:0xcc000}}} [00022.079] 01050.01053> dso: id=67a12284bce140fc32aaaeac223e0e8f85cb5085 base=0x00006cb8efadf000 name=libc.so [00022.079] 01050.01053> {{{module:0x4:libfdio.so:elf:27787977e95f3b9563c9e0bd4d34ec92b7e9ad88}}} [00022.079] 01050.01053> {{{mmap:0x754fcd73c000:0x24000:load:0x4:rx:0}}} [00022.079] 01050.01053> {{{mmap:0x754fcd761000:0x4000:load:0x4:rw:0x25000}}} [00022.079] 01050.01053> dso: id=27787977e95f3b9563c9e0bd4d34ec92b7e9ad88 base=0x0000754fcd73c000 name=libfdio.so [00022.079] 01050.01053> {{{module:0x5:liblaunchpad.so:elf:6fc2232dc8c1bc5c6adb8ad50ca794b5a260ee4f}}} [00022.079] 01050.01053> {{{mmap:0x71e20fac8000:0x7000:load:0x5:rx:0}}} [00022.079] 01050.01053> {{{mmap:0x71e20facf000:0x2000:load:0x5:rw:0x7000}}} [00022.079] 01050.01053> dso: id=6fc2232dc8c1bc5c6adb8ad50ca794b5a260ee4f base=0x000071e20fac8000 name=liblaunchpad.so [00022.079] 01050.01053> {{{module:0x6:libtrace-engine.so:elf:c9042b83fe01206008fcefb16395238417248169}}} [00022.079] 01050.01053> {{{mmap:0x2729a6238000:0x9000:load:0x6:rx:0}}} [00022.079] 01050.01053> {{{mmap:0x2729a6241000:0x2000:load:0x6:rw:0x9000}}} [00022.079] 01050.01053> dso: id=c9042b83fe01206008fcefb16395238417248169 base=0x00002729a6238000 name=libtrace-engine.so [00022.079] 01050.01053> bootsvc: Starting... [00022.079] 01036.01043> userboot: loader-service channel peer closed [00022.079] 01036.01043> userboot: finished! [00022.079] 01050.01053> bootsvc: Creating bootfs service... [00022.080] 01050.01053> bootsvc: Processing bootdata... [00022.080] 01050.01053> bootsvc: Loading boot cmdline overrides... [00022.080] 01050.01053> bootsvc: Loading kernel VMOs... [00022.080] 01050.01053> bootsvc: Creating loader service... [00022.080] 01050.01053> bootsvc: Launching next process... [00022.080] 01050.01096> bootsvc: launched bin/devmgr [00022.081] 01104.01117> devmgr: main() [00022.081] 01104.01117> cmdline: netsvc.disable=true [00022.081] 01104.01117> cmdline: zircon.system.disable-automount=true [00022.081] 01104.01117> cmdline: zircon.autorun.boot=/boot/infra/setup [00022.081] 01104.01117> cmdline: kernel.serial=legacy [00022.081] 01104.01117> cmdline: http://192.168.42.1/multiboot/54%3Ab2%3A03%3A13%3A37%3A3b= [00022.081] 01104.01117> cmdline: multiboot.boot_loader_name=iPXE+1.0.0++(d2063) [00022.081] 01104.01117> devmgr: coordinator_init() [00022.081] 01104.01117> devmgr: init [00022.081] 01104.01117> devmgr: svc init [00022.081] 01104.01117> devmgr: launch /boot/bin/svchost (svchost) OK [00022.081] 01104.01117> devmgr: vfs init [00022.081] 01104.01117> devmgr: launch /boot/bin/fshost (fshost) OK [00022.081] 01104.01220> devmgr: shell startup [00022.083] 01182.01202> fshost: started. [00022.083] 01104.01213> devmgr: launch /boot/bin/pwrbtn-monitor (pwrbtn-monitor) OK [00022.084] 01104.01232> devmgr: launch /boot/bin/virtual-console (virtual-console) OK [00022.084] 01104.01232> zircon.autorun.boot: starting '/boot/infra/setup'... [00022.085] 01104.01232> devmgr: launch /boot/infra/setup (autorun:boot) OK [00022.087] 01104.01117> devcoord: launch devhost 'devhost:sys': pid=2049 [00022.087] 01104.01117> devcoord: launch devhost 'devhost:test': pid=2082 [00022.088] 01104.01117> devcoord: launch devhost 'devhost:root': pid=2115 [00022.088] 01104.01117> devcoord: launch devhost 'devhost:misc': pid=2171 [00022.089] 02049.02073> devhost: trace provider registry begun [00022.089] 02082.02106> devhost: trace provider registry begun [00022.091] 02115.02153> devhost: trace provider registry begun [00022.092] 02171.02203> devhost: trace provider registry begun [00022.094] 01104.01220> devmgr: launch /boot/bin/sh (sh:console) OK [00022.150] 02049.02073> acpi-bus: not using IOMMU [00022.154] 02049.02073> acpi-pwrbtn: initialized [00022.176] 02049.02073> acpi: published device pci(0x5973ce7a200), parent=proxy(0x5973ce76540), handle=0x5973ceb2c30 [00022.178] 02049.02073> acpi: published device rtc(0x5973ce75080), parent=acpi(0x5973ce76780), handle=0x5973cecb5b0 [00022.179] 02049.02073> acpi-ec: initialized [00022.180] 02049.02073> acpi: failed to create NHLT VMO (res -10) [00022.180] 02049.02073> acpi: failed to publish NHLT metadata [00022.182] 02049.02073> [sysmem_init 28] async_get_default_dispatcher(): 0x5973ce690a0 [00022.182] 02049.02073> [sysmem_bind 40] sysmem_bind() [00022.183] 02049.02073> acpi-bus: sysmem_register_protocol() intentionally ignored for now. [00022.183] 02049.02073> PMU: 7 arch events [00022.183] 02049.02073> PMU: arch event id range: 1-7 [00022.183] 02049.02073> PMU: 102 model events [00022.183] 02049.02073> PMU: model event id range: 1-241 [00022.183] 02049.02073> Intel Processor Trace configuration for this chipset: [00022.183] 02049.02073> mtc_freq_mask: 0x249 [00022.183] 02049.02073> cyc_thresh_mask: 0x3fff [00022.183] 02049.02073> psb_freq_mask: 0x3f [00022.183] 02049.02073> num addr ranges: 2 [00022.183] 01104.01117> devcoord: launch devhost 'devhost:pci#1:8086:5916': pid=2840 [00022.183] 01104.01117> devcoord: launch devhost 'devhost:pci#3:8086:9d2f': pid=2887 [00022.184] 01104.01117> devcoord: launch devhost 'devhost:pci#5:8086:9d60': pid=2948 [00022.184] 01104.01117> devcoord: launch devhost 'devhost:pci#6:8086:9d61': pid=2996 [00022.184] 02840.02863> devhost: trace provider registry begun [00022.185] 01104.01117> devcoord: launch devhost 'devhost:pci#9:8086:9d03': pid=3073 [00022.185] 02948.02975> devhost: trace provider registry begun [00022.186] 01104.01117> devcoord: launch devhost 'devhost:pci#14:8086:9d71': pid=3196 [00022.186] 02887.02921> devhost: trace provider registry begun [00022.187] 02996.03028> devhost: trace provider registry begun [00022.187] 01104.01117> devcoord: launch devhost 'devhost:pci#16:8086:156f': pid=3296 [00022.188] 03073.03142> devhost: trace provider registry begun [00022.188] 02948.02975> initialized intel serialio i2c driver, reg=0x122329839000 regsize=4096 [00022.188] 02996.03028> initialized intel serialio i2c driver, reg=0x60237569000 regsize=4096 [00022.189] 03196.03256> devhost: trace provider registry begun [00022.189] 03296.03350> devhost: trace provider registry begun [00022.191] 03073.03142> ahci: using MSI interrupt [00022.193] 02887.03630> * found USB device (0x18d1:0xa002, USB 2.0) config 1 [00022.193] 02887.03630> * found USB device (0x18d1:0xa003, USB 3.0) config 1 [00022.204] 03196.03256> [IHDA DSP 00:1f.3] Failed to fetch NHLT (res -25) [00022.204] 03196.03256> devhost[00:1f.3/intel-hda-000/intel-sst-dsp-000] bind driver '/boot/driver/dsp.so' failed: -25 [00022.204] 01262.01559> vc: new input device /dev/class/input/000 [00022.204] 01104.01117> devcoord: rpc: bind-driver 'intel-sst-dsp-000' status -25 [00022.294] 01262.01559> vc: new display device /dev/class/display-controller/000/virtcon [00022.435] 02840.04142> i915: MST not supported [00022.855] 02840.04142> i915: Found DP monitor [00022.855] 02840.04142> i915: Display 1 connected [00023.414] 01262.01559> vc: Successfully attached to display 1 [00023.664] 02887.03630> * found USB device (0x0781:0x5571, USB 2.0) config 1 [00023.665] 02887.02921> UMS: parent: 'ifc-000' [00023.665] 02887.02921> UMS:Max lun is: 0 [00023.915] 02887.03630> * found USB device (0x8087:0x0a2b, USB 2.0) config 1 [00023.916] 02887.02921> devhost[00:14.0/xhci/usb-bus/002/002/ifc-001] bind driver '/boot/driver/bt-transport-usb.so' failed: -2 [00023.916] 01104.01117> devcoord: rpc: bind-driver 'ifc-001' status -2 [00024.191] 02996.03028> intel-i2c-controller: intel_serialio_i2c_slave_transfer: -21 [00024.191] 02996.03028> i2c-hid: could not read HID descriptor: 0 [00024.191] 02996.03028> devhost[00:15.1/i2c-bus-9d61/004c] bind driver '/boot/driver/i2c-hid.so' failed: -2 [00024.191] 01104.01117> devcoord: rpc: bind-driver '004c' status -2 [00024.191] 02948.02975> intel-i2c-controller: intel_serialio_i2c_slave_transfer: -21 [00024.191] 02948.02975> i2c-hid: could not read HID descriptor: 0 [00024.191] 02948.02975> devhost[00:15.0/i2c-bus-9d60/0020] bind driver '/boot/driver/i2c-hid.so' failed: -2 [00024.191] 01104.01117> devcoord: rpc: bind-driver '0020' status -2 [00024.207] 03073.03625> sata2: dev info [00024.207] 03073.03625> serial=AA000000000000009043 [00024.207] 03073.03625> firmware rev=0R08A1 0 [00024.207] 03073.03625> model id=ETMAT 8MSP1582 G [00024.207] 03073.03625> major=0x3f0 ACS2 DMA 32 commands [00024.207] 03073.03625> LBA48 250069680 sectors, sector size=512 [00024.209] 04413.04427> paver:[InitializeGpt] Located GPT is invalid; Attempting to initialize [00024.209] 01104.01117> devcoord: dc_bind_device() '/boot/driver/gpt.so' [00024.209] 03073.03142> gpt: device_get_metadata failed (-25) [00024.212] 04413.04427> paver:[Initialize] Successfully initialized EFI Device Partitioner [00024.212] 01104.01117> devcoord: dc_bind_device() '' [00024.212] 01182.01202> devmgr: /dev/class/block/000: GPT? [00024.212] 01104.01117> devcoord: dc_bind_device() '/boot/driver/gpt.so' [00024.212] 03073.03142> gpt: device_get_metadata failed (-25) [00024.214] 04567.04584> 34+0 records in [00024.214] 04567.04584> 34+0 records out [00024.214] 04567.04584> 17408 bytes copied [00024.217] 04674.04688> 34+0 records in [00024.217] 04674.04688> 34+0 records out [00024.217] 04674.04688> 17408 bytes copied [00024.218] 04778.04792> netifc: ? /dev/class/ethernet/000 [00024.218] 04778.04792> netifc: create 512 eth buffers [00024.218] 04778.04792> macaddr: 54:b2:03:13:37:3b [00024.218] 04778.04792> ip6addr: fe80::56b2:34d:fe13:373b [00024.218] 04778.04792> snmaddr: ff02::1:ff13:373b [00024.218] 04778.04792> netsvc: using /dev/class/ethernet/000 [00024.218] 04778.04792> _ _ _ [00024.218] 04778.04792> | | | | | [00024.218] 04778.04792> _______ __| | |__ ___ ___ | |_ [00024.218] 04778.04792> |_ / _ \/ _` | '_ \ / _ \ / _ \| __| [00024.218] 04778.04792> / / __/ (_| | |_) | (_) | (_) | |_ [00024.218] 04778.04792> /___\___|\__,_|_.__/ \___/ \___/ \__| [00024.218] 04778.04792> [00024.218] 04778.04792> [00024.218] 04778.04792> zedboot: version: 0.7.13 [00024.218] 04778.04792> [00024.218] 04778.04792> netsvc: nodename='jam-fade-plank-poker' [00024.218] 04778.04792> netsvc: will not advertise [00024.218] 04778.04792> netsvc: start [00024.667] 02887.04246> UMS: block size is: 0x00000200 [00024.667] 02887.04246> UMS: total blocks is: 15232000 [00024.667] 02887.04246> UMS: total size is: 7798784000 [00024.667] 02887.04246> UMS: read-only: 0 removable: 1 [00024.668] 01182.01202> devmgr: /dev/class/block/001: MBR? [00024.668] 01104.01117> devcoord: dc_bind_device() '/boot/driver/mbr.so' [00024.671] 01182.01202> devmgr: /dev/class/block/003: MBR? [00024.671] 01104.01117> devcoord: dc_bind_device() '/boot/driver/mbr.so' [00434.854] 04778.04792> netsvc: Running FVM Paver [00434.856] 04778.04961> paver:[InitializeGpt] Located GPT is invalid; Attempting to initialize [00434.856] 01104.01117> devcoord: dc_bind_device() '' [00434.856] 01104.01117> devcoord: dc_bind_device() '/boot/driver/gpt.so' [00434.856] 03073.03142> gpt: device_get_metadata failed (-25) [00434.857] 01182.01202> devmgr: /dev/class/block/000: GPT? [00434.857] 01104.01117> devcoord: dc_bind_device() '/boot/driver/gpt.so' [00434.857] 03073.03142> devhost: rpc:bind-device failed: -20 [00434.858] 04778.04961> paver:[Initialize] Successfully initialized EFI Device Partitioner [00434.858] 04778.04961> paver:[PartitionPave] Paving partition. [00434.858] 04778.04961> paver:[FindFirstFit] Looking for space [00434.858] 04778.04961> paver:[FindFirstFit] Sorting [00434.858] 04778.04961> paver:[FindFirstFit] Partition[0] From Block [0, 34) ... (next partition starts at block 250069646) [00434.858] 04778.04961> paver:[FindFirstFit] There are 250069612 free blocks (16777216 requested) [00434.858] 04778.04961> paver:[AddPartition] Found space in GPT - OK 250069612 @ 34 [00434.858] 04778.04961> paver:[AddPartition] Final space in GPT - OK 16777216 @ 34 [00434.858] 04778.04961> paver:[AddPartition] Added partition, waiting for bind [00434.858] 01104.01117> devcoord: dc_bind_device() '' [00434.860] 01182.01202> devmgr: /dev/class/block/000: GPT? [00434.860] 01104.01117> devcoord: dc_bind_device() '/boot/driver/gpt.so' [00434.860] 03073.03142> gpt: device_get_metadata failed (-25) [00434.861] 04778.04961> paver:[AddPartition] Added partition, waiting for bind - OK [00434.861] 04778.04961> paver:[PartitionPave] Streaming partitions... [00434.861] 04941.04955> Found compressed file [00434.861] 04778.04961> paver:[FvmStreamPartitions] Header Validated - OK [00434.861] 04778.04961> paver:[FvmPartitionFormat] Initializing partition as FVM [00434.863] 01104.01117> devcoord: dc_bind_device() '/boot/driver/fvm.so' [00435.865] 04778.04961> paver:[FvmStreamPartitions] Partitions pre-validated successfully: Enough space exists to pave. [00435.865] 04778.04961> paver:[AllocatePartitions] Allocating partition blobfs consisting of 1 slices [00435.869] 04778.04961> paver:[AllocatePartitions] Allocating partition minfs consisting of 1 slices [00435.870] 04778.04961> paver:[AllocatePartitions] Creating zxcrypt volume [00435.872] 03073.03142> devhost_get_handles(0x325cef3f79c0:block) open path='zxcrypt/block', r=-2 [00435.872] 01104.01117> devcoord: dc_bind_device() '/boot/driver/zxcrypt.so' [00435.873] 03073.03142> devhost_get_handles(0x325cef3f79c0:block) open path='zxcrypt', r=-2 [00435.876] 04778.04961> paver:[FvmStreamPartitions] Partition space pre-allocated successfully. [00435.876] 04778.04961> paver:[FvmStreamPartitions] Streaming partition 0 [00435.876] 04778.04961> paver:[StreamFvmPartition] Writing extent 0... [00435.876] 04778.04967> netsvc: paver write progress 0.1% [00435.876] 04778.04961> paver:[StreamFvmPartition] 8192 bytes written, 8380416 zeroes left [00435.896] 04778.04961> paver:[StreamFvmPartition] Writing extent 1... [00435.897] 04778.04961> paver:[StreamFvmPartition] 8192 bytes written, 8380416 zeroes left [00435.913] 04778.04961> paver:[StreamFvmPartition] Writing extent 2... [00435.917] 04778.04961> paver:[StreamFvmPartition] 2097152 bytes written, 6291456 zeroes left [00435.929] 04778.04961> paver:[StreamFvmPartition] Writing extent 3... [00435.934] 04778.04961> paver:[StreamFvmPartition] 2097152 bytes written, 6291456 zeroes left [00435.946] 04778.04961> paver:[StreamFvmPartition] Writing extent 4... [00436.876] 04778.04967> netsvc: paver write progress 23.3% [00437.876] 04778.04967> netsvc: paver write progress 34.9% [00438.876] 04778.04967> netsvc: paver write progress 46.5% [00439.876] 04778.04967> netsvc: paver write progress 58.1% [00440.876] 04778.04967> netsvc: paver write progress 69.6% [00441.876] 04778.04967> netsvc: paver write progress 81.2% [00442.876] 04778.04967> netsvc: paver write progress 92.8% 2019/04/19 19:49:49 done 2019/04/19 19:49:49 attempting to send <<image>>bootloader.img... 2019/04/19 19:49:49 target is busy, retrying in one second [00443.438] 04778.04792> netsvc: tftp write of file <<image>>sparse.fvm completed [00443.438] 04778.04792> netsvc: metrics: {"inorderblks": 483260,"oooblks": 0,"ack": 1888,"nack": 0,"timeouts": 0,"sas": 0,"inorderbytes": 494857246} [00443.439] 04778.04961> paver:[StreamFvmPartition] 523771904 bytes written, 4710400 zeroes left [00443.448] 04778.04961> paver:[FvmStreamPartitions] Done streaming partition 0 [00443.448] 04778.04961> paver:[FvmStreamPartitions] Done flushing partition 0 [00443.448] 04778.04961> paver:[FvmStreamPartitions] Streaming partition 1 [00443.448] 04778.04961> paver:[StreamFvmPartition] Writing extent 0... [00443.449] 04778.04961> paver:[StreamFvmPartition] 8192 bytes written, 8380416 zeroes left [00443.487] 04778.04961> paver:[StreamFvmPartition] Writing extent 1... [00443.487] 04778.04961> paver:[StreamFvmPartition] 65536 bytes written, 8323072 zeroes left [00443.530] 04778.04961> paver:[StreamFvmPartition] Writing extent 2... [00443.530] 04778.04961> paver:[StreamFvmPartition] 65536 bytes written, 8323072 zeroes left [00443.566] 04778.04961> paver:[StreamFvmPartition] Writing extent 3... [00443.604] 04778.04961> paver:[StreamFvmPartition] Writing extent 4... [00443.614] 04778.04961> paver:[StreamFvmPartition] 2097152 bytes written, 14680064 zeroes left [00443.681] 04778.04961> paver:[StreamFvmPartition] Writing extent 5... [00443.681] 04778.04961> paver:[StreamFvmPartition] 57344 bytes written, 8331264 zeroes left [00443.716] 04778.04961> paver:[FvmStreamPartitions] Done streaming partition 1 [00443.716] 04778.04961> paver:[FvmStreamPartitions] Done flushing partition 1 [00443.718] 04941.04955> Reading FVM from compressed file: true [00443.718] 04941.04955> Remaining bytes read into compression buffer: 0 [00443.718] 04941.04955> Remaining bytes written to decompression buffer: 0 [00443.718] 04941.04955> Time reading bytes from sparse FVM file: 17151047617 (6 s) [00443.718] 04941.04955> Time reading bytes AND decompressing them: 17382247095 (6 s) [00443.718] 04778.04961> paver:[PartitionPave] Completed successfully 2019/04/19 19:49:50 attempting to send <<image>>bootloader.img... 2019/04/19 19:49:50 done 2019/04/19 19:49:50 attempting to send <<image>>zircona.img... [00444.439] 04778.04792> netsvc: Running BOOTLOADER Paver [00444.442] 04778.06013> paver:[Initialize] Successfully initialized EFI Device Partitioner [00444.442] 04778.06013> paver:[RealMain] SKIPPING BOOTLOADER install on x64 device, pass --force if desired. [00444.453] 04778.04792> netsvc: tftp write of file <<image>>bootloader.img completed [00444.453] 04778.04792> netsvc: metrics: {"inorderblks": 1093,"oooblks": 0,"ack": 5,"nack": 0,"timeouts": 0,"sas": 0,"inorderbytes": 1118208} [00444.453] 04778.04792> netsvc: Running ZIRCON-A Paver [00444.456] 04778.06142> paver:[Initialize] Successfully initialized EFI Device Partitioner [00444.456] 04778.06142> paver:[PartitionPave] Paving partition. [00444.456] 04778.06142> paver:[FindFirstFit] Looking for space [00444.456] 04778.06142> paver:[FindFirstFit] Partition seen with start 34, end 16777249 (length 16777216) [00444.456] 04778.06142> paver:[FindFirstFit] Sorting [00444.456] 04778.06142> paver:[FindFirstFit] Partition[0] From Block [0, 34) ... (next partition starts at block 34) [00444.456] 04778.06142> paver:[FindFirstFit] There are 0 free blocks (32768 requested) [00444.456] 04778.06142> paver:[FindFirstFit] Partition[1] From Block [34, 16777250) ... (next partition starts at block 250069646) [00444.456] 04778.06142> paver:[FindFirstFit] There are 233292396 free blocks (32768 requested) [00444.456] 04778.06142> paver:[AddPartition] Found space in GPT - OK 233292396 @ 16777250 [00444.456] 04778.06142> paver:[AddPartition] Final space in GPT - OK 32768 @ 16777250 [00444.456] 03073.03142> block: Joining un-closed FIFO server [00444.456] 04778.06142> paver:[AddPartition] Added partition, waiting for bind [00444.456] 03073.03142> block: Joining un-closed FIFO server [00444.456] 01104.01117> devcoord: dc_bind_device() '' [00444.457] 01182.01202> devmgr: /dev/class/block/000: GPT? [00444.457] 01104.01117> devcoord: dc_bind_device() '/boot/driver/gpt.so' [00444.457] 03073.03142> gpt: device_get_metadata failed (-25) [00444.458] 01182.01202> devmgr: /dev/class/block/008: FVM? [00444.458] 01104.01117> devcoord: dc_bind_device() '/boot/driver/fvm.so' [00444.458] 04778.06142> paver:[AddPartition] Added partition, waiting for bind - OK 2019/04/19 19:49:50 done 2019/04/19 19:49:50 attempting to send <<image>>zirconr.img... 2019/04/19 19:49:50 target is busy, retrying in one second [00444.595] 04778.04792> netsvc: tftp write of file <<image>>zircona.img completed [00444.595] 04778.04792> netsvc: metrics: {"inorderblks": 13889,"oooblks": 0,"ack": 55,"nack": 0,"timeouts": 0,"sas": 0,"inorderbytes": 14221680} [00444.622] 04778.06142> paver:[PartitionPave] Completed successfully 2019/04/19 19:49:51 attempting to send <<image>>zirconr.img... [00445.596] 04778.04792> netsvc: Running ZIRCON-R Paver [00445.599] 04778.06403> paver:[Initialize] Successfully initialized EFI Device Partitioner [00445.599] 04778.06403> paver:[PartitionPave] Paving partition. [00445.599] 04778.06403> paver:[FindFirstFit] Looking for space [00445.599] 04778.06403> paver:[FindFirstFit] Partition seen with start 34, end 16777249 (length 16777216) [00445.599] 04778.06403> paver:[FindFirstFit] Partition seen with start 16777250, end 16810017 (length 32768) [00445.599] 04778.06403> paver:[FindFirstFit] Sorting [00445.599] 04778.06403> paver:[FindFirstFit] Partition[0] From Block [0, 34) ... (next partition starts at block 34) [00445.599] 04778.06403> paver:[FindFirstFit] There are 0 free blocks (49152 requested) [00445.599] 04778.06403> paver:[FindFirstFit] Partition[1] From Block [34, 16777250) ... (next partition starts at block 16777250) [00445.599] 04778.06403> paver:[FindFirstFit] There are 0 free blocks (49152 requested) [00445.599] 04778.06403> paver:[FindFirstFit] Partition[2] From Block [16777250, 16810018) ... (next partition starts at block 250069646) [00445.599] 04778.06403> paver:[FindFirstFit] There are 233259628 free blocks (49152 requested) [00445.599] 04778.06403> paver:[AddPartition] Found space in GPT - OK 233259628 @ 16810018 [00445.599] 04778.06403> paver:[AddPartition] Final space in GPT - OK 49152 @ 16810018 [00445.599] 04778.06403> paver:[AddPartition] Added partition, waiting for bind [00445.599] 03073.03142> block: Joining un-closed FIFO server [00445.600] 01104.01117> devcoord: dc_bind_device() '' [00445.600] 01182.01202> devmgr: /dev/class/block/000: GPT? [00445.600] 01104.01117> devcoord: dc_bind_device() '/boot/driver/gpt.so' [00445.600] 03073.03142> gpt: device_get_metadata failed (-25) [00445.602] 01182.01202> devmgr: /dev/class/block/012: FVM? [00445.602] 01104.01117> devcoord: dc_bind_device() '/boot/driver/fvm.so' [00445.602] 04778.06403> paver:[AddPartition] Added partition, waiting for bind - OK 2019/04/19 19:49:51 done 2019/04/19 19:49:51 attempting to send <<image>>authorized_keys... 2019/04/19 19:49:51 target is busy, retrying in one second [00445.724] 04778.04792> netsvc: tftp write of file <<image>>zirconr.img completed [00445.724] 04778.04792> netsvc: metrics: {"inorderblks": 12578,"oooblks": 0,"ack": 50,"nack": 0,"timeouts": 0,"sas": 0,"inorderbytes": 12878856} [00445.761] 04778.06403> paver:[PartitionPave] Completed successfully 2019/04/19 19:49:52 attempting to send <<image>>authorized_keys... 2019/04/19 19:49:52 done 2019/04/19 19:49:52 attempting to send <<netboot>>kernel.bin... 2019/04/19 19:49:52 target is busy, retrying in one second [00446.725] 04778.04792> netsvc: Installing SSH authorized_keys [00446.726] 04778.04792> netsvc: tftp write of file <<image>>authorized_keys completed [00446.726] 04778.04792> netsvc: metrics: {"inorderblks": 1,"oooblks": 0,"ack": 1,"nack": 0,"timeouts": 0,"sas": 0,"inorderbytes": 806} [00446.728] 04778.06681> paver:[Initialize] Successfully initialized EFI Device Partitioner [00446.728] 01104.01117> devcoord: dc_bind_device() '/boot/driver/zxcrypt.so' [00446.729] 03073.03142> devhost_get_handles(0x325cef3f79c0:block) open path='zxcrypt', r=-2 [00446.755] 04778.06681> paver:[DataFilePave] Wrote ssh/authorized_keys 2019/04/19 19:49:53 attempting to send <<netboot>>kernel.bin... 2019/04/19 19:49:54 done [00000.000] 00000.00000> zbi: @ 0xffffff8007388000 (12699528 bytes) [00000.000] 00000.00000> UART: FIFO depth 16 [00000.000] 00000.00000> PMM: boot reserve add [0x100000, 0x2fefff] [00000.000] 00000.00000> PMM: boot reserve add [0x7388000, 0x7fa4fff] [00000.000] 00000.00000> PMM: arena too small to be useful (size 4096) [00000.000] 00000.00000> PMM: pmm_add_arena failed to initialize arena [00000.000] 00000.00000> MEM: Failed to add pmm range at 0x8afff000 size 0x1000 [00000.000] 00000.00000> PMM: boot reserve marking WIRED [0x100000, 0x2fefff] [00000.000] 00000.00000> PMM: boot reserve marking WIRED [0x7388000, 0x7fa4fff] [00000.000] 00000.00000> [00000.000] 00000.00000> welcome to Zircon [00000.000] 00000.00000> [00000.000] 00000.00000> KASLR: .text section at 0xffffffff00100000 [00000.000] 00000.00000> INIT: cpu 0, calling hook 0xffffffff00114e2c (global_prng_seed) at level 0x30000, flags 0x1 [00000.000] 00000.00000> initializing vm pre-heap [00000.000] 00000.00000> VM: marking boot alloc used range [0x7fa5000, 0x7fa5100) [00000.000] 00000.00000> INIT: cpu 0, calling hook 0xffffffff001221dc (elf_build_id) at level 0x4fffe, flags 0x1 [00000.000] 00000.00000> INIT: cpu 0, calling hook 0xffffffff00122368 (version) at level 0x4ffff, flags 0x1 [00000.000] 00000.00000> version: [00000.000] 00000.00000> arch: x86 [00000.000] 00000.00000> platform: XXX [00000.000] 00000.00000> target: XXX [00000.000] 00000.00000> project: x64 [00000.000] 00000.00000> buildid: git-9e270ea8151fc86c4ac848c2262fb16022451ba3-dirty [00000.000] 00000.00000> ELF build ID: ff823c6b1314b4bda84861b6c82534fa2102dd35 [00000.000] 00000.00000> initializing heap [00000.000] 00000.00000> INIT: cpu 0, calling hook 0xffffffff00101fc4 (console) at level 0x50000, flags 0x1 [00000.000] 00000.00000> INIT: cpu 0, calling hook 0xffffffff0018262c (x86_resource_init) at level 0x50000, flags 0x1 [00000.000] 00000.00000> initializing vm [00000.000] 00000.00000> VM: reserving kernel region [0xffffffff00100000, 0xffffffff0021b000) flags 0x28 name 'kernel_code' [00000.000] 00000.00000> VM: reserving kernel region [0xffffffff0021b000, 0xffffffff0026b000) flags 0x8 name 'kernel_rodata' [00000.000] 00000.00000> VM: reserving kernel region [0xffffffff0026b000, 0xffffffff00273000) flags 0x18 name 'kernel_data' [00000.000] 00000.00000> VM: reserving kernel region [0xffffffff00273000, 0xffffffff002ff000) flags 0x18 name 'kernel_bss' [00000.000] 00000.00000> INIT: cpu 0, calling hook 0xffffffff001832f0 (display_memtype) at level 0x60001, flags 0x1 [00000.000] 00000.00000> INIT: cpu 0, calling hook 0xffffffff00186780 (acpi_tables) at level 0x60001, flags 0x1 [00000.000] 00000.00000> INIT: cpu 0, calling hook 0xffffffff00181430 (hpet) at level 0x60002, flags 0x1 [00000.000] 00000.00000> INIT: cpu 0, calling hook 0xffffffff001817f0 (apic) at level 0x60002, flags 0x1 [00000.000] 00000.00000> x2APIC enabled [00000.000] 00000.00000> INIT: cpu 0, calling hook 0xffffffff001a7dd4 (system_topology_init) at level 0x60002, flags 0x1 [00000.000] 00000.00000> WARNING: more than 1000 levels of cache, couldn't find highest. [00000.000] 00000.00000> WARNING: unable to find any cache levels. [00000.000] 00000.00000> Could not find SRAT table. ACPICA returned: 5 [00000.000] 00000.00000> INIT: cpu 0, calling hook 0xffffffff00185d70 (timer) at level 0x60003, flags 0x1 [00000.000] 00000.00000> HPET frequency: 23999 ticks/ms [00000.000] 00000.00000> TSC frequency: 2712000 ticks/ms [00448.158] 00000.00000> timer features: constant_tsc 1 invariant_tsc 1 tsc_deadline 1 [00448.158] 00000.00000> Using TSC as wallclock [00448.158] 00000.00000> INIT: cpu 0, calling hook 0xffffffff002085fc (percpu_heap_init) at level 0x60003, flags 0x1 [00448.158] 00000.00000> initializing kernel [00448.158] 00000.00000> initializing mp [00448.158] 00000.00000> INIT: cpu 0, calling hook 0xffffffff00115080 (global_prng_thread_safe) at level 0x7ffff, flags 0x1 [00448.158] 00000.00000> creating bootstrap completion thread [00448.158] 00000.00000> top of bootstrap2() [00448.158] 00000.00000> INIT: cpu 0, calling hook 0xffffffff0013169c (libobject) at level 0x80000, flags 0x1 [00448.158] 00000.00000> OOM: started thread [00448.158] 00000.00000> INIT: cpu 0, calling hook 0xffffffff00205568 (dpc) at level 0x80000, flags 0x1 [00448.158] 00000.00000> Processor Model Info: type 0 family 0x6 model 0xe stepping 0x9 [00448.158] 00000.00000> display_family 0x6 display_model 0x8e [00448.158] 00000.00000> Vendor: Intel [00448.158] 00000.00000> Microarch: Kaby Lake [00448.158] 00000.00000> F/M/S: 6/8e/9 [00448.158] 00000.00000> patch_level: 8e [00448.158] 00000.00000> Brand: Intel(R) Core(TM) i5-7300U CPU @ 2.60GHz [00448.158] 00000.00000> Features: fpu sse sse2 sse3 ssse3 sse4.1 sse4.2 mmx avx avx2 fxsr pcid xsave mon aesni clflush [00448.158] 00000.00000> clflushopt fsgsbase tsc_adj smep smap erms rdrand rdseed syscall nx huge rdtscp [00448.158] 00000.00000> invar_tsc tsc_deadline x2apic vmx pt hwp [00448.158] 00000.00000> Properties: meltdown l1tf pcid_good [00448.158] 00000.00000> initializing platform [00448.158] 00000.00000> INIT: cpu 0, calling hook 0xffffffff001a14e4 (x86_perfmon) at level 0x90000, flags 0x1 [00448.158] 00000.00000> PMU: version 4 [00448.158] 00000.00000> UART: started IRQ driven RX [00448.158] 00000.00000> UART: started IRQ driven TX [00448.158] 00000.00000> cpu topology: [00448.158] 00000.00000> 0: apic id 0x0 BSP [00448.158] 00000.00000> 1: apic id 0x1 [00448.158] 00000.00000> 2: apic id 0x2 [00448.158] 00000.00000> 3: apic id 0x3 [00448.158] 00000.00000> Found 4 cpus [00448.158] 00000.00000> booting apic ids: 0x1 0x2 0x3 [00448.173] 00000.00000> entering scheduler on cpu 1 [00448.174] 00000.00000> entering scheduler on cpu 2 [00448.174] 00000.00000> entering scheduler on cpu 3 [00448.177] 00000.00000> smbios: manufacturer="Intel Corporation" product="NUC7i5DNHE" [00448.177] 00000.00000> initializing target [00448.177] 00000.00000> INIT: cpu 0, calling hook 0xffffffff00185020 (x86_pcie_init) at level 0xa0000, flags 0x1 [00448.177] 00000.00000> moving to last init level [00448.177] 00000.00000> INIT: cpu 0, calling hook 0xffffffff00121434 (debuglog) at level 0xb0000, flags 0x1 [00448.177] 00000.00000> INIT: cpu 0, calling hook 0xffffffff00174ca8 (kcounters) at level 0xb0000, flags 0x1 [00448.177] 00000.00000> INIT: cpu 0, calling hook 0xffffffff00102aec (kernel_shell) at level 0xc0000, flags 0x1 [00448.177] 00000.00000> INIT: cpu 0, calling hook 0xffffffff002027a0 (ktrace) at level 0xc0000, flags 0x1 [00448.180] 00000.00000> ktrace: buffer at 0xffffff91e965f000 (33554432 bytes) [00448.180] 00000.00000> INIT: cpu 0, calling hook 0xffffffff002181d0 (userboot) at level 0xc0000, flags 0x1 [00448.180] 00000.00000> userboot: ramdisk 0xc1d000 @ 0xffffff8007388000 [00448.181] 00000.00000> userboot: userboot rodata 0 @ [0xa61d63c9000,0xa61d63cc000) [00448.181] 00000.00000> userboot: userboot code 0x3000 @ [0xa61d63cc000,0xa61d63d7000) [00448.181] 00000.00000> userboot: vdso/full rodata 0 @ [0xa61d63d7000,0xa61d63de000) [00448.181] 00000.00000> userboot: vdso/full code 0x7000 @ [0xa61d63de000,0xa61d63df000) [00448.181] 00000.00000> userboot: entry point @ 0xa61d63ccc90 [00448.211] 01036.01043> userboot: searching bootfs for 'bin/bootsvc' [00448.211] 01036.01043> userboot: 'bin/bootsvc' has PT_INTERP "lib/ld.so.1" [00448.211] 01036.01043> userboot: searching bootfs for 'lib/ld.so.1' [00448.211] 01036.01043> userboot: userboot: loaded lib/ld.so.1 at 0x5aad31fe9000, entry point 0x5aad320073d0 [00448.211] 01036.01043> userboot: userboot: loaded vDSO at 0x45471a816000, entry point 0x45471a81d8fa [00448.211] 01036.01043> userboot: process bin/bootsvc started. [00448.211] 01036.01043> userboot: waiting for loader-service requests... [00448.211] 01036.01043> userboot: searching bootfs for 'lib/libasync-default.so' [00448.211] 01036.01043> userboot: searching bootfs for 'lib/libfdio.so' [00448.211] 01036.01043> userboot: searching bootfs for 'lib/libtrace-engine.so' [00448.211] 01036.01043> userboot: searching bootfs for 'lib/liblaunchpad.so' [00448.211] 01050.01053> {{{reset}}} [00448.211] 01050.01053> {{{module:0:<application>:elf:73f57194d3258e1cae93968f676f30f863d98c9e}}} [00448.211] 01050.01053> {{{mmap:0x919fc1ad000:0x3a000:load:0:rx:0}}} [00448.211] 01050.01053> {{{mmap:0x919fc1e7000:0x4000:load:0:rw:0x3a000}}} [00448.211] 01050.01053> dso: id=73f57194d3258e1cae93968f676f30f863d98c9e base=0x00000919fc1ad000 name=<application> [00448.211] 01050.01053> {{{module:0x2:<vDSO>:elf:71712e0a455898a51e34d40a4013786ab1fa5335}}} [00448.211] 01050.01053> {{{mmap:0x45471a816000:0x7000:load:0x2:r:0}}} [00448.211] 01050.01053> {{{mmap:0x45471a81d000:0x1000:load:0x2:rx:0x7000}}} [00448.211] 01050.01053> dso: id=71712e0a455898a51e34d40a4013786ab1fa5335 base=0x000045471a816000 name=<vDSO> [00448.211] 01050.01053> {{{module:0x3:libasync-default.so:elf:8c511b4202cf569c8fdde14ca97222102ba3a9e0}}} [00448.211] 01050.01053> {{{mmap:0x3efdd61ed000:0x1000:load:0x3:rx:0}}} [00448.211] 01050.01053> {{{mmap:0x3efdd61ee000:0x1000:load:0x3:rw:0x1000}}} [00448.211] 01050.01053> dso: id=8c511b4202cf569c8fdde14ca97222102ba3a9e0 base=0x00003efdd61ed000 name=libasync-default.so [00448.211] 01050.01053> {{{module:0x4:libfdio.so:elf:3efa72b2e3bd2e4271f835d34a81d9719d6e08a7}}} [00448.211] 01050.01053> {{{mmap:0x4f5b07813000:0x32000:load:0x4:rx:0}}} [00448.211] 01050.01053> {{{mmap:0x4f5b07846000:0x4000:load:0x4:rw:0x33000}}} [00448.211] 01050.01053> dso: id=3efa72b2e3bd2e4271f835d34a81d9719d6e08a7 base=0x00004f5b07813000 name=libfdio.so [00448.211] 01050.01053> {{{module:0x5:libtrace-engine.so:elf:b82e75659fdaaa34e91100dc98d0a90f14f77ded}}} [00448.211] 01050.01053> {{{mmap:0x593a73962000:0x9000:load:0x5:rx:0}}} [00448.211] 01050.01053> {{{mmap:0x593a7396b000:0x2000:load:0x5:rw:0x9000}}} [00448.211] 01050.01053> dso: id=b82e75659fdaaa34e91100dc98d0a90f14f77ded base=0x0000593a73962000 name=libtrace-engine.so [00448.211] 01050.01053> {{{module:0x6:liblaunchpad.so:elf:5b0854856213eae6bab93c982f39551f8f9591c5}}} [00448.211] 01050.01053> {{{mmap:0x4646af815000:0x7000:load:0x6:rx:0}}} [00448.211] 01050.01053> {{{mmap:0x4646af81c000:0x2000:load:0x6:rw:0x7000}}} [00448.211] 01050.01053> dso: id=5b0854856213eae6bab93c982f39551f8f9591c5 base=0x00004646af815000 name=liblaunchpad.so [00448.211] 01050.01053> {{{module:0x1:libc.so:elf:5d417db61b3a48a58a8fa1ffbfc2e71b830e0857}}} [00448.211] 01050.01053> {{{mmap:0x5aad31fe9000:0xa6000:load:0x1:rx:0}}} [00448.211] 01050.01053> {{{mmap:0x5aad3208f000:0x5000:load:0x1:rw:0xa6000}}} [00448.211] 01050.01053> dso: id=5d417db61b3a48a58a8fa1ffbfc2e71b830e0857 base=0x00005aad31fe9000 name=libc.so [00448.211] 01050.01053> bootsvc: Starting... [00448.212] 01036.01043> userboot: loader-service channel peer closed [00448.212] 01036.01043> userboot: finished! [00448.212] 01050.01053> bootsvc: Creating bootfs service... [00448.212] 01050.01053> bootsvc: Retrieving boot image... [00448.212] 01050.01053> bootsvc: Decommitted BOOTDATA VMO from 0 to 0xc1c000 [00448.212] 01050.01053> bootsvc: Loading boot arguments... [00448.212] 01050.01053> bootsvc: Creating svcfs service... [00448.212] 01050.01053> bootsvc: Loading kernel VMOs... [00448.212] 01050.01053> bootsvc: Creating loader service... [00448.212] 01050.01053> bootsvc: Launching next process... [00448.212] 01050.01107> bootsvc: Launched bin/devcoordinator [00448.213] 01114.01129> devcoordinator: launch /boot/bin/svchost (svchost) OK [00448.214] 01114.01129> devcoordinator: launch /boot/bin/fshost (fshost) OK [00448.217] 01114.01350> devcoordinator: launch /boot/bin/netsvc (netsvc) OK [00448.217] 01114.01322> devcoordinator: launch /boot/bin/pwrbtn-monitor (pwrbtn-monitor) OK [00448.218] 01114.01350> devcoordinator: launch /boot/bin/virtual-console (virtual-console) OK [00448.221] 01114.01129> devcoordinator: full system required, ignoring fallback drivers until /system is loaded [00448.221] 01114.01129> devcoordinator: launch devhost 'devhost:sys': pid=2193 [00448.222] 01114.01129> devcoordinator: launch devhost 'devhost:test': pid=2225 [00448.222] 01114.01129> devcoordinator: launch devhost 'devhost:root': pid=2272 [00448.222] 02193.02207> devhost: trace provider registry begun [00448.223] 01114.01129> devcoordinator: launch devhost 'devhost:misc': pid=2370 [00448.223] 02225.02247> devhost: trace provider registry begun [00448.224] 02272.02301> devhost: trace provider registry begun [00448.224] 02370.02406> devhost: trace provider registry begun [00448.225] 01114.01334> devcoordinator: launch /boot/bin/sh (sh:console) OK [00448.309] 02193.02207> acpi-bus: not using IOMMU [00448.316] 02193.02207> PMU: 7 arch events [00448.316] 02193.02207> PMU: arch event id range: 1-7 [00448.316] 02193.02207> PMU: 102 arch events [00448.316] 02193.02207> PMU: arch event id range: 1-241 [00448.316] 02193.02207> Intel Processor Trace configuration for this chipset: [00448.316] 02193.02207> mtc_freq_mask: 0x249 [00448.316] 02193.02207> cyc_thresh_mask: 0x3fff [00448.316] 02193.02207> psb_freq_mask: 0x3f [00448.316] 02193.02207> num addr ranges: 2 [00448.317] 02193.02207> [sysmem_init 28] async_get_default_dispatcher(): 0x36d62f119bd0 [00448.317] 02193.02207> [sysmem_bind 40] sysmem_bind() [00448.317] 02193.02885> acpi-pwrbtn: initialized [00448.317] 01729.01756> vc: new input device /dev/class/input/000 [00448.348] 02193.02885> acpi: published device pci(0x36d56f174550), parent=sys(0x36d6af113510), handle=0x36d52f12aa50 [00448.348] 01114.01129> devcoordinator: launch devhost 'devhost:pci#1:8086:5916': pid=2981 [00448.349] 01114.01129> devcoordinator: launch devhost 'devhost:pci#3:8086:9d2f': pid=3053 [00448.350] 02193.02885> acpi: published device rtc(0x36d56f1765f0), parent=acpi(0x36d6af113010), handle=0x36d52f150190 [00448.351] 02981.02995> devhost: trace provider registry begun [00448.352] 03053.03067> devhost: trace provider registry begun [00448.352] 01114.01129> devcoordinator: launch devhost 'devhost:pci#5:8086:9d60': pid=3202 [00448.352] 01114.01129> devcoordinator: launch devhost 'devhost:pci#6:8086:9d61': pid=3252 [00448.353] 02193.02885> acpi-ec: initialized [00448.353] 01114.01129> devcoordinator: launch devhost 'devhost:pci#9:8086:9d03': pid=3342 [00448.354] 03202.03216> devhost: trace provider registry begun [00448.355] 03252.03273> devhost: trace provider registry begun [00448.355] 01114.01129> devcoordinator: launch devhost 'devhost:pci#14:8086:9d71': pid=3505 [00448.356] 03342.03374> devhost: trace provider registry begun [00448.356] 01114.01129> devcoordinator: launch devhost 'devhost:pci#16:8086:156f': pid=3616 [00448.357] 03342.03374> ahci: using MSI interrupt [00448.357] 03202.03216> initialized intel serialio i2c driver, reg=0x87481bb2000 regsize=4096 [00448.357] 03252.03273> initialized intel serialio i2c driver, reg=0x23e915450000 regsize=4096 [00448.357] 03505.03541> devhost: trace provider registry begun [00448.358] 03616.03646> devhost: trace provider registry begun [00448.358] 02193.02885> acpi: failed to create NHLT VMO (res -10) [00448.358] 02193.02885> acpi: failed to publish NHLT metadata [00448.369] 03053.03965> * found USB device (0x18d1:0xa002, USB 2.0) config 1 [00448.369] 03053.03965> * found USB device (0x18d1:0xa003, USB 3.0) config 1 [00448.370] 03505.03541> [IHDA DSP 00:1f.3] Failed to fetch NHLT (res -25) [00448.370] 03505.03541> [IHDA Controller 00:1f.3] Failed to initialize DSP device (res = -25) [00448.438] 01610.01634> netifc: ? /dev/class/ethernet/000 [00448.438] 01610.01634> netifc: create 512 eth buffers [00448.438] 01610.01634> macaddr: 54:b2:03:13:37:3b [00448.438] 01610.01634> ip6addr: fe80::56b2:34d:fe13:373b [00448.438] 01610.01634> snmaddr: ff02::1:ff13:373b [00448.438] 01610.01634> netsvc: using /dev/class/ethernet/000 [00448.438] 01610.01634> netsvc: nodename='jam-fade-plank-poker' [00448.438] 01610.01634> netsvc: start [00448.467] 01729.01756> vc: new display device /dev/class/display-controller/000 [00448.507] 02981.04249> i915: MST not supported [00448.974] 02981.04249> i915: Found DP monitor [00448.974] 02981.04249> i915: Display 1 connected [00449.532] 01729.01756> vc: Successfully attached to display 1 [00449.831] 03053.03965> * found USB device (0x0781:0x5571, USB 2.0) config 1 [00450.082] 03053.03965> * found USB device (0x8087:0x0a2b, USB 2.0) config 1 [00450.367] 03252.03273> intel-i2c-controller: intel_serialio_i2c_slave_transfer: -21 [00450.367] 03252.03273> i2c-hid: could not read HID descriptor: 0 [00450.367] 03252.03273> devhost[00:15.1/i2c-bus-9d61/004c] bind driver '/boot/driver/i2c-hid.so' failed: -2 [00450.367] 01114.01129> devcoordinator: rpc: bind-driver '004c' status -2 [00450.370] 03202.03216> intel-i2c-controller: intel_serialio_i2c_slave_transfer: -21 [00450.370] 03202.03216> i2c-hid: could not read HID descriptor: 0 [00450.370] 03202.03216> devhost[00:15.0/i2c-bus-9d60/0020] bind driver '/boot/driver/i2c-hid.so' failed: -2 [00450.370] 01114.01129> devcoordinator: rpc: bind-driver '0020' status -2 [00450.381] 03342.03919> sata2: dev info [00450.381] 03342.03919> serial=AA000000000000009043 [00450.381] 03342.03919> firmware rev=0R08A1 0 [00450.381] 03342.03919> model id=ETMAT 8MSP1582 G [00450.381] 03342.03919> major=0x3f0 ACS2 DMA 32 commands [00450.381] 03342.03919> LBA48 250069680 sectors, sector size=512 [00450.382] 01300.01314> fshost: /dev/class/block/000: GPT? [00450.382] 03342.03374> gpt: device_get_metadata failed (-25) [00450.386] 01300.01314> fshost: /dev/class/block/001: FVM? [00450.389] 01300.01314> devcoordinator: launch /boot/bin/blobfs (blobfs:/blob) OK [00450.531] 01300.01314> fshost: starting 'bin/pkgsvr' 'eed676c69ed4a826e059065ca4d313f7867c7a0bf654233fa03616194f36ed03'... [00450.537] 01300.01314> devcoordinator: launch bin/pkgsvr (pkgfs) OK [00450.549] 04659.04873> pkgsvr: system: will be served from eed676c69ed4a826e059065ca4d313f7867c7a0bf654233fa03616194f36ed03 [00450.549] 04659.04873> pkgsvr: pkgfs serving index /data/pkgfs_index from blobfs /blob [00450.555] 01300.01314> fshost: /dev/class/block/005: zxcrypt? [00450.555] 03342.03374> devhost_get_handles(0x4b12c1e4f310:block) open path='zxcrypt', r=-2 [00450.566] 01114.01772> devcoordinator: launch /system/bin/appmgr (appmgr) OK DEBUG: stopping or rebooting the node "jam-fade-plank-poker" ERROR: cannot connect to address "[fe80::56b2:3ff:fe13:373b%eno2]:22": dial tcp6 [fe80::56b2:3ff:fe13:373b%eno2]:22: i/o timeout @@@