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

2019/05/22 09:37:42 attempting to send <<netboot>>cmdline... 2019/05/22 09:37:42 done 2019/05/22 09:37:42 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 [19.783] 00000.00000> timer features: constant_tsc 1 invariant_tsc 1 tsc_deadline 1 [19.783] 00000.00000> Using TSC as wallclock [19.783] 00000.00000> initializing kernel [19.783] 00000.00000> initializing mp [19.783] 00000.00000> initializing timers [19.783] 00000.00000> INIT: cpu 0, calling hook 0xffffffff0013c578 (debuglog) at level 0x7ffff, flags 0x1 [19.783] 00000.00000> INIT: cpu 0, calling hook 0xffffffff00195518 (thread_set_priority_experiment) at level 0x7ffff, flags 0x1 [19.783] 00000.00000> thread set priority experiment is : ENABLED [19.783] 00000.00000> INIT: cpu 0, calling hook 0xffffffff001aa67c (global_prng_thread_safe) at level 0x7ffff, flags 0x1 [19.783] 00000.00000> creating bootstrap completion thread [20.125] 00000.00000> top of bootstrap2() [20.125] 00000.00000> INIT: cpu 0, calling hook 0xffffffff0013151c (dpc) at level 0x80000, flags 0x1 [20.138] 00000.00000> INIT: cpu 0, calling hook 0xffffffff00152978 (libobject) at level 0x80000, flags 0x1 [20.138] 00000.00000> OOM: started thread [20.152] 00000.00000> Processor Model Info: type 0 family 0x6 model 0xe stepping 0x9 [20.152] 00000.00000> display_family 0x6 display_model 0x8e [20.152] 00000.00000> Vendor: Intel [20.152] 00000.00000> Microarch: Kaby Lake [20.152] 00000.00000> F/M/S: 6/8e/9 [20.152] 00000.00000> Brand: Intel(R) Core(TM) i5-7300U CPU @ 2.60GHz [20.152] 00000.00000> Features: fpu sse sse2 sse3 ssse3 sse4.1 sse4.2 mmx avx avx2 fxsr pcid xsave mon aesni clflush [20.152] 00000.00000> clflushopt fsgsbase tsc_adj smep smap erms rdrand rdseed syscall nx huge rdtscp [20.152] 00000.00000> invar_tsc tsc_deadline x2apic vmx pt hwp [20.152] 00000.00000> initializing platform [20.152] 00000.00000> INIT: cpu 0, calling hook 0xffffffff001101f4 (x86_perfmon) at level 0x90000, flags 0x1 [20.152] 00000.00000> PMU: version 4 [20.152] 00000.00000> UART: started IRQ driven RX [20.152] 00000.00000> UART: started IRQ driven TX [20.152] 00000.00000> cpu topology: [20.152] 00000.00000> 0: apic id 0x0 package 0 node 0 core 0 smt 0 BSP [20.152] 00000.00000> 1: apic id 0x2 package 0 node 0 core 1 smt 0 [20.152] 00000.00000> 2: apic id 0x1 package 0 node 0 core 0 smt 1 [20.152] 00000.00000> 3: apic id 0x3 package 0 node 0 core 1 smt 1 [20.152] 00000.00000> Found 4 cpus [20.152] 00000.00000> booting apic ids: 0x2 0x1 0x3 [20.167] 00000.00000> entering scheduler on cpu 2 [20.169] 00000.00000> entering scheduler on cpu 3 [20.169] 00000.00000> entering scheduler on cpu 1 [20.171] 00000.00000> smbios: manufacturer="Intel Corporation" product="NUC7i5DNHE" [20.171] 00000.00000> initializing target [20.171] 00000.00000> INIT: cpu 1, calling hook 0xffffffff001053a0 (x86_pcie_init) at level 0xa0000, flags 0x1 [20.171] 00000.00000> moving to last init level [20.171] 00000.00000> INIT: cpu 1, calling hook 0xffffffff00144140 (ktrace) at level 0xc0000, flags 0x1 [20.175] 00000.00000> ktrace: buffer at 0xffffff96ea606000 (33554432 bytes) [20.175] 00000.00000> INIT: cpu 1, calling hook 0xffffffff00147ab4 (userboot) at level 0xc0000, flags 0x1 [20.175] 00000.00000> userboot: ramdisk 0x10ad000 @ 0xffffff80012f2000 [20.175] 00000.00000> userboot: userboot rodata 0 @ [0x2ffc441ac000,0x2ffc441af000) [20.175] 00000.00000> userboot: userboot code 0x3000 @ [0x2ffc441af000,0x2ffc441ba000) [20.175] 00000.00000> userboot: vdso/full rodata 0 @ [0x2ffc441ba000,0x2ffc441c1000) [20.175] 00000.00000> userboot: vdso/full code 0x7000 @ [0x2ffc441c1000,0x2ffc441c2000) [20.175] 00000.00000> userboot: entry point @ 0x2ffc441afc10 [20.175] 00000.00000> INIT: cpu 1, calling hook 0xffffffff001aa030 (kernel_shell) at level 0xc0000, flags 0x1 [20.175] 01036.01043> userboot: option "netsvc.disable=true" [20.175] 01036.01043> userboot: option "zircon.system.disable-automount=true" [20.175] 01036.01043> userboot: option "zircon.autorun.boot=/boot/infra/setup" [20.175] 01036.01043> userboot: option "kernel.serial=legacy" [20.175] 01036.01043> userboot: option "http://192.168.42.1/multiboot/54%3Ab2%3A03%3A13%3Ab5%3Ab1=" [20.175] 01036.01043> userboot: option "multiboot.boot_loader_name=iPXE+1.0.0++(d2063)" [20.215] 01036.01043> userboot: searching bootfs for 'bin/bootsvc' [20.215] 01036.01043> userboot: 'bin/bootsvc' has PT_INTERP "lib/ld.so.1" [20.215] 01036.01043> userboot: searching bootfs for 'lib/ld.so.1' [20.215] 01036.01043> userboot: userboot: loaded lib/ld.so.1 at 0x4da1a1892000, entry point 0x4da1a19180d3 [20.215] 01036.01043> userboot: userboot: loaded vDSO at 0x590ad87ee000, entry point 0x0 [20.215] 01036.01043> userboot: process bin/bootsvc started. [20.215] 01036.01043> userboot: waiting for loader-service requests... [20.215] 01036.01043> userboot: searching bootfs for 'lib/libasync-default.so' [20.215] 01036.01043> userboot: searching bootfs for 'lib/libfdio.so' [20.215] 01036.01043> userboot: searching bootfs for 'lib/liblaunchpad.so' [20.215] 01036.01043> userboot: searching bootfs for 'lib/libtrace-engine.so' [20.215] 01050.01053> dso: id=18de7d58f51e8ba5c4f6afdd0cc8440f482c2b45 base=0x00003e71d2ec7000 name=<application> [20.215] 01050.01053> dso: id=c189f51f19d10785d93b5235ad1b46dca4451b00 base=0x0000007d10382000 name=libasync-default.so [20.215] 01050.01053> dso: id=40ab5fa3b61f12fef4a44477a687f608661cd450 base=0x0000590ad87ee000 name=<vDSO> [20.215] 01050.01053> dso: id=67a12284bce140fc32aaaeac223e0e8f85cb5085 base=0x00004da1a1892000 name=libc.so [20.215] 01050.01053> dso: id=27787977e95f3b9563c9e0bd4d34ec92b7e9ad88 base=0x000045d41fae9000 name=libfdio.so [20.215] 01050.01053> dso: id=6fc2232dc8c1bc5c6adb8ad50ca794b5a260ee4f base=0x0000340ffcbbd000 name=liblaunchpad.so [20.215] 01050.01053> dso: id=c9042b83fe01206008fcefb16395238417248169 base=0x00005fe0687fa000 name=libtrace-engine.so [20.215] 01050.01053> bootsvc: Starting... [20.215] 01036.01043> userboot: loader-service channel peer closed [20.215] 01036.01043> userboot: finished! [20.215] 01050.01053> bootsvc: Creating bootfs service... [20.216] 01050.01053> bootsvc: Processing bootdata... [20.216] 01050.01053> bootsvc: Loading boot cmdline overrides... [20.216] 01050.01053> bootsvc: Loading kernel VMOs... [20.216] 01050.01053> bootsvc: Creating loader service... [20.216] 01050.01053> bootsvc: Launching next process... [20.216] 01050.01096> bootsvc: launched bin/devmgr [20.217] 01105.01118> devmgr: main() [20.217] 01105.01118> cmdline: netsvc.disable=true [20.217] 01105.01118> cmdline: zircon.system.disable-automount=true [20.217] 01105.01118> cmdline: zircon.autorun.boot=/boot/infra/setup [20.217] 01105.01118> cmdline: kernel.serial=legacy [20.217] 01105.01118> cmdline: http://192.168.42.1/multiboot/54%3Ab2%3A03%3A13%3Ab5%3Ab1= [20.217] 01105.01118> cmdline: multiboot.boot_loader_name=iPXE+1.0.0++(d2063) [20.217] 01105.01118> devmgr: coordinator_init() [20.217] 01105.01118> devmgr: init [20.217] 01105.01118> devmgr: svc init [20.217] 01105.01118> devmgr: launch /boot/bin/svchost (svchost) OK [20.217] 01105.01118> devmgr: vfs init [20.217] 01105.01118> devmgr: launch /boot/bin/fshost (fshost) OK [20.217] 01105.01222> devmgr: shell startup [20.219] 01183.01203> fshost: started. [20.219] 01105.01213> devmgr: launch /boot/bin/pwrbtn-monitor (pwrbtn-monitor) OK [20.220] 01105.01236> devmgr: launch /boot/bin/virtual-console (virtual-console) OK [20.220] 01105.01236> zircon.autorun.boot: starting '/boot/infra/setup'... [20.221] 01105.01236> devmgr: launch /boot/infra/setup (autorun:boot) OK [20.223] 01105.01118> devcoord: launch devhost 'devhost:sys': pid=2050 [20.223] 01105.01118> devcoord: launch devhost 'devhost:test': pid=2083 [20.224] 01105.01118> devcoord: launch devhost 'devhost:root': pid=2115 [20.224] 01105.01118> devcoord: launch devhost 'devhost:misc': pid=2166 [20.225] 02050.02074> devhost: trace provider registry begun [20.226] 02083.02106> devhost: trace provider registry begun [20.226] 02115.02152> devhost: trace provider registry begun [20.227] 02166.02196> devhost: trace provider registry begun [20.229] 01105.01222> devmgr: launch /boot/bin/sh (sh:console) OK [20.284] 02050.02074> acpi-bus: not using IOMMU [20.288] 02050.02074> acpi-pwrbtn: initialized [20.310] 02050.02074> acpi: published device pci(0x6f3c79180200), parent=proxy(0x6f3c7917c540), handle=0x6f3c791b8c30 [20.312] 02050.02074> acpi: published device rtc(0x6f3c7917b080), parent=acpi(0x6f3c7917c780), handle=0x6f3c791d15b0 [20.313] 02050.02074> acpi-ec: initialized [20.314] 02050.02074> acpi: failed to create NHLT VMO (res -10) [20.314] 02050.02074> acpi: failed to publish NHLT metadata [20.316] 02050.02074> [sysmem_init 28] async_get_default_dispatcher(): 0x6f3c7916f0a0 [20.316] 02050.02074> [sysmem_bind 40] sysmem_bind() [20.316] 02050.02074> acpi-bus: sysmem_register_protocol() intentionally ignored for now. [20.316] 02050.02074> PMU: 7 arch events [20.316] 02050.02074> PMU: arch event id range: 1-7 [20.316] 02050.02074> PMU: 102 model events [20.316] 02050.02074> PMU: model event id range: 1-241 [20.316] 02050.02074> Intel Processor Trace configuration for this chipset: [20.316] 02050.02074> mtc_freq_mask: 0x249 [20.316] 02050.02074> cyc_thresh_mask: 0x3fff [20.316] 02050.02074> psb_freq_mask: 0x3f [20.316] 02050.02074> num addr ranges: 2 [20.317] 01105.01118> devcoord: launch devhost 'devhost:pci#1:8086:5916': pid=2841 [20.317] 01105.01118> devcoord: launch devhost 'devhost:pci#3:8086:9d2f': pid=2883 [20.318] 01105.01118> devcoord: launch devhost 'devhost:pci#5:8086:9d60': pid=2949 [20.318] 02841.02864> devhost: trace provider registry begun [20.318] 01105.01118> devcoord: launch devhost 'devhost:pci#6:8086:9d61': pid=3024 [20.319] 02883.02921> devhost: trace provider registry begun [20.319] 02949.03001> devhost: trace provider registry begun [20.319] 01105.01118> devcoord: launch devhost 'devhost:pci#9:8086:9d03': pid=3124 [20.320] 01105.01118> devcoord: launch devhost 'devhost:pci#14:8086:9d71': pid=3239 [20.320] 03024.03087> devhost: trace provider registry begun [20.320] 01105.01118> devcoord: launch devhost 'devhost:pci#16:8086:156f': pid=3316 [20.321] 03124.03185> devhost: trace provider registry begun [20.322] 03124.03185> ahci: using MSI interrupt [20.322] 03024.03087> initialized intel serialio i2c driver, reg=0x2bf4922e6000 regsize=4096 [20.322] 02949.03001> initialized intel serialio i2c driver, reg=0x44e3d264b000 regsize=4096 [20.324] 03239.03284> devhost: trace provider registry begun [20.326] 03316.03358> devhost: trace provider registry begun [20.337] 03239.03284> [IHDA DSP 00:1f.3] Failed to fetch NHLT (res -25) [20.337] 03239.03284> devhost[00:1f.3/intel-hda-000/intel-sst-dsp-000] bind driver '/boot/driver/dsp.so' failed: -25 [20.337] 01105.01118> devcoord: rpc: bind-driver 'intel-sst-dsp-000' status -25 [20.337] 02883.03746> * found USB device (0x18d1:0xa002, USB 2.0) config 1 [20.338] 02883.03746> * found USB device (0x18d1:0xa003, USB 3.0) config 1 [20.339] 01243.01557> vc: new input device /dev/class/input/000 [20.428] 01243.01557> vc: new display device /dev/class/display-controller/000/virtcon [20.568] 02841.04143> i915: MST not supported [21.068] 02841.04143> i915: Found DP monitor [21.068] 02841.04143> i915: Display 1 connected [21.627] 01243.01557> vc: Successfully attached to display 1 [21.801] 02883.03746> * found USB device (0x0781:0x5571, USB 2.10) config 1 [21.802] 02883.02921> UMS: parent: 'ifc-000' [21.802] 02883.02921> UMS:Max lun is: 0 [22.052] 02883.03746> * found USB device (0x8087:0x0a2b, USB 2.0) config 1 [22.053] 02883.02921> devhost[00:14.0/xhci/usb-bus/002/002/ifc-001] bind driver '/boot/driver/bt-transport-usb.so' failed: -2 [22.053] 01105.01118> devcoord: rpc: bind-driver 'ifc-001' status -2 [22.327] 03024.03087> intel-i2c-controller: intel_serialio_i2c_slave_transfer: -21 [22.327] 03024.03087> i2c-hid: could not read HID descriptor: 0 [22.327] 03024.03087> devhost[00:15.1/i2c-bus-9d61/004c] bind driver '/boot/driver/i2c-hid.so' failed: -2 [22.327] 01105.01118> devcoord: rpc: bind-driver '004c' status -2 [22.329] 02949.03001> intel-i2c-controller: intel_serialio_i2c_slave_transfer: -21 [22.329] 02949.03001> i2c-hid: could not read HID descriptor: 0 [22.329] 02949.03001> devhost[00:15.0/i2c-bus-9d60/0020] bind driver '/boot/driver/i2c-hid.so' failed: -2 [22.329] 01105.01118> devcoord: rpc: bind-driver '0020' status -2 [22.341] 03124.03637> sata2: dev info [22.341] 03124.03637> serial=AA000000000000000164 [22.341] 03124.03637> firmware rev=0R08A1 0 [22.341] 03124.03637> model id=ETMAT 8MSP1582 G [22.341] 03124.03637> major=0x3f0 ACS2 DMA 32 commands [22.341] 03124.03637> LBA48 250069680 sectors, sector size=512 [22.342] 01183.01203> devmgr: /dev/class/block/000: GPT? [22.342] 01105.01118> devcoord: dc_bind_device() '/boot/driver/gpt.so' [22.342] 03124.03185> gpt: device_get_metadata failed (-25) [22.344] 01183.01203> devmgr: /dev/class/block/001: FVM? [22.344] 01105.01118> devcoord: dc_bind_device() '/boot/driver/fvm.so' [22.346] 04414.04428> paver:[Initialize] Successfully initialized EFI Device Partitioner [22.348] 04414.04428> paver:[WipePartitions] Immediate reboot strongly recommended [22.348] 03124.03185> block: Joining un-closed FIFO server [22.348] 03124.03185> block: Joining un-closed FIFO server [22.348] 03124.03185> block: Joining un-closed FIFO server [22.348] 01105.01118> devcoord: dc_bind_device() '' [22.349] 01183.01203> devmgr: /dev/class/block/000: GPT? [22.349] 01105.01118> devcoord: dc_bind_device() '/boot/driver/gpt.so' [22.349] 03124.03185> gpt: device_get_metadata failed (-25) [22.350] 03124.04754> gpt: bad header magic [22.351] 04703.04717> 34+0 records in [22.351] 04703.04717> 34+0 records out [22.351] 04703.04717> 17408 bytes copied [22.354] 04820.04834> 34+0 records in [22.354] 04820.04834> 34+0 records out [22.354] 04820.04834> 17408 bytes copied [22.355] 04924.04938> netifc: ? /dev/class/ethernet/000 [22.355] 04924.04938> netifc: create 512 eth buffers [22.355] 04924.04938> macaddr: 54:b2:03:13:b5:b1 [22.355] 04924.04938> ip6addr: fe80::56b2:34d:fe13:b5b1 [22.355] 04924.04938> snmaddr: ff02::1:ff13:b5b1 [22.355] 04924.04938> netsvc: using /dev/class/ethernet/000 [22.355] 04924.04938> _ _ _ [22.355] 04924.04938> | | | | | [22.355] 04924.04938> _______ __| | |__ ___ ___ | |_ [22.355] 04924.04938> |_ / _ \/ _` | '_ \ / _ \ / _ \| __| [22.355] 04924.04938> / / __/ (_| | |_) | (_) | (_) | |_ [22.355] 04924.04938> /___\___|\__,_|_.__/ \___/ \___/ \__| [22.355] 04924.04938> zedboot: version: 0.7.13 [22.355] 04924.04938> netsvc: nodename='banjo-flint-copy-crazy' [22.355] 04924.04938> netsvc: will not advertise [22.355] 04924.04938> netsvc: start [22.804] 02883.04247> UMS: block size is: 0x00000200 [22.804] 02883.04247> UMS: total blocks is: 15630336 [22.804] 02883.04247> UMS: total size is: 8002732032 [22.804] 02883.04247> UMS: read-only: 0 removable: 1 [22.805] 01183.01203> devmgr: /dev/class/block/006: MBR? [22.805] 01105.01118> devcoord: dc_bind_device() '/boot/driver/mbr.so' [22.808] 01183.01203> devmgr: /dev/class/block/008: MBR? [22.808] 01105.01118> devcoord: dc_bind_device() '/boot/driver/mbr.so' [2279.423] 04924.04938> netsvc: tftp write of file <<netboot>>cmdline completed [2279.423] 04924.04938> netsvc: metrics: {"inorderblks": 1,"oooblks": 0,"ack": 1,"nack": 0,"timeouts": 0,"sas": 0,"inorderbytes": 21} [2279.423] 04924.04938> netsvc: Running FVM Paver [2279.425] 04924.05107> paver:[InitializeGpt] Located GPT is invalid; Attempting to initialize [2279.426] 01105.01118> devcoord: dc_bind_device() '/boot/driver/gpt.so' [2279.426] 03124.03185> gpt: device_get_metadata failed (-25) [2279.428] 04924.05107> paver:[Initialize] Successfully initialized EFI Device Partitioner [2279.428] 04924.05107> paver:[PartitionPave] Paving partition. [2279.428] 04924.05107> paver:[FindFirstFit] Looking for space [2279.428] 04924.05107> paver:[FindFirstFit] Sorting [2279.428] 04924.05107> paver:[FindFirstFit] Partition[0] From Block [0, 34) ... (next partition starts at block 250069646) [2279.428] 04924.05107> paver:[FindFirstFit] There are 250069612 free blocks (16777216 requested) [2279.428] 04924.05107> paver:[AddPartition] Found space in GPT - OK 250069612 @ 34 [2279.428] 04924.05107> paver:[AddPartition] Final space in GPT - OK 16777216 @ 34 [2279.428] 04924.05107> paver:[AddPartition] Added partition, waiting for bind [2279.428] 01105.01118> devcoord: dc_bind_device() '' [2279.429] 01183.01203> devmgr: /dev/class/block/000: GPT? [2279.429] 01105.01118> devcoord: dc_bind_device() '/boot/driver/gpt.so' [2279.429] 03124.03185> gpt: device_get_metadata failed (-25) [2279.430] 04924.05107> paver:[AddPartition] Added partition, waiting for bind - OK [2279.430] 04924.05107> paver:[PartitionPave] Streaming partitions... [2279.430] 05087.05101> Found compressed file [2279.430] 04924.05107> paver:[FvmStreamPartitions] Header Validated - OK [2279.431] 04924.05107> paver:[FvmPartitionFormat] Initializing partition as FVM [2279.433] 01105.01118> devcoord: dc_bind_device() '/boot/driver/fvm.so' [2280.435] 04924.05107> paver:[FvmStreamPartitions] Partitions pre-validated successfully: Enough space exists to pave. [2280.435] 04924.05107> paver:[AllocatePartitions] Allocating partition blobfs consisting of 1 slices [2280.439] 04924.05107> paver:[AllocatePartitions] Allocating partition minfs consisting of 1 slices [2280.441] 04924.05107> paver:[AllocatePartitions] Creating zxcrypt volume [2280.442] 03124.03185> devhost_get_handles(0x4b00c3591900:block) open path='zxcrypt/block', r=-2 [2280.442] 01105.01118> devcoord: dc_bind_device() '/boot/driver/zxcrypt.so' [2280.443] 03124.03185> devhost_get_handles(0x4b00c3591900:block) open path='zxcrypt', r=-2 [2280.447] 04924.05107> paver:[FvmStreamPartitions] Partition space pre-allocated successfully. [2280.447] 04924.05107> paver:[FvmStreamPartitions] Streaming partition 0 [2280.447] 04924.05107> paver:[StreamFvmPartition] Writing extent 0... [2280.447] 04924.05113> netsvc: paver write progress 0.0% [2280.455] 04924.05107> paver:[StreamFvmPartition] 8192 bytes written, 8380416 zeroes left [2280.473] 04924.05107> paver:[StreamFvmPartition] Writing extent 1... [2280.473] 04924.05107> paver:[StreamFvmPartition] 16384 bytes written, 8372224 zeroes left [2280.489] 04924.05107> paver:[StreamFvmPartition] Writing extent 2... [2280.494] 04924.05107> paver:[StreamFvmPartition] 2097152 bytes written, 6291456 zeroes left [2280.506] 04924.05107> paver:[StreamFvmPartition] Writing extent 3... [2280.511] 04924.05107> paver:[StreamFvmPartition] 2097152 bytes written, 6291456 zeroes left [2280.523] 04924.05107> paver:[StreamFvmPartition] Writing extent 4... [2281.447] 04924.05113> netsvc: paver write progress 30.5% [2282.447] 04924.05113> netsvc: paver write progress 45.6% [2283.447] 04924.05113> netsvc: paver write progress 60.6% [2284.447] 04924.05113> netsvc: paver write progress 75.6% [2285.447] 04924.05113> netsvc: paver write progress 90.7% 2019/05/22 09:37:49 done 2019/05/22 09:37:49 attempting to send <<image>>bootloader.img... 2019/05/22 09:37:49 target is busy, retrying in one second [2286.066] 04924.04938> netsvc: tftp write of file <<image>>sparse.fvm completed [2286.066] 04924.04938> netsvc: metrics: {"inorderblks": 659118,"oooblks": 0,"ack": 2575,"nack": 0,"timeouts": 0,"sas": 0,"inorderbytes": 674936610} [2286.066] 04924.05107> paver:[StreamFvmPartition] 722796544 bytes written, 7012352 zeroes left [2286.080] 04924.05107> paver:[FvmStreamPartitions] Done streaming partition 0 [2286.080] 04924.05107> paver:[FvmStreamPartitions] Done flushing partition 0 [2286.080] 04924.05107> paver:[FvmStreamPartitions] Streaming partition 1 [2286.080] 04924.05107> paver:[StreamFvmPartition] Writing extent 0... [2286.080] 04924.05107> paver:[StreamFvmPartition] 8192 bytes written, 8380416 zeroes left [2286.122] 04924.05107> paver:[StreamFvmPartition] Writing extent 1... [2286.123] 04924.05107> paver:[StreamFvmPartition] 65536 bytes written, 8323072 zeroes left [2286.161] 04924.05107> paver:[StreamFvmPartition] Writing extent 2... [2286.161] 04924.05107> paver:[StreamFvmPartition] 65536 bytes written, 8323072 zeroes left [2286.197] 04924.05107> paver:[StreamFvmPartition] Writing extent 3... [2286.235] 04924.05107> paver:[StreamFvmPartition] Writing extent 4... [2286.245] 04924.05107> paver:[StreamFvmPartition] 2097152 bytes written, 14680064 zeroes left [2286.317] 04924.05107> paver:[StreamFvmPartition] Writing extent 5... [2286.318] 04924.05107> paver:[StreamFvmPartition] 57344 bytes written, 8331264 zeroes left [2286.353] 04924.05107> paver:[FvmStreamPartitions] Done streaming partition 1 [2286.353] 04924.05107> paver:[FvmStreamPartitions] Done flushing partition 1 [2286.354] 05087.05101> Reading FVM from compressed file: true [2286.354] 05087.05101> Remaining bytes read into compression buffer: 0 [2286.354] 05087.05101> Remaining bytes written to decompression buffer: 0 [2286.354] 05087.05101> Time reading bytes from sparse FVM file: 10673813012 (3 s) [2286.354] 05087.05101> Time reading bytes AND decompressing them: 11002190188 (4 s) [2286.354] 04924.05107> paver:[PartitionPave] Completed successfully 2019/05/22 09:37:50 attempting to send <<image>>bootloader.img... 2019/05/22 09:37:50 done 2019/05/22 09:37:50 attempting to send <<image>>zircona.img... [2287.067] 04924.04938> netsvc: Running BOOTLOADER Paver [2287.070] 04924.06346> paver:[Initialize] Successfully initialized EFI Device Partitioner [2287.070] 04924.06346> paver:[RealMain] SKIPPING BOOTLOADER install on x64 device, pass --force if desired. [2287.078] 04924.04938> netsvc: tftp write of file <<image>>bootloader.img completed [2287.078] 04924.04938> netsvc: metrics: {"inorderblks": 1093,"oooblks": 0,"ack": 5,"nack": 0,"timeouts": 0,"sas": 0,"inorderbytes": 1118208} [2287.079] 04924.04938> netsvc: Running ZIRCON-A Paver [2287.082] 04924.06475> paver:[Initialize] Successfully initialized EFI Device Partitioner [2287.082] 04924.06475> paver:[PartitionPave] Paving partition. [2287.082] 04924.06475> paver:[FindFirstFit] Looking for space [2287.082] 04924.06475> paver:[FindFirstFit] Partition seen with start 34, end 16777249 (length 16777216) [2287.082] 04924.06475> paver:[FindFirstFit] Sorting [2287.082] 04924.06475> paver:[FindFirstFit] Partition[0] From Block [0, 34) ... (next partition starts at block 34) [2287.082] 04924.06475> paver:[FindFirstFit] There are 0 free blocks (32768 requested) [2287.082] 04924.06475> paver:[FindFirstFit] Partition[1] From Block [34, 16777250) ... (next partition starts at block 250069646) [2287.082] 04924.06475> paver:[FindFirstFit] There are 233292396 free blocks (32768 requested) [2287.082] 04924.06475> paver:[AddPartition] Found space in GPT - OK 233292396 @ 16777250 [2287.082] 04924.06475> paver:[AddPartition] Final space in GPT - OK 32768 @ 16777250 [2287.082] 04924.06475> paver:[AddPartition] Added partition, waiting for bind [2287.082] 03124.03185> block: Joining un-closed FIFO server [2287.082] 03124.03185> block: Joining un-closed FIFO server [2287.083] 01105.01118> devcoord: dc_bind_device() '' [2287.084] 01183.01203> devmgr: /dev/class/block/000: GPT? [2287.084] 01105.01118> devcoord: dc_bind_device() '/boot/driver/gpt.so' [2287.084] 03124.03185> gpt: device_get_metadata failed (-25) [2287.085] 01183.01203> devmgr: /dev/class/block/013: FVM? [2287.085] 01105.01118> devcoord: dc_bind_device() '/boot/driver/fvm.so' [2287.085] 04924.06475> paver:[AddPartition] Added partition, waiting for bind - OK 2019/05/22 09:37:50 done 2019/05/22 09:37:50 attempting to send <<image>>zirconr.img... 2019/05/22 09:37:50 target is busy, retrying in one second [2287.203] 04924.04938> netsvc: tftp write of file <<image>>zircona.img completed [2287.203] 04924.04938> netsvc: metrics: {"inorderblks": 12203,"oooblks": 0,"ack": 48,"nack": 0,"timeouts": 0,"sas": 0,"inorderbytes": 12495176} [2287.227] 04924.06475> paver:[PartitionPave] Completed successfully 2019/05/22 09:37:51 attempting to send <<image>>zirconr.img... [2288.204] 04924.04938> netsvc: Running ZIRCON-R Paver [2288.207] 04924.06735> paver:[Initialize] Successfully initialized EFI Device Partitioner [2288.207] 04924.06735> paver:[PartitionPave] Paving partition. [2288.207] 04924.06735> paver:[FindFirstFit] Looking for space [2288.207] 04924.06735> paver:[FindFirstFit] Partition seen with start 34, end 16777249 (length 16777216) [2288.207] 04924.06735> paver:[FindFirstFit] Partition seen with start 16777250, end 16810017 (length 32768) [2288.207] 04924.06735> paver:[FindFirstFit] Sorting [2288.207] 04924.06735> paver:[FindFirstFit] Partition[0] From Block [0, 34) ... (next partition starts at block 34) [2288.207] 04924.06735> paver:[FindFirstFit] There are 0 free blocks (49152 requested) [2288.207] 04924.06735> paver:[FindFirstFit] Partition[1] From Block [34, 16777250) ... (next partition starts at block 16777250) [2288.207] 04924.06735> paver:[FindFirstFit] There are 0 free blocks (49152 requested) [2288.207] 04924.06735> paver:[FindFirstFit] Partition[2] From Block [16777250, 16810018) ... (next partition starts at block 250069646) [2288.207] 04924.06735> paver:[FindFirstFit] There are 233259628 free blocks (49152 requested) [2288.207] 04924.06735> paver:[AddPartition] Found space in GPT - OK 233259628 @ 16810018 [2288.207] 04924.06735> paver:[AddPartition] Final space in GPT - OK 49152 @ 16810018 [2288.208] 04924.06735> paver:[AddPartition] Added partition, waiting for bind [2288.208] 03124.03185> block: Joining un-closed FIFO server [2288.208] 01105.01118> devcoord: dc_bind_device() '' [2288.209] 01183.01203> devmgr: /dev/class/block/000: GPT? [2288.209] 01105.01118> devcoord: dc_bind_device() '/boot/driver/gpt.so' [2288.209] 03124.03185> gpt: device_get_metadata failed (-25) [2288.210] 01183.01203> devmgr: /dev/class/block/017: FVM? [2288.210] 01105.01118> devcoord: dc_bind_device() '/boot/driver/fvm.so' [2288.210] 04924.06735> paver:[AddPartition] Added partition, waiting for bind - OK 2019/05/22 09:37:51 done 2019/05/22 09:37:51 attempting to send <<image>>authorized_keys... 2019/05/22 09:37:51 target is busy, retrying in one second [2288.319] 04924.04938> netsvc: tftp write of file <<image>>zirconr.img completed [2288.319] 04924.04938> netsvc: metrics: {"inorderblks": 11146,"oooblks": 0,"ack": 44,"nack": 0,"timeouts": 0,"sas": 0,"inorderbytes": 11413104} [2288.347] 04924.06735> paver:[PartitionPave] Completed successfully 2019/05/22 09:37:52 attempting to send <<image>>authorized_keys... 2019/05/22 09:37:52 done 2019/05/22 09:37:52 attempting to send <<netboot>>kernel.bin... 2019/05/22 09:37:52 target is busy, retrying in one second [2289.319] 04924.04938> netsvc: Installing SSH authorized_keys [2289.320] 04924.04938> netsvc: tftp write of file <<image>>authorized_keys completed [2289.320] 04924.04938> netsvc: metrics: {"inorderblks": 1,"oooblks": 0,"ack": 1,"nack": 0,"timeouts": 0,"sas": 0,"inorderbytes": 806} [2289.322] 04924.07012> paver:[Initialize] Successfully initialized EFI Device Partitioner [2289.323] 01105.01118> devcoord: dc_bind_device() '/boot/driver/zxcrypt.so' [2289.323] 03124.03185> devhost_get_handles(0x4b00c3591900:block) open path='zxcrypt', r=-2 [2289.349] 04924.07012> paver:[DataFilePave] Wrote ssh/authorized_keys 2019/05/22 09:37:53 attempting to send <<netboot>>kernel.bin... 2019/05/22 09:37:53 done DEBUG: stopping or rebooting the node "banjo-flint-copy-crazy" ERROR: cannot find node "banjo-flint-copy-crazy": read udp6 [::]:45624: i/o timeout