DEBUG: config flag: /etc/botanist/config.json
DEBUG: executing command: "/etc/connectivity/host_cmds.sh"
environment of subprocess:
[]
2019/04/26 04:10:46 attempting to send <<netboot>>cmdline...
2019/04/26 04:10:46 done
2019/04/26 04:10:46 attempting to send <<image>>sparse.fvm...
2019/04/26 04:10:47 done
2019/04/26 04:10:47 attempting to send <<image>>bootloader.img...
2019/04/26 04:10:47 target is busy, retrying in one second
2019/04/26 04:10:48 attempting to send <<image>>bootloader.img...
2019/04/26 04:10:48 done
2019/04/26 04:10:48 attempting to send <<image>>zircona.img...
2019/04/26 04:10:49 done
2019/04/26 04:10:49 attempting to send <<image>>zirconr.img...
2019/04/26 04:10:49 target is busy, retrying in one second
[00000.000] 00000.00000> zbi: @ 0xffffff80012f2000 (17482848 bytes)
[00000.000] 00000.00000> UART: FIFO depth 16
[00000.000] 00000.00000> PMM: boot reserve add [0x100000, 0x2c5fff]
[00000.000] 00000.00000> PMM: boot reserve add [0x12f2000, 0x239efff]
[00000.000] 00000.00000> PMM: arena too small to be useful (size 4096)
[00000.000] 00000.00000> PMM: pmm_add_arena failed to initialize arena
[00000.000] 00000.00000> MEM: Failed to add pmm range at 0x8afff000 size 0x1000
[00000.000] 00000.00000> PMM: boot reserve marking WIRED [0x100000, 0x2c5fff]
[00000.000] 00000.00000> PMM: boot reserve marking WIRED [0x12f2000, 0x239efff]
[00000.000] 00000.00000>
[00000.000] 00000.00000> welcome to Zircon
[00000.000] 00000.00000>
[00000.000] 00000.00000> KASLR: .text section at 0xffffffff00100000
[00000.000] 00000.00000> INIT: cpu 0, calling hook 0xffffffff001aa428 (global_prng_seed) at level 0x30000, flags 0x1
[00000.000] 00000.00000> initializing vm pre-heap
[00000.000] 00000.00000> VM: marking boot alloc used range [0x239f000, 0x239f100)
[00000.000] 00000.00000> INIT: cpu 0, calling hook 0xffffffff00147abc (elf_build_id) at level 0x4fffe, flags 0x1
[00000.000] 00000.00000> INIT: cpu 0, calling hook 0xffffffff00147c48 (version) at level 0x4ffff, flags 0x1
[00000.000] 00000.00000> version:
[00000.000] 00000.00000> arch: x86
[00000.000] 00000.00000> platform: pc
[00000.000] 00000.00000> target: pc
[00000.000] 00000.00000> project: x64
[00000.000] 00000.00000> buildid: git-13ee3dc5e4c46bf127977ad28645c47442ec517d
[00000.000] 00000.00000> ELF build ID: 5f3e39bd4ed89d3b8122947842f1eac846a04683
[00000.000] 00000.00000> initializing heap
[00000.000] 00000.00000> INIT: cpu 0, calling hook 0xffffffff00102e1c (x86_resource_init) at level 0x50000, flags 0x1
[00000.000] 00000.00000> INIT: cpu 0, calling hook 0xffffffff001a9630 (console) at level 0x50000, flags 0x1
[00000.000] 00000.00000> initializing vm
[00000.000] 00000.00000> VM: reserving kernel region [0xffffffff00100000, 0xffffffff001ee000) flags 0x28 name 'kernel_code'
[00000.000] 00000.00000> VM: reserving kernel region [0xffffffff001ee000, 0xffffffff00232000) flags 0x8 name 'kernel_rodata'
[00000.000] 00000.00000> VM: reserving kernel region [0xffffffff00232000, 0xffffffff00242000) flags 0x18 name 'kernel_data'
[00000.000] 00000.00000> VM: reserving kernel region [0xffffffff00242000, 0xffffffff002c6000) flags 0x18 name 'kernel_bss'
[00000.000] 00000.00000> INIT: cpu 0, calling hook 0xffffffff00103ae0 (display_memtype) at level 0x60001, flags 0x1
[00000.000] 00000.00000> INIT: cpu 0, calling hook 0xffffffff00138fa0 (acpi_tables) at level 0x60001, flags 0x1
[00000.000] 00000.00000> INIT: cpu 0, calling hook 0xffffffff00101c40 (hpet) at level 0x60002, flags 0x1
[00000.000] 00000.00000> INIT: cpu 0, calling hook 0xffffffff00102000 (apic) at level 0x60002, flags 0x1
[00000.000] 00000.00000> x2APIC enabled
[00000.000] 00000.00000> INIT: cpu 0, calling hook 0xffffffff001061b4 (timer) at level 0x60003, flags 0x1
[00000.000] 00000.00000> HPET frequency: 23999 ticks/ms
[00000.000] 00000.00000> TSC frequency: 2712000 ticks/ms
[00021.101] 00000.00000> timer features: constant_tsc 1 invariant_tsc 1 tsc_deadline 1
[00021.101] 00000.00000> Using TSC as wallclock
[00021.101] 00000.00000> initializing kernel
[00021.101] 00000.00000> initializing mp
[00021.101] 00000.00000> initializing timers
[00021.101] 00000.00000> INIT: cpu 0, calling hook 0xffffffff0013c578 (debuglog) at level 0x7ffff, flags 0x1
[00021.101] 00000.00000> INIT: cpu 0, calling hook 0xffffffff00195518 (thread_set_priority_experiment) at level 0x7ffff, flags 0x1
[00021.101] 00000.00000> thread set priority experiment is : ENABLED
[00021.101] 00000.00000> INIT: cpu 0, calling hook 0xffffffff001aa67c (global_prng_thread_safe) at level 0x7ffff, flags 0x1
[00021.101] 00000.00000> creating bootstrap completion thread
[00021.443] 00000.00000> top of bootstrap2()
[00021.443] 00000.00000> INIT: cpu 0, calling hook 0xffffffff0013151c (dpc) at level 0x80000, flags 0x1
[00021.456] 00000.00000> INIT: cpu 0, calling hook 0xffffffff00152978 (libobject) at level 0x80000, flags 0x1
[00021.456] 00000.00000> OOM: started thread
[00021.469] 00000.00000> Processor Model Info: type 0 family 0x6 model 0xe stepping 0x9
[00021.469] 00000.00000> display_family 0x6 display_model 0x8e
[00021.469] 00000.00000> Vendor: Intel
[00021.469] 00000.00000> Microarch: Kaby Lake
[00021.469] 00000.00000> F/M/S: 6/8e/9
[00021.469] 00000.00000> Brand: Intel(R) Core(TM) i5-7300U CPU @ 2.60GHz
[00021.469] 00000.00000> Features: fpu sse sse2 sse3 ssse3 sse4.1 sse4.2 mmx avx avx2 fxsr pcid xsave mon aesni clflush
[00021.469] 00000.00000> clflushopt fsgsbase tsc_adj smep smap erms rdrand rdseed syscall nx huge rdtscp
[00021.469] 00000.00000> invar_tsc tsc_deadline x2apic vmx pt hwp
[00021.469] 00000.00000> initializing platform
[00021.469] 00000.00000> INIT: cpu 0, calling hook 0xffffffff001101f4 (x86_perfmon) at level 0x90000, flags 0x1
[00021.469] 00000.00000> PMU: version 4
[00021.469] 00000.00000> UART: started IRQ driven RX
[00021.469] 00000.00000> UART: started IRQ driven TX
[00021.469] 00000.00000> cpu topology:
[00021.469] 00000.00000> 0: apic id 0x0 package 0 node 0 core 0 smt 0 BSP
[00021.469] 00000.00000> 1: apic id 0x2 package 0 node 0 core 1 smt 0
[00021.469] 00000.00000> 2: apic id 0x1 package 0 node 0 core 0 smt 1
[00021.469] 00000.00000> 3: apic id 0x3 package 0 node 0 core 1 smt 1
[00021.469] 00000.00000> Found 4 cpus
[00021.469] 00000.00000> booting apic ids: 0x2 0x1 0x3
[00021.485] 00000.00000> entering scheduler on cpu 2
[00021.486] 00000.00000> entering scheduler on cpu 3
[00021.486] 00000.00000> entering scheduler on cpu 1
[00021.489] 00000.00000> smbios: manufacturer="Intel Corporation" product="NUC7i5DNHE"
[00021.489] 00000.00000> initializing target
[00021.489] 00000.00000> INIT: cpu 1, calling hook 0xffffffff001053a0 (x86_pcie_init) at level 0xa0000, flags 0x1
[00021.489] 00000.00000> moving to last init level
[00021.489] 00000.00000> INIT: cpu 1, calling hook 0xffffffff00144140 (ktrace) at level 0xc0000, flags 0x1
[00021.492] 00000.00000> ktrace: buffer at 0xffffff9028200000 (33554432 bytes)
[00021.492] 00000.00000> INIT: cpu 1, calling hook 0xffffffff00147ab4 (userboot) at level 0xc0000, flags 0x1
[00021.492] 00000.00000> userboot: ramdisk 0x10ad000 @ 0xffffff80012f2000
[00021.492] 00000.00000> userboot: userboot rodata 0 @ [0x66915dd21000,0x66915dd24000)
[00021.492] 00000.00000> userboot: userboot code 0x3000 @ [0x66915dd24000,0x66915dd2f000)
[00021.492] 00000.00000> userboot: vdso/full rodata 0 @ [0x66915dd2f000,0x66915dd36000)
[00021.492] 00000.00000> userboot: vdso/full code 0x7000 @ [0x66915dd36000,0x66915dd37000)
[00021.492] 00000.00000> userboot: entry point @ 0x66915dd24c10
[00021.492] 00000.00000> INIT: cpu 1, calling hook 0xffffffff001aa030 (kernel_shell) at level 0xc0000, flags 0x1
[00021.492] 01036.01043> userboot: option "netsvc.disable=true"
[00021.493] 01036.01043> userboot: option "zircon.system.disable-automount=true"
[00021.493] 01036.01043> userboot: option "zircon.autorun.boot=/boot/infra/setup"
[00021.493] 01036.01043> userboot: option "kernel.serial=legacy"
[00021.493] 01036.01043> userboot: option "
http://192.168.42.1/multiboot/54%3Ab2%3A03%3A13%3Ab3%3Ae7="
[00021.493] 01036.01043> userboot: option "multiboot.boot_loader_name=iPXE+1.0.0++(d2063)"
[00021.532] 01036.01043> userboot: searching bootfs for 'bin/bootsvc'
[00021.532] 01036.01043> userboot: 'bin/bootsvc' has PT_INTERP "lib/ld.so.1"
[00021.532] 01036.01043> userboot: searching bootfs for 'lib/ld.so.1'
[00021.532] 01036.01043> userboot: userboot: loaded lib/ld.so.1 at 0x555847c54000, entry point 0x555847cda0d3
[00021.532] 01036.01043> userboot: userboot: loaded vDSO at 0x6e686f6d3000, entry point 0x0
[00021.532] 01036.01043> userboot: process bin/bootsvc started.
[00021.532] 01036.01043> userboot: waiting for loader-service requests...
[00021.532] 01036.01043> userboot: searching bootfs for 'lib/libasync-default.so'
[00021.532] 01036.01043> userboot: searching bootfs for 'lib/libfdio.so'
[00021.532] 01036.01043> userboot: searching bootfs for 'lib/liblaunchpad.so'
[00021.532] 01036.01043> userboot: searching bootfs for 'lib/libtrace-engine.so'
[00021.532] 01050.01053> {{{reset}}}
[00021.532] 01050.01053> {{{module:0:<application>:elf:18de7d58f51e8ba5c4f6afdd0cc8440f482c2b45}}}
[00021.532] 01050.01053> {{{mmap:0x297356291000:0x2e000:load:0:rx:0}}}
[00021.532] 01050.01053> {{{mmap:0x2973562bf000:0x4000:load:0:rw:0x2e000}}}
[00021.533] 01050.01053> dso: id=18de7d58f51e8ba5c4f6afdd0cc8440f482c2b45 base=0x0000297356291000 name=<application>
[00021.533] 01050.01053> {{{module:0x3:libasync-default.so:elf:c189f51f19d10785d93b5235ad1b46dca4451b00}}}
[00021.533] 01050.01053> {{{mmap:0x2fef158a0000:0x1000:load:0x3:rx:0}}}
[00021.533] 01050.01053> {{{mmap:0x2fef158a1000:0x1000:load:0x3:rw:0x1000}}}
[00021.533] 01050.01053> dso: id=c189f51f19d10785d93b5235ad1b46dca4451b00 base=0x00002fef158a0000 name=libasync-default.so
[00021.533] 01050.01053> {{{module:0x2:<vDSO>:elf:40ab5fa3b61f12fef4a44477a687f608661cd450}}}
[00021.533] 01050.01053> {{{mmap:0x6e686f6d3000:0x7000:load:0x2:r:0}}}
[00021.533] 01050.01053> {{{mmap:0x6e686f6da000:0x1000:load:0x2:rx:0x7000}}}
[00021.533] 01050.01053> dso: id=40ab5fa3b61f12fef4a44477a687f608661cd450 base=0x00006e686f6d3000 name=<vDSO>
[00021.533] 01050.01053> {{{module:0x1:libc.so:elf:67a12284bce140fc32aaaeac223e0e8f85cb5085}}}
[00021.533] 01050.01053> {{{mmap:0x555847c54000:0xcb000:load:0x1:rx:0}}}
[00021.533] 01050.01053> {{{mmap:0x555847d20000:0x6000:load:0x1:rw:0xcc000}}}
[00021.533] 01050.01053> dso: id=67a12284bce140fc32aaaeac223e0e8f85cb5085 base=0x0000555847c54000 name=libc.so
[00021.533] 01050.01053> {{{module:0x4:libfdio.so:elf:27787977e95f3b9563c9e0bd4d34ec92b7e9ad88}}}
[00021.533] 01050.01053> {{{mmap:0x7be0f4eec000:0x24000:load:0x4:rx:0}}}
[00021.533] 01050.01053> {{{mmap:0x7be0f4f11000:0x4000:load:0x4:rw:0x25000}}}
[00021.533] 01050.01053> dso: id=27787977e95f3b9563c9e0bd4d34ec92b7e9ad88 base=0x00007be0f4eec000 name=libfdio.so
[00021.533] 01050.01053> {{{module:0x5:liblaunchpad.so:elf:6fc2232dc8c1bc5c6adb8ad50ca794b5a260ee4f}}}
[00021.533] 01050.01053> {{{mmap:0x7fdbca5f2000:0x7000:load:0x5:rx:0}}}
[00021.533] 01050.01053> {{{mmap:0x7fdbca5f9000:0x2000:load:0x5:rw:0x7000}}}
[00021.533] 01050.01053> dso: id=6fc2232dc8c1bc5c6adb8ad50ca794b5a260ee4f base=0x00007fdbca5f2000 name=liblaunchpad.so
[00021.533] 01050.01053> {{{module:0x6:libtrace-engine.so:elf:c9042b83fe01206008fcefb16395238417248169}}}
[00021.533] 01050.01053> {{{mmap:0x288b7866c000:0x9000:load:0x6:rx:0}}}
[00021.533] 01050.01053> {{{mmap:0x288b78675000:0x2000:load:0x6:rw:0x9000}}}
[00021.533] 01050.01053> dso: id=c9042b83fe01206008fcefb16395238417248169 base=0x0000288b7866c000 name=libtrace-engine.so
[00021.533] 01050.01053> bootsvc: Starting...
[00021.533] 01036.01043> userboot: loader-service channel peer closed
[00021.533] 01036.01043> userboot: finished!
[00021.533] 01050.01053> bootsvc: Creating bootfs service...
[00021.533] 01050.01053> bootsvc: Processing bootdata...
[00021.533] 01050.01053> bootsvc: Loading boot cmdline overrides...
[00021.533] 01050.01053> bootsvc: Loading kernel VMOs...
[00021.533] 01050.01053> bootsvc: Creating loader service...
[00021.533] 01050.01053> bootsvc: Launching next process...
[00021.534] 01050.01096> bootsvc: launched bin/devmgr
[00021.534] 01104.01117> devmgr: main()
[00021.534] 01104.01117> cmdline: netsvc.disable=true
[00021.534] 01104.01117> cmdline: zircon.system.disable-automount=true
[00021.534] 01104.01117> cmdline: zircon.autorun.boot=/boot/infra/setup
[00021.534] 01104.01117> cmdline: kernel.serial=legacy
[00021.534] 01104.01117> cmdline:
http://192.168.42.1/multiboot/54%3Ab2%3A03%3A13%3Ab3%3Ae7=
[00021.534] 01104.01117> cmdline: multiboot.boot_loader_name=iPXE+1.0.0++(d2063)
[00021.534] 01104.01117> devmgr: coordinator_init()
[00021.534] 01104.01117> devmgr: init
[00021.534] 01104.01117> devmgr: svc init
[00021.534] 01104.01117> devmgr: launch /boot/bin/svchost (svchost) OK
[00021.534] 01104.01117> devmgr: vfs init
[00021.535] 01104.01117> devmgr: launch /boot/bin/fshost (fshost) OK
[00021.535] 01104.01222> devmgr: shell startup
[00021.536] 01182.01202> fshost: started.
[00021.537] 01104.01213> devmgr: launch /boot/bin/pwrbtn-monitor (pwrbtn-monitor) OK
[00021.537] 01104.01235> devmgr: launch /boot/bin/virtual-console (virtual-console) OK
[00021.537] 01104.01235> zircon.autorun.boot: starting '/boot/infra/setup'...
[00021.538] 01104.01235> devmgr: launch /boot/infra/setup (autorun:boot) OK
[00021.541] 01104.01117> devcoord: launch devhost 'devhost:sys': pid=2049
[00021.541] 01104.01117> devcoord: launch devhost 'devhost:test': pid=2082
[00021.541] 01104.01117> devcoord: launch devhost 'devhost:root': pid=2114
[00021.541] 01104.01117> devcoord: launch devhost 'devhost:misc': pid=2171
[00021.542] 02049.02073> devhost: trace provider registry begun
[00021.543] 02082.02105> devhost: trace provider registry begun
[00021.544] 02114.02157> devhost: trace provider registry begun
[00021.545] 02171.02210> devhost: trace provider registry begun
[00021.547] 01104.01222> devmgr: launch /boot/bin/sh (sh:console) OK
[00021.613] 02049.02073> acpi-bus: not using IOMMU
[00021.617] 02049.02073> acpi-pwrbtn: initialized
[00021.640] 02049.02073> acpi: published device pci(0x24646c044200), parent=proxy(0x24646c040540), handle=0x24646c07cc30
[00021.642] 02049.02073> acpi: published device rtc(0x24646c03f080), parent=acpi(0x24646c040780), handle=0x24646c0955b0
[00021.643] 02049.02073> acpi-ec: initialized
[00021.644] 02049.02073> acpi: failed to create NHLT VMO (res -10)
[00021.644] 02049.02073> acpi: failed to publish NHLT metadata
[00021.646] 02049.02073> [sysmem_init 28] async_get_default_dispatcher(): 0x24646c0330a0
[00021.646] 02049.02073> [sysmem_bind 40] sysmem_bind()
[00021.646] 02049.02073> acpi-bus: sysmem_register_protocol() intentionally ignored for now.
[00021.647] 02049.02073> PMU: 7 arch events
[00021.647] 02049.02073> PMU: arch event id range: 1-7
[00021.647] 02049.02073> PMU: 102 model events
[00021.647] 02049.02073> PMU: model event id range: 1-241
[00021.647] 02049.02073> Intel Processor Trace configuration for this chipset:
[00021.647] 02049.02073> mtc_freq_mask: 0x249
[00021.647] 02049.02073> cyc_thresh_mask: 0x3fff
[00021.647] 02049.02073> psb_freq_mask: 0x3f
[00021.647] 02049.02073> num addr ranges: 2
[00021.647] 01104.01117> devcoord: launch devhost 'devhost:pci#1:8086:5916': pid=2931
[00021.648] 01104.01117> devcoord: launch devhost 'devhost:pci#3:8086:9d2f': pid=3012
[00021.649] 01246.01572> vc: new input device /dev/class/input/000
[00021.649] 01104.01117> devcoord: launch devhost 'devhost:pci#5:8086:9d60': pid=3123
[00021.650] 01104.01117> devcoord: launch devhost 'devhost:pci#6:8086:9d61': pid=3202
[00021.650] 02931.02977> devhost: trace provider registry begun
[00021.651] 01104.01117> devcoord: launch devhost 'devhost:pci#9:8086:9d03': pid=3307
[00021.652] 03012.03082> devhost: trace provider registry begun
[00021.652] 01104.01117> devcoord: launch devhost 'devhost:pci#14:8086:9d71': pid=3395
[00021.653] 03123.03181> devhost: trace provider registry begun
[00021.653] 01104.01117> devcoord: launch devhost 'devhost:pci#16:8086:156f': pid=3461
[00021.655] 03123.03181> initialized intel serialio i2c driver, reg=0x3728cfbc7000 regsize=4096
[00021.656] 03307.03344> devhost: trace provider registry begun
[00021.658] 03307.03344> ahci: using MSI interrupt
[00021.660] 03202.03253> devhost: trace provider registry begun
[00021.660] 03461.03515> devhost: trace provider registry begun
[00021.660] 03202.03253> initialized intel serialio i2c driver, reg=0x657d70a4000 regsize=4096
[00021.667] 03395.03438> devhost: trace provider registry begun
[00021.670] 03395.03438> [IHDA DSP 00:1f.3] Failed to fetch NHLT (res -25)
[00021.670] 03395.03438> devhost[00:1f.3/intel-hda-000/intel-sst-dsp-000] bind driver '/boot/driver/dsp.so' failed: -25
[00021.670] 01104.01117> devcoord: rpc: bind-driver 'intel-sst-dsp-000' status -25
[00021.687] 03012.03752> * found USB device (0x18d1:0xa002, USB 2.0) config 1
[00021.687] 03012.03752> * found USB device (0x18d1:0xa003, USB 3.0) config 1
[00021.759] 01246.01572> vc: new display device /dev/class/display-controller/000/virtcon
[00021.899] 02931.04142> i915: MST not supported
[00022.400] 03012.03752> * found USB device (0x0781:0x5583, USB 3.0) config 1
[00022.400] 03012.03082> UMS: parent: 'ifc-000'
[00022.400] 03012.03082> UMS:Max lun is: 0
[00022.402] 02931.04142> i915: MST not supported
[00023.160] 03012.03752> * found USB device (0x0cf3:0xe300, USB 2.1) config 1
[00023.161] 03012.03082> devhost[00:14.0/xhci/usb-bus/002/002/ifc-001] bind driver '/boot/driver/bt-transport-usb.so' failed: -2
[00023.161] 01104.01117> devcoord: rpc: bind-driver 'ifc-001' status -2
[00023.403] 03012.04229> UMS: block size is: 0x00000200
[00023.403] 03012.04229> UMS: total blocks is: 30031872
[00023.403] 03012.04229> UMS: total size is: 15376318464
[00023.403] 03012.04229> UMS: read-only: 0 removable: 1
[00023.404] 01182.01202> devmgr: /dev/class/block/000: MBR?
[00023.404] 01104.01117> devcoord: dc_bind_device() '/boot/driver/mbr.so'
[00023.406] 01182.01202> devmgr: /dev/class/block/002: MBR?
[00023.406] 01104.01117> devcoord: dc_bind_device() '/boot/driver/mbr.so'
[00023.446] 02931.04142> i915: No displays detected
[00023.658] 03123.03181> intel-i2c-controller: intel_serialio_i2c_slave_transfer: -21
[00023.658] 03123.03181> i2c-hid: could not read HID descriptor: 0
[00023.658] 03123.03181> devhost[00:15.0/i2c-bus-9d60/0020] bind driver '/boot/driver/i2c-hid.so' failed: -2
[00023.658] 01104.01117> devcoord: rpc: bind-driver '0020' status -2
[00023.661] 03202.03253> intel-i2c-controller: intel_serialio_i2c_slave_transfer: -21
[00023.661] 03202.03253> i2c-hid: could not read HID descriptor: 0
[00023.661] 03202.03253> devhost[00:15.1/i2c-bus-9d61/004c] bind driver '/boot/driver/i2c-hid.so' failed: -2
[00023.661] 01104.01117> devcoord: rpc: bind-driver '004c' status -2
[00023.681] 03307.03762> sata2: dev info
[00023.681] 03307.03762> serial=AA000000000000008069
[00023.681] 03307.03762> firmware rev=0R08A1 0
[00023.681] 03307.03762> model id=ETMAT 8MSP1582 G
[00023.681] 03307.03762> major=0x3f0 ACS2 DMA 32 commands
[00023.681] 03307.03762> LBA48 250069680 sectors, sector size=512
[00023.682] 01182.01202> devmgr: /dev/class/block/003: GPT?
[00023.682] 01104.01117> devcoord: dc_bind_device() '/boot/driver/gpt.so'
[00023.682] 03307.03344> gpt: device_get_metadata failed (-25)
[00023.684] 01182.01202> devmgr: /dev/class/block/004: FVM?
[00023.684] 01104.01117> devcoord: dc_bind_device() '/boot/driver/fvm.so'
[00023.686] 04483.04497> paver:[Initialize] Successfully initialized EFI Device Partitioner
[00023.688] 04483.04497> paver:[WipePartitions] Immediate reboot strongly recommended
[00023.688] 03307.03344> block: Joining un-closed FIFO server
[00023.688] 03307.03344> block: Joining un-closed FIFO server
[00023.688] 03307.03344> block: Joining un-closed FIFO server
[00023.688] 01104.01117> devcoord: dc_bind_device() ''
[00023.689] 01182.01202> devmgr: /dev/class/block/003: GPT?
[00023.689] 01104.01117> devcoord: dc_bind_device() '/boot/driver/gpt.so'
[00023.689] 03307.03344> gpt: device_get_metadata failed (-25)
[00023.692] 04802.04816> 34+0 records in
[00023.692] 04802.04816> 34+0 records out
[00023.692] 04802.04816> 17408 bytes copied
[00023.694] 04920.04934> 34+0 records in
[00023.694] 04920.04934> 34+0 records out
[00023.694] 04920.04934> 17408 bytes copied
[00023.695] 05024.05038> netifc: ? /dev/class/ethernet/000
[00023.695] 05024.05038> netifc: create 512 eth buffers
[00023.695] 05024.05038> macaddr: 54:b2:03:13:b3:e7
[00023.695] 05024.05038> ip6addr: fe80::56b2:34d:fe13:b3e7
[00023.695] 05024.05038> snmaddr: ff02::1:ff13:b3e7
[00023.696] 05024.05038> netsvc: using /dev/class/ethernet/000
[00023.696] 05024.05038> _ _ _
[00023.696] 05024.05038> | | | | |
[00023.696] 05024.05038> _______ __| | |__ ___ ___ | |_
[00023.696] 05024.05038> |_ / _ \/ _` | '_ \ / _ \ / _ \| __|
[00023.696] 05024.05038> / / __/ (_| | |_) | (_) | (_) | |_
[00023.696] 05024.05038> /___\___|\__,_|_.__/ \___/ \___/ \__|
[00023.696] 05024.05038>
[00023.696] 05024.05038>
[00023.696] 05024.05038> zedboot: version: 0.7.13
[00023.696] 05024.05038>
[00023.696] 05024.05038> netsvc: nodename='rash-moan-copy-slob'
[00023.696] 05024.05038> netsvc: will not advertise
[00023.696] 05024.05038> netsvc: start
[00880.576] 05024.05038> netsvc: tftp write of file <<netboot>>cmdline completed
[00880.576] 05024.05038> netsvc: metrics: {"inorderblks": 1,"oooblks": 0,"ack": 1,"nack": 0,"timeouts": 0,"sas": 0,"inorderbytes": 55}
[00880.576] 05024.05038> netsvc: Running FVM Paver
[00880.578] 05024.05132> paver:[InitializeGpt] Located GPT is invalid; Attempting to initialize
[00880.579] 01104.01117> devcoord: dc_bind_device() ''
[00880.579] 01104.01117> devcoord: dc_bind_device() '/boot/driver/gpt.so'
[00880.579] 03307.03344> gpt: device_get_metadata failed (-25)
[00880.580] 01182.01202> devmgr: /dev/class/block/003: GPT?
[00880.580] 01104.01117> devcoord: dc_bind_device() '/boot/driver/gpt.so'
[00880.580] 03307.03344> devhost: rpc:bind-device failed: -20
[00880.581] 05024.05132> paver:[Initialize] Successfully initialized EFI Device Partitioner
[00880.581] 05024.05132> paver:[PartitionPave] Paving partition.
[00880.581] 05024.05132> paver:[FindFirstFit] Looking for space
[00880.581] 05024.05132> paver:[FindFirstFit] Sorting
[00880.581] 05024.05132> paver:[FindFirstFit] Partition[0] From Block [0, 34) ... (next partition starts at block 250069646)
[00880.581] 05024.05132> paver:[FindFirstFit] There are 250069612 free blocks (16777216 requested)
[00880.581] 05024.05132> paver:[AddPartition] Found space in GPT - OK 250069612 @ 34
[00880.581] 05024.05132> paver:[AddPartition] Final space in GPT - OK 16777216 @ 34
[00880.581] 05024.05132> paver:[AddPartition] Added partition, waiting for bind
[00880.581] 01104.01117> devcoord: dc_bind_device() ''
[00880.582] 01182.01202> devmgr: /dev/class/block/003: GPT?
[00880.582] 01104.01117> devcoord: dc_bind_device() '/boot/driver/gpt.so'
[00880.583] 03307.03344> gpt: device_get_metadata failed (-25)
[00880.583] 05024.05132> paver:[AddPartition] Added partition, waiting for bind - OK
[00880.583] 05024.05132> paver:[PartitionPave] Streaming partitions...
[00880.583] 05112.05126> Found compressed file
[00880.584] 05024.05132> paver:[FvmStreamPartitions] Header Validated - OK
[00880.584] 05024.05132> paver:[FvmPartitionFormat] Initializing partition as FVM
[00880.586] 01104.01117> devcoord: dc_bind_device() '/boot/driver/fvm.so'
[00881.588] 05024.05132> paver:[FvmStreamPartitions] Partitions pre-validated successfully: Enough space exists to pave.
[00881.588] 05024.05132> paver:[AllocatePartitions] Allocating partition blobfs consisting of 1 slices
[00881.592] 05024.05132> paver:[AllocatePartitions] Allocating partition minfs consisting of 1 slices
[00881.593] 05024.05132> paver:[AllocatePartitions] Creating zxcrypt volume
[00881.595] 03307.03344> devhost_get_handles(0x39b8aa005900:block) open path='zxcrypt/block', r=-2
[00881.595] 01104.01117> devcoord: dc_bind_device() '/boot/driver/zxcrypt.so'
[00881.595] 03307.03344> devhost_get_handles(0x39b8aa005900:block) open path='zxcrypt', r=-2
[00881.600] 05024.05132> paver:[FvmStreamPartitions] Partition space pre-allocated successfully.
[00881.600] 05024.05132> paver:[FvmStreamPartitions] Streaming partition 0
[00881.600] 05024.05132> paver:[StreamFvmPartition] Writing extent 0...
[00881.600] 05024.05138> netsvc: paver write progress 0.1%
[00881.600] 05024.05132> paver:[StreamFvmPartition] 8192 bytes written, 8380416 zeroes left
[00881.616] 05024.05132> paver:[StreamFvmPartition] Writing extent 1...
[00881.616] 05024.05132> paver:[StreamFvmPartition] 8192 bytes written, 8380416 zeroes left
[00881.633] 05024.05132> paver:[StreamFvmPartition] Writing extent 2...
[00881.637] 05024.05132> paver:[StreamFvmPartition] 2097152 bytes written, 6291456 zeroes left
[00881.649] 05024.05132> paver:[StreamFvmPartition] Writing extent 3...
[00881.667] 05024.05132> paver:[StreamFvmPartition] 2097152 bytes written, 6291456 zeroes left
[00881.679] 05024.05132> paver:[StreamFvmPartition] Writing extent 4...
[00882.233] 05024.05038> netsvc: tftp write of file <<image>>sparse.fvm completed
[00882.233] 05024.05038> netsvc: metrics: {"inorderblks": 172321,"oooblks": 0,"ack": 674,"nack": 0,"timeouts": 0,"sas": 0,"inorderbytes": 176456018}
[00882.234] 05024.05132> paver:[StreamFvmPartition] 189751296 bytes written, 3186688 zeroes left
[00882.240] 05024.05132> paver:[FvmStreamPartitions] Done streaming partition 0
[00882.240] 05024.05132> paver:[FvmStreamPartitions] Done flushing partition 0
[00882.241] 05024.05132> paver:[FvmStreamPartitions] Streaming partition 1
[00882.241] 05024.05132> paver:[StreamFvmPartition] Writing extent 0...
[00882.241] 05024.05132> paver:[StreamFvmPartition] 8192 bytes written, 8380416 zeroes left
[00882.288] 05024.05132> paver:[StreamFvmPartition] Writing extent 1...
[00882.288] 05024.05132> paver:[StreamFvmPartition] 65536 bytes written, 8323072 zeroes left
[00882.326] 05024.05132> paver:[StreamFvmPartition] Writing extent 2...
[00882.327] 05024.05132> paver:[StreamFvmPartition] 65536 bytes written, 8323072 zeroes left
[00882.362] 05024.05132> paver:[StreamFvmPartition] Writing extent 3...
[00882.401] 05024.05132> paver:[StreamFvmPartition] Writing extent 4...
[00882.414] 05024.05132> paver:[StreamFvmPartition] 2097152 bytes written, 14680064 zeroes left
[00882.477] 05024.05132> paver:[StreamFvmPartition] Writing extent 5...
[00882.477] 05024.05132> paver:[StreamFvmPartition] 57344 bytes written, 8331264 zeroes left
[00882.513] 05024.05132> paver:[FvmStreamPartitions] Done streaming partition 1
[00882.513] 05024.05132> paver:[FvmStreamPartitions] Done flushing partition 1
[00882.514] 05112.05126> Reading FVM from compressed file: true
[00882.514] 05112.05126> Remaining bytes read into compression buffer: 0
[00882.514] 05112.05126> Remaining bytes written to decompression buffer: 0
[00882.514] 05112.05126> Time reading bytes from sparse FVM file: 332603331 (0 s)
[00882.514] 05112.05126> Time reading bytes AND decompressing them: 434503706 (0 s)
[00882.514] 05024.05132> paver:[PartitionPave] Completed successfully
[00883.234] 05024.05038> netsvc: Running BOOTLOADER Paver
[00883.237] 05024.05874> paver:[Initialize] Successfully initialized EFI Device Partitioner
[00883.237] 05024.05874> paver:[RealMain] SKIPPING BOOTLOADER install on x64 device, pass --force if desired.
[00883.246] 05024.05038> netsvc: tftp write of file <<image>>bootloader.img completed
[00883.246] 05024.05038> netsvc: metrics: {"inorderblks": 1093,"oooblks": 0,"ack": 5,"nack": 0,"timeouts": 0,"sas": 0,"inorderbytes": 1118208}
[00883.246] 05024.05038> netsvc: Running ZIRCON-A Paver
[00883.249] 05024.06015> paver:[Initialize] Successfully initialized EFI Device Partitioner
[00883.249] 05024.06015> paver:[PartitionPave] Paving partition.
[00883.249] 05024.06015> paver:[FindFirstFit] Looking for space
[00883.249] 05024.06015> paver:[FindFirstFit] Partition seen with start 34, end 16777249 (length 16777216)
[00883.249] 05024.06015> paver:[FindFirstFit] Sorting
[00883.249] 05024.06015> paver:[FindFirstFit] Partition[0] From Block [0, 34) ... (next partition starts at block 34)
[00883.249] 05024.06015> paver:[FindFirstFit] There are 0 free blocks (32768 requested)
[00883.249] 05024.06015> paver:[FindFirstFit] Partition[1] From Block [34, 16777250) ... (next partition starts at block 250069646)
[00883.249] 05024.06015> paver:[FindFirstFit] There are 233292396 free blocks (32768 requested)
[00883.249] 05024.06015> paver:[AddPartition] Found space in GPT - OK 233292396 @ 16777250
[00883.249] 05024.06015> paver:[AddPartition] Final space in GPT - OK 32768 @ 16777250
[00883.250] 05024.06015> paver:[AddPartition] Added partition, waiting for bind
[00883.250] 03307.03344> block: Joining un-closed FIFO server
[00883.250] 03307.03344> block: Joining un-closed FIFO server
[00883.250] 01104.01117> devcoord: dc_bind_device() ''
[00883.251] 01182.01202> devmgr: /dev/class/block/003: GPT?
[00883.251] 01104.01117> devcoord: dc_bind_device() '/boot/driver/gpt.so'
[00883.251] 03307.03344> gpt: device_get_metadata failed (-25)
[00883.252] 01182.01202> devmgr: /dev/class/block/013: FVM?
[00883.252] 01104.01117> devcoord: dc_bind_device() '/boot/driver/fvm.so'
[00883.252] 05024.06015> paver:[AddPartition] Added partition, waiting for bind - OK
[00883.378] 05024.05038> netsvc: tftp write of file <<image>>zircona.img completed
[00883.378] 05024.05038> netsvc: metrics: {"inorderblks": 13392,"oooblks": 0,"ack": 53,"nack": 0,"timeouts": 0,"sas": 0,"inorderbytes": 13712904}
[00883.414] 05024.06015> paver:[PartitionPave] Completed successfully
2019/04/26 04:10:50 attempting to send <<image>>zirconr.img...
[00884.379] 05024.05038> netsvc: Running ZIRCON-R Paver
[00884.382] 05024.06288> paver:[Initialize] Successfully initialized EFI Device Partitioner
[00884.382] 05024.06288> paver:[PartitionPave] Paving partition.
[00884.382] 05024.06288> paver:[FindFirstFit] Looking for space
[00884.382] 05024.06288> paver:[FindFirstFit] Partition seen with start 34, end 16777249 (length 16777216)
[00884.382] 05024.06288> paver:[FindFirstFit] Partition seen with start 16777250, end 16810017 (length 32768)
[00884.382] 05024.06288> paver:[FindFirstFit] Sorting
[00884.382] 05024.06288> paver:[FindFirstFit] Partition[0] From Block [0, 34) ... (next partition starts at block 34)
[00884.382] 05024.06288> paver:[FindFirstFit] There are 0 free blocks (49152 requested)
[00884.382] 05024.06288> paver:[FindFirstFit] Partition[1] From Block [34, 16777250) ... (next partition starts at block 16777250)
[00884.382] 05024.06288> paver:[FindFirstFit] There are 0 free blocks (49152 requested)
[00884.382] 05024.06288> paver:[FindFirstFit] Partition[2] From Block [16777250, 16810018) ... (next partition starts at block 250069646)
[00884.382] 05024.06288> paver:[FindFirstFit] There are 233259628 free blocks (49152 requested)
[00884.382] 05024.06288> paver:[AddPartition] Found space in GPT - OK 233259628 @ 16810018
[00884.382] 05024.06288> paver:[AddPartition] Final space in GPT - OK 49152 @ 16810018
[00884.382] 05024.06288> paver:[AddPartition] Added partition, waiting for bind
[00884.382] 03307.03344> block: Joining un-closed FIFO server
[00884.383] 01104.01117> devcoord: dc_bind_device() ''
[00884.383] 01182.01202> devmgr: /dev/class/block/003: GPT?
[00884.383] 01104.01117> devcoord: dc_bind_device() '/boot/driver/gpt.so'
[00884.383] 03307.03344> gpt: device_get_metadata failed (-25)
[00884.385] 01182.01202> devmgr: /dev/class/block/017: FVM?
[00884.385] 01104.01117> devcoord: dc_bind_device() '/boot/driver/fvm.so'
[00884.385] 05024.06288> paver:[AddPartition] Added partition, waiting for bind - OK
2019/04/26 04:10:50 done
2019/04/26 04:10:50 attempting to send <<image>>authorized_keys...
2019/04/26 04:10:50 target is busy, retrying in one second
[00884.499] 05024.05038> netsvc: tftp write of file <<image>>zirconr.img completed
[00884.499] 05024.05038> netsvc: metrics: {"inorderblks": 12182,"oooblks": 0,"ack": 48,"nack": 0,"timeouts": 0,"sas": 0,"inorderbytes": 12473696}
[00884.523] 05024.06288> paver:[PartitionPave] Completed successfully
2019/04/26 04:10:51 attempting to send <<image>>authorized_keys...
2019/04/26 04:10:51 done
2019/04/26 04:10:51 attempting to send <<netboot>>kernel.bin...
2019/04/26 04:10:51 target is busy, retrying in one second
[00885.500] 05024.05038> netsvc: Installing SSH authorized_keys
[00885.501] 05024.05038> netsvc: tftp write of file <<image>>authorized_keys completed
[00885.501] 05024.05038> netsvc: metrics: {"inorderblks": 1,"oooblks": 0,"ack": 1,"nack": 0,"timeouts": 0,"sas": 0,"inorderbytes": 806}
[00885.503] 05024.06577> paver:[Initialize] Successfully initialized EFI Device Partitioner
[00885.504] 01104.01117> devcoord: dc_bind_device() '/boot/driver/zxcrypt.so'
[00885.504] 03307.03344> devhost_get_handles(0x39b8aa005900:block) open path='zxcrypt', r=-2
[00885.530] 05024.06577> paver:[DataFilePave] Wrote ssh/authorized_keys
2019/04/26 04:10:52 attempting to send <<netboot>>kernel.bin...
2019/04/26 04:10:52 done
[00000.000] 00000.00000> zbi: @ 0xffffff8005dcc000 (12199160 bytes)
[00000.000] 00000.00000> UART: FIFO depth 16
[00000.000] 00000.00000> PMM: boot reserve add [0x100000, 0x2fcfff]
[00000.000] 00000.00000> PMM: boot reserve add [0x5dcc000, 0x696efff]
[00000.000] 00000.00000> PMM: arena too small to be useful (size 4096)
[00000.000] 00000.00000> PMM: pmm_add_arena failed to initialize arena
[00000.000] 00000.00000> MEM: Failed to add pmm range at 0x8afff000 size 0x1000
[00000.000] 00000.00000> PMM: boot reserve marking WIRED [0x100000, 0x2fcfff]
[00000.000] 00000.00000> PMM: boot reserve marking WIRED [0x5dcc000, 0x696efff]
[00000.000] 00000.00000>
[00000.000] 00000.00000> welcome to Zircon
[00000.000] 00000.00000>
[00000.000] 00000.00000> KASLR: .text section at 0xffffffff00100000
[00000.000] 00000.00000> INIT: cpu 0, calling hook 0xffffffff00115228 (global_prng_seed) at level 0x30000, flags 0x1
[00000.000] 00000.00000> initializing vm pre-heap
[00000.000] 00000.00000> VM: marking boot alloc used range [0x696f000, 0x696f100)
[00000.000] 00000.00000> INIT: cpu 0, calling hook 0xffffffff001225d8 (elf_build_id) at level 0x4fffe, flags 0x1
[00000.000] 00000.00000> INIT: cpu 0, calling hook 0xffffffff00122764 (version) at level 0x4ffff, flags 0x1
[00000.000] 00000.00000> version:
[00000.000] 00000.00000> arch: x86
[00000.000] 00000.00000> platform: XXX
[00000.000] 00000.00000> target: XXX
[00000.000] 00000.00000> project: x64
[00000.000] 00000.00000> buildid: git-d74104514739d2114d674d60550ba7cb3f2ad724-dirty
[00000.000] 00000.00000> ELF build ID: 838280d29ba1a62acdf6800d6285f04028acc678
[00000.000] 00000.00000> initializing heap
[00000.000] 00000.00000> INIT: cpu 0, calling hook 0xffffffff00101fc4 (console) at level 0x50000, flags 0x1
[00000.000] 00000.00000> INIT: cpu 0, calling hook 0xffffffff00182dc0 (x86_resource_init) at level 0x50000, flags 0x1
[00000.000] 00000.00000> initializing vm
[00000.000] 00000.00000> VM: reserving kernel region [0xffffffff00100000, 0xffffffff00219000) flags 0x28 name 'kernel_code'
[00000.000] 00000.00000> VM: reserving kernel region [0xffffffff00219000, 0xffffffff00269000) flags 0x8 name 'kernel_rodata'
[00000.000] 00000.00000> VM: reserving kernel region [0xffffffff00269000, 0xffffffff00271000) flags 0x18 name 'kernel_data'
[00000.000] 00000.00000> VM: reserving kernel region [0xffffffff00271000, 0xffffffff002fd000) flags 0x18 name 'kernel_bss'
[00000.000] 00000.00000> INIT: cpu 0, calling hook 0xffffffff00183ad0 (display_memtype) at level 0x60001, flags 0x1
[00000.000] 00000.00000> INIT: cpu 0, calling hook 0xffffffff00186f5c (acpi_tables) at level 0x60001, flags 0x1
[00000.000] 00000.00000> INIT: cpu 0, calling hook 0xffffffff00181bc4 (hpet) at level 0x60002, flags 0x1
[00000.000] 00000.00000> INIT: cpu 0, calling hook 0xffffffff00181f84 (apic) at level 0x60002, flags 0x1
[00000.000] 00000.00000> x2APIC enabled
[00000.000] 00000.00000> INIT: cpu 0, calling hook 0xffffffff001a85b4 (system_topology_init) at level 0x60002, flags 0x1
[00000.000] 00000.00000> WARNING: more than 1000 levels of cache, couldn't find highest.
[00000.000] 00000.00000> WARNING: unable to find any cache levels.
[00000.000] 00000.00000> Could not find SRAT table. ACPICA returned: 5
[00000.000] 00000.00000> INIT: cpu 0, calling hook 0xffffffff0018654c (timer) at level 0x60003, flags 0x1
[00000.000] 00000.00000> HPET frequency: 23999 ticks/ms
[00000.000] 00000.00000> TSC frequency: 2712000 ticks/ms
[00886.917] 00000.00000> timer features: constant_tsc 1 invariant_tsc 1 tsc_deadline 1
[00886.917] 00000.00000> Using TSC as wallclock
[00886.917] 00000.00000> INIT: cpu 0, calling hook 0xffffffff0020967c (percpu_heap_init) at level 0x60003, flags 0x1
[00886.917] 00000.00000> initializing kernel
[00886.917] 00000.00000> initializing mp
[00886.917] 00000.00000> INIT: cpu 0, calling hook 0xffffffff0011547c (global_prng_thread_safe) at level 0x7ffff, flags 0x1
[00886.917] 00000.00000> creating bootstrap completion thread
[00886.917] 00000.00000> top of bootstrap2()
[00886.917] 00000.00000> INIT: cpu 0, calling hook 0xffffffff00131a94 (libobject) at level 0x80000, flags 0x1
[00886.917] 00000.00000> OOM: started thread
[00886.917] 00000.00000> INIT: cpu 0, calling hook 0xffffffff00206630 (dpc) at level 0x80000, flags 0x1
[00886.917] 00000.00000> Processor Model Info: type 0 family 0x6 model 0xe stepping 0x9
[00886.917] 00000.00000> display_family 0x6 display_model 0x8e
[00886.917] 00000.00000> Vendor: Intel
[00886.917] 00000.00000> Microarch: Kaby Lake
[00886.917] 00000.00000> F/M/S: 6/8e/9
[00886.917] 00000.00000> patch_level: 8e
[00886.917] 00000.00000> Brand: Intel(R) Core(TM) i5-7300U CPU @ 2.60GHz
[00886.917] 00000.00000> Features: fpu sse sse2 sse3 ssse3 sse4.1 sse4.2 mmx avx avx2 fxsr pcid xsave mon aesni clflush
[00886.917] 00000.00000> clflushopt fsgsbase tsc_adj smep smap erms rdrand rdseed syscall nx huge rdtscp
[00886.917] 00000.00000> invar_tsc tsc_deadline x2apic vmx pt hwp
[00886.917] 00000.00000> Properties: meltdown l1tf pcid_good
[00886.917] 00000.00000> initializing platform
[00886.917] 00000.00000> INIT: cpu 0, calling hook 0xffffffff001a1cc4 (x86_perfmon) at level 0x90000, flags 0x1
[00886.917] 00000.00000> PMU: version 4
[00886.917] 00000.00000> UART: started IRQ driven RX
[00886.917] 00000.00000> UART: started IRQ driven TX
[00886.917] 00000.00000> cpu topology:
[00886.917] 00000.00000> 0: apic id 0x0 BSP
[00886.917] 00000.00000> 1: apic id 0x1
[00886.917] 00000.00000> 2: apic id 0x2
[00886.917] 00000.00000> 3: apic id 0x3
[00886.917] 00000.00000> Found 4 cpus
[00886.917] 00000.00000> booting apic ids: 0x1 0x2 0x3
[00886.932] 00000.00000> entering scheduler on cpu 1
[00886.933] 00000.00000> entering scheduler on cpu 3
[00886.933] 00000.00000> entering scheduler on cpu 2
[00886.935] 00000.00000> smbios: manufacturer="Intel Corporation" product="NUC7i5DNHE"
[00886.935] 00000.00000> initializing target
[00886.935] 00000.00000> INIT: cpu 0, calling hook 0xffffffff001857fc (x86_pcie_init) at level 0xa0000, flags 0x1
[00886.935] 00000.00000> moving to last init level
[00886.935] 00000.00000> INIT: cpu 0, calling hook 0xffffffff00121830 (debuglog) at level 0xb0000, flags 0x1
[00886.935] 00000.00000> INIT: cpu 0, calling hook 0xffffffff00175444 (kcounters) at level 0xb0000, flags 0x1
[00886.935] 00000.00000> INIT: cpu 0, calling hook 0xffffffff00102aec (kernel_shell) at level 0xc0000, flags 0x1
[00886.935] 00000.00000> INIT: cpu 0, calling hook 0xffffffff0020383c (ktrace) at level 0xc0000, flags 0x1
[00886.939] 00000.00000> ktrace: buffer at 0xffffff93f7c99000 (33554432 bytes)
[00886.939] 00000.00000> INIT: cpu 0, calling hook 0xffffffff00216470 (userboot) at level 0xc0000, flags 0x1
[00886.939] 00000.00000> userboot: ramdisk 0xba3000 @ 0xffffff8005dcc000
[00886.939] 00000.00000> userboot: userboot rodata 0 @ [0x44b784006000,0x44b784009000)
[00886.939] 00000.00000> userboot: userboot code 0x3000 @ [0x44b784009000,0x44b784014000)
[00886.939] 00000.00000> userboot: vdso/full rodata 0 @ [0x44b784014000,0x44b78401b000)
[00886.939] 00000.00000> userboot: vdso/full code 0x7000 @ [0x44b78401b000,0x44b78401c000)
[00886.939] 00000.00000> userboot: entry point @ 0x44b784009c90
[00886.939] 01036.01043> userboot: option "zircon.autorun.system=/boot/bin/sh+/boot/infra/runcmds"
[00886.968] 01036.01043> userboot: searching bootfs for 'bin/bootsvc'
[00886.968] 01036.01043> userboot: 'bin/bootsvc' has PT_INTERP "lib/ld.so.1"
[00886.968] 01036.01043> userboot: searching bootfs for 'lib/ld.so.1'
[00886.968] 01036.01043> userboot: userboot: loaded lib/ld.so.1 at 0x725ccc6d9000, entry point 0x725ccc6f73e0
[00886.968] 01036.01043> userboot: userboot: loaded vDSO at 0x5f40b765c000, entry point 0x5f40b7663907
[00886.968] 01036.01043> userboot: process bin/bootsvc started.
[00886.968] 01036.01043> userboot: waiting for loader-service requests...
[00886.968] 01036.01043> userboot: searching bootfs for 'lib/libasync-default.so'
[00886.968] 01036.01043> userboot: searching bootfs for 'lib/libfdio.so'
[00886.968] 01036.01043> userboot: searching bootfs for 'lib/libtrace-engine.so'
[00886.968] 01036.01043> userboot: searching bootfs for 'lib/liblaunchpad.so'
[00886.968] 01050.01053> {{{reset}}}
[00886.968] 01050.01053> {{{module:0:<application>:elf:b8a10fabd40dc946723955482070cd89ad5d6f6e}}}
[00886.968] 01050.01053> {{{mmap:0x452ac18d1000:0x3a000:load:0:rx:0}}}
[00886.968] 01050.01053> {{{mmap:0x452ac190b000:0x4000:load:0:rw:0x3a000}}}
[00886.968] 01050.01053> dso: id=b8a10fabd40dc946723955482070cd89ad5d6f6e base=0x0000452ac18d1000 name=<application>
[00886.968] 01050.01053> {{{module:0x2:<vDSO>:elf:2596d83da12ef9224f4df627b37dddb0f871b655}}}
[00886.968] 01050.01053> {{{mmap:0x5f40b765c000:0x7000:load:0x2:r:0}}}
[00886.968] 01050.01053> {{{mmap:0x5f40b7663000:0x1000:load:0x2:rx:0x7000}}}
[00886.968] 01050.01053> dso: id=2596d83da12ef9224f4df627b37dddb0f871b655 base=0x00005f40b765c000 name=<vDSO>
[00886.968] 01050.01053> {{{module:0x3:libasync-default.so:elf:a1ebd820a8fe8a159e7eb0ad92ab9f7dcf4c728e}}}
[00886.968] 01050.01053> {{{mmap:0x71e95e61a000:0x1000:load:0x3:rx:0}}}
[00886.968] 01050.01053> {{{mmap:0x71e95e61b000:0x1000:load:0x3:rw:0x1000}}}
[00886.968] 01050.01053> dso: id=a1ebd820a8fe8a159e7eb0ad92ab9f7dcf4c728e base=0x000071e95e61a000 name=libasync-default.so
[00886.968] 01050.01053> {{{module:0x4:libfdio.so:elf:e0d689c514dd90434528ba82d0bd7b842ef42be6}}}
[00886.968] 01050.01053> {{{mmap:0x4227fd45d000:0x32000:load:0x4:rx:0}}}
[00886.968] 01050.01053> {{{mmap:0x4227fd490000:0x4000:load:0x4:rw:0x33000}}}
[00886.968] 01050.01053> dso: id=e0d689c514dd90434528ba82d0bd7b842ef42be6 base=0x00004227fd45d000 name=libfdio.so
[00886.968] 01050.01053> {{{module:0x5:libtrace-engine.so:elf:5cf99e00b68e3cfa41dfd874cffe13a69dfd4c37}}}
[00886.968] 01050.01053> {{{mmap:0x403d1e609000:0x9000:load:0x5:rx:0}}}
[00886.968] 01050.01053> {{{mmap:0x403d1e612000:0x2000:load:0x5:rw:0x9000}}}
[00886.968] 01050.01053> dso: id=5cf99e00b68e3cfa41dfd874cffe13a69dfd4c37 base=0x0000403d1e609000 name=libtrace-engine.so
[00886.968] 01050.01053> {{{module:0x6:liblaunchpad.so:elf:a1c266341f7802b66afac60326dec9b419057b49}}}
[00886.968] 01050.01053> {{{mmap:0x6c2e57d9b000:0x7000:load:0x6:rx:0}}}
[00886.968] 01050.01053> {{{mmap:0x6c2e57da2000:0x2000:load:0x6:rw:0x7000}}}
[00886.968] 01050.01053> dso: id=a1c266341f7802b66afac60326dec9b419057b49 base=0x00006c2e57d9b000 name=liblaunchpad.so
[00886.968] 01050.01053> {{{module:0x1:libc.so:elf:8de7cb63945a526403ca2b041e14473d5b67c4f2}}}
[00886.968] 01050.01053> {{{mmap:0x725ccc6d9000:0xa6000:load:0x1:rx:0}}}
[00886.968] 01050.01053> {{{mmap:0x725ccc77f000:0x5000:load:0x1:rw:0xa6000}}}
[00886.968] 01050.01053> dso: id=8de7cb63945a526403ca2b041e14473d5b67c4f2 base=0x0000725ccc6d9000 name=libc.so
[00886.968] 01050.01053> bootsvc: Starting...
[00886.968] 01036.01043> userboot: loader-service channel peer closed
[00886.968] 01036.01043> userboot: finished!
[00886.968] 01050.01053> bootsvc: Creating bootfs service...
[00886.969] 01050.01053> bootsvc: Retrieving boot image...
[00886.969] 01050.01053> bootsvc: Decommitted BOOTDATA VMO from 0 to 0xba2000
[00886.969] 01050.01053> bootsvc: Loading boot arguments...
[00886.969] 01050.01053> bootsvc: Creating svcfs service...
[00886.969] 01050.01053> bootsvc: Loading kernel VMOs...
[00886.969] 01050.01053> bootsvc: Creating loader service...
[00886.969] 01050.01053> bootsvc: Launching next process...
[00886.969] 01050.01108> bootsvc: Launched bin/devcoordinator
[00886.970] 01115.01130> devcoordinator: launch /boot/bin/svchost (svchost) OK
[00886.971] 01115.01130> devcoordinator: launch /boot/bin/fshost (fshost) OK
[00886.973] 01115.01323> devcoordinator: launch /boot/bin/pwrbtn-monitor (pwrbtn-monitor) OK
[00886.974] 01115.01341> devcoordinator: launch /boot/bin/netsvc (netsvc) OK
[00886.974] 01115.01341> devcoordinator: launch /boot/bin/virtual-console (virtual-console) OK
[00886.977] 01115.01130> devcoordinator: full system required, ignoring fallback drivers until /system is loaded
[00886.978] 01115.01130> devcoordinator: launch devhost 'devhost:sys': pid=2179
[00886.978] 01115.01130> devcoordinator: launch devhost 'devhost:test': pid=2211
[00886.978] 01115.01130> devcoordinator: launch devhost 'devhost:root': pid=2258
[00886.979] 02179.02193> devhost: trace provider registry begun
[00886.979] 01115.01130> devcoordinator: launch devhost 'devhost:misc': pid=2334
[00886.980] 02211.02233> devhost: trace provider registry begun
[00886.980] 02258.02288> devhost: trace provider registry begun
[00886.981] 02334.02370> devhost: trace provider registry begun
[00886.982] 01115.01335> devcoordinator: launch /boot/bin/sh (sh:console) OK
[00887.067] 02179.02193> acpi-bus: not using IOMMU
[00887.074] 02179.02193> PMU: 7 arch events
[00887.074] 02179.02193> PMU: arch event id range: 1-7
[00887.074] 02179.02193> PMU: 102 arch events
[00887.074] 02179.02193> PMU: arch event id range: 1-241
[00887.074] 02179.02193> Intel Processor Trace configuration for this chipset:
[00887.074] 02179.02193> mtc_freq_mask: 0x249
[00887.074] 02179.02193> cyc_thresh_mask: 0x3fff
[00887.074] 02179.02193> psb_freq_mask: 0x3f
[00887.074] 02179.02193> num addr ranges: 2
[00887.074] 02179.02193> [sysmem_init 28] async_get_default_dispatcher(): 0x707a7e2c90d0
[00887.074] 02179.02193> [sysmem_bind 40] sysmem_bind()
[00887.074] 02179.02871> acpi-pwrbtn: initialized
[00887.075] 01702.01730> vc: new input device /dev/class/input/000
[00887.106] 02179.02871> acpi: published device pci(0x7079be32d770), parent=sys(0x707afe2c9110), handle=0x70797e2d7610
[00887.106] 01115.01130> devcoordinator: launch devhost 'devhost:pci#1:8086:5916': pid=2967
[00887.107] 01115.01130> devcoordinator: launch devhost 'devhost:pci#3:8086:9d2f': pid=3025
[00887.107] 02967.02981> devhost: trace provider registry begun
[00887.107] 01115.01130> devcoordinator: launch devhost 'devhost:pci#5:8086:9d60': pid=3092
[00887.108] 03025.03050> devhost: trace provider registry begun
[00887.108] 01115.01130> devcoordinator: launch devhost 'devhost:pci#6:8086:9d61': pid=3189
[00887.109] 01115.01130> devcoordinator: launch devhost 'devhost:pci#9:8086:9d03': pid=3294
[00887.109] 03092.03147> devhost: trace provider registry begun
[00887.109] 01115.01130> devcoordinator: launch devhost 'devhost:pci#14:8086:9d71': pid=3397
[00887.110] 02179.02871> acpi: published device rtc(0x7079be2e7270), parent=acpi(0x707afe2c9210), handle=0x70797e2fda50
[00887.110] 03294.03308> devhost: trace provider registry begun
[00887.111] 01115.01130> devcoordinator: launch devhost 'devhost:pci#16:8086:156f': pid=3544
[00887.111] 02179.02871> acpi-ec: initialized
[00887.113] 03189.03235> devhost: trace provider registry begun
[00887.115] 02179.02871> acpi: failed to create NHLT VMO (res -10)
[00887.115] 02179.02871> acpi: failed to publish NHLT metadata
[00887.115] 03397.03421> devhost: trace provider registry begun
[00887.115] 03092.03147> initialized intel serialio i2c driver, reg=0x8573bbf7000 regsize=4096
[00887.116] 03544.03567> devhost: trace provider registry begun
[00887.120] 03294.03308> ahci: using MSI interrupt
[00887.121] 03189.03235> initialized intel serialio i2c driver, reg=0x257eb930a000 regsize=4096
[00887.123] 03025.03941> * found USB device (0x18d1:0xa002, USB 2.0) config 1
[00887.123] 03025.03941> * found USB device (0x18d1:0xa003, USB 3.0) config 1
[00887.125] 03397.03421> [IHDA DSP 00:1f.3] Failed to fetch NHLT (res -25)
[00887.125] 03397.03421> [IHDA Controller 00:1f.3] Failed to initialize DSP device (res = -25)
[00887.197] 01616.01638> netifc: ? /dev/class/ethernet/000
[00887.197] 01616.01638> netifc: create 512 eth buffers
[00887.197] 01616.01638> macaddr: 54:b2:03:13:b3:e7
[00887.197] 01616.01638> ip6addr: fe80::56b2:34d:fe13:b3e7
[00887.197] 01616.01638> snmaddr: ff02::1:ff13:b3e7
[00887.197] 01616.01638> netsvc: using /dev/class/ethernet/000
[00887.197] 01616.01638> netsvc: nodename='rash-moan-copy-slob'
[00887.197] 01616.01638> netsvc: start
[00887.223] 01702.01730> vc: new display device /dev/class/display-controller/000
[00887.263] 02967.04235> i915: MST not supported
[00887.766] 02967.04235> i915: MST not supported
[00887.836] 03025.03941> * found USB device (0x0781:0x5583, USB 3.0) config 1
[00888.587] 03025.03941> * found USB device (0x0cf3:0xe300, USB 2.1) config 1
[00888.810] 02967.04235> i915: No displays detected
[00889.122] 03092.03147> intel-i2c-controller: intel_serialio_i2c_slave_transfer: -21
[00889.122] 03092.03147> i2c-hid: could not read HID descriptor: 0
[00889.122] 03092.03147> devhost[00:15.0/i2c-bus-9d60/0020] bind driver '/boot/driver/i2c-hid.so' failed: -2
[00889.122] 01115.01130> devcoordinator: rpc: bind-driver '0020' status -2
[00889.123] 03189.03235> intel-i2c-controller: intel_serialio_i2c_slave_transfer: -21
[00889.123] 03189.03235> i2c-hid: could not read HID descriptor: 0
[00889.123] 03189.03235> devhost[00:15.1/i2c-bus-9d61/004c] bind driver '/boot/driver/i2c-hid.so' failed: -2
[00889.123] 01115.01130> devcoordinator: rpc: bind-driver '004c' status -2
[00889.135] 03294.03883> sata2: dev info
[00889.135] 03294.03883> serial=AA000000000000008069
[00889.135] 03294.03883> firmware rev=0R08A1 0
[00889.135] 03294.03883> model id=ETMAT 8MSP1582 G
[00889.135] 03294.03883> major=0x3f0 ACS2 DMA 32 commands
[00889.135] 03294.03883> LBA48 250069680 sectors, sector size=512
[00889.136] 01301.01315> fshost: /dev/class/block/000: GPT?
[00889.137] 03294.03308> gpt: device_get_metadata failed (-25)
[00889.138] 01301.01315> fshost: /dev/class/block/001: FVM?
[00889.141] 01301.01315> devcoordinator: launch /boot/bin/blobfs (blobfs:/blob) OK
[00889.278] 01301.01315> fshost: starting 'bin/pkgsvr' 'c9e859cf093854111a854141d166ef121228dbdd970dde6841f9c77e50108b60'...
[00889.285] 01301.01315> devcoordinator: launch bin/pkgsvr (pkgfs) OK
[00889.295] 04626.04837> pkgsvr: system: will be served from c9e859cf093854111a854141d166ef121228dbdd970dde6841f9c77e50108b60
[00889.295] 04626.04837> pkgsvr: pkgfs serving index /data/pkgfs_index from blobfs /blob
[00889.295] 01301.01315> fshost: /dev/class/block/005: zxcrypt?
[00889.295] 03294.03308> devhost_get_handles(0x56eda884fa10:block) open path='zxcrypt', r=-2
[00889.302] 01301.01315> fshost: mounting minfs
[00889.302] 01301.01315> devcoordinator: launch /boot/bin/minfs (minfs:/data) OK
[00889.304] 05060.05074> minfs: filesystem in clean state.
[00889.347] 01115.04880> devcoordinator: adding system driver 'bt_hci_atheros' '/system/driver/bt-hci-atheros.so'
[00889.348] 01115.01748> devcoordinator: launch /system/bin/appmgr (appmgr) OK
[00889.348] 01115.01748> autorun: starting '/boot/bin/sh' '/boot/infra/runcmds'...
[00889.348] 01115.01748> devcoordinator: launch /boot/bin/sh (autorun:system) OK
[00889.356] 01115.04880> devcoordinator: adding system driver 'brcmfmac' '/system/driver/brcmfmac.so'
[00889.361] 01115.04880> devcoordinator: adding system driver 'qmi_fake' '/system/driver/qmi-fake.so'
[00889.418] 01115.04880> devcoordinator: adding system driver 'ralink' '/system/driver/ralink.so'
[00889.436] 01115.04880> devcoordinator: adding system driver 'wlan' '/system/driver/wlanif.so'
[00889.447] 01115.04880> devcoordinator: adding system driver 'usb_video' '/system/driver/usb_video.so'
[00889.460] 01115.04880> devcoordinator: adding system driver 'bt_hci_fake' '/system/driver/bt-hci-fake.so'
[00889.473] 01115.04880> devcoordinator: adding system driver 'wlan' '/system/driver/wlanphy.so'
[00889.475] 01115.04880> devcoordinator: adding system driver 'iwlwifi_pci' '/system/driver/iwlwifi.so'
[00889.484] 01115.04880> devcoordinator: adding system driver 'virtual_audio' '/system/driver/virtual_audio_driver.so'
[00889.495] 01115.04880> devcoordinator: adding system driver 'qmi_usb' '/system/driver/qmi-transport.so'
[00889.509] 01115.04880> devcoordinator: adding system driver 'virtual_camera' '/system/driver/virtual_camera_driver.so'
[00889.534] 01115.04880> devcoordinator: adding system driver 'bt_hci_intel' '/system/driver/bt-hci-intel.so'
[00889.537] 01115.04880> devcoordinator: adding system driver 'bt_hci_passthrough' '/system/driver/bt-hci-passthrough.so'
[00889.546] 01115.04880> devcoordinator: adding system driver 'gpu' '/system/driver/libmsd_intel.so'
[00889.577] 01115.04880> devcoordinator: adding system driver 'bt_host' '/system/driver/bt-host.so'
[00889.594] 01115.04880> devcoordinator: adding system driver 'mt8167s_gpu' '/system/driver/libmsd_img_rgx_mtk.so'
[00889.609] 01115.04880> devcoordinator: adding system driver 'bt_hog' '/system/driver/bt-hog.so'
[00889.609] 05173.05190> [INFO:namespace_builder.cc(44)] config-data for sysmgr
[00889.670] 01115.04880> devcoordinator: adding system driver 'wlan' '/system/driver/wlan.so'
[00889.679] 01115.04880> devcoordinator: adding system driver 'magma_pdev_gpu' '/system/driver/libmsd_arm.so'
[00889.688] 01115.04880> devcoordinator: adding system driver 'rtl88xx' '/system/driver/rtl88xx.so'
[00889.693] 01115.04880> devcoordinator: adding system driver 'ath10k_pci' '/system/driver/ath10k.so'
[00889.693] 01115.01130> devcoordinator: driver 'ath10k_pci' added
[00889.693] 01115.01130> devcoordinator: launch devhost 'devhost:pci#11:168c:003e': pid=5913
[00889.693] 01115.01130> devcoordinator: driver 'rtl88xx' added
[00889.693] 01115.01130> devcoordinator: driver 'magma_pdev_gpu' added
[00889.693] 01115.01130> devcoordinator: driver 'wlan' added
[00889.693] 01115.01130> devcoordinator: driver 'bt_hog' added
[00889.693] 01115.01130> devcoordinator: driver 'mt8167s_gpu' added
[00889.693] 01115.01130> devcoordinator: driver 'bt_host' added
[00889.693] 01115.01130> devcoordinator: driver 'gpu' added
[00889.693] 01115.01130> devcoordinator: driver 'bt_hci_intel' added
[00889.693] 01115.01130> devcoordinator: driver 'qmi_usb' added
[00889.693] 01115.01130> devcoordinator: driver 'iwlwifi_pci' added
[00889.693] 01115.01130> devcoordinator: driver 'wlan' added
[00889.693] 01115.01130> devcoordinator: driver 'bt_hci_fake' added
[00889.693] 01115.01130> devcoordinator: driver 'usb_video' added
[00889.693] 01115.01130> devcoordinator: driver 'wlan' added
[00889.693] 01115.01130> devcoordinator: driver 'ralink' added
[00889.693] 01115.01130> devcoordinator: driver 'qmi_fake' added
[00889.693] 01115.01130> devcoordinator: driver 'brcmfmac' added
[00889.693] 01115.01130> devcoordinator: driver 'bt_hci_atheros' added
[00889.693] 01115.01130> devcoordinator: driver 'bt_hci_passthrough' added
[00889.693] 01115.01130> devcoordinator: fallback driver 'usb_composite' is available
[00889.693] 01115.01130> devcoordinator: driver 'usb_composite' added
[00889.693] 01115.01130> devcoordinator: fallback driver 'intel_disp' is available
[00889.693] 01115.01130> devcoordinator: driver 'intel_disp' added
[00889.695] 05913.05927> devhost: trace provider registry begun
[00889.695] 05913.05927> ath10k: Probed chip QCA6174 ver: 2.1
[00889.697] 03025.03050> UMS: parent: 'ifc-000'
[00889.697] 03025.03050> UMS:Max lun is: 0
[00889.698] 03025.03050> devhost[00:14.0/xhci/usb-bus/002/002/ifc-001] bind driver '/boot/driver/bt-transport-usb.so' failed: -2
[00889.698] 01115.01130> devcoordinator: rpc: bind-driver 'ifc-001' status -2
[00889.700] 03025.06524> UMS: block size is: 0x00000200
[00889.700] 03025.06524> UMS: total blocks is: 30031872
[00889.700] 03025.06524> UMS: total size is: 15376318464
[00889.700] 03025.06524> UMS: read-only: 0 removable: 1
[00889.723] 03025.08988> btatheros: Making visible
[00889.723] 03025.08988> btatheros: loaded successfully
[00889.724] 03025.09089> [INFO:command_channel.cc(149)] hci: initialized
[00889.724] 01301.01315> fshost: /dev/class/block/007: MBR?
[00889.727] 01301.01315> fshost: /dev/class/block/009: MBR?
[00889.791] 03025.09089> [WARN:adapter.cc(273)] gap: controller is using legacy HCI version 4.1
[00889.792] 05173.05190> [INFO:namespace_builder.cc(44)] config-data for amber
[00889.797] 03025.09089> [INFO:acl_data_channel.cc(91)] hci: initialized
[00889.858] 05173.05190> [INFO:namespace_builder.cc(44)] config-data for pkg_resolver
[00889.993] 13636.13648> [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
[00889.993] 13636.13648> kfill_days=2, start_event_aggregator_worker=1.
[00890.059] 05173.05190> [INFO:namespace_builder.cc(44)] config-data for wlancfg
[00890.073] 05913.13559> devhost: rpc:load-firmware failed: -25
[00890.074] 05913.13559> devhost: rpc:load-firmware failed: -25
[00890.102] 05173.05190> [INFO:namespace_builder.cc(44)] config-data for mdns
[00890.348] 05173.05190> [INFO:namespace_builder.cc(44)] config-data for crashpad_agent
[00890.382] 16630.16648> [INFO:main.cc(35)] Trace Manager starting with config: /pkg/data/tracing.config
[00890.402] 15124.15141> [INFO:system_metrics_main.cc(23)] Cobalt SystemMetricsDaemon: System metrics daemon created.
[00890.502] 17178.17190> wlanstack2 [I]: Starting
[00890.765] 05913.13096> ath10k: Unknown eventid: 0x1d019
[00890.768] 05913.13096> ath10k: Unknown eventid: 0x16006
[00890.773] 05913.05927> wlanphy: event loop started
[00890.773] 05913.05927> wlanphy_bind
[00890.774] 17178.17190> wlanstack2::device [I]: new phy #0: /dev/sys/pci/01:00.0/ath10k-wlanphy/wlanphy
[00890.774] 14256.14274> wlancfg got event: OnPhyAdded { phy_id: 0 }
[00890.774] 14256.14274> wlancfg: phy 0 added
[00890.774] 17178.17190> wlanstack2::service [I]: query_phy(id = 0)
[00890.775] 17178.17190> wlanstack2::service [I]: query_phy(id = 0): received a 'QueryResult' from device
[00890.775] 14256.14274> wlancfg: received a PhyInfo from phy #0: path is /dev/sys/pci/01:00.0/ath10k-wlanphy/wlanphy
[00890.775] 14256.14274> using default wlan config entry for phy
[00890.775] 14256.14274> wlancfg: Creating Client iface for phy 0
[00890.776] 17178.17190> wlanstack2::service [I]: iface #0 started (phy id: 0, local id: 0)
[00890.776] 17178.17190> wlanstack2::service [I]: iface's driver does not support SME channels
[00890.782] 05913.05927> wlan_bind
[00890.785] 05913.05927> ath10k: adding a station interface (vdev_id=0) ...
[00890.787] 05913.05927> wlan: [I] Initialize a client MLME.
[00890.787] 05913.18062> wlan: [I] starting MainLoop
[00890.787] 05913.05927> wlan: [I] channel opened
[00890.788] 17178.17190> wlanstack2::device [I]: new iface #0 with role 'Client': /dev/sys/pci/01:00.0/ath10k-wlanphy/ath10k-wlanmac/wlan
[00890.789] 14256.14274> wlancfg got event: OnIfaceAdded { iface_id: 0 }
[00890.789] 14256.14274> wlancfg: new iface 0 added successfully
[00890.790] 14256.14274> wlancfg: Starting auto-connect loop with 0 saved networks
[00891.430] 14482.14496> Starting mDNS on interface ethp001f6 [2ff::100:13ff:e7b3] using port 5356
[00891.430] 14482.14496> [WARNING:garnet/bin/mdns/service/mdns_interface_transceiver_v6.cc(29)] NET-291 IPV6_MULTICAST_LOOP not supported (ENOPROTOOPT), continuing anyway
[00891.430] 14482.14496> [WARNING:garnet/bin/mdns/service/mdns_interface_transceiver_v6.cc(50)] NET-2180 IPV6_JOIN_GROUP returned ENODEV, mDNS will not communicate via IPV6
[00891.431] 14482.14496> Starting mDNS on interface ethp001f6 [80fe::b256:ff03:13fe:e7b3] using port 5356
[00891.431] 14482.14496> [WARNING:garnet/bin/mdns/service/mdns_interface_transceiver_v6.cc(29)] NET-291 IPV6_MULTICAST_LOOP not supported (ENOPROTOOPT), continuing anyway
[00891.431] 14482.14496> [WARNING:garnet/bin/mdns/service/mdns_interface_transceiver_v6.cc(50)] NET-2180 IPV6_JOIN_GROUP returned ENODEV, mDNS will not communicate via IPV6
[00894.953] 14482.14496> Starting mDNS on interface ethp001f6 192.168.42.103 using port 5356
[00894.953] 14482.14496> [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
[00894.954] 14482.14496> Starting mDNS on interface ethp001f6 [80fe::b256:ff03:13fe:e7b3] using port 5356
[00894.954] 14482.14496> [WARNING:garnet/bin/mdns/service/mdns_interface_transceiver_v6.cc(29)] NET-291 IPV6_MULTICAST_LOOP not supported (ENOPROTOOPT), continuing anyway
[00894.954] 14482.14496> [WARNING:garnet/bin/mdns/service/mdns_interface_transceiver_v6.cc(50)] NET-2180 IPV6_JOIN_GROUP returned ENODEV, mDNS will not communicate via IPV6
[00894.954] 14482.14496> Starting mDNS on interface ethp001f6 [2ff::100:13ff:e7b3] using port 5356
[00894.954] 14482.14496> [WARNING:garnet/bin/mdns/service/mdns_interface_transceiver_v6.cc(29)] NET-291 IPV6_MULTICAST_LOOP not supported (ENOPROTOOPT), continuing anyway
[00894.954] 14482.14496> [WARNING:garnet/bin/mdns/service/mdns_interface_transceiver_v6.cc(50)] NET-2180 IPV6_JOIN_GROUP returned ENODEV, mDNS will not communicate via IPV6
[00894.954] 14482.14496> mDNS: Verifying uniqueness of host name rash-moan-copy-slob.local.
[00895.851] 14482.14496> mDNS: Using unique host name rash-moan-copy-slob.local.
Running tests sequentially.
[tb] 2019-04-26 04:11:47.835 [22mINFO[0m [AndroidDevice|896X05XLX] The primary device under test is "896X05XLX". [android_device.py:create:92]
[tb] 2019-04-26 04:11:49.960 [22mINFO[0m [AndroidDevice|896X05XLX] Screen is not awake, wake it up [android_device.py:wakeup_screen:1374]
[tb] 2019-04-26 04:11:50.994 [22mINFO[0m Controller AndroidDevice: [{'build_id': '5289084', 'build_type': 'userdebug', 'model': 'blueline', 'serial': '896X05XLX', 'incremental_build_id': '5289084'}] [base_test.py:register_controller:396]
[tb] 2019-04-26 04:11:51.002 [22mINFO[0m [SshConnection | 192.168.42.103] Starting master ssh connection. [connection.py:setup_master_ssh:141]
[00945.458] 23450.23462> setsockopt IP_TOS 32: Protocol not available:
[tb] 2019-04-26 04:11:51.226 [22mINFO[0m [SshConnection | 192.168.42.103] Starting master ssh connection. [connection.py:setup_master_ssh:141]
[00945.667] 24027.24041> setsockopt IP_TOS 32: Protocol not available:
[tb] 2019-04-26 04:11:52.453 [22mINFO[0m [SshConnection | 192.168.42.103] Starting master ssh connection. [connection.py:setup_master_ssh:141]
[00946.880] 25080.25094> setsockopt IP_TOS 32: Protocol not available:
[tb] 2019-04-26 04:11:52.684 [22mINFO[0m Controller FuchsiaDevice: [{'ip': '192.168.42.103'}] [base_test.py:register_controller:396]
[tb] 2019-04-26 04:11:53.507 [22mINFO[0m ==========> Sl4fSanityTest <========== [base_test.py:run:967]
[tb] 2019-04-26 04:11:53.509 [22mINFO[0m Congratulations! Fuchsia controllers have been initialized successfully! [Sl4fSanityTest.py:setup_class:41]
[tb] 2019-04-26 04:11:53.516 [22mINFO[0m [Test Case] test_example [base_test.py:exec_one_testcase:662]
[tb] 2019-04-26 04:11:53.517 [22mINFO[0m Congratulations! You've run your first test. [Sl4fSanityTest.py:test_example:46]
[tb] 2019-04-26 04:11:53.520 [22mINFO[0m [Test Case] test_example PASS [base_test.py:_on_pass:542]
[tb] 2019-04-26 04:11:54.065 [22mINFO[0m Summary for test class Sl4fSanityTest: ControllerInfo {'AndroidDevice': [{'build_id': '5289084', 'build_type': 'userdebug', 'model': 'blueline', 'serial': '896X05XLX', 'incremental_build_id': '5289084'}], 'FuchsiaDevice': [{'ip': '192.168.42.103'}]}, Requested 1, Executed 1, Passed 1, Failed 0, Skipped 0, Blocked 0, Unknown 0, Errors 0 [base_test.py:run:1027]
[tb] 2019-04-26 04:11:54.096 [22mINFO[0m [AndroidDevice|896X05XLX] The primary device under test is "896X05XLX". [android_device.py:create:92]
[tb] 2019-04-26 04:11:56.938 [22mINFO[0m Controller AndroidDevice: [{'build_id': '5289084', 'build_type': 'userdebug', 'model': 'blueline', 'serial': '896X05XLX', 'incremental_build_id': '5289084'}] [base_test.py:register_controller:396]
[tb] 2019-04-26 04:11:56.945 [22mINFO[0m [SshConnection | 192.168.42.103] Starting master ssh connection. [connection.py:setup_master_ssh:141]
[00951.393] 25755.25770> setsockopt IP_TOS 32: Protocol not available:
[tb] 2019-04-26 04:11:57.170 [22mINFO[0m [SshConnection | 192.168.42.103] Starting master ssh connection. [connection.py:setup_master_ssh:141]
[00951.605] 26360.26375> setsockopt IP_TOS 32: Protocol not available:
[tb] 2019-04-26 04:11:58.400 [22mINFO[0m [SshConnection | 192.168.42.103] Starting master ssh connection. [connection.py:setup_master_ssh:141]
[00952.834] 27425.27439> setsockopt IP_TOS 32: Protocol not available:
[tb] 2019-04-26 04:11:58.628 [22mINFO[0m Controller FuchsiaDevice: [{'ip': '192.168.42.103'}] [base_test.py:register_controller:396]
[tb] 2019-04-26 04:11:59.535 [22mINFO[0m There are: 1 fuchsia and 1 android devices. [BleFuchsiaAndroidTest.py:__init__:48]
[tb] 2019-04-26 04:11:59.536 [22mINFO[0m ==========> BleFuchsiaAndroidTest <========== [base_test.py:run:967]
[tb] 2019-04-26 04:11:59.537 [22mINFO[0m Setting up Android Devices
[tb] 2019-04-26 04:11:59.578 [22mINFO[0m [AndroidDevice|896X05XLX] Reset state of bluetooth on device. [bt_test_utils.py:factory_reset_bluetooth:529]
[tb] 2019-04-26 04:12:02.193 [22mINFO[0m State normalized {10}
[tb] 2019-04-26 04:12:07.084 [22mINFO[0m [AndroidDevice|896X05XLX] Android Phone device found. [bt_test_utils.py:get_device_selector_dictionary:694]
[tb] 2019-04-26 04:12:07.093 [22mINFO[0m [Test Case] test_fuchsia_adv_android_scan [base_test.py:exec_one_testcase:662]
[tb] 2019-04-26 04:12:07.117 [22mINFO[0m [Test ID] BleFuchsiaAndroidTest:test_fuchsia_adv_android_scan:1556251927.1159716 [BluetoothBaseTest.py:_safe_wrap_test_case:95]
[00961.570] 03025.03050> bt-transport-usb: timed out: ZX_ERR_TIMED_OUT
[tb] 2019-04-26 04:12:07.606 [22mINFO[0m Found scan result: {'data': {'CallbackType': 1,
'ID': 1,
'Result': {'advertiseFlags': 2,
'deviceInfo': {'address': '46:27:DD:38:6E:15',
'name': 'testADV123',
'state': 10,
'type': 2},
'deviceName': 'testADV123',
'manufacturerIdList': '[]',
'manufacturerSpecificDataList': '[]',
'rssi': -54,
'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',
'serviceDataList': '[]',
'serviceUuidList': '[]',
'serviceUuids': '',
'timestampNanos': 2111430748822601,
'txPowerLevel': -2147483648},
'Type': 'onScanResult'},
'name': 'BleScan1onScanResults',
'time': 1556251927585} [BleFuchsiaAndroidTest.py:test_fuchsia_adv_android_scan:151]
[tb] 2019-04-26 04:12:07.637 [22mINFO[0m [Test Case] test_fuchsia_adv_android_scan PASS [base_test.py:_on_pass:542]
[tb] 2019-04-26 04:12:07.651 [22mINFO[0m [Test Case] test_fuchsia_connect_android_periph [base_test.py:exec_one_testcase:662]
[tb] 2019-04-26 04:12:07.666 [22mINFO[0m [Test ID] BleFuchsiaAndroidTest:test_fuchsia_connect_android_periph:1556251927.6658487 [BluetoothBaseTest.py:_safe_wrap_test_case:95]
[tb] 2019-04-26 04:12:07.757 [22mINFO[0m Android device name: Pixel1234 [BleFuchsiaAndroidTest.py:test_fuchsia_connect_android_periph:98]
[00962.124] 03025.09089> [INFO:low_energy_discovery_manager.cc(91)] gap-le: start discovery
[tb] 2019-04-26 04:12:08.777 [22mINFO[0m Successfully found advertisement! name, id: Pixel1234, 54f556fee63a347d [bt_test_utils.py:le_scan_for_device_by_name:43]
[tb] 2019-04-26 04:12:08.837 [22mINFO[0m Connecting returned status: {'id': '3', 'result': None, 'error': None} [BleFuchsiaAndroidTest.py:test_fuchsia_connect_android_periph:109]
[00963.195] 03025.09089> [INFO:low_energy_connection_manager.cc(769)] gap-le: new connection (LE link - handle: 0x0002, role: master, address: (LE rand) 5D:8A:AD:FC:71:47, interval: 45.00 ms, latency: 0.00 ms, timeout: 420 ms)
[tb] 2019-04-26 04:12:08.982 [22mINFO[0m Listing services returned: {'id': '4', 'result': [{'uuid_type': '00001801-0000-1000-8000-00805f9b34fb', 'id': 1, 'primary': True}, {'uuid_type': '00001800-0000-1000-8000-00805f9b34fb', 'id': 20, 'primary': True}], 'error': None} [BleFuchsiaAndroidTest.py:test_fuchsia_connect_android_periph:112]
[tb] 2019-04-26 04:12:08.991 [22mINFO[0m Disconnect status: {'id': '5', 'result': None, 'error': None} [BleFuchsiaAndroidTest.py:test_fuchsia_connect_android_periph:115]
[tb] 2019-04-26 04:12:09.034 [22mINFO[0m [Test Case] test_fuchsia_connect_android_periph PASS [base_test.py:_on_pass:542]
[00963.349] 03025.09089> [INFO:low_energy_connection_manager.cc(608)] gap-le: all refs dropped on connection: (LE link - handle: 0x0002, role: master, address: (LE rand) 5D:8A:AD:FC:71:47, interval: 45.00 ms, latency: 0.00 ms, timeout: 420 ms)
[00963.392] 03025.09089> [INFO:low_energy_connection_manager.cc(866)] gap-le: link disconnected - status: "success", handle: 0x0002, reason: 0x16
[tb] 2019-04-26 04:12:09.051 [22mINFO[0m [Test Case] test_fuchsia_scan_android_adv [base_test.py:exec_one_testcase:662]
[tb] 2019-04-26 04:12:09.067 [22mINFO[0m [Test ID] BleFuchsiaAndroidTest:test_fuchsia_scan_android_adv:1556251929.0667303 [BluetoothBaseTest.py:_safe_wrap_test_case:95]
[tb] 2019-04-26 04:12:09.144 [22mINFO[0m Android device name: Pixel1234 [BleFuchsiaAndroidTest.py:test_fuchsia_scan_android_adv:75]
[00963.510] 03025.09089> [INFO:low_energy_discovery_manager.cc(91)] gap-le: start discovery
[tb] 2019-04-26 04:12:10.162 [22mINFO[0m Successfully found advertisement! name, id: Pixel1234, a52c354ea8ce63be [bt_test_utils.py:le_scan_for_device_by_name:43]
[tb] 2019-04-26 04:12:10.203 [22mINFO[0m [Test Case] test_fuchsia_scan_android_adv PASS [base_test.py:_on_pass:542]
[tb] 2019-04-26 04:12:10.767 [22mINFO[0m Summary for test class BleFuchsiaAndroidTest: ControllerInfo {'AndroidDevice': [{'build_id': '5289084', 'build_type': 'userdebug', 'model': 'blueline', 'serial': '896X05XLX', 'incremental_build_id': '5289084'}], 'FuchsiaDevice': [{'ip': '192.168.42.103'}]}, Requested 3, Executed 3, Passed 3, Failed 0, Skipped 0, Blocked 0, Unknown 0, Errors 0 [base_test.py:run:1027]
[tb] 2019-04-26 04:12:10.790 [22mINFO[0m [AndroidDevice|896X05XLX] The primary device under test is "896X05XLX". [android_device.py:create:92]
[tb] 2019-04-26 04:12:13.551 [22mINFO[0m Controller AndroidDevice: [{'build_id': '5289084', 'build_type': 'userdebug', 'model': 'blueline', 'serial': '896X05XLX', 'incremental_build_id': '5289084'}] [base_test.py:register_controller:396]
[tb] 2019-04-26 04:12:13.558 [22mINFO[0m [SshConnection | 192.168.42.103] Starting master ssh connection. [connection.py:setup_master_ssh:141]
[00968.006] 31125.31140> setsockopt IP_TOS 32: Protocol not available:
[tb] 2019-04-26 04:12:13.782 [22mINFO[0m [SshConnection | 192.168.42.103] Starting master ssh connection. [connection.py:setup_master_ssh:141]
[00968.218] 31713.31728> setsockopt IP_TOS 32: Protocol not available:
[tb] 2019-04-26 04:12:15.009 [22mINFO[0m [SshConnection | 192.168.42.103] Starting master ssh connection. [connection.py:setup_master_ssh:141]
[00969.435] 32786.32802> setsockopt IP_TOS 32: Protocol not available:
[tb] 2019-04-26 04:12:15.243 [22mINFO[0m Controller FuchsiaDevice: [{'ip': '192.168.42.103'}] [base_test.py:register_controller:396]
[tb] 2019-04-26 04:12:16.070 [22mINFO[0m ==========> GattServerSetupTest <========== [base_test.py:run:967]
[tb] 2019-04-26 04:12:16.078 [22mINFO[0m [Test Case] test_alert_notification_service [base_test.py:exec_one_testcase:662]
[tb] 2019-04-26 04:12:16.093 [22mINFO[0m [Test Case] test_alert_notification_service PASS [base_test.py:_on_pass:542]
[tb] 2019-04-26 04:12:16.110 [22mINFO[0m [Test Case] test_automation_io_service [base_test.py:exec_one_testcase:662]
[tb] 2019-04-26 04:12:16.127 [22mINFO[0m [Test Case] test_automation_io_service PASS [base_test.py:_on_pass:542]
[tb] 2019-04-26 04:12:16.145 [22mINFO[0m [Test Case] test_battery_service [base_test.py:exec_one_testcase:662]
[tb] 2019-04-26 04:12:16.162 [22mINFO[0m [Test Case] test_battery_service PASS [base_test.py:_on_pass:542]
[tb] 2019-04-26 04:12:16.179 [22mINFO[0m [Test Case] test_blood_pressure_service [base_test.py:exec_one_testcase:662]
[tb] 2019-04-26 04:12:16.194 [22mINFO[0m [Test Case] test_blood_pressure_service PASS [base_test.py:_on_pass:542]
[tb] 2019-04-26 04:12:16.212 [22mINFO[0m [Test Case] test_body_composition_service [base_test.py:exec_one_testcase:662]
[tb] 2019-04-26 04:12:16.227 [22mINFO[0m [Test Case] test_body_composition_service PASS [base_test.py:_on_pass:542]
[tb] 2019-04-26 04:12:16.242 [22mINFO[0m [Test Case] test_bond_management_service [base_test.py:exec_one_testcase:662]
[tb] 2019-04-26 04:12:16.255 [22mINFO[0m [Test Case] test_bond_management_service PASS [base_test.py:_on_pass:542]
[tb] 2019-04-26 04:12:16.269 [22mINFO[0m [Test Case] test_continuous_glucose_monitoring_service [base_test.py:exec_one_testcase:662]
[tb] 2019-04-26 04:12:16.282 [22mINFO[0m [Test Case] test_continuous_glucose_monitoring_service PASS [base_test.py:_on_pass:542]
[tb] 2019-04-26 04:12:16.297 [22mINFO[0m [Test Case] test_current_time_service [base_test.py:exec_one_testcase:662]
[tb] 2019-04-26 04:12:16.313 [22mINFO[0m [Test Case] test_current_time_service PASS [base_test.py:_on_pass:542]
[tb] 2019-04-26 04:12:16.327 [22mINFO[0m [Test Case] test_cycling_power_service [base_test.py:exec_one_testcase:662]
[tb] 2019-04-26 04:12:16.341 [22mINFO[0m [Test Case] test_cycling_power_service PASS [base_test.py:_on_pass:542]
[tb] 2019-04-26 04:12:16.358 [22mINFO[0m [Test Case] test_cycling_speed_and_cadence_service [base_test.py:exec_one_testcase:662]
[tb] 2019-04-26 04:12:16.372 [22mINFO[0m [Test Case] test_cycling_speed_and_cadence_service PASS [base_test.py:_on_pass:542]
[tb] 2019-04-26 04:12:16.384 [22mINFO[0m [Test Case] test_device_information_service [base_test.py:exec_one_testcase:662]
[tb] 2019-04-26 04:12:16.399 [22mINFO[0m [Test Case] test_device_information_service PASS [base_test.py:_on_pass:542]
[tb] 2019-04-26 04:12:16.415 [22mINFO[0m [Test Case] test_duplicate_services [base_test.py:exec_one_testcase:662]
[tb] 2019-04-26 04:12:16.431 [22mINFO[0m [Test Case] test_duplicate_services PASS [base_test.py:_on_pass:542]
[tb] 2019-04-26 04:12:16.448 [22mINFO[0m [Test Case] test_environmental_sensing_service [base_test.py:exec_one_testcase:662]
[tb] 2019-04-26 04:12:16.472 [22mINFO[0m [Test Case] test_environmental_sensing_service PASS [base_test.py:_on_pass:542]
[tb] 2019-04-26 04:12:16.490 [22mINFO[0m [Test Case] test_fitness_machine_service [base_test.py:exec_one_testcase:662]
[tb] 2019-04-26 04:12:16.507 [22mINFO[0m [Test Case] test_fitness_machine_service PASS [base_test.py:_on_pass:542]
[tb] 2019-04-26 04:12:16.522 [22mINFO[0m [Test Case] test_glucose_service [base_test.py:exec_one_testcase:662]
[tb] 2019-04-26 04:12:16.538 [22mINFO[0m [Test Case] test_glucose_service PASS [base_test.py:_on_pass:542]
[tb] 2019-04-26 04:12:16.553 [22mINFO[0m [Test Case] test_health_thermometer_service [base_test.py:exec_one_testcase:662]
[tb] 2019-04-26 04:12:16.567 [22mINFO[0m [Test Case] test_health_thermometer_service PASS [base_test.py:_on_pass:542]
[tb] 2019-04-26 04:12:16.583 [22mINFO[0m [Test Case] test_heart_rate_service [base_test.py:exec_one_testcase:662]
[tb] 2019-04-26 04:12:16.597 [22mINFO[0m [Test Case] test_heart_rate_service PASS [base_test.py:_on_pass:542]
[tb] 2019-04-26 04:12:16.614 [22mINFO[0m [Test Case] test_http_proxy_service [base_test.py:exec_one_testcase:662]
[tb] 2019-04-26 04:12:16.629 [22mINFO[0m [Test Case] test_http_proxy_service PASS [base_test.py:_on_pass:542]
[tb] 2019-04-26 04:12:16.643 [22mINFO[0m [Test Case] test_human_interface_device_service [base_test.py:exec_one_testcase:662]
[tb] 2019-04-26 04:12:16.657 [22mINFO[0m [Test Case] test_human_interface_device_service PASS [base_test.py:_on_pass:542]
[tb] 2019-04-26 04:12:16.673 [22mINFO[0m [Test Case] test_immediate_alert_service [base_test.py:exec_one_testcase:662]
[tb] 2019-04-26 04:12:16.686 [22mINFO[0m [Test Case] test_immediate_alert_service PASS [base_test.py:_on_pass:542]
[tb] 2019-04-26 04:12:16.705 [22mINFO[0m [Test Case] test_indoor_positioning_service [base_test.py:exec_one_testcase:662]
[tb] 2019-04-26 04:12:16.722 [22mINFO[0m [Test Case] test_indoor_positioning_service PASS [base_test.py:_on_pass:542]
[tb] 2019-04-26 04:12:16.741 [22mINFO[0m [Test Case] test_insulin_delivery_service [base_test.py:exec_one_testcase:662]
[tb] 2019-04-26 04:12:16.758 [22mINFO[0m [Test Case] test_insulin_delivery_service PASS [base_test.py:_on_pass:542]
[tb] 2019-04-26 04:12:16.777 [22mINFO[0m [Test Case] test_internet_protocol_support_service [base_test.py:exec_one_testcase:662]
[tb] 2019-04-26 04:12:16.791 [22mINFO[0m [Test Case] test_internet_protocol_support_service PASS [base_test.py:_on_pass:542]
[tb] 2019-04-26 04:12:16.806 [22mINFO[0m [Test Case] test_link_loss_service [base_test.py:exec_one_testcase:662]
[tb] 2019-04-26 04:12:16.820 [22mINFO[0m [Test Case] test_link_loss_service PASS [base_test.py:_on_pass:542]
[tb] 2019-04-26 04:12:16.838 [22mINFO[0m [Test Case] test_location_and_navigation_service [base_test.py:exec_one_testcase:662]
[tb] 2019-04-26 04:12:16.853 [22mINFO[0m [Test Case] test_location_and_navigation_service PASS [base_test.py:_on_pass:542]
[tb] 2019-04-26 04:12:16.868 [22mINFO[0m [Test Case] test_mesh_provisioning_service [base_test.py:exec_one_testcase:662]
[tb] 2019-04-26 04:12:16.881 [22mINFO[0m [Test Case] test_mesh_provisioning_service PASS [base_test.py:_on_pass:542]
[tb] 2019-04-26 04:12:16.899 [22mINFO[0m [Test Case] test_mesh_proxy_service [base_test.py:exec_one_testcase:662]
[tb] 2019-04-26 04:12:16.911 [22mINFO[0m [Test Case] test_mesh_proxy_service PASS [base_test.py:_on_pass:542]
[tb] 2019-04-26 04:12:16.927 [22mINFO[0m [Test Case] test_next_dst_change_service [base_test.py:exec_one_testcase:662]
[tb] 2019-04-26 04:12:16.939 [22mINFO[0m [Test Case] test_next_dst_change_service PASS [base_test.py:_on_pass:542]
[tb] 2019-04-26 04:12:16.957 [22mINFO[0m [Test Case] test_object_transfer_service [base_test.py:exec_one_testcase:662]
[tb] 2019-04-26 04:12:16.971 [22mINFO[0m [Test Case] test_object_transfer_service PASS [base_test.py:_on_pass:542]
[tb] 2019-04-26 04:12:16.988 [22mINFO[0m [Test Case] test_phone_alert_status_service [base_test.py:exec_one_testcase:662]
[tb] 2019-04-26 04:12:17.002 [22mINFO[0m [Test Case] test_phone_alert_status_service PASS [base_test.py:_on_pass:542]
[tb] 2019-04-26 04:12:17.021 [22mINFO[0m [Test Case] test_primary_and_secondary_service [base_test.py:exec_one_testcase:662]
[tb] 2019-04-26 04:12:17.035 [22mINFO[0m [Test Case] test_primary_and_secondary_service PASS [base_test.py:_on_pass:542]
[tb] 2019-04-26 04:12:17.051 [22mINFO[0m [Test Case] test_pulse_oximeter_service [base_test.py:exec_one_testcase:662]
[tb] 2019-04-26 04:12:17.065 [22mINFO[0m [Test Case] test_pulse_oximeter_service PASS [base_test.py:_on_pass:542]
[tb] 2019-04-26 04:12:17.082 [22mINFO[0m [Test Case] test_reconnection_configuration_service [base_test.py:exec_one_testcase:662]
[tb] 2019-04-26 04:12:17.095 [22mINFO[0m [Test Case] test_reconnection_configuration_service PASS [base_test.py:_on_pass:542]
[tb] 2019-04-26 04:12:17.112 [22mINFO[0m [Test Case] test_reference_time_update_service [base_test.py:exec_one_testcase:662]
[tb] 2019-04-26 04:12:17.125 [22mINFO[0m [Test Case] test_reference_time_update_service PASS [base_test.py:_on_pass:542]
[tb] 2019-04-26 04:12:17.141 [22mINFO[0m [Test Case] test_running_speed_and_cadence_service [base_test.py:exec_one_testcase:662]
[tb] 2019-04-26 04:12:17.155 [22mINFO[0m [Test Case] test_running_speed_and_cadence_service PASS [base_test.py:_on_pass:542]
[tb] 2019-04-26 04:12:17.166 [22mINFO[0m [Test Case] test_scan_parameters_service [base_test.py:exec_one_testcase:662]
[tb] 2019-04-26 04:12:17.179 [22mINFO[0m [Test Case] test_scan_parameters_service PASS [base_test.py:_on_pass:542]
[tb] 2019-04-26 04:12:17.192 [22mINFO[0m [Test Case] test_single_primary_service [base_test.py:exec_one_testcase:662]
[tb] 2019-04-26 04:12:17.206 [22mINFO[0m [Test Case] test_single_primary_service PASS [base_test.py:_on_pass:542]
[tb] 2019-04-26 04:12:17.220 [22mINFO[0m [Test Case] test_single_secondary_service [base_test.py:exec_one_testcase:662]
[tb] 2019-04-26 04:12:17.233 [22mINFO[0m [Test Case] test_single_secondary_service PASS [base_test.py:_on_pass:542]
[tb] 2019-04-26 04:12:17.245 [22mINFO[0m [Test Case] test_transport_discovery_service [base_test.py:exec_one_testcase:662]
[tb] 2019-04-26 04:12:17.259 [22mINFO[0m [Test Case] test_transport_discovery_service PASS [base_test.py:_on_pass:542]
[tb] 2019-04-26 04:12:17.274 [22mINFO[0m [Test Case] test_tx_power_service [base_test.py:exec_one_testcase:662]
[tb] 2019-04-26 04:12:17.288 [22mINFO[0m [Test Case] test_tx_power_service PASS [base_test.py:_on_pass:542]
[tb] 2019-04-26 04:12:17.301 [22mINFO[0m [Test Case] test_user_data_service [base_test.py:exec_one_testcase:662]
[tb] 2019-04-26 04:12:17.315 [22mINFO[0m [Test Case] test_user_data_service PASS [base_test.py:_on_pass:542]
[tb] 2019-04-26 04:12:17.326 [22mINFO[0m [Test Case] test_weight_scale_service [base_test.py:exec_one_testcase:662]
[tb] 2019-04-26 04:12:17.338 [22mINFO[0m [Test Case] test_weight_scale_service PASS [base_test.py:_on_pass:542]
[tb] 2019-04-26 04:12:18.009 [22mINFO[0m Summary for test class GattServerSetupTest: ControllerInfo {'AndroidDevice': [{'build_id': '5289084', 'build_type': 'userdebug', 'model': 'blueline', 'serial': '896X05XLX', 'incremental_build_id': '5289084'}], 'FuchsiaDevice': [{'ip': '192.168.42.103'}]}, Requested 42, Executed 42, Passed 42, Failed 0, Skipped 0, Blocked 0, Unknown 0, Errors 0 [base_test.py:run:1027]
[tb] 2019-04-26 04:12:18.028 [22mINFO[0m [AndroidDevice|896X05XLX] The primary device under test is "896X05XLX". [android_device.py:create:92]
[tb] 2019-04-26 04:12:20.099 [22mINFO[0m [AndroidDevice|896X05XLX] Screen is not awake, wake it up [android_device.py:wakeup_screen:1374]
[tb] 2019-04-26 04:12:21.169 [22mINFO[0m Controller AndroidDevice: [{'build_id': '5289084', 'build_type': 'userdebug', 'model': 'blueline', 'serial': '896X05XLX', 'incremental_build_id': '5289084'}] [base_test.py:register_controller:396]
[tb] 2019-04-26 04:12:21.173 [22mINFO[0m [SshConnection | 192.168.42.103] Starting master ssh connection. [connection.py:setup_master_ssh:141]
[00975.606] 43846.43864> setsockopt IP_TOS 32: Protocol not available:
[tb] 2019-04-26 04:12:21.395 [22mINFO[0m [SshConnection | 192.168.42.103] Starting master ssh connection. [connection.py:setup_master_ssh:141]
[00975.835] 44442.44455> setsockopt IP_TOS 32: Protocol not available:
[tb] 2019-04-26 04:12:22.620 [22mINFO[0m [SshConnection | 192.168.42.103] Starting master ssh connection. [connection.py:setup_master_ssh:141]
[00977.061] 45527.45541> setsockopt IP_TOS 32: Protocol not available:
[tb] 2019-04-26 04:12:22.856 [22mINFO[0m Controller FuchsiaDevice: [{'ip': '192.168.42.103'}] [base_test.py:register_controller:396]
[tb] 2019-04-26 04:12:23.702 [22mINFO[0m Running testbed setup with one fuchsia devices [NetstackFuchsiaTest.py:__init__:31]
[tb] 2019-04-26 04:12:23.704 [22mINFO[0m ==========> NetstackFuchsiaTest <========== [base_test.py:run:967]
[tb] 2019-04-26 04:12:23.712 [22mINFO[0m [Test Case] test_fuchsia_publish_service [base_test.py:exec_one_testcase:662]
[tb] 2019-04-26 04:12:23.729 [22mINFO[0m [Test Case] test_fuchsia_publish_service PASS [base_test.py:_on_pass:542]
[tb] 2019-04-26 04:12:24.341 [22mINFO[0m Summary for test class NetstackFuchsiaTest: ControllerInfo {'AndroidDevice': [{'build_id': '5289084', 'build_type': 'userdebug', 'model': 'blueline', 'serial': '896X05XLX', 'incremental_build_id': '5289084'}], 'FuchsiaDevice': [{'ip': '192.168.42.103'}]}, Requested 1, Executed 1, Passed 1, Failed 0, Skipped 0, Blocked 0, Unknown 0, Errors 0 [base_test.py:run:1027]
[tb] 2019-04-26 04:12:24.363 [22mINFO[0m Summary for test run tb@2019-04-26_04-11-46-308: ControllerInfo {'AndroidDevice': [{'model': 'blueline', 'build_type': 'userdebug', 'build_id': '5289084', 'serial': '896X05XLX', 'incremental_build_id': '5289084'}], 'FuchsiaDevice': [{'ip': '192.168.42.103'}]}, Requested 47, Executed 47, Passed 47, Failed 0, Skipped 0, Blocked 0, Unknown 0, Errors 0
/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?
assert (True is pri_device.droid.bluetoothUnbond(target_address),
Command succeeded!