{ "444748bead271d10": { "output": "2 files remaining...\nDEBUG: config flag: /etc/botanist/config.json\nDEBUG: executing command: \"/etc/connectivity/host_cmds.sh\"\nenvironment of subprocess:\n[]\n2019/04/18 03:23:45 attempting to send <<netboot>>cmdline...\n2019/04/18 03:23:45 done\n2019/04/18 03:23:45 attempting to send <<image>>sparse.fvm...\n[00000.000] 00000.00000> zbi: @ 0xffffff80012f2000 (17482848 bytes)\n[00000.000] 00000.00000> UART: FIFO depth 16\n[00000.000] 00000.00000> PMM: boot reserve add [0x100000, 0x2c5fff]\n[00000.000] 00000.00000> PMM: boot reserve add [0x12f2000, 0x239efff]\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 0x8afff000 size 0x1000\n[00000.000] 00000.00000> PMM: boot reserve marking WIRED [0x100000, 0x2c5fff]\n[00000.000] 00000.00000> PMM: boot reserve marking WIRED [0x12f2000, 0x239efff]\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 0xffffffff001aa428 (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 [0x239f000, 0x239f100)\n[00000.000] 00000.00000> INIT: cpu 0, calling hook 0xffffffff00147abc (elf_build_id) at level 0x4fffe, flags 0x1\n[00000.000] 00000.00000> INIT: cpu 0, calling hook 0xffffffff00147c48 (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-13ee3dc5e4c46bf127977ad28645c47442ec517d\n[00000.000] 00000.00000> \tELF build ID: 5f3e39bd4ed89d3b8122947842f1eac846a04683\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 0xffffffff001a9630 (console) at level 0x50000, flags 0x1\n[00000.000] 00000.00000> initializing vm\n[00000.000] 00000.00000> VM: reserving kernel region [0xffffffff00100000, 0xffffffff001ee000) flags 0x28 name 'kernel_code'\n[00000.000] 00000.00000> VM: reserving kernel region [0xffffffff001ee000, 0xffffffff00232000) flags 0x8 name 'kernel_rodata'\n[00000.000] 00000.00000> VM: reserving kernel region [0xffffffff00232000, 0xffffffff00242000) flags 0x18 name 'kernel_data'\n[00000.000] 00000.00000> VM: reserving kernel region [0xffffffff00242000, 0xffffffff002c6000) 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 0xffffffff00138fa0 (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[00021.024] 00000.00000> timer features: constant_tsc 1 invariant_tsc 1 tsc_deadline 1\n[00021.024] 00000.00000> Using TSC as wallclock\n[00021.024] 00000.00000> initializing kernel\n[00021.024] 00000.00000> initializing mp\n[00021.024] 00000.00000> initializing timers\n[00021.024] 00000.00000> INIT: cpu 0, calling hook 0xffffffff0013c578 (debuglog) at level 0x7ffff, flags 0x1\n[00021.024] 00000.00000> INIT: cpu 0, calling hook 0xffffffff00195518 (thread_set_priority_experiment) at level 0x7ffff, flags 0x1\n[00021.024] 00000.00000> thread set priority experiment is : ENABLED\n[00021.024] 00000.00000> INIT: cpu 0, calling hook 0xffffffff001aa67c (global_prng_thread_safe) at level 0x7ffff, flags 0x1\n[00021.024] 00000.00000> creating bootstrap completion thread\n[00021.366] 00000.00000> top of bootstrap2()\n[00021.366] 00000.00000> INIT: cpu 0, calling hook 0xffffffff0013151c (dpc) at level 0x80000, flags 0x1\n[00021.379] 00000.00000> INIT: cpu 0, calling hook 0xffffffff00152978 (libobject) at level 0x80000, flags 0x1\n[00021.379] 00000.00000> OOM: started thread\n[00021.392] 00000.00000> Processor Model Info: type 0 family 0x6 model 0xe stepping 0x9\n[00021.392] 00000.00000> \tdisplay_family 0x6 display_model 0x8e\n[00021.392] 00000.00000> Vendor: Intel\n[00021.392] 00000.00000> Microarch: Kaby Lake\n[00021.392] 00000.00000> F/M/S: 6/8e/9\n[00021.392] 00000.00000> Brand: Intel(R) Core(TM) i5-7300U CPU @ 2.60GHz\n[00021.392] 00000.00000> Features: fpu sse sse2 sse3 ssse3 sse4.1 sse4.2 mmx avx avx2 fxsr pcid xsave mon aesni clflush \n[00021.392] 00000.00000> clflushopt fsgsbase tsc_adj smep smap erms rdrand rdseed syscall nx huge rdtscp \n[00021.392] 00000.00000> invar_tsc tsc_deadline x2apic vmx pt hwp \n[00021.392] 00000.00000> initializing platform\n[00021.392] 00000.00000> INIT: cpu 0, calling hook 0xffffffff001101f4 (x86_perfmon) at level 0x90000, flags 0x1\n[00021.392] 00000.00000> PMU: version 4\n[00021.392] 00000.00000> UART: started IRQ driven RX\n[00021.392] 00000.00000> UART: started IRQ driven TX\n[00021.392] 00000.00000> cpu topology:\n[00021.392] 00000.00000> \t0: apic id 0x0 package 0 node 0 core 0 smt 0 BSP\n[00021.392] 00000.00000> \t1: apic id 0x2 package 0 node 0 core 1 smt 0\n[00021.392] 00000.00000> \t2: apic id 0x1 package 0 node 0 core 0 smt 1\n[00021.392] 00000.00000> \t3: apic id 0x3 package 0 node 0 core 1 smt 1\n[00021.392] 00000.00000> Found 4 cpus\n[00021.392] 00000.00000> booting apic ids: 0x2 0x1 0x3 \n[00021.408] 00000.00000> entering scheduler on cpu 2\n[00021.409] 00000.00000> entering scheduler on cpu 3\n[00021.409] 00000.00000> entering scheduler on cpu 1\n[00021.412] 00000.00000> smbios: manufacturer=\"Intel Corporation\" product=\"NUC7i5DNHE\"\n[00021.412] 00000.00000> initializing target\n[00021.412] 00000.00000> INIT: cpu 0, calling hook 0xffffffff001053a0 (x86_pcie_init) at level 0xa0000, flags 0x1\n[00021.412] 00000.00000> moving to last init level\n[00021.412] 00000.00000> INIT: cpu 0, calling hook 0xffffffff00144140 (ktrace) at level 0xc0000, flags 0x1\n[00021.415] 00000.00000> ktrace: buffer at 0xffffff92d8542000 (33554432 bytes)\n[00021.415] 00000.00000> INIT: cpu 0, calling hook 0xffffffff00147ab4 (userboot) at level 0xc0000, flags 0x1\n[00021.415] 00000.00000> userboot: ramdisk 0x10ad000 @ 0xffffff80012f2000\n[00021.416] 00000.00000> userboot: userboot rodata 0 @ [0x5fa2d5179000,0x5fa2d517c000)\n[00021.416] 00000.00000> userboot: userboot code 0x3000 @ [0x5fa2d517c000,0x5fa2d5187000)\n[00021.416] 00000.00000> userboot: vdso/full rodata 0 @ [0x5fa2d5187000,0x5fa2d518e000)\n[00021.416] 00000.00000> userboot: vdso/full code 0x7000 @ [0x5fa2d518e000,0x5fa2d518f000)\n[00021.416] 00000.00000> userboot: entry point @ 0x5fa2d517cc10\n[00021.416] 00000.00000> INIT: cpu 0, calling hook 0xffffffff001aa030 (kernel_shell) at level 0xc0000, flags 0x1\n[00021.416] 01036.01043> userboot: option \"netsvc.disable=true\"\n[00021.416] 01036.01043> userboot: option \"zircon.system.disable-automount=true\"\n[00021.416] 01036.01043> userboot: option \"zircon.autorun.boot=/boot/infra/setup\"\n[00021.416] 01036.01043> userboot: option \"kernel.serial=legacy\"\n[00021.416] 01036.01043> userboot: option \"http://192.168.42.1/multiboot/54%3Ab2%3A03%3A13%3Ab3%3Ae7=\"\n[00021.416] 01036.01043> userboot: option \"multiboot.boot_loader_name=iPXE+1.0.0++(d2063)\"\n[00021.455] 01036.01043> userboot: searching bootfs for 'bin/bootsvc'\n[00021.455] 01036.01043> userboot: 'bin/bootsvc' has PT_INTERP \"lib/ld.so.1\"\n[00021.455] 01036.01043> userboot: searching bootfs for 'lib/ld.so.1'\n[00021.455] 01036.01043> userboot: userboot: loaded lib/ld.so.1 at 0x7c8d2f795000, entry point 0x7c8d2f81b0d3\n[00021.455] 01036.01043> userboot: userboot: loaded vDSO at 0x7a8096a5c000, entry point 0x0\n[00021.455] 01036.01043> userboot: process bin/bootsvc started.\n[00021.455] 01036.01043> userboot: waiting for loader-service requests...\n[00021.455] 01036.01043> userboot: searching bootfs for 'lib/libasync-default.so'\n[00021.455] 01036.01043> userboot: searching bootfs for 'lib/libfdio.so'\n[00021.455] 01036.01043> userboot: searching bootfs for 'lib/liblaunchpad.so'\n[00021.455] 01036.01043> userboot: searching bootfs for 'lib/libtrace-engine.so'\n[00021.455] 01050.01053> {{{reset}}}\n[00021.455] 01050.01053> {{{module:0:<application>:elf:18de7d58f51e8ba5c4f6afdd0cc8440f482c2b45}}}\n[00021.455] 01050.01053> {{{mmap:0x3e4802693000:0x2e000:load:0:rx:0}}}\n[00021.455] 01050.01053> {{{mmap:0x3e48026c1000:0x4000:load:0:rw:0x2e000}}}\n[00021.455] 01050.01053> dso: id=18de7d58f51e8ba5c4f6afdd0cc8440f482c2b45 base=0x00003e4802693000 name=<application>\n[00021.455] 01050.01053> {{{module:0x3:libasync-default.so:elf:c189f51f19d10785d93b5235ad1b46dca4451b00}}}\n[00021.455] 01050.01053> {{{mmap:0x73f202f73000:0x1000:load:0x3:rx:0}}}\n[00021.455] 01050.01053> {{{mmap:0x73f202f74000:0x1000:load:0x3:rw:0x1000}}}\n[00021.455] 01050.01053> dso: id=c189f51f19d10785d93b5235ad1b46dca4451b00 base=0x000073f202f73000 name=libasync-default.so\n[00021.455] 01050.01053> {{{module:0x2:<vDSO>:elf:40ab5fa3b61f12fef4a44477a687f608661cd450}}}\n[00021.455] 01050.01053> {{{mmap:0x7a8096a5c000:0x7000:load:0x2:r:0}}}\n[00021.455] 01050.01053> {{{mmap:0x7a8096a63000:0x1000:load:0x2:rx:0x7000}}}\n[00021.455] 01050.01053> dso: id=40ab5fa3b61f12fef4a44477a687f608661cd450 base=0x00007a8096a5c000 name=<vDSO>\n[00021.455] 01050.01053> {{{module:0x1:libc.so:elf:67a12284bce140fc32aaaeac223e0e8f85cb5085}}}\n[00021.455] 01050.01053> {{{mmap:0x7c8d2f795000:0xcb000:load:0x1:rx:0}}}\n[00021.455] 01050.01053> {{{mmap:0x7c8d2f861000:0x6000:load:0x1:rw:0xcc000}}}\n[00021.455] 01050.01053> dso: id=67a12284bce140fc32aaaeac223e0e8f85cb5085 base=0x00007c8d2f795000 name=libc.so\n[00021.455] 01050.01053> {{{module:0x4:libfdio.so:elf:27787977e95f3b9563c9e0bd4d34ec92b7e9ad88}}}\n[00021.455] 01050.01053> {{{mmap:0x5c5c1479f000:0x24000:load:0x4:rx:0}}}\n[00021.455] 01050.01053> {{{mmap:0x5c5c147c4000:0x4000:load:0x4:rw:0x25000}}}\n[00021.455] 01050.01053> dso: id=27787977e95f3b9563c9e0bd4d34ec92b7e9ad88 base=0x00005c5c1479f000 name=libfdio.so\n[00021.455] 01050.01053> {{{module:0x5:liblaunchpad.so:elf:6fc2232dc8c1bc5c6adb8ad50ca794b5a260ee4f}}}\n[00021.455] 01050.01053> {{{mmap:0x3fbe8317b000:0x7000:load:0x5:rx:0}}}\n[00021.455] 01050.01053> {{{mmap:0x3fbe83182000:0x2000:load:0x5:rw:0x7000}}}\n[00021.455] 01050.01053> dso: id=6fc2232dc8c1bc5c6adb8ad50ca794b5a260ee4f base=0x00003fbe8317b000 name=liblaunchpad.so\n[00021.455] 01050.01053> {{{module:0x6:libtrace-engine.so:elf:c9042b83fe01206008fcefb16395238417248169}}}\n[00021.455] 01050.01053> {{{mmap:0x1069e3dd2000:0x9000:load:0x6:rx:0}}}\n[00021.455] 01050.01053> {{{mmap:0x1069e3ddb000:0x2000:load:0x6:rw:0x9000}}}\n[00021.455] 01050.01053> dso: id=c9042b83fe01206008fcefb16395238417248169 base=0x00001069e3dd2000 name=libtrace-engine.so\n[00021.455] 01050.01053> bootsvc: Starting...\n[00021.455] 01036.01043> userboot: loader-service channel peer closed\n[00021.455] 01036.01043> userboot: finished!\n[00021.455] 01050.01053> bootsvc: Creating bootfs service...\n[00021.456] 01050.01053> bootsvc: Processing bootdata...\n[00021.456] 01050.01053> bootsvc: Loading boot cmdline overrides...\n[00021.456] 01050.01053> bootsvc: Loading kernel VMOs...\n[00021.456] 01050.01053> bootsvc: Creating loader service...\n[00021.456] 01050.01053> bootsvc: Launching next process...\n[00021.456] 01050.01096> bootsvc: launched bin/devmgr\n[00021.457] 01104.01117> devmgr: main()\n[00021.457] 01104.01117> cmdline: netsvc.disable=true\n[00021.457] 01104.01117> cmdline: zircon.system.disable-automount=true\n[00021.457] 01104.01117> cmdline: zircon.autorun.boot=/boot/infra/setup\n[00021.457] 01104.01117> cmdline: kernel.serial=legacy\n[00021.457] 01104.01117> cmdline: http://192.168.42.1/multiboot/54%3Ab2%3A03%3A13%3Ab3%3Ae7=\n[00021.457] 01104.01117> cmdline: multiboot.boot_loader_name=iPXE+1.0.0++(d2063)\n[00021.457] 01104.01117> devmgr: coordinator_init()\n[00021.457] 01104.01117> devmgr: init\n[00021.457] 01104.01117> devmgr: svc init\n[00021.457] 01104.01117> devmgr: launch /boot/bin/svchost (svchost) OK\n[00021.457] 01104.01117> devmgr: vfs init\n[00021.457] 01104.01117> devmgr: launch /boot/bin/fshost (fshost) OK\n[00021.457] 01104.01223> devmgr: shell startup\n[00021.458] 01182.01202> fshost: started.\n[00021.459] 01104.01213> devmgr: launch /boot/bin/pwrbtn-monitor (pwrbtn-monitor) OK\n[00021.460] 01104.01241> devmgr: launch /boot/bin/virtual-console (virtual-console) OK\n[00021.460] 01104.01241> zircon.autorun.boot: starting '/boot/infra/setup'...\n[00021.461] 01104.01241> devmgr: launch /boot/infra/setup (autorun:boot) OK\n[00021.463] 01104.01117> devcoord: launch devhost 'devhost:sys': pid=2049\n[00021.463] 01104.01117> devcoord: launch devhost 'devhost:test': pid=2082\n[00021.464] 01104.01117> devcoord: launch devhost 'devhost:root': pid=2117\n[00021.464] 01104.01117> devcoord: launch devhost 'devhost:misc': pid=2170\n[00021.464] 02049.02073> devhost: trace provider registry begun\n[00021.465] 02082.02106> devhost: trace provider registry begun\n[00021.467] 02117.02156> devhost: trace provider registry begun\n[00021.468] 02170.02217> devhost: trace provider registry begun\n[00021.475] 01104.01223> devmgr: launch /boot/bin/sh (sh:console) OK\n[00021.535] 02049.02073> acpi-bus: not using IOMMU\n[00021.539] 02049.02073> acpi-pwrbtn: initialized\n[00021.562] 02049.02073> acpi: published device pci(0x32239de7d200), parent=proxy(0x32239de79540), handle=0x32239deb5c30\n[00021.564] 02049.02073> acpi: published device rtc(0x32239de78080), parent=acpi(0x32239de79780), handle=0x32239dece5b0\n[00021.565] 02049.02073> acpi-ec: initialized\n[00021.566] 02049.02073> acpi: failed to create NHLT VMO (res -10)\n[00021.566] 02049.02073> acpi: failed to publish NHLT metadata\n[00021.569] 02049.02073> [sysmem_init 28] async_get_default_dispatcher(): 0x32239de6c0a0\n[00021.569] 02049.02073> [sysmem_bind 40] sysmem_bind()\n[00021.569] 02049.02073> acpi-bus: sysmem_register_protocol() intentionally ignored for now.\n[00021.569] 02049.02073> PMU: 7 arch events\n[00021.569] 02049.02073> PMU: arch event id range: 1-7\n[00021.569] 02049.02073> PMU: 102 model events\n[00021.569] 02049.02073> PMU: model event id range: 1-241\n[00021.569] 02049.02073> Intel Processor Trace configuration for this chipset:\n[00021.569] 02049.02073> mtc_freq_mask: 0x249\n[00021.569] 02049.02073> cyc_thresh_mask: 0x3fff\n[00021.569] 02049.02073> psb_freq_mask: 0x3f\n[00021.569] 02049.02073> num addr ranges: 2\n[00021.570] 01256.01539> vc: new input device /dev/class/input/000\n[00021.570] 01104.01117> devcoord: launch devhost 'devhost:pci#1:8086:5916': pid=3029\n[00021.570] 01104.01117> devcoord: launch devhost 'devhost:pci#3:8086:9d2f': pid=3092\n[00021.571] 01104.01117> devcoord: launch devhost 'devhost:pci#5:8086:9d60': pid=3149\n[00021.571] 01104.01117> devcoord: launch devhost 'devhost:pci#6:8086:9d61': pid=3224\n[00021.572] 03092.03122> devhost: trace provider registry begun\n[00021.572] 03029.03064> devhost: trace provider registry begun\n[00021.572] 01104.01117> devcoord: launch devhost 'devhost:pci#9:8086:9d03': pid=3301\n[00021.573] 01104.01117> devcoord: launch devhost 'devhost:pci#14:8086:9d71': pid=3424\n[00021.574] 03149.03194> devhost: trace provider registry begun\n[00021.574] 03224.03257> devhost: trace provider registry begun\n[00021.575] 01104.01117> devcoord: launch devhost 'devhost:pci#16:8086:156f': pid=3521\n[00021.575] 03301.03369> devhost: trace provider registry begun\n[00021.577] 03301.03369> ahci: using MSI interrupt\n[00021.577] 03424.03459> devhost: trace provider registry begun\n[00021.578] 03149.03194> initialized intel serialio i2c driver, reg=0x6c591bb8b000 regsize=4096\n[00021.578] 03224.03257> initialized intel serialio i2c driver, reg=0x70580c2f6000 regsize=4096\n[00021.578] 03521.03577> devhost: trace provider registry begun\n[00021.582] 03092.03831> * found USB device (0x18d1:0xa002, USB 2.0) config 1\n[00021.582] 03092.03831> * found USB device (0x18d1:0xa003, USB 3.0) config 1\n[00021.583] 03424.03459> [IHDA DSP 00:1f.3] Failed to fetch NHLT (res -25)\n[00021.583] 03424.03459> devhost[00:1f.3/intel-hda-000/intel-sst-dsp-000] bind driver '/boot/driver/dsp.so' failed: -25\n[00021.583] 01104.01117> devcoord: rpc: bind-driver 'intel-sst-dsp-000' status -25\n[00021.680] 01256.01539> vc: new display device /dev/class/display-controller/000/virtcon\n[00021.821] 03029.04142> i915: MST not supported\n[00022.294] 03092.03831> * found USB device (0x0781:0x5583, USB 3.0) config 1\n[00022.295] 03092.03122> UMS: parent: 'ifc-000'\n[00022.295] 03092.03122> UMS:Max lun is: 0\n[00022.323] 03029.04142> i915: MST not supported\n[00023.045] 03092.03831> * found USB device (0x0cf3:0xe300, USB 2.1) config 1\n[00023.046] 03092.03122> devhost[00:14.0/xhci/usb-bus/002/002/ifc-001] bind driver '/boot/driver/bt-transport-usb.so' failed: -2\n[00023.046] 01104.01117> devcoord: rpc: bind-driver 'ifc-001' status -2\n[00023.297] 03092.04229> UMS: block size is: 0x00000200\n[00023.297] 03092.04229> UMS: total blocks is: 30031872\n[00023.297] 03092.04229> UMS: total size is: 15376318464\n[00023.297] 03092.04229> UMS: read-only: 0 removable: 1\n[00023.298] 01182.01202> devmgr: /dev/class/block/000: MBR?\n[00023.298] 01104.01117> devcoord: dc_bind_device() '/boot/driver/mbr.so'\n[00023.301] 01182.01202> devmgr: /dev/class/block/002: MBR?\n[00023.301] 01104.01117> devcoord: dc_bind_device() '/boot/driver/mbr.so'\n[00023.369] 03029.04142> i915: No displays detected\n[00023.581] 03149.03194> intel-i2c-controller: intel_serialio_i2c_slave_transfer: -21\n[00023.581] 03149.03194> i2c-hid: could not read HID descriptor: 0\n[00023.581] 03149.03194> devhost[00:15.0/i2c-bus-9d60/0020] bind driver '/boot/driver/i2c-hid.so' failed: -2\n[00023.581] 01104.01117> devcoord: rpc: bind-driver '0020' status -2\n[00023.581] 03224.03257> intel-i2c-controller: intel_serialio_i2c_slave_transfer: -21\n[00023.581] 03224.03257> i2c-hid: could not read HID descriptor: 0\n[00023.581] 03224.03257> devhost[00:15.1/i2c-bus-9d61/004c] bind driver '/boot/driver/i2c-hid.so' failed: -2\n[00023.581] 01104.01117> devcoord: rpc: bind-driver '004c' status -2\n[00023.592] 03301.03781> sata2: dev info\n[00023.592] 03301.03781> serial=AA000000000000008069\n[00023.592] 03301.03781> firmware rev=0R08A1 0\n[00023.592] 03301.03781> model id=ETMAT 8MSP1582 G \n[00023.592] 03301.03781> major=0x3f0 ACS2 DMA 32 commands\n[00023.592] 03301.03781> LBA48 250069680 sectors, sector size=512\n[00023.593] 01182.01202> devmgr: /dev/class/block/003: GPT?\n[00023.593] 01104.01117> devcoord: dc_bind_device() '/boot/driver/gpt.so'\n[00023.594] 03301.03369> gpt: device_get_metadata failed (-25)\n[00023.595] 01182.01202> devmgr: /dev/class/block/004: FVM?\n[00023.595] 01104.01117> devcoord: dc_bind_device() '/boot/driver/fvm.so'\n[00023.597] 04483.04497> paver:[Initialize] Successfully initialized EFI Device Partitioner\n[00023.599] 04483.04497> paver:[WipePartitions] Immediate reboot strongly recommended\n[00023.599] 03301.03369> block: Joining un-closed FIFO server\n[00023.599] 03301.03369> block: Joining un-closed FIFO server\n[00023.599] 03301.03369> block: Joining un-closed FIFO server\n[00023.599] 01104.01117> devcoord: dc_bind_device() ''\n[00023.600] 01182.01202> devmgr: /dev/class/block/003: GPT?\n[00023.600] 01104.01117> devcoord: dc_bind_device() '/boot/driver/gpt.so'\n[00023.600] 03301.03369> gpt: device_get_metadata failed (-25)\n[00023.603] 04802.04816> 34+0 records in\n[00023.603] 04802.04816> 34+0 records out\n[00023.603] 04802.04816> 17408 bytes copied\n[00023.605] 04920.04934> 34+0 records in\n[00023.605] 04920.04934> 34+0 records out\n[00023.605] 04920.04934> 17408 bytes copied\n[00023.606] 05024.05038> netifc: ? /dev/class/ethernet/000\n[00023.606] 05024.05038> netifc: create 512 eth buffers\n[00023.606] 05024.05038> macaddr: 54:b2:03:13:b3:e7\n[00023.606] 05024.05038> ip6addr: fe80::56b2:34d:fe13:b3e7\n[00023.606] 05024.05038> snmaddr: ff02::1:ff13:b3e7\n[00023.606] 05024.05038> netsvc: using /dev/class/ethernet/000\n[00023.606] 05024.05038> _ _ _ \n[00023.606] 05024.05038> | | | | | \n[00023.606] 05024.05038> _______ __| | |__ ___ ___ | |_ \n[00023.606] 05024.05038> |_ / _ \\/ _` | '_ \\ / _ \\ / _ \\| __|\n[00023.606] 05024.05038> / / __/ (_| | |_) | (_) | (_) | |_ \n[00023.606] 05024.05038> /___\\___|\\__,_|_.__/ \\___/ \\___/ \\__|\n[00023.606] 05024.05038> \n[00023.606] 05024.05038> \n[00023.606] 05024.05038> zedboot: version: 0.7.13\n[00023.606] 05024.05038> \n[00023.606] 05024.05038> netsvc: nodename='rash-moan-copy-slob'\n[00023.607] 05024.05038> netsvc: will not advertise\n[00023.607] 05024.05038> netsvc: start\n[00907.469] 05024.05038> netsvc: tftp write of file <<netboot>>cmdline completed\n[00907.469] 05024.05038> netsvc: metrics: {\"inorderblks\": 1,\"oooblks\": 0,\"ack\": 1,\"nack\": 0,\"timeouts\": 0,\"sas\": 0,\"inorderbytes\": 55}\n[00907.469] 05024.05038> netsvc: Running FVM Paver\n[00907.472] 05024.05132> paver:[InitializeGpt] Located GPT is invalid; Attempting to initialize\n[00907.472] 01104.01117> devcoord: dc_bind_device() ''\n[00907.472] 01104.01117> devcoord: dc_bind_device() '/boot/driver/gpt.so'\n[00907.472] 03301.03369> gpt: device_get_metadata failed (-25)\n[00907.473] 01182.01202> devmgr: /dev/class/block/003: GPT?\n[00907.473] 01104.01117> devcoord: dc_bind_device() '/boot/driver/gpt.so'\n[00907.473] 03301.03369> devhost: rpc:bind-device failed: -20\n[00907.474] 05024.05132> paver:[Initialize] Successfully initialized EFI Device Partitioner\n[00907.474] 05024.05132> paver:[PartitionPave] Paving partition.\n[00907.474] 05024.05132> paver:[FindFirstFit] Looking for space\n[00907.474] 05024.05132> paver:[FindFirstFit] Sorting\n[00907.474] 05024.05132> paver:[FindFirstFit] Partition[0] From Block [0, 34) ... (next partition starts at block 250069646)\n[00907.474] 05024.05132> paver:[FindFirstFit] There are 250069612 free blocks (16777216 requested)\n[00907.474] 05024.05132> paver:[AddPartition] Found space in GPT - OK 250069612 @ 34\n[00907.474] 05024.05132> paver:[AddPartition] Final space in GPT - OK 16777216 @ 34\n[00907.475] 05024.05132> paver:[AddPartition] Added partition, waiting for bind\n[00907.475] 01104.01117> devcoord: dc_bind_device() ''\n[00907.476] 01182.01202> devmgr: /dev/class/block/003: GPT?\n[00907.476] 01104.01117> devcoord: dc_bind_device() '/boot/driver/gpt.so'\n[00907.476] 03301.03369> gpt: device_get_metadata failed (-25)\n[00907.476] 05024.05132> paver:[AddPartition] Added partition, waiting for bind - OK\n[00907.476] 05024.05132> paver:[PartitionPave] Streaming partitions...\n[00907.476] 05112.05126> Found compressed file\n[00907.476] 05024.05132> paver:[FvmStreamPartitions] Header Validated - OK\n[00907.477] 05024.05132> paver:[FvmPartitionFormat] Initializing partition as FVM\n[00907.479] 01104.01117> devcoord: dc_bind_device() '/boot/driver/fvm.so'\n[00908.481] 05024.05132> paver:[FvmStreamPartitions] Partitions pre-validated successfully: Enough space exists to pave.\n[00908.481] 05024.05132> paver:[AllocatePartitions] Allocating partition blobfs consisting of 1 slices\n[00908.485] 05024.05132> paver:[AllocatePartitions] Allocating partition minfs consisting of 1 slices\n[00908.486] 05024.05132> paver:[AllocatePartitions] Creating zxcrypt volume\n[00908.489] 03301.03369> devhost_get_handles(0x1056bad29900:block) open path='zxcrypt/block', r=-2\n[00908.489] 01104.01117> devcoord: dc_bind_device() '/boot/driver/zxcrypt.so'\n[00908.489] 03301.03369> devhost_get_handles(0x1056bad29900:block) open path='zxcrypt', r=-2\n[00908.494] 05024.05132> paver:[FvmStreamPartitions] Partition space pre-allocated successfully.\n[00908.494] 05024.05132> paver:[FvmStreamPartitions] Streaming partition 0\n[00908.494] 05024.05132> paver:[StreamFvmPartition] Writing extent 0... \n[00908.494] 05024.05138> netsvc: paver write progress 0.2%\n[00908.494] 05024.05132> paver:[StreamFvmPartition] 8192 bytes written, 8380416 zeroes left\n[00908.510] 05024.05132> paver:[StreamFvmPartition] Writing extent 1... \n[00908.510] 05024.05132> paver:[StreamFvmPartition] 8192 bytes written, 8380416 zeroes left\n[00908.527] 05024.05132> paver:[StreamFvmPartition] Writing extent 2... \n[00908.531] 05024.05132> paver:[StreamFvmPartition] 2097152 bytes written, 6291456 zeroes left\n[00908.543] 05024.05132> paver:[StreamFvmPartition] Writing extent 3... \n[00908.548] 05024.05132> paver:[StreamFvmPartition] 2097152 bytes written, 6291456 zeroes left\n[00908.574] 05024.05132> paver:[StreamFvmPartition] Writing extent 4... \n2019/04/18 03:23:47 done\n2019/04/18 03:23:47 attempting to send <<image>>bootloader.img...\n2019/04/18 03:23:47 target is busy, retrying in one second\n[00909.079] 05024.05038> netsvc: tftp write of file <<image>>sparse.fvm completed\n[00909.079] 05024.05038> netsvc: metrics: {\"inorderblks\": 167010,\"oooblks\": 0,\"ack\": 653,\"nack\": 0,\"timeouts\": 0,\"sas\": 0,\"inorderbytes\": 171018140}\n[00909.081] 05024.05132> paver:[StreamFvmPartition] 184279040 bytes written, 270336 zeroes left\n[00909.081] 05024.05132> paver:[FvmStreamPartitions] Done streaming partition 0\n[00909.081] 05024.05132> paver:[FvmStreamPartitions] Done flushing partition 0\n[00909.081] 05024.05132> paver:[FvmStreamPartitions] Streaming partition 1\n[00909.081] 05024.05132> paver:[StreamFvmPartition] Writing extent 0... \n[00909.081] 05024.05132> paver:[StreamFvmPartition] 8192 bytes written, 8380416 zeroes left\n[00909.120] 05024.05132> paver:[StreamFvmPartition] Writing extent 1... \n[00909.120] 05024.05132> paver:[StreamFvmPartition] 65536 bytes written, 8323072 zeroes left\n[00909.168] 05024.05132> paver:[StreamFvmPartition] Writing extent 2... \n[00909.168] 05024.05132> paver:[StreamFvmPartition] 65536 bytes written, 8323072 zeroes left\n[00909.204] 05024.05132> paver:[StreamFvmPartition] Writing extent 3... \n[00909.242] 05024.05132> paver:[StreamFvmPartition] Writing extent 4... \n[00909.252] 05024.05132> paver:[StreamFvmPartition] 2097152 bytes written, 14680064 zeroes left\n[00909.318] 05024.05132> paver:[StreamFvmPartition] Writing extent 5... \n[00909.319] 05024.05132> paver:[StreamFvmPartition] 57344 bytes written, 8331264 zeroes left\n[00909.355] 05024.05132> paver:[FvmStreamPartitions] Done streaming partition 1\n[00909.355] 05024.05132> paver:[FvmStreamPartitions] Done flushing partition 1\n[00909.356] 05112.05126> Reading FVM from compressed file: true\n[00909.356] 05112.05126> Remaining bytes read into compression buffer: 0\n[00909.356] 05112.05126> Remaining bytes written to decompression buffer: 0\n[00909.356] 05112.05126> Time reading bytes from sparse FVM file: 230465810 (0 s)\n[00909.356] 05112.05126> Time reading bytes AND decompressing them: 329604056 (0 s)\n[00909.356] 05024.05132> paver:[PartitionPave] Completed successfully\n2019/04/18 03:23:48 attempting to send <<image>>bootloader.img...\n2019/04/18 03:23:48 done\n2019/04/18 03:23:48 attempting to send <<image>>zircona.img...\n[00910.080] 05024.05038> netsvc: Running BOOTLOADER Paver\n[00910.083] 05024.05866> paver:[Initialize] Successfully initialized EFI Device Partitioner\n[00910.083] 05024.05866> paver:[RealMain] SKIPPING BOOTLOADER install on x64 device, pass --force if desired.\n[00910.091] 05024.05038> netsvc: tftp write of file <<image>>bootloader.img completed\n[00910.091] 05024.05038> netsvc: metrics: {\"inorderblks\": 1093,\"oooblks\": 0,\"ack\": 5,\"nack\": 0,\"timeouts\": 0,\"sas\": 0,\"inorderbytes\": 1118208}\n[00910.092] 05024.05038> netsvc: Running ZIRCON-A Paver\n[00910.095] 05024.06007> paver:[Initialize] Successfully initialized EFI Device Partitioner\n[00910.095] 05024.06007> paver:[PartitionPave] Paving partition.\n[00910.095] 05024.06007> paver:[FindFirstFit] Looking for space\n[00910.095] 05024.06007> paver:[FindFirstFit] Partition seen with start 34, end 16777249 (length 16777216)\n[00910.095] 05024.06007> paver:[FindFirstFit] Sorting\n[00910.095] 05024.06007> paver:[FindFirstFit] Partition[0] From Block [0, 34) ... (next partition starts at block 34)\n[00910.095] 05024.06007> paver:[FindFirstFit] There are 0 free blocks (32768 requested)\n[00910.095] 05024.06007> paver:[FindFirstFit] Partition[1] From Block [34, 16777250) ... (next partition starts at block 250069646)\n[00910.095] 05024.06007> paver:[FindFirstFit] There are 233292396 free blocks (32768 requested)\n[00910.095] 05024.06007> paver:[AddPartition] Found space in GPT - OK 233292396 @ 16777250\n[00910.095] 05024.06007> paver:[AddPartition] Final space in GPT - OK 32768 @ 16777250\n[00910.096] 05024.06007> paver:[AddPartition] Added partition, waiting for bind\n[00910.096] 03301.03369> block: Joining un-closed FIFO server\n[00910.096] 03301.03369> block: Joining un-closed FIFO server\n[00910.096] 01104.01117> devcoord: dc_bind_device() ''\n[00910.097] 01182.01202> devmgr: /dev/class/block/003: GPT?\n[00910.097] 01104.01117> devcoord: dc_bind_device() '/boot/driver/gpt.so'\n[00910.097] 03301.03369> gpt: device_get_metadata failed (-25)\n[00910.098] 01182.01202> devmgr: /dev/class/block/013: FVM?\n[00910.098] 01104.01117> devcoord: dc_bind_device() '/boot/driver/fvm.so'\n[00910.098] 05024.06007> paver:[AddPartition] Added partition, waiting for bind - OK\n2019/04/18 03:23:48 done\n2019/04/18 03:23:48 attempting to send <<image>>zirconr.img...\n2019/04/18 03:23:48 target is busy, retrying in one second\n[00910.227] 05024.05038> netsvc: tftp write of file <<image>>zircona.img completed\n[00910.227] 05024.05038> netsvc: metrics: {\"inorderblks\": 13811,\"oooblks\": 0,\"ack\": 54,\"nack\": 0,\"timeouts\": 0,\"sas\": 0,\"inorderbytes\": 14141800}\n[00910.253] 05024.06007> paver:[PartitionPave] Completed successfully\n2019/04/18 03:23:49 attempting to send <<image>>zirconr.img...\n[00911.228] 05024.05038> netsvc: Running ZIRCON-R Paver\n[00911.231] 05024.06280> paver:[Initialize] Successfully initialized EFI Device Partitioner\n[00911.231] 05024.06280> paver:[PartitionPave] Paving partition.\n[00911.231] 05024.06280> paver:[FindFirstFit] Looking for space\n[00911.231] 05024.06280> paver:[FindFirstFit] Partition seen with start 34, end 16777249 (length 16777216)\n[00911.231] 05024.06280> paver:[FindFirstFit] Partition seen with start 16777250, end 16810017 (length 32768)\n[00911.231] 05024.06280> paver:[FindFirstFit] Sorting\n[00911.231] 05024.06280> paver:[FindFirstFit] Partition[0] From Block [0, 34) ... (next partition starts at block 34)\n[00911.231] 05024.06280> paver:[FindFirstFit] There are 0 free blocks (49152 requested)\n[00911.231] 05024.06280> paver:[FindFirstFit] Partition[1] From Block [34, 16777250) ... (next partition starts at block 16777250)\n[00911.231] 05024.06280> paver:[FindFirstFit] There are 0 free blocks (49152 requested)\n[00911.231] 05024.06280> paver:[FindFirstFit] Partition[2] From Block [16777250, 16810018) ... (next partition starts at block 250069646)\n[00911.231] 05024.06280> paver:[FindFirstFit] There are 233259628 free blocks (49152 requested)\n[00911.231] 05024.06280> paver:[AddPartition] Found space in GPT - OK 233259628 @ 16810018\n[00911.231] 05024.06280> paver:[AddPartition] Final space in GPT - OK 49152 @ 16810018\n[00911.231] 05024.06280> paver:[AddPartition] Added partition, waiting for bind\n[00911.231] 03301.03369> block: Joining un-closed FIFO server\n[00911.232] 01104.01117> devcoord: dc_bind_device() ''\n[00911.233] 01182.01202> devmgr: /dev/class/block/003: GPT?\n[00911.233] 01104.01117> devcoord: dc_bind_device() '/boot/driver/gpt.so'\n[00911.233] 03301.03369> gpt: device_get_metadata failed (-25)\n[00911.234] 01182.01202> devmgr: /dev/class/block/017: FVM?\n[00911.234] 01104.01117> devcoord: dc_bind_device() '/boot/driver/fvm.so'\n[00911.234] 05024.06280> paver:[AddPartition] Added partition, waiting for bind - OK\n2019/04/18 03:23:49 done\n2019/04/18 03:23:49 attempting to send <<image>>authorized_keys...\n2019/04/18 03:23:49 target is busy, retrying in one second\n[00911.352] 05024.05038> netsvc: tftp write of file <<image>>zirconr.img completed\n[00911.352] 05024.05038> netsvc: metrics: {\"inorderblks\": 12519,\"oooblks\": 0,\"ack\": 49,\"nack\": 0,\"timeouts\": 0,\"sas\": 0,\"inorderbytes\": 12819048}\n[00911.389] 05024.06280> paver:[PartitionPave] Completed successfully\n2019/04/18 03:23:50 attempting to send <<image>>authorized_keys...\n2019/04/18 03:23:50 done\n2019/04/18 03:23:50 attempting to send <<netboot>>kernel.bin...\n2019/04/18 03:23:50 target is busy, retrying in one second\n[00912.354] 05024.05038> netsvc: Installing SSH authorized_keys\n[00912.354] 05024.05038> netsvc: tftp write of file <<image>>authorized_keys completed\n[00912.354] 05024.05038> netsvc: metrics: {\"inorderblks\": 1,\"oooblks\": 0,\"ack\": 1,\"nack\": 0,\"timeouts\": 0,\"sas\": 0,\"inorderbytes\": 806}\n[00912.357] 05024.06570> paver:[Initialize] Successfully initialized EFI Device Partitioner\n[00912.357] 01104.01117> devcoord: dc_bind_device() '/boot/driver/zxcrypt.so'\n[00912.357] 03301.03369> devhost_get_handles(0x1056bad29900:block) open path='zxcrypt', r=-2\n[00912.384] 05024.06570> paver:[DataFilePave] Wrote ssh/authorized_keys\n2019/04/18 03:23:51 attempting to send <<netboot>>kernel.bin...\n2019/04/18 03:23:51 done\n[00000.000] 00000.00000> zbi: @ 0xffffff8005ddd000 (12627928 bytes)\n[00000.000] 00000.00000> UART: FIFO depth 16\n[00000.000] 00000.00000> PMM: boot reserve add [0x100000, 0x2fcfff]\n[00000.000] 00000.00000> PMM: boot reserve add [0x5ddd000, 0x69e7fff]\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 0x8afff000 size 0x1000\n[00000.000] 00000.00000> PMM: boot reserve marking WIRED [0x100000, 0x2fcfff]\n[00000.000] 00000.00000> PMM: boot reserve marking WIRED [0x5ddd000, 0x69e7fff]\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 0xffffffff00114e2c (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 [0x69e8000, 0x69e8100)\n[00000.000] 00000.00000> INIT: cpu 0, calling hook 0xffffffff001221dc (elf_build_id) at level 0x4fffe, flags 0x1\n[00000.000] 00000.00000> INIT: cpu 0, calling hook 0xffffffff00122368 (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: XXX\n[00000.000] 00000.00000> \ttarget: XXX\n[00000.000] 00000.00000> \tproject: x64\n[00000.000] 00000.00000> \tbuildid: git-db523e680c83eb5b5b47ab4f86b6a84254e303a4-dirty\n[00000.000] 00000.00000> \tELF build ID: ad3796bc07167fb7b788926965c7ac170255c8ef\n[00000.000] 00000.00000> initializing heap\n[00000.000] 00000.00000> INIT: cpu 0, calling hook 0xffffffff00101fc4 (console) at level 0x50000, flags 0x1\n[00000.000] 00000.00000> INIT: cpu 0, calling hook 0xffffffff00181a10 (x86_resource_init) at level 0x50000, flags 0x1\n[00000.000] 00000.00000> initializing vm\n[00000.000] 00000.00000> VM: reserving kernel region [0xffffffff00100000, 0xffffffff00219000) flags 0x28 name 'kernel_code'\n[00000.000] 00000.00000> VM: reserving kernel region [0xffffffff00219000, 0xffffffff00269000) flags 0x8 name 'kernel_rodata'\n[00000.000] 00000.00000> VM: reserving kernel region [0xffffffff00269000, 0xffffffff00271000) flags 0x18 name 'kernel_data'\n[00000.000] 00000.00000> VM: reserving kernel region [0xffffffff00271000, 0xffffffff002fd000) flags 0x18 name 'kernel_bss'\n[00000.000] 00000.00000> INIT: cpu 0, calling hook 0xffffffff001826d4 (display_memtype) at level 0x60001, flags 0x1\n[00000.000] 00000.00000> INIT: cpu 0, calling hook 0xffffffff00185b64 (acpi_tables) at level 0x60001, flags 0x1\n[00000.000] 00000.00000> INIT: cpu 0, calling hook 0xffffffff00180814 (hpet) at level 0x60002, flags 0x1\n[00000.000] 00000.00000> INIT: cpu 0, calling hook 0xffffffff00180bd4 (apic) at level 0x60002, flags 0x1\n[00000.000] 00000.00000> x2APIC enabled\n[00000.000] 00000.00000> INIT: cpu 0, calling hook 0xffffffff001a71bc (system_topology_init) at level 0x60002, flags 0x1\n[00000.000] 00000.00000> WARNING: more than 1000 levels of cache, couldn't find highest.\n[00000.000] 00000.00000> WARNING: unable to find any cache levels.\n[00000.000] 00000.00000> Could not find SRAT table. ACPICA returned: 5\n[00000.000] 00000.00000> INIT: cpu 0, calling hook 0xffffffff00185154 (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[00913.773] 00000.00000> timer features: constant_tsc 1 invariant_tsc 1 tsc_deadline 1\n[00913.773] 00000.00000> Using TSC as wallclock\n[00913.773] 00000.00000> INIT: cpu 0, calling hook 0xffffffff00207070 (percpu_heap_init) at level 0x60003, flags 0x1\n[00913.773] 00000.00000> initializing kernel\n[00913.773] 00000.00000> initializing mp\n[00913.773] 00000.00000> INIT: cpu 0, calling hook 0xffffffff00115080 (global_prng_thread_safe) at level 0x7ffff, flags 0x1\n[00913.773] 00000.00000> creating bootstrap completion thread\n[00913.773] 00000.00000> top of bootstrap2()\n[00913.773] 00000.00000> INIT: cpu 0, calling hook 0xffffffff00131058 (libobject) at level 0x80000, flags 0x1\n[00913.773] 00000.00000> OOM: started thread\n[00913.773] 00000.00000> INIT: cpu 0, calling hook 0xffffffff00203fdc (dpc) at level 0x80000, flags 0x1\n[00913.773] 00000.00000> Processor Model Info: type 0 family 0x6 model 0xe stepping 0x9\n[00913.773] 00000.00000> \tdisplay_family 0x6 display_model 0x8e\n[00913.773] 00000.00000> Vendor: Intel\n[00913.773] 00000.00000> Microarch: Kaby Lake\n[00913.773] 00000.00000> F/M/S: 6/8e/9\n[00913.773] 00000.00000> patch_level: 8e\n[00913.773] 00000.00000> Brand: Intel(R) Core(TM) i5-7300U CPU @ 2.60GHz\n[00913.773] 00000.00000> Features: fpu sse sse2 sse3 ssse3 sse4.1 sse4.2 mmx avx avx2 fxsr pcid xsave mon aesni clflush \n[00913.773] 00000.00000> clflushopt fsgsbase tsc_adj smep smap erms rdrand rdseed syscall nx huge rdtscp \n[00913.773] 00000.00000> invar_tsc tsc_deadline x2apic vmx pt hwp \n[00913.773] 00000.00000> Properties: meltdown l1tf pcid_good \n[00913.773] 00000.00000> initializing platform\n[00913.773] 00000.00000> INIT: cpu 0, calling hook 0xffffffff001a08cc (x86_perfmon) at level 0x90000, flags 0x1\n[00913.773] 00000.00000> PMU: version 4\n[00913.773] 00000.00000> UART: started IRQ driven RX\n[00913.773] 00000.00000> UART: started IRQ driven TX\n[00913.773] 00000.00000> cpu topology:\n[00913.773] 00000.00000> \t0: apic id 0x0 BSP\n[00913.773] 00000.00000> \t1: apic id 0x1 \n[00913.773] 00000.00000> \t2: apic id 0x2 \n[00913.773] 00000.00000> \t3: apic id 0x3 \n[00913.773] 00000.00000> Found 4 cpus\n[00913.774] 00000.00000> booting apic ids: 0x1 0x2 0x3 \n[00913.788] 00000.00000> entering scheduler on cpu 1\n[00913.790] 00000.00000> entering scheduler on cpu 2\n[00913.790] 00000.00000> entering scheduler on cpu 3\n[00913.792] 00000.00000> smbios: manufacturer=\"Intel Corporation\" product=\"NUC7i5DNHE\"\n[00913.792] 00000.00000> initializing target\n[00913.792] 00000.00000> INIT: cpu 0, calling hook 0xffffffff00184404 (x86_pcie_init) at level 0xa0000, flags 0x1\n[00913.792] 00000.00000> moving to last init level\n[00913.792] 00000.00000> INIT: cpu 0, calling hook 0xffffffff00121434 (debuglog) at level 0xb0000, flags 0x1\n[00913.792] 00000.00000> INIT: cpu 0, calling hook 0xffffffff0017408c (kcounters) at level 0xb0000, flags 0x1\n[00913.792] 00000.00000> INIT: cpu 0, calling hook 0xffffffff00102aec (kernel_shell) at level 0xc0000, flags 0x1\n[00913.792] 00000.00000> INIT: cpu 0, calling hook 0xffffffff00201214 (ktrace) at level 0xc0000, flags 0x1\n[00913.796] 00000.00000> ktrace: buffer at 0xffffff9005da1000 (33554432 bytes)\n[00913.796] 00000.00000> INIT: cpu 0, calling hook 0xffffffff00216838 (userboot) at level 0xc0000, flags 0x1\n[00913.796] 00000.00000> userboot: ramdisk 0xc0b000 @ 0xffffff8005ddd000\n[00913.796] 00000.00000> userboot: userboot rodata 0 @ [0x57149dd08000,0x57149dd0b000)\n[00913.796] 00000.00000> userboot: userboot code 0x3000 @ [0x57149dd0b000,0x57149dd16000)\n[00913.796] 00000.00000> userboot: vdso/full rodata 0 @ [0x57149dd16000,0x57149dd1d000)\n[00913.796] 00000.00000> userboot: vdso/full code 0x7000 @ [0x57149dd1d000,0x57149dd1e000)\n[00913.796] 00000.00000> userboot: entry point @ 0x57149dd0bc90\n[00913.796] 01036.01043> userboot: option \"zircon.autorun.system=/boot/bin/sh+/boot/infra/runcmds\"\n[00913.826] 01036.01043> userboot: searching bootfs for 'bin/bootsvc'\n[00913.826] 01036.01043> userboot: 'bin/bootsvc' has PT_INTERP \"lib/ld.so.1\"\n[00913.826] 01036.01043> userboot: searching bootfs for 'lib/ld.so.1'\n[00913.826] 01036.01043> userboot: userboot: loaded lib/ld.so.1 at 0x5998e8801000, entry point 0x5998e881f3d0\n[00913.826] 01036.01043> userboot: userboot: loaded vDSO at 0x79768489a000, entry point 0x7976848a18fa\n[00913.826] 01036.01043> userboot: process bin/bootsvc started.\n[00913.826] 01036.01043> userboot: waiting for loader-service requests...\n[00913.826] 01036.01043> userboot: searching bootfs for 'lib/libasync-default.so'\n[00913.826] 01036.01043> userboot: searching bootfs for 'lib/libfdio.so'\n[00913.826] 01036.01043> userboot: searching bootfs for 'lib/libtrace-engine.so'\n[00913.826] 01036.01043> userboot: searching bootfs for 'lib/liblaunchpad.so'\n[00913.826] 01050.01053> {{{reset}}}\n[00913.826] 01050.01053> {{{module:0:<application>:elf:c77c4e38fc5058ecd8c644c9a1f8c22836bc17f2}}}\n[00913.826] 01050.01053> {{{mmap:0x35f40bc18000:0x3a000:load:0:rx:0}}}\n[00913.826] 01050.01053> {{{mmap:0x35f40bc52000:0x4000:load:0:rw:0x3a000}}}\n[00913.826] 01050.01053> dso: id=c77c4e38fc5058ecd8c644c9a1f8c22836bc17f2 base=0x000035f40bc18000 name=<application>\n[00913.826] 01050.01053> {{{module:0x2:<vDSO>:elf:0db263a6dbb45a10ea0a4b329d710e0f56d8315e}}}\n[00913.826] 01050.01053> {{{mmap:0x79768489a000:0x7000:load:0x2:r:0}}}\n[00913.826] 01050.01053> {{{mmap:0x7976848a1000:0x1000:load:0x2:rx:0x7000}}}\n[00913.826] 01050.01053> dso: id=0db263a6dbb45a10ea0a4b329d710e0f56d8315e base=0x000079768489a000 name=<vDSO>\n[00913.826] 01050.01053> {{{module:0x3:libasync-default.so:elf:8c511b4202cf569c8fdde14ca97222102ba3a9e0}}}\n[00913.826] 01050.01053> {{{mmap:0x10e8a5fdb000:0x1000:load:0x3:rx:0}}}\n[00913.826] 01050.01053> {{{mmap:0x10e8a5fdc000:0x1000:load:0x3:rw:0x1000}}}\n[00913.826] 01050.01053> dso: id=8c511b4202cf569c8fdde14ca97222102ba3a9e0 base=0x000010e8a5fdb000 name=libasync-default.so\n[00913.826] 01050.01053> {{{module:0x4:libfdio.so:elf:6b9d6c01a1b1dceae0f80e625ebd3da0867d7aac}}}\n[00913.826] 01050.01053> {{{mmap:0x499562f32000:0x32000:load:0x4:rx:0}}}\n[00913.826] 01050.01053> {{{mmap:0x499562f65000:0x4000:load:0x4:rw:0x33000}}}\n[00913.826] 01050.01053> dso: id=6b9d6c01a1b1dceae0f80e625ebd3da0867d7aac base=0x0000499562f32000 name=libfdio.so\n[00913.826] 01050.01053> {{{module:0x5:libtrace-engine.so:elf:b82e75659fdaaa34e91100dc98d0a90f14f77ded}}}\n[00913.826] 01050.01053> {{{mmap:0x72b447d3c000:0x9000:load:0x5:rx:0}}}\n[00913.826] 01050.01053> {{{mmap:0x72b447d45000:0x2000:load:0x5:rw:0x9000}}}\n[00913.826] 01050.01053> dso: id=b82e75659fdaaa34e91100dc98d0a90f14f77ded base=0x000072b447d3c000 name=libtrace-engine.so\n[00913.826] 01050.01053> {{{module:0x6:liblaunchpad.so:elf:5b0854856213eae6bab93c982f39551f8f9591c5}}}\n[00913.826] 01050.01053> {{{mmap:0x107d41599000:0x7000:load:0x6:rx:0}}}\n[00913.826] 01050.01053> {{{mmap:0x107d415a0000:0x2000:load:0x6:rw:0x7000}}}\n[00913.826] 01050.01053> dso: id=5b0854856213eae6bab93c982f39551f8f9591c5 base=0x0000107d41599000 name=liblaunchpad.so\n[00913.826] 01050.01053> {{{module:0x1:libc.so:elf:5d417db61b3a48a58a8fa1ffbfc2e71b830e0857}}}\n[00913.826] 01050.01053> {{{mmap:0x5998e8801000:0xa6000:load:0x1:rx:0}}}\n[00913.826] 01050.01053> {{{mmap:0x5998e88a7000:0x5000:load:0x1:rw:0xa6000}}}\n[00913.826] 01050.01053> dso: id=5d417db61b3a48a58a8fa1ffbfc2e71b830e0857 base=0x00005998e8801000 name=libc.so\n[00913.826] 01050.01053> bootsvc: Starting...\n[00913.826] 01036.01043> userboot: loader-service channel peer closed\n[00913.826] 01036.01043> userboot: finished!\n[00913.826] 01050.01053> bootsvc: Creating bootfs service...\n[00913.827] 01050.01053> bootsvc: Retrieving boot image...\n[00913.827] 01050.01053> bootsvc: Decommitted BOOTDATA VMO from 0 to 0xc0a000\n[00913.827] 01050.01053> bootsvc: Loading boot arguments...\n[00913.827] 01050.01053> bootsvc: Creating svcfs service...\n[00913.827] 01050.01053> bootsvc: Loading kernel VMOs...\n[00913.827] 01050.01053> bootsvc: Creating loader service...\n[00913.827] 01050.01053> bootsvc: Launching next process...\n[00913.827] 01050.01108> bootsvc: Launched bin/devcoordinator\n[00913.828] 01115.01130> devcoordinator: launch /boot/bin/svchost (svchost) OK\n[00913.829] 01115.01130> devcoordinator: launch /boot/bin/fshost (fshost) OK\n[00913.831] 01115.01321> devcoordinator: launch /boot/bin/pwrbtn-monitor (pwrbtn-monitor) OK\n[00913.832] 01115.01346> devcoordinator: launch /boot/bin/netsvc (netsvc) OK\n[00913.832] 01115.01346> devcoordinator: launch /boot/bin/virtual-console (virtual-console) OK\n[00913.836] 01115.01130> devcoordinator: full system required, ignoring fallback drivers until /system is loaded\n[00913.836] 01115.01130> devcoordinator: launch devhost 'devhost:sys': pid=2189\n[00913.836] 01115.01130> devcoordinator: launch devhost 'devhost:test': pid=2221\n[00913.837] 01115.01130> devcoordinator: launch devhost 'devhost:root': pid=2270\n[00913.838] 01115.01130> devcoordinator: launch devhost 'devhost:misc': pid=2343\n[00913.838] 02189.02203> devhost: trace provider registry begun\n[00913.838] 02221.02243> devhost: trace provider registry begun\n[00913.839] 02270.02318> devhost: trace provider registry begun\n[00913.840] 02343.02390> devhost: trace provider registry begun\n[00913.843] 01115.01333> devcoordinator: launch /boot/bin/sh (sh:console) OK\n[00913.926] 02189.02203> acpi-bus: not using IOMMU\n[00913.933] 02189.02203> PMU: 7 arch events\n[00913.933] 02189.02203> PMU: arch event id range: 1-7\n[00913.933] 02189.02203> PMU: 102 arch events\n[00913.933] 02189.02203> PMU: arch event id range: 1-241\n[00913.933] 02189.02203> Intel Processor Trace configuration for this chipset:\n[00913.933] 02189.02203> mtc_freq_mask: 0x249\n[00913.933] 02189.02203> cyc_thresh_mask: 0x3fff\n[00913.933] 02189.02203> psb_freq_mask: 0x3f\n[00913.933] 02189.02203> num addr ranges: 2\n[00913.933] 02189.02203> [sysmem_init 28] async_get_default_dispatcher(): 0x39317c2dfd90\n[00913.933] 02189.02203> [sysmem_bind 40] sysmem_bind()\n[00913.933] 02189.02881> acpi-pwrbtn: initialized\n[00913.933] 01707.01747> vc: new input device /dev/class/input/000\n[00913.964] 02189.02881> acpi: published device pci(0x3930bc33f710), parent=sys(0x3931fc2dea10), handle=0x39307c2f5350\n[00913.965] 01115.01130> devcoordinator: launch devhost 'devhost:pci#1:8086:5916': pid=2977\n[00913.965] 01115.01130> devcoordinator: launch devhost 'devhost:pci#3:8086:9d2f': pid=3030\n[00913.967] 02189.02881> acpi: published device rtc(0x3930bc2f9c30), parent=acpi(0x3931fc2ddb10), handle=0x39307c31b6d0\n[00913.968] 02977.02991> devhost: trace provider registry begun\n[00913.968] 01115.01130> devcoordinator: launch devhost 'devhost:pci#5:8086:9d60': pid=3145\n[00913.968] 02189.02881> acpi-ec: initialized\n[00913.969] 03030.03053> devhost: trace provider registry begun\n[00913.969] 01115.01130> devcoordinator: launch devhost 'devhost:pci#6:8086:9d61': pid=3268\n[00913.970] 03145.03172> devhost: trace provider registry begun\n[00913.970] 01115.01130> devcoordinator: launch devhost 'devhost:pci#9:8086:9d03': pid=3352\n[00913.970] 03268.03289> devhost: trace provider registry begun\n[00913.970] 01115.01130> devcoordinator: launch devhost 'devhost:pci#14:8086:9d71': pid=3486\n[00913.971] 03352.03390> devhost: trace provider registry begun\n[00913.971] 01115.01130> devcoordinator: launch devhost 'devhost:pci#16:8086:156f': pid=3600\n[00913.972] 03486.03525> devhost: trace provider registry begun\n[00913.973] 03352.03390> ahci: using MSI interrupt\n[00913.973] 03268.03289> initialized intel serialio i2c driver, reg=0x454caeff4000 regsize=4096\n[00913.973] 03145.03172> initialized intel serialio i2c driver, reg=0x21b71081f000 regsize=4096\n[00913.974] 02189.02881> acpi: failed to create NHLT VMO (res -10)\n[00913.974] 02189.02881> acpi: failed to publish NHLT metadata\n[00913.974] 03600.03639> devhost: trace provider registry begun\n[00913.982] 03486.03525> [IHDA DSP 00:1f.3] Failed to fetch NHLT (res -25)\n[00913.982] 03486.03525> [IHDA Controller 00:1f.3] Failed to initialize DSP device (res = -25)\n[00913.983] 03030.04024> * found USB device (0x18d1:0xa002, USB 2.0) config 1\n[00913.983] 03030.04024> * found USB device (0x18d1:0xa003, USB 3.0) config 1\n[00914.056] 01621.01653> netifc: ? /dev/class/ethernet/000\n[00914.056] 01621.01653> netifc: create 512 eth buffers\n[00914.056] 01621.01653> macaddr: 54:b2:03:13:b3:e7\n[00914.056] 01621.01653> ip6addr: fe80::56b2:34d:fe13:b3e7\n[00914.056] 01621.01653> snmaddr: ff02::1:ff13:b3e7\n[00914.056] 01621.01653> netsvc: using /dev/class/ethernet/000\n[00914.056] 01621.01653> netsvc: nodename='rash-moan-copy-slob'\n[00914.056] 01621.01653> netsvc: start\n[00914.083] 01707.01747> vc: new display device /dev/class/display-controller/000\n[00914.123] 02977.04246> i915: MST not supported\n[00914.626] 02977.04246> i915: MST not supported\n[00914.696] 03030.04024> * found USB device (0x0781:0x5583, USB 3.0) config 1\n[00915.446] 03030.04024> * found USB device (0x0cf3:0xe300, USB 2.1) config 1\n[00915.671] 02977.04246> i915: No displays detected\n[00915.978] 03352.03826> sata2: dev info\n[00915.978] 03352.03826> serial=AA000000000000008069\n[00915.978] 03352.03826> firmware rev=0R08A1 0\n[00915.978] 03352.03826> model id=ETMAT 8MSP1582 G \n[00915.978] 03352.03826> major=0x3f0 ACS2 DMA 32 commands\n[00915.978] 03352.03826> LBA48 250069680 sectors, sector size=512\n[00915.979] 01299.01313> fshost: /dev/class/block/000: GPT?\n[00915.979] 03352.03390> gpt: device_get_metadata failed (-25)\n[00915.980] 01299.01313> fshost: /dev/class/block/001: FVM?\n[00915.981] 03268.03289> intel-i2c-controller: intel_serialio_i2c_slave_transfer: -21\n[00915.981] 03268.03289> i2c-hid: could not read HID descriptor: 0\n[00915.981] 03268.03289> devhost[00:15.1/i2c-bus-9d61/004c] bind driver '/boot/driver/i2c-hid.so' failed: -2\n[00915.981] 01115.01130> devcoordinator: rpc: bind-driver '004c' status -2\n[00915.982] 03145.03172> intel-i2c-controller: intel_serialio_i2c_slave_transfer: -21\n[00915.982] 03145.03172> i2c-hid: could not read HID descriptor: 0\n[00915.982] 03145.03172> devhost[00:15.0/i2c-bus-9d60/0020] bind driver '/boot/driver/i2c-hid.so' failed: -2\n[00915.982] 01115.01130> devcoordinator: rpc: bind-driver '0020' status -2\n[00915.983] 01299.01313> devcoordinator: launch /boot/bin/blobfs (blobfs:/blob) OK\n[00916.118] 01299.01313> fshost: starting 'bin/pkgsvr' '518485b20cee32d8fb564f70297ff8a2339c6eb0da3ea0edb8cda676eb46fe6b'...\n[00916.125] 01299.01313> devcoordinator: launch bin/pkgsvr (pkgfs) OK\n[00916.135] 04637.04848> pkgsvr: system: will be served from 518485b20cee32d8fb564f70297ff8a2339c6eb0da3ea0edb8cda676eb46fe6b\n[00916.135] 04637.04848> pkgsvr: pkgfs serving index /data/pkgfs_index from blobfs /blob\n[00916.135] 01299.01313> fshost: /dev/class/block/005: zxcrypt?\n[00916.135] 03352.03390> devhost_get_handles(0x323483f1a110:block) open path='zxcrypt', r=-2\n[00916.138] 01299.01313> fshost: mounting minfs\n[00916.138] 01299.01313> devcoordinator: launch /boot/bin/minfs (minfs:/data) OK\n[00916.165] 01115.01761> devcoordinator: launch /system/bin/appmgr (appmgr) OK\n[00916.165] 01115.01761> autorun: starting '/boot/bin/sh' '/boot/infra/runcmds'...\n[00916.169] 01115.04892> devcoordinator: adding system driver 'brcmfmac' '/system/driver/brcmfmac.so'\n[00916.170] 01115.01761> devcoordinator: launch /boot/bin/sh (autorun:system) OK\n[00916.185] 01115.04892> devcoordinator: adding system driver 'rtl88xx' '/system/driver/rtl88xx.so'\n[00916.192] 01115.04892> devcoordinator: adding system driver 'ath10k_pci' '/system/driver/ath10k.so'\n[00916.201] 01115.04892> devcoordinator: adding system driver 'magma_pdev_gpu' '/system/driver/libmsd_arm.so'\n[00916.256] 01115.04892> devcoordinator: adding system driver 'wlan' '/system/driver/wlan.so'\n[00916.285] 01115.04892> devcoordinator: adding system driver 'bt_host' '/system/driver/bt-host.so'\n[00916.295] 01115.04892> devcoordinator: adding system driver 'gpu' '/system/driver/libmsd_intel.so'\n[00916.306] 01115.04892> devcoordinator: adding system driver 'usb_video' '/system/driver/usb_video.so'\n[00916.310] 01115.04892> devcoordinator: adding system driver 'qmi_fake' '/system/driver/qmi-fake.so'\n[00916.367] 01115.04892> devcoordinator: adding system driver 'ralink' '/system/driver/ralink.so'\n[00916.379] 01115.04892> devcoordinator: adding system driver 'wlan' '/system/driver/wlanphy.so'\n[00916.387] 01115.04892> devcoordinator: adding system driver 'virtual_audio' '/system/driver/virtual_audio_driver.so'\n[00916.404] 01115.04892> devcoordinator: adding system driver 'mt8167s_gpu' '/system/driver/libmsd_img_rgx_mtk.so'\n[00916.414] 01115.04892> devcoordinator: adding system driver 'qmi_usb' '/system/driver/qmi-transport.so'\n[00916.426] 05163.05181> [INFO:namespace_builder.cc(93)] config-data for sysmgr\n[00916.438] 01115.04892> devcoordinator: adding system driver 'bt_hci_fake' '/system/driver/bt-hci-fake.so'\n[00916.440] 01115.04892> devcoordinator: adding system driver 'bt_hci_passthrough' '/system/driver/bt-hci-passthrough.so'\n[00916.441] 01115.04892> devcoordinator: adding system driver 'bt_hog' '/system/driver/bt-hog.so'\n[00916.466] 01115.04892> devcoordinator: adding system driver 'bt_hci_atheros' '/system/driver/bt-hci-atheros.so'\n[00916.482] 01115.04892> devcoordinator: adding system driver 'virtual_camera' '/system/driver/virtual_camera_driver.so'\n[00916.507] 01115.04892> devcoordinator: adding system driver 'bt_hci_intel' '/system/driver/bt-hci-intel.so'\n[00916.509] 01115.04892> devcoordinator: adding system driver 'iwlwifi_pci' '/system/driver/iwlwifi.so'\n[00916.518] 01115.04892> devcoordinator: adding system driver 'wlan' '/system/driver/wlanif.so'\n[00916.518] 01115.01130> devcoordinator: driver 'wlan' added\n[00916.518] 01115.01130> devcoordinator: driver 'iwlwifi_pci' added\n[00916.518] 01115.01130> devcoordinator: driver 'bt_hci_intel' added\n[00916.518] 01115.01130> devcoordinator: driver 'bt_hci_atheros' added\n[00916.518] 01115.01130> devcoordinator: driver 'bt_hog' added\n[00916.518] 01115.01130> devcoordinator: driver 'bt_hci_fake' added\n[00916.518] 01115.01130> devcoordinator: driver 'qmi_usb' added\n[00916.518] 01115.01130> devcoordinator: driver 'mt8167s_gpu' added\n[00916.518] 01115.01130> devcoordinator: driver 'wlan' added\n[00916.518] 01115.01130> devcoordinator: driver 'ralink' added\n[00916.518] 01115.01130> devcoordinator: driver 'qmi_fake' added\n[00916.518] 01115.01130> devcoordinator: driver 'usb_video' added\n[00916.518] 01115.01130> devcoordinator: driver 'gpu' added\n[00916.518] 01115.01130> devcoordinator: driver 'bt_host' added\n[00916.518] 01115.01130> devcoordinator: driver 'wlan' added\n[00916.518] 01115.01130> devcoordinator: driver 'magma_pdev_gpu' added\n[00916.518] 01115.01130> devcoordinator: driver 'ath10k_pci' added\n[00916.519] 01115.01130> devcoordinator: launch devhost 'devhost:pci#11:168c:003e': pid=5969\n[00916.519] 01115.01130> devcoordinator: driver 'rtl88xx' added\n[00916.519] 01115.01130> devcoordinator: driver 'brcmfmac' added\n[00916.519] 01115.01130> devcoordinator: driver 'bt_hci_passthrough' added\n[00916.519] 01115.01130> devcoordinator: fallback driver 'usb_composite' is available\n[00916.519] 01115.01130> devcoordinator: driver 'usb_composite' added\n[00916.519] 01115.01130> devcoordinator: fallback driver 'intel_disp' is available\n[00916.519] 01115.01130> devcoordinator: driver 'intel_disp' added\n[00916.521] 03030.03053> UMS: parent: 'ifc-000'\n[00916.522] 05969.06002> devhost: trace provider registry begun\n[00916.522] 03030.03053> UMS:Max lun is: 0\n[00916.522] 05969.06002> ath10k: Probed chip QCA6174 ver: 2.1\n[00916.522] 03030.03053> devhost[00:14.0/xhci/usb-bus/002/002/ifc-001] bind driver '/boot/driver/bt-transport-usb.so' failed: -2\n[00916.523] 01115.01130> devcoordinator: rpc: bind-driver 'ifc-001' status -2\n[00916.524] 03030.06233> UMS: block size is: 0x00000200\n[00916.524] 03030.06233> UMS: total blocks is: 30031872\n[00916.524] 03030.06233> UMS: total size is: 15376318464\n[00916.524] 03030.06233> UMS: read-only: 0 removable: 1\n[00916.550] 03030.08892> btatheros: Making visible\n[00916.550] 03030.08892> btatheros: loaded successfully\n[00916.551] 03030.09147> [INFO:command_channel.cc(149)] hci: initialized\n[00916.552] 01299.01313> fshost: /dev/class/block/007: MBR?\n[00916.554] 01299.01313> fshost: /dev/class/block/009: MBR?\n[00916.618] 03030.09147> [WARN:adapter.cc(274)] gap: controller is using legacy HCI version 4.1\n[00916.624] 03030.09147> [INFO:acl_data_channel.cc(91)] hci: initialized\n[00916.625] 05163.05181> [INFO:namespace_builder.cc(93)] config-data for amber\n[00916.691] 05163.05181> [INFO:namespace_builder.cc(93)] config-data for pkg_resolver\n[00916.837] 13651.13663> [INFO:cobalt_main.cc(219)] Cobalt is starting with the following parameters: schedule_interval=3600 seconds, min_interval=10 seconds, initial_interval=60 seconds, max_bytes_per_observation_store=1048576, event_aggregator_bac\n[00916.837] 13651.13663> kfill_days=2, start_event_aggregator_worker=1.\n[00916.899] 05969.13574> devhost: rpc:load-firmware failed: -25\n[00916.899] 05969.13574> devhost: rpc:load-firmware failed: -25\n[00916.905] 05163.05181> [INFO:namespace_builder.cc(93)] config-data for wlancfg\n[00917.136] 05163.05181> [INFO:namespace_builder.cc(93)] config-data for crashpad_agent\n[00917.182] 16720.16732> [INFO:main.cc(35)] Trace Manager starting with config: /pkg/data/tracing.config\n[00917.197] 15512.15526> [INFO:system_metrics_main.cc(23)] Cobalt SystemMetricsDaemon: System metrics daemon created.\n[00917.401] 17150.17162> wlanstack2 [I]: Starting\n[00917.601] 05969.12816> ath10k: Unknown eventid: 0x1d019\n[00917.604] 05969.12816> ath10k: Unknown eventid: 0x16006\n[00917.610] 05969.06002> wlanphy: event loop started\n[00917.610] 05969.06002> wlanphy_bind\n[00917.610] 17150.17162> wlanstack2::device [I]: new phy #0: /dev/sys/pci/01:00.0/ath10k-wlanphy/wlanphy\n[00917.610] 14467.14479> wlancfg got event: OnPhyAdded { phy_id: 0 }\n[00917.610] 14467.14479> wlancfg: phy 0 added\n[00917.610] 17150.17162> wlanstack2::service [I]: query_phy(id = 0)\n[00917.611] 17150.17162> wlanstack2::service [I]: query_phy(id = 0): received a 'QueryResult' from device\n[00917.611] 14467.14479> wlancfg: received a PhyInfo from phy #0: path is /dev/sys/pci/01:00.0/ath10k-wlanphy/wlanphy\n[00917.611] 14467.14479> using default wlan config entry for phy\n[00917.611] 14467.14479> wlancfg: Creating Client iface for phy 0\n[00917.617] 05969.06002> wlan_bind\n[00917.619] 05969.06002> ath10k: adding a station interface (vdev_id=0) ...\n[00917.620] 05969.06002> wlan: [I] Initialize a client MLME.\n[00917.621] 05969.18003> wlan: [I] starting MainLoop\n[00917.621] 05969.06002> wlan: [I] channel opened\n[00917.622] 17150.17162> wlanstack2::device [I]: new iface #0 with role 'Client': /dev/sys/pci/01:00.0/ath10k-wlanphy/ath10k-wlanmac/wlan\n[00917.622] 14467.14479> wlancfg got event: OnIfaceAdded { iface_id: 0 }\n[00917.622] 14467.14479> wlancfg: new iface 0 added successfully\n[00917.623] 14467.14479> wlancfg: Starting auto-connect loop with 0 saved networks\n[00918.211] 14195.14211> Starting mDNS on interface ethp001f6 [80fe::b256:ff03:13fe:e7b3]\n[00918.212] 14195.14211> [WARNING:garnet/bin/mdns/service/mdns_interface_transceiver_v6.cc(29)] NET-291 IPV6_MULTICAST_LOOP not supported (ENOPROTOOPT), continuing anyway\n[00918.212] 14195.14211> [WARNING:garnet/bin/mdns/service/mdns_interface_transceiver_v6.cc(50)] NET-2180 IPV6_JOIN_GROUP returned ENODEV, mDNS will not communicate via IPV6\n[00921.792] 14195.14211> Starting mDNS on interface ethp001f6 192.168.42.103\n[00921.793] 14195.14211> [WARNING:garnet/bin/mdns/service/mdns_interface_transceiver_v4.cc(68)] NET-2177 IP_TTL not supported (ENOPROTOOPT), continuing anyway. May cause spurious IP traffic\n[00921.793] 14195.14211> Starting mDNS on interface ethp001f6 [80fe::b256:ff03:13fe:e7b3]\n[00921.793] 14195.14211> [WARNING:garnet/bin/mdns/service/mdns_interface_transceiver_v6.cc(29)] NET-291 IPV6_MULTICAST_LOOP not supported (ENOPROTOOPT), continuing anyway\n[00921.793] 14195.14211> [WARNING:garnet/bin/mdns/service/mdns_interface_transceiver_v6.cc(50)] NET-2180 IPV6_JOIN_GROUP returned ENODEV, mDNS will not communicate via IPV6\n[00921.793] 14195.14211> mDNS: Verifying uniqueness of host name rash-moan-copy-slob.local.\n[00922.661] 14195.14211> mDNS: Using unique host name rash-moan-copy-slob.local.\nRunning tests sequentially.\n[tb] 2019-04-18 03:24:47.125 \u001b[22mINFO\u001b[0m [AndroidDevice|896X05XLX] The primary device under test is \"896X05XLX\". [android_device.py:create:92]\n[tb] 2019-04-18 03:24:49.286 \u001b[22mINFO\u001b[0m [AndroidDevice|896X05XLX] Screen is not awake, wake it up [android_device.py:wakeup_screen:1374]\n[tb] 2019-04-18 03:24:50.333 \u001b[22mINFO\u001b[0m Controller AndroidDevice: [{'serial': '896X05XLX', 'model': 'blueline', 'incremental_build_id': '5289084', 'build_id': '5289084', 'build_type': 'userdebug'}] [base_test.py:register_controller:396]\n[tb] 2019-04-18 03:24:50.347 \u001b[22mINFO\u001b[0m Controller FuchsiaDevice: [{'ip': '192.168.42.103'}] [base_test.py:register_controller:396]\n[tb] 2019-04-18 03:24:51.161 \u001b[22mINFO\u001b[0m ==========> Sl4fSanityTest <========== [base_test.py:run:966]\n[tb] 2019-04-18 03:24:51.162 \u001b[22mINFO\u001b[0m Congratulations! Fuchsia controllers have been initialized successfully! [Sl4fSanityTest.py:setup_class:41]\n[tb] 2019-04-18 03:24:51.163 \u001b[22mINFO\u001b[0m [Test Case] test_example [base_test.py:exec_one_testcase:670]\n[tb] 2019-04-18 03:24:51.172 \u001b[22mINFO\u001b[0m Congratulations! You've run your first test. [Sl4fSanityTest.py:test_example:46]\n[tb] 2019-04-18 03:24:51.182 \u001b[22mINFO\u001b[0m [Test Case] test_example PASS [base_test.py:_on_pass:551]\n[tb] 2019-04-18 03:24:51.806 \u001b[22mINFO\u001b[0m Summary for test class Sl4fSanityTest: ControllerInfo {'FuchsiaDevice': [{'ip': '192.168.42.103'}], 'AndroidDevice': [{'serial': '896X05XLX', 'model': 'blueline', 'incremental_build_id': '5289084', 'build_id': '5289084', 'build_type': 'userdebug'}]}, Requested 1, Executed 1, Passed 1, Failed 0, Skipped 0, Blocked 0, Unknown 0, Errors 0 [base_test.py:run:1026]\n[tb] 2019-04-18 03:24:51.826 \u001b[22mINFO\u001b[0m [AndroidDevice|896X05XLX] The primary device under test is \"896X05XLX\". [android_device.py:create:92]\n[tb] 2019-04-18 03:24:54.715 \u001b[22mINFO\u001b[0m Controller AndroidDevice: [{'serial': '896X05XLX', 'model': 'blueline', 'incremental_build_id': '5289084', 'build_id': '5289084', 'build_type': 'userdebug'}] [base_test.py:register_controller:396]\n[tb] 2019-04-18 03:24:54.727 \u001b[22mINFO\u001b[0m Controller FuchsiaDevice: [{'ip': '192.168.42.103'}] [base_test.py:register_controller:396]\n[tb] 2019-04-18 03:24:55.665 \u001b[22mINFO\u001b[0m There are: 1 fuchsia and 1 android devices. [BleFuchsiaAndroidTest.py:__init__:48]\n[tb] 2019-04-18 03:24:55.666 \u001b[22mINFO\u001b[0m ==========> BleFuchsiaAndroidTest <========== [base_test.py:run:966]\n[tb] 2019-04-18 03:24:55.667 \u001b[22mINFO\u001b[0m Setting up Android Devices\n[tb] 2019-04-18 03:24:55.725 \u001b[22mINFO\u001b[0m [AndroidDevice|896X05XLX] Reset state of bluetooth on device. [bt_test_utils.py:factory_reset_bluetooth:529]\n[tb] 2019-04-18 03:25:01.413 \u001b[22mINFO\u001b[0m State normalized {12}\n[tb] 2019-04-18 03:25:02.295 \u001b[22mINFO\u001b[0m [AndroidDevice|896X05XLX] Android Phone device found. [bt_test_utils.py:get_device_selector_dictionary:694]\n[tb] 2019-04-18 03:25:02.296 \u001b[22mINFO\u001b[0m [Test Case] test_fuchsia_adv_android_scan [base_test.py:exec_one_testcase:670]\n[tb] 2019-04-18 03:25:02.327 \u001b[22mINFO\u001b[0m [Test ID] BleFuchsiaAndroidTest:test_fuchsia_adv_android_scan:1555557902.3265333 [BluetoothBaseTest.py:_safe_wrap_test_case:95]\n[00984.368] 03030.03053> bt-transport-usb: timed out: ZX_ERR_TIMED_OUT\n[tb] 2019-04-18 03:25:02.810 \u001b[22mINFO\u001b[0m Found scan result: {'data': {'CallbackType': 1,\n 'ID': 1,\n 'Result': {'advertiseFlags': 2,\n 'deviceInfo': {'address': '5A:95:B0:CC:5F:70',\n 'name': 'testADV123',\n 'state': 10,\n 'type': 2},\n 'deviceName': 'testADV123',\n 'manufacturerIdList': '[]',\n 'manufacturerSpecificDataList': '[]',\n 'rssi': -53,\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': 1417405683524199,\n 'txPowerLevel': -2147483648},\n 'Type': 'onScanResult'},\n 'name': 'BleScan1onScanResults',\n 'time': 1555557902778} [BleFuchsiaAndroidTest.py:test_fuchsia_adv_android_scan:151]\n[tb] 2019-04-18 03:25:02.858 \u001b[22mINFO\u001b[0m [Test Case] test_fuchsia_adv_android_scan PASS [base_test.py:_on_pass:551]\n[tb] 2019-04-18 03:25:02.859 \u001b[22mINFO\u001b[0m [Test Case] test_fuchsia_connect_android_periph [base_test.py:exec_one_testcase:670]\n[tb] 2019-04-18 03:25:02.884 \u001b[22mINFO\u001b[0m [Test ID] BleFuchsiaAndroidTest:test_fuchsia_connect_android_periph:1555557902.8838074 [BluetoothBaseTest.py:_safe_wrap_test_case:95]\n[tb] 2019-04-18 03:25:03.002 \u001b[22mINFO\u001b[0m Android device name: Pixel1234 [BleFuchsiaAndroidTest.py:test_fuchsia_connect_android_periph:98]\n[00984.948] 03030.09147> [INFO:low_energy_discovery_manager.cc(91)] gap-le: start discovery\n[tb] 2019-04-18 03:25:04.021 \u001b[22mINFO\u001b[0m Successfully found advertisement! name, id: Pixel1234, a5cc314715ca668c [bt_test_utils.py:le_scan_for_device_by_name:43]\n[tb] 2019-04-18 03:25:04.155 \u001b[22mINFO\u001b[0m Connecting returned status: {'result': None, 'error': None, 'id': '3'} [BleFuchsiaAndroidTest.py:test_fuchsia_connect_android_periph:109]\n[00986.093] 03030.09147> [INFO:low_energy_connection_manager.cc(751)] gap-le: new connection (LE link - handle: 0x0002, role: master, address: (LE rand) 4A:C7:1F:92:B3:EB, interval: 45.00 ms, latency: 0.00 ms, timeout: 420 ms)\n[tb] 2019-04-18 03:25:04.327 \u001b[22mINFO\u001b[0m Listing services returned: {'result': [{'primary': True, 'id': 1, 'uuid_type': '00001801-0000-1000-8000-00805f9b34fb'}, {'primary': True, 'id': 20, 'uuid_type': '00001800-0000-1000-8000-00805f9b34fb'}], 'error': None, 'id': '4'} [BleFuchsiaAndroidTest.py:test_fuchsia_connect_android_periph:112]\n[tb] 2019-04-18 03:25:04.335 \u001b[22mINFO\u001b[0m Disconnect status: {'result': None, 'error': None, 'id': '5'} [BleFuchsiaAndroidTest.py:test_fuchsia_connect_android_periph:115]\n[tb] 2019-04-18 03:25:04.391 \u001b[22mINFO\u001b[0m [Test Case] test_fuchsia_connect_android_periph PASS [base_test.py:_on_pass:551]\n[tb] 2019-04-18 03:25:04.392 \u001b[22mINFO\u001b[0m [Test Case] test_fuchsia_scan_android_adv [base_test.py:exec_one_testcase:670]\n[tb] 2019-04-18 03:25:04.417 \u001b[22mINFO\u001b[0m [Test ID] BleFuchsiaAndroidTest:test_fuchsia_scan_android_adv:1555557904.4158068 [BluetoothBaseTest.py:_safe_wrap_test_case:95]\n[00986.273] 03030.09147> [INFO:low_energy_connection_manager.cc(590)] gap-le: all refs dropped on connection: (LE link - handle: 0x0002, role: master, address: (LE rand) 4A:C7:1F:92:B3:EB, interval: 45.00 ms, latency: 0.00 ms, timeout: 420 ms)\n[00986.317] 03030.09147> [INFO:low_energy_connection_manager.cc(848)] gap-le: link disconnected - status: \"success\", handle: 0x0002, reason: 0x16\n[tb] 2019-04-18 03:25:04.491 \u001b[22mINFO\u001b[0m Android device name: Pixel1234 [BleFuchsiaAndroidTest.py:test_fuchsia_scan_android_adv:75]\n[00986.437] 03030.09147> [INFO:low_energy_discovery_manager.cc(91)] gap-le: start discovery\n[tb] 2019-04-18 03:25:05.512 \u001b[22mINFO\u001b[0m Successfully found advertisement! name, id: Pixel1234, 171ddb8e508d2e11 [bt_test_utils.py:le_scan_for_device_by_name:43]\n[tb] 2019-04-18 03:25:05.560 \u001b[22mINFO\u001b[0m [Test Case] test_fuchsia_scan_android_adv PASS [base_test.py:_on_pass:551]\n[tb] 2019-04-18 03:25:06.210 \u001b[22mINFO\u001b[0m Summary for test class BleFuchsiaAndroidTest: ControllerInfo {'FuchsiaDevice': [{'ip': '192.168.42.103'}], 'AndroidDevice': [{'serial': '896X05XLX', 'model': 'blueline', 'incremental_build_id': '5289084', 'build_id': '5289084', 'build_type': 'userdebug'}]}, Requested 3, Executed 3, Passed 3, Failed 0, Skipped 0, Blocked 0, Unknown 0, Errors 0 [base_test.py:run:1026]\n[tb] 2019-04-18 03:25:06.244 \u001b[22mINFO\u001b[0m [AndroidDevice|896X05XLX] The primary device under test is \"896X05XLX\". [android_device.py:create:92]\n[tb] 2019-04-18 03:25:09.180 \u001b[22mINFO\u001b[0m Controller AndroidDevice: [{'serial': '896X05XLX', 'model': 'blueline', 'incremental_build_id': '5289084', 'build_id': '5289084', 'build_type': 'userdebug'}] [base_test.py:register_controller:396]\n[tb] 2019-04-18 03:25:09.196 \u001b[22mINFO\u001b[0m Controller FuchsiaDevice: [{'ip': '192.168.42.103'}] [base_test.py:register_controller:396]\n[tb] 2019-04-18 03:25:10.021 \u001b[22mINFO\u001b[0m ==========> GattServerSetupTest <========== [base_test.py:run:966]\n[tb] 2019-04-18 03:25:10.024 \u001b[22mINFO\u001b[0m [Test Case] test_alert_notification_service [base_test.py:exec_one_testcase:670]\n[tb] 2019-04-18 03:25:10.056 \u001b[22mINFO\u001b[0m [Test Case] test_alert_notification_service PASS [base_test.py:_on_pass:551]\n[tb] 2019-04-18 03:25:10.058 \u001b[22mINFO\u001b[0m [Test Case] test_automation_io_service [base_test.py:exec_one_testcase:670]\n[tb] 2019-04-18 03:25:10.096 \u001b[22mINFO\u001b[0m [Test Case] test_automation_io_service PASS [base_test.py:_on_pass:551]\n[tb] 2019-04-18 03:25:10.097 \u001b[22mINFO\u001b[0m [Test Case] test_battery_service [base_test.py:exec_one_testcase:670]\n[tb] 2019-04-18 03:25:10.132 \u001b[22mINFO\u001b[0m [Test Case] test_battery_service PASS [base_test.py:_on_pass:551]\n[tb] 2019-04-18 03:25:10.133 \u001b[22mINFO\u001b[0m [Test Case] test_blood_pressure_service [base_test.py:exec_one_testcase:670]\n[tb] 2019-04-18 03:25:10.174 \u001b[22mINFO\u001b[0m [Test Case] test_blood_pressure_service PASS [base_test.py:_on_pass:551]\n[tb] 2019-04-18 03:25:10.175 \u001b[22mINFO\u001b[0m [Test Case] test_body_composition_service [base_test.py:exec_one_testcase:670]\n[tb] 2019-04-18 03:25:10.216 \u001b[22mINFO\u001b[0m [Test Case] test_body_composition_service PASS [base_test.py:_on_pass:551]\n[tb] 2019-04-18 03:25:10.218 \u001b[22mINFO\u001b[0m [Test Case] test_bond_management_service [base_test.py:exec_one_testcase:670]\n[tb] 2019-04-18 03:25:10.251 \u001b[22mINFO\u001b[0m [Test Case] test_bond_management_service PASS [base_test.py:_on_pass:551]\n[tb] 2019-04-18 03:25:10.253 \u001b[22mINFO\u001b[0m [Test Case] test_continuous_glucose_monitoring_service [base_test.py:exec_one_testcase:670]\n[tb] 2019-04-18 03:25:10.291 \u001b[22mINFO\u001b[0m [Test Case] test_continuous_glucose_monitoring_service PASS [base_test.py:_on_pass:551]\n[tb] 2019-04-18 03:25:10.292 \u001b[22mINFO\u001b[0m [Test Case] test_current_time_service [base_test.py:exec_one_testcase:670]\n[tb] 2019-04-18 03:25:10.326 \u001b[22mINFO\u001b[0m [Test Case] test_current_time_service PASS [base_test.py:_on_pass:551]\n[tb] 2019-04-18 03:25:10.328 \u001b[22mINFO\u001b[0m [Test Case] test_cycling_power_service [base_test.py:exec_one_testcase:670]\n[tb] 2019-04-18 03:25:10.359 \u001b[22mINFO\u001b[0m [Test Case] test_cycling_power_service PASS [base_test.py:_on_pass:551]\n[tb] 2019-04-18 03:25:10.360 \u001b[22mINFO\u001b[0m [Test Case] test_cycling_speed_and_cadence_service [base_test.py:exec_one_testcase:670]\n[tb] 2019-04-18 03:25:10.395 \u001b[22mINFO\u001b[0m [Test Case] test_cycling_speed_and_cadence_service PASS [base_test.py:_on_pass:551]\n[tb] 2019-04-18 03:25:10.396 \u001b[22mINFO\u001b[0m [Test Case] test_device_information_service [base_test.py:exec_one_testcase:670]\n[tb] 2019-04-18 03:25:10.439 \u001b[22mINFO\u001b[0m [Test Case] test_device_information_service PASS [base_test.py:_on_pass:551]\n[tb] 2019-04-18 03:25:10.440 \u001b[22mINFO\u001b[0m [Test Case] test_duplicate_services [base_test.py:exec_one_testcase:670]\n[tb] 2019-04-18 03:25:10.473 \u001b[22mINFO\u001b[0m [Test Case] test_duplicate_services PASS [base_test.py:_on_pass:551]\n[tb] 2019-04-18 03:25:10.474 \u001b[22mINFO\u001b[0m [Test Case] test_environmental_sensing_service [base_test.py:exec_one_testcase:670]\n[tb] 2019-04-18 03:25:10.520 \u001b[22mINFO\u001b[0m [Test Case] test_environmental_sensing_service PASS [base_test.py:_on_pass:551]\n[tb] 2019-04-18 03:25:10.522 \u001b[22mINFO\u001b[0m [Test Case] test_fitness_machine_service [base_test.py:exec_one_testcase:670]\n[tb] 2019-04-18 03:25:10.561 \u001b[22mINFO\u001b[0m [Test Case] test_fitness_machine_service PASS [base_test.py:_on_pass:551]\n[tb] 2019-04-18 03:25:10.563 \u001b[22mINFO\u001b[0m [Test Case] test_glucose_service [base_test.py:exec_one_testcase:670]\n[tb] 2019-04-18 03:25:10.597 \u001b[22mINFO\u001b[0m [Test Case] test_glucose_service PASS [base_test.py:_on_pass:551]\n[tb] 2019-04-18 03:25:10.598 \u001b[22mINFO\u001b[0m [Test Case] test_health_thermometer_service [base_test.py:exec_one_testcase:670]\n[tb] 2019-04-18 03:25:10.642 \u001b[22mINFO\u001b[0m [Test Case] test_health_thermometer_service PASS [base_test.py:_on_pass:551]\n[tb] 2019-04-18 03:25:10.644 \u001b[22mINFO\u001b[0m [Test Case] test_heart_rate_service [base_test.py:exec_one_testcase:670]\n[tb] 2019-04-18 03:25:10.676 \u001b[22mINFO\u001b[0m [Test Case] test_heart_rate_service PASS [base_test.py:_on_pass:551]\n[tb] 2019-04-18 03:25:10.677 \u001b[22mINFO\u001b[0m [Test Case] test_http_proxy_service [base_test.py:exec_one_testcase:670]\n[tb] 2019-04-18 03:25:10.715 \u001b[22mINFO\u001b[0m [Test Case] test_http_proxy_service PASS [base_test.py:_on_pass:551]\n[tb] 2019-04-18 03:25:10.716 \u001b[22mINFO\u001b[0m [Test Case] test_human_interface_device_service [base_test.py:exec_one_testcase:670]\n[tb] 2019-04-18 03:25:10.752 \u001b[22mINFO\u001b[0m [Test Case] test_human_interface_device_service PASS [base_test.py:_on_pass:551]\n[tb] 2019-04-18 03:25:10.753 \u001b[22mINFO\u001b[0m [Test Case] test_immediate_alert_service [base_test.py:exec_one_testcase:670]\n[tb] 2019-04-18 03:25:10.783 \u001b[22mINFO\u001b[0m [Test Case] test_immediate_alert_service PASS [base_test.py:_on_pass:551]\n[tb] 2019-04-18 03:25:10.784 \u001b[22mINFO\u001b[0m [Test Case] test_indoor_positioning_service [base_test.py:exec_one_testcase:670]\n[tb] 2019-04-18 03:25:10.815 \u001b[22mINFO\u001b[0m [Test Case] test_indoor_positioning_service PASS [base_test.py:_on_pass:551]\n[tb] 2019-04-18 03:25:10.816 \u001b[22mINFO\u001b[0m [Test Case] test_insulin_delivery_service [base_test.py:exec_one_testcase:670]\n[tb] 2019-04-18 03:25:10.843 \u001b[22mINFO\u001b[0m [Test Case] test_insulin_delivery_service PASS [base_test.py:_on_pass:551]\n[tb] 2019-04-18 03:25:10.843 \u001b[22mINFO\u001b[0m [Test Case] test_internet_protocol_support_service [base_test.py:exec_one_testcase:670]\n[tb] 2019-04-18 03:25:10.884 \u001b[22mINFO\u001b[0m [Test Case] test_internet_protocol_support_service PASS [base_test.py:_on_pass:551]\n[tb] 2019-04-18 03:25:10.885 \u001b[22mINFO\u001b[0m [Test Case] test_link_loss_service [base_test.py:exec_one_testcase:670]\n[tb] 2019-04-18 03:25:10.926 \u001b[22mINFO\u001b[0m [Test Case] test_link_loss_service PASS [base_test.py:_on_pass:551]\n[tb] 2019-04-18 03:25:10.927 \u001b[22mINFO\u001b[0m [Test Case] test_location_and_navigation_service [base_test.py:exec_one_testcase:670]\n[tb] 2019-04-18 03:25:10.968 \u001b[22mINFO\u001b[0m [Test Case] test_location_and_navigation_service PASS [base_test.py:_on_pass:551]\n[tb] 2019-04-18 03:25:10.969 \u001b[22mINFO\u001b[0m [Test Case] test_mesh_provisioning_service [base_test.py:exec_one_testcase:670]\n[tb] 2019-04-18 03:25:11.005 \u001b[22mINFO\u001b[0m [Test Case] test_mesh_provisioning_service PASS [base_test.py:_on_pass:551]\n[tb] 2019-04-18 03:25:11.006 \u001b[22mINFO\u001b[0m [Test Case] test_mesh_proxy_service [base_test.py:exec_one_testcase:670]\n[tb] 2019-04-18 03:25:11.039 \u001b[22mINFO\u001b[0m [Test Case] test_mesh_proxy_service PASS [base_test.py:_on_pass:551]\n[tb] 2019-04-18 03:25:11.041 \u001b[22mINFO\u001b[0m [Test Case] test_next_dst_change_service [base_test.py:exec_one_testcase:670]\n[tb] 2019-04-18 03:25:11.074 \u001b[22mINFO\u001b[0m [Test Case] test_next_dst_change_service PASS [base_test.py:_on_pass:551]\n[tb] 2019-04-18 03:25:11.076 \u001b[22mINFO\u001b[0m [Test Case] test_object_transfer_service [base_test.py:exec_one_testcase:670]\n[tb] 2019-04-18 03:25:11.111 \u001b[22mINFO\u001b[0m [Test Case] test_object_transfer_service PASS [base_test.py:_on_pass:551]\n[tb] 2019-04-18 03:25:11.112 \u001b[22mINFO\u001b[0m [Test Case] test_phone_alert_status_service [base_test.py:exec_one_testcase:670]\n[tb] 2019-04-18 03:25:11.144 \u001b[22mINFO\u001b[0m [Test Case] test_phone_alert_status_service PASS [base_test.py:_on_pass:551]\n[tb] 2019-04-18 03:25:11.145 \u001b[22mINFO\u001b[0m [Test Case] test_primary_and_secondary_service [base_test.py:exec_one_testcase:670]\n[tb] 2019-04-18 03:25:11.184 \u001b[22mINFO\u001b[0m [Test Case] test_primary_and_secondary_service PASS [base_test.py:_on_pass:551]\n[tb] 2019-04-18 03:25:11.185 \u001b[22mINFO\u001b[0m [Test Case] test_pulse_oximeter_service [base_test.py:exec_one_testcase:670]\n[tb] 2019-04-18 03:25:11.220 \u001b[22mINFO\u001b[0m [Test Case] test_pulse_oximeter_service PASS [base_test.py:_on_pass:551]\n[tb] 2019-04-18 03:25:11.221 \u001b[22mINFO\u001b[0m [Test Case] test_reconnection_configuration_service [base_test.py:exec_one_testcase:670]\n[tb] 2019-04-18 03:25:11.255 \u001b[22mINFO\u001b[0m [Test Case] test_reconnection_configuration_service PASS [base_test.py:_on_pass:551]\n[tb] 2019-04-18 03:25:11.256 \u001b[22mINFO\u001b[0m [Test Case] test_reference_time_update_service [base_test.py:exec_one_testcase:670]\n[tb] 2019-04-18 03:25:11.288 \u001b[22mINFO\u001b[0m [Test Case] test_reference_time_update_service PASS [base_test.py:_on_pass:551]\n[tb] 2019-04-18 03:25:11.289 \u001b[22mINFO\u001b[0m [Test Case] test_running_speed_and_cadence_service [base_test.py:exec_one_testcase:670]\n[tb] 2019-04-18 03:25:11.328 \u001b[22mINFO\u001b[0m [Test Case] test_running_speed_and_cadence_service PASS [base_test.py:_on_pass:551]\n[tb] 2019-04-18 03:25:11.329 \u001b[22mINFO\u001b[0m [Test Case] test_scan_parameters_service [base_test.py:exec_one_testcase:670]\n[tb] 2019-04-18 03:25:11.362 \u001b[22mINFO\u001b[0m [Test Case] test_scan_parameters_service PASS [base_test.py:_on_pass:551]\n[tb] 2019-04-18 03:25:11.363 \u001b[22mINFO\u001b[0m [Test Case] test_single_primary_service [base_test.py:exec_one_testcase:670]\n[tb] 2019-04-18 03:25:11.398 \u001b[22mINFO\u001b[0m [Test Case] test_single_primary_service PASS [base_test.py:_on_pass:551]\n[tb] 2019-04-18 03:25:11.399 \u001b[22mINFO\u001b[0m [Test Case] test_single_secondary_service [base_test.py:exec_one_testcase:670]\n[tb] 2019-04-18 03:25:11.426 \u001b[22mINFO\u001b[0m [Test Case] test_single_secondary_service PASS [base_test.py:_on_pass:551]\n[tb] 2019-04-18 03:25:11.427 \u001b[22mINFO\u001b[0m [Test Case] test_transport_discovery_service [base_test.py:exec_one_testcase:670]\n[tb] 2019-04-18 03:25:11.458 \u001b[22mINFO\u001b[0m [Test Case] test_transport_discovery_service PASS [base_test.py:_on_pass:551]\n[tb] 2019-04-18 03:25:11.459 \u001b[22mINFO\u001b[0m [Test Case] test_tx_power_service [base_test.py:exec_one_testcase:670]\n[tb] 2019-04-18 03:25:11.495 \u001b[22mINFO\u001b[0m [Test Case] test_tx_power_service PASS [base_test.py:_on_pass:551]\n[tb] 2019-04-18 03:25:11.496 \u001b[22mINFO\u001b[0m [Test Case] test_user_data_service [base_test.py:exec_one_testcase:670]\n[tb] 2019-04-18 03:25:11.535 \u001b[22mINFO\u001b[0m [Test Case] test_user_data_service PASS [base_test.py:_on_pass:551]\n[tb] 2019-04-18 03:25:11.536 \u001b[22mINFO\u001b[0m [Test Case] test_weight_scale_service [base_test.py:exec_one_testcase:670]\n[tb] 2019-04-18 03:25:11.570 \u001b[22mINFO\u001b[0m [Test Case] test_weight_scale_service PASS [base_test.py:_on_pass:551]\n[tb] 2019-04-18 03:25:12.185 \u001b[22mINFO\u001b[0m Summary for test class GattServerSetupTest: ControllerInfo {'FuchsiaDevice': [{'ip': '192.168.42.103'}], 'AndroidDevice': [{'serial': '896X05XLX', 'model': 'blueline', 'incremental_build_id': '5289084', 'build_id': '5289084', 'build_type': 'userdebug'}]}, Requested 42, Executed 42, Passed 42, Failed 0, Skipped 0, Blocked 0, Unknown 0, Errors 0 [base_test.py:run:1026]\n[tb] 2019-04-18 03:25:12.225 \u001b[22mINFO\u001b[0m [AndroidDevice|896X05XLX] The primary device under test is \"896X05XLX\". [android_device.py:create:92]\n[tb] 2019-04-18 03:25:14.334 \u001b[22mINFO\u001b[0m [AndroidDevice|896X05XLX] Screen is not awake, wake it up [android_device.py:wakeup_screen:1374]\n[tb] 2019-04-18 03:25:15.401 \u001b[22mINFO\u001b[0m Controller AndroidDevice: [{'serial': '896X05XLX', 'model': 'blueline', 'incremental_build_id': '5289084', 'build_id': '5289084', 'build_type': 'userdebug'}] [base_test.py:register_controller:396]\n[tb] 2019-04-18 03:25:15.412 \u001b[22mINFO\u001b[0m Controller FuchsiaDevice: [{'ip': '192.168.42.103'}] [base_test.py:register_controller:396]\n[tb] 2019-04-18 03:25:16.245 \u001b[22mINFO\u001b[0m Running testbed setup with one fuchsia devices [NetstackFuchsiaTest.py:__init__:31]\n[tb] 2019-04-18 03:25:16.246 \u001b[22mINFO\u001b[0m ==========> NetstackFuchsiaTest <========== [base_test.py:run:966]\n[tb] 2019-04-18 03:25:16.248 \u001b[22mINFO\u001b[0m [Test Case] test_fuchsia_publish_service [base_test.py:exec_one_testcase:670]\n[tb] 2019-04-18 03:25:16.280 \u001b[22mINFO\u001b[0m [Test Case] test_fuchsia_publish_service PASS [base_test.py:_on_pass:551]\n[tb] 2019-04-18 03:25:16.964 \u001b[22mINFO\u001b[0m Summary for test class NetstackFuchsiaTest: ControllerInfo {'FuchsiaDevice': [{'ip': '192.168.42.103'}], 'AndroidDevice': [{'serial': '896X05XLX', 'model': 'blueline', 'incremental_build_id': '5289084', 'build_id': '5289084', 'build_type': 'userdebug'}]}, Requested 1, Executed 1, Passed 1, Failed 0, Skipped 0, Blocked 0, Unknown 0, Errors 0 [base_test.py:run:1026]\n[tb] 2019-04-18 03:25:16.984 \u001b[22mINFO\u001b[0m Summary for test run tb@2019-04-18_03-24-45-625: ControllerInfo {'FuchsiaDevice': [{'ip': '192.168.42.103'}], 'AndroidDevice': [{'serial': '896X05XLX', 'model': 'blueline', 'incremental_build_id': '5289084', 'build_id': '5289084', 'build_type': 'userdebug'}]}, Requested 47, Executed 47, Passed 47, Failed 0, Skipped 0, Blocked 0, Unknown 0, Errors 0\n/etc/connectivity/acts/tools/test/connectivity/acts/framework/acts/controllers/buds_lib/test_actions/bt_utils.py:201: SyntaxWarning: assertion is always true, perhaps remove parentheses?\n assert (True is pri_device.droid.bluetoothUnbond(target_address),\nCommand succeeded!\n", "outputs": [ "out.tar" ], "results": { "bot_dimensions": [ { "key": "device_type", "value": [ "Intel NUC Kit NUC7i5DNHE" ] }, { "key": "host_cpu", "value": [ "x64", "x86", "x86-64-avx2", "x86-64-i7-8559U" ] }, { "key": "host_os", "value": [ "Debian", "Debian-9.8", "Linux" ] }, { "key": "id", "value": [ "fuchsia946-row3-rack8-server-1--rash-moan-copy-slob" ] }, { "key": "pool", "value": [ "fuchsia.tests.connectivity" ] }, { "key": "serial", "value": [ "0" ] }, { "key": "server_version", "value": [ "4260-fb32526" ] }, { "key": "testbed", "value": [ "bt_rf_chamber_nuc_phone" ] }, { "key": "zone", "value": [ "cloud" ] } ], "bot_id": "fuchsia946-row3-rack8-server-1--rash-moan-copy-slob", "bot_version": "84fce6b5d9235ac606544652bb2ef7411c74b0807d26a0712f3ff2c315b69522", "cipd_pins": { "client_package": { "package_name": "infra/tools/cipd/linux-amd64", "version": "nFftZl2kFquaI2EUmPGwzbc5sIbCocl9L55UeASqlLsC" }, "packages": [ { "package_name": "fuchsia/tools/botanist/linux-amd64", "path": ".", "version": "UKxkEVGmq0NiYbOjB0eSh6K_lJJ4_Mmm4BAi94owjbMC" } ] }, "completed_ts": "2019-04-18T03:25:28.262783", "costs_usd": [ 0.01148432219789245 ], "created_ts": "2019-04-18T03:22:05.858058", "duration": 101.9764769077301, "modified_ts": "2019-04-18T03:25:28.262783", "name": "all tests", "outputs_ref": { "isolated": "4e3ef22513de776b5639aee70bc0a07a8c864072", "isolatedserver": "https://isolateserver.appspot.com", "namespace": "default-gzip" }, "run_id": "444748bead271d11", "server_versions": [ "4260-fb32526" ], "started_ts": "2019-04-18T03:22:55.726808", "state": "COMPLETED", "tags": [ "device_type:Intel NUC Kit NUC7i5DNHE", "pool:fuchsia.tests.connectivity", "priority:200", "service_account:none", "swarming.pool.template:none", "swarming.pool.version:e92b70e5906b78622d57ed770afb642ca59ad5d3", "testbed:bt_rf_chamber_nuc_phone", "user:None" ], "task_id": "444748bead271d10", "try_number": "1" } } }