0 files remaining...
2019/05/20 21:37:38 attempting to send <<netboot>>cmdline...
2019/05/20 21:37:38 done
2019/05/20 21:37:38 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.007] 00000.00000> timer features: constant_tsc 1 invariant_tsc 1 tsc_deadline 1
[00021.007] 00000.00000> Using TSC as wallclock
[00021.007] 00000.00000> initializing kernel
[00021.007] 00000.00000> initializing mp
[00021.007] 00000.00000> initializing timers
[00021.007] 00000.00000> INIT: cpu 0, calling hook 0xffffffff0013c578 (debuglog) at level 0x7ffff, flags 0x1
[00021.007] 00000.00000> INIT: cpu 0, calling hook 0xffffffff00195518 (thread_set_priority_experiment) at level 0x7ffff, flags 0x1
[00021.007] 00000.00000> thread set priority experiment is : ENABLED
[00021.007] 00000.00000> INIT: cpu 0, calling hook 0xffffffff001aa67c (global_prng_thread_safe) at level 0x7ffff, flags 0x1
[00021.007] 00000.00000> creating bootstrap completion thread
[00021.349] 00000.00000> top of bootstrap2()
[00021.349] 00000.00000> INIT: cpu 0, calling hook 0xffffffff0013151c (dpc) at level 0x80000, flags 0x1
[00021.362] 00000.00000> INIT: cpu 0, calling hook 0xffffffff00152978 (libobject) at level 0x80000, flags 0x1
[00021.362] 00000.00000> OOM: started thread
[00021.376] 00000.00000> Processor Model Info: type 0 family 0x6 model 0xe stepping 0x9
[00021.376] 00000.00000> display_family 0x6 display_model 0x8e
[00021.376] 00000.00000> Vendor: Intel
[00021.376] 00000.00000> Microarch: Kaby Lake
[00021.376] 00000.00000> F/M/S: 6/8e/9
[00021.376] 00000.00000> Brand: Intel(R) Core(TM) i5-7300U CPU @ 2.60GHz
[00021.376] 00000.00000> Features: fpu sse sse2 sse3 ssse3 sse4.1 sse4.2 mmx avx avx2 fxsr pcid xsave mon aesni clflush
[00021.376] 00000.00000> clflushopt fsgsbase tsc_adj smep smap erms rdrand rdseed syscall nx huge rdtscp
[00021.376] 00000.00000> invar_tsc tsc_deadline x2apic vmx pt hwp
[00021.376] 00000.00000> initializing platform
[00021.376] 00000.00000> INIT: cpu 0, calling hook 0xffffffff001101f4 (x86_perfmon) at level 0x90000, flags 0x1
[00021.376] 00000.00000> PMU: version 4
[00021.376] 00000.00000> UART: started IRQ driven RX
[00021.376] 00000.00000> UART: started IRQ driven TX
[00021.376] 00000.00000> cpu topology:
[00021.376] 00000.00000> 0: apic id 0x0 package 0 node 0 core 0 smt 0 BSP
[00021.376] 00000.00000> 1: apic id 0x2 package 0 node 0 core 1 smt 0
[00021.376] 00000.00000> 2: apic id 0x1 package 0 node 0 core 0 smt 1
[00021.376] 00000.00000> 3: apic id 0x3 package 0 node 0 core 1 smt 1
[00021.376] 00000.00000> Found 4 cpus
[00021.376] 00000.00000> booting apic ids: 0x2 0x1 0x3
[00021.392] 00000.00000> entering scheduler on cpu 2
[00021.393] 00000.00000> entering scheduler on cpu 1
[00021.393] 00000.00000> entering scheduler on cpu 3
[00021.396] 00000.00000> smbios: manufacturer="Intel Corporation" product="NUC7i5DNHE"
[00021.396] 00000.00000> initializing target
[00021.396] 00000.00000> INIT: cpu 0, calling hook 0xffffffff001053a0 (x86_pcie_init) at level 0xa0000, flags 0x1
[00021.396] 00000.00000> moving to last init level
[00021.396] 00000.00000> INIT: cpu 0, calling hook 0xffffffff00144140 (ktrace) at level 0xc0000, flags 0x1
[00021.399] 00000.00000> ktrace: buffer at 0xffffff9ca6064000 (33554432 bytes)
[00021.399] 00000.00000> INIT: cpu 0, calling hook 0xffffffff00147ab4 (userboot) at level 0xc0000, flags 0x1
[00021.399] 00000.00000> userboot: ramdisk 0x10ad000 @ 0xffffff80012f2000
[00021.400] 00000.00000> userboot: userboot rodata 0 @ [0x711f89120000,0x711f89123000)
[00021.400] 00000.00000> userboot: userboot code 0x3000 @ [0x711f89123000,0x711f8912e000)
[00021.400] 00000.00000> userboot: vdso/full rodata 0 @ [0x711f8912e000,0x711f89135000)
[00021.400] 00000.00000> userboot: vdso/full code 0x7000 @ [0x711f89135000,0x711f89136000)
[00021.400] 00000.00000> userboot: entry point @ 0x711f89123c10
[00021.400] 00000.00000> INIT: cpu 0, calling hook 0xffffffff001aa030 (kernel_shell) at level 0xc0000, flags 0x1
[00021.400] 01036.01043> userboot: option "netsvc.disable=true"
[00021.400] 01036.01043> userboot: option "zircon.system.disable-automount=true"
[00021.400] 01036.01043> userboot: option "zircon.autorun.boot=/boot/infra/setup"
[00021.400] 01036.01043> userboot: option "kernel.serial=legacy"
[00021.400] 01036.01043> userboot: option "
http://192.168.42.1/multiboot/54%3Ab2%3A03%3A13%3Aae%3Ab3="
[00021.400] 01036.01043> userboot: option "multiboot.boot_loader_name=iPXE+1.0.0++(d2063)"
[00021.439] 01036.01043> userboot: searching bootfs for 'bin/bootsvc'
[00021.439] 01036.01043> userboot: 'bin/bootsvc' has PT_INTERP "lib/ld.so.1"
[00021.439] 01036.01043> userboot: searching bootfs for 'lib/ld.so.1'
[00021.439] 01036.01043> userboot: userboot: loaded lib/ld.so.1 at 0x6690cc5fc000, entry point 0x6690cc6820d3
[00021.439] 01036.01043> userboot: userboot: loaded vDSO at 0x532810c88000, entry point 0x0
[00021.439] 01036.01043> userboot: process bin/bootsvc started.
[00021.439] 01036.01043> userboot: waiting for loader-service requests...
[00021.439] 01036.01043> userboot: searching bootfs for 'lib/libasync-default.so'
[00021.439] 01036.01043> userboot: searching bootfs for 'lib/libfdio.so'
[00021.439] 01036.01043> userboot: searching bootfs for 'lib/liblaunchpad.so'
[00021.439] 01036.01043> userboot: searching bootfs for 'lib/libtrace-engine.so'
[00021.439] 01050.01053> {{{reset}}}
[00021.439] 01050.01053> {{{module:0:<application>:elf:18de7d58f51e8ba5c4f6afdd0cc8440f482c2b45}}}
[00021.439] 01050.01053> {{{mmap:0x47c77b120000:0x2e000:load:0:rx:0}}}
[00021.439] 01050.01053> {{{mmap:0x47c77b14e000:0x4000:load:0:rw:0x2e000}}}
[00021.439] 01050.01053> dso: id=18de7d58f51e8ba5c4f6afdd0cc8440f482c2b45 base=0x000047c77b120000 name=<application>
[00021.439] 01050.01053> {{{module:0x3:libasync-default.so:elf:c189f51f19d10785d93b5235ad1b46dca4451b00}}}
[00021.439] 01050.01053> {{{mmap:0x20815da1d000:0x1000:load:0x3:rx:0}}}
[00021.439] 01050.01053> {{{mmap:0x20815da1e000:0x1000:load:0x3:rw:0x1000}}}
[00021.439] 01050.01053> dso: id=c189f51f19d10785d93b5235ad1b46dca4451b00 base=0x000020815da1d000 name=libasync-default.so
[00021.439] 01050.01053> {{{module:0x2:<vDSO>:elf:40ab5fa3b61f12fef4a44477a687f608661cd450}}}
[00021.439] 01050.01053> {{{mmap:0x532810c88000:0x7000:load:0x2:r:0}}}
[00021.439] 01050.01053> {{{mmap:0x532810c8f000:0x1000:load:0x2:rx:0x7000}}}
[00021.439] 01050.01053> dso: id=40ab5fa3b61f12fef4a44477a687f608661cd450 base=0x0000532810c88000 name=<vDSO>
[00021.439] 01050.01053> {{{module:0x1:libc.so:elf:67a12284bce140fc32aaaeac223e0e8f85cb5085}}}
[00021.439] 01050.01053> {{{mmap:0x6690cc5fc000:0xcb000:load:0x1:rx:0}}}
[00021.439] 01050.01053> {{{mmap:0x6690cc6c8000:0x6000:load:0x1:rw:0xcc000}}}
[00021.439] 01050.01053> dso: id=67a12284bce140fc32aaaeac223e0e8f85cb5085 base=0x00006690cc5fc000 name=libc.so
[00021.439] 01050.01053> {{{module:0x4:libfdio.so:elf:27787977e95f3b9563c9e0bd4d34ec92b7e9ad88}}}
[00021.439] 01050.01053> {{{mmap:0xed718976000:0x24000:load:0x4:rx:0}}}
[00021.439] 01050.01053> {{{mmap:0xed71899b000:0x4000:load:0x4:rw:0x25000}}}
[00021.439] 01050.01053> dso: id=27787977e95f3b9563c9e0bd4d34ec92b7e9ad88 base=0x00000ed718976000 name=libfdio.so
[00021.439] 01050.01053> {{{module:0x5:liblaunchpad.so:elf:6fc2232dc8c1bc5c6adb8ad50ca794b5a260ee4f}}}
[00021.439] 01050.01053> {{{mmap:0x2d1719c64000:0x7000:load:0x5:rx:0}}}
[00021.439] 01050.01053> {{{mmap:0x2d1719c6b000:0x2000:load:0x5:rw:0x7000}}}
[00021.439] 01050.01053> dso: id=6fc2232dc8c1bc5c6adb8ad50ca794b5a260ee4f base=0x00002d1719c64000 name=liblaunchpad.so
[00021.439] 01050.01053> {{{module:0x6:libtrace-engine.so:elf:c9042b83fe01206008fcefb16395238417248169}}}
[00021.439] 01050.01053> {{{mmap:0x68d08e3b5000:0x9000:load:0x6:rx:0}}}
[00021.439] 01050.01053> {{{mmap:0x68d08e3be000:0x2000:load:0x6:rw:0x9000}}}
[00021.439] 01050.01053> dso: id=c9042b83fe01206008fcefb16395238417248169 base=0x000068d08e3b5000 name=libtrace-engine.so
[00021.440] 01050.01053> bootsvc: Starting...
[00021.440] 01036.01043> userboot: loader-service channel peer closed
[00021.440] 01036.01043> userboot: finished!
[00021.440] 01050.01053> bootsvc: Creating bootfs service...
[00021.440] 01050.01053> bootsvc: Processing bootdata...
[00021.440] 01050.01053> bootsvc: Loading boot cmdline overrides...
[00021.440] 01050.01053> bootsvc: Loading kernel VMOs...
[00021.440] 01050.01053> bootsvc: Creating loader service...
[00021.440] 01050.01053> bootsvc: Launching next process...
[00021.440] 01050.01096> bootsvc: launched bin/devmgr
[00021.441] 01104.01117> devmgr: main()
[00021.441] 01104.01117> cmdline: netsvc.disable=true
[00021.441] 01104.01117> cmdline: zircon.system.disable-automount=true
[00021.441] 01104.01117> cmdline: zircon.autorun.boot=/boot/infra/setup
[00021.441] 01104.01117> cmdline: kernel.serial=legacy
[00021.441] 01104.01117> cmdline:
http://192.168.42.1/multiboot/54%3Ab2%3A03%3A13%3Aae%3Ab3=
[00021.441] 01104.01117> cmdline: multiboot.boot_loader_name=iPXE+1.0.0++(d2063)
[00021.441] 01104.01117> devmgr: coordinator_init()
[00021.441] 01104.01117> devmgr: init
[00021.441] 01104.01117> devmgr: svc init
[00021.441] 01104.01117> devmgr: launch /boot/bin/svchost (svchost) OK
[00021.441] 01104.01117> devmgr: vfs init
[00021.441] 01104.01117> devmgr: launch /boot/bin/fshost (fshost) OK
[00021.442] 01104.01222> devmgr: shell startup
[00021.443] 01182.01202> fshost: started.
[00021.444] 01104.01213> devmgr: launch /boot/bin/pwrbtn-monitor (pwrbtn-monitor) OK
[00021.444] 01104.01231> devmgr: launch /boot/bin/virtual-console (virtual-console) OK
[00021.444] 01104.01231> zircon.autorun.boot: starting '/boot/infra/setup'...
[00021.444] 01104.01231> devmgr: launch /boot/infra/setup (autorun:boot) OK
[00021.447] 01104.01117> devcoord: launch devhost 'devhost:sys': pid=2049
[00021.447] 01104.01117> devcoord: launch devhost 'devhost:test': pid=2082
[00021.447] 01104.01117> devcoord: launch devhost 'devhost:root': pid=2115
[00021.448] 01104.01117> devcoord: launch devhost 'devhost:misc': pid=2171
[00021.449] 02049.02073> devhost: trace provider registry begun
[00021.449] 02082.02105> devhost: trace provider registry begun
[00021.451] 02171.02203> devhost: trace provider registry begun
[00021.452] 02115.02152> devhost: trace provider registry begun
[00021.453] 01104.01222> devmgr: launch /boot/bin/sh (sh:console) OK
[00021.508] 02049.02073> acpi-bus: not using IOMMU
[00021.513] 02049.02073> acpi-pwrbtn: initialized
[00021.535] 02049.02073> acpi: published device pci(0x98cf95cd200), parent=proxy(0x98cf95c9540), handle=0x98cf9605c30
[00021.536] 02049.02073> acpi: published device rtc(0x98cf95c8080), parent=acpi(0x98cf95c9780), handle=0x98cf961e5b0
[00021.537] 02049.02073> acpi-ec: initialized
[00021.539] 02049.02073> acpi: failed to create NHLT VMO (res -10)
[00021.539] 02049.02073> acpi: failed to publish NHLT metadata
[00021.541] 02049.02073> [sysmem_init 28] async_get_default_dispatcher(): 0x98cf95bc0a0
[00021.541] 02049.02073> [sysmem_bind 40] sysmem_bind()
[00021.541] 02049.02073> acpi-bus: sysmem_register_protocol() intentionally ignored for now.
[00021.541] 02049.02073> PMU: 7 arch events
[00021.541] 02049.02073> PMU: arch event id range: 1-7
[00021.541] 02049.02073> PMU: 102 model events
[00021.541] 02049.02073> PMU: model event id range: 1-241
[00021.541] 02049.02073> Intel Processor Trace configuration for this chipset:
[00021.541] 02049.02073> mtc_freq_mask: 0x249
[00021.541] 02049.02073> cyc_thresh_mask: 0x3fff
[00021.541] 02049.02073> psb_freq_mask: 0x3f
[00021.541] 02049.02073> num addr ranges: 2
[00021.541] 01104.01117> devcoord: launch devhost 'devhost:pci#1:8086:5916': pid=2837
[00021.542] 01104.01117> devcoord: launch devhost 'devhost:pci#3:8086:9d2f': pid=2880
[00021.542] 01104.01117> devcoord: launch devhost 'devhost:pci#5:8086:9d60': pid=2944
[00021.543] 02837.02860> devhost: trace provider registry begun
[00021.543] 01104.01117> devcoord: launch devhost 'devhost:pci#6:8086:9d61': pid=3011
[00021.543] 02880.02918> devhost: trace provider registry begun
[00021.544] 01104.01117> devcoord: launch devhost 'devhost:pci#9:8086:9d03': pid=3099
[00021.545] 02944.02985> devhost: trace provider registry begun
[00021.545] 03011.03062> devhost: trace provider registry begun
[00021.545] 01104.01117> devcoord: launch devhost 'devhost:pci#14:8086:9d71': pid=3211
[00021.546] 01104.01117> devcoord: launch devhost 'devhost:pci#16:8086:156f': pid=3323
[00021.546] 03099.03155> devhost: trace provider registry begun
[00021.547] 03099.03155> ahci: using MSI interrupt
[00021.547] 02944.02985> initialized intel serialio i2c driver, reg=0x46ce52115000 regsize=4096
[00021.547] 03211.03285> devhost: trace provider registry begun
[00021.548] 03323.03368> devhost: trace provider registry begun
[00021.550] 03011.03062> initialized intel serialio i2c driver, reg=0x7ba244fc000 regsize=4096
[00021.554] 01240.01545> vc: new input device /dev/class/input/000
[00021.563] 03211.03285> [IHDA DSP 00:1f.3] Failed to fetch NHLT (res -25)
[00021.563] 03211.03285> devhost[00:1f.3/intel-hda-000/intel-sst-dsp-000] bind driver '/boot/driver/dsp.so' failed: -25
[00021.563] 02880.03825> * found USB device (0x18d1:0xa002, USB 2.0) config 1
[00021.563] 01104.01117> devcoord: rpc: bind-driver 'intel-sst-dsp-000' status -25
[00021.564] 02880.03825> * found USB device (0x18d1:0xa003, USB 3.0) config 1
[00021.654] 01240.01545> vc: new display device /dev/class/display-controller/000/virtcon
[00021.795] 02837.04142> i915: MST not supported
[00022.294] 02837.04142> i915: Found DP monitor
[00022.294] 02837.04142> i915: Display 1 connected
[00022.854] 01240.01545> vc: Successfully attached to display 1
[00023.026] 02880.03825> * found USB device (0x0781:0x5571, USB 2.0) config 1
[00023.027] 02880.02918> UMS: parent: 'ifc-000'
[00023.027] 02880.02918> UMS:Max lun is: 0
[00023.277] 02880.03825> * found USB device (0x8087:0x0a2b, USB 2.0) config 1
[00023.278] 02880.02918> devhost[00:14.0/xhci/usb-bus/002/002/ifc-001] bind driver '/boot/driver/bt-transport-usb.so' failed: -2
[00023.278] 01104.01117> devcoord: rpc: bind-driver 'ifc-001' status -2
[00023.552] 02944.02985> intel-i2c-controller: intel_serialio_i2c_slave_transfer: -21
[00023.552] 02944.02985> i2c-hid: could not read HID descriptor: 0
[00023.552] 02944.02985> devhost[00:15.0/i2c-bus-9d60/0020] bind driver '/boot/driver/i2c-hid.so' failed: -2
[00023.552] 01104.01117> devcoord: rpc: bind-driver '0020' status -2
[00023.552] 03011.03062> intel-i2c-controller: intel_serialio_i2c_slave_transfer: -21
[00023.552] 03011.03062> i2c-hid: could not read HID descriptor: 0
[00023.552] 03011.03062> devhost[00:15.1/i2c-bus-9d61/004c] bind driver '/boot/driver/i2c-hid.so' failed: -2
[00023.552] 01104.01117> devcoord: rpc: bind-driver '004c' status -2
[00023.566] 03099.03668> sata2: dev info
[00023.566] 03099.03668> serial=AA000000000000009037
[00023.566] 03099.03668> firmware rev=0R08A1 0
[00023.566] 03099.03668> model id=ETMAT 8MSP1582 G
[00023.566] 03099.03668> major=0x3f0 ACS2 DMA 32 commands
[00023.566] 03099.03668> LBA48 250069680 sectors, sector size=512
[00023.567] 01182.01202> devmgr: /dev/class/block/000: GPT?
[00023.567] 01104.01117> devcoord: dc_bind_device() '/boot/driver/gpt.so'
[00023.567] 03099.03155> gpt: device_get_metadata failed (-25)
[00023.569] 01182.01202> devmgr: /dev/class/block/001: FVM?
[00023.569] 01104.01117> devcoord: dc_bind_device() '/boot/driver/fvm.so'
[00023.571] 04413.04427> paver:[Initialize] Successfully initialized EFI Device Partitioner
[00023.573] 04413.04427> paver:[WipePartitions] Immediate reboot strongly recommended
[00023.573] 03099.03155> block: Joining un-closed FIFO server
[00023.573] 03099.03155> block: Joining un-closed FIFO server
[00023.573] 03099.03155> block: Joining un-closed FIFO server
[00023.573] 01104.01117> devcoord: dc_bind_device() ''
[00023.574] 01182.01202> devmgr: /dev/class/block/000: GPT?
[00023.575] 01104.01117> devcoord: dc_bind_device() '/boot/driver/gpt.so'
[00023.575] 03099.03155> gpt: device_get_metadata failed (-25)
[00023.575] 03099.04753> gpt: bad header magic
[00023.577] 04702.04716> 34+0 records in
[00023.577] 04702.04716> 34+0 records out
[00023.577] 04702.04716> 17408 bytes copied
[00023.579] 04819.04833> 34+0 records in
[00023.579] 04819.04833> 34+0 records out
[00023.579] 04819.04833> 17408 bytes copied
[00023.580] 04923.04937> netifc: ? /dev/class/ethernet/000
[00023.580] 04923.04937> netifc: create 512 eth buffers
[00023.580] 04923.04937> macaddr: 54:b2:03:13:ae:b3
[00023.580] 04923.04937> ip6addr: fe80::56b2:34d:fe13:aeb3
[00023.580] 04923.04937> snmaddr: ff02::1:ff13:aeb3
[00023.580] 04923.04937> netsvc: using /dev/class/ethernet/000
[00023.580] 04923.04937> _ _ _
[00023.580] 04923.04937> | | | | |
[00023.580] 04923.04937> _______ __| | |__ ___ ___ | |_
[00023.580] 04923.04937> |_ / _ \/ _` | '_ \ / _ \ / _ \| __|
[00023.580] 04923.04937> / / __/ (_| | |_) | (_) | (_) | |_
[00023.580] 04923.04937> /___\___|\__,_|_.__/ \___/ \___/ \__|
[00023.580] 04923.04937>
[00023.580] 04923.04937>
[00023.580] 04923.04937> zedboot: version: 0.7.13
[00023.580] 04923.04937>
[00023.580] 04923.04937> netsvc: nodename='stick-shady-wool-crazy'
[00023.580] 04923.04937> netsvc: will not advertise
[00023.580] 04923.04937> netsvc: start
[00024.029] 02880.04246> UMS: block size is: 0x00000200
[00024.029] 02880.04246> UMS: total blocks is: 15630336
[00024.029] 02880.04246> UMS: total size is: 8002732032
[00024.029] 02880.04246> UMS: read-only: 0 removable: 1
[00024.030] 01182.01202> devmgr: /dev/class/block/006: MBR?
[00024.030] 01104.01117> devcoord: dc_bind_device() '/boot/driver/mbr.so'
[00024.033] 01182.01202> devmgr: /dev/class/block/008: MBR?
[00024.033] 01104.01117> devcoord: dc_bind_device() '/boot/driver/mbr.so'
[00845.362] 04923.04937> netsvc: tftp write of file <<netboot>>cmdline completed
[00845.362] 04923.04937> netsvc: metrics: {"inorderblks": 1,"oooblks": 0,"ack": 1,"nack": 0,"timeouts": 0,"sas": 0,"inorderbytes": 21}
[00845.363] 04923.04937> netsvc: Running FVM Paver
[00845.364] 04923.05107> paver:[InitializeGpt] Located GPT is invalid; Attempting to initialize
[00845.365] 01104.01117> devcoord: dc_bind_device() '/boot/driver/gpt.so'
[00845.365] 03099.03155> gpt: device_get_metadata failed (-25)
[00845.366] 04923.05107> paver:[Initialize] Successfully initialized EFI Device Partitioner
[00845.366] 04923.05107> paver:[PartitionPave] Paving partition.
[00845.366] 04923.05107> paver:[FindFirstFit] Looking for space
[00845.366] 04923.05107> paver:[FindFirstFit] Sorting
[00845.366] 04923.05107> paver:[FindFirstFit] Partition[0] From Block [0, 34) ... (next partition starts at block 250069646)
[00845.366] 04923.05107> paver:[FindFirstFit] There are 250069612 free blocks (16777216 requested)
[00845.366] 04923.05107> paver:[AddPartition] Found space in GPT - OK 250069612 @ 34
[00845.366] 04923.05107> paver:[AddPartition] Final space in GPT - OK 16777216 @ 34
[00845.367] 01104.01117> devcoord: dc_bind_device() ''
[00845.367] 04923.05107> paver:[AddPartition] Added partition, waiting for bind
[00845.368] 01182.01202> devmgr: /dev/class/block/000: GPT?
[00845.368] 01104.01117> devcoord: dc_bind_device() '/boot/driver/gpt.so'
[00845.368] 03099.03155> gpt: device_get_metadata failed (-25)
[00845.369] 04923.05107> paver:[AddPartition] Added partition, waiting for bind - OK
[00845.369] 04923.05107> paver:[PartitionPave] Streaming partitions...
[00845.369] 05087.05101> Found compressed file
[00845.369] 04923.05107> paver:[FvmStreamPartitions] Header Validated - OK
[00845.369] 04923.05107> paver:[FvmPartitionFormat] Initializing partition as FVM
[00845.371] 01104.01117> devcoord: dc_bind_device() '/boot/driver/fvm.so'
[00846.374] 04923.05107> paver:[FvmStreamPartitions] Partitions pre-validated successfully: Enough space exists to pave.
[00846.374] 04923.05107> paver:[AllocatePartitions] Allocating partition blobfs consisting of 1 slices
[00846.377] 04923.05107> paver:[AllocatePartitions] Allocating partition minfs consisting of 1 slices
[00846.378] 04923.05107> paver:[AllocatePartitions] Creating zxcrypt volume
[00846.380] 03099.03155> devhost_get_handles(0x3a27efd17900:block) open path='zxcrypt/block', r=-2
[00846.380] 01104.01117> devcoord: dc_bind_device() '/boot/driver/zxcrypt.so'
[00846.381] 03099.03155> devhost_get_handles(0x3a27efd17900:block) open path='zxcrypt', r=-2
[00846.384] 04923.05107> paver:[FvmStreamPartitions] Partition space pre-allocated successfully.
[00846.385] 04923.05107> paver:[FvmStreamPartitions] Streaming partition 0
[00846.385] 04923.05107> paver:[StreamFvmPartition] Writing extent 0...
[00846.385] 04923.05113> netsvc: paver write progress 0.0%
[00846.385] 04923.05107> paver:[StreamFvmPartition] 8192 bytes written, 8380416 zeroes left
[00846.412] 04923.05107> paver:[StreamFvmPartition] Writing extent 1...
[00846.412] 04923.05107> paver:[StreamFvmPartition] 24576 bytes written, 8364032 zeroes left
[00846.428] 04923.05107> paver:[StreamFvmPartition] Writing extent 2...
[00846.432] 04923.05107> paver:[StreamFvmPartition] 2097152 bytes written, 6291456 zeroes left
[00846.445] 04923.05107> paver:[StreamFvmPartition] Writing extent 3...
[00846.449] 04923.05107> paver:[StreamFvmPartition] 2097152 bytes written, 6291456 zeroes left
[00846.461] 04923.05107> paver:[StreamFvmPartition] Writing extent 4...
[00847.385] 04923.05113> netsvc: paver write progress 18.9%
[00848.385] 04923.05113> netsvc: paver write progress 28.2%
[00849.385] 04923.05113> netsvc: paver write progress 36.1%
[00850.385] 04923.05113> netsvc: paver write progress 45.5%
[00851.385] 04923.05113> netsvc: paver write progress 54.8%
[00852.385] 04923.05113> netsvc: paver write progress 64.3%
[00853.385] 04923.05113> netsvc: paver write progress 73.6%
[00854.385] 04923.05113> netsvc: paver write progress 82.8%
[00855.385] 04923.05113> netsvc: paver write progress 92.1%
2019/05/20 21:37:49 done
2019/05/20 21:37:49 attempting to send <<image>>bootloader.img...
2019/05/20 21:37:49 target is busy, retrying in one second
[00856.233] 04923.04937> netsvc: tftp write of file <<image>>sparse.fvm completed
[00856.233] 04923.04937> netsvc: metrics: {"inorderblks": 1078465,"oooblks": 0,"ack": 4213,"nack": 0,"timeouts": 0,"sas": 0,"inorderbytes": 1104347873}
[00856.235] 04923.05107> paver:[StreamFvmPartition] 1152311296 bytes written, 5316608 zeroes left
[00856.245] 04923.05107> paver:[FvmStreamPartitions] Done streaming partition 0
[00856.245] 04923.05107> paver:[FvmStreamPartitions] Done flushing partition 0
[00856.245] 04923.05107> paver:[FvmStreamPartitions] Streaming partition 1
[00856.245] 04923.05107> paver:[StreamFvmPartition] Writing extent 0...
[00856.245] 04923.05107> paver:[StreamFvmPartition] 8192 bytes written, 8380416 zeroes left
[00856.284] 04923.05107> paver:[StreamFvmPartition] Writing extent 1...
[00856.284] 04923.05107> paver:[StreamFvmPartition] 65536 bytes written, 8323072 zeroes left
[00856.323] 04923.05107> paver:[StreamFvmPartition] Writing extent 2...
[00856.323] 04923.05107> paver:[StreamFvmPartition] 65536 bytes written, 8323072 zeroes left
[00856.366] 04923.05107> paver:[StreamFvmPartition] Writing extent 3...
[00856.404] 04923.05107> paver:[StreamFvmPartition] Writing extent 4...
[00856.414] 04923.05107> paver:[StreamFvmPartition] 2097152 bytes written, 14680064 zeroes left
[00856.476] 04923.05107> paver:[StreamFvmPartition] Writing extent 5...
[00856.477] 04923.05107> paver:[StreamFvmPartition] 57344 bytes written, 8331264 zeroes left
[00856.517] 04923.05107> paver:[FvmStreamPartitions] Done streaming partition 1
[00856.517] 04923.05107> paver:[FvmStreamPartitions] Done flushing partition 1
[00856.518] 05087.05101> Reading FVM from compressed file: true
[00856.518] 05087.05101> Remaining bytes read into compression buffer: 0
[00856.518] 05087.05101> Remaining bytes written to decompression buffer: 0
[00856.518] 05087.05101> Time reading bytes from sparse FVM file: 19562380067 (7 s)
[00856.518] 05087.05101> Time reading bytes AND decompressing them: 20045572615 (7 s)
[00856.518] 04923.05107> paver:[PartitionPave] Completed successfully
2019/05/20 21:37:50 attempting to send <<image>>bootloader.img...
2019/05/20 21:37:50 done
2019/05/20 21:37:50 attempting to send <<image>>zircona.img...
[00857.234] 04923.04937> netsvc: Running BOOTLOADER Paver
[00857.237] 04923.06754> paver:[Initialize] Successfully initialized EFI Device Partitioner
[00857.237] 04923.06754> paver:[RealMain] SKIPPING BOOTLOADER install on x64 device, pass --force if desired.
[00857.245] 04923.04937> netsvc: tftp write of file <<image>>bootloader.img completed
[00857.245] 04923.04937> netsvc: metrics: {"inorderblks": 1093,"oooblks": 0,"ack": 5,"nack": 0,"timeouts": 0,"sas": 0,"inorderbytes": 1118208}
[00857.246] 04923.04937> netsvc: Running ZIRCON-A Paver
[00857.249] 04923.06883> paver:[Initialize] Successfully initialized EFI Device Partitioner
[00857.249] 04923.06883> paver:[PartitionPave] Paving partition.
[00857.249] 04923.06883> paver:[FindFirstFit] Looking for space
[00857.249] 04923.06883> paver:[FindFirstFit] Partition seen with start 34, end 16777249 (length 16777216)
[00857.249] 04923.06883> paver:[FindFirstFit] Sorting
[00857.249] 04923.06883> paver:[FindFirstFit] Partition[0] From Block [0, 34) ... (next partition starts at block 34)
[00857.249] 04923.06883> paver:[FindFirstFit] There are 0 free blocks (32768 requested)
[00857.249] 04923.06883> paver:[FindFirstFit] Partition[1] From Block [34, 16777250) ... (next partition starts at block 250069646)
[00857.249] 04923.06883> paver:[FindFirstFit] There are 233292396 free blocks (32768 requested)
[00857.249] 04923.06883> paver:[AddPartition] Found space in GPT - OK 233292396 @ 16777250
[00857.249] 04923.06883> paver:[AddPartition] Final space in GPT - OK 32768 @ 16777250
[00857.249] 03099.03155> block: Joining un-closed FIFO server
[00857.249] 04923.06883> paver:[AddPartition] Added partition, waiting for bind
[00857.249] 03099.03155> block: Joining un-closed FIFO server
[00857.250] 01104.01117> devcoord: dc_bind_device() ''
[00857.250] 01182.01202> devmgr: /dev/class/block/000: GPT?
[00857.250] 01104.01117> devcoord: dc_bind_device() '/boot/driver/gpt.so'
[00857.250] 03099.03155> gpt: device_get_metadata failed (-25)
[00857.251] 01182.01202> devmgr: /dev/class/block/013: FVM?
[00857.251] 01104.01117> devcoord: dc_bind_device() '/boot/driver/fvm.so'
[00857.251] 04923.06883> paver:[AddPartition] Added partition, waiting for bind - OK
2019/05/20 21:37:50 done
2019/05/20 21:37:50 attempting to send <<image>>zirconr.img...
2019/05/20 21:37:50 target is busy, retrying in one second
[00857.390] 04923.04937> netsvc: tftp write of file <<image>>zircona.img completed
[00857.390] 04923.04937> netsvc: metrics: {"inorderblks": 14350,"oooblks": 0,"ack": 57,"nack": 0,"timeouts": 0,"sas": 0,"inorderbytes": 14693784}
[00857.418] 04923.06883> paver:[PartitionPave] Completed successfully
2019/05/20 21:37:51 attempting to send <<image>>zirconr.img...
[00858.391] 04923.04937> netsvc: Running ZIRCON-R Paver
[00858.393] 04923.07145> paver:[Initialize] Successfully initialized EFI Device Partitioner
[00858.393] 04923.07145> paver:[PartitionPave] Paving partition.
[00858.393] 04923.07145> paver:[FindFirstFit] Looking for space
[00858.393] 04923.07145> paver:[FindFirstFit] Partition seen with start 34, end 16777249 (length 16777216)
[00858.393] 04923.07145> paver:[FindFirstFit] Partition seen with start 16777250, end 16810017 (length 32768)
[00858.393] 04923.07145> paver:[FindFirstFit] Sorting
[00858.393] 04923.07145> paver:[FindFirstFit] Partition[0] From Block [0, 34) ... (next partition starts at block 34)
[00858.393] 04923.07145> paver:[FindFirstFit] There are 0 free blocks (49152 requested)
[00858.393] 04923.07145> paver:[FindFirstFit] Partition[1] From Block [34, 16777250) ... (next partition starts at block 16777250)
[00858.393] 04923.07145> paver:[FindFirstFit] There are 0 free blocks (49152 requested)
[00858.393] 04923.07145> paver:[FindFirstFit] Partition[2] From Block [16777250, 16810018) ... (next partition starts at block 250069646)
[00858.393] 04923.07145> paver:[FindFirstFit] There are 233259628 free blocks (49152 requested)
[00858.393] 04923.07145> paver:[AddPartition] Found space in GPT - OK 233259628 @ 16810018
[00858.393] 04923.07145> paver:[AddPartition] Final space in GPT - OK 49152 @ 16810018
[00858.394] 04923.07145> paver:[AddPartition] Added partition, waiting for bind
[00858.394] 03099.03155> block: Joining un-closed FIFO server
[00858.394] 01104.01117> devcoord: dc_bind_device() ''
[00858.395] 01182.01202> devmgr: /dev/class/block/000: GPT?
[00858.395] 01104.01117> devcoord: dc_bind_device() '/boot/driver/gpt.so'
[00858.395] 03099.03155> gpt: device_get_metadata failed (-25)
[00858.396] 01182.01202> devmgr: /dev/class/block/017: FVM?
[00858.396] 01104.01117> devcoord: dc_bind_device() '/boot/driver/fvm.so'
[00858.396] 04923.07145> paver:[AddPartition] Added partition, waiting for bind - OK
2019/05/20 21:37:51 done
2019/05/20 21:37:51 attempting to send <<image>>authorized_keys...
2019/05/20 21:37:51 target is busy, retrying in one second
[00858.523] 04923.04937> netsvc: tftp write of file <<image>>zirconr.img completed
[00858.523] 04923.04937> netsvc: metrics: {"inorderblks": 13296,"oooblks": 0,"ack": 52,"nack": 0,"timeouts": 0,"sas": 0,"inorderbytes": 13614176}
[00858.561] 04923.07145> paver:[PartitionPave] Completed successfully
2019/05/20 21:37:52 attempting to send <<image>>authorized_keys...
2019/05/20 21:37:52 done
2019/05/20 21:37:52 attempting to send <<netboot>>kernel.bin...
2019/05/20 21:37:52 target is busy, retrying in one second
[00859.523] 04923.04937> netsvc: Installing SSH authorized_keys
[00859.524] 04923.04937> netsvc: tftp write of file <<image>>authorized_keys completed
[00859.524] 04923.04937> netsvc: metrics: {"inorderblks": 1,"oooblks": 0,"ack": 1,"nack": 0,"timeouts": 0,"sas": 0,"inorderbytes": 806}
[00859.526] 04923.07423> paver:[Initialize] Successfully initialized EFI Device Partitioner
[00859.527] 01104.01117> devcoord: dc_bind_device() '/boot/driver/zxcrypt.so'
[00859.527] 03099.03155> devhost_get_handles(0x3a27efd17900:block) open path='zxcrypt', r=-2
[00859.554] 04923.07423> paver:[DataFilePave] Wrote ssh/authorized_keys
2019/05/20 21:37:53 attempting to send <<netboot>>kernel.bin...
2019/05/20 21:37:53 done
DEBUG: stopping or rebooting the node "stick-shady-wool-crazy"
ERROR: cannot find node "stick-shady-wool-crazy": read udp6 [::]:58751: i/o timeout