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

{ "42f9b67c48c51a10": { "output": "2019/02/12 08:49:59 attempting to send <<netboot>>cmdline...\n2019/02/12 08:49:59 done\n2019/02/12 08:49:59 attempting to send <<image>>sparse.fvm...\n2019/02/12 08:50:01 done\n2019/02/12 08:50:01 attempting to send <<image>>efi.img...\n2019/02/12 08:50:01 target is busy, retrying in one second\n2019/02/12 08:50:02 attempting to send <<image>>efi.img...\n2019/02/12 08:50:02 target is busy, retrying in one second\n[00000.000] 00000.00000> zbi: @ 0xffffff8000d92000 (11879096 bytes)\n[00000.000] 00000.00000> PMM: boot reserve add [0x100000, 0x2bcfff]\n[00000.000] 00000.00000> PMM: boot reserve add [0xd92000, 0x18e6fff]\n[00000.000] 00000.00000> PMM: arena too small to be useful (size 4096)\n[00000.000] 00000.00000> PMM: pmm_add_arena failed to initialize arena\n[00000.000] 00000.00000> MEM: Failed to add pmm range at 0x7ffff000 size 0x1000\n[00000.000] 00000.00000> PMM: boot reserve marking WIRED [0x100000, 0x2bcfff]\n[00000.000] 00000.00000> PMM: boot reserve marking WIRED [0xd92000, 0x18e6fff]\n[00000.000] 00000.00000> \n[00000.000] 00000.00000> welcome to Zircon\n[00000.000] 00000.00000> \n[00000.000] 00000.00000> KASLR: .text section at 0xffffffff00100000\n[00000.000] 00000.00000> INIT: cpu 0, calling hook 0xffffffff001ac398 (global_prng_seed) at level 0x30000, flags 0x1\n[00000.000] 00000.00000> initializing vm pre-heap\n[00000.000] 00000.00000> VM: marking boot alloc used range [0x18e7000, 0x18e7100)\n[00000.000] 00000.00000> INIT: cpu 0, calling hook 0xffffffff00147b90 (elf_build_id) at level 0x4fffe, flags 0x1\n[00000.000] 00000.00000> INIT: cpu 0, calling hook 0xffffffff00147d1c (version) at level 0x4ffff, flags 0x1\n[00000.000] 00000.00000> version:\n[00000.000] 00000.00000> \tarch: x86\n[00000.000] 00000.00000> \tplatform: pc\n[00000.000] 00000.00000> \ttarget: pc\n[00000.000] 00000.00000> \tproject: x64\n[00000.000] 00000.00000> \tbuildid: git-71785cd38a478fd12119897e6c8514fd7fdb1bf3-dirty\n[00000.000] 00000.00000> \tELF build ID: 1f5e3e417ba1f67767aa444fd66f7c0ae3e572fc\n[00000.000] 00000.00000> initializing heap\n[00000.000] 00000.00000> INIT: cpu 0, calling hook 0xffffffff00103420 (x86_resource_init) at level 0x50000, flags 0x1\n[00000.000] 00000.00000> INIT: cpu 0, calling hook 0xffffffff001ab000 (console) at level 0x50000, flags 0x1\n[00000.000] 00000.00000> initializing vm\n[00000.000] 00000.00000> VM: reserving kernel region [0xffffffff00100000, 0xffffffff001eb000) flags 0x28 name 'kernel_code'\n[00000.000] 00000.00000> VM: reserving kernel region [0xffffffff001eb000, 0xffffffff0022a000) flags 0x8 name 'kernel_rodata'\n[00000.000] 00000.00000> VM: reserving kernel region [0xffffffff0022a000, 0xffffffff0023a000) flags 0x18 name 'kernel_data'\n[00000.000] 00000.00000> VM: reserving kernel region [0xffffffff0023a000, 0xffffffff002bd000) flags 0x18 name 'kernel_bss'\n[00000.000] 00000.00000> INIT: cpu 0, calling hook 0xffffffff00101168 (acpi_tables) at level 0x60001, flags 0x1\n[00000.000] 00000.00000> INIT: cpu 0, calling hook 0xffffffff001041c0 (display_memtype) at level 0x60001, flags 0x1\n[00000.000] 00000.00000> INIT: cpu 0, calling hook 0xffffffff0010212c (hpet) at level 0x60002, flags 0x1\n[00000.000] 00000.00000> INIT: cpu 0, calling hook 0xffffffff001024b4 (apic) at level 0x60002, flags 0x1\n[00000.000] 00000.00000> x2APIC enabled\n[00000.000] 00000.00000> INIT: cpu 0, calling hook 0xffffffff00106ec8 (timer) at level 0x60003, flags 0x1\n[00000.000] 00000.00000> HPET frequency: 23999 ticks/ms\n[00000.000] 00000.00000> TSC frequency: 2712000 ticks/ms\n[00017.949] 00000.00000> timer features: constant_tsc 1 invariant_tsc 1 tsc_deadline 1\n[00017.949] 00000.00000> Using TSC as wallclock\n[00017.949] 00000.00000> initializing kernel\n[00017.949] 00000.00000> initializing mp\n[00017.949] 00000.00000> initializing timers\n[00017.949] 00000.00000> INIT: cpu 0, calling hook 0xffffffff0013b230 (debuglog) at level 0x7ffff, flags 0x1\n[00017.949] 00000.00000> INIT: cpu 0, calling hook 0xffffffff00197624 (thread_set_priority_experiment) at level 0x7ffff, flags 0x1\n[00017.949] 00000.00000> thread set priority experiment is : ENABLED\n[00017.949] 00000.00000> INIT: cpu 0, calling hook 0xffffffff001ac5f8 (global_prng_thread_safe) at level 0x7ffff, flags 0x1\n[00017.949] 00000.00000> creating bootstrap completion thread\n[00017.949] 00000.00000> top of bootstrap2()\n[00017.949] 00000.00000> INIT: cpu 0, calling hook 0xffffffff0012fe24 (dpc) at level 0x80000, flags 0x1\n[00017.949] 00000.00000> INIT: cpu 0, calling hook 0xffffffff001552b4 (libobject) at level 0x80000, flags 0x1\n[00017.949] 00000.00000> OOM: started thread\n[00017.949] 00000.00000> Processor Model Info: type 0 family 0x6 model 0xe stepping 0x9\n[00017.949] 00000.00000> \tdisplay_family 0x6 display_model 0x8e\n[00017.949] 00000.00000> Vendor: Intel\n[00017.949] 00000.00000> Microarch: Kaby Lake\n[00017.949] 00000.00000> F/M/S: 6/8e/9\n[00017.949] 00000.00000> Brand: Intel(R) Core(TM) i5-7300U CPU @ 2.60GHz\n[00017.949] 00000.00000> Features: fpu sse sse2 sse3 ssse3 sse4.1 sse4.2 mmx avx avx2 fxsr pcid xsave mon aesni clflush \n[00017.949] 00000.00000> clflushopt fsgsbase tsc_adj smep smap erms rdrand rdseed syscall nx huge rdtscp \n[00017.949] 00000.00000> invar_tsc tsc_deadline x2apic vmx pt hwp \n[00017.949] 00000.00000> initializing platform\n[00017.949] 00000.00000> cpu topology:\n[00017.949] 00000.00000> \t0: apic id 0x0 package 0 node 0 core 0 smt 0 BSP\n[00017.949] 00000.00000> \t1: apic id 0x2 package 0 node 0 core 1 smt 0\n[00017.949] 00000.00000> \t2: apic id 0x1 package 0 node 0 core 0 smt 1\n[00017.949] 00000.00000> \t3: apic id 0x3 package 0 node 0 core 1 smt 1\n[00017.949] 00000.00000> Found 4 cpus\n[00017.949] 00000.00000> booting apic ids: 0x2 0x1 0x3 \n[00017.963] 00000.00000> entering scheduler on cpu 2\n[00017.965] 00000.00000> entering scheduler on cpu 3\n[00017.965] 00000.00000> entering scheduler on cpu 1\n[00017.967] 00000.00000> smbios: manufacturer=\"Intel Corporation\" product=\"NUC7i5DNHE\"\n[00017.967] 00000.00000> initializing target\n[00017.967] 00000.00000> INIT: cpu 0, calling hook 0xffffffff00105dfc (x86_pcie_init) at level 0xa0000, flags 0x1\n[00017.967] 00000.00000> moving to last init level\n[00017.967] 00000.00000> INIT: cpu 0, calling hook 0xffffffff0014323c (ktrace) at level 0xc0000, flags 0x1\n[00017.971] 00000.00000> ktrace: buffer at 0xffffff953a864000 (33554432 bytes)\n[00017.971] 00000.00000> INIT: cpu 0, calling hook 0xffffffff00147b88 (userboot) at level 0xc0000, flags 0x1\n[00017.971] 00000.00000> userboot: ramdisk 0xb55000 @ 0xffffff8000d92000\n[00017.971] 00000.00000> userboot: userboot rodata 0 @ [0x108c8e9b4000,0x108c8e9b7000)\n[00017.971] 00000.00000> userboot: userboot code 0x3000 @ [0x108c8e9b7000,0x108c8e9c2000)\n[00017.971] 00000.00000> userboot: vdso/full rodata 0 @ [0x108c8e9c2000,0x108c8e9c8000)\n[00017.971] 00000.00000> userboot: vdso/full code 0x6000 @ [0x108c8e9c8000,0x108c8e9c9000)\n[00017.971] 00000.00000> userboot: entry point @ 0x108c8e9b7be0\n[00017.971] 00000.00000> INIT: cpu 0, calling hook 0xffffffff001abab0 (kernel_shell) at level 0xc0000, flags 0x1\n[00017.971] 01034.01041> userboot: option \"netsvc.disable=true\"\n[00017.971] 01034.01041> userboot: option \"zircon.system.disable-automount=true\"\n[00017.971] 01034.01041> userboot: option \"zircon.autorun.boot=/boot/infra/setup\"\n[00017.971] 01034.01041> userboot: option \"http://192.168.42.1/multiboot/d4%3A5d%3Adf%3A1a%3A42%3A46=\"\n[00017.971] 01034.01041> userboot: option \"multiboot.boot_loader_name=iPXE+1.0.0++(d2063)\"\n[00017.998] 01034.01041> userboot: searching bootfs for 'bin/devmgr'\n[00017.998] 01034.01041> userboot: 'bin/devmgr' has PT_INTERP \"lib/ld.so.1\"\n[00017.998] 01034.01041> userboot: searching bootfs for 'lib/ld.so.1'\n[00017.998] 01034.01041> userboot: userboot: loaded lib/ld.so.1 at 0x46385f311000, entry point 0x46385f3975e3\n[00017.998] 01034.01041> userboot: userboot: loaded vDSO at 0x69322f65c000, entry point 0x0\n[00017.998] 01034.01041> userboot: process bin/devmgr started.\n[00017.998] 01034.01041> userboot: waiting for loader-service requests...\n[00017.998] 01034.01041> userboot: searching bootfs for 'lib/libasync-default.so'\n[00017.998] 01034.01041> userboot: searching bootfs for 'lib/liblaunchpad.so'\n[00017.998] 01034.01041> userboot: searching bootfs for 'lib/libfdio.so'\n[00017.998] 01048.01051> {{{reset}}}\n[00017.998] 01048.01051> {{{module:0:<application>:elf:adb289d09c14e41d57cc06e64c3fbad20af116de}}}\n[00017.998] 01048.01051> {{{mmap:0x505c53ed4000:0x16000:load:0:rx:0}}}\n[00017.998] 01048.01051> {{{mmap:0x505c53eeb000:0x2000:load:0:rw:0x17000}}}\n[00017.998] 01048.01051> dso: id=adb289d09c14e41d57cc06e64c3fbad20af116de base=0x0000505c53ed4000 name=<application>\n[00017.998] 01048.01051> {{{module:0x3:libasync-default.so:elf:e185a560eff06a87149e82ac163f0cab85d35cd2}}}\n[00017.998] 01048.01051> {{{mmap:0x616580ba9000:0x1000:load:0x3:rx:0}}}\n[00017.998] 01048.01051> {{{mmap:0x616580baa000:0x1000:load:0x3:rw:0x1000}}}\n[00017.998] 01048.01051> dso: id=e185a560eff06a87149e82ac163f0cab85d35cd2 base=0x0000616580ba9000 name=libasync-default.so\n[00017.998] 01048.01051> {{{module:0x4:liblaunchpad.so:elf:8b03b75574d08d314aa5efad9a560559dba03719}}}\n[00017.998] 01048.01051> {{{mmap:0x19c29e89d000:0x7000:load:0x4:rx:0}}}\n[00017.998] 01048.01051> {{{mmap:0x19c29e8a4000:0x2000:load:0x4:rw:0x7000}}}\n[00017.998] 01048.01051> dso: id=8b03b75574d08d314aa5efad9a560559dba03719 base=0x000019c29e89d000 name=liblaunchpad.so\n[00017.998] 01048.01051> {{{module:0x5:libfdio.so:elf:67093cd5a6d51815a7899f50f338c85506c5afeb}}}\n[00017.998] 01048.01051> {{{mmap:0x74b3703de000:0x1f000:load:0x5:rx:0}}}\n[00017.998] 01048.01051> {{{mmap:0x74b3703fe000:0x4000:load:0x5:rw:0x20000}}}\n[00017.998] 01048.01051> dso: id=67093cd5a6d51815a7899f50f338c85506c5afeb base=0x000074b3703de000 name=libfdio.so\n[00017.998] 01048.01051> {{{module:0x2:<vDSO>:elf:669f338dda92c28c851da7148fb092cfbae24e8b}}}\n[00017.998] 01048.01051> {{{mmap:0x69322f65c000:0x6000:load:0x2:r:0}}}\n[00017.998] 01048.01051> {{{mmap:0x69322f662000:0x1000:load:0x2:rx:0x6000}}}\n[00017.998] 01048.01051> dso: id=669f338dda92c28c851da7148fb092cfbae24e8b base=0x000069322f65c000 name=<vDSO>\n[00017.998] 01048.01051> {{{module:0x1:libc.so:elf:f994d740a587fd43637c52aa7659f5ec4e448248}}}\n[00017.998] 01048.01051> {{{mmap:0x46385f311000:0xcb000:load:0x1:rx:0}}}\n[00017.998] 01048.01051> {{{mmap:0x46385f3dd000:0x6000:load:0x1:rw:0xcc000}}}\n[00017.998] 01048.01051> dso: id=f994d740a587fd43637c52aa7659f5ec4e448248 base=0x000046385f311000 name=libc.so\n[00017.998] 01034.01041> userboot: loader-service channel peer closed\n[00017.998] 01034.01041> userboot: finished!\n[00017.999] 01048.01051> devmgr: main()\n[00017.999] 01048.01051> devmgr: init\n[00017.999] 01048.01051> coordinator_init()\n[00017.999] 01048.01051> bootfs_open: 'config/devmgr' not found\n[00017.999] 01048.01051> cmdline: netsvc.disable=true\n[00017.999] 01048.01051> cmdline: zircon.system.disable-automount=true\n[00017.999] 01048.01051> cmdline: zircon.autorun.boot=/boot/infra/setup\n[00017.999] 01048.01051> cmdline: http://192.168.42.1/multiboot/d4%3A5d%3Adf%3A1a%3A42%3A46=\n[00017.999] 01048.01051> cmdline: multiboot.boot_loader_name=iPXE+1.0.0++(d2063)\n[00017.999] 01048.01051> devmgr: svc init\n[00017.999] 01048.01051> devmgr: launch /boot/bin/svchost (svchost) OK\n[00017.999] 01048.01051> devmgr: vfs init\n[00017.999] 01048.01051> devmgr: launch /boot/bin/fshost (fshost) OK\n[00017.999] 01048.01168> devmgr: shell startup\n[00017.999] 01048.01051> devmgr: coordinator()\n[00018.000] 01130.01144> fshost: started.\n[00018.001] 01048.01157> devmgr: launch /boot/bin/pwrbtn-monitor (pwrbtn-monitor) OK\n[00018.001] 01048.01178> devmgr: launch /boot/bin/crashsvc (crashsvc) OK\n[00018.002] 01048.01178> devmgr: launch /boot/bin/virtual-console (virtual-console) OK\n[00018.002] 01048.01178> zircon.autorun.boot: starting '/boot/infra/setup'...\n[00018.002] 01048.01178> devmgr: launch /boot/infra/setup (autorun:boot) OK\n[00018.005] 01048.01051> devcoord: launch devhost 'devhost:sys': pid=1951\n[00018.005] 01048.01051> devcoord: launch devhost 'devhost:test': pid=1984\n[00018.005] 01048.01051> devcoord: launch devhost 'devhost:root': pid=2017\n[00018.006] 01048.01051> devcoord: launch devhost 'devhost:misc': pid=2070\n[00018.073] 01951.01975> acpi-bus: not using IOMMU\n[00018.083] 01951.01975> WARNING: ACPI found bad _CRS address entry\n[00018.089] 01951.01975> WARNING: ACPI found bad _CRS address entry\n[00018.100] 01951.01975> acpi-pwrbtn: initialized\n[00018.100] 01951.01975> acpi: published device pci(0x77c396f95000), parent=proxy(0x77c397056480), handle=0x77c396fcf7e0\n[00018.101] 01951.01975> acpi: published device rtc(0x77c396f95040), parent=acpi(0x77c397056600), handle=0x77c396fee3c0\n[00018.102] 01951.01975> acpi-ec: initialized\n[00018.104] 01951.01975> acpi: failed to create NHLT VMO (res -10)\n[00018.104] 01951.01975> acpi: failed to publish NHLT metadata\n[00018.106] 01951.01975> Intel Processor Trace configuration for this chipset:\n[00018.106] 01951.01975> mtc_freq_mask: 0x249\n[00018.106] 01951.01975> cyc_thresh_mask: 0x3fff\n[00018.106] 01951.01975> psb_freq_mask: 0x3f\n[00018.106] 01951.01975> num addr ranges: 2\n[00018.106] 01951.01975> mtrace_ipm_control:34: action 0, options 0x0, arg 0x2c791132ac0, size 0x20\n[00018.106] 01048.01051> devcoord: launch devhost 'devhost:pci#1:8086:5916': pid=2531\n[00018.107] 01048.01051> devcoord: launch devhost 'devhost:pci#3:8086:9d2f': pid=2577\n[00018.107] 01048.01168> devmgr: launch /boot/bin/sh (sh:console) OK\n[00018.108] 01048.01051> devcoord: launch devhost 'devhost:pci#5:8086:9d60': pid=2685\n[00018.108] 01048.01051> devcoord: launch devhost 'devhost:pci#6:8086:9d61': pid=2767\n[00018.109] 01048.01051> devcoord: launch devhost 'devhost:pci#9:8086:9d03': pid=2851\n[00018.110] 01048.01051> devcoord: launch devhost 'devhost:pci#14:8086:9d71': pid=2924\n[00018.110] 01048.01051> devcoord: launch devhost 'devhost:pci#16:8086:156f': pid=2990\n[00018.112] 02685.02733> initialized intel serialio i2c driver, reg=0x49526bd01000 regsize=4096\n[00018.113] 02767.02815> initialized intel serialio i2c driver, reg=0x7a3659c11000 regsize=4096\n[00018.115] 02851.02883> ahci: using MSI interrupt\n[00018.115] 02990.03027> eth: using MSI mode\n[00018.116] 02990.03027> eth: mac: d4:5d:df:1a:42:46\n[00018.116] 02990.03027> eth: iomem @0x6fb9b81cf000 (phys ed6000)\n[00018.116] 02990.03027> eth: intel-ethernet online\n[00018.117] 02577.03301> * found USB device (0x18d1:0xa002, USB 2.0) config 1\n[00018.125] 02577.03301> * found USB device (0x18d1:0xa003, USB 3.0) config 1\n[00018.125] 02924.02955> [IHDA DSP 00:1f.3] Failed to fetch NHLT (res -25)\n[00018.125] 02924.02955> devhost[00:1f.3/intel-hda-000/intel-sst-dsp-000] bind driver '/boot/driver/dsp.so' failed: -25\n[00018.125] 01048.01051> devcoord: rpc: bind-driver 'intel-sst-dsp-000' status -25\n[00018.338] 02531.03565> i915: MST not supported\n[00018.801] 02531.03565> i915: Found DP monitor\n[00018.801] 02531.03565> i915: Display 1 connected\n[00018.837] 02577.03301> * found USB device (0x0781:0x5583, USB 3.0) config 1\n[00018.838] 02577.02648> UMS:Max lun is: 0\n[00019.364] 01354.01424> vc: Successfully attached to display 1\n[00019.364] 01354.01424> vc: new input device /dev/class/input/000\n[00019.591] 02577.03301> * found USB device (0x046d:0xc31c, USB 1.10) config 1\n[00019.594] 01354.01424> vc: new input device /dev/class/input/001\n[00019.599] 01354.01424> vc: new input device /dev/class/input/002\n[00019.838] 02577.03301> * found USB device (0x0cf3:0xe300, USB 2.1) config 1\n[00019.839] 02577.02648> devhost[00:14.0/xhci/usb/003/ifc-001] bind driver '/boot/driver/bt-transport-usb.so' failed: -2\n[00019.839] 01048.01051> devcoord: rpc: bind-driver 'ifc-001' status -2\n[00019.841] 02577.03643> UMS: block size is: 0x00000200\n[00019.841] 02577.03643> UMS: total blocks is: 30031250\n[00019.841] 02577.03643> UMS: total size is: 15376000000\n[00019.841] 02577.03643> UMS: read-only: 0 removable: 1\n[00019.842] 01130.01144> devmgr: /dev/class/block/000: MBR?\n[00019.842] 01048.01051> devcoord: dc_bind_device() '/boot/driver/mbr.so'\n[00019.844] 01130.01144> devmgr: /dev/class/block/002: MBR?\n[00019.844] 01048.01051> devcoord: dc_bind_device() '/boot/driver/mbr.so'\n[00020.114] 02767.02815> i2c-hid: could not read HID descriptor: -21\n[00020.114] 02767.02815> devhost[00:15.1/i2c-bus-9d61/004c] bind driver '/boot/driver/i2c-hid.so' failed: -2\n[00020.114] 01048.01051> devcoord: rpc: bind-driver '004c' status -2\n[00020.115] 02685.02733> i2c-hid: could not read HID descriptor: -21\n[00020.115] 02685.02733> devhost[00:15.0/i2c-bus-9d60/0020] bind driver '/boot/driver/i2c-hid.so' failed: -2\n[00020.115] 01048.01051> devcoord: rpc: bind-driver '0020' status -2\n[00020.120] 02851.03296> sata2: dev info\n[00020.120] 02851.03296> serial=711430952084 9 \n[00020.120] 02851.03296> firmware rev=1Q01A7 0\n[00020.120] 02851.03296> model id=IBIW NSS D \n[00020.120] 02851.03296> major=0x3f0 ACS2 DMA 32 commands\n[00020.120] 02851.03296> LBA48 234441648 sectors, sector size=512\n[00020.121] 01130.01144> devmgr: /dev/class/block/003: GPT?\n[00020.121] 01048.01051> devcoord: dc_bind_device() '/boot/driver/gpt.so'\n[00020.122] 02851.04263> gpt: entries crc invalid\n[00020.180] 04211.04225> 1024+0 records in\n[00020.180] 04211.04225> 1024+0 records out\n[00020.180] 04211.04225> 4194304 bytes copied\n[00020.181] 05320.05334> netifc: ? /dev/class/ethernet/000\n[00020.181] 05320.05334> netifc: create 512 eth buffers\n[00020.181] 05320.05334> macaddr: d4:5d:df:1a:42:46\n[00020.181] 05320.05334> ip6addr: fe80::d65d:df4d:fe1a:4246\n[00020.181] 05320.05334> snmaddr: ff02::1:ff1a:4246\n[00020.181] 05320.05334> netsvc: using /dev/class/ethernet/000\n[00020.181] 05320.05334> _ _ _ \n[00020.181] 05320.05334> | | | | | \n[00020.181] 05320.05334> _______ __| | |__ ___ ___ | |_ \n[00020.181] 05320.05334> |_ / _ \\/ _` | '_ \\ / _ \\ / _ \\| __|\n[00020.181] 05320.05334> / / __/ (_| | |_) | (_) | (_) | |_ \n[00020.181] 05320.05334> /___\\___|\\__,_|_.__/ \\___/ \\___/ \\__|\n[00020.181] 05320.05334> \n[00020.181] 05320.05334> \n[00020.181] 05320.05334> zedboot: version: 0.7.10\n[00020.181] 05320.05334> \n[00020.181] 05320.05334> netsvc: nodename='ocean-drank-wick-spot'\n[00020.181] 05320.05334> netsvc: will not advertise\n[00020.181] 05320.05334> netsvc: start\n[01273.434] 05320.05334> netsvc: tftp write of file <<netboot>>cmdline completed\n[01273.434] 05320.05334> netsvc: Running FVM Paver\n[01273.436] 05320.05427> install-disk-image:[InitializeGpt] Located GPT is invalid; Attempting to initialize\n[01273.437] 01048.01051> devcoord: dc_bind_device() '/boot/driver/gpt.so'\n[01273.438] 05320.05427> install-disk-image:[Initialize] Successfully intitialized EFI Device Partitioner\n[01273.438] 05320.05427> install-disk-image:[FvmPave] Paving FVM\n[01273.438] 05320.05427> install-disk-image:[FvmPave] Could not find FVM; attempting to add it: ZX_ERR_NOT_FOUND\n[01273.438] 05320.05427> install-disk-image:[FindFirstFit] Looking for space\n[01273.438] 05320.05427> install-disk-image:[FindFirstFit] Sorting\n[01273.438] 05320.05427> install-disk-image:[FindFirstFit] Partition[0] From Block [0, 34) ... (next partition starts at block 234441614)\n[01273.438] 05320.05427> install-disk-image:[FindFirstFit] There are 234441580 free blocks (16777216 requested)\n[01273.438] 05320.05427> install-disk-image:[AddPartition] Found space in GPT - OK 234441580 @ 34\n[01273.438] 05320.05427> install-disk-image:[AddPartition] Final space in GPT - OK 16777216 @ 34\n[01273.439] 01048.01051> devcoord: dc_bind_device() ''\n[01273.439] 05320.05427> install-disk-image:[AddPartition] Added partition, waiting for bind\n[01273.439] 01130.01144> devmgr: /dev/class/block/003: GPT?\n[01273.439] 01048.01051> devcoord: dc_bind_device() '/boot/driver/gpt.so'\n[01273.440] 05320.05427> install-disk-image:[AddPartition] Added partition, waiting for bind - OK\n[01273.440] 05320.05427> install-disk-image:[FvmPave] Streaming partitions...\n[01273.440] 05407.05421> Found compressed file\n[01273.440] 05320.05427> install-disk-image:[FvmStreamPartitions] Header Validated - OK\n[01273.441] 05320.05427> install-disk-image:[FvmPartitionFormat] Initializing partition as FVM\n[01273.443] 01048.01051> devcoord: dc_bind_device() '/boot/driver/fvm.so'\n[01275.241] 05320.05334> netsvc: tftp write of file <<image>>sparse.fvm completed\n[01275.445] 05320.05427> install-disk-image:[FvmStreamPartitions] Allocating partition blobfs consisting of 1 slices\n[01275.446] 05320.05427> install-disk-image:[FvmStreamPartitions] Extending partition[0] at offset 64 by length 1\n[01275.447] 05320.05427> install-disk-image:[FvmStreamPartitions] Extending partition[0] at offset 128 by length 1\n[01275.447] 05320.05427> install-disk-image:[FvmStreamPartitions] Extending partition[0] at offset 192 by length 1\n[01275.448] 05320.05427> install-disk-image:[FvmStreamPartitions] Extending partition[0] at offset 256 by length 23\n2019/02/12 08:50:03 attempting to send <<image>>efi.img...\n2019/02/12 08:50:03 target is busy, retrying in one second\n[01277.448] 05320.05427> install-disk-image:[FvmStreamPartitions] Allocating partition minfs consisting of 1 slices\n[01277.450] 01130.01144> devmgr: /dev/class/block/006: zxcrypt?\n[01277.450] 01048.01051> devcoord: dc_bind_device() '/boot/driver/zxcrypt.so'\n[01277.450] 05320.05427> install-disk-image:[FvmStreamPartitions] Creating zxcrypt volume\n[01277.451] 02851.02883> devhost_get_handles(0x2b3dcc5b89c0:block) open path='zxcrypt/block', r=-2\n[01277.451] 01048.01051> devcoord: dc_bind_device() '/boot/driver/zxcrypt.so'\n[01277.451] 02851.02883> devhost_get_handles(0x2b3dcc5b89c0:block) open path='zxcrypt', r=-2\n[01277.452] 05320.05427> install-disk-image:[FvmStreamPartitions] Extending partition[1] at offset 64 by length 1\n[01277.453] 05320.05427> install-disk-image:[FvmStreamPartitions] Extending partition[1] at offset 128 by length 1\n[01277.454] 05320.05427> install-disk-image:[FvmStreamPartitions] Extending partition[1] at offset 192 by length 1\n[01277.454] 05320.05427> install-disk-image:[FvmStreamPartitions] Extending partition[1] at offset 256 by length 2\n[01277.455] 05320.05427> install-disk-image:[FvmStreamPartitions] Extending partition[1] at offset 320 by length 1\n[01277.455] 05320.05427> install-disk-image:[FvmStreamPartitions] Partition space pre-allocated\n[01277.455] 05320.05427> install-disk-image:[FvmStreamPartitions] Streaming partition 0\n[01277.455] 05320.05427> install-disk-image:[StreamFvmPartition] Writing extent 0... \n[01277.455] 05320.05433> netsvc: paver write progress 0.1%\n[01277.455] 05320.05427> install-disk-image:[StreamFvmPartition] 8192 bytes written, 8380416 zeroes left\n[01277.479] 05320.05427> install-disk-image:[StreamFvmPartition] Writing extent 1... \n[01277.480] 05320.05427> install-disk-image:[StreamFvmPartition] 8192 bytes written, 8380416 zeroes left\n[01277.496] 05320.05427> install-disk-image:[StreamFvmPartition] Writing extent 2... \n[01277.501] 05320.05427> install-disk-image:[StreamFvmPartition] 2097152 bytes written, 6291456 zeroes left\n[01277.514] 05320.05427> install-disk-image:[StreamFvmPartition] Writing extent 3... \n[01277.521] 05320.05427> install-disk-image:[StreamFvmPartition] 2097152 bytes written, 6291456 zeroes left\n[01277.534] 05320.05427> install-disk-image:[StreamFvmPartition] Writing extent 4... \n[01278.005] 05320.05427> install-disk-image:[StreamFvmPartition] 190906368 bytes written, 2031616 zeroes left\n[01278.009] 05320.05427> install-disk-image:[FvmStreamPartitions] Done streaming partition 0\n[01278.009] 05320.05427> install-disk-image:[FvmStreamPartitions] Done flushing partition 0\n[01278.009] 05320.05427> install-disk-image:[FvmStreamPartitions] Streaming partition 1\n[01278.009] 05320.05427> install-disk-image:[StreamFvmPartition] Writing extent 0... \n[01278.009] 05320.05427> install-disk-image:[StreamFvmPartition] 8192 bytes written, 8380416 zeroes left\n[01278.048] 05320.05427> install-disk-image:[StreamFvmPartition] Writing extent 1... \n[01278.048] 05320.05427> install-disk-image:[StreamFvmPartition] 65536 bytes written, 8323072 zeroes left\n[01278.091] 05320.05427> install-disk-image:[StreamFvmPartition] Writing extent 2... \n[01278.091] 05320.05427> install-disk-image:[StreamFvmPartition] 65536 bytes written, 8323072 zeroes left\n[01278.127] 05320.05427> install-disk-image:[StreamFvmPartition] Writing extent 3... \n2019/02/12 08:50:04 attempting to send <<image>>efi.img...\n2019/02/12 08:50:04 target is busy, retrying in one second\n[01278.165] 05320.05427> install-disk-image:[StreamFvmPartition] Writing extent 4... \n[01278.175] 05320.05427> install-disk-image:[StreamFvmPartition] 2097152 bytes written, 14680064 zeroes left\n[01278.240] 05320.05427> install-disk-image:[StreamFvmPartition] Writing extent 5... \n[01278.240] 05320.05427> install-disk-image:[StreamFvmPartition] 57344 bytes written, 8331264 zeroes left\n[01278.279] 05320.05427> install-disk-image:[FvmStreamPartitions] Done streaming partition 1\n[01278.279] 05320.05427> install-disk-image:[FvmStreamPartitions] Done flushing partition 1\n[01278.280] 05407.05421> Reading FVM from compressed file: true\n[01278.280] 05407.05421> Remaining bytes read into compression buffer: 0\n[01278.280] 05407.05421> Remaining bytes written to decompression buffer: 0\n[01278.280] 05407.05421> Time reading bytes from sparse FVM file: 91825108 (0 s)\n[01278.280] 05407.05421> Time reading bytes AND decompressing them: 199120495 (0 s)\n[01278.280] 05320.05427> install-disk-image:[FvmPave] Completed successfully\n2019/02/12 08:50:05 attempting to send <<image>>efi.img...\n[01279.243] 05320.05334> netsvc: Running EFI Paver\n[01279.246] 05320.06187> install-disk-image:[Initialize] Successfully intitialized EFI Device Partitioner\n[01279.246] 05320.06187> install-disk-image:[PartitionPave] Paving partition.\n[01279.246] 05320.06187> install-disk-image:[FindFirstFit] Looking for space\n[01279.246] 05320.06187> install-disk-image:[FindFirstFit] Partition seen with start 34, end 16777249 (length 16777216)\n[01279.246] 05320.06187> install-disk-image:[FindFirstFit] Sorting\n[01279.246] 05320.06187> install-disk-image:[FindFirstFit] Partition[0] From Block [0, 34) ... (next partition starts at block 34)\n[01279.246] 05320.06187> install-disk-image:[FindFirstFit] There are 0 free blocks (2097152 requested)\n[01279.246] 05320.06187> install-disk-image:[FindFirstFit] Partition[1] From Block [34, 16777250) ... (next partition starts at block 234441614)\n[01279.246] 05320.06187> install-disk-image:[FindFirstFit] There are 217664364 free blocks (2097152 requested)\n[01279.246] 05320.06187> install-disk-image:[AddPartition] Found space in GPT - OK 217664364 @ 16777250\n[01279.246] 05320.06187> install-disk-image:[AddPartition] Final space in GPT - OK 2097152 @ 16777250\n[01279.247] 01048.01051> devcoord: dc_bind_device() ''\n[01279.247] 05320.06187> install-disk-image:[AddPartition] Added partition, waiting for bind\n[01279.248] 01130.01144> devmgr: /dev/class/block/003: GPT?\n[01279.248] 01048.01051> devcoord: dc_bind_device() '/boot/driver/gpt.so'\n[01279.249] 01130.01144> devmgr: /dev/class/block/008: FVM?\n[01279.249] 01048.01051> devcoord: dc_bind_device() '/boot/driver/fvm.so'\n[01279.249] 05320.06187> install-disk-image:[AddPartition] Added partition, waiting for bind - OK\n[01279.252] 01130.01144> devmgr: /dev/class/block/011: zxcrypt?\n[01279.252] 01048.01051> devcoord: dc_bind_device() '/boot/driver/zxcrypt.so'\n2019/02/12 08:50:05 done\n2019/02/12 08:50:05 attempting to send <<image>>kernc.img...\n2019/02/12 08:50:05 target is busy, retrying in one second\n[01279.262] 05320.05334> netsvc: tftp write of file <<image>>efi.img completed\n[01279.265] 05320.06187> install-disk-image:[PartitionPave] Completed successfully\n2019/02/12 08:50:06 attempting to send <<image>>kernc.img...\n[01280.263] 05320.05334> netsvc: Running KERN-C Paver\n[01280.267] 05320.06489> install-disk-image:[Initialize] Successfully intitialized EFI Device Partitioner\n[01280.267] 05320.06489> install-disk-image:[RealMain] SKIPPING KERNC install on non-CROS device, pass --force if desired.\n2019/02/12 08:50:06 done\n2019/02/12 08:50:06 attempting to send <<image>>zircona.img...\n2019/02/12 08:50:06 target is busy, retrying in one second\n[01280.369] 05320.05334> netsvc: tftp write of file <<image>>kernc.img completed\n2019/02/12 08:50:07 attempting to send <<image>>zircona.img...\n[01281.370] 05320.05334> netsvc: Running ZIRCON-A Paver\n[01281.374] 05320.06626> install-disk-image:[Initialize] Successfully intitialized EFI Device Partitioner\n[01281.374] 05320.06626> install-disk-image:[RealMain] SKIPPING ZIRCON-A install on x64 device, pass --force if desired.\n2019/02/12 08:50:07 done\n2019/02/12 08:50:07 attempting to send <<image>>zirconr.img...\n2019/02/12 08:50:07 target is busy, retrying in one second\n[01281.468] 05320.05334> netsvc: tftp write of file <<image>>zircona.img completed\n2019/02/12 08:50:08 attempting to send <<image>>zirconr.img...\n[01282.468] 05320.05334> netsvc: Running ZIRCON-R Paver\n[01282.472] 05320.06763> install-disk-image:[Initialize] Successfully intitialized EFI Device Partitioner\n[01282.472] 05320.06763> install-disk-image:[RealMain] SKIPPING ZIRCON-R install on x64 device, pass --force if desired.\n2019/02/12 08:50:08 done\n2019/02/12 08:50:08 attempting to send <<netboot>>kernel.bin...\n2019/02/12 08:50:08 target is busy, retrying in one second\n[01282.565] 05320.05334> netsvc: tftp write of file <<image>>zirconr.img completed\n2019/02/12 08:50:09 attempting to send <<netboot>>kernel.bin...\n2019/02/12 08:50:09 done\n[00000.000] 00000.00000> zbi: @ 0xffffff80059cf000 (6789208 bytes)\n[00000.000] 00000.00000> PMM: boot reserve add [0x100000, 0x2c9fff]\n[00000.000] 00000.00000> PMM: boot reserve add [0x59cf000, 0x6048fff]\n[00000.000] 00000.00000> PMM: arena too small to be useful (size 4096)\n[00000.000] 00000.00000> PMM: pmm_add_arena failed to initialize arena\n[00000.000] 00000.00000> MEM: Failed to add pmm range at 0x7ffff000 size 0x1000\n[00000.000] 00000.00000> PMM: boot reserve marking WIRED [0x100000, 0x2c9fff]\n[00000.000] 00000.00000> PMM: boot reserve marking WIRED [0x59cf000, 0x6048fff]\n[00000.000] 00000.00000> \n[00000.000] 00000.00000> welcome to Zircon\n[00000.000] 00000.00000> \n[00000.000] 00000.00000> KASLR: .text section at 0xffffffff00100000\n[00000.000] 00000.00000> INIT: cpu 0, calling hook 0xffffffff001ab28c (global_prng_seed) at level 0x30000, flags 0x1\n[00000.000] 00000.00000> initializing vm pre-heap\n[00000.000] 00000.00000> VM: marking boot alloc used range [0x6049000, 0x6049100)\n[00000.000] 00000.00000> INIT: cpu 0, calling hook 0xffffffff0014a140 (elf_build_id) at level 0x4fffe, flags 0x1\n[00000.000] 00000.00000> INIT: cpu 0, calling hook 0xffffffff0014a2cc (version) at level 0x4ffff, flags 0x1\n[00000.000] 00000.00000> version:\n[00000.000] 00000.00000> \tarch: x86\n[00000.000] 00000.00000> \tplatform: pc\n[00000.000] 00000.00000> \ttarget: pc\n[00000.000] 00000.00000> \tproject: x64\n[00000.000] 00000.00000> \tbuildid: git-66632b640a92fa2baaadc44b521dfc84c5044995-dirty\n[00000.000] 00000.00000> \tELF build ID: 03c7f19a53a12a3b0d810e9482871233f1062beb\n[00000.000] 00000.00000> initializing heap\n[00000.000] 00000.00000> INIT: cpu 0, calling hook 0xffffffff00102e1c (x86_resource_init) at level 0x50000, flags 0x1\n[00000.000] 00000.00000> INIT: cpu 0, calling hook 0xffffffff001aa494 (console) at level 0x50000, flags 0x1\n[00000.000] 00000.00000> initializing vm\n[00000.000] 00000.00000> VM: reserving kernel region [0xffffffff00100000, 0xffffffff001ef000) flags 0x28 name 'kernel_code'\n[00000.000] 00000.00000> VM: reserving kernel region [0xffffffff001ef000, 0xffffffff00234000) flags 0x8 name 'kernel_rodata'\n[00000.000] 00000.00000> VM: reserving kernel region [0xffffffff00234000, 0xffffffff00244000) flags 0x18 name 'kernel_data'\n[00000.000] 00000.00000> VM: reserving kernel region [0xffffffff00244000, 0xffffffff002ca000) flags 0x18 name 'kernel_bss'\n[00000.000] 00000.00000> INIT: cpu 0, calling hook 0xffffffff00103ae0 (display_memtype) at level 0x60001, flags 0x1\n[00000.000] 00000.00000> INIT: cpu 0, calling hook 0xffffffff00138f30 (acpi_tables) at level 0x60001, flags 0x1\n[00000.000] 00000.00000> INIT: cpu 0, calling hook 0xffffffff00101c40 (hpet) at level 0x60002, flags 0x1\n[00000.000] 00000.00000> INIT: cpu 0, calling hook 0xffffffff00102000 (apic) at level 0x60002, flags 0x1\n[00000.000] 00000.00000> x2APIC enabled\n[00000.000] 00000.00000> INIT: cpu 0, calling hook 0xffffffff001061b4 (timer) at level 0x60003, flags 0x1\n[00000.000] 00000.00000> HPET frequency: 23999 ticks/ms\n[00000.000] 00000.00000> TSC frequency: 2712000 ticks/ms\n[01283.916] 00000.00000> timer features: constant_tsc 1 invariant_tsc 1 tsc_deadline 1\n[01283.916] 00000.00000> Using TSC as wallclock\n[01283.916] 00000.00000> initializing kernel\n[01283.916] 00000.00000> initializing mp\n[01283.916] 00000.00000> initializing timers\n[01283.916] 00000.00000> INIT: cpu 0, calling hook 0xffffffff0013eb68 (debuglog) at level 0x7ffff, flags 0x1\n[01283.916] 00000.00000> INIT: cpu 0, calling hook 0xffffffff00198904 (thread_set_priority_experiment) at level 0x7ffff, flags 0x1\n[01283.916] 00000.00000> thread set priority experiment is : ENABLED\n[01283.916] 00000.00000> INIT: cpu 0, calling hook 0xffffffff001ab4e0 (global_prng_thread_safe) at level 0x7ffff, flags 0x1\n[01283.916] 00000.00000> creating bootstrap completion thread\n[01283.916] 00000.00000> top of bootstrap2()\n[01283.916] 00000.00000> INIT: cpu 0, calling hook 0xffffffff001314ac (dpc) at level 0x80000, flags 0x1\n[01283.916] 00000.00000> INIT: cpu 0, calling hook 0xffffffff00155330 (libobject) at level 0x80000, flags 0x1\n[01283.916] 00000.00000> OOM: started thread\n[01283.916] 00000.00000> Processor Model Info: type 0 family 0x6 model 0xe stepping 0x9\n[01283.916] 00000.00000> \tdisplay_family 0x6 display_model 0x8e\n[01283.916] 00000.00000> Vendor: Intel\n[01283.916] 00000.00000> Microarch: Kaby Lake\n[01283.916] 00000.00000> F/M/S: 6/8e/9\n[01283.916] 00000.00000> Brand: Intel(R) Core(TM) i5-7300U CPU @ 2.60GHz\n[01283.916] 00000.00000> Features: fpu sse sse2 sse3 ssse3 sse4.1 sse4.2 mmx avx avx2 fxsr pcid xsave mon aesni clflush \n[01283.916] 00000.00000> clflushopt fsgsbase tsc_adj smep smap erms rdrand rdseed syscall nx huge rdtscp \n[01283.916] 00000.00000> invar_tsc tsc_deadline x2apic vmx pt hwp \n[01283.916] 00000.00000> initializing platform\n[01283.916] 00000.00000> INIT: cpu 0, calling hook 0xffffffff00110180 (x86_perfmon) at level 0x90000, flags 0x1\n[01283.916] 00000.00000> PMU: version 4\n[01283.916] 00000.00000> cpu topology:\n[01283.916] 00000.00000> \t0: apic id 0x0 package 0 node 0 core 0 smt 0 BSP\n[01283.916] 00000.00000> \t1: apic id 0x2 package 0 node 0 core 1 smt 0\n[01283.916] 00000.00000> \t2: apic id 0x1 package 0 node 0 core 0 smt 1\n[01283.916] 00000.00000> \t3: apic id 0x3 package 0 node 0 core 1 smt 1\n[01283.916] 00000.00000> Found 4 cpus\n[01283.916] 00000.00000> booting apic ids: 0x2 0x1 0x3 \n[01283.931] 00000.00000> entering scheduler on cpu 2\n[01283.933] 00000.00000> entering scheduler on cpu 3\n[01283.933] 00000.00000> entering scheduler on cpu 1\n[01283.935] 00000.00000> smbios: manufacturer=\"Intel Corporation\" product=\"NUC7i5DNHE\"\n[01283.935] 00000.00000> initializing target\n[01283.935] 00000.00000> INIT: cpu 0, calling hook 0xffffffff001053a0 (x86_pcie_init) at level 0xa0000, flags 0x1\n[01283.935] 00000.00000> moving to last init level\n[01283.935] 00000.00000> INIT: cpu 0, calling hook 0xffffffff00146730 (ktrace) at level 0xc0000, flags 0x1\n[01283.938] 00000.00000> ktrace: buffer at 0xffffff9da707c000 (33554432 bytes)\n[01283.938] 00000.00000> INIT: cpu 0, calling hook 0xffffffff0014a138 (userboot) at level 0xc0000, flags 0x1\n[01283.938] 00000.00000> userboot: ramdisk 0x67a000 @ 0xffffff80059cf000\n[01283.939] 00000.00000> userboot: userboot rodata 0 @ [0x56c23f93f000,0x56c23f942000)\n[01283.939] 00000.00000> userboot: userboot code 0x3000 @ [0x56c23f942000,0x56c23f94d000)\n[01283.939] 00000.00000> userboot: vdso/full rodata 0 @ [0x56c23f94d000,0x56c23f954000)\n[01283.939] 00000.00000> userboot: vdso/full code 0x7000 @ [0x56c23f954000,0x56c23f955000)\n[01283.939] 00000.00000> userboot: entry point @ 0x56c23f942c10\n[01283.939] 00000.00000> INIT: cpu 0, calling hook 0xffffffff001aae94 (kernel_shell) at level 0xc0000, flags 0x1\n[01283.939] 01036.01043> userboot: option \"zircon.autorun.system=/boot/bin/sh+/boot/infra/runcmds\"\n[01283.954] 01036.01043> userboot: searching bootfs for 'bin/bootsvc'\n[01283.954] 01036.01043> userboot: 'bin/bootsvc' has PT_INTERP \"lib/ld.so.1\"\n[01283.954] 01036.01043> userboot: searching bootfs for 'lib/ld.so.1'\n[01283.954] 01036.01043> userboot: userboot: loaded lib/ld.so.1 at 0x67944304d000, entry point 0x6794430d2ed3\n[01283.954] 01036.01043> userboot: userboot: loaded vDSO at 0x472aff1d0000, entry point 0x0\n[01283.954] 01036.01043> userboot: process bin/bootsvc started.\n[01283.954] 01036.01043> userboot: waiting for loader-service requests...\n[01283.954] 01036.01043> userboot: searching bootfs for 'lib/libasync-default.so'\n[01283.954] 01036.01043> userboot: searching bootfs for 'lib/libfdio.so'\n[01283.954] 01036.01043> userboot: searching bootfs for 'lib/liblaunchpad.so'\n[01283.954] 01036.01043> userboot: searching bootfs for 'lib/libtrace-engine.so'\n[01283.954] 01050.01053> {{{reset}}}\n[01283.954] 01050.01053> {{{module:0:<application>:elf:ff40cb107e4e270d34f8b9a81e77cbe62fead8e3}}}\n[01283.954] 01050.01053> {{{mmap:0x1ae9de2e7000:0x2e000:load:0:rx:0}}}\n[01283.954] 01050.01053> {{{mmap:0x1ae9de315000:0x4000:load:0:rw:0x2e000}}}\n[01283.954] 01050.01053> dso: id=ff40cb107e4e270d34f8b9a81e77cbe62fead8e3 base=0x00001ae9de2e7000 name=<application>\n[01283.954] 01050.01053> {{{module:0x3:libasync-default.so:elf:10281b26e8f274e0f9b174380cea42e4f723a6d4}}}\n[01283.954] 01050.01053> {{{mmap:0x23167dba5000:0x1000:load:0x3:rx:0}}}\n[01283.954] 01050.01053> {{{mmap:0x23167dba6000:0x1000:load:0x3:rw:0x1000}}}\n[01283.954] 01050.01053> dso: id=10281b26e8f274e0f9b174380cea42e4f723a6d4 base=0x000023167dba5000 name=libasync-default.so\n[01283.954] 01050.01053> {{{module:0x2:<vDSO>:elf:4cee38a00d11cadeaf384d656500ac174da0908b}}}\n[01283.954] 01050.01053> {{{mmap:0x472aff1d0000:0x7000:load:0x2:r:0}}}\n[01283.954] 01050.01053> {{{mmap:0x472aff1d7000:0x1000:load:0x2:rx:0x7000}}}\n[01283.954] 01050.01053> dso: id=4cee38a00d11cadeaf384d656500ac174da0908b base=0x0000472aff1d0000 name=<vDSO>\n[01283.954] 01050.01053> {{{module:0x1:libc.so:elf:8037f5a57d48c49ce05a4febaddab982d33aa5af}}}\n[01283.954] 01050.01053> {{{mmap:0x67944304d000:0xcb000:load:0x1:rx:0}}}\n[01283.954] 01050.01053> {{{mmap:0x679443119000:0x6000:load:0x1:rw:0xcc000}}}\n[01283.954] 01050.01053> dso: id=8037f5a57d48c49ce05a4febaddab982d33aa5af base=0x000067944304d000 name=libc.so\n[01283.954] 01050.01053> {{{module:0x4:libfdio.so:elf:b895fe15d3cc77b75d0d5147f2e003ae3dc96d6e}}}\n[01283.954] 01050.01053> {{{mmap:0x5fbf5f611000:0x31000:load:0x4:rx:0}}}\n[01283.954] 01050.01053> {{{mmap:0x5fbf5f643000:0x4000:load:0x4:rw:0x32000}}}\n[01283.954] 01050.01053> dso: id=b895fe15d3cc77b75d0d5147f2e003ae3dc96d6e base=0x00005fbf5f611000 name=libfdio.so\n[01283.954] 01050.01053> {{{module:0x5:liblaunchpad.so:elf:a7b33c058b4c1307694eaa6c6609da5f2c84bf23}}}\n[01283.954] 01050.01053> {{{mmap:0x15dd06f11000:0x7000:load:0x5:rx:0}}}\n[01283.954] 01050.01053> {{{mmap:0x15dd06f18000:0x2000:load:0x5:rw:0x7000}}}\n[01283.954] 01050.01053> dso: id=a7b33c058b4c1307694eaa6c6609da5f2c84bf23 base=0x000015dd06f11000 name=liblaunchpad.so\n[01283.954] 01050.01053> {{{module:0x6:libtrace-engine.so:elf:5722f5eefe103de398f23445f8cedd9d7720f4b5}}}\n[01283.954] 01050.01053> {{{mmap:0x31fcaee4c000:0x9000:load:0x6:rx:0}}}\n[01283.954] 01050.01053> {{{mmap:0x31fcaee55000:0x2000:load:0x6:rw:0x9000}}}\n[01283.954] 01050.01053> dso: id=5722f5eefe103de398f23445f8cedd9d7720f4b5 base=0x000031fcaee4c000 name=libtrace-engine.so\n[01283.955] 01050.01053> bootsvc: Starting...\n[01283.955] 01036.01043> userboot: loader-service channel peer closed\n[01283.955] 01036.01043> userboot: finished!\n[01283.955] 01050.01053> bootsvc: Creating bootfs service...\n[01283.955] 01050.01053> bootsvc: Processing bootdata...\n[01283.955] 01050.01053> bootsvc: Loading boot cmdline overrides...\n[01283.955] 01050.01053> bootsvc: Loading kernel VMOs...\n[01283.955] 01050.01053> bootsvc: Creating loader service...\n[01283.955] 01050.01053> bootsvc: Launching next process...\n[01283.955] 01050.01097> bootsvc: launched bin/devmgr\n[01283.956] 01105.01118> devmgr: main()\n[01283.956] 01105.01118> cmdline: zircon.autorun.system=/boot/bin/sh+/boot/infra/runcmds\n[01283.956] 01105.01118> cmdline: devhost.asan.strict=false\n[01283.956] 01105.01118> cmdline: devmgr.require-system=true\n[01283.956] 01105.01118> cmdline: zircon.system.pkgfs.cmd=bin/pkgsvr+3d4f97f8f154ef43bac98715fe9df39af66da7bd8dd3921adad3a8bc9af32210\n[01283.956] 01105.01118> cmdline: zircon.system.pkgfs.file.bin/amber=b0cacf77133592d92534f15415b71a82a07ea626aa2ccd351f5e5a6df16dc182\n[01283.956] 01105.01118> cmdline: zircon.system.pkgfs.file.bin/pkgsvr=b0cacf77133592d92534f15415b71a82a07ea626aa2ccd351f5e5a6df16dc182\n[01283.956] 01105.01118> cmdline: zircon.system.pkgfs.file.bin/system_updater=b0cacf77133592d92534f15415b71a82a07ea626aa2ccd351f5e5a6df16dc182\n[01283.956] 01105.01118> cmdline: zircon.system.pkgfs.file.data/cobalt_config.pb=54e36f77a6bdfabb07777ea4cefb134b925c5a9cb5e7a0eab9c8d884820f2283\n[01283.956] 01105.01118> cmdline: zircon.system.pkgfs.file.data/images=c37e47d9e001f09cc6011aa7ba954271c83f06dd8b9c73a6f7a0cfaebc8d4fd9\n[01283.956] 01105.01118> cmdline: zircon.system.pkgfs.file.data/keys=e1c910214f22ddecf06fc8ea9b2fe274120c3962ae5ab590def2223734835557\n[01283.956] 01105.01118> cmdline: zircon.system.pkgfs.file.lib/ld.so.1=b3cd7c247d53a50f96637210cafd2fc3410df9374415df6c9fe27a3e2335bae8\n[01283.956] 01105.01118> cmdline: zircon.system.pkgfs.file.lib/libfdio.so=d87c185ac73da1c1e66c0db3003fd8ae06b0b18b42d9b5fe088458278bf36501\n[01283.956] 01105.01118> devmgr: coordinator_init()\n[01283.956] 01105.01118> devmgr: init\n[01283.956] 01105.01118> devmgr: svc init\n[01283.956] 01105.01118> devmgr: launch /boot/bin/svchost (svchost) OK\n[01283.956] 01105.01118> devmgr: vfs init\n[01283.956] 01105.01118> devmgr: launch /boot/bin/fshost (fshost) OK\n[01283.956] 01105.01223> devmgr: shell startup\n[01283.958] 01183.01203> fshost: started.\n[01283.958] 01105.01214> devmgr: launch /boot/bin/pwrbtn-monitor (pwrbtn-monitor) OK\n[01283.959] 01105.01235> devmgr: launch /boot/bin/netsvc (netsvc) OK\n[01283.959] 01105.01235> devmgr: launch /boot/bin/virtual-console (virtual-console) OK\n[01283.961] 01105.01118> devcoord: full system required, ignoring fallback drivers until /system is loaded\n[01283.962] 01105.01118> devcoord: launch devhost 'devhost:sys': pid=2029\n[01283.962] 01105.01118> devcoord: launch devhost 'devhost:test': pid=2062\n[01283.962] 01105.01118> devcoord: launch devhost 'devhost:root': pid=2099\n[01283.962] 01105.01118> devcoord: launch devhost 'devhost:misc': pid=2148\n[01283.963] 02029.02053> devhost: trace provider registry begun\n[01283.964] 02062.02088> devhost: trace provider registry begun\n[01283.965] 02099.02134> devhost: trace provider registry begun\n[01283.965] 02029.02053> GetZbiMetadata metadata not found for type 524f426d, extra 0\n[01283.965] 02148.02194> devhost: trace provider registry begun\n[01283.966] 01105.01223> devmgr: launch /boot/bin/sh (sh:console) OK\n[01284.021] 02029.02053> acpi-bus: not using IOMMU\n[01284.025] 02029.02053> PMU: 7 arch events\n[01284.025] 02029.02053> PMU: arch event id range: 1-7\n[01284.025] 02029.02053> PMU: 102 model events\n[01284.025] 02029.02053> PMU: model event id range: 1-241\n[01284.025] 02029.02053> Intel Processor Trace configuration for this chipset:\n[01284.025] 02029.02053> mtc_freq_mask: 0x249\n[01284.025] 02029.02053> cyc_thresh_mask: 0x3fff\n[01284.025] 02029.02053> psb_freq_mask: 0x3f\n[01284.025] 02029.02053> num addr ranges: 2\n[01284.025] 02029.02053> [sysmem_init 28] async_get_default_dispatcher(): 0x770dfea710a0\n[01284.025] 02029.02053> [sysmem_bind 40] sysmem_bind()\n[01284.026] 02029.02673> acpi-pwrbtn: initialized\n[01284.026] 01598.01680> vc: new input device /dev/class/input/000\n[01284.032] 02029.02673> WARNING: ACPI found bad _CRS address entry\n[01284.038] 02029.02673> WARNING: ACPI found bad _CRS address entry\n[01284.049] 02029.02673> acpi: published device pci(0x7755b68ec100), parent=sys(0x770dfea7f0c0), handle=0x770dfeabb720\n[01284.049] 01105.01118> devcoord: launch devhost 'devhost:pci#1:8086:5916': pid=2750\n[01284.049] 01105.01118> devcoord: launch devhost 'devhost:pci#3:8086:9d2f': pid=2797\n[01284.050] 01105.01118> devcoord: launch devhost 'devhost:pci#5:8086:9d60': pid=2858\n[01284.050] 02750.02777> devhost: trace provider registry begun\n[01284.050] 01105.01118> devcoord: launch devhost 'devhost:pci#6:8086:9d61': pid=2926\n[01284.050] 02029.02673> acpi: published device rtc(0x7755b68ec180), parent=acpi(0x770dfea7f780), handle=0x770dfeada300\n[01284.051] 02797.02833> devhost: trace provider registry begun\n[01284.052] 01105.01118> devcoord: launch devhost 'devhost:pci#9:8086:9d03': pid=3028\n[01284.053] 02029.02673> acpi-ec: initialized\n[01284.054] 02926.02981> devhost: trace provider registry begun\n[01284.054] 01105.01118> devcoord: launch devhost 'devhost:pci#14:8086:9d71': pid=3197\n[01284.055] 02858.02895> devhost: trace provider registry begun\n[01284.055] 03028.03089> devhost: trace provider registry begun\n[01284.055] 01105.01118> devcoord: launch devhost 'devhost:pci#16:8086:156f': pid=3279\n[01284.056] 03197.03251> devhost: trace provider registry begun\n[01284.057] 02858.02895> initialized intel serialio i2c driver, reg=0x1249ab6fb000 regsize=4096\n[01284.057] 02029.02673> acpi: failed to create NHLT VMO (res -10)\n[01284.057] 02029.02673> acpi: failed to publish NHLT metadata\n[01284.057] 03279.03343> devhost: trace provider registry begun\n[01284.061] 02926.02981> initialized intel serialio i2c driver, reg=0x7897520a000 regsize=4096\n[01284.061] 03028.03089> ahci: using MSI interrupt\n[01284.063] 02797.03594> * found USB device (0x18d1:0xa002, USB 2.0) config 1\n[01284.063] 02797.03594> * found USB device (0x18d1:0xa003, USB 3.0) config 1\n[01284.063] 03197.03251> [IHDA DSP 00:1f.3] Failed to fetch NHLT (res -25)\n[01284.063] 03197.03251> devhost[00:1f.3/intel-hda-000/intel-sst-dsp-000] bind driver '/boot/driver/dsp.so' failed: -25\n[01284.063] 01105.01118> devcoord: rpc: bind-driver 'intel-sst-dsp-000' status -25\n[01284.135] 01240.01581> netifc: ? /dev/class/ethernet/000\n[01284.135] 01240.01581> netifc: create 512 eth buffers\n[01284.135] 01240.01581> macaddr: d4:5d:df:1a:42:46\n[01284.135] 01240.01581> ip6addr: fe80::d65d:df4d:fe1a:4246\n[01284.135] 01240.01581> snmaddr: ff02::1:ff1a:4246\n[01284.135] 01240.01581> netsvc: using /dev/class/ethernet/000\n[01284.135] 01240.01581> netsvc: nodename='ocean-drank-wick-spot'\n[01284.135] 01240.01581> netsvc: start\n[01284.163] 01598.01680> vc: new display device /dev/class/display-controller/000/virtcon\n[01284.204] 02750.03900> i915: MST not supported\n[01284.708] 02750.03900> i915: Found DP monitor\n[01284.708] 02750.03900> i915: Display 1 connected\n[01284.776] 02797.03594> * found USB device (0x0781:0x5583, USB 3.0) config 1\n[01285.261] 01598.01680> vc: Successfully attached to display 1\n[01285.529] 02797.03594> * found USB device (0x046d:0xc31c, USB 1.10) config 1\n[01285.776] 02797.03594> * found USB device (0x0cf3:0xe300, USB 2.1) config 1\n[01286.061] 02858.02895> intel-i2c-controller: intel_serialio_i2c_slave_transfer: -21\n[01286.061] 02858.02895> i2c-hid: could not read HID descriptor: 0\n[01286.061] 02858.02895> devhost[00:15.0/i2c-bus-9d60/0020] bind driver '/boot/driver/i2c-hid.so' failed: -2\n[01286.061] 01105.01118> devcoord: rpc: bind-driver '0020' status -2\n[01286.062] 02926.02981> intel-i2c-controller: intel_serialio_i2c_slave_transfer: -21\n[01286.062] 02926.02981> i2c-hid: could not read HID descriptor: 0\n[01286.062] 02926.02981> devhost[00:15.1/i2c-bus-9d61/004c] bind driver '/boot/driver/i2c-hid.so' failed: -2\n[01286.062] 01105.01118> devcoord: rpc: bind-driver '004c' status -2\n[01286.076] 03028.03588> sata2: dev info\n[01286.076] 03028.03588> serial=711430952084 9 \n[01286.076] 03028.03588> firmware rev=1Q01A7 0\n[01286.076] 03028.03588> model id=IBIW NSS D \n[01286.076] 03028.03588> major=0x3f0 ACS2 DMA 32 commands\n[01286.076] 03028.03588> LBA48 234441648 sectors, sector size=512\n[01286.077] 01183.01203> devmgr: /dev/class/block/000: GPT?\n[01286.077] 01105.01118> devcoord: dc_bind_device() '/boot/driver/gpt.so'\n[01286.077] 03028.03089> gpt: device_get_metadata failed (-25)\n[01286.078] 01183.01203> devmgr: /dev/class/block/001: FVM?\n[01286.078] 01105.01118> devcoord: dc_bind_device() '/boot/driver/fvm.so'\n[01286.079] 01183.01203> devmgr: not automounting efi\n[01286.081] 01183.01203> devmgr: launch /boot/bin/blobfs (blobfs:/blob) OK\n[01286.145] 01183.01203> fshost: starting 'bin/pkgsvr' '3d4f97f8f154ef43bac98715fe9df39af66da7bd8dd3921adad3a8bc9af32210'...\n[01286.236] 01183.01203> devmgr: launch bin/pkgsvr (pkgfs) OK\n[01286.247] 04244.04462> pkgsvr: system: will be served from 3d4f97f8f154ef43bac98715fe9df39af66da7bd8dd3921adad3a8bc9af32210\n[01286.247] 04244.04462> pkgsvr: pkgfs serving index /data/pkgfs_index from blobfs /blob\n[01286.247] 01183.01203> devmgr: /dev/class/block/004: zxcrypt?\n[01286.247] 01105.01118> devcoord: dc_bind_device() '/boot/driver/zxcrypt.so'\n[01286.252] 01183.01203> devmgr: mounting minfs\n[01286.252] 01183.01203> devmgr: launch /boot/bin/minfs (minfs:/data) OK\n[01286.280] 01105.04514> devmgr: adding system driver 'ath10k_pci' '/system/driver/ath10k.so'\n[01286.280] 01105.01697> devmgr: launch /system/bin/appmgr (appmgr) OK\n[01286.280] 01105.01697> zircon.autorun.system: starting '/boot/bin/sh' '/boot/infra/runcmds'...\n[01286.281] 01105.01697> devmgr: launch /boot/bin/sh (autorun:system) OK\n[01286.302] 01105.04514> devmgr: adding system driver 'bt_hci_intel' '/system/driver/bt-hci-intel.so'\n[01286.316] 01105.04514> devmgr: adding system driver 'bt_hci_fake' '/system/driver/bt-hci-fake.so'\n[01286.319] 01105.04514> devmgr: adding system driver 'bt_hog' '/system/driver/bt-hog.so'\n[01286.347] 01105.04514> devmgr: adding system driver 'bt_hci_atheros' '/system/driver/bt-hci-atheros.so'\n[01286.359] 01105.04514> devmgr: adding system driver 'gpu' '/system/driver/libmsd_intel.so'\n[01286.385] 01105.04514> devmgr: adding system driver 'bt_host' '/system/driver/bt-host.so'\n[01286.437] 01105.04514> devmgr: adding system driver 'ralink' '/system/driver/ralink.so'\n[01286.442] 01105.04514> devmgr: adding system driver 'brcmfmac' '/system/driver/brcmfmac.so'\n[01286.451] 01105.04514> devmgr: adding system driver 'wlan' '/system/driver/wlanif.so'\n[01286.502] 01105.04514> devmgr: adding system driver 'wlan' '/system/driver/wlan.so'\n[01286.504] 01105.04514> devmgr: adding system driver 'mt8167s_gpu' '/system/driver/libmsd_img_rgx_mtk.so'\n[01286.514] 01105.04514> devmgr: adding system driver 'wlantapctl' '/system/driver/wlantap.so'\n[01286.518] 01105.04514> devmgr: adding system driver 'qmi_fake' '/system/driver/qmi-fake.so'\n[01286.532] 01105.04514> devmgr: adding system driver 'usb_video' '/system/driver/usb_video.so'\n[01286.535] 01105.04514> devmgr: adding system driver 'bt_hci_passthrough' '/system/driver/bt-hci-passthrough.so'\n[01286.544] 01105.04514> devmgr: adding system driver 'qmi_usb' '/system/driver/qmi-transport.so'\n[01286.555] 01105.04514> devmgr: adding system driver 'wlan' '/system/driver/wlanphy.so'\n[01286.574] 01105.04514> devmgr: adding system driver 'rtl88xx' '/system/driver/rtl88xx.so'\n[01286.575] 01105.01118> devcoord: driver 'rtl88xx' added\n[01286.575] 01105.01118> devcoord: driver 'wlan' added\n[01286.575] 01105.01118> devcoord: driver 'qmi_usb' added\n[01286.575] 01105.01118> devcoord: driver 'usb_video' added\n[01286.575] 01105.01118> devcoord: driver 'qmi_fake' added\n[01286.575] 01105.01118> devcoord: driver 'mt8167s_gpu' added\n[01286.575] 01105.01118> devcoord: driver 'wlan' added\n[01286.575] 01105.01118> devcoord: driver 'wlan' added\n[01286.575] 01105.01118> devcoord: driver 'brcmfmac' added\n[01286.575] 01105.01118> devcoord: driver 'ralink' added\n[01286.575] 01105.01118> devcoord: driver 'bt_host' added\n[01286.575] 01105.01118> devcoord: driver 'gpu' added\n[01286.575] 01105.01118> devcoord: drv='gpu' bindable to dev='intel-gpu-core'\n[01286.575] 01105.01118> devcoord: driver 'bt_hci_atheros' added\n[01286.575] 01105.01118> devcoord: driver 'bt_hog' added\n[01286.575] 01105.01118> devcoord: driver 'bt_hci_fake' added\n[01286.575] 01105.01118> devcoord: driver 'bt_hci_intel' added\n[01286.575] 01105.01118> devcoord: driver 'ath10k_pci' added\n[01286.575] 01105.01118> devcoord: drv='ath10k_pci' bindable to dev='01:00.0'\n[01286.575] 01105.01118> devcoord: launch devhost 'devhost:pci#11:168c:003e': pid=5335\n[01286.575] 01105.01118> devcoord: driver 'bt_hci_passthrough' added\n[01286.575] 01105.01118> devcoord: fallback driver 'usb_composite' is available\n[01286.575] 01105.01118> devcoord: driver 'usb_composite' added\n[01286.575] 01105.01118> devcoord: drv='usb_composite' bindable to dev='001'\n[01286.575] 01105.01118> devcoord: drv='usb_composite' bindable to dev='002'\n[01286.575] 01105.01118> devcoord: drv='usb_composite' bindable to dev='003'\n[01286.575] 01105.01118> devcoord: fallback driver 'intel_disp' is available\n[01286.575] 01105.01118> devcoord: driver 'intel_disp' added\n[01286.576] 05335.05371> devhost: trace provider registry begun\n[01286.576] 05335.05371> ath10k: ath10k: Probed chip QCA6174 ver: 2.1\n[01286.580] 02797.02833> UMS: parent: 'ifc-000'\n[01286.580] 02797.02833> UMS:Max lun is: 0\n[01286.586] 02797.02833> devhost[00:14.0/xhci/usb-bus/003/003/ifc-001] bind driver '/boot/driver/bt-transport-usb.so' failed: -2\n[01286.586] 01105.01118> devcoord: rpc: bind-driver 'ifc-001' status -2\n[01286.627] 02797.08259> btatheros: Making visible\n[01286.627] 02797.08259> btatheros: loaded successfully\n[01286.628] 02797.08320> [INFO:command_channel.cc(150)] hci: initialized\n[01286.662] 09722.09740> netstack: main.go:40: started\n[01286.662] 09722.09740> netstack: main.go:119: OnInterfacesChanged failed: ErrPeerClosed: zx.Channel.Write\n[01286.666] 04524.04762> [ERROR:garnet/bin/appmgr/namespace_builder.cc(60)] Failed to migrate '.' to new global data directory\n[01286.666] 04524.04762> [ERROR:garnet/bin/appmgr/namespace_builder.cc(60)] Failed to migrate 'deprecated-global-persistent-storage' to new global data directory\n[01286.694] 02797.08320> [WARN:adapter.cc(272)] gap: controller is using legacy HCI version 4.1\n[01286.700] 02797.08320> [INFO:acl_data_channel.cc(91)] hci: initialized\n[01286.759] 01598.01680> vc: new input device /dev/class/input/001\n[01286.769] 01598.01680> vc: new input device /dev/class/input/002\n[01286.850] 12772.12784> [INFO:cobalt_main.cc(102)] Cobalt client schedule params: schedule_interval=3600 seconds, min_interval=10 seconds, initial_interval=60 seconds.\n[01286.974] 09722.10091> netstack: netstack.go:589: NIC ethp001f6 added\n[01286.974] 09722.10091> netstack: netstack.go:604: NIC ethp001f6: link-local IPv6: fe80::d65d:dfff:fe1a:4246\n[01286.974] 09722.10091> netstack: netstack.go:308: NIC ethp001f6: starting\n[01286.975] 09722.12304> netstack: netstack.go:295: NIC ethp001f6: stopped\n[01286.987] 05335.13160> devhost: rpc:load-firmware failed: -25\n[01286.988] 05335.13160> devhost: rpc:load-firmware failed: -25\n[01287.183] 15549.15567> [INFO:main.cc(35)] Trace Manager starting with config: /pkg/data/tracing.config\n[01287.275] 16120.16132> wlanstack2 [I]: Starting\n[01287.588] 02797.06290> UMS: block size is: 0x00000200\n[01287.588] 02797.06290> UMS: total blocks is: 30031250\n[01287.588] 02797.06290> UMS: total size is: 15376000000\n[01287.588] 02797.06290> UMS: read-only: 0 removable: 1\n[01287.591] 01183.01203> devmgr: /dev/class/block/006: MBR?\n[01287.591] 01105.01118> devcoord: dc_bind_device() '/boot/driver/mbr.so'\n[01287.593] 01183.01203> devmgr: /dev/class/block/008: MBR?\n[01287.593] 01105.01118> devcoord: dc_bind_device() '/boot/driver/mbr.so'\n[01287.674] 05335.12411> ath10k: Unknown eventid: 0x1d019\n[01287.677] 05335.12411> ath10k: Unknown eventid: 0x16006\n[01287.682] 05335.05371> wlanphy: event loop started\n[01287.682] 05335.05371> wlanphy_bind\n[01287.683] 16120.16132> wlanstack2::device [I]: new phy #0: /dev/sys/pci/01:00.0/ath10k-wlanphy/wlanphy\n[01287.683] 13569.13581> wlancfg got event: OnPhyAdded { phy_id: 0 }\n[01287.683] 13569.13581> wlancfg: phy 0 added\n[01287.683] 16120.16132> wlanstack2::service [I]: query_phy(id = 0)\n[01287.684] 16120.16132> wlanstack2::service [I]: query_phy(id = 0): received a 'QueryResult' from device\n[01287.684] 13569.13581> wlancfg: received a PhyInfo from phy #0: path is /dev/sys/pci/01:00.0/ath10k-wlanphy/wlanphy\n[01287.684] 13569.13581> using default wlan config entry for phy\n[01287.684] 13569.13581> wlancfg: Creating Client iface for phy 0\n[01287.689] 05335.05371> wlan_bind\n[01287.691] 05335.05371> ath10k: adding a station interface (vdev_id=0) ...\n[01287.692] 05335.05371> wlan: [I] Initialize a client MLME.\n[01287.693] 05335.17023> wlan: [I] starting MainLoop\n[01287.693] 05335.05371> wlan: [I] channel opened\n[01287.694] 16120.16132> wlanstack2::device [I]: new iface #0 with role 'Client': /dev/sys/pci/01:00.0/ath10k-wlanphy/ath10k-wlanmac/wlan\n[01287.695] 13569.13581> wlancfg got event: OnIfaceAdded { iface_id: 0 }\n[01287.695] 13569.13581> wlancfg: new iface 0 added successfully\n[01287.695] 13569.13581> wlancfg: Starting auto-connect loop\n[01287.697] 09722.10091> netstack: netstack.go:589: NIC wlanp01 added\n[01287.697] 09722.10091> netstack: netstack.go:604: NIC wlanp01: link-local IPv6: fe80::20e:8eff:fe8b:40ec\n[01287.697] 09722.10091> netstack: netstack.go:308: NIC wlanp01: starting\n[01287.698] 09722.12287> netstack: netstack.go:295: NIC wlanp01: stopped\n[01287.789] 09722.17104> netstack: netstack.go:308: NIC ethp001f6: starting\n[01291.834] 09722.12287> netstack: netstack.go:237: NIC ethp001f6: DHCP acquired IP 192.168.42.250 for 240h0m0s\n[01291.834] 09722.12287> netstack: netstack.go:238: NIC ethp001f6: Adding DNS servers: [8.8.8.8]\nRunning tests sequentially.\n[tb] 2019-02-12 08:51:10.955 \u001b[22mINFO\u001b[0m [AndroidDevice|HT83M1A00122] The primary device under test is \"HT83M1A00122\". [android_device.py:create:91]\n[tb] 2019-02-12 08:51:14.313 \u001b[22mINFO\u001b[0m Controller AndroidDevice: [{'model': 'walleye', 'incremental_build_id': '4760640', 'build_type': 'userdebug', 'build_id': '4760640', 'serial': 'HT83M1A00122'}]\n[tb] 2019-02-12 08:51:14.327 \u001b[22mINFO\u001b[0m Controller FuchsiaDevice: [{'ip': '192.168.42.250'}]\n[tb] 2019-02-12 08:51:15.512 \u001b[22mINFO\u001b[0m ==========> Sl4fSanityTest <========== [base_test.py:run:663]\n[tb] 2019-02-12 08:51:15.515 \u001b[22mINFO\u001b[0m Congratulations! Fuchsia controllers have been initialized successfully! [Sl4fSanityTest.py:setup_class:41]\n[tb] 2019-02-12 08:51:15.517 \u001b[22mINFO\u001b[0m [Test Case] test_example [base_test.py:exec_one_testcase:390]\n[tb] 2019-02-12 08:51:15.529 \u001b[22mINFO\u001b[0m Congratulations! You've run your first test. [Sl4fSanityTest.py:test_example:46]\n[tb] 2019-02-12 08:51:15.541 \u001b[22mINFO\u001b[0m [Test Case] test_example PASS [base_test.py:_on_pass:271]\n[tb] 2019-02-12 08:51:15.543 \u001b[22mINFO\u001b[0m Summary for test class Sl4fSanityTest: Blocked 0, ControllerInfo {}, Errors 0, Executed 1, Failed 0, Passed 1, Requested 1, Skipped 0, Unknown 0 [base_test.py:run:725]\n[tb] 2019-02-12 08:51:16.473 \u001b[22mINFO\u001b[0m [AndroidDevice|HT83M1A00122] The primary device under test is \"HT83M1A00122\". [android_device.py:create:91]\n[tb] 2019-02-12 08:51:19.446 \u001b[22mINFO\u001b[0m Controller AndroidDevice: [{'model': 'walleye', 'incremental_build_id': '4760640', 'build_type': 'userdebug', 'build_id': '4760640', 'serial': 'HT83M1A00122'}]\n[tb] 2019-02-12 08:51:19.456 \u001b[22mINFO\u001b[0m Controller FuchsiaDevice: [{'ip': '192.168.42.250'}]\n[tb] 2019-02-12 08:51:20.808 \u001b[22mINFO\u001b[0m ==========> WlanScanTest <========== [base_test.py:run:663]\n[tb] 2019-02-12 08:51:20.812 \u001b[22mINFO\u001b[0m [Test Case] test_basic_scan_request [base_test.py:exec_one_testcase:390]\n[01354.913] 05335.17023> ath10k: starting a hardware scan\n[tb] 2019-02-12 08:51:26.330 \u001b[22mINFO\u001b[0m scan contained 33 results [WlanScanTest.py:test_basic_scan_request:57]\n[tb] 2019-02-12 08:51:26.333 \u001b[22mINFO\u001b[0m scan time: 5510 ms [WlanScanTest.py:test_basic_scan_request:60]\n[tb] 2019-02-12 08:51:26.355 \u001b[22mINFO\u001b[0m [Test Case] test_basic_scan_request PASS [base_test.py:_on_pass:271]\n[tb] 2019-02-12 08:51:26.357 \u001b[22mINFO\u001b[0m Summary for test class WlanScanTest: Blocked 0, ControllerInfo {}, Errors 0, Executed 1, Failed 0, Passed 1, Requested 1, Skipped 0, Unknown 0 [base_test.py:run:725]\n[tb] 2019-02-12 08:51:27.403 \u001b[22mINFO\u001b[0m [AndroidDevice|HT83M1A00122] The primary device under test is \"HT83M1A00122\". [android_device.py:create:91]\n[tb] 2019-02-12 08:51:30.626 \u001b[22mINFO\u001b[0m Controller AndroidDevice: [{'model': 'walleye', 'incremental_build_id': '4760640', 'build_type': 'userdebug', 'build_id': '4760640', 'serial': 'HT83M1A00122'}]\n[tb] 2019-02-12 08:51:30.636 \u001b[22mINFO\u001b[0m Controller FuchsiaDevice: [{'ip': '192.168.42.250'}]\n[tb] 2019-02-12 08:51:31.902 \u001b[22mINFO\u001b[0m There are: 1 fuchsia and 1 android devices. [BleFuchsiaAndroidTest.py:__init__:48]\n[tb] 2019-02-12 08:51:31.904 \u001b[22mINFO\u001b[0m ==========> BleFuchsiaAndroidTest <========== [base_test.py:run:663]\n[tb] 2019-02-12 08:51:31.907 \u001b[22mINFO\u001b[0m Setting up Android Devices\n[tb] 2019-02-12 08:51:31.993 \u001b[22mINFO\u001b[0m [AndroidDevice|HT83M1A00122] Reset state of bluetooth on device. [bt_test_utils.py:factory_reset_bluetooth:529]\n[tb] 2019-02-12 08:51:34.704 \u001b[22mINFO\u001b[0m State normalized {15}\n[tb] 2019-02-12 08:51:35.151 \u001b[22mINFO\u001b[0m [AndroidDevice|HT83M1A00122] Android Phone device found. [bt_test_utils.py:get_device_selector_dictionary:694]\n[tb] 2019-02-12 08:51:35.153 \u001b[22mINFO\u001b[0m [Test Case] test_fuchsia_adv_android_scan [base_test.py:exec_one_testcase:390]\n[tb] 2019-02-12 08:51:35.176 \u001b[22mINFO\u001b[0m [Test ID] BleFuchsiaAndroidTest:test_fuchsia_adv_android_scan:1549961495.175287 [BluetoothBaseTest.py:_safe_wrap_test_case:95]\n[01369.349] 02797.02833> bt-transport-usb: timed out: ZX_ERR_TIMED_OUT\n[tb] 2019-02-12 08:51:36.129 \u001b[22mINFO\u001b[0m Found scan result: {'data': {'CallbackType': 1,\n 'ID': 1,\n 'Result': {'advertiseFlags': 2,\n 'deviceInfo': {'address': '02:B8:41:ED:9C:3C',\n 'name': 'testADV123',\n 'state': 10,\n 'type': 2},\n 'deviceName': 'testADV123',\n 'manufacturerIdList': '[]',\n 'manufacturerSpecificDataList': '[]',\n 'rssi': -32,\n 'scanRecord': '2,1,2,11,9,116,101,115,116,65,68,86,49,50,51,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0',\n 'serviceDataList': '[]',\n 'serviceUuidList': '[]',\n 'serviceUuids': '',\n 'timestampNanos': 4872433853631243,\n 'txPowerLevel': -2147483648},\n 'Type': 'onScanResult'},\n 'name': 'BleScan1onScanResults',\n 'time': 1549961496090} [BleFuchsiaAndroidTest.py:test_fuchsia_adv_android_scan:151]\n[tb] 2019-02-12 08:51:36.186 \u001b[22mINFO\u001b[0m [Test Case] test_fuchsia_adv_android_scan PASS [base_test.py:_on_pass:271]\n[tb] 2019-02-12 08:51:36.188 \u001b[22mINFO\u001b[0m [Test Case] test_fuchsia_connect_android_periph [base_test.py:exec_one_testcase:390]\n[tb] 2019-02-12 08:51:36.212 \u001b[22mINFO\u001b[0m [Test ID] BleFuchsiaAndroidTest:test_fuchsia_connect_android_periph:1549961496.2114694 [BluetoothBaseTest.py:_safe_wrap_test_case:95]\n[tb] 2019-02-12 08:51:36.346 \u001b[22mINFO\u001b[0m Android device name: Pixel1234 [BleFuchsiaAndroidTest.py:test_fuchsia_connect_android_periph:98]\n[01370.437] 02797.08320> [INFO:low_energy_discovery_manager.cc(92)] gap-le: start discovery\n[tb] 2019-02-12 08:51:37.368 \u001b[22mINFO\u001b[0m Successfully found advertisement! name, id: Pixel1234, 8ae72e65-8357-4fb5-9aa3-b8ba1f40d8cd [bt_test_utils.py:le_scan_for_device_by_name:43]\n[tb] 2019-02-12 08:51:37.534 \u001b[22mINFO\u001b[0m Connecting returned status: {'result': None, 'id': '3', 'error': None} [BleFuchsiaAndroidTest.py:test_fuchsia_connect_android_periph:109]\n[01371.616] 02797.08320> [INFO:low_energy_connection_manager.cc(754)] gap-le: new connection (LE link - handle: 0x0002, role: master, address: (LE rand) 6D:A5:46:F1:3E:07, interval: 45.00 ms, latency: 0.00 ms, timeout: 420 ms)\n[tb] 2019-02-12 08:51:37.792 \u001b[22mINFO\u001b[0m Listing services returned: {'result': [{'id': 1, 'uuid_type': '00001801-0000-1000-8000-00805f9b34fb', 'primary': True}, {'id': 20, 'uuid_type': '00001800-0000-1000-8000-00805f9b34fb', 'primary': True}, {'id': 40, 'uuid_type': 'b3b7e28e-a000-3e17-bd86-6e97b9e28c11', 'primary': True}], 'id': '4', 'error': None} [BleFuchsiaAndroidTest.py:test_fuchsia_connect_android_periph:112]\n[tb] 2019-02-12 08:51:37.802 \u001b[22mINFO\u001b[0m Disconnect status: {'result': None, 'id': '5', 'error': None} [BleFuchsiaAndroidTest.py:test_fuchsia_connect_android_periph:115]\n[01371.884] 02797.08320> [INFO:low_energy_connection_manager.cc(593)] gap-le: all refs dropped on connection: (LE link - handle: 0x0002, role: master, address: (LE rand) 6D:A5:46:F1:3E:07, interval: 45.00 ms, latency: 0.00 ms, timeout: 420 ms)\n[01371.926] 02797.08320> [INFO:low_energy_connection_manager.cc(851)] gap-le: link disconnected - status: \"success\", handle: 0x0002, reason: 0x16\n[tb] 2019-02-12 08:51:37.901 \u001b[22mINFO\u001b[0m [Test Case] test_fuchsia_connect_android_periph PASS [base_test.py:_on_pass:271]\n[tb] 2019-02-12 08:51:37.904 \u001b[22mINFO\u001b[0m [Test Case] test_fuchsia_scan_android_adv [base_test.py:exec_one_testcase:390]\n[tb] 2019-02-12 08:51:37.936 \u001b[22mINFO\u001b[0m [Test ID] BleFuchsiaAndroidTest:test_fuchsia_scan_android_adv:1549961497.9354608 [BluetoothBaseTest.py:_safe_wrap_test_case:95]\n[tb] 2019-02-12 08:51:38.048 \u001b[22mINFO\u001b[0m Android device name: Pixel1234 [BleFuchsiaAndroidTest.py:test_fuchsia_scan_android_adv:75]\n[01372.139] 02797.08320> [INFO:low_energy_discovery_manager.cc(92)] gap-le: start discovery\n[tb] 2019-02-12 08:51:39.068 \u001b[22mINFO\u001b[0m Successfully found advertisement! name, id: Pixel1234, 18f0f0c2-0088-407e-b762-9208bff3c088 [bt_test_utils.py:le_scan_for_device_by_name:43]\n[tb] 2019-02-12 08:51:39.161 \u001b[22mINFO\u001b[0m [Test Case] test_fuchsia_scan_android_adv PASS [base_test.py:_on_pass:271]\n[tb] 2019-02-12 08:51:39.163 \u001b[22mINFO\u001b[0m Summary for test class BleFuchsiaAndroidTest: Blocked 0, ControllerInfo {}, Errors 0, Executed 3, Failed 0, Passed 3, Requested 3, Skipped 0, Unknown 0 [base_test.py:run:725]\n[tb] 2019-02-12 08:51:40.242 \u001b[22mINFO\u001b[0m Summary for test run tb@2019-02-12_08-51-09-770: Blocked 0, ControllerInfo {'FuchsiaDevice': [{'ip': '192.168.42.250'}], 'AndroidDevice': [{'model': 'walleye', 'incremental_build_id': '4760640', 'build_type': 'userdebug', 'build_id': '4760640', 'serial': 'HT83M1A00122'}]}, Errors 0, Executed 5, Failed 0, Passed 5, Requested 5, Skipped 0, Unknown 0\nCommand succeeded!\n", "outputs": [ "out.tar" ], "results": { "bot_dimensions": [ { "key": "device_type", "value": [ "Intel NUC Kit NUC6i3SYK" ] }, { "key": "host_cpu", "value": [ "x64", "x86", "x86-64-avx2" ] }, { "key": "host_os", "value": [ "Debian", "Debian-9.6", "Linux" ] }, { "key": "id", "value": [ "fuchsia-tests-x64-lab01-0001--ocean-drank-wick-spot" ] }, { "key": "pool", "value": [ "fuchsia.tests" ] }, { "key": "server_version", "value": [ "4085-c81638b" ] }, { "key": "zone", "value": [ "cloud" ] } ], "bot_id": "fuchsia-tests-x64-lab01-0001--ocean-drank-wick-spot", "bot_version": "6fda8587d8e40cbc2d0c208ea94136c96de739ec01ce6b45c68d42a526d02316", "cipd_pins": { "client_package": { "package_name": "infra/tools/cipd/linux-amd64", "version": "a2dqpK39PjGpFdcdw62OAE0JOJJ9n8J_AXpJHmH0QCIC" }, "packages": [ { "package_name": "fuchsia/tools/botanist/linux-amd64", "path": ".", "version": "xCeDsO8Ytka6oy_fiRwW6wgP2CGXrVUFWi1EaiUZ7rUC" } ] }, "completed_ts": "2019-02-12T08:51:41.818733", "costs_usd": [ 0.050769301950192185 ], "created_ts": "2019-02-12T08:48:47.672814", "duration": 102.01434898376465, "modified_ts": "2019-02-12T08:51:41.818733", "name": "all tests", "outputs_ref": { "isolated": "ff9e175eab355a5338b21c77201fa821a34d8f14", "isolatedserver": "https://isolateserver.appspot.com", "namespace": "default-gzip" }, "run_id": "42f9b67c48c51a11", "server_versions": [ "4085-c81638b" ], "started_ts": "2019-02-12T08:49:47.709576", "state": "COMPLETED", "tags": [ "device_type:Intel NUC Kit NUC6i3SYK", "id:fuchsia-tests-x64-lab01-0001--ocean-drank-wick-spot", "pool:fuchsia.tests", "priority:200", "service_account:none", "swarming.pool.template:none", "swarming.pool.version:741960cd72af27a2e6e1b9f08377d63df8bb1551", "user:None" ], "task_id": "42f9b67c48c51a10", "try_number": "1" } } }