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

@@@STEP_TEXT@1 out of 8 aggregated steps failed: Swarming task failed: 2019/05/22 12:33:48 attempting to send <<netboot>>cmdline... 2019/05/22 12:33:48 done 2019/05/22 12:33:48 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 [00019.791] 00000.00000> timer features: constant_tsc 1 invariant_tsc 1 tsc_deadline 1 [00019.791] 00000.00000> Using TSC as wallclock [00019.791] 00000.00000> initializing kernel [00019.791] 00000.00000> initializing mp [00019.791] 00000.00000> initializing timers [00019.791] 00000.00000> INIT: cpu 0, calling hook 0xffffffff0013c578 (debuglog) at level 0x7ffff, flags 0x1 [00019.791] 00000.00000> INIT: cpu 0, calling hook 0xffffffff00195518 (thread_set_priority_experiment) at level 0x7ffff, flags 0x1 [00019.791] 00000.00000> thread set priority experiment is : ENABLED [00019.791] 00000.00000> INIT: cpu 0, calling hook 0xffffffff001aa67c (global_prng_thread_safe) at level 0x7ffff, flags 0x1 [00019.791] 00000.00000> creating bootstrap completion thread [00020.134] 00000.00000> top of bootstrap2() [00020.134] 00000.00000> INIT: cpu 0, calling hook 0xffffffff0013151c (dpc) at level 0x80000, flags 0x1 [00020.147] 00000.00000> INIT: cpu 0, calling hook 0xffffffff00152978 (libobject) at level 0x80000, flags 0x1 [00020.147] 00000.00000> OOM: started thread [00020.161] 00000.00000> Processor Model Info: type 0 family 0x6 model 0xe stepping 0x9 [00020.161] 00000.00000> display_family 0x6 display_model 0x8e [00020.161] 00000.00000> Vendor: Intel [00020.161] 00000.00000> Microarch: Kaby Lake [00020.161] 00000.00000> F/M/S: 6/8e/9 [00020.161] 00000.00000> Brand: Intel(R) Core(TM) i5-7300U CPU @ 2.60GHz [00020.161] 00000.00000> Features: fpu sse sse2 sse3 ssse3 sse4.1 sse4.2 mmx avx avx2 fxsr pcid xsave mon aesni clflush [00020.161] 00000.00000> clflushopt fsgsbase tsc_adj smep smap erms rdrand rdseed syscall nx huge rdtscp [00020.161] 00000.00000> invar_tsc tsc_deadline x2apic vmx pt hwp [00020.161] 00000.00000> initializing platform [00020.161] 00000.00000> INIT: cpu 0, calling hook 0xffffffff001101f4 (x86_perfmon) at level 0x90000, flags 0x1 [00020.161] 00000.00000> PMU: version 4 [00020.161] 00000.00000> UART: started IRQ driven RX [00020.161] 00000.00000> UART: started IRQ driven TX [00020.161] 00000.00000> cpu topology: [00020.161] 00000.00000> 0: apic id 0x0 package 0 node 0 core 0 smt 0 BSP [00020.161] 00000.00000> 1: apic id 0x2 package 0 node 0 core 1 smt 0 [00020.161] 00000.00000> 2: apic id 0x1 package 0 node 0 core 0 smt 1 [00020.161] 00000.00000> 3: apic id 0x3 package 0 node 0 core 1 smt 1 [00020.161] 00000.00000> Found 4 cpus [00020.161] 00000.00000> booting apic ids: 0x2 0x1 0x3 [00020.176] 00000.00000> entering scheduler on cpu 2 [00020.178] 00000.00000> entering scheduler on cpu 3 [00020.178] 00000.00000> entering scheduler on cpu 1 [00020.180] 00000.00000> smbios: manufacturer="Intel Corporation" product="NUC7i5DNHE" [00020.180] 00000.00000> initializing target [00020.180] 00000.00000> INIT: cpu 0, calling hook 0xffffffff001053a0 (x86_pcie_init) at level 0xa0000, flags 0x1 [00020.180] 00000.00000> moving to last init level [00020.180] 00000.00000> INIT: cpu 0, calling hook 0xffffffff00144140 (ktrace) at level 0xc0000, flags 0x1 [00020.184] 00000.00000> ktrace: buffer at 0xffffff9933400000 (33554432 bytes) [00020.184] 00000.00000> INIT: cpu 0, calling hook 0xffffffff00147ab4 (userboot) at level 0xc0000, flags 0x1 [00020.184] 00000.00000> userboot: ramdisk 0x10ad000 @ 0xffffff80012f2000 [00020.184] 00000.00000> userboot: userboot rodata 0 @ [0x38e2ed7b6000,0x38e2ed7b9000) [00020.184] 00000.00000> userboot: userboot code 0x3000 @ [0x38e2ed7b9000,0x38e2ed7c4000) [00020.184] 00000.00000> userboot: vdso/full rodata 0 @ [0x38e2ed7c4000,0x38e2ed7cb000) [00020.184] 00000.00000> userboot: vdso/full code 0x7000 @ [0x38e2ed7cb000,0x38e2ed7cc000) [00020.184] 00000.00000> userboot: entry point @ 0x38e2ed7b9c10 [00020.184] 00000.00000> INIT: cpu 0, calling hook 0xffffffff001aa030 (kernel_shell) at level 0xc0000, flags 0x1 [00020.184] 01036.01043> userboot: option "netsvc.disable=true" [00020.184] 01036.01043> userboot: option "zircon.system.disable-automount=true" [00020.184] 01036.01043> userboot: option "zircon.autorun.boot=/boot/infra/setup" [00020.184] 01036.01043> userboot: option "kernel.serial=legacy" [00020.184] 01036.01043> userboot: option "http://192.168.42.1/multiboot/54%3Ab2%3A03%3A13%3Aae%3Ab3=" [00020.184] 01036.01043> userboot: option "multiboot.boot_loader_name=iPXE+1.0.0++(d2063)" [00020.223] 01036.01043> userboot: searching bootfs for 'bin/bootsvc' [00020.223] 01036.01043> userboot: 'bin/bootsvc' has PT_INTERP "lib/ld.so.1" [00020.223] 01036.01043> userboot: searching bootfs for 'lib/ld.so.1' [00020.223] 01036.01043> userboot: userboot: loaded lib/ld.so.1 at 0x5199234ab000, entry point 0x5199235310d3 [00020.223] 01036.01043> userboot: userboot: loaded vDSO at 0x52c39d880000, entry point 0x0 [00020.223] 01036.01043> userboot: process bin/bootsvc started. [00020.223] 01036.01043> userboot: waiting for loader-service requests... [00020.224] 01036.01043> userboot: searching bootfs for 'lib/libasync-default.so' [00020.224] 01036.01043> userboot: searching bootfs for 'lib/libfdio.so' [00020.224] 01036.01043> userboot: searching bootfs for 'lib/liblaunchpad.so' [00020.224] 01036.01043> userboot: searching bootfs for 'lib/libtrace-engine.so' [00020.224] 01050.01053> {{{reset}}} [00020.224] 01050.01053> {{{module:0:<application>:elf:18de7d58f51e8ba5c4f6afdd0cc8440f482c2b45}}} [00020.224] 01050.01053> {{{mmap:0x14614b615000:0x2e000:load:0:rx:0}}} [00020.224] 01050.01053> {{{mmap:0x14614b643000:0x4000:load:0:rw:0x2e000}}} [00020.224] 01050.01053> dso: id=18de7d58f51e8ba5c4f6afdd0cc8440f482c2b45 base=0x000014614b615000 name=<application> [00020.224] 01050.01053> {{{module:0x3:libasync-default.so:elf:c189f51f19d10785d93b5235ad1b46dca4451b00}}} [00020.224] 01050.01053> {{{mmap:0x60f3a6e40000:0x1000:load:0x3:rx:0}}} [00020.224] 01050.01053> {{{mmap:0x60f3a6e41000:0x1000:load:0x3:rw:0x1000}}} [00020.224] 01050.01053> dso: id=c189f51f19d10785d93b5235ad1b46dca4451b00 base=0x000060f3a6e40000 name=libasync-default.so [00020.224] 01050.01053> {{{module:0x2:<vDSO>:elf:40ab5fa3b61f12fef4a44477a687f608661cd450}}} [00020.224] 01050.01053> {{{mmap:0x52c39d880000:0x7000:load:0x2:r:0}}} [00020.224] 01050.01053> {{{mmap:0x52c39d887000:0x1000:load:0x2:rx:0x7000}}} [00020.224] 01050.01053> dso: id=40ab5fa3b61f12fef4a44477a687f608661cd450 base=0x000052c39d880000 name=<vDSO> [00020.224] 01050.01053> {{{module:0x1:libc.so:elf:67a12284bce140fc32aaaeac223e0e8f85cb5085}}} [00020.224] 01050.01053> {{{mmap:0x5199234ab000:0xcb000:load:0x1:rx:0}}} [00020.224] 01050.01053> {{{mmap:0x519923577000:0x6000:load:0x1:rw:0xcc000}}} [00020.224] 01050.01053> dso: id=67a12284bce140fc32aaaeac223e0e8f85cb5085 base=0x00005199234ab000 name=libc.so [00020.224] 01050.01053> {{{module:0x4:libfdio.so:elf:27787977e95f3b9563c9e0bd4d34ec92b7e9ad88}}} [00020.224] 01050.01053> {{{mmap:0x581664329000:0x24000:load:0x4:rx:0}}} [00020.224] 01050.01053> {{{mmap:0x58166434e000:0x4000:load:0x4:rw:0x25000}}} [00020.224] 01050.01053> dso: id=27787977e95f3b9563c9e0bd4d34ec92b7e9ad88 base=0x0000581664329000 name=libfdio.so [00020.224] 01050.01053> {{{module:0x5:liblaunchpad.so:elf:6fc2232dc8c1bc5c6adb8ad50ca794b5a260ee4f}}} [00020.224] 01050.01053> {{{mmap:0x25c3fdfa6000:0x7000:load:0x5:rx:0}}} [00020.224] 01050.01053> {{{mmap:0x25c3fdfad000:0x2000:load:0x5:rw:0x7000}}} [00020.224] 01050.01053> dso: id=6fc2232dc8c1bc5c6adb8ad50ca794b5a260ee4f base=0x000025c3fdfa6000 name=liblaunchpad.so [00020.224] 01050.01053> {{{module:0x6:libtrace-engine.so:elf:c9042b83fe01206008fcefb16395238417248169}}} [00020.224] 01050.01053> {{{mmap:0x69f540bd5000:0x9000:load:0x6:rx:0}}} [00020.224] 01050.01053> {{{mmap:0x69f540bde000:0x2000:load:0x6:rw:0x9000}}} [00020.224] 01050.01053> dso: id=c9042b83fe01206008fcefb16395238417248169 base=0x000069f540bd5000 name=libtrace-engine.so [00020.224] 01050.01053> bootsvc: Starting... [00020.224] 01036.01043> userboot: loader-service channel peer closed [00020.224] 01036.01043> userboot: finished! [00020.224] 01050.01053> bootsvc: Creating bootfs service... [00020.225] 01050.01053> bootsvc: Processing bootdata... [00020.225] 01050.01053> bootsvc: Loading boot cmdline overrides... [00020.225] 01050.01053> bootsvc: Loading kernel VMOs... [00020.225] 01050.01053> bootsvc: Creating loader service... [00020.225] 01050.01053> bootsvc: Launching next process... [00020.225] 01050.01096> bootsvc: launched bin/devmgr [00020.225] 01104.01117> devmgr: main() [00020.225] 01104.01117> cmdline: netsvc.disable=true [00020.225] 01104.01117> cmdline: zircon.system.disable-automount=true [00020.225] 01104.01117> cmdline: zircon.autorun.boot=/boot/infra/setup [00020.225] 01104.01117> cmdline: kernel.serial=legacy [00020.225] 01104.01117> cmdline: http://192.168.42.1/multiboot/54%3Ab2%3A03%3A13%3Aae%3Ab3= [00020.225] 01104.01117> cmdline: multiboot.boot_loader_name=iPXE+1.0.0++(d2063) [00020.226] 01104.01117> devmgr: coordinator_init() [00020.226] 01104.01117> devmgr: init [00020.226] 01104.01117> devmgr: svc init [00020.226] 01104.01117> devmgr: launch /boot/bin/svchost (svchost) OK [00020.226] 01104.01117> devmgr: vfs init [00020.226] 01104.01117> devmgr: launch /boot/bin/fshost (fshost) OK [00020.226] 01104.01220> devmgr: shell startup [00020.227] 01182.01202> fshost: started. [00020.228] 01104.01213> devmgr: launch /boot/bin/pwrbtn-monitor (pwrbtn-monitor) OK [00020.228] 01104.01230> devmgr: launch /boot/bin/virtual-console (virtual-console) OK [00020.228] 01104.01230> zircon.autorun.boot: starting '/boot/infra/setup'... [00020.229] 01104.01230> devmgr: launch /boot/infra/setup (autorun:boot) OK [00020.232] 01104.01117> devcoord: launch devhost 'devhost:sys': pid=2049 [00020.232] 01104.01117> devcoord: launch devhost 'devhost:test': pid=2082 [00020.232] 01104.01117> devcoord: launch devhost 'devhost:root': pid=2114 [00020.233] 01104.01117> devcoord: launch devhost 'devhost:misc': pid=2171 [00020.233] 02049.02073> devhost: trace provider registry begun [00020.234] 02082.02105> devhost: trace provider registry begun [00020.235] 02114.02156> devhost: trace provider registry begun [00020.236] 02171.02220> devhost: trace provider registry begun [00020.238] 01104.01220> devmgr: launch /boot/bin/sh (sh:console) OK [00020.293] 02049.02073> acpi-bus: not using IOMMU [00020.297] 02049.02073> acpi-pwrbtn: initialized [00020.319] 02049.02073> acpi: published device pci(0x28a38925c200), parent=proxy(0x28a389258540), handle=0x28a389294c30 [00020.320] 02049.02073> acpi: published device rtc(0x28a389257080), parent=acpi(0x28a389258780), handle=0x28a3892ad5b0 [00020.321] 02049.02073> acpi-ec: initialized [00020.323] 02049.02073> acpi: failed to create NHLT VMO (res -10) [00020.323] 02049.02073> acpi: failed to publish NHLT metadata [00020.325] 02049.02073> [sysmem_init 28] async_get_default_dispatcher(): 0x28a38924b0a0 [00020.325] 02049.02073> [sysmem_bind 40] sysmem_bind() [00020.325] 02049.02073> acpi-bus: sysmem_register_protocol() intentionally ignored for now. [00020.325] 02049.02073> PMU: 7 arch events [00020.325] 02049.02073> PMU: arch event id range: 1-7 [00020.325] 02049.02073> PMU: 102 model events [00020.325] 02049.02073> PMU: model event id range: 1-241 [00020.325] 02049.02073> Intel Processor Trace configuration for this chipset: [00020.325] 02049.02073> mtc_freq_mask: 0x249 [00020.325] 02049.02073> cyc_thresh_mask: 0x3fff [00020.325] 02049.02073> psb_freq_mask: 0x3f [00020.325] 02049.02073> num addr ranges: 2 [00020.326] 01104.01117> devcoord: launch devhost 'devhost:pci#1:8086:5916': pid=2837 [00020.326] 01104.01117> devcoord: launch devhost 'devhost:pci#3:8086:9d2f': pid=2882 [00020.326] 01104.01117> devcoord: launch devhost 'devhost:pci#5:8086:9d60': pid=2945 [00020.327] 01104.01117> devcoord: launch devhost 'devhost:pci#6:8086:9d61': pid=3009 [00020.327] 02837.02860> devhost: trace provider registry begun [00020.328] 02882.02917> devhost: trace provider registry begun [00020.328] 01104.01117> devcoord: launch devhost 'devhost:pci#9:8086:9d03': pid=3106 [00020.328] 02945.02985> devhost: trace provider registry begun [00020.329] 01104.01117> devcoord: launch devhost 'devhost:pci#14:8086:9d71': pid=3228 [00020.329] 03009.03048> devhost: trace provider registry begun [00020.329] 01104.01117> devcoord: launch devhost 'devhost:pci#16:8086:156f': pid=3315 [00020.330] 03106.03163> devhost: trace provider registry begun [00020.331] 03106.03163> ahci: using MSI interrupt [00020.331] 03228.03276> devhost: trace provider registry begun [00020.331] 02945.02985> initialized intel serialio i2c driver, reg=0x760f28447000 regsize=4096 [00020.332] 03009.03048> initialized intel serialio i2c driver, reg=0x7ce738a44000 regsize=4096 [00020.335] 03315.03369> devhost: trace provider registry begun [00020.337] 03228.03276> [IHDA DSP 00:1f.3] Failed to fetch NHLT (res -25) [00020.337] 03228.03276> devhost[00:1f.3/intel-hda-000/intel-sst-dsp-000] bind driver '/boot/driver/dsp.so' failed: -25 [00020.337] 01104.01117> devcoord: rpc: bind-driver 'intel-sst-dsp-000' status -25 [00020.337] 02882.03630> * found USB device (0x18d1:0xa002, USB 2.0) config 1 [00020.345] 02882.03630> * found USB device (0x18d1:0xa003, USB 3.0) config 1 [00020.347] 01239.01551> vc: new input device /dev/class/input/000 [00020.437] 01239.01551> vc: new display device /dev/class/display-controller/000/virtcon [00020.577] 02837.04142> i915: MST not supported [00021.077] 02837.04142> i915: Found DP monitor [00021.077] 02837.04142> i915: Display 1 connected [00021.636] 01239.01551> vc: Successfully attached to display 1 [00021.808] 02882.03630> * found USB device (0x0781:0x5571, USB 2.0) config 1 [00021.808] 02882.02917> UMS: parent: 'ifc-000' [00021.809] 02882.02917> UMS:Max lun is: 0 [00022.058] 02882.03630> * found USB device (0x8087:0x0a2b, USB 2.0) config 1 [00022.060] 02882.02917> devhost[00:14.0/xhci/usb-bus/002/002/ifc-001] bind driver '/boot/driver/bt-transport-usb.so' failed: -2 [00022.060] 01104.01117> devcoord: rpc: bind-driver 'ifc-001' status -2 [00022.335] 03009.03048> intel-i2c-controller: intel_serialio_i2c_slave_transfer: -21 [00022.335] 03009.03048> i2c-hid: could not read HID descriptor: 0 [00022.335] 03009.03048> devhost[00:15.1/i2c-bus-9d61/004c] bind driver '/boot/driver/i2c-hid.so' failed: -2 [00022.335] 01104.01117> devcoord: rpc: bind-driver '004c' status -2 [00022.335] 02945.02985> intel-i2c-controller: intel_serialio_i2c_slave_transfer: -21 [00022.335] 02945.02985> i2c-hid: could not read HID descriptor: 0 [00022.335] 02945.02985> devhost[00:15.0/i2c-bus-9d60/0020] bind driver '/boot/driver/i2c-hid.so' failed: -2 [00022.335] 01104.01117> devcoord: rpc: bind-driver '0020' status -2 [00022.349] 03106.03602> sata2: dev info [00022.349] 03106.03602> serial=AA000000000000009037 [00022.349] 03106.03602> firmware rev=0R08A1 0 [00022.349] 03106.03602> model id=ETMAT 8MSP1582 G [00022.349] 03106.03602> major=0x3f0 ACS2 DMA 32 commands [00022.349] 03106.03602> LBA48 250069680 sectors, sector size=512 [00022.350] 01182.01202> devmgr: /dev/class/block/000: GPT? [00022.350] 01104.01117> devcoord: dc_bind_device() '/boot/driver/gpt.so' [00022.350] 03106.03163> gpt: device_get_metadata failed (-25) [00022.351] 01182.01202> devmgr: /dev/class/block/001: FVM? [00022.351] 01104.01117> devcoord: dc_bind_device() '/boot/driver/fvm.so' [00022.353] 04413.04427> paver:[Initialize] Successfully initialized EFI Device Partitioner [00022.356] 04413.04427> paver:[WipePartitions] Immediate reboot strongly recommended [00022.356] 03106.03163> block: Joining un-closed FIFO server [00022.356] 03106.03163> block: Joining un-closed FIFO server [00022.356] 03106.03163> block: Joining un-closed FIFO server [00022.356] 01104.01117> devcoord: dc_bind_device() '' [00022.357] 01182.01202> devmgr: /dev/class/block/000: GPT? [00022.357] 01104.01117> devcoord: dc_bind_device() '/boot/driver/gpt.so' [00022.357] 03106.03163> gpt: device_get_metadata failed (-25) [00022.358] 03106.04753> gpt: bad header magic [00022.359] 04702.04716> 34+0 records in [00022.359] 04702.04716> 34+0 records out [00022.359] 04702.04716> 17408 bytes copied [00022.361] 04819.04833> 34+0 records in [00022.361] 04819.04833> 34+0 records out [00022.361] 04819.04833> 17408 bytes copied [00022.362] 04923.04937> netifc: ? /dev/class/ethernet/000 [00022.362] 04923.04937> netifc: create 512 eth buffers [00022.363] 04923.04937> macaddr: 54:b2:03:13:ae:b3 [00022.363] 04923.04937> ip6addr: fe80::56b2:34d:fe13:aeb3 [00022.363] 04923.04937> snmaddr: ff02::1:ff13:aeb3 [00022.363] 04923.04937> netsvc: using /dev/class/ethernet/000 [00022.363] 04923.04937> _ _ _ [00022.363] 04923.04937> | | | | | [00022.363] 04923.04937> _______ __| | |__ ___ ___ | |_ [00022.363] 04923.04937> |_ / _ \/ _` | '_ \ / _ \ / _ \| __| [00022.363] 04923.04937> / / __/ (_| | |_) | (_) | (_) | |_ [00022.363] 04923.04937> /___\___|\__,_|_.__/ \___/ \___/ \__| [00022.363] 04923.04937> [00022.363] 04923.04937> [00022.363] 04923.04937> zedboot: version: 0.7.13 [00022.363] 04923.04937> [00022.363] 04923.04937> netsvc: nodename='stick-shady-wool-crazy' [00022.363] 04923.04937> netsvc: will not advertise [00022.363] 04923.04937> netsvc: start [00022.811] 02882.04246> UMS: block size is: 0x00000200 [00022.811] 02882.04246> UMS: total blocks is: 15630336 [00022.811] 02882.04246> UMS: total size is: 8002732032 [00022.811] 02882.04246> UMS: read-only: 0 removable: 1 [00022.812] 01182.01202> devmgr: /dev/class/block/006: MBR? [00022.812] 01104.01117> devcoord: dc_bind_device() '/boot/driver/mbr.so' [00022.815] 01182.01202> devmgr: /dev/class/block/008: MBR? [00022.815] 01104.01117> devcoord: dc_bind_device() '/boot/driver/mbr.so' [10745.679] 04923.04937> netsvc: tftp write of file <<netboot>>cmdline completed [10745.679] 04923.04937> netsvc: metrics: {"inorderblks": 1,"oooblks": 0,"ack": 1,"nack": 0,"timeouts": 0,"sas": 0,"inorderbytes": 21} [10745.679] 04923.04937> netsvc: Running FVM Paver [10745.681] 04923.05107> paver:[InitializeGpt] Located GPT is invalid; Attempting to initialize [10745.681] 01104.01117> devcoord: dc_bind_device() '/boot/driver/gpt.so' [10745.682] 03106.03163> gpt: device_get_metadata failed (-25) [10745.684] 04923.05107> paver:[Initialize] Successfully initialized EFI Device Partitioner [10745.684] 04923.05107> paver:[PartitionPave] Paving partition. [10745.684] 04923.05107> paver:[FindFirstFit] Looking for space [10745.684] 04923.05107> paver:[FindFirstFit] Sorting [10745.684] 04923.05107> paver:[FindFirstFit] Partition[0] From Block [0, 34) ... (next partition starts at block 250069646) [10745.684] 04923.05107> paver:[FindFirstFit] There are 250069612 free blocks (16777216 requested) [10745.684] 04923.05107> paver:[AddPartition] Found space in GPT - OK 250069612 @ 34 [10745.684] 04923.05107> paver:[AddPartition] Final space in GPT - OK 16777216 @ 34 [10745.684] 04923.05107> paver:[AddPartition] Added partition, waiting for bind [10745.684] 01104.01117> devcoord: dc_bind_device() '' [10745.685] 01182.01202> devmgr: /dev/class/block/000: GPT? [10745.685] 01104.01117> devcoord: dc_bind_device() '/boot/driver/gpt.so' [10745.685] 03106.03163> gpt: device_get_metadata failed (-25) [10745.686] 04923.05107> paver:[AddPartition] Added partition, waiting for bind - OK [10745.686] 04923.05107> paver:[PartitionPave] Streaming partitions... [10745.686] 05087.05101> Found compressed file [10745.686] 04923.05107> paver:[FvmStreamPartitions] Header Validated - OK [10745.687] 04923.05107> paver:[FvmPartitionFormat] Initializing partition as FVM [10745.689] 01104.01117> devcoord: dc_bind_device() '/boot/driver/fvm.so' [10746.691] 04923.05107> paver:[FvmStreamPartitions] Partitions pre-validated successfully: Enough space exists to pave. [10746.691] 04923.05107> paver:[AllocatePartitions] Allocating partition blobfs consisting of 1 slices [10746.695] 04923.05107> paver:[AllocatePartitions] Allocating partition minfs consisting of 1 slices [10746.696] 04923.05107> paver:[AllocatePartitions] Creating zxcrypt volume [10746.698] 03106.03163> devhost_get_handles(0x5a3678407900:block) open path='zxcrypt/block', r=-2 [10746.698] 01104.01117> devcoord: dc_bind_device() '/boot/driver/zxcrypt.so' [10746.699] 03106.03163> devhost_get_handles(0x5a3678407900:block) open path='zxcrypt', r=-2 [10746.703] 04923.05107> paver:[FvmStreamPartitions] Partition space pre-allocated successfully. [10746.703] 04923.05107> paver:[FvmStreamPartitions] Streaming partition 0 [10746.703] 04923.05107> paver:[StreamFvmPartition] Writing extent 0... [10746.703] 04923.05113> netsvc: paver write progress 0.0% [10746.703] 04923.05107> paver:[StreamFvmPartition] 8192 bytes written, 8380416 zeroes left [10746.720] 04923.05107> paver:[StreamFvmPartition] Writing extent 1... [10746.720] 04923.05107> paver:[StreamFvmPartition] 16384 bytes written, 8372224 zeroes left [10746.736] 04923.05107> paver:[StreamFvmPartition] Writing extent 2... [10746.740] 04923.05107> paver:[StreamFvmPartition] 2097152 bytes written, 6291456 zeroes left [10746.765] 04923.05107> paver:[StreamFvmPartition] Writing extent 3... [10746.770] 04923.05107> paver:[StreamFvmPartition] 2097152 bytes written, 6291456 zeroes left [10746.782] 04923.05107> paver:[StreamFvmPartition] Writing extent 4... [10747.703] 04923.05113> netsvc: paver write progress 31.2% [10748.703] 04923.05113> netsvc: paver write progress 46.6% [10749.703] 04923.05113> netsvc: paver write progress 61.9% [10750.703] 04923.05113> netsvc: paver write progress 77.3% [10751.703] 04923.05113> netsvc: paver write progress 92.6% 2019/05/22 12:33:55 done 2019/05/22 12:33:55 attempting to send <<image>>bootloader.img... 2019/05/22 12:33:55 target is busy, retrying in one second [10752.180] 04923.04937> netsvc: tftp write of file <<image>>sparse.fvm completed [10752.180] 04923.04937> netsvc: metrics: {"inorderblks": 660098,"oooblks": 0,"ack": 2579,"nack": 0,"timeouts": 0,"sas": 0,"inorderbytes": 675939875} [10752.181] 04923.05107> paver:[StreamFvmPartition] 723861504 bytes written, 5947392 zeroes left [10752.203] 04923.05107> paver:[FvmStreamPartitions] Done streaming partition 0 [10752.203] 04923.05107> paver:[FvmStreamPartitions] Done flushing partition 0 [10752.203] 04923.05107> paver:[FvmStreamPartitions] Streaming partition 1 [10752.203] 04923.05107> paver:[StreamFvmPartition] Writing extent 0... [10752.203] 04923.05107> paver:[StreamFvmPartition] 8192 bytes written, 8380416 zeroes left [10752.242] 04923.05107> paver:[StreamFvmPartition] Writing extent 1... [10752.242] 04923.05107> paver:[StreamFvmPartition] 65536 bytes written, 8323072 zeroes left [10752.281] 04923.05107> paver:[StreamFvmPartition] Writing extent 2... [10752.281] 04923.05107> paver:[StreamFvmPartition] 65536 bytes written, 8323072 zeroes left [10752.317] 04923.05107> paver:[StreamFvmPartition] Writing extent 3... [10752.358] 04923.05107> paver:[StreamFvmPartition] Writing extent 4... [10752.368] 04923.05107> paver:[StreamFvmPartition] 2097152 bytes written, 14680064 zeroes left [10752.431] 04923.05107> paver:[StreamFvmPartition] Writing extent 5... [10752.431] 04923.05107> paver:[StreamFvmPartition] 57344 bytes written, 8331264 zeroes left [10752.466] 04923.05107> paver:[FvmStreamPartitions] Done streaming partition 1 [10752.466] 04923.05107> paver:[FvmStreamPartitions] Done flushing partition 1 [10752.468] 05087.05101> Reading FVM from compressed file: true [10752.468] 05087.05101> Remaining bytes read into compression buffer: 0 [10752.468] 05087.05101> Remaining bytes written to decompression buffer: 0 [10752.468] 05087.05101> Time reading bytes from sparse FVM file: 10189563356 (3 s) [10752.468] 05087.05101> Time reading bytes AND decompressing them: 10521478673 (3 s) [10752.468] 04923.05107> paver:[PartitionPave] Completed successfully 2019/05/22 12:33:56 attempting to send <<image>>bootloader.img... 2019/05/22 12:33:56 done 2019/05/22 12:33:56 attempting to send <<image>>zircona.img... [10753.181] 04923.04937> netsvc: Running BOOTLOADER Paver [10753.184] 04923.06346> paver:[Initialize] Successfully initialized EFI Device Partitioner [10753.184] 04923.06346> paver:[RealMain] SKIPPING BOOTLOADER install on x64 device, pass --force if desired. [10753.192] 04923.04937> netsvc: tftp write of file <<image>>bootloader.img completed [10753.192] 04923.04937> netsvc: metrics: {"inorderblks": 1093,"oooblks": 0,"ack": 5,"nack": 0,"timeouts": 0,"sas": 0,"inorderbytes": 1118208} [10753.192] 04923.04937> netsvc: Running ZIRCON-A Paver [10753.196] 04923.06475> paver:[Initialize] Successfully initialized EFI Device Partitioner [10753.196] 04923.06475> paver:[PartitionPave] Paving partition. [10753.196] 04923.06475> paver:[FindFirstFit] Looking for space [10753.196] 04923.06475> paver:[FindFirstFit] Partition seen with start 34, end 16777249 (length 16777216) [10753.196] 04923.06475> paver:[FindFirstFit] Sorting [10753.196] 04923.06475> paver:[FindFirstFit] Partition[0] From Block [0, 34) ... (next partition starts at block 34) [10753.196] 04923.06475> paver:[FindFirstFit] There are 0 free blocks (32768 requested) [10753.196] 04923.06475> paver:[FindFirstFit] Partition[1] From Block [34, 16777250) ... (next partition starts at block 250069646) [10753.196] 04923.06475> paver:[FindFirstFit] There are 233292396 free blocks (32768 requested) [10753.196] 04923.06475> paver:[AddPartition] Found space in GPT - OK 233292396 @ 16777250 [10753.196] 04923.06475> paver:[AddPartition] Final space in GPT - OK 32768 @ 16777250 [10753.196] 03106.03163> block: Joining un-closed FIFO server [10753.196] 04923.06475> paver:[AddPartition] Added partition, waiting for bind [10753.196] 03106.03163> block: Joining un-closed FIFO server [10753.196] 01104.01117> devcoord: dc_bind_device() '' [10753.197] 01182.01202> devmgr: /dev/class/block/000: GPT? [10753.197] 01104.01117> devcoord: dc_bind_device() '/boot/driver/gpt.so' [10753.197] 03106.03163> gpt: device_get_metadata failed (-25) [10753.198] 01182.01202> devmgr: /dev/class/block/013: FVM? [10753.198] 01104.01117> devcoord: dc_bind_device() '/boot/driver/fvm.so' [10753.198] 04923.06475> paver:[AddPartition] Added partition, waiting for bind - OK 2019/05/22 12:33:56 done 2019/05/22 12:33:56 attempting to send <<image>>zirconr.img... 2019/05/22 12:33:56 target is busy, retrying in one second [10753.312] 04923.04937> netsvc: tftp write of file <<image>>zircona.img completed [10753.312] 04923.04937> netsvc: metrics: {"inorderblks": 12203,"oooblks": 0,"ack": 48,"nack": 0,"timeouts": 0,"sas": 0,"inorderbytes": 12495176} [10753.346] 04923.06475> paver:[PartitionPave] Completed successfully 2019/05/22 12:33:57 attempting to send <<image>>zirconr.img... [10754.313] 04923.04937> netsvc: Running ZIRCON-R Paver [10754.316] 04923.06735> paver:[Initialize] Successfully initialized EFI Device Partitioner [10754.316] 04923.06735> paver:[PartitionPave] Paving partition. [10754.316] 04923.06735> paver:[FindFirstFit] Looking for space [10754.316] 04923.06735> paver:[FindFirstFit] Partition seen with start 34, end 16777249 (length 16777216) [10754.316] 04923.06735> paver:[FindFirstFit] Partition seen with start 16777250, end 16810017 (length 32768) [10754.316] 04923.06735> paver:[FindFirstFit] Sorting [10754.316] 04923.06735> paver:[FindFirstFit] Partition[0] From Block [0, 34) ... (next partition starts at block 34) [10754.316] 04923.06735> paver:[FindFirstFit] There are 0 free blocks (49152 requested) [10754.316] 04923.06735> paver:[FindFirstFit] Partition[1] From Block [34, 16777250) ... (next partition starts at block 16777250) [10754.316] 04923.06735> paver:[FindFirstFit] There are 0 free blocks (49152 requested) [10754.316] 04923.06735> paver:[FindFirstFit] Partition[2] From Block [16777250, 16810018) ... (next partition starts at block 250069646) [10754.316] 04923.06735> paver:[FindFirstFit] There are 233259628 free blocks (49152 requested) [10754.316] 04923.06735> paver:[AddPartition] Found space in GPT - OK 233259628 @ 16810018 [10754.316] 04923.06735> paver:[AddPartition] Final space in GPT - OK 49152 @ 16810018 [10754.316] 04923.06735> paver:[AddPartition] Added partition, waiting for bind [10754.316] 03106.03163> block: Joining un-closed FIFO server [10754.316] 01104.01117> devcoord: dc_bind_device() '' [10754.317] 01182.01202> devmgr: /dev/class/block/000: GPT? [10754.317] 01104.01117> devcoord: dc_bind_device() '/boot/driver/gpt.so' [10754.317] 03106.03163> gpt: device_get_metadata failed (-25) [10754.318] 01182.01202> devmgr: /dev/class/block/017: FVM? [10754.318] 01104.01117> devcoord: dc_bind_device() '/boot/driver/fvm.so' [10754.319] 04923.06735> paver:[AddPartition] Added partition, waiting for bind - OK 2019/05/22 12:33:57 done 2019/05/22 12:33:57 attempting to send <<image>>authorized_keys... 2019/05/22 12:33:57 target is busy, retrying in one second [10754.425] 04923.04937> netsvc: tftp write of file <<image>>zirconr.img completed [10754.425] 04923.04937> netsvc: metrics: {"inorderblks": 11146,"oooblks": 0,"ack": 44,"nack": 0,"timeouts": 0,"sas": 0,"inorderbytes": 11413104} [10754.446] 04923.06735> paver:[PartitionPave] Completed successfully 2019/05/22 12:33:58 attempting to send <<image>>authorized_keys... 2019/05/22 12:33:58 done 2019/05/22 12:33:58 attempting to send <<netboot>>kernel.bin... 2019/05/22 12:33:58 target is busy, retrying in one second [10755.425] 04923.04937> netsvc: Installing SSH authorized_keys [10755.426] 04923.04937> netsvc: tftp write of file <<image>>authorized_keys completed [10755.426] 04923.04937> netsvc: metrics: {"inorderblks": 1,"oooblks": 0,"ack": 1,"nack": 0,"timeouts": 0,"sas": 0,"inorderbytes": 806} [10755.428] 04923.07012> paver:[Initialize] Successfully initialized EFI Device Partitioner [10755.429] 01104.01117> devcoord: dc_bind_device() '/boot/driver/zxcrypt.so' [10755.429] 03106.03163> devhost_get_handles(0x5a3678407900:block) open path='zxcrypt', r=-2 [10755.455] 04923.07012> paver:[DataFilePave] Wrote ssh/authorized_keys 2019/05/22 12:33:59 attempting to send <<netboot>>kernel.bin... 2019/05/22 12:33:59 done DEBUG: stopping or rebooting the node "stick-shady-wool-crazy" ERROR: cannot find node "stick-shady-wool-crazy": read udp6 [::]:38663: i/o timeout @@@