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

2019/05/22 10:38:00 attempting to send <<image>>sparse.fvm... [00000.000] 00000.00000> zbi: @ 0xffffff80012f2000 (17482848 bytes) [00000.000] 00000.00000> UART: FIFO depth 16 [00000.000] 00000.00000> PMM: boot reserve add [0x100000, 0x2c5fff] [00000.000] 00000.00000> PMM: boot reserve add [0x12f2000, 0x239efff] [00000.000] 00000.00000> PMM: arena too small to be useful (size 4096) [00000.000] 00000.00000> PMM: pmm_add_arena failed to initialize arena [00000.000] 00000.00000> MEM: Failed to add pmm range at 0x7ffff000 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.363] 00000.00000> timer features: constant_tsc 1 invariant_tsc 1 tsc_deadline 1 [00021.363] 00000.00000> Using TSC as wallclock [00021.363] 00000.00000> initializing kernel [00021.363] 00000.00000> initializing mp [00021.363] 00000.00000> initializing timers [00021.363] 00000.00000> INIT: cpu 0, calling hook 0xffffffff0013c578 (debuglog) at level 0x7ffff, flags 0x1 [00021.363] 00000.00000> INIT: cpu 0, calling hook 0xffffffff00195518 (thread_set_priority_experiment) at level 0x7ffff, flags 0x1 [00021.363] 00000.00000> thread set priority experiment is : ENABLED [00021.363] 00000.00000> INIT: cpu 0, calling hook 0xffffffff001aa67c (global_prng_thread_safe) at level 0x7ffff, flags 0x1 [00021.363] 00000.00000> creating bootstrap completion thread [00021.705] 00000.00000> top of bootstrap2() [00021.705] 00000.00000> INIT: cpu 0, calling hook 0xffffffff0013151c (dpc) at level 0x80000, flags 0x1 [00021.719] 00000.00000> INIT: cpu 0, calling hook 0xffffffff00152978 (libobject) at level 0x80000, flags 0x1 [00021.719] 00000.00000> OOM: started thread [00021.732] 00000.00000> Processor Model Info: type 0 family 0x6 model 0xe stepping 0x9 [00021.732] 00000.00000> display_family 0x6 display_model 0x8e [00021.732] 00000.00000> Vendor: Intel [00021.732] 00000.00000> Microarch: Kaby Lake [00021.732] 00000.00000> F/M/S: 6/8e/9 [00021.732] 00000.00000> Brand: Intel(R) Core(TM) i5-7300U CPU @ 2.60GHz [00021.732] 00000.00000> Features: fpu sse sse2 sse3 ssse3 sse4.1 sse4.2 mmx avx avx2 fxsr pcid xsave mon aesni clflush [00021.732] 00000.00000> clflushopt fsgsbase tsc_adj smep smap erms rdrand rdseed syscall nx huge rdtscp [00021.732] 00000.00000> invar_tsc tsc_deadline x2apic vmx pt hwp [00021.732] 00000.00000> initializing platform [00021.732] 00000.00000> INIT: cpu 0, calling hook 0xffffffff001101f4 (x86_perfmon) at level 0x90000, flags 0x1 [00021.732] 00000.00000> PMU: version 4 [00021.732] 00000.00000> UART: started IRQ driven RX [00021.732] 00000.00000> UART: started IRQ driven TX [00021.732] 00000.00000> cpu topology: [00021.732] 00000.00000> 0: apic id 0x0 package 0 node 0 core 0 smt 0 BSP [00021.732] 00000.00000> 1: apic id 0x2 package 0 node 0 core 1 smt 0 [00021.732] 00000.00000> 2: apic id 0x1 package 0 node 0 core 0 smt 1 [00021.732] 00000.00000> 3: apic id 0x3 package 0 node 0 core 1 smt 1 [00021.732] 00000.00000> Found 4 cpus [00021.732] 00000.00000> booting apic ids: 0x2 0x1 0x3 [00021.748] 00000.00000> entering scheduler on cpu 2 [00021.749] 00000.00000> entering scheduler on cpu 1 [00021.749] 00000.00000> entering scheduler on cpu 3 [00021.752] 00000.00000> smbios: manufacturer="Intel Corporation" product="NUC7i5DNKE" [00021.752] 00000.00000> initializing target [00021.752] 00000.00000> INIT: cpu 1, calling hook 0xffffffff001053a0 (x86_pcie_init) at level 0xa0000, flags 0x1 [00021.752] 00000.00000> moving to last init level [00021.752] 00000.00000> INIT: cpu 1, calling hook 0xffffffff00144140 (ktrace) at level 0xc0000, flags 0x1 [00021.755] 00000.00000> ktrace: buffer at 0xffffff920c929000 (33554432 bytes) [00021.755] 00000.00000> INIT: cpu 1, calling hook 0xffffffff00147ab4 (userboot) at level 0xc0000, flags 0x1 [00021.755] 00000.00000> userboot: ramdisk 0x10ad000 @ 0xffffff80012f2000 [00021.756] 00000.00000> userboot: userboot rodata 0 @ [0x19b69fd9e000,0x19b69fda1000) [00021.756] 00000.00000> userboot: userboot code 0x3000 @ [0x19b69fda1000,0x19b69fdac000) [00021.756] 00000.00000> userboot: vdso/full rodata 0 @ [0x19b69fdac000,0x19b69fdb3000) [00021.756] 00000.00000> userboot: vdso/full code 0x7000 @ [0x19b69fdb3000,0x19b69fdb4000) [00021.756] 00000.00000> userboot: entry point @ 0x19b69fda1c10 [00021.756] 00000.00000> INIT: cpu 1, calling hook 0xffffffff001aa030 (kernel_shell) at level 0xc0000, flags 0x1 [00021.756] 01036.01043> userboot: option "netsvc.disable=true" [00021.756] 01036.01043> userboot: option "zircon.system.disable-automount=true" [00021.756] 01036.01043> userboot: option "zircon.autorun.boot=/boot/infra/setup" [00021.756] 01036.01043> userboot: option "kernel.serial=legacy" [00021.756] 01036.01043> userboot: option "http://192.168.42.1/multiboot/d4%3A5d%3Adf%3A07%3Abe%3A7e=" [00021.756] 01036.01043> userboot: option "multiboot.boot_loader_name=iPXE+1.0.0++(d2063)" [00021.795] 01036.01043> userboot: searching bootfs for 'bin/bootsvc' [00021.795] 01036.01043> userboot: 'bin/bootsvc' has PT_INTERP "lib/ld.so.1" [00021.795] 01036.01043> userboot: searching bootfs for 'lib/ld.so.1' [00021.795] 01036.01043> userboot: userboot: loaded lib/ld.so.1 at 0x52caf5366000, entry point 0x52caf53ec0d3 [00021.795] 01036.01043> userboot: userboot: loaded vDSO at 0x5f96ea925000, entry point 0x0 [00021.795] 01036.01043> userboot: process bin/bootsvc started. [00021.795] 01036.01043> userboot: waiting for loader-service requests... [00021.795] 01036.01043> userboot: searching bootfs for 'lib/libasync-default.so' [00021.795] 01036.01043> userboot: searching bootfs for 'lib/libfdio.so' [00021.795] 01036.01043> userboot: searching bootfs for 'lib/liblaunchpad.so' [00021.795] 01036.01043> userboot: searching bootfs for 'lib/libtrace-engine.so' [00021.796] 01050.01053> {{{reset}}} [00021.796] 01050.01053> {{{module:0:<application>:elf:18de7d58f51e8ba5c4f6afdd0cc8440f482c2b45}}} [00021.796] 01050.01053> {{{mmap:0x3dab052cb000:0x2e000:load:0:rx:0}}} [00021.796] 01050.01053> {{{mmap:0x3dab052f9000:0x4000:load:0:rw:0x2e000}}} [00021.796] 01050.01053> dso: id=18de7d58f51e8ba5c4f6afdd0cc8440f482c2b45 base=0x00003dab052cb000 name=<application> [00021.796] 01050.01053> {{{module:0x3:libasync-default.so:elf:c189f51f19d10785d93b5235ad1b46dca4451b00}}} [00021.796] 01050.01053> {{{mmap:0x448073db9000:0x1000:load:0x3:rx:0}}} [00021.796] 01050.01053> {{{mmap:0x448073dba000:0x1000:load:0x3:rw:0x1000}}} [00021.796] 01050.01053> dso: id=c189f51f19d10785d93b5235ad1b46dca4451b00 base=0x0000448073db9000 name=libasync-default.so [00021.796] 01050.01053> {{{module:0x2:<vDSO>:elf:40ab5fa3b61f12fef4a44477a687f608661cd450}}} [00021.796] 01050.01053> {{{mmap:0x5f96ea925000:0x7000:load:0x2:r:0}}} [00021.796] 01050.01053> {{{mmap:0x5f96ea92c000:0x1000:load:0x2:rx:0x7000}}} [00021.796] 01050.01053> dso: id=40ab5fa3b61f12fef4a44477a687f608661cd450 base=0x00005f96ea925000 name=<vDSO> [00021.796] 01050.01053> {{{module:0x1:libc.so:elf:67a12284bce140fc32aaaeac223e0e8f85cb5085}}} [00021.796] 01050.01053> {{{mmap:0x52caf5366000:0xcb000:load:0x1:rx:0}}} [00021.796] 01050.01053> {{{mmap:0x52caf5432000:0x6000:load:0x1:rw:0xcc000}}} [00021.796] 01050.01053> dso: id=67a12284bce140fc32aaaeac223e0e8f85cb5085 base=0x000052caf5366000 name=libc.so [00021.796] 01050.01053> {{{module:0x4:libfdio.so:elf:27787977e95f3b9563c9e0bd4d34ec92b7e9ad88}}} [00021.796] 01050.01053> {{{mmap:0x55d12da8c000:0x24000:load:0x4:rx:0}}} [00021.796] 01050.01053> {{{mmap:0x55d12dab1000:0x4000:load:0x4:rw:0x25000}}} [00021.796] 01050.01053> dso: id=27787977e95f3b9563c9e0bd4d34ec92b7e9ad88 base=0x000055d12da8c000 name=libfdio.so [00021.796] 01050.01053> {{{module:0x5:liblaunchpad.so:elf:6fc2232dc8c1bc5c6adb8ad50ca794b5a260ee4f}}} [00021.796] 01050.01053> {{{mmap:0x8c910abd000:0x7000:load:0x5:rx:0}}} [00021.796] 01050.01053> {{{mmap:0x8c910ac4000:0x2000:load:0x5:rw:0x7000}}} [00021.796] 01050.01053> dso: id=6fc2232dc8c1bc5c6adb8ad50ca794b5a260ee4f base=0x000008c910abd000 name=liblaunchpad.so [00021.796] 01050.01053> {{{module:0x6:libtrace-engine.so:elf:c9042b83fe01206008fcefb16395238417248169}}} [00021.796] 01050.01053> {{{mmap:0x518f24ce9000:0x9000:load:0x6:rx:0}}} [00021.796] 01050.01053> {{{mmap:0x518f24cf2000:0x2000:load:0x6:rw:0x9000}}} [00021.796] 01050.01053> dso: id=c9042b83fe01206008fcefb16395238417248169 base=0x0000518f24ce9000 name=libtrace-engine.so [00021.796] 01050.01053> bootsvc: Starting... [00021.796] 01036.01043> userboot: loader-service channel peer closed [00021.796] 01036.01043> userboot: finished! [00021.796] 01050.01053> bootsvc: Creating bootfs service... [00021.796] 01050.01053> bootsvc: Processing bootdata... [00021.796] 01050.01053> bootsvc: Loading boot cmdline overrides... [00021.796] 01050.01053> bootsvc: Loading kernel VMOs... [00021.796] 01050.01053> bootsvc: Creating loader service... [00021.796] 01050.01053> bootsvc: Launching next process... [00021.797] 01050.01096> bootsvc: launched bin/devmgr [00021.797] 01104.01117> devmgr: main() [00021.797] 01104.01117> cmdline: netsvc.disable=true [00021.797] 01104.01117> cmdline: zircon.system.disable-automount=true [00021.797] 01104.01117> cmdline: zircon.autorun.boot=/boot/infra/setup [00021.797] 01104.01117> cmdline: kernel.serial=legacy [00021.797] 01104.01117> cmdline: http://192.168.42.1/multiboot/d4%3A5d%3Adf%3A07%3Abe%3A7e= [00021.797] 01104.01117> cmdline: multiboot.boot_loader_name=iPXE+1.0.0++(d2063) [00021.797] 01104.01117> devmgr: coordinator_init() [00021.797] 01104.01117> devmgr: init [00021.797] 01104.01117> devmgr: svc init [00021.797] 01104.01117> devmgr: launch /boot/bin/svchost (svchost) OK [00021.797] 01104.01117> devmgr: vfs init [00021.798] 01104.01117> devmgr: launch /boot/bin/fshost (fshost) OK [00021.798] 01104.01222> devmgr: shell startup [00021.799] 01182.01202> fshost: started. [00021.800] 01104.01213> devmgr: launch /boot/bin/pwrbtn-monitor (pwrbtn-monitor) OK [00021.800] 01104.01233> devmgr: launch /boot/bin/virtual-console (virtual-console) OK [00021.800] 01104.01233> zircon.autorun.boot: starting '/boot/infra/setup'... [00021.801] 01104.01233> devmgr: launch /boot/infra/setup (autorun:boot) OK [00021.803] 01104.01117> devcoord: launch devhost 'devhost:sys': pid=2049 [00021.803] 01104.01117> devcoord: launch devhost 'devhost:test': pid=2082 [00021.803] 01104.01117> devcoord: launch devhost 'devhost:root': pid=2115 [00021.804] 01104.01117> devcoord: launch devhost 'devhost:misc': pid=2165 [00021.805] 02049.02073> devhost: trace provider registry begun [00021.806] 02082.02106> devhost: trace provider registry begun [00021.807] 02165.02200> devhost: trace provider registry begun [00021.807] 02115.02151> devhost: trace provider registry begun [00021.815] 01104.01222> devmgr: launch /boot/bin/sh (sh:console) OK [00021.864] 02049.02073> acpi-bus: not using IOMMU [00021.868] 02049.02073> acpi-pwrbtn: initialized [00021.874] 02049.02073> WARNING: ACPI found bad _CRS address entry [00021.880] 02049.02073> WARNING: ACPI found bad _CRS address entry [00021.891] 02049.02073> acpi: published device pci(0x326e11c0e200), parent=proxy(0x326e11c0a540), handle=0x326e11c46c30 [00021.892] 02049.02073> acpi: published device rtc(0x326e11c09080), parent=acpi(0x326e11c0a780), handle=0x326e11c5f5b0 [00021.893] 02049.02073> acpi-ec: initialized [00021.895] 02049.02073> acpi: failed to create NHLT VMO (res -10) [00021.895] 02049.02073> acpi: failed to publish NHLT metadata [00021.897] 02049.02073> [sysmem_init 28] async_get_default_dispatcher(): 0x326e11bfd0a0 [00021.897] 02049.02073> [sysmem_bind 40] sysmem_bind() [00021.897] 02049.02073> acpi-bus: sysmem_register_protocol() intentionally ignored for now. [00021.897] 02049.02073> PMU: 7 arch events [00021.897] 02049.02073> PMU: arch event id range: 1-7 [00021.897] 02049.02073> PMU: 102 model events [00021.897] 02049.02073> PMU: model event id range: 1-241 [00021.897] 02049.02073> Intel Processor Trace configuration for this chipset: [00021.897] 02049.02073> mtc_freq_mask: 0x249 [00021.897] 02049.02073> cyc_thresh_mask: 0x3fff [00021.897] 02049.02073> psb_freq_mask: 0x3f [00021.897] 02049.02073> num addr ranges: 2 [00021.898] 01104.01117> devcoord: launch devhost 'devhost:pci#1:8086:5916': pid=2837 [00021.898] 01104.01117> devcoord: launch devhost 'devhost:pci#3:8086:9d2f': pid=2880 [00021.898] 01104.01117> devcoord: launch devhost 'devhost:pci#5:8086:9d60': pid=2944 [00021.899] 02837.02860> devhost: trace provider registry begun [00021.899] 01104.01117> devcoord: launch devhost 'devhost:pci#6:8086:9d61': pid=3008 [00021.900] 02880.02917> devhost: trace provider registry begun [00021.900] 02944.02978> devhost: trace provider registry begun [00021.900] 01104.01117> devcoord: launch devhost 'devhost:pci#9:8086:9d03': pid=3110 [00021.900] 03008.03076> devhost: trace provider registry begun [00021.901] 01104.01117> devcoord: launch devhost 'devhost:pci#14:8086:9d71': pid=3230 [00021.901] 01104.01117> devcoord: launch devhost 'devhost:pci#16:8086:156f': pid=3315 [00021.901] 03110.03182> devhost: trace provider registry begun [00021.903] 03008.03076> initialized intel serialio i2c driver, reg=0x4064dd81f000 regsize=4096 [00021.903] 02944.02978> initialized intel serialio i2c driver, reg=0x72789c274000 regsize=4096 [00021.903] 03230.03294> devhost: trace provider registry begun [00021.903] 03315.03358> devhost: trace provider registry begun [00021.905] 03110.03182> ahci: using MSI interrupt [00021.919] 02880.03730> * found USB device (0x18d1:0xa002, USB 2.0) config 1 [00021.919] 02880.03730> * found USB device (0x18d1:0xa003, USB 3.0) config 1 [00021.920] 03230.03294> [IHDA DSP 00:1f.3] Failed to fetch NHLT (res -25) [00021.920] 03230.03294> devhost[00:1f.3/intel-hda-000/intel-sst-dsp-000] bind driver '/boot/driver/dsp.so' failed: -25 [00021.920] 01104.01117> devcoord: rpc: bind-driver 'intel-sst-dsp-000' status -25 [00021.920] 01241.01587> vc: new input device /dev/class/input/000 [00022.010] 01241.01587> vc: new display device /dev/class/display-controller/000/virtcon [00022.150] 02837.04142> i915: Found DP monitor [00022.150] 02837.04142> i915: Display 1 connected [00022.151] 02837.04142> i915: MST not supported [00023.209] 01241.01587> vc: Successfully attached to display 1 [00023.382] 02880.03730> * found USB device (0x0781:0x5571, USB 2.0) config 1 [00023.383] 02880.02917> UMS: parent: 'ifc-000' [00023.383] 02880.02917> UMS:Max lun is: 0 [00023.633] 02880.03730> * found USB device (0x8087:0x0a2b, USB 2.0) config 1 [00023.635] 02880.02917> devhost[00:14.0/xhci/usb-bus/002/002/ifc-001] bind driver '/boot/driver/bt-transport-usb.so' failed: -2 [00023.635] 01104.01117> devcoord: rpc: bind-driver 'ifc-001' status -2 [00023.906] 03008.03076> intel-i2c-controller: intel_serialio_i2c_slave_transfer: -21 [00023.906] 03008.03076> i2c-hid: could not read HID descriptor: 0 [00023.906] 03008.03076> devhost[00:15.1/i2c-bus-9d61/004c] bind driver '/boot/driver/i2c-hid.so' failed: -2 [00023.906] 01104.01117> devcoord: rpc: bind-driver '004c' status -2 [00023.907] 02944.02978> intel-i2c-controller: intel_serialio_i2c_slave_transfer: -21 [00023.907] 02944.02978> i2c-hid: could not read HID descriptor: 0 [00023.907] 02944.02978> devhost[00:15.0/i2c-bus-9d60/0020] bind driver '/boot/driver/i2c-hid.so' failed: -2 [00023.907] 01104.01117> devcoord: rpc: bind-driver '0020' status -2 [00023.920] 03110.03662> sata2: dev info [00023.920] 03110.03662> serial=715400411052 5 [00023.920] 03110.03662> firmware rev=1P11A1E_ [00023.920] 03110.03662> model id=IBIW NSS D [00023.920] 03110.03662> major=0x3f0 ACS2 DMA 32 commands [00023.920] 03110.03662> LBA48 250069680 sectors, sector size=512 [00023.921] 01182.01202> devmgr: /dev/class/block/000: GPT? [00023.921] 01104.01117> devcoord: dc_bind_device() '/boot/driver/gpt.so' [00023.921] 03110.03182> gpt: device_get_metadata failed (-25) [00023.922] 01182.01202> devmgr: /dev/class/block/001: FVM? [00023.922] 01104.01117> devcoord: dc_bind_device() '/boot/driver/fvm.so' [00023.926] 04418.04441> paver:[Initialize] Successfully initialized EFI Device Partitioner [00023.927] 04418.04441> paver:[WipePartitions] Immediate reboot strongly recommended [00023.927] 03110.03182> block: Joining un-closed FIFO server [00023.927] 03110.03182> block: Joining un-closed FIFO server [00023.927] 03110.03182> block: Joining un-closed FIFO server [00023.927] 01104.01117> devcoord: dc_bind_device() '' [00023.927] 01182.01202> devmgr: /dev/class/block/000: GPT? [00023.927] 01104.01117> devcoord: dc_bind_device() '/boot/driver/gpt.so' [00023.928] 03110.03182> gpt: device_get_metadata failed (-25) [00023.930] 04715.04731> 34+0 records in [00023.930] 04715.04731> 34+0 records out [00023.930] 04715.04731> 17408 bytes copied [00023.933] 04820.04834> 34+0 records in [00023.933] 04820.04834> 34+0 records out [00023.933] 04820.04834> 17408 bytes copied [00023.934] 04924.04938> netifc: ? /dev/class/ethernet/000 [00023.934] 04924.04938> netifc: create 512 eth buffers [00023.934] 04924.04938> macaddr: d4:5d:df:07:be:7e [00023.934] 04924.04938> ip6addr: fe80::d65d:df4d:fe07:be7e [00023.934] 04924.04938> snmaddr: ff02::1:ff07:be7e [00023.934] 04924.04938> netsvc: using /dev/class/ethernet/000 [00023.934] 04924.04938> _ _ _ [00023.934] 04924.04938> | | | | | [00023.934] 04924.04938> _______ __| | |__ ___ ___ | |_ [00023.934] 04924.04938> |_ / _ \/ _` | '_ \ / _ \ / _ \| __| [00023.934] 04924.04938> / / __/ (_| | |_) | (_) | (_) | |_ [00023.934] 04924.04938> /___\___|\__,_|_.__/ \___/ \___/ \__| [00023.934] 04924.04938> [00023.934] 04924.04938> [00023.934] 04924.04938> zedboot: version: 0.7.13 [00023.934] 04924.04938> [00023.934] 04924.04938> netsvc: nodename='upper-stoop-folk-grape' [00023.934] 04924.04938> netsvc: will not advertise [00023.934] 04924.04938> netsvc: start [00024.385] 02880.04246> UMS: block size is: 0x00000200 [00024.385] 02880.04246> UMS: total blocks is: 15630336 [00024.385] 02880.04246> UMS: total size is: 8002732032 [00024.385] 02880.04246> UMS: read-only: 0 removable: 1 [00024.387] 01182.01202> devmgr: /dev/class/block/006: MBR? [00024.387] 01104.01117> devcoord: dc_bind_device() '/boot/driver/mbr.so' [00024.389] 01182.01202> devmgr: /dev/class/block/008: MBR? [00024.389] 01104.01117> devcoord: dc_bind_device() '/boot/driver/mbr.so' [03509.887] 04924.04938> netsvc: Running FVM Paver [03509.889] 04924.05107> paver:[InitializeGpt] Located GPT is invalid; Attempting to initialize [03509.890] 01104.01117> devcoord: dc_bind_device() '' [03509.890] 01104.01117> devcoord: dc_bind_device() '/boot/driver/gpt.so' [03509.890] 03110.03182> gpt: device_get_metadata failed (-25) [03509.890] 01182.01202> devmgr: /dev/class/block/000: GPT? [03509.890] 01104.01117> devcoord: dc_bind_device() '/boot/driver/gpt.so' [03509.890] 03110.03182> devhost: rpc:bind-device failed: -20 [03509.891] 04924.05107> paver:[Initialize] Successfully initialized EFI Device Partitioner [03509.891] 04924.05107> paver:[PartitionPave] Paving partition. [03509.891] 04924.05107> paver:[FindFirstFit] Looking for space [03509.891] 04924.05107> paver:[FindFirstFit] Sorting [03509.891] 04924.05107> paver:[FindFirstFit] Partition[0] From Block [0, 34) ... (next partition starts at block 250069646) [03509.891] 04924.05107> paver:[FindFirstFit] There are 250069612 free blocks (16777216 requested) [03509.891] 04924.05107> paver:[AddPartition] Found space in GPT - OK 250069612 @ 34 [03509.891] 04924.05107> paver:[AddPartition] Final space in GPT - OK 16777216 @ 34 [03509.891] 04924.05107> paver:[AddPartition] Added partition, waiting for bind [03509.891] 01104.01117> devcoord: dc_bind_device() '' [03509.891] 01182.01202> devmgr: /dev/class/block/000: GPT? [03509.892] 01104.01117> devcoord: dc_bind_device() '/boot/driver/gpt.so' [03509.892] 03110.03182> gpt: device_get_metadata failed (-25) [03509.892] 04924.05107> paver:[AddPartition] Added partition, waiting for bind - OK [03509.892] 04924.05107> paver:[PartitionPave] Streaming partitions... [03509.892] 05087.05101> Found compressed file [03509.892] 04924.05107> paver:[FvmStreamPartitions] Header Validated - OK [03509.892] 04924.05107> paver:[FvmPartitionFormat] Initializing partition as FVM [03509.895] 01104.01117> devcoord: dc_bind_device() '/boot/driver/fvm.so' [03510.896] 04924.05107> paver:[FvmStreamPartitions] Partitions pre-validated successfully: Enough space exists to pave. [03510.896] 04924.05107> paver:[AllocatePartitions] Allocating partition blobfs consisting of 1 slices [03510.900] 04924.05107> paver:[AllocatePartitions] Allocating partition minfs consisting of 1 slices [03510.901] 04924.05107> paver:[AllocatePartitions] Creating zxcrypt volume [03510.902] 03110.03182> devhost_get_handles(0x7b72adf8f900:block) open path='zxcrypt/block', r=-2 [03510.902] 01104.01117> devcoord: dc_bind_device() '/boot/driver/zxcrypt.so' [03510.903] 03110.03182> devhost_get_handles(0x7b72adf8f900:block) open path='zxcrypt', r=-2 [03510.906] 04924.05107> paver:[FvmStreamPartitions] Partition space pre-allocated successfully. [03510.906] 04924.05107> paver:[FvmStreamPartitions] Streaming partition 0 [03510.906] 04924.05107> paver:[StreamFvmPartition] Writing extent 0... [03510.906] 04924.05113> netsvc: paver write progress 0.0% [03510.906] 04924.05107> paver:[StreamFvmPartition] 8192 bytes written, 8380416 zeroes left [03510.958] 04924.05107> paver:[StreamFvmPartition] Writing extent 1... [03510.959] 04924.05107> paver:[StreamFvmPartition] 16384 bytes written, 8372224 zeroes left [03511.012] 04924.05107> paver:[StreamFvmPartition] Writing extent 2... [03511.025] 04924.05107> paver:[StreamFvmPartition] 2097152 bytes written, 6291456 zeroes left [03511.066] 04924.05107> paver:[StreamFvmPartition] Writing extent 3... [03511.079] 04924.05107> paver:[StreamFvmPartition] 2097152 bytes written, 6291456 zeroes left [03511.119] 04924.05107> paver:[StreamFvmPartition] Writing extent 4... [03511.907] 04924.05113> netsvc: paver write progress 17.1% [03512.913] 04924.05113> netsvc: paver write progress 38.6% [03513.941] 04924.05113> netsvc: paver write progress 51.9% [03514.965] 04924.05113> netsvc: paver write progress 56.9% [03515.968] 04924.05113> netsvc: paver write progress 72.8% 2019/05/22 10:38:06 done 2019/05/22 10:38:06 attempting to send <<image>>bootloader.img... 2019/05/22 10:38:06 target is busy, retrying in one second [03516.624] 04924.04938> netsvc: tftp write of file <<image>>sparse.fvm completed [03516.624] 04924.04938> netsvc: metrics: {"inorderblks": 659113,"oooblks": 0,"ack": 2575,"nack": 0,"timeouts": 0,"sas": 0,"inorderbytes": 674931252} [03516.970] 04924.05113> netsvc: paver write progress 96.1% [03517.139] 04924.05107> paver:[StreamFvmPartition] 722788352 bytes written, 7020544 zeroes left [03517.184] 04924.05107> paver:[FvmStreamPartitions] Done streaming partition 0 [03517.184] 04924.05107> paver:[FvmStreamPartitions] Done flushing partition 0 [03517.184] 04924.05107> paver:[FvmStreamPartitions] Streaming partition 1 [03517.184] 04924.05107> paver:[StreamFvmPartition] Writing extent 0... [03517.185] 04924.05107> paver:[StreamFvmPartition] 8192 bytes written, 8380416 zeroes left [03517.237] 04924.05107> paver:[StreamFvmPartition] Writing extent 1... [03517.238] 04924.05107> paver:[StreamFvmPartition] 65536 bytes written, 8323072 zeroes left [03517.290] 04924.05107> paver:[StreamFvmPartition] Writing extent 2... [03517.291] 04924.05107> paver:[StreamFvmPartition] 65536 bytes written, 8323072 zeroes left [03517.342] 04924.05107> paver:[StreamFvmPartition] Writing extent 3... [03517.394] 04924.05107> paver:[StreamFvmPartition] Writing extent 4... [03517.406] 04924.05107> paver:[StreamFvmPartition] 2097152 bytes written, 14680064 zeroes left [03517.503] 04924.05107> paver:[StreamFvmPartition] Writing extent 5... [03517.504] 04924.05107> paver:[StreamFvmPartition] 57344 bytes written, 8331264 zeroes left [03517.557] 04924.05107> paver:[FvmStreamPartitions] Done streaming partition 1 [03517.557] 04924.05107> paver:[FvmStreamPartitions] Done flushing partition 1 [03517.558] 05087.05101> Reading FVM from compressed file: true [03517.558] 05087.05101> Remaining bytes read into compression buffer: 0 [03517.558] 05087.05101> Remaining bytes written to decompression buffer: 0 [03517.558] 05087.05101> Time reading bytes from sparse FVM file: 352405838 (0 s) [03517.558] 05087.05101> Time reading bytes AND decompressing them: 709111487 (0 s) [03517.558] 04924.05107> paver:[PartitionPave] Completed successfully 2019/05/22 10:38:07 attempting to send <<image>>bootloader.img... 2019/05/22 10:38:07 done 2019/05/22 10:38:07 attempting to send <<image>>zircona.img... [03517.625] 04924.04938> netsvc: Running BOOTLOADER Paver [03517.627] 04924.06349> paver:[Initialize] Successfully initialized EFI Device Partitioner [03517.627] 04924.06349> paver:[RealMain] SKIPPING BOOTLOADER install on x64 device, pass --force if desired. [03517.641] 04924.04938> netsvc: tftp write of file <<image>>bootloader.img completed [03517.641] 04924.04938> netsvc: metrics: {"inorderblks": 1093,"oooblks": 0,"ack": 5,"nack": 0,"timeouts": 0,"sas": 0,"inorderbytes": 1118208} [03517.642] 04924.04938> netsvc: Running ZIRCON-A Paver [03517.644] 04924.06478> paver:[Initialize] Successfully initialized EFI Device Partitioner [03517.644] 04924.06478> paver:[PartitionPave] Paving partition. [03517.644] 04924.06478> paver:[FindFirstFit] Looking for space [03517.644] 04924.06478> paver:[FindFirstFit] Partition seen with start 34, end 16777249 (length 16777216) [03517.644] 04924.06478> paver:[FindFirstFit] Sorting [03517.644] 04924.06478> paver:[FindFirstFit] Partition[0] From Block [0, 34) ... (next partition starts at block 34) [03517.644] 04924.06478> paver:[FindFirstFit] There are 0 free blocks (32768 requested) [03517.644] 04924.06478> paver:[FindFirstFit] Partition[1] From Block [34, 16777250) ... (next partition starts at block 250069646) [03517.644] 04924.06478> paver:[FindFirstFit] There are 233292396 free blocks (32768 requested) [03517.644] 04924.06478> paver:[AddPartition] Found space in GPT - OK 233292396 @ 16777250 [03517.644] 04924.06478> paver:[AddPartition] Final space in GPT - OK 32768 @ 16777250 [03517.645] 03110.03182> block: Joining un-closed FIFO server [03517.645] 04924.06478> paver:[AddPartition] Added partition, waiting for bind [03517.645] 03110.03182> block: Joining un-closed FIFO server [03517.645] 01104.01117> devcoord: dc_bind_device() '' [03517.646] 01182.01202> devmgr: /dev/class/block/000: GPT? [03517.646] 01104.01117> devcoord: dc_bind_device() '/boot/driver/gpt.so' [03517.646] 03110.03182> gpt: device_get_metadata failed (-25) [03517.646] 01182.01202> devmgr: /dev/class/block/013: FVM? [03517.646] 01104.01117> devcoord: dc_bind_device() '/boot/driver/fvm.so' [03517.646] 04924.06478> paver:[AddPartition] Added partition, waiting for bind - OK 2019/05/22 10:38:08 done 2019/05/22 10:38:08 attempting to send <<image>>zirconr.img... 2019/05/22 10:38:08 target is busy, retrying in one second [03517.774] 04924.04938> netsvc: tftp write of file <<image>>zircona.img completed [03517.774] 04924.04938> netsvc: metrics: {"inorderblks": 12203,"oooblks": 0,"ack": 48,"nack": 0,"timeouts": 0,"sas": 0,"inorderbytes": 12495176} [03517.849] 04924.06478> paver:[PartitionPave] Completed successfully 2019/05/22 10:38:09 attempting to send <<image>>zirconr.img... [03518.775] 04924.04938> netsvc: Running ZIRCON-R Paver [03518.778] 04924.06738> paver:[Initialize] Successfully initialized EFI Device Partitioner [03518.778] 04924.06738> paver:[PartitionPave] Paving partition. [03518.778] 04924.06738> paver:[FindFirstFit] Looking for space [03518.778] 04924.06738> paver:[FindFirstFit] Partition seen with start 34, end 16777249 (length 16777216) [03518.778] 04924.06738> paver:[FindFirstFit] Partition seen with start 16777250, end 16810017 (length 32768) [03518.778] 04924.06738> paver:[FindFirstFit] Sorting [03518.778] 04924.06738> paver:[FindFirstFit] Partition[0] From Block [0, 34) ... (next partition starts at block 34) [03518.778] 04924.06738> paver:[FindFirstFit] There are 0 free blocks (49152 requested) [03518.778] 04924.06738> paver:[FindFirstFit] Partition[1] From Block [34, 16777250) ... (next partition starts at block 16777250) [03518.778] 04924.06738> paver:[FindFirstFit] There are 0 free blocks (49152 requested) [03518.778] 04924.06738> paver:[FindFirstFit] Partition[2] From Block [16777250, 16810018) ... (next partition starts at block 250069646) [03518.778] 04924.06738> paver:[FindFirstFit] There are 233259628 free blocks (49152 requested) [03518.778] 04924.06738> paver:[AddPartition] Found space in GPT - OK 233259628 @ 16810018 [03518.778] 04924.06738> paver:[AddPartition] Final space in GPT - OK 49152 @ 16810018 [03518.779] 04924.06738> paver:[AddPartition] Added partition, waiting for bind [03518.779] 03110.03182> block: Joining un-closed FIFO server [03518.779] 01104.01117> devcoord: dc_bind_device() '' [03518.779] 01182.01202> devmgr: /dev/class/block/000: GPT? [03518.779] 01104.01117> devcoord: dc_bind_device() '/boot/driver/gpt.so' [03518.779] 03110.03182> gpt: device_get_metadata failed (-25) [03518.780] 01182.01202> devmgr: /dev/class/block/017: FVM? [03518.780] 01104.01117> devcoord: dc_bind_device() '/boot/driver/fvm.so' [03518.780] 04924.06738> paver:[AddPartition] Added partition, waiting for bind - OK 2019/05/22 10:38:09 done 2019/05/22 10:38:09 attempting to send <<image>>authorized_keys... 2019/05/22 10:38:09 target is busy, retrying in one second [03518.909] 04924.04938> netsvc: tftp write of file <<image>>zirconr.img completed [03518.909] 04924.04938> netsvc: metrics: {"inorderblks": 11146,"oooblks": 0,"ack": 44,"nack": 0,"timeouts": 0,"sas": 0,"inorderbytes": 11413104} [03518.976] 04924.06738> paver:[PartitionPave] Completed successfully 2019/05/22 10:38:10 attempting to send <<image>>authorized_keys... 2019/05/22 10:38:10 done 2019/05/22 10:38:10 attempting to send <<netboot>>kernel.bin... 2019/05/22 10:38:10 target is busy, retrying in one second [03519.910] 04924.04938> netsvc: Installing SSH authorized_keys [03519.911] 04924.04938> netsvc: tftp write of file <<image>>authorized_keys completed [03519.911] 04924.04938> netsvc: metrics: {"inorderblks": 1,"oooblks": 0,"ack": 1,"nack": 0,"timeouts": 0,"sas": 0,"inorderbytes": 806} [03519.913] 04924.07015> paver:[Initialize] Successfully initialized EFI Device Partitioner [03519.914] 01104.01117> devcoord: dc_bind_device() '/boot/driver/zxcrypt.so' [03519.914] 03110.03182> devhost_get_handles(0x7b72adf8f900:block) open path='zxcrypt', r=-2 [03519.939] 04924.07015> paver:[DataFilePave] Wrote ssh/authorized_keys 2019/05/22 10:38:11 attempting to send <<netboot>>kernel.bin... 2019/05/22 10:38:11 done [00000.000] 00000.00000> zbi: @ 0xffffff80066f4000 (10903144 bytes) [00000.000] 00000.00000> UART: FIFO depth 16 [00000.000] 00000.00000> PMM: boot reserve add [0x100000, 0x311fff] [00000.000] 00000.00000> PMM: boot reserve add [0x66f4000, 0x7159fff] [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 0x7ffff000 size 0x1000 [00000.000] 00000.00000> PMM: boot reserve marking WIRED [0x100000, 0x311fff] [00000.000] 00000.00000> PMM: boot reserve marking WIRED [0x66f4000, 0x7159fff] [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 0xffffffff00118014 (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 [0x715a000, 0x715a100) [00000.000] 00000.00000> INIT: cpu 0, calling hook 0xffffffff00125270 (elf_build_id) at level 0x4fffe, flags 0x1 [00000.000] 00000.00000> INIT: cpu 0, calling hook 0xffffffff001253fc (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-c6f89f99e4712632917300ff480339ef2c3a704a-dirty [00000.000] 00000.00000> ELF build ID: 4b31e2e01b268026705ee30438d03e36a282c644 [00000.000] 00000.00000> initializing heap [00000.000] 00000.00000> INIT: cpu 0, calling hook 0xffffffff00101f78 (console) at level 0x50000, flags 0x1 [00000.000] 00000.00000> INIT: cpu 0, calling hook 0xffffffff00186c70 (x86_resource_init) at level 0x50000, flags 0x1 [00000.000] 00000.00000> initializing vm [00000.000] 00000.00000> VM: reserving kernel region [0xffffffff00100000, 0xffffffff00229000) flags 0x28 name 'kernel_code' [00000.000] 00000.00000> VM: reserving kernel region [0xffffffff00229000, 0xffffffff0027c000) flags 0x8 name 'kernel_rodata' [00000.000] 00000.00000> VM: reserving kernel region [0xffffffff0027c000, 0xffffffff00284000) flags 0x18 name 'kernel_data' [00000.000] 00000.00000> VM: reserving kernel region [0xffffffff00284000, 0xffffffff00312000) flags 0x18 name 'kernel_bss' [00000.000] 00000.00000> INIT: cpu 0, calling hook 0xffffffff00187994 (display_memtype) at level 0x60001, flags 0x1 [00000.000] 00000.00000> INIT: cpu 0, calling hook 0xffffffff0018aeb8 (acpi_tables) at level 0x60001, flags 0x1 [00000.000] 00000.00000> INIT: cpu 0, calling hook 0xffffffff00185998 (hpet) at level 0x60002, flags 0x1 [00000.000] 00000.00000> INIT: cpu 0, calling hook 0xffffffff00185db4 (apic) at level 0x60002, flags 0x1 [00000.000] 00000.00000> x2APIC enabled [00000.000] 00000.00000> INIT: cpu 0, calling hook 0xffffffff001acbd4 (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 0xffffffff0018a4a8 (timer) at level 0x60003, flags 0x1 [00000.000] 00000.00000> HPET frequency: 23999 ticks/ms [00000.000] 00000.00000> TSC frequency: 2712000 ticks/ms [03521.327] 00000.00000> timer features: constant_tsc 1 invariant_tsc 1 tsc_deadline 1 [03521.327] 00000.00000> Using TSC as wallclock [03521.327] 00000.00000> INIT: cpu 0, calling hook 0xffffffff00218bf4 (percpu_heap_init) at level 0x60003, flags 0x1 [03521.327] 00000.00000> initializing kernel [03521.327] 00000.00000> initializing mp [03521.327] 00000.00000> INIT: cpu 0, calling hook 0xffffffff00118268 (global_prng_thread_safe) at level 0x7ffff, flags 0x1 [03521.327] 00000.00000> creating bootstrap completion thread [03521.327] 00000.00000> top of bootstrap2() [03521.327] 00000.00000> INIT: cpu 0, calling hook 0xffffffff001348cc (libobject) at level 0x80000, flags 0x1 [03521.327] 00000.00000> OOM: started thread [03521.327] 00000.00000> INIT: cpu 0, calling hook 0xffffffff00215a04 (dpc) at level 0x80000, flags 0x1 [03521.327] 00000.00000> Processor Model Info: type 0 family 0x6 model 0xe stepping 0x9 [03521.327] 00000.00000> display_family 0x6 display_model 0x8e [03521.327] 00000.00000> Vendor: Intel [03521.327] 00000.00000> Microarch: Kaby Lake [03521.327] 00000.00000> F/M/S: 6/8e/9 [03521.327] 00000.00000> patch_level: 8e [03521.327] 00000.00000> Brand: Intel(R) Core(TM) i5-7300U CPU @ 2.60GHz [03521.327] 00000.00000> Features: fpu sse sse2 sse3 ssse3 sse4.1 sse4.2 mmx avx avx2 fxsr pcid xsave mon aesni clflush [03521.327] 00000.00000> clflushopt fsgsbase tsc_adj smep smap erms rdrand rdseed syscall nx huge rdtscp [03521.327] 00000.00000> invar_tsc tsc_deadline x2apic vmx pt hwp [03521.327] 00000.00000> Properties: meltdown l1tf pcid_good [03521.327] 00000.00000> initializing platform [03521.327] 00000.00000> INIT: cpu 0, calling hook 0xffffffff001a6298 (x86_perfmon) at level 0x90000, flags 0x1 [03521.327] 00000.00000> PMU: version 4 [03521.327] 00000.00000> UART: started IRQ driven RX [03521.327] 00000.00000> UART: started IRQ driven TX [03521.327] 00000.00000> cpu topology: [03521.327] 00000.00000> 0: apic id 0x0 BSP [03521.327] 00000.00000> 1: apic id 0x1 [03521.327] 00000.00000> 2: apic id 0x2 [03521.327] 00000.00000> 3: apic id 0x3 [03521.327] 00000.00000> Found 4 cpus [03521.327] 00000.00000> booting apic ids: 0x1 0x2 0x3 [03521.342] 00000.00000> entering scheduler on cpu 1 [03521.343] 00000.00000> entering scheduler on cpu 2 [03521.343] 00000.00000> entering scheduler on cpu 3 [03521.346] 00000.00000> smbios: manufacturer="Intel Corporation" product="NUC7i5DNKE" [03521.346] 00000.00000> initializing target [03521.346] 00000.00000> INIT: cpu 0, calling hook 0xffffffff0018964c (x86_pcie_init) at level 0xa0000, flags 0x1 [03521.346] 00000.00000> moving to last init level [03521.346] 00000.00000> INIT: cpu 0, calling hook 0xffffffff001244c8 (debuglog) at level 0xb0000, flags 0x1 [03521.346] 00000.00000> INIT: cpu 0, calling hook 0xffffffff00179278 (kcounters) at level 0xb0000, flags 0x1 [03521.346] 00000.00000> INIT: cpu 0, calling hook 0xffffffff00102aa0 (kernel_shell) at level 0xc0000, flags 0x1 [03521.346] 00000.00000> INIT: cpu 0, calling hook 0xffffffff0021242c (ktrace) at level 0xc0000, flags 0x1 [03521.349] 00000.00000> ktrace: buffer at 0xffffff91dc2d2000 (33554432 bytes) [03521.349] 00000.00000> INIT: cpu 0, calling hook 0xffffffff00225a38 (userboot) at level 0xc0000, flags 0x1 [03521.349] 00000.00000> userboot: ramdisk 0xa66000 @ 0xffffff80066f4000 [03521.350] 00000.00000> userboot: userboot rodata 0 @ [0x2209a9eb6000,0x2209a9eb9000) [03521.350] 00000.00000> userboot: userboot code 0x3000 @ [0x2209a9eb9000,0x2209a9ec4000) [03521.350] 00000.00000> userboot: vdso/full rodata 0 @ [0x2209a9ec4000,0x2209a9ecb000) [03521.350] 00000.00000> userboot: vdso/full code 0x7000 @ [0x2209a9ecb000,0x2209a9ecc000) [03521.350] 00000.00000> userboot: entry point @ 0x2209a9eb9c90 [03521.374] 01036.01043> userboot: searching bootfs for 'bin/bootsvc' [03521.374] 01036.01043> userboot: 'bin/bootsvc' has PT_INTERP "lib/ld.so.1" [03521.374] 01036.01043> userboot: searching bootfs for 'lib/ld.so.1' [03521.374] 01036.01043> userboot: userboot: loaded lib/ld.so.1 at 0x513b9c245000, entry point 0x513b9c263880 [03521.374] 01036.01043> userboot: userboot: loaded vDSO at 0x7ea5b431a000, entry point 0x7ea5b4321947 [03521.374] 01036.01043> userboot: process bin/bootsvc started. [03521.374] 01036.01043> userboot: waiting for loader-service requests... [03521.374] 01036.01043> userboot: searching bootfs for 'lib/libfdio.so' [03521.374] 01036.01043> userboot: searching bootfs for 'lib/libtrace-engine.so' [03521.374] 01036.01043> userboot: searching bootfs for 'lib/libasync-default.so' [03521.374] 01036.01043> userboot: searching bootfs for 'lib/liblaunchpad.so' [03521.374] 01036.01043> userboot: searching bootfs for 'lib/libc++.so.2' [03521.375] 01036.01043> userboot: searching bootfs for 'lib/libc++abi.so.1' [03521.375] 01036.01043> userboot: searching bootfs for 'lib/libunwind.so.1' [03521.375] 01050.01053> {{{reset}}} [03521.375] 01050.01053> {{{module:0:<application>:elf:378da0248fca2fb8c10e339ae03cb289aff5c110}}} [03521.375] 01050.01053> {{{mmap:0x150375271000:0x3b000:load:0:rx:0}}} [03521.375] 01050.01053> {{{mmap:0x1503752ac000:0x4000:load:0:rw:0x3b000}}} [03521.375] 01050.01053> dso: id=378da0248fca2fb8c10e339ae03cb289aff5c110 base=0x0000150375271000 name=<application> [03521.375] 01050.01053> {{{module:0x2:<vDSO>:elf:f82422446b9a9c521dcb0b0be40cb053fb8e7ef2}}} [03521.375] 01050.01053> {{{mmap:0x7ea5b431a000:0x7000:load:0x2:r:0}}} [03521.375] 01050.01053> {{{mmap:0x7ea5b4321000:0x1000:load:0x2:rx:0x7000}}} [03521.375] 01050.01053> dso: id=f82422446b9a9c521dcb0b0be40cb053fb8e7ef2 base=0x00007ea5b431a000 name=<vDSO> [03521.375] 01050.01053> {{{module:0x3:libfdio.so:elf:040528230cb93f3e80655a281da76235ec3b9308}}} [03521.375] 01050.01053> {{{mmap:0x3914e6e84000:0x38000:load:0x3:rx:0}}} [03521.375] 01050.01053> {{{mmap:0x3914e6ebd000:0x6000:load:0x3:rw:0x39000}}} [03521.375] 01050.01053> dso: id=040528230cb93f3e80655a281da76235ec3b9308 base=0x00003914e6e84000 name=libfdio.so [03521.375] 01050.01053> {{{module:0x4:libtrace-engine.so:elf:386dbd94d10ac2f61293861e8e1ac22585e420b8}}} [03521.375] 01050.01053> {{{mmap:0x228cf5161000:0x9000:load:0x4:rx:0}}} [03521.375] 01050.01053> {{{mmap:0x228cf516a000:0x2000:load:0x4:rw:0x9000}}} [03521.375] 01050.01053> dso: id=386dbd94d10ac2f61293861e8e1ac22585e420b8 base=0x0000228cf5161000 name=libtrace-engine.so [03521.375] 01050.01053> {{{module:0x5:libasync-default.so:elf:744cfae1697ffe6c2ab3401ff64a56d828f4e099}}} [03521.375] 01050.01053> {{{mmap:0x215be928c000:0x1000:load:0x5:rx:0}}} [03521.375] 01050.01053> {{{mmap:0x215be928d000:0x1000:load:0x5:rw:0x1000}}} [03521.375] 01050.01053> dso: id=744cfae1697ffe6c2ab3401ff64a56d828f4e099 base=0x0000215be928c000 name=libasync-default.so [03521.375] 01050.01053> {{{module:0x6:liblaunchpad.so:elf:2f80313e6faa90c888a0f1df712c7e806cc50153}}} [03521.375] 01050.01053> {{{mmap:0x19381b44d000:0x7000:load:0x6:rx:0}}} [03521.375] 01050.01053> {{{mmap:0x19381b454000:0x2000:load:0x6:rw:0x7000}}} [03521.375] 01050.01053> dso: id=2f80313e6faa90c888a0f1df712c7e806cc50153 base=0x000019381b44d000 name=liblaunchpad.so [03521.375] 01050.01053> {{{module:0x1:libc.so:elf:b183f02896022681571a29ba78b01e870de381bb}}} [03521.375] 01050.01053> {{{mmap:0x513b9c245000:0xa6000:load:0x1:rx:0}}} [03521.375] 01050.01053> {{{mmap:0x513b9c2eb000:0x5000:load:0x1:rw:0xa6000}}} [03521.375] 01050.01053> dso: id=b183f02896022681571a29ba78b01e870de381bb base=0x0000513b9c245000 name=libc.so [03521.375] 01050.01053> {{{module:0x7:libc++.so.2:elf:c40e3db9703e022b}}} [03521.375] 01050.01053> {{{mmap:0x64287c59e000:0x53000:load:0x7:r:0}}} [03521.375] 01050.01053> {{{mmap:0x64287c5f1000:0x7e000:load:0x7:rx:0x53000}}} [03521.375] 01050.01053> {{{mmap:0x64287c66f000:0x5000:load:0x7:rw:0xd1000}}} [03521.375] 01050.01053> {{{mmap:0x64287c674000:0x3000:load:0x7:rw:0xd6000}}} [03521.375] 01050.01053> dso: id=c40e3db9703e022b base=0x000064287c59e000 name=libc++.so.2 [03521.375] 01050.01053> {{{module:0x8:libc++abi.so.1:elf:7dd43029d9b84d36}}} [03521.375] 01050.01053> {{{mmap:0x4341b945a000:0x16000:load:0x8:r:0}}} [03521.375] 01050.01053> {{{mmap:0x4341b9470000:0x23000:load:0x8:rx:0x16000}}} [03521.375] 01050.01053> {{{mmap:0x4341b9493000:0x3000:load:0x8:rw:0x39000}}} [03521.375] 01050.01053> {{{mmap:0x4341b9496000:0x1000:load:0x8:rw:0x3c000}}} [03521.375] 01050.01053> dso: id=7dd43029d9b84d36 base=0x00004341b945a000 name=libc++abi.so.1 [03521.375] 01050.01053> {{{module:0x9:libunwind.so.1:elf:53013261665bb49a}}} [03521.375] 01050.01053> {{{mmap:0x2bf9648b000:0x6000:load:0x9:r:0}}} [03521.375] 01050.01053> {{{mmap:0x2bf96491000:0x8000:load:0x9:rx:0x6000}}} [03521.375] 01050.01053> {{{mmap:0x2bf96499000:0x1000:load:0x9:rw:0xe000}}} [03521.375] 01050.01053> {{{mmap:0x2bf9649a000:0x1000:load:0x9:rw:0xf000}}} [03521.375] 01050.01053> dso: id=53013261665bb49a base=0x000002bf9648b000 name=libunwind.so.1 [03521.376] 01050.01053> bootsvc: Starting... [03521.376] 01036.01043> userboot: loader-service channel peer closed [03521.376] 01036.01043> userboot: finished! [03521.376] 01050.01053> bootsvc: Creating bootfs service... [03521.376] 01050.01053> bootsvc: Retrieving boot image... [03521.376] 01050.01053> bootsvc: Decommitted BOOTDATA VMO from 0 to 0xa65000 [03521.376] 01050.01053> bootsvc: Loading boot arguments... [03521.376] 01050.01053> bootsvc: Creating svcfs service... [03521.376] 01050.01053> bootsvc: Loading kernel VMOs... [03521.376] 01050.01053> bootsvc: Creating loader service... [03521.376] 01050.01053> bootsvc: Launching next process... [03521.376] 01050.01117> bootsvc: bootsvc.next = bin/devcoordinator [03521.376] 01050.01117> bootsvc: Launched bin/devcoordinator [03521.378] 01124.01139> devcoordinator: launch /boot/bin/svchost (svchost) OK [03521.380] 01124.01139> devcoordinator: launch /boot/bin/fshost (fshost) OK [03521.383] 01124.01361> devcoordinator: launch /boot/bin/pwrbtn-monitor (pwrbtn-monitor) OK [03521.384] 01124.01385> devcoordinator: launch /boot/bin/miscsvc (miscsvc) OK [03521.384] 01124.01385> devcoordinator: launch /boot/bin/netsvc (netsvc) OK [03521.386] 01124.01385> devcoordinator: launch /boot/bin/virtual-console (virtual-console) OK [03521.390] 01124.01139> devcoordinator: full system required, ignoring fallback drivers until /system is loaded [03521.390] 01124.01139> devcoordinator: launch devhost 'devhost:sys': pid=2462 [03521.390] 01124.01139> devcoordinator: launch devhost 'devhost:test': pid=2494 [03521.391] 01124.01139> devcoordinator: launch devhost 'devhost:root': pid=2542 [03521.391] 01124.01139> devcoordinator: launch devhost 'devhost:misc': pid=2628 [03521.402] 01124.01371> devcoordinator: launch /boot/bin/sh (sh:console) OK [03521.479] 02462.02476> acpi-bus: not using IOMMU [03521.487] 02462.02476> PMU: 7 arch events [03521.487] 02462.02476> PMU: arch event id range: 1-7 [03521.487] 02462.02476> PMU: 102 arch events [03521.487] 02462.02476> PMU: arch event id range: 1-241 [03521.487] 02462.02476> Intel Processor Trace configuration for this chipset: [03521.487] 02462.02476> mtc_freq_mask: 0x249 [03521.487] 02462.02476> cyc_thresh_mask: 0x3fff [03521.487] 02462.02476> psb_freq_mask: 0x3f [03521.487] 02462.02476> num addr ranges: 2 [03521.487] 02462.02476> [sysmem_init 28] async_get_default_dispatcher(): 0xc972e4010d0 [03521.487] 02462.02476> [sysmem_bind 40] sysmem_bind() [03521.487] 02462.03270> acpi-pwrbtn: initialized [03521.487] 01957.02009> vc: new input device /dev/class/input/000 [03521.497] 02462.03270> WARNING: ACPI found bad _CRS address entry [03521.506] 02462.03270> WARNING: ACPI found bad _CRS address entry [03521.518] 02462.03270> acpi: published device pci(0xc966e3fd310), parent=sys(0xc97ae402310), handle=0xc962e40ee10 [03521.519] 01124.01139> devcoordinator: launch devhost 'devhost:pci#1:8086:5916': pid=3364 [03521.519] 01124.01139> devcoordinator: launch devhost 'devhost:pci#3:8086:9d2f': pid=3422 [03521.520] 01124.01139> devcoordinator: launch devhost 'devhost:pci#5:8086:9d60': pid=3497 [03521.520] 01124.01139> devcoordinator: launch devhost 'devhost:pci#6:8086:9d61': pid=3555 [03521.522] 01124.01139> devcoordinator: launch devhost 'devhost:pci#9:8086:9d03': pid=3682 [03521.522] 02462.03270> acpi: published device rtc(0xc966e401390), parent=acpi(0xc97ae401210), handle=0xc962e434050 [03521.524] 01124.01139> devcoordinator: launch devhost 'devhost:pci#14:8086:9d71': pid=3795 [03521.525] 02462.03270> acpi-ec: initialized [03521.526] 01124.01139> devcoordinator: launch devhost 'devhost:pci#16:8086:156f': pid=3968 [03521.529] 02462.03270> acpi: failed to create NHLT VMO (res -10) [03521.529] 02462.03270> acpi: failed to publish NHLT metadata [03521.533] 03497.03520> initialized intel serialio i2c driver, reg=0x47111c695000 regsize=4096 [03521.535] 03555.03580> initialized intel serialio i2c driver, reg=0x7fece6578000 regsize=4096 [03521.546] 03682.03713> ahci: using MSI interrupt [03521.556] 03422.04531> * found USB device (0x18d1:0xa002, USB 2.0) config 1 [03521.556] 03422.04531> * found USB device (0x18d1:0xa003, USB 3.0) config 1 [03521.556] 03795.03865> [IHDA DSP 00:1f.3] Failed to fetch NHLT (res -25) [03521.556] 03795.03865> [IHDA Controller 00:1f.3] Failed to initialize DSP device (res = -25) [03521.627] 01830.01872> netifc: ? /dev/class/ethernet/000 [03521.627] 01830.01872> netifc: create 512 eth buffers [03521.627] 01830.01872> macaddr: d4:5d:df:07:be:7e [03521.627] 01830.01872> ip6addr: fe80::d65d:df4d:fe07:be7e [03521.627] 01830.01872> snmaddr: ff02::1:ff07:be7e [03521.627] 01830.01872> netsvc: using /dev/class/ethernet/000 [03521.627] 01830.01872> netsvc: nodename='upper-stoop-folk-grape' [03521.627] 01830.01872> netsvc: start [03521.646] 01957.02009> vc: new display device /dev/class/display-controller/000 [03521.686] 03364.04821> i915: Found DP monitor [03521.686] 03364.04821> i915: Display 1 connected [03521.686] 03364.04821> i915: MST not supported [03522.744] 01957.02009> vc: Successfully attached to display 1 [03523.018] 03422.04531> * found USB device (0x0781:0x5571, USB 2.0) config 1 [03523.269] 03422.04531> * found USB device (0x8087:0x0a2b, USB 2.0) config 1 [03523.538] 03497.03520> intel-i2c-controller: intel_serialio_i2c_slave_transfer: -21 [03523.538] 03497.03520> i2c-hid: could not read HID descriptor: 0 [03523.538] 03497.03520> devhost[00:15.0/i2c-bus-9d60/0020] bind driver '/boot/driver/i2c-hid.so' failed: -2 [03523.538] 01124.01139> devcoordinator: rpc: bind-driver '0020' status -2 [03523.546] 03555.03580> intel-i2c-controller: intel_serialio_i2c_slave_transfer: -21 [03523.546] 03555.03580> i2c-hid: could not read HID descriptor: 0 [03523.546] 03555.03580> devhost[00:15.1/i2c-bus-9d61/004c] bind driver '/boot/driver/i2c-hid.so' failed: -2 [03523.546] 01124.01139> devcoordinator: rpc: bind-driver '004c' status -2 [03523.567] 03682.04520> sata2: dev info [03523.567] 03682.04520> serial=1745001401255 [03523.567] 03682.04520> firmware rev=P1111A_E [03523.567] 03682.04520> model id=BIWIN SSD [03523.567] 03682.04520> major=0x3f0 ACS2 DMA 32 commands [03523.567] 03682.04520> LBA48 250069680 sectors, sector size=512 [03523.568] 01339.01353> fshost: Binding: /boot/driver/gpt.so [03523.568] 03682.03713> DeviceControllerBind running: /boot/driver/gpt.so [03523.568] 01124.01139> devcoordinator: rpc: bind-device 'block' [03523.568] 03682.03713> DeviceControllerBind finished: /boot/driver/gpt.so ZX_OK [03523.568] 03682.03713> gpt: device_get_metadata failed (-25) [03523.569] 01339.01353> fshost: Binding: /boot/driver/fvm.so [03523.569] 03682.03713> DeviceControllerBind running: /boot/driver/fvm.so [03523.569] 01124.01139> devcoordinator: rpc: bind-device 'block' [03523.569] 03682.03713> DeviceControllerBind finished: /boot/driver/fvm.so ZX_OK [03523.570] 01339.01353> fshost: (/dev/class/block/002) failed: ZX_ERR_NOT_SUPPORTED [03523.570] 01339.01353> fshost: (/dev/class/block/003) failed: ZX_ERR_NOT_SUPPORTED [03523.572] 01339.01353> fshost: BlockDevice::MountFilesystem(blobfs) [03523.572] 01339.01353> devcoordinator: launch /boot/bin/blobfs (blobfs:/blob) OK [03523.714] 01339.01353> fshost: starting 'bin/pkgsvr' '630b89bcd1dae792b7d403d5f381f00b301011a3d8de84e5cce710cc1d0a9daf'... [03523.721] 01339.01353> devcoordinator: launch bin/pkgsvr (pkgfs) OK [03523.735] 05266.05470> pkgsvr: system: will be served from 630b89bcd1dae792b7d403d5f381f00b301011a3d8de84e5cce710cc1d0a9daf [03523.735] 05266.05470> pkgsvr: pkgfs serving index /data/pkgfs_index from blobfs /blob [03523.735] 01339.01353> fshost: unsealing zxcrypt [03523.735] 03682.03713> DeviceControllerBind running: /boot/driver/zxcrypt.so [03523.735] 01124.01139> devcoordinator: rpc: bind-device 'block' [03523.736] 03682.03713> DeviceControllerBind finished: /boot/driver/zxcrypt.so ZX_OK [03523.737] 01339.01353> fshost: mounting minfs [03523.737] 01339.01353> fshost: BlockDevice::MountFilesystem(minfs) [03523.739] 01339.01353> devcoordinator: launch /boot/bin/minfs (minfs:/data) OK [03523.743] 05659.05673> minfs: filesystem in clean state. [03523.749] 01124.05519> devcoordinator: adding system driver 'qmi_usb' '/system/driver/qmi-transport.so' [03523.755] 01124.02019> devcoordinator: launch /system/bin/appmgr (appmgr) OK [03523.779] 01124.05519> devcoordinator: adding system driver 'ralink' '/system/driver/ralink.so' [03523.780] 01124.05519> devcoordinator: adding system driver 'bt_hog' '/system/driver/bt-hog.so' [03523.785] 01124.05519> devcoordinator: adding system driver 'virtual_camera' '/system/driver/virtual_camera_driver.so' [03523.789] 01124.05519> devcoordinator: adding system driver 'gpu' '/system/driver/libmsd_intel.so' [03523.799] 01124.05519> devcoordinator: adding system driver 'mt8167s_gpu' '/system/driver/libmsd_img_rgx_mt8167.so' [03523.830] 01124.05519> devcoordinator: adding system driver 'wlan' '/system/driver/wlan.so' [03523.833] 01124.05519> devcoordinator: adding system driver 'rtl88xx' '/system/driver/rtl88xx.so' [03523.835] 01124.05519> devcoordinator: adding system driver 'qmi_fake' '/system/driver/qmi-fake.so' [03523.842] 01124.05519> devcoordinator: adding system driver 'bt_hci_fake' '/system/driver/bt-hci-fake.so' [03523.848] 01124.05519> devcoordinator: adding system driver 'bt_hci_atheros' '/system/driver/bt-hci-atheros.so' [03523.852] 01124.05519> devcoordinator: adding system driver 'virtual_audio' '/system/driver/virtual_audio_driver.so' [03523.855] 01124.05519> devcoordinator: adding system driver 'ath10k_pci' '/system/driver/ath10k.so' [03523.859] 01124.05519> devcoordinator: adding system driver 'bt_hci_intel' '/system/driver/bt-hci-intel.so' [03523.862] 01124.05519> devcoordinator: adding system driver 'wlan' '/system/driver/wlanif.so' [03523.866] 01124.05519> devcoordinator: adding system driver 'wlantapctl' '/system/driver/wlantap.so' [03523.871] 01124.05519> devcoordinator: adding system driver 'brcmfmac' '/system/driver/brcmfmac.so' [03523.880] 01124.05519> devcoordinator: adding system driver 'no_hardware_gpu' '/system/driver/libmsd_img_rgx_no_hardware.so' [03523.898] 01124.05519> devcoordinator: adding system driver 'bt_host' '/system/driver/bt-host.so' [03523.901] 05791.05805> [INFO:namespace_builder.cc(44)] config-data for sysmgr [03523.902] 01124.05519> devcoordinator: adding system driver 'bt_hci_passthrough' '/system/driver/bt-hci-passthrough.so' [03523.907] 01124.05519> devcoordinator: adding system driver 'magma_pdev_gpu' '/system/driver/libmsd_arm.so' [03523.911] 01124.05519> devcoordinator: adding system driver 'wlan' '/system/driver/wlanphy.so' [03523.912] 01124.05519> devcoordinator: adding system driver 'iwlwifi_pci' '/system/driver/iwlwifi.so' [03523.917] 01124.05519> devcoordinator: adding system driver 'usb_video' '/system/driver/usb_video.so' [03523.917] 01124.01139> devcoordinator: driver 'usb_video' added [03523.917] 01124.01139> devcoordinator: driver 'iwlwifi_pci' added [03523.917] 01124.01139> devcoordinator: driver 'wlan' added [03523.917] 01124.01139> devcoordinator: driver 'magma_pdev_gpu' added [03523.917] 01124.01139> devcoordinator: driver 'bt_host' added [03523.917] 01124.01139> devcoordinator: driver 'brcmfmac' added [03523.917] 01124.01139> devcoordinator: driver 'wlan' added [03523.917] 01124.01139> devcoordinator: driver 'bt_hci_intel' added [03523.917] 01124.01139> devcoordinator: driver 'ath10k_pci' added [03523.917] 01124.01139> devcoordinator: driver 'bt_hci_atheros' added [03523.917] 01124.01139> devcoordinator: driver 'bt_hci_fake' added [03523.917] 01124.01139> devcoordinator: driver 'qmi_fake' added [03523.917] 01124.01139> devcoordinator: driver 'rtl88xx' added [03523.917] 01124.01139> devcoordinator: driver 'wlan' added [03523.917] 01124.01139> devcoordinator: driver 'mt8167s_gpu' added [03523.917] 01124.01139> devcoordinator: driver 'gpu' added [03523.917] 01124.01139> devcoordinator: driver 'bt_hog' added [03523.917] 01124.01139> devcoordinator: driver 'ralink' added [03523.917] 01124.01139> devcoordinator: driver 'qmi_usb' added [03523.917] 01124.01139> devcoordinator: driver 'bt_hci_passthrough' added [03523.917] 01124.01139> devcoordinator: fallback driver 'usb_composite' is available [03523.917] 01124.01139> devcoordinator: driver 'usb_composite' added [03523.918] 02494.02517> img_rgx_no_hardware: Not implemented in OSCreateStatisticEntry:../../third_party/imgtec-pvr-rgx-km/services/server/env/fuchsia/osfunc.cc:846 [03523.918] 02494.02517> img_rgx_no_hardware: Not implemented in OSCreateStatisticEntry:../../third_party/imgtec-pvr-rgx-km/services/server/env/fuchsia/osfunc.cc:846 [03523.918] 02494.02517> img_rgx_no_hardware: Not implemented in OSPlatformBridgeInit:../../third_party/imgtec-pvr-rgx-km/services/server/env/fuchsia/pvr_bridge_k.cc:48 [03523.919] 02494.02517> img_rgx_no_hardware: Not implemented in OSCreateStatisticEntry:../../third_party/imgtec-pvr-rgx-km/services/server/env/fuchsia/osfunc.cc:846 [03523.919] 02494.02517> img_rgx_no_hardware: Not implemented in OSSetThreadPriority:../../third_party/imgtec-pvr-rgx-km/services/server/env/fuchsia/osfunc.cc:609 [03523.919] 01124.01139> devcoordinator: fallback driver 'intel_disp' is available [03523.919] 01124.01139> devcoordinator: driver 'intel_disp' added [03523.919] 02494.02517> img_rgx_no_hardware: Not implemented in OSSetThreadPriority:../../third_party/imgtec-pvr-rgx-km/services/server/env/fuchsia/osfunc.cc:609 [03523.919] 02494.02517> img_rgx_no_hardware: Not implemented in OSCreateStatisticEntry:../../third_party/imgtec-pvr-rgx-km/services/server/env/fuchsia/osfunc.cc:846 [03523.941] 03422.03448> UMS: parent: 'ifc-000' [03523.941] 03422.03448> UMS:Max lun is: 0 [03523.942] 03422.03448> devhost[00:14.0/xhci/usb-bus/002/002/ifc-001] bind driver '/boot/driver/bt-transport-usb.so' failed: -2 [03523.942] 01124.01139> devcoordinator: rpc: bind-driver 'ifc-001' status -2 [03523.945] 03422.06710> UMS: block size is: 0x00000200 [03523.945] 03422.06710> UMS: total blocks is: 15630336 [03523.945] 03422.06710> UMS: total size is: 8002732032 [03523.945] 03422.06710> UMS: read-only: 0 removable: 1 [03523.978] 03422.06865> btintel: firmware already loaded [03523.978] 03422.06875> hci_read_thread: failed to read from command channel ZX_ERR_PEER_CLOSED [03523.978] 03422.06875> hci_read_thread: failed to read from ACL channel ZX_ERR_PEER_CLOSED [03523.978] 03422.06875> bt-transport-usb: all channels closed - exiting [03523.979] 03422.07179> [INFO:command_channel.cc(148)] hci: initialized [03523.980] 01339.01353> fshost: Binding: /boot/driver/mbr.so [03523.980] 03422.03448> DeviceControllerBind running: /boot/driver/mbr.so [03523.980] 01124.01139> devcoordinator: rpc: bind-device 'block' [03523.980] 03422.03448> DeviceControllerBind finished: /boot/driver/mbr.so ZX_OK [03523.982] 01339.01353> fshost: (/dev/class/block/008) failed: ZX_ERR_NOT_FOUND [03523.983] 01339.01353> fshost: Binding: /boot/driver/mbr.so [03523.983] 03422.03448> DeviceControllerBind running: /boot/driver/mbr.so [03523.983] 01124.01139> devcoordinator: rpc: bind-device 'block' [03523.983] 03422.03448> DeviceControllerBind finished: /boot/driver/mbr.so ZX_OK [03523.991] 05791.05805> [INFO:namespace_builder.cc(44)] config-data for amber [03523.999] 03422.07179> [INFO:acl_data_channel.cc(91)] hci: initialized [03524.022] 07997.08009> [03524.022874][1230184835][0][netstack] INFO: netstack.go(668): NIC lo added [sniff = false] [03524.023] 07997.08225> [03524.023260][1230184835][0][netstack] WARNING: main.go(148): OnInterfacesChanged failed: ErrBadHandle: zx.Channel.Write [03524.040] 05791.05805> [INFO:namespace_builder.cc(44)] config-data for pkg_resolver [03524.115] 08745.08757> [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 [03524.115] 08745.08757> kfill_days=2, start_event_aggregator_worker=1. [03524.137] 05791.05805> [INFO:namespace_builder.cc(44)] config-data for mdns [03524.172] 05791.05805> [INFO:namespace_builder.cc(44)] config-data for wlancfg [03524.273] 05791.05805> [INFO:namespace_builder.cc(44)] config-data for crashpad_agent [03524.290] 11315.11330> [INFO:main.cc(35)] Trace Manager starting with config: /pkg/data/tracing.config [03524.309] 10140.10153> [INFO:system_metrics_main.cc(23)] Cobalt SystemMetricsDaemon: System metrics daemon created. [03524.309] 07997.08009> [03524.309870][1230184835][0][netstack] INFO: netstack.go(668): NIC ethp001f6 added [sniff = false] [03524.309] 07997.08009> [03524.309927][1230184835][0][netstack] INFO: netstack.go(694): NIC ethp001f6: link-local IPv6: fe80::d65d:dfff:fe07:be7e [03524.310] 07997.08009> [03524.310195][1230184835][0][netstack] INFO: netstack.go(434): NIC ethp001f6: stopped [03524.334] 07997.08260> [03524.334858][1230184835][0][netstack] WARNING: netstack.go(540): getNodeName: device settings error: key not set [03524.336] 03422.07179> [WARN:bredr_discovery_manager.cc(480)] gap-bredr: write inquiry scan activity failed: [status: invalid HCI command parameters (HCI 0x12)] [03524.336] 11881.11900> wlanstack [I]: Starting [03524.337] 07997.08229> [03524.337364][1230184835][0][netstack] WARNING: netstack.go(540): getNodeName: device settings error: key not set [03524.343] 07997.08219> [03524.343545][1230184835][0][netstack] WARNING: netstack.go(540): getNodeName: device settings error: key not set [03524.367] 07997.08265> [03524.367378][1230184835][0][netstack] INFO: netstack.go(455): NIC ethp001f6: starting IPv4 address of upper-stoop-folk-grape found: 192.168.42.113 environment of subprocess: [FUCHSIA_TEST_OUTDIR=/b/s/w/iouMKQUf BUILDBUCKET_ID=8912768060757274752 SWARMING_SERVER=https://chromium-swarm.appspot.com CIPD_PROTOCOL=v2 SWARMING_EXTERNAL_BOT_SETUP=1 HOSTNAME=fuchsia-tests-x64-lab01-0003--upper-stoop-folk-grape SWARMING_HEADLESS=1 SWARMING_TASK_ID=44f7ef9c40a9a011 NO_GCE_CHECK=False DEBIAN_FRONTEND=noninteractive BOTO_CONFIG=/home/swarming/.boto SWARMING_BOT_ID=fuchsia-tests-x64-lab01-0003--upper-stoop-folk-grape LUCI_CONTEXT=/b/s/w/itWCWMBU/luci_ctx.1TlczH.json HOME=/home/swarming CIPD_CACHE_DIR=/b/s/cipd_cache/cache TMPDIR=/b/s/w/itWCWMBU PATH=/b/s/cipd_cache/bin:/usr/local/sbin:/usr/local/bin:/usr/sbin:/usr/bin:/sbin:/bin FUCHSIA_NODENAME=upper-stoop-folk-grape FUCHSIA_IPV4_ADDR=192.168.42.113 FUCHSIA_SSH_KEY=/etc/botanist/keys/pkey_infra] TAP version 13 1..326 [03524.428] 07997.08260> [03524.428870][1230184835][0][netstack] INFO: netstack.go(373): NIC ethp001f6: DHCP acquired IP 192.168.42.113 for 240h0m0s [03524.428] 07997.08260> [03524.428901][1230184835][0][netstack] INFO: netstack.go(374): NIC ethp001f6: Adding DNS servers: [8.8.8.8] [03524.429] 07997.08260> [03524.428925][1230184835][0][netstack] INFO: netstack.go(384): adding routes [{Destination:0.0.0.0 Mask:0.0.0.0 Gateway:192.168.42.1 NIC:2} {Destination::: Mask::: Gateway: NIC:2} {Destination:192.168.42.0 Mask:255.255.255. [03524.429] 07997.08260> 0 Gateway: NIC:2}] with metric=<not-set> dynamic=true [03525.110] 07997.08229> [03525.110035][1230184835][0][netstack] INFO: socket_conv.go(523): unimplemented setsockopt: SOL_IPV6 name=67 optVal=20000000 [03525.110] 12666.12678> setsockopt IPV6_TCLASS 32: Protocol not available: [03525.170] 07997.12773> [03525.170741][1230184835][0][netstack] INFO: socket_conv.go(523): unimplemented setsockopt: SOL_IPV6 name=67 optVal=20000000 [03525.170] 13026.13045> setsockopt IPV6_TCLASS 32: Protocol not available: [03525.339] 09271.09284> Starting mDNS on interface ethp001f6 192.168.42.113 using port 5356 [03525.340] 09271.09284> [WARNING:src/connectivity/network/mdns/service/mdns_interface_transceiver_v4.cc(68)] NET-2177 IP_TTL not supported (ENOPROTOOPT), continuing anyway. May cause spurious IP traffic [03525.340] 09271.09284> Starting mDNS on interface ethp001f6 fe80::d65d:dfff:fe07:be7e using port 5356 [03525.340] 07997.08219> [03525.340523][1230184835][0][netstack] INFO: socket_conv.go(523): unimplemented setsockopt: SOL_IPV6 name=19 optVal=00 [03525.340] 09271.09284> [WARNING:src/connectivity/network/mdns/service/mdns_interface_transceiver_v6.cc(29)] NET-291 IPV6_MULTICAST_LOOP not supported (ENOPROTOOPT), continuing anyway [03525.340] 09271.09284> [WARNING:src/connectivity/network/mdns/service/mdns_interface_transceiver_v6.cc(50)] NET-2180 IPV6_JOIN_GROUP returned ENODEV, mDNS will not communicate via IPV6 [03525.340] 09271.09284> Starting mDNS on interface ethp001f6 ff02::1:ff07:be7e using port 5356 [03525.341] 07997.08219> [03525.341037][1230184835][0][netstack] INFO: socket_conv.go(523): unimplemented setsockopt: SOL_IPV6 name=19 optVal=00 [03525.341] 09271.09284> [WARNING:src/connectivity/network/mdns/service/mdns_interface_transceiver_v6.cc(29)] NET-291 IPV6_MULTICAST_LOOP not supported (ENOPROTOOPT), continuing anyway [03525.341] 09271.09284> [WARNING:src/connectivity/network/mdns/service/mdns_interface_transceiver_v6.cc(50)] NET-2180 IPV6_JOIN_GROUP returned ENODEV, mDNS will not communicate via IPV6 [03525.341] 09271.09284> mDNS: Verifying uniqueness of host name upper-stoop-folk-grape.local. [03526.210] 09271.09284> mDNS: Using unique host name upper-stoop-folk-grape.local. ------------------------------------------------ RUNNING TEST: /pkgfs/packages/ime_service_tests/0/test/ime_service_unittests running 49 tests test index_convert::test::test_byte_to_char ... ok test index_convert::test::test_byte_to_codeunit ... ok test ime_service::test::test_inject_input_sends_action ... ok test ime_service::test::test_visibility_service_sends_updates ... ok test index_convert::test::test_char_to_byte ... ok test ime_service::test::test_inject_input_updates_ime ... ok test index_convert::test::test_codeunit_to_byte ... ok test legacy_ime::tests::test_action ... ok test legacy_ime::tests::test_cursor_left_on_inverted_selection ... ok test legacy_ime::tests::test_cursor_left_on_selection ... ok test legacy_ime::tests::test_cursor_right_on_selection ... ok test legacy_ime::tests::test_cursor_word ... ok test legacy_ime::tests::test_cursor_word_left ... ok test legacy_ime::tests::test_cursor_word_left_no_words ... ok test legacy_ime::tests::test_cursor_word_off_limits ... ok test legacy_ime::tests::test_cursor_word_right ... ok test legacy_ime::tests::test_cursor_word_right_no_words ... ok test legacy_ime::tests::test_delete_backward_beginning_string ... ok test legacy_ime::tests::test_delete_backward_empty_string ... ok test legacy_ime::tests::test_delete_backward_first_char_selected ... ok test legacy_ime::tests::test_delete_backward_emoji ... ok test legacy_ime::tests::test_delete_backward_combining_diacritic ... ok test legacy_ime::tests::test_delete_backward_flag ... ok test legacy_ime::tests::test_delete_backward_end_string ... ok test legacy_ime::tests::test_delete_forward_beginning_string ... ok test legacy_ime::tests::test_delete_forward_combining_diacritic ... ok test legacy_ime::tests::test_delete_forward_emoji ... ok test legacy_ime::tests::test_delete_forward_empty_string ... ok test legacy_ime::tests::test_delete_forward_end_string ... ok test legacy_ime::tests::test_delete_forward_flag ... ok test legacy_ime::tests::test_delete_forward_last_char_selected ... ok test legacy_ime::tests::test_delete_no_selection ... ok test legacy_ime::tests::test_delete_selection ... ok test legacy_ime::tests::test_delete_selection_inverted ... ok test legacy_ime::tests::test_delete_selection_out_of_bounds ... ok test legacy_ime::tests::test_delete_with_zero_width_selection ... ok test legacy_ime::tests::test_delete_with_zero_width_selection_at_end ... ok test legacy_ime::tests::test_mock_ime_channels ... ok test legacy_ime::tests::test_type_at_beginning ... ok test legacy_ime::tests::test_set_state ... ok test legacy_ime::tests::test_type_empty_string ... ok test legacy_ime::tests::test_type_invalid_selection ... ok test legacy_ime::tests::test_type_inverted_selection ... ok test legacy_ime::tests::test_type_selection ... ok test legacy_ime::tests::test_unicode_selection ... ok test legacy_ime::tests::test_unicode_backspace ... ok test multiplex::tests::forwards_content_requests_correctly ... ok test multiplex::tests::queues_interleaving_edits_correctly ... ok test test::test_external_text_field_implementation ... ok test result: ok. 49 passed; 0 failed; 0 ignored; 0 measured; 0 filtered out PASSED: /pkgfs/packages/ime_service_tests/0/test/ime_service_unittests passed SUMMARY: Ran 1 tests: 0 failed (0.081 sec) ok 1 //garnet/bin/ui:ime_service_bin_test (1.274206993s) ------------------------------------------------ RUNNING TEST: /pkgfs/packages/scenic_tests/0/test/gfx_apptests Running main() from ../../third_party/googletest/googletest/src/gtest_main.cc [==========] Running 4 tests from 1 test suite. [----------] Global test environment set-up. [----------] 4 tests from GfxSystemTest [ RUN ] GfxSystemTest.CreateAndDestroySession TEST_LOOP_RANDOM_SEED="423511205" [INFO:gfx_system.cc(196)] No Vulkan found, but using a test-only "display". [ OK ] GfxSystemTest.CreateAndDestroySession (0 ms) [ RUN ] GfxSystemTest.ScheduleUpdateInOrder TEST_LOOP_RANDOM_SEED="392885383" [INFO:gfx_system.cc(196)] No Vulkan found, but using a test-only "display". [ OK ] GfxSystemTest.ScheduleUpdateInOrder (1 ms) [ RUN ] GfxSystemTest.ReleaseFences TEST_LOOP_RANDOM_SEED="2080432344" [INFO:gfx_system.cc(196)] No Vulkan found, but using a test-only "display". [INFO:default_frame_scheduler.cc(237)] ScheduleUpdateForSession session_id: 1 presentation_time: 0 [INFO:default_frame_scheduler.cc(115)] RequestFrame [INFO:default_frame_scheduler.cc(148)] MaybeRenderFrame presentation_time=16666667 wakeup_time=8666667 frame_number=0 [INFO:default_frame_scheduler.cc(250)] ApplyScheduledSessionUpdates presentation_time=16666667 frame_number=0 [INFO:default_frame_scheduler.cc(189)] Calling RenderFrame presentation_time=16666667 frame_number=0 [WARNING:garnet/lib/ui/gfx/engine/default_frame_scheduler.cc(216)] RenderFrame failed. There may not be any calls to OnFrameRendered or OnFramePresented, and no callbacks may be invoked. [INFO:default_frame_scheduler.cc(237)] ScheduleUpdateForSession session_id: 1 presentation_time: 0 [INFO:default_frame_scheduler.cc(115)] RequestFrame [INFO:default_frame_scheduler.cc(148)] MaybeRenderFrame presentation_time=1016666687 wakeup_time=1008666687 frame_number=1 [INFO:default_frame_scheduler.cc(250)] ApplyScheduledSessionUpdates presentation_time=1016666687 frame_number=1 [INFO:default_frame_scheduler.cc(189)] Calling RenderFrame presentation_time=1016666687 frame_number=1 [WARNING:garnet/lib/ui/gfx/engine/default_frame_scheduler.cc(216)] RenderFrame failed. There may not be any calls to OnFrameRendered or OnFramePresented, and no callbacks may be invoked. [ OK ] GfxSystemTest.ReleaseFences (0 ms) [ RUN ] GfxSystemTest.AcquireAndReleaseFences TEST_LOOP_RANDOM_SEED="4171837963" [INFO:gfx_system.cc(196)] No Vulkan found, but using a test-only "display". [INFO:default_frame_scheduler.cc(237)] ScheduleUpdateForSession session_id: 1 presentation_time: 0 [INFO:default_frame_scheduler.cc(115)] RequestFrame [INFO:default_frame_scheduler.cc(148)] MaybeRenderFrame presentation_time=1016666687 wakeup_time=1008666687 frame_number=0 [INFO:default_frame_scheduler.cc(250)] ApplyScheduledSessionUpdates presentation_time=1016666687 frame_number=0 [INFO:default_frame_scheduler.cc(115)] RequestFrame [INFO:default_frame_scheduler.cc(148)] MaybeRenderFrame presentation_time=1033333354 wakeup_time=1025333354 frame_number=0 [INFO:default_frame_scheduler.cc(250)] ApplyScheduledSessionUpdates presentation_time=1033333354 frame_number=0 [INFO:default_frame_scheduler.cc(115)] RequestFrame [INFO:default_frame_scheduler.cc(148)] MaybeRenderFrame presentation_time=1050000021 wakeup_time=1042000021 frame_number=0 [INFO:default_frame_scheduler.cc(250)] ApplyScheduledSessionUpdates presentation_time=1050000021 frame_number=0 [INFO:default_frame_scheduler.cc(115)] RequestFrame [INFO:default_frame_scheduler.cc(148)] MaybeRenderFrame presentation_time=1066666688 wakeup_time=1058666688 frame_number=0 [INFO:default_frame_scheduler.cc(250)] ApplyScheduledSessionUpdates presentation_time=1066666688 frame_number=0 [INFO:default_frame_scheduler.cc(115)] RequestFrame [INFO:default_frame_scheduler.cc(148)] MaybeRenderFrame presentation_time=1083333355 wakeup_time=1075333355 frame_number=0 [INFO:default_frame_scheduler.cc(250)] ApplyScheduledSessionUpdates presentation_time=1083333355 frame_number=0 [INFO:default_frame_scheduler.cc(115)] RequestFrame [INFO:default_frame_scheduler.cc(148)] MaybeRenderFrame presentation_time=1100000022 wakeup_time=1092000022 frame_number=0 [INFO:default_frame_scheduler.cc(250)] ApplyScheduledSessionUpdates presentation_time=1100000022 frame_number=0 [INFO:default_frame_scheduler.cc(115)] RequestFrame [INFO:default_frame_scheduler.cc(148)] MaybeRenderFrame presentation_time=1116666689 wakeup_time=1108666689 frame_number=0 [INFO:default_frame_scheduler.cc(250)] ApplyScheduledSessionUpdates presentation_time=1116666689 frame_number=0 [INFO:default_frame_scheduler.cc(115)] RequestFrame [INFO:default_frame_scheduler.cc(148)] MaybeRenderFrame presentation_time=1133333356 wakeup_time=1125333356 frame_number=0 [INFO:default_frame_scheduler.cc(250)] ApplyScheduledSessionUpdates presentation_time=1133333356 frame_number=0 [INFO:default_frame_scheduler.cc(115)] RequestFrame [INFO:default_frame_scheduler.cc(148)] MaybeRenderFrame presentation_time=1150000023 wakeup_time=1142000023 frame_number=0 [INFO:default_frame_scheduler.cc(250)] ApplyScheduledSessionUpdates presentation_time=1150000023 frame_number=0 [INFO:default_frame_scheduler.cc(115)] RequestFrame [INFO:default_frame_scheduler.cc(148)] MaybeRenderFrame presentation_time=1166666690 wakeup_time=1158666690 frame_number=0 [INFO:default_frame_scheduler.cc(250)] ApplyScheduledSessionUpdates presentation_time=1166666690 frame_number=0 [INFO:default_frame_scheduler.cc(115)] RequestFrame [INFO:default_frame_scheduler.cc(148)] MaybeRenderFrame presentation_time=1183333357 wakeup_time=1175333357 frame_number=0 [INFO:default_frame_scheduler.cc(250)] ApplyScheduledSessionUpdates presentation_time=1183333357 frame_number=0 [INFO:default_frame_scheduler.cc(115)] RequestFrame [INFO:default_frame_scheduler.cc(148)] MaybeRenderFrame presentation_time=1200000024 wakeup_time=1192000024 frame_number=0 [INFO:default_frame_scheduler.cc(250)] ApplyScheduledSessionUpdates presentation_time=1200000024 frame_number=0 [INFO:default_frame_scheduler.cc(115)] RequestFrame [INFO:default_frame_scheduler.cc(148)] MaybeRenderFrame presentation_time=1216666691 wakeup_time=1208666691 frame_number=0 [INFO:default_frame_scheduler.cc(250)] ApplyScheduledSessionUpdates presentation_time=1216666691 frame_number=0 [INFO:default_frame_scheduler.cc(115)] RequestFrame [INFO:default_frame_scheduler.cc(148)] MaybeRenderFrame presentation_time=1233333358 wakeup_time=1225333358 frame_number=0 [INFO:default_frame_scheduler.cc(250)] ApplyScheduledSessionUpdates presentation_time=1233333358 frame_number=0 [INFO:default_frame_scheduler.cc(115)] RequestFrame [INFO:default_frame_scheduler.cc(148)] MaybeRenderFrame presentation_time=1250000025 wakeup_time=1242000025 frame_number=0 [INFO:default_frame_scheduler.cc(250)] ApplyScheduledSessionUpdates presentation_time=1250000025 frame_number=0 [INFO:default_frame_scheduler.cc(115)] RequestFrame [INFO:default_frame_scheduler.cc(148)] MaybeRenderFrame presentation_time=1266666692 wakeup_time=1258666692 frame_number=0 [INFO:default_frame_scheduler.cc(250)] ApplyScheduledSessionUpdates presentation_time=1266666692 frame_number=0 [INFO:default_frame_scheduler.cc(115)] RequestFrame [INFO:default_frame_scheduler.cc(148)] MaybeRenderFrame presentation_time=1283333359 wakeup_time=1275333359 frame_number=0 [INFO:default_frame_scheduler.cc(250)] ApplyScheduledSessionUpdates presentation_time=1283333359 frame_number=0 [INFO:default_frame_scheduler.cc(115)] RequestFrame [INFO:default_frame_scheduler.cc(148)] MaybeRenderFrame presentation_time=1300000026 wakeup_time=1292000026 frame_number=0 [INFO:default_frame_scheduler.cc(250)] ApplyScheduledSessionUpdates presentation_time=1300000026 frame_number=0 [INFO:default_frame_scheduler.cc(115)] RequestFrame [INFO:default_frame_scheduler.cc(148)] MaybeRenderFrame presentation_time=1316666693 wakeup_time=1308666693 frame_number=0 [INFO:default_frame_scheduler.cc(250)] ApplyScheduledSessionUpdates presentation_time=1316666693 frame_number=0 [INFO:default_frame_scheduler.cc(115)] RequestFrame [INFO:default_frame_scheduler.cc(148)] MaybeRenderFrame presentation_time=1333333360 wakeup_time=1325333360 frame_number=0 [INFO:default_frame_scheduler.cc(250)] ApplyScheduledSessionUpdates presentation_time=1333333360 frame_number=0 [INFO:default_frame_scheduler.cc(115)] RequestFrame [INFO:default_frame_scheduler.cc(148)] MaybeRenderFrame presentation_time=1350000027 wakeup_time=1342000027 frame_number=0 [INFO:default_frame_scheduler.cc(250)] ApplyScheduledSessionUpdates presentation_time=1350000027 frame_number=0 [INFO:default_frame_scheduler.cc(115)] RequestFrame [INFO:default_frame_scheduler.cc(148)] MaybeRenderFrame presentation_time=1366666694 wakeup_time=1358666694 frame_number=0 [INFO:default_frame_scheduler.cc(250)] ApplyScheduledSessionUpdates presentation_time=1366666694 frame_number=0 [INFO:default_frame_scheduler.cc(115)] RequestFrame [INFO:default_frame_scheduler.cc(148)] MaybeRenderFrame presentation_time=1383333361 wakeup_time=1375333361 frame_number=0 [INFO:default_frame_scheduler.cc(250)] ApplyScheduledSessionUpdates presentation_time=1383333361 frame_number=0 [INFO:default_frame_scheduler.cc(115)] RequestFrame [INFO:default_frame_scheduler.cc(148)] MaybeRenderFrame presentation_time=1400000028 wakeup_time=1392000028 frame_number=0 [INFO:default_frame_scheduler.cc(250)] ApplyScheduledSessionUpdates presentation_time=1400000028 frame_number=0 [INFO:default_frame_scheduler.cc(115)] RequestFrame [INFO:default_frame_scheduler.cc(148)] MaybeRenderFrame presentation_time=1416666695 wakeup_time=1408666695 frame_number=0 [INFO:default_frame_scheduler.cc(250)] ApplyScheduledSessionUpdates presentation_time=1416666695 frame_number=0 [INFO:default_frame_scheduler.cc(115)] RequestFrame [INFO:default_frame_scheduler.cc(148)] MaybeRenderFrame presentation_time=1433333362 wakeup_time=1425333362 frame_number=0 [INFO:default_frame_scheduler.cc(250)] ApplyScheduledSessionUpdates presentation_time=1433333362 frame_number=0 [INFO:default_frame_scheduler.cc(115)] RequestFrame [INFO:default_frame_scheduler.cc(148)] MaybeRenderFrame presentation_time=1450000029 wakeup_time=1442000029 frame_number=0 [INFO:default_frame_scheduler.cc(250)] ApplyScheduledSessionUpdates presentation_time=1450000029 frame_number=0 [INFO:default_frame_scheduler.cc(115)] RequestFrame [INFO:default_frame_scheduler.cc(148)] MaybeRenderFrame presentation_time=1466666696 wakeup_time=1458666696 frame_number=0 [INFO:default_frame_scheduler.cc(250)] ApplyScheduledSessionUpdates presentation_time=1466666696 frame_number=0 [INFO:default_frame_scheduler.cc(115)] RequestFrame [INFO:default_frame_scheduler.cc(148)] MaybeRenderFrame presentation_time=1483333363 wakeup_time=1475333363 frame_number=0 [INFO:default_frame_scheduler.cc(250)] ApplyScheduledSessionUpdates presentation_time=1483333363 frame_number=0 [INFO:default_frame_scheduler.cc(115)] RequestFrame [INFO:default_frame_scheduler.cc(148)] MaybeRenderFrame presentation_time=1500000030 wakeup_time=1492000030 frame_number=0 [INFO:default_frame_scheduler.cc(250)] ApplyScheduledSessionUpdates presentation_time=1500000030 frame_number=0 [INFO:default_frame_scheduler.cc(115)] RequestFrame [INFO:default_frame_scheduler.cc(148)] MaybeRenderFrame presentation_time=1516666697 wakeup_time=1508666697 frame_number=0 [INFO:default_frame_scheduler.cc(250)] ApplyScheduledSessionUpdates presentation_time=1516666697 frame_number=0 [INFO:default_frame_scheduler.cc(115)] RequestFrame [INFO:default_frame_scheduler.cc(148)] MaybeRenderFrame presentation_time=1533333364 wakeup_time=1525333364 frame_number=0 [INFO:default_frame_scheduler.cc(250)] ApplyScheduledSessionUpdates presentation_time=1533333364 frame_number=0 [INFO:default_frame_scheduler.cc(115)] RequestFrame [INFO:default_frame_scheduler.cc(148)] MaybeRenderFrame presentation_time=1550000031 wakeup_time=1542000031 frame_number=0 [INFO:default_frame_scheduler.cc(250)] ApplyScheduledSessionUpdates presentation_time=1550000031 frame_number=0 [INFO:default_frame_scheduler.cc(115)] RequestFrame [INFO:default_frame_scheduler.cc(148)] MaybeRenderFrame presentation_time=1566666698 wakeup_time=1558666698 frame_number=0 [INFO:default_frame_scheduler.cc(250)] ApplyScheduledSessionUpdates presentation_time=1566666698 frame_number=0 [INFO:default_frame_scheduler.cc(115)] RequestFrame [INFO:default_frame_scheduler.cc(148)] MaybeRenderFrame presentation_time=1583333365 wakeup_time=1575333365 frame_number=0 [INFO:default_frame_scheduler.cc(250)] ApplyScheduledSessionUpdates presentation_time=1583333365 frame_number=0 [INFO:default_frame_scheduler.cc(115)] RequestFrame [INFO:default_frame_scheduler.cc(148)] MaybeRenderFrame presentation_time=1600000032 wakeup_time=1592000032 frame_number=0 [INFO:default_frame_scheduler.cc(250)] ApplyScheduledSessionUpdates presentation_time=1600000032 frame_number=0 [INFO:default_frame_scheduler.cc(115)] RequestFrame [INFO:default_frame_scheduler.cc(148)] MaybeRenderFrame presentation_time=1616666699 wakeup_time=1608666699 frame_number=0 [INFO:default_frame_scheduler.cc(250)] ApplyScheduledSessionUpdates presentation_time=1616666699 frame_number=0 [INFO:default_frame_scheduler.cc(115)] RequestFrame [INFO:default_frame_scheduler.cc(148)] MaybeRenderFrame presentation_time=1633333366 wakeup_time=1625333366 frame_number=0 [INFO:default_frame_scheduler.cc(250)] ApplyScheduledSessionUpdates presentation_time=1633333366 frame_number=0 [INFO:default_frame_scheduler.cc(115)] RequestFrame [INFO:default_frame_scheduler.cc(148)] MaybeRenderFrame presentation_time=1650000033 wakeup_time=1642000033 frame_number=0 [INFO:default_frame_scheduler.cc(250)] ApplyScheduledSessionUpdates presentation_time=1650000033 frame_number=0 [INFO:default_frame_scheduler.cc(115)] RequestFrame [INFO:default_frame_scheduler.cc(148)] MaybeRenderFrame presentation_time=1666666700 wakeup_time=1658666700 frame_number=0 [INFO:default_frame_scheduler.cc(250)] ApplyScheduledSessionUpdates presentation_time=1666666700 frame_number=0 [INFO:default_frame_scheduler.cc(115)] RequestFrame [INFO:default_frame_scheduler.cc(148)] MaybeRenderFrame presentation_time=1683333367 wakeup_time=1675333367 frame_number=0 [INFO:default_frame_scheduler.cc(250)] ApplyScheduledSessionUpdates presentation_time=1683333367 frame_number=0 [INFO:default_frame_scheduler.cc(115)] RequestFrame [INFO:default_frame_scheduler.cc(148)] MaybeRenderFrame presentation_time=1700000034 wakeup_time=1692000034 frame_number=0 [INFO:default_frame_scheduler.cc(250)] ApplyScheduledSessionUpdates presentation_time=1700000034 frame_number=0 [INFO:default_frame_scheduler.cc(115)] RequestFrame [INFO:default_frame_scheduler.cc(148)] MaybeRenderFrame presentation_time=1716666701 wakeup_time=1708666701 frame_number=0 [INFO:default_frame_scheduler.cc(250)] ApplyScheduledSessionUpdates presentation_time=1716666701 frame_number=0 [INFO:default_frame_scheduler.cc(115)] RequestFrame [INFO:default_frame_scheduler.cc(148)] MaybeRenderFrame presentation_time=1733333368 wakeup_time=1725333368 frame_number=0 [INFO:default_frame_scheduler.cc(250)] ApplyScheduledSessionUpdates presentation_time=1733333368 frame_number=0 [INFO:default_frame_scheduler.cc(115)] RequestFrame [INFO:default_frame_scheduler.cc(148)] MaybeRenderFrame presentation_time=1750000035 wakeup_time=1742000035 frame_number=0 [INFO:default_frame_scheduler.cc(250)] ApplyScheduledSessionUpdates presentation_time=1750000035 frame_number=0 [INFO:default_frame_scheduler.cc(115)] RequestFrame [INFO:default_frame_scheduler.cc(148)] MaybeRenderFrame presentation_time=1766666702 wakeup_time=1758666702 frame_number=0 [INFO:default_frame_scheduler.cc(250)] ApplyScheduledSessionUpdates presentation_time=1766666702 frame_number=0 [INFO:default_frame_scheduler.cc(115)] RequestFrame [INFO:default_frame_scheduler.cc(148)] MaybeRenderFrame presentation_time=1783333369 wakeup_time=1775333369 frame_number=0 [INFO:default_frame_scheduler.cc(250)] ApplyScheduledSessionUpdates presentation_time=1783333369 frame_number=0 [INFO:default_frame_scheduler.cc(115)] RequestFrame [INFO:default_frame_scheduler.cc(148)] MaybeRenderFrame presentation_time=1800000036 wakeup_time=1792000036 frame_number=0 [INFO:default_frame_scheduler.cc(250)] ApplyScheduledSessionUpdates presentation_time=1800000036 frame_number=0 [INFO:default_frame_scheduler.cc(115)] RequestFrame [INFO:default_frame_scheduler.cc(148)] MaybeRenderFrame presentation_time=1816666703 wakeup_time=1808666703 frame_number=0 [INFO:default_frame_scheduler.cc(250)] ApplyScheduledSessionUpdates presentation_time=1816666703 frame_number=0 [INFO:default_frame_scheduler.cc(115)] RequestFrame [INFO:default_frame_scheduler.cc(148)] MaybeRenderFrame presentation_time=1833333370 wakeup_time=1825333370 frame_number=0 [INFO:default_frame_scheduler.cc(250)] ApplyScheduledSessionUpdates presentation_time=1833333370 frame_number=0 [INFO:default_frame_scheduler.cc(115)] RequestFrame [INFO:default_frame_scheduler.cc(148)] MaybeRenderFrame presentation_time=1850000037 wakeup_time=1842000037 frame_number=0 [INFO:default_frame_scheduler.cc(250)] ApplyScheduledSessionUpdates presentation_time=1850000037 frame_number=0 [INFO:default_frame_scheduler.cc(115)] RequestFrame [INFO:default_frame_scheduler.cc(148)] MaybeRenderFrame presentation_time=1866666704 wakeup_time=1858666704 frame_number=0 [INFO:default_frame_scheduler.cc(250)] ApplyScheduledSessionUpdates presentation_time=1866666704 frame_number=0 [INFO:default_frame_scheduler.cc(115)] RequestFrame [INFO:default_frame_scheduler.cc(148)] MaybeRenderFrame presentation_time=1883333371 wakeup_time=1875333371 frame_number=0 [INFO:default_frame_scheduler.cc(250)] ApplyScheduledSessionUpdates presentation_time=1883333371 frame_number=0 [INFO:default_frame_scheduler.cc(115)] RequestFrame [INFO:default_frame_scheduler.cc(148)] MaybeRenderFrame presentation_time=1900000038 wakeup_time=1892000038 frame_number=0 [INFO:default_frame_scheduler.cc(250)] ApplyScheduledSessionUpdates presentation_time=1900000038 frame_number=0 [INFO:default_frame_scheduler.cc(115)] RequestFrame [INFO:default_frame_scheduler.cc(148)] MaybeRenderFrame presentation_time=1916666705 wakeup_time=1908666705 frame_number=0 [INFO:default_frame_scheduler.cc(250)] ApplyScheduledSessionUpdates presentation_time=1916666705 frame_number=0 [INFO:default_frame_scheduler.cc(115)] RequestFrame [INFO:default_frame_scheduler.cc(148)] MaybeRenderFrame presentation_time=1933333372 wakeup_time=1925333372 frame_number=0 [INFO:default_frame_scheduler.cc(250)] ApplyScheduledSessionUpdates presentation_time=1933333372 frame_number=0 [INFO:default_frame_scheduler.cc(115)] RequestFrame [INFO:default_frame_scheduler.cc(148)] MaybeRenderFrame presentation_time=1950000039 wakeup_time=1942000039 frame_number=0 [INFO:default_frame_scheduler.cc(250)] ApplyScheduledSessionUpdates presentation_time=1950000039 frame_number=0 [INFO:default_frame_scheduler.cc(115)] RequestFrame [INFO:default_frame_scheduler.cc(148)] MaybeRenderFrame presentation_time=1966666706 wakeup_time=1958666706 frame_number=0 [INFO:default_frame_scheduler.cc(250)] ApplyScheduledSessionUpdates presentation_time=1966666706 frame_number=0 [INFO:default_frame_scheduler.cc(115)] RequestFrame [INFO:default_frame_scheduler.cc(148)] MaybeRenderFrame presentation_time=1983333373 wakeup_time=1975333373 frame_number=0 [INFO:default_frame_scheduler.cc(250)] ApplyScheduledSessionUpdates presentation_time=1983333373 frame_number=0 [INFO:default_frame_scheduler.cc(115)] RequestFrame [INFO:default_frame_scheduler.cc(148)] MaybeRenderFrame presentation_time=2000000040 wakeup_time=1992000040 frame_number=0 [INFO:default_frame_scheduler.cc(250)] ApplyScheduledSessionUpdates presentation_time=2000000040 frame_number=0 [INFO:default_frame_scheduler.cc(115)] RequestFrame PASSED: /pkgfs/packages/scenic_tests/0/test/gfx_apptests passed [INFO:default_frame_scheduler.cc(237)] ScheduleUpdateForSession session_id: 1 presentation_time: 0 [INFO:default_frame_scheduler.cc(115)] RequestFrame [INFO:default_frame_scheduler.cc(148)] MaybeRenderFrame presentation_time=2016666707 wakeup_time=2008666707 frame_number=0 [INFO:default_frame_scheduler.cc(250)] ApplyScheduledSessionUpdates presentation_time=2016666707 frame_number=0 [INFO:default_frame_scheduler.cc(189)] Calling RenderFrame presentation_time=2016666707 frame_number=0 [WARNING:garnet/lib/ui/gfx/engine/default_frame_scheduler.cc(216)] RenderFrame failed. There may not be any calls to OnFrameRendered or OnFramePresented, and no callbacks may be invoked. [ OK ] GfxSystemTest.AcquireAndReleaseFences (3 ms) [----------] 4 tests from GfxSystemTest (4 ms total) [----------] Global test environment tear-down [==========] 4 tests from 1 test suite ran. (4 ms total) [ PASSED ] 4 tests. [03527.723] 05791.05805> [WARNING:garnet/bin/appmgr/service_provider_dir_impl.cc(127)] Component fuchsia-pkg://fuchsia.com/scenic_tests#meta/gfx_apptests.cmx is not allowed to connect to fuchsia.sysmem.Allocator because this service is not present i [03527.723] 05791.05805> n the component's sandbox. [03527.723] 05791.05805> Refer to https://fuchsia.googlesource.com/fuchsia/+/master/docs/the-book/sandboxing.md#services for more information. [03527.723] 05791.05805> [WARNING:garnet/bin/appmgr/service_provider_dir_impl.cc(127)] Component fuchsia-pkg://fuchsia.com/scenic_tests#meta/gfx_apptests.cmx is not allowed to connect to fuchsia.sysmem.Allocator because this service is not present i [03527.723] 05791.05805> n the component's sandbox. [03527.723] 05791.05805> Refer to https://fuchsia.googlesource.com/fuchsia/+/master/docs/the-book/sandboxing.md#services for more information. [03527.724] 05791.05805> [WARNING:garnet/bin/appmgr/service_provider_dir_impl.cc(127)] Component fuchsia-pkg://fuchsia.com/scenic_tests#meta/gfx_apptests.cmx is not allowed to connect to fuchsia.sysmem.Allocator because this service is not present i [03527.724] 05791.05805> n the component's sandbox. [03527.724] 05791.05805> Refer to https://fuchsia.googlesource.com/fuchsia/+/master/docs/the-book/sandboxing.md#services for more information. [03527.724] 05791.05805> [WARNING:garnet/bin/appmgr/service_provider_dir_impl.cc(127)] Component fuchsia-pkg://fuchsia.com/scenic_tests#meta/gfx_apptests.cmx is not allowed to connect to fuchsia.sysmem.Allocator because this service is not present i [03527.724] 05791.05805> n the component's sandbox. [03527.724] 05791.05805> Refer to https://fuchsia.googlesource.com/fuchsia/+/master/docs/the-book/sandboxing.md#services for more information. SUMMARY: Ran 1 tests: 0 failed (0.101 sec) ok 2 //garnet/bin/ui:gfx_apptests (1.29301333s) ------------------------------------------------ RUNNING TEST: /pkgfs/packages/scenic_tests/0/test/gfx_pixeltests [03529.031] 05791.05805> [WARNING:garnet/bin/appmgr/service_provider_dir_impl.cc(127)] Component fuchsia-pkg://fuchsia.com/scenic_tests#meta/gfx_pixeltests.cmx is not allowed to connect to fuchsia.tracelink.Registry because this service is not prese [03529.031] 05791.05805> nt in the component's sandbox. [03529.031] 05791.05805> Refer to https://fuchsia.googlesource.com/fuchsia/+/master/docs/the-book/sandboxing.md#services for more information. [03529.085] 05791.05805> [INFO:namespace_builder.cc(44)] config-data for root_presenter Running main() from ../../third_party/googletest/googletest/src/gtest_main.cc [==========] Running 8 tests from 1 test suite. [----------] Global test environment set-up. [----------] 8 tests from ScenicPixelTest [ RUN ] ScenicPixelTest.SolidColor [INFO:display_watcher.cc(40)] Scenic: Acquired display controller /dev/class/display-controller/000.(000) [INFO:input_interpreter.cc(398)] Can't process HID report descriptor for 000; All parsing attempts failed. [INFO:main.cc(35)] Trace Manager starting with config: /pkg/data/tracing.config [INFO:input_system.cc(203)] Scenic input system initialized. [ERROR:garnet/lib/ui/input/input_system.cc(200)] Scenic lost connection to TextSync [INFO:default_frame_scheduler.cc(237)] ScheduleUpdateForSession session_id: 1 presentation_time: 0 [INFO:default_frame_scheduler.cc(115)] RequestFrame [INFO:input_system.cc(556)] Scenic: Parallel dispatch is turned OFF [WARNING:garnet/bin/ui/root_presenter/displays/display_configuration.cc(79)] RootPresenter: unrecognized display. [INFO:default_frame_scheduler.cc(237)] ScheduleUpdateForSession session_id: 2 presentation_time: 0 [INFO:default_frame_scheduler.cc(115)] RequestFrame [INFO:default_frame_scheduler.cc(237)] ScheduleUpdateForSession session_id: 2 presentation_time: 0 [INFO:default_frame_scheduler.cc(115)] RequestFrame [INFO:default_frame_scheduler.cc(237)] ScheduleUpdateForSession session_id: 2 presentation_time: 0 [INFO:default_frame_scheduler.cc(115)] RequestFrame [INFO:default_frame_scheduler.cc(148)] MaybeRenderFrame presentation_time=3529204359355 wakeup_time=3529196359355 frame_number=0 [INFO:default_frame_scheduler.cc(250)] ApplyScheduledSessionUpdates presentation_time=3529204359355 frame_number=0 [INFO:default_frame_scheduler.cc(189)] Calling RenderFrame presentation_time=3529204359355 frame_number=0 [INFO:background_view.cc(61)] OnScenicEvent [INFO:background_view.cc(81)] Metrics: 1117.09x628.364x1000 [INFO:default_frame_scheduler.cc(237)] ScheduleUpdateForSession session_id: 1 presentation_time: 0 [INFO:default_frame_scheduler.cc(115)] RequestFrame [INFO:default_frame_scheduler.cc(281)] DefaultFrameScheduler::OnFramePresented frame_number=0 [03529.265] 03364.03378> DdkClose [03529.267] 03364.04831> Failed to send vsync event -24 [03529.321] 05791.05805> [INFO:namespace_builder.cc(44)] config-data for root_presenter [INFO:default_frame_scheduler.cc(148)] MaybeRenderFrame presentation_time=3529221026022 wakeup_time=3529213026022 frame_number=1 [INFO:default_frame_scheduler.cc(250)] ApplyScheduledSessionUpdates presentation_time=3529221026022 frame_number=1 [INFO:default_frame_scheduler.cc(189)] Calling RenderFrame presentation_time=3529221026022 frame_number=1 [INFO:default_frame_scheduler.cc(281)] DefaultFrameScheduler::OnFramePresented frame_number=1 [ OK ] ScenicPixelTest.SolidColor (228 ms) [ RUN ] ScenicPixelTest.NV12Texture [INFO:display_watcher.cc(40)] Scenic: Acquired display controller /dev/class/display-controller/000.(000) [INFO:input_interpreter.cc(398)] Can't process HID report descriptor for 000; All parsing attempts failed. [INFO:main.cc(35)] Trace Manager starting with config: /pkg/data/tracing.config [INFO:input_system.cc(203)] Scenic input system initialized. [ERROR:garnet/lib/ui/input/input_system.cc(200)] Scenic lost connection to TextSync [INFO:default_frame_scheduler.cc(237)] ScheduleUpdateForSession session_id: 1 presentation_time: 0 [INFO:default_frame_scheduler.cc(115)] RequestFrame [INFO:input_system.cc(556)] Scenic: Parallel dispatch is turned OFF [WARNING:garnet/bin/ui/root_presenter/displays/display_configuration.cc(79)] RootPresenter: unrecognized display. [INFO:default_frame_scheduler.cc(237)] ScheduleUpdateForSession session_id: 2 presentation_time: 0 [INFO:default_frame_scheduler.cc(115)] RequestFrame [INFO:default_frame_scheduler.cc(237)] ScheduleUpdateForSession session_id: 2 presentation_time: 0 [INFO:default_frame_scheduler.cc(115)] RequestFrame [INFO:default_frame_scheduler.cc(237)] ScheduleUpdateForSession session_id: 2 presentation_time: 0 [INFO:default_frame_scheduler.cc(115)] RequestFrame [INFO:default_frame_scheduler.cc(148)] MaybeRenderFrame presentation_time=3529458667002 wakeup_time=3529450667002 frame_number=0 [INFO:default_frame_scheduler.cc(250)] ApplyScheduledSessionUpdates presentation_time=3529458667002 frame_number=0 [INFO:default_frame_scheduler.cc(189)] Calling RenderFrame presentation_time=3529458667002 frame_number=0 [03529.520] 03364.03378> DdkClose [03529.521] 03364.04831> Failed to send vsync event -24 [INFO:background_view.cc(61)] OnScenicEvent [INFO:background_view.cc(81)] Metrics: 1117.09x628.364x1000 [INFO:default_frame_scheduler.cc(237)] ScheduleUpdateForSession session_id: 1 presentation_time: 0 [INFO:default_frame_scheduler.cc(115)] RequestFrame [INFO:default_frame_scheduler.cc(281)] DefaultFrameScheduler::OnFramePresented frame_number=0 [INFO:default_frame_scheduler.cc(148)] MaybeRenderFrame presentation_time=3529475333669 wakeup_time=3529467333669 frame_number=1 [INFO:default_frame_scheduler.cc(250)] ApplyScheduledSessionUpdates presentation_time=3529475333669 frame_number=1 [INFO:default_frame_scheduler.cc(189)] Calling RenderFrame presentation_time=3529475333669 frame_number=1 [INFO:descriptor_set_allocator.cc(86)] Allocating immutable descriptor set layout, sampler = 0x95ee3a84ff0 [INFO:default_frame_scheduler.cc(281)] DefaultFrameScheduler::OnFramePresented frame_number=1 [ OK ] ScenicPixelTest.NV12Texture (254 ms) [ RUN ] ScenicPixelTest.ViewCoordinates [INFO:display_watcher.cc(40)] Scenic: Acquired display controller /dev/class/display-controller/000.(000) [INFO:main.cc(35)] Trace Manager starting with config: /pkg/data/tracing.config [INFO:input_system.cc(203)] Scenic input system initialized. [ERROR:garnet/lib/ui/input/input_system.cc(200)] Scenic lost connection to TextSync [INFO:default_frame_scheduler.cc(237)] ScheduleUpdateForSession session_id: 1 presentation_time: 0 [INFO:default_frame_scheduler.cc(115)] RequestFrame [INFO:default_frame_scheduler.cc(148)] MaybeRenderFrame presentation_time=3529684592924 wakeup_time=3529676592924 frame_number=0 [INFO:default_frame_scheduler.cc(250)] ApplyScheduledSessionUpdates presentation_time=3529684592924 frame_number=0 [INFO:default_frame_scheduler.cc(189)] Calling RenderFrame presentation_time=3529684592924 frame_number=0 [WARNING:garnet/lib/ui/gfx/engine/default_frame_scheduler.cc(216)] RenderFrame failed. There may not be any calls to OnFrameRendered or OnFramePresented, and no callbacks may be invoked. [INFO:input_interpreter.cc(398)] Can't process HID report descriptor for 000; All parsing attempts failed. [INFO:input_system.cc(556)] Scenic: Parallel dispatch is turned OFF [INFO:default_frame_scheduler.cc(237)] ScheduleUpdateForSession session_id: 2 presentation_time: 0 [INFO:default_frame_scheduler.cc(115)] RequestFrame [WARNING:garnet/bin/ui/root_presenter/displays/display_configuration.cc(79)] RootPresenter: unrecognized display. [INFO:default_frame_scheduler.cc(237)] ScheduleUpdateForSession session_id: 2 presentation_time: 0 [INFO:default_frame_scheduler.cc(115)] RequestFrame [INFO:default_frame_scheduler.cc(237)] ScheduleUpdateForSession session_id: 2 presentation_time: 0 [INFO:default_frame_scheduler.cc(115)] RequestFrame [INFO:default_frame_scheduler.cc(148)] MaybeRenderFrame presentation_time=3529701259591 wakeup_time=3529693259591 frame_number=1 [INFO:default_frame_scheduler.cc(250)] ApplyScheduledSessionUpdates presentation_time=3529701259591 frame_number=1 [INFO:default_frame_scheduler.cc(189)] Calling RenderFrame presentation_time=3529701259591 frame_number=1 [INFO:background_view.cc(61)] OnScenicEvent [INFO:background_view.cc(81)] Metrics: 0x0x0 [INFO:background_view.cc(81)] Metrics: 1117.09x628.364x1000 [03529.679] 05791.05805> [INFO:namespace_builder.cc(44)] config-data for root_presenter [INFO:default_frame_scheduler.cc(237)] ScheduleUpdateForSession session_id: 1 presentation_time: 0 [INFO:default_frame_scheduler.cc(115)] RequestFrame [INFO:default_frame_scheduler.cc(148)] MaybeRenderFrame presentation_time=3529717926258 wakeup_time=3529709926258 frame_number=2 [INFO:default_frame_scheduler.cc(250)] ApplyScheduledSessionUpdates presentation_time=3529717926258 frame_number=2 [INFO:default_frame_scheduler.cc(281)] DefaultFrameScheduler::OnFramePresented frame_number=1 [INFO:default_frame_scheduler.cc(115)] RequestFrame [INFO:default_frame_scheduler.cc(148)] MaybeRenderFrame presentation_time=3529727444726 wakeup_time=3529719444726 frame_number=2 [INFO:default_frame_scheduler.cc(250)] ApplyScheduledSessionUpdates presentation_time=3529727444726 frame_number=2 [INFO:default_frame_scheduler.cc(189)] Calling RenderFrame presentation_time=3529727444726 frame_number=2 [INFO:default_frame_scheduler.cc(281)] DefaultFrameScheduler::OnFramePresented frame_number=2 [ OK ] ScenicPixelTest.ViewCoordinates (235 ms) [ RUN ] ScenicPixelTest.GlobalCoordinates [03529.754] 03364.03378> DdkClose [03529.755] 03364.04831> Failed to send vsync event -24 [INFO:display_watcher.cc(40)] Scenic: Acquired display controller /dev/class/display-controller/000.(000) [INFO:main.cc(35)] Trace Manager starting with config: /pkg/data/tracing.config [INFO:input_system.cc(203)] Scenic input system initialized. [ERROR:garnet/lib/ui/input/input_system.cc(200)] Scenic lost connection to TextSync [INFO:scenic_pixel_test.cc(386)] Testing orthographic camera [INFO:default_frame_scheduler.cc(237)] ScheduleUpdateForSession session_id: 1 presentation_time: 0 [INFO:default_frame_scheduler.cc(115)] RequestFrame [INFO:default_frame_scheduler.cc(148)] MaybeRenderFrame presentation_time=3529921043243 wakeup_time=3529913043243 frame_number=0 [INFO:default_frame_scheduler.cc(250)] ApplyScheduledSessionUpdates presentation_time=3529921043243 frame_number=0 [INFO:default_frame_scheduler.cc(189)] Calling RenderFrame presentation_time=3529921043243 frame_number=0 [INFO:default_frame_scheduler.cc(281)] DefaultFrameScheduler::OnFramePresented frame_number=0 [INFO:scenic_pixel_test.cc(386)] Testing perspective camera [03529.984] 03364.03378> DdkClose [03529.984] 03364.04831> Failed to send vsync event -24 [INFO:default_frame_scheduler.cc(237)] ScheduleUpdateForSession session_id: 1 presentation_time: 0 [INFO:default_frame_scheduler.cc(115)] RequestFrame [INFO:default_frame_scheduler.cc(148)] MaybeRenderFrame presentation_time=3529960785794 wakeup_time=3529952785794 frame_number=1 [INFO:default_frame_scheduler.cc(250)] ApplyScheduledSessionUpdates presentation_time=3529960785794 frame_number=1 [INFO:default_frame_scheduler.cc(189)] Calling RenderFrame presentation_time=3529960785794 frame_number=1 [INFO:default_frame_scheduler.cc(281)] DefaultFrameScheduler::OnFramePresented frame_number=1 [ OK ] ScenicPixelTest.GlobalCoordinates (227 ms) [ RUN ] ScenicPixelTest.StereoCamera [INFO:display_watcher.cc(40)] Scenic: Acquired display controller /dev/class/display-controller/000.(000) [INFO:main.cc(35)] Trace Manager starting with config: /pkg/data/tracing.config [INFO:input_system.cc(203)] Scenic input system initialized. [ERROR:garnet/lib/ui/input/input_system.cc(200)] Scenic lost connection to TextSync [INFO:default_frame_scheduler.cc(237)] ScheduleUpdateForSession session_id: 1 presentation_time: 0 [03530.182] 03364.03378> DdkClose [03530.183] 03364.04831> Failed to send vsync event -24 [INFO:default_frame_scheduler.cc(115)] RequestFrame [INFO:default_frame_scheduler.cc(148)] MaybeRenderFrame presentation_time=3530150079251 wakeup_time=3530142079251 frame_number=0 [INFO:default_frame_scheduler.cc(250)] ApplyScheduledSessionUpdates presentation_time=3530150079251 frame_number=0 [INFO:default_frame_scheduler.cc(189)] Calling RenderFrame presentation_time=3530150079251 frame_number=0 [INFO:default_frame_scheduler.cc(281)] DefaultFrameScheduler::OnFramePresented frame_number=0 [ OK ] ScenicPixelTest.StereoCamera (200 ms) [ RUN ] ScenicPixelTest.PoseBuffer [INFO:display_watcher.cc(40)] Scenic: Acquired display controller /dev/class/display-controller/000.(000) [INFO:main.cc(35)] Trace Manager starting with config: /pkg/data/tracing.config [INFO:input_system.cc(203)] Scenic input system initialized. [ERROR:garnet/lib/ui/input/input_system.cc(200)] Scenic lost connection to TextSync [ERROR:garnet/lib/ui/gfx/tests/scenic_pixel_test.cc(733)] translation: vec3(960.000000, 540.000000, -375.000000) [ERROR:garnet/lib/ui/gfx/tests/scenic_pixel_test.cc(734)] orientation: quat(0.000000, 0.000000, 0.000000, 1.000000) [ERROR:garnet/lib/ui/gfx/tests/scenic_pixel_test.cc(733)] translation: vec3(960.000000, 540.000000, -625.000000) [ERROR:garnet/lib/ui/gfx/tests/scenic_pixel_test.cc(734)] orientation: quat(1.000000, 0.000000, 0.000000, -0.000000) [ERROR:garnet/lib/ui/gfx/tests/scenic_pixel_test.cc(733)] translation: vec3(835.000000, 540.000000, -500.000000) [ERROR:garnet/lib/ui/gfx/tests/scenic_pixel_test.cc(734)] orientation: quat(-0.000000, -0.707107, -0.000000, 0.707107) [ERROR:garnet/lib/ui/gfx/tests/scenic_pixel_test.cc(733)] translation: vec3(1085.000000, 540.000000, -500.000000) [ERROR:garnet/lib/ui/gfx/tests/scenic_pixel_test.cc(734)] orientation: quat(0.000000, 0.707107, 0.000000, 0.707107) [ERROR:garnet/lib/ui/gfx/tests/scenic_pixel_test.cc(733)] translation: vec3(960.000000, 415.000000, -500.000000) [ERROR:garnet/lib/ui/gfx/tests/scenic_pixel_test.cc(734)] orientation: quat(0.707107, 0.000000, 0.000000, 0.707107) [ERROR:garnet/lib/ui/gfx/tests/scenic_pixel_test.cc(733)] translation: vec3(960.000000, 665.000000, -500.000000) [ERROR:garnet/lib/ui/gfx/tests/scenic_pixel_test.cc(734)] orientation: quat(-0.707107, -0.000000, -0.000000, 0.707107) [INFO:default_frame_scheduler.cc(237)] ScheduleUpdateForSession session_id: 1 presentation_time: 0 [INFO:default_frame_scheduler.cc(115)] RequestFrame [INFO:default_frame_scheduler.cc(148)] MaybeRenderFrame presentation_time=3530529407766 wakeup_time=3530521407766 frame_number=0 [INFO:default_frame_scheduler.cc(250)] ApplyScheduledSessionUpdates presentation_time=3530529407766 frame_number=0 [INFO:default_frame_scheduler.cc(189)] Calling RenderFrame presentation_time=3530529407766 frame_number=0 [INFO:default_frame_scheduler.cc(281)] DefaultFrameScheduler::OnFramePresented frame_number=0 [INFO:default_frame_scheduler.cc(237)] ScheduleUpdateForSession session_id: 1 presentation_time: 0 [INFO:default_frame_scheduler.cc(115)] RequestFrame [INFO:default_frame_scheduler.cc(148)] MaybeRenderFrame presentation_time=3530610786701 wakeup_time=3530602786701 frame_number=1 [INFO:default_frame_scheduler.cc(250)] ApplyScheduledSessionUpdates presentation_time=3530610786701 frame_number=1 [INFO:default_frame_scheduler.cc(189)] Calling RenderFrame presentation_time=3530610786701 frame_number=1 [INFO:default_frame_scheduler.cc(281)] DefaultFrameScheduler::OnFramePresented frame_number=1 [INFO:default_frame_scheduler.cc(237)] ScheduleUpdateForSession session_id: 1 presentation_time: 0 [INFO:default_frame_scheduler.cc(115)] RequestFrame [INFO:default_frame_scheduler.cc(148)] MaybeRenderFrame presentation_time=3530644119212 wakeup_time=3530636119212 frame_number=2 [INFO:default_frame_scheduler.cc(250)] ApplyScheduledSessionUpdates presentation_time=3530644119212 frame_number=2 [INFO:default_frame_scheduler.cc(189)] Calling RenderFrame presentation_time=3530644119212 frame_number=2 [INFO:default_frame_scheduler.cc(281)] DefaultFrameScheduler::OnFramePresented frame_number=2 [INFO:default_frame_scheduler.cc(281)] DefaultFrameScheduler::OnFramePresented frame_number=3 [ OK ] ScenicPixelTest.PoseBuffer (665 ms) [ RUN ] ScenicPixelTest.Opacity [INFO:display_watcher.cc(40)] Scenic: Acquired display controller /dev/class/display-controller/000.(000) [INFO:input_interpreter.cc(398)] Can't process HID report descriptor for 000; All parsing attempts failed. [03530.850] 03364.03378> DdkClose [03530.850] 03364.04831> Failed to send vsync event -24 [03530.904] 05791.05805> [INFO:namespace_builder.cc(44)] config-data for root_presenter [INFO:main.cc(35)] Trace Manager starting with config: /pkg/data/tracing.config [INFO:input_system.cc(203)] Scenic input system initialized. [ERROR:garnet/lib/ui/input/input_system.cc(200)] Scenic lost connection to TextSync [INFO:default_frame_scheduler.cc(237)] ScheduleUpdateForSession session_id: 1 presentation_time: 0 [INFO:default_frame_scheduler.cc(115)] RequestFrame [INFO:input_system.cc(556)] Scenic: Parallel dispatch is turned OFF [WARNING:garnet/bin/ui/root_presenter/displays/display_configuration.cc(79)] RootPresenter: unrecognized display. [INFO:default_frame_scheduler.cc(237)] ScheduleUpdateForSession session_id: 2 presentation_time: 0 [INFO:default_frame_scheduler.cc(115)] RequestFrame [INFO:default_frame_scheduler.cc(237)] ScheduleUpdateForSession session_id: 2 presentation_time: 0 [INFO:default_frame_scheduler.cc(115)] RequestFrame [INFO:default_frame_scheduler.cc(237)] ScheduleUpdateForSession session_id: 2 presentation_time: 0 [INFO:default_frame_scheduler.cc(115)] RequestFrame [INFO:default_frame_scheduler.cc(148)] MaybeRenderFrame presentation_time=3531041149233 wakeup_time=3531033149233 frame_number=0 [INFO:default_frame_scheduler.cc(250)] ApplyScheduledSessionUpdates presentation_time=3531041149233 frame_number=0 [WARNING:garnet/lib/ui/gfx/resources/nodes/opacity_node.cc(17)] Opacity support is limited. Z sorting and shadows may not behave correctly. [INFO:default_frame_scheduler.cc(189)] Calling RenderFrame presentation_time=3531041149233 frame_number=0 [INFO:opacity_view.cc(70)] OnScenicEvent [INFO:opacity_view.cc(90)] Metrics: 1117.09x628.364x1000 [INFO:default_frame_scheduler.cc(237)] ScheduleUpdateForSession session_id: 1 presentation_time: 0 [INFO:default_frame_scheduler.cc(115)] RequestFrame [INFO:default_frame_scheduler.cc(281)] DefaultFrameScheduler::OnFramePresented frame_number=0 [INFO:default_frame_scheduler.cc(148)] MaybeRenderFrame presentation_time=3531057815900 wakeup_time=3531049815900 frame_number=1 [INFO:default_frame_scheduler.cc(250)] ApplyScheduledSessionUpdates presentation_time=3531057815900 frame_number=1 [INFO:default_frame_scheduler.cc(189)] Calling RenderFrame presentation_time=3531057815900 frame_number=1 [INFO:default_frame_scheduler.cc(281)] DefaultFrameScheduler::OnFramePresented frame_number=1 [ERROR:garnet/bin/ui/root_presenter/app.cc(268)] Root presenter: Content view terminated unexpectedly. [INFO:default_frame_scheduler.cc(237)] ScheduleUpdateForSession session_id: 3 presentation_time: 0 [INFO:default_frame_scheduler.cc(115)] RequestFrame [WARNING:garnet/bin/ui/root_presenter/displays/display_configuration.cc(79)] RootPresenter: unrecognized display. [INFO:default_frame_scheduler.cc(237)] ScheduleUpdateForSession session_id: 2 presentation_time: 0 [INFO:default_frame_scheduler.cc(115)] RequestFrame [INFO:default_frame_scheduler.cc(237)] ScheduleUpdateForSession session_id: 2 presentation_time: 0 [INFO:default_frame_scheduler.cc(115)] RequestFrame [INFO:default_frame_scheduler.cc(148)] MaybeRenderFrame presentation_time=3531110782768 wakeup_time=3531102782768 frame_number=2 [INFO:default_frame_scheduler.cc(250)] ApplyScheduledSessionUpdates presentation_time=3531110782768 frame_number=2 [WARNING:garnet/lib/ui/gfx/resources/nodes/opacity_node.cc(17)] Opacity support is limited. Z sorting and shadows may not behave correctly. [03531.228] 03364.03378> DdkClose [03531.229] 03364.04831> Failed to send vsync event -24 [INFO:default_frame_scheduler.cc(189)] Calling RenderFrame presentation_time=3531110782768 frame_number=2 [INFO:opacity_view.cc(70)] OnScenicEvent [INFO:opacity_view.cc(90)] Metrics: 1117.09x628.364x1000 [INFO:default_frame_scheduler.cc(281)] DefaultFrameScheduler::OnFramePresented frame_number=2 [INFO:default_frame_scheduler.cc(281)] DefaultFrameScheduler::OnFramePresented frame_number=3 [ERROR:garnet/bin/ui/root_presenter/app.cc(268)] Root presenter: Content view terminated unexpectedly. [WARNING:garnet/bin/ui/root_presenter/displays/display_configuration.cc(79)] RootPresenter: unrecognized display. [WARNING:garnet/lib/ui/gfx/resources/nodes/opacity_node.cc(17)] Opacity support is limited. Z sorting and shadows may not behave correctly. [INFO:opacity_view.cc(70)] OnScenicEvent [INFO:opacity_view.cc(90)] Metrics: 1117.09x628.364x1000 [ OK ] ScenicPixelTest.Opacity (381 ms) [ RUN ] ScenicPixelTest.RotationTest [INFO:display_watcher.cc(40)] Scenic: Acquired display controller /dev/class/display-controller/000.(000) [INFO:main.cc(35)] Trace Manager starting with config: /pkg/data/tracing.config [INFO:input_system.cc(203)] Scenic input system initialized. [ERROR:garnet/lib/ui/input/input_system.cc(200)] Scenic lost connection to TextSync [INFO:default_frame_scheduler.cc(237)] ScheduleUpdateForSession session_id: 1 presentation_time: 0 [INFO:default_frame_scheduler.cc(115)] RequestFrame [INFO:default_frame_scheduler.cc(148)] MaybeRenderFrame presentation_time=3531408205322 wakeup_time=3531400205322 frame_number=0 [INFO:default_frame_scheduler.cc(250)] ApplyScheduledSessionUpdates presentation_time=3531408205322 frame_number=0 [INFO:default_frame_scheduler.cc(189)] Calling RenderFrame presentation_time=3531408205322 frame_number=0 [INFO:default_frame_scheduler.cc(281)] DefaultFrameScheduler::OnFramePresented frame_number=0 [INFO:default_frame_scheduler.cc(237)] ScheduleUpdateForSession session_id: 1 presentation_time: 1000000 [INFO:default_frame_scheduler.cc(115)] RequestFrame [INFO:default_frame_scheduler.cc(148)] MaybeRenderFrame presentation_time=3531460787559 wakeup_time=3531452787559 frame_number=1 [INFO:default_frame_scheduler.cc(250)] ApplyScheduledSessionUpdates presentation_time=3531460787559 frame_number=1 [INFO:default_frame_scheduler.cc(189)] Calling RenderFrame presentation_time=3531460787559 frame_number=1 [INFO:default_frame_scheduler.cc(281)] DefaultFrameScheduler::OnFramePresented frame_number=1 [ OK ] ScenicPixelTest.RotationTest (324 ms) [----------] 8 tests from ScenicPixelTest (2514 ms total) [----------] Global test environment tear-down [==========] 8 tests from 1 test suite ran. (2514 ms total) [ PASSED ] 8 tests. YOU HAVE 1 DISABLED TEST PASSED: /pkgfs/packages/scenic_tests/0/test/gfx_pixeltests passed SUMMARY: Ran 1 tests: 0 failed (2.629 sec) ok 3 //garnet/bin/ui:gfx_pixeltests (3.83834848s) [03531.544] 03364.03378> DdkClose [03531.545] 03364.04831> Failed to send vsync event -24 ------------------------------------------------ RUNNING TEST: /pkgfs/packages/scenic_tests/0/test/gfx_viewstate_apptests [03532.910] 05791.05805> [INFO:namespace_builder.cc(44)] config-data for root_presenter Running main() from ../../third_party/googletest/googletest/src/gtest_main.cc [==========] Running 1 test from 1 test suite. [----------] Global test environment set-up. [----------] 1 test from ViewEmbedderTest [ RUN ] ViewEmbedderTest.BouncingBall [INFO:display_watcher.cc(40)] Scenic: Acquired display controller /dev/class/display-controller/000.(000) [INFO:input_interpreter.cc(398)] Can't process HID report descriptor for 000; All parsing attempts failed. [INFO:main.cc(35)] Trace Manager starting with config: /pkg/data/tracing.config [INFO:input_system.cc(203)] Scenic input system initialized. [ERROR:garnet/lib/ui/input/input_system.cc(200)] Scenic lost connection to TextSync [INFO:default_frame_scheduler.cc(237)] ScheduleUpdateForSession session_id: 1 presentation_time: 0 [INFO:default_frame_scheduler.cc(115)] RequestFrame [INFO:default_frame_scheduler.cc(237)] ScheduleUpdateForSession session_id: 1 presentation_time: 0 [INFO:default_frame_scheduler.cc(115)] RequestFrame [INFO:default_frame_scheduler.cc(237)] ScheduleUpdateForSession session_id: 2 presentation_time: 0 [INFO:default_frame_scheduler.cc(115)] RequestFrame [INFO:input_system.cc(556)] Scenic: Parallel dispatch is turned OFF [WARNING:garnet/bin/ui/root_presenter/displays/display_configuration.cc(79)] RootPresenter: unrecognized display. [INFO:default_frame_scheduler.cc(237)] ScheduleUpdateForSession session_id: 3 presentation_time: 0 [INFO:default_frame_scheduler.cc(115)] RequestFrame [INFO:default_frame_scheduler.cc(237)] ScheduleUpdateForSession session_id: 3 presentation_time: 0 [INFO:default_frame_scheduler.cc(115)] RequestFrame [INFO:default_frame_scheduler.cc(237)] ScheduleUpdateForSession session_id: 3 presentation_time: 0 [INFO:default_frame_scheduler.cc(115)] RequestFrame [INFO:default_frame_scheduler.cc(148)] MaybeRenderFrame presentation_time=3533096163966 wakeup_time=3533088163966 frame_number=0 [INFO:default_frame_scheduler.cc(250)] ApplyScheduledSessionUpdates presentation_time=3533096163966 frame_number=0 [INFO:default_frame_scheduler.cc(189)] Calling RenderFrame presentation_time=3533096163966 frame_number=0 [INFO:default_frame_scheduler.cc(237)] ScheduleUpdateForSession session_id: 1 presentation_time: 0 [INFO:default_frame_scheduler.cc(115)] RequestFrame [INFO:default_frame_scheduler.cc(148)] MaybeRenderFrame presentation_time=3533112830633 wakeup_time=3533104830633 frame_number=1 [INFO:default_frame_scheduler.cc(250)] ApplyScheduledSessionUpdates presentation_time=3533112830633 frame_number=1 [INFO:default_frame_scheduler.cc(281)] DefaultFrameScheduler::OnFramePresented frame_number=0 [INFO:default_frame_scheduler.cc(115)] RequestFrame [INFO:default_frame_scheduler.cc(237)] ScheduleUpdateForSession session_id: 2 presentation_time: 3533127451005 [INFO:default_frame_scheduler.cc(115)] RequestFrame [INFO:default_frame_scheduler.cc(148)] MaybeRenderFrame presentation_time=3533127451005 wakeup_time=3533119451005 frame_number=1 [INFO:default_frame_scheduler.cc(250)] ApplyScheduledSessionUpdates presentation_time=3533127451005 frame_number=1 [INFO:default_frame_scheduler.cc(189)] Calling RenderFrame presentation_time=3533127451005 frame_number=1 [INFO:default_frame_scheduler.cc(115)] RequestFrame [INFO:default_frame_scheduler.cc(281)] DefaultFrameScheduler::OnFramePresented frame_number=1 [INFO:default_frame_scheduler.cc(148)] MaybeRenderFrame presentation_time=3533144117672 wakeup_time=3533136117672 frame_number=2 [INFO:default_frame_scheduler.cc(250)] ApplyScheduledSessionUpdates presentation_time=3533144117672 frame_number=2 [INFO:default_frame_scheduler.cc(189)] Calling RenderFrame presentation_time=3533144117672 frame_number=2 [ERROR:garnet/bin/ui/root_presenter/app.cc(268)] Root presenter: Content view terminated unexpectedly. [ OK ] ViewEmbedderTest.BouncingBall (314 ms) [----------] 1 test from ViewEmbedderTest (314 ms total) [----------] Global test environment tear-down [==========] 1 test from 1 test suite ran. (314 ms total) [ PASSED ] 1 test. PASSED: /pkgfs/packages/scenic_tests/0/test/gfx_viewstate_apptests passed SUMMARY: Ran 1 tests: 0 failed (0.378 sec) ok 4 //garnet/bin/ui:gfx_viewstate_apptests (1.585506547s) [03533.147] 03364.03378> DdkClose [03533.148] 03364.04831> Failed to send vsync event -24 ------------------------------------------------ RUNNING TEST: /pkgfs/packages/scenic_tests/0/test/gfx_unittests [==========] Running 156 tests from 29 test suites. [----------] Global test environment set-up. [----------] 1 test from CompositorTest [ RUN ] CompositorTest.Validation fidl channel writing error at ../../sdk/lib/fidl/cpp/internal/proxy_controller.cc:59: zx_status_t -24, type fuchsia.scheduler/ProfileProviderGetProfileRequest, 80 bytes, 0 handles TEST_LOOP_RANDOM_SEED="271189938" [ OK ] CompositorTest.Validation (0 ms) [----------] 1 test from CompositorTest (0 ms total) [----------] 10 tests from FrameSchedulerTest [ RUN ] FrameSchedulerTest.PresentTimeZero_ShouldBeScheduledBeforeNextVsync TEST_LOOP_RANDOM_SEED="4045442459" [INFO:default_frame_scheduler.cc(237)] ScheduleUpdateForSession session_id: 1 presentation_time: 0 [INFO:default_frame_scheduler.cc(115)] RequestFrame [INFO:default_frame_scheduler.cc(148)] MaybeRenderFrame presentation_time=100000000 wakeup_time=92000000 frame_number=0 [INFO:default_frame_scheduler.cc(250)] ApplyScheduledSessionUpdates presentation_time=100000000 frame_number=0 [INFO:default_frame_scheduler.cc(189)] Calling RenderFrame presentation_time=100000000 frame_number=0 [INFO:default_frame_scheduler.cc(281)] DefaultFrameScheduler::OnFramePresented frame_number=0 [ OK ] FrameSchedulerTest.PresentTimeZero_ShouldBeScheduledBeforeNextVsync (0 ms) [ RUN ] FrameSchedulerTest.PresentBiggerThanNextVsync_ShouldBeScheduledAfterNextVsync TEST_LOOP_RANDOM_SEED="22720695" [INFO:default_frame_scheduler.cc(237)] ScheduleUpdateForSession session_id: 1 presentation_time: 150000000 [INFO:default_frame_scheduler.cc(115)] RequestFrame [INFO:default_frame_scheduler.cc(148)] MaybeRenderFrame presentation_time=200000000 wakeup_time=192000000 frame_number=0 [INFO:default_frame_scheduler.cc(250)] ApplyScheduledSessionUpdates presentation_time=200000000 frame_number=0 [INFO:default_frame_scheduler.cc(189)] Calling RenderFrame presentation_time=200000000 frame_number=0 [INFO:default_frame_scheduler.cc(281)] DefaultFrameScheduler::OnFramePresented frame_number=0 [ OK ] FrameSchedulerTest.PresentBiggerThanNextVsync_ShouldBeScheduledAfterNextVsync (0 ms) [ RUN ] FrameSchedulerTest.SinglePresent_ShouldGetSingleRenderCall TEST_LOOP_RANDOM_SEED="451108447" [INFO:default_frame_scheduler.cc(237)] ScheduleUpdateForSession session_id: 1 presentation_time: 0 [INFO:default_frame_scheduler.cc(115)] RequestFrame [INFO:default_frame_scheduler.cc(148)] MaybeRenderFrame presentation_time=100000000 wakeup_time=92000000 frame_number=0 [INFO:default_frame_scheduler.cc(250)] ApplyScheduledSessionUpdates presentation_time=100000000 frame_number=0 [INFO:default_frame_scheduler.cc(189)] Calling RenderFrame presentation_time=100000000 frame_number=0 [INFO:default_frame_scheduler.cc(281)] DefaultFrameScheduler::OnFramePresented frame_number=0 [ OK ] FrameSchedulerTest.SinglePresent_ShouldGetSingleRenderCall (0 ms) [ RUN ] FrameSchedulerTest.PresentsForTheSameFrame_ShouldGetSingleRenderCall TEST_LOOP_RANDOM_SEED="429241557" [INFO:default_frame_scheduler.cc(237)] ScheduleUpdateForSession session_id: 1 presentation_time: 0 [INFO:default_frame_scheduler.cc(115)] RequestFrame [INFO:default_frame_scheduler.cc(237)] ScheduleUpdateForSession session_id: 2 presentation_time: 0 [INFO:default_frame_scheduler.cc(115)] RequestFrame [INFO:default_frame_scheduler.cc(148)] MaybeRenderFrame presentation_time=100000000 wakeup_time=92000000 frame_number=0 [INFO:default_frame_scheduler.cc(250)] ApplyScheduledSessionUpdates presentation_time=100000000 frame_number=0 [INFO:default_frame_scheduler.cc(189)] Calling RenderFrame presentation_time=100000000 frame_number=0 [INFO:default_frame_scheduler.cc(281)] DefaultFrameScheduler::OnFramePresented frame_number=0 [ OK ] FrameSchedulerTest.PresentsForTheSameFrame_ShouldGetSingleRenderCall (1 ms) [ RUN ] FrameSchedulerTest.PresentsForDifferentFrames_ShouldGetSeparateRenderCalls TEST_LOOP_RANDOM_SEED="4240552465" [INFO:default_frame_scheduler.cc(237)] ScheduleUpdateForSession session_id: 1 presentation_time: 0 [INFO:default_frame_scheduler.cc(115)] RequestFrame [INFO:default_frame_scheduler.cc(237)] ScheduleUpdateForSession session_id: 1 presentation_time: 150000000 [INFO:default_frame_scheduler.cc(115)] RequestFrame [INFO:default_frame_scheduler.cc(148)] MaybeRenderFrame presentation_time=100000000 wakeup_time=92000000 frame_number=0 [INFO:default_frame_scheduler.cc(250)] ApplyScheduledSessionUpdates presentation_time=100000000 frame_number=0 [INFO:default_frame_scheduler.cc(189)] Calling RenderFrame presentation_time=100000000 frame_number=0 [INFO:default_frame_scheduler.cc(115)] RequestFrame [INFO:default_frame_scheduler.cc(281)] DefaultFrameScheduler::OnFramePresented frame_number=0 [INFO:default_frame_scheduler.cc(148)] MaybeRenderFrame presentation_time=200000000 wakeup_time=192000000 frame_number=1 [INFO:default_frame_scheduler.cc(250)] ApplyScheduledSessionUpdates presentation_time=200000000 frame_number=1 [INFO:default_frame_scheduler.cc(189)] Calling RenderFrame presentation_time=200000000 frame_number=1 [ OK ] FrameSchedulerTest.PresentsForDifferentFrames_ShouldGetSeparateRenderCalls (0 ms) [ RUN ] FrameSchedulerTest.SecondPresentDuringRender_ShouldApplyUpdatesAndReschedule TEST_LOOP_RANDOM_SEED="1615869159" [INFO:default_frame_scheduler.cc(237)] ScheduleUpdateForSession session_id: 1 presentation_time: 0 [INFO:default_frame_scheduler.cc(115)] RequestFrame [INFO:default_frame_scheduler.cc(148)] MaybeRenderFrame presentation_time=100000000 wakeup_time=92000000 frame_number=0 [INFO:default_frame_scheduler.cc(250)] ApplyScheduledSessionUpdates presentation_time=100000000 frame_number=0 [INFO:default_frame_scheduler.cc(189)] Calling RenderFrame presentation_time=100000000 frame_number=0 [INFO:default_frame_scheduler.cc(237)] ScheduleUpdateForSession session_id: 1 presentation_time: 0 [INFO:default_frame_scheduler.cc(115)] RequestFrame [INFO:default_frame_scheduler.cc(148)] MaybeRenderFrame presentation_time=200000000 wakeup_time=192000000 frame_number=1 [INFO:default_frame_scheduler.cc(250)] ApplyScheduledSessionUpdates presentation_time=200000000 frame_number=1 [INFO:default_frame_scheduler.cc(281)] DefaultFrameScheduler::OnFramePresented frame_number=0 [INFO:default_frame_scheduler.cc(115)] RequestFrame [INFO:default_frame_scheduler.cc(148)] MaybeRenderFrame presentation_time=300000000 wakeup_time=292000000 frame_number=1 [INFO:default_frame_scheduler.cc(250)] ApplyScheduledSessionUpdates presentation_time=300000000 frame_number=1 [INFO:default_frame_scheduler.cc(189)] Calling RenderFrame presentation_time=300000000 frame_number=1 [INFO:default_frame_scheduler.cc(281)] DefaultFrameScheduler::OnFramePresented frame_number=1 [ OK ] FrameSchedulerTest.SecondPresentDuringRender_ShouldApplyUpdatesAndReschedule (0 ms) [ RUN ] FrameSchedulerTest.RenderCalls_ShouldNotExceed_MaxOutstandingFrames TEST_LOOP_RANDOM_SEED="3984162580" [INFO:default_frame_scheduler.cc(237)] ScheduleUpdateForSession session_id: 1 presentation_time: 0 [INFO:default_frame_scheduler.cc(115)] RequestFrame [INFO:default_frame_scheduler.cc(148)] MaybeRenderFrame presentation_time=100000000 wakeup_time=92000000 frame_number=0 [INFO:default_frame_scheduler.cc(250)] ApplyScheduledSessionUpdates presentation_time=100000000 frame_number=0 [INFO:default_frame_scheduler.cc(189)] Calling RenderFrame presentation_time=100000000 frame_number=0 [INFO:default_frame_scheduler.cc(237)] ScheduleUpdateForSession session_id: 1 presentation_time: 0 [INFO:default_frame_scheduler.cc(115)] RequestFrame [INFO:default_frame_scheduler.cc(148)] MaybeRenderFrame presentation_time=600000000 wakeup_time=592000000 frame_number=1 [INFO:default_frame_scheduler.cc(250)] ApplyScheduledSessionUpdates presentation_time=600000000 frame_number=1 [ OK ] FrameSchedulerTest.RenderCalls_ShouldNotExceed_MaxOutstandingFrames (0 ms) [ RUN ] FrameSchedulerTest.SignalSuccessfulPresentCallbackOnlyWhenFramePresented TEST_LOOP_RANDOM_SEED="2159408319" [INFO:default_frame_scheduler.cc(237)] ScheduleUpdateForSession session_id: 1 presentation_time: 0 [INFO:default_frame_scheduler.cc(115)] RequestFrame [INFO:default_frame_scheduler.cc(148)] MaybeRenderFrame presentation_time=100000000 wakeup_time=92000000 frame_number=0 [INFO:default_frame_scheduler.cc(250)] ApplyScheduledSessionUpdates presentation_time=100000000 frame_number=0 [INFO:default_frame_scheduler.cc(189)] Calling RenderFrame presentation_time=100000000 frame_number=0 [INFO:default_frame_scheduler.cc(237)] ScheduleUpdateForSession session_id: 1 presentation_time: 0 [INFO:default_frame_scheduler.cc(115)] RequestFrame [INFO:default_frame_scheduler.cc(148)] MaybeRenderFrame presentation_time=200000000 wakeup_time=192000000 frame_number=1 [INFO:default_frame_scheduler.cc(250)] ApplyScheduledSessionUpdates presentation_time=200000000 frame_number=1 [INFO:default_frame_scheduler.cc(281)] DefaultFrameScheduler::OnFramePresented frame_number=0 [INFO:default_frame_scheduler.cc(115)] RequestFrame [INFO:default_frame_scheduler.cc(148)] MaybeRenderFrame presentation_time=400000000 wakeup_time=392000000 frame_number=1 [INFO:default_frame_scheduler.cc(250)] ApplyScheduledSessionUpdates presentation_time=400000000 frame_number=1 [INFO:default_frame_scheduler.cc(189)] Calling RenderFrame presentation_time=400000000 frame_number=1 [INFO:default_frame_scheduler.cc(281)] DefaultFrameScheduler::OnFramePresented frame_number=1 [ OK ] FrameSchedulerTest.SignalSuccessfulPresentCallbackOnlyWhenFramePresented (0 ms) [ RUN ] FrameSchedulerTest.FailedUpdate_ShouldNotTriggerRenderCall TEST_LOOP_RANDOM_SEED="1097324100" [INFO:default_frame_scheduler.cc(237)] ScheduleUpdateForSession session_id: 1 presentation_time: 0 [INFO:default_frame_scheduler.cc(115)] RequestFrame [INFO:default_frame_scheduler.cc(148)] MaybeRenderFrame presentation_time=100000000 wakeup_time=92000000 frame_number=0 [INFO:default_frame_scheduler.cc(250)] ApplyScheduledSessionUpdates presentation_time=100000000 frame_number=0 [ OK ] FrameSchedulerTest.FailedUpdate_ShouldNotTriggerRenderCall (0 ms) [ RUN ] FrameSchedulerTest.NoOpUpdateWithSecondPendingUpdate_ShouldBeRescheduled TEST_LOOP_RANDOM_SEED="3293226574" [INFO:default_frame_scheduler.cc(237)] ScheduleUpdateForSession session_id: 1 presentation_time: 0 [INFO:default_frame_scheduler.cc(115)] RequestFrame [INFO:default_frame_scheduler.cc(237)] ScheduleUpdateForSession session_id: 1 presentation_time: 100000000 [INFO:default_frame_scheduler.cc(115)] RequestFrame [INFO:default_frame_scheduler.cc(148)] MaybeRenderFrame presentation_time=100000000 wakeup_time=92000000 frame_number=0 [INFO:default_frame_scheduler.cc(250)] ApplyScheduledSessionUpdates presentation_time=100000000 frame_number=0 [INFO:default_frame_scheduler.cc(115)] RequestFrame [INFO:default_frame_scheduler.cc(148)] MaybeRenderFrame presentation_time=200000000 wakeup_time=192000000 frame_number=0 [INFO:default_frame_scheduler.cc(250)] ApplyScheduledSessionUpdates presentation_time=200000000 frame_number=0 [INFO:default_frame_scheduler.cc(189)] Calling RenderFrame presentation_time=200000000 frame_number=0 [ OK ] FrameSchedulerTest.NoOpUpdateWithSecondPendingUpdate_ShouldBeRescheduled (0 ms) [----------] 10 tests from FrameSchedulerTest (1 ms total) [----------] 7 tests from DurationPredictor [ RUN ] DurationPredictor.FirstPredictionIsInitialPrediction [ OK ] DurationPredictor.FirstPredictionIsInitialPrediction (0 ms) [ RUN ] DurationPredictor.PredictionAfterWindowFlushIsMeasurement [ OK ] DurationPredictor.PredictionAfterWindowFlushIsMeasurement (0 ms) [ RUN ] DurationPredictor.PredictionIsSmallestInWindowAsMeasurementsIncrease [ OK ] DurationPredictor.PredictionIsSmallestInWindowAsMeasurementsIncrease (0 ms) [ RUN ] DurationPredictor.PredictionIsSmallestInWindowAsMeasurementsDecrease [ OK ] DurationPredictor.PredictionIsSmallestInWindowAsMeasurementsDecrease (0 ms) [ RUN ] DurationPredictor.PredictionIsSmallestInWindow [ OK ] DurationPredictor.PredictionIsSmallestInWindow (0 ms) [ RUN ] DurationPredictor.MinIsResetWhenSmallestIsOutOfWindow [ OK ] DurationPredictor.MinIsResetWhenSmallestIsOutOfWindow (0 ms) [ RUN ] DurationPredictor.WindowSizeOfOneWorks [ OK ] DurationPredictor.WindowSizeOfOneWorks (0 ms) [----------] 7 tests from DurationPredictor (0 ms total) [----------] 1 test from EscherVulkanSmokeTest [ RUN ] EscherVulkanSmokeTest.OnlyIfSupported [ OK ] EscherVulkanSmokeTest.OnlyIfSupported (0 ms) [----------] 1 test from EscherVulkanSmokeTest (0 ms total) [----------] 1 test from EventTimestamperTest [ RUN ] EventTimestamperTest.WatchingState [ OK ] EventTimestamperTest.WatchingState (10 ms) [----------] 1 test from EventTimestamperTest (10 ms total) [----------] 8 tests from FramePredictorTest [ RUN ] FramePredictorTest.BasicPredictions_ShouldBeReasonable TEST_LOOP_RANDOM_SEED="1419331920" [ OK ] FramePredictorTest.BasicPredictions_ShouldBeReasonable (0 ms) [ RUN ] FramePredictorTest.PredictionsAfterUpdating_ShouldBeMoreReasonable TEST_LOOP_RANDOM_SEED="3297499401" [ OK ] FramePredictorTest.PredictionsAfterUpdating_ShouldBeMoreReasonable (1 ms) [ RUN ] FramePredictorTest.OneExpensiveTime_ShouldNotPredictForFutureVsyncIntervals TEST_LOOP_RANDOM_SEED="891147338" [ OK ] FramePredictorTest.OneExpensiveTime_ShouldNotPredictForFutureVsyncIntervals (0 ms) [ RUN ] FramePredictorTest.ManyExpensiveTimes_ShouldPredictForFutureVsyncIntervals TEST_LOOP_RANDOM_SEED="3569475808" [ OK ] FramePredictorTest.ManyExpensiveTimes_ShouldPredictForFutureVsyncIntervals (0 ms) [ RUN ] FramePredictorTest.ManyFramesOfPredictions_ShouldBeReasonable TEST_LOOP_RANDOM_SEED="2726806362" [ OK ] FramePredictorTest.ManyFramesOfPredictions_ShouldBeReasonable (0 ms) [ RUN ] FramePredictorTest.MissedLastVsync_ShouldPredictWithInterval TEST_LOOP_RANDOM_SEED="4008837215" [ OK ] FramePredictorTest.MissedLastVsync_ShouldPredictWithInterval (0 ms) [ RUN ] FramePredictorTest.MissedPresentRequest_ShouldTargetNextVsync TEST_LOOP_RANDOM_SEED="127176618" [ OK ] FramePredictorTest.MissedPresentRequest_ShouldTargetNextVsync (0 ms) [ RUN ] FramePredictorTest.AttemptsToBeLowLatent_ShouldBePossible TEST_LOOP_RANDOM_SEED="478557495" [ OK ] FramePredictorTest.AttemptsToBeLowLatent_ShouldBePossible (0 ms) [----------] 8 tests from FramePredictorTest (1 ms total) [----------] 6 tests from FrameTimingsTest [ RUN ] FrameTimingsTest.ReceivingCallsInOrder_ShouldTriggerFrameSchedulerCallsInOrder TEST_LOOP_RANDOM_SEED="3040697443" [ OK ] FrameTimingsTest.ReceivingCallsInOrder_ShouldTriggerFrameSchedulerCallsInOrder (0 ms) [ RUN ] FrameTimingsTest.ReceivingCallsOutOfOrder_ShouldTriggerFrameSchedulerCallsInOrder TEST_LOOP_RANDOM_SEED="2457464494" [ OK ] FrameTimingsTest.ReceivingCallsOutOfOrder_ShouldTriggerFrameSchedulerCallsInOrder (0 ms) [ RUN ] FrameTimingsTest.ReceivingCallsAndTimesOutOfOrder_ShouldTriggerFrameSchedulerCallsInOrder TEST_LOOP_RANDOM_SEED="1843619895" [ OK ] FrameTimingsTest.ReceivingCallsAndTimesOutOfOrder_ShouldTriggerFrameSchedulerCallsInOrder (0 ms) [ RUN ] FrameTimingsTest.ReceivingTimesOutOfOrder_ShouldRecordTimesInOrder TEST_LOOP_RANDOM_SEED="2572447646" [ OK ] FrameTimingsTest.ReceivingTimesOutOfOrder_ShouldRecordTimesInOrder (0 ms) [ RUN ] FrameTimingsTest.FrameDroppedAfterRender_ShouldNotTriggerSecondFrameRenderedCall TEST_LOOP_RANDOM_SEED="349099332" [ OK ] FrameTimingsTest.FrameDroppedAfterRender_ShouldNotTriggerSecondFrameRenderedCall (0 ms) [ RUN ] FrameTimingsTest.FrameDroppedBeforeRender_ShouldStillTriggerFrameRenderedCall TEST_LOOP_RANDOM_SEED="3565595279" [ OK ] FrameTimingsTest.FrameDroppedBeforeRender_ShouldStillTriggerFrameRenderedCall (0 ms) [----------] 6 tests from FrameTimingsTest (0 ms total) [----------] 2 tests from FrameTimings [ RUN ] FrameTimings.DroppedAndUnitializedTimesAreUnique [ OK ] FrameTimings.DroppedAndUnitializedTimesAreUnique (0 ms) [ RUN ] FrameTimings.InitTimestamps [ OK ] FrameTimings.InitTimestamps (0 ms) [----------] 2 tests from FrameTimings (0 ms total) [----------] 3 tests from GfxCommandApplierTest [ RUN ] GfxCommandApplierTest.NewCreateEntityNodeCmd TEST_LOOP_RANDOM_SEED="1801559128" [ OK ] GfxCommandApplierTest.NewCreateEntityNodeCmd (0 ms) [ RUN ] GfxCommandApplierTest.EraseResource TEST_LOOP_RANDOM_SEED="4223073677" [ OK ] GfxCommandApplierTest.EraseResource (0 ms) [ RUN ] GfxCommandApplierTest.SeparateSessionsAreIndependent TEST_LOOP_RANDOM_SEED="3190806561" [ OK ] GfxCommandApplierTest.SeparateSessionsAreIndependent (0 ms) [----------] 3 tests from GfxCommandApplierTest (0 ms total) [----------] 5 tests from HLATest [ RUN ] HLATest.HasHardwareLayerAssignment TEST_LOOP_RANDOM_SEED="4030657513" [ OK ] HLATest.HasHardwareLayerAssignment (0 ms) [ RUN ] HLATest.HardwareLayerAssignmentMissingSwapchain TEST_LOOP_RANDOM_SEED="3490047330" [WARNING:garnet/lib/ui/gfx/engine/hardware_layer_assignment.cc(16)] Invalid HardwareLayerAssignment: no swapchain. [ OK ] HLATest.HardwareLayerAssignmentMissingSwapchain (0 ms) [ RUN ] HLATest.HardwareLayerAssignmentMissingLayers TEST_LOOP_RANDOM_SEED="1137180507" [WARNING:garnet/lib/ui/gfx/engine/hardware_layer_assignment.cc(26)] Invalid HardwareLayerAssignment: item with no layers. [ OK ] HLATest.HardwareLayerAssignmentMissingLayers (0 ms) [ RUN ] HLATest.HardwareLayerAssignmentMissingItems TEST_LOOP_RANDOM_SEED="2858093763" [WARNING:garnet/lib/ui/gfx/engine/hardware_layer_assignment.cc(19)] Invalid HardwareLayerAssignment: no items. [ OK ] HLATest.HardwareLayerAssignmentMissingItems (0 ms) [ RUN ] HLATest.HardwareLayerAssignmentDuplicateLayerIDs TEST_LOOP_RANDOM_SEED="4212499765" [WARNING:garnet/lib/ui/gfx/engine/hardware_layer_assignment.cc(32)] Invalid HardwareLayerAssignment: duplicate layer ID � [ OK ] HLATest.HardwareLayerAssignmentDuplicateLayerIDs (0 ms) [----------] 5 tests from HLATest (0 ms total) [----------] 1 test from MultiSessionHitTestTest [ RUN ] MultiSessionHitTestTest.GlobalHits TEST_LOOP_RANDOM_SEED="1401218214" [WARNING:garnet/lib/ui/scenic/event_reporter.cc(23)] EventReporter not set up, dropped event: ViewConnectedEvent(view_holder_id=1008) [WARNING:garnet/lib/ui/scenic/event_reporter.cc(23)] EventReporter not set up, dropped event: ViewAttachedToSceneEvent(view_id=2001, properties=<TBD> [WARNING:garnet/lib/ui/scenic/event_reporter.cc(23)] EventReporter not set up, dropped event: ViewPropertiesChangedEvent(view_id=2001, properties=<TBD>) [WARNING:garnet/lib/ui/scenic/event_reporter.cc(23)] EventReporter not set up, dropped event: ViewHolderConnectedEvent(view_id=2001) [WARNING:garnet/lib/ui/scenic/event_reporter.cc(23)] EventReporter not set up, dropped event: ViewConnectedEvent(view_holder_id=1009) [WARNING:garnet/lib/ui/scenic/event_reporter.cc(23)] EventReporter not set up, dropped event: ViewAttachedToSceneEvent(view_id=3001, properties=<TBD> [WARNING:garnet/lib/ui/scenic/event_reporter.cc(23)] EventReporter not set up, dropped event: ViewPropertiesChangedEvent(view_id=3001, properties=<TBD>) [WARNING:garnet/lib/ui/scenic/event_reporter.cc(23)] EventReporter not set up, dropped event: ViewHolderConnectedEvent(view_id=3001) [WARNING:garnet/lib/ui/scenic/event_reporter.cc(23)] EventReporter not set up, dropped event: ViewDisconnectedEvent(view_holder_id=1009) [WARNING:garnet/lib/ui/scenic/event_reporter.cc(23)] EventReporter not set up, dropped event: ViewDisconnectedEvent(view_holder_id=1008) [ OK ] MultiSessionHitTestTest.GlobalHits (0 ms) [----------] 1 test from MultiSessionHitTestTest (0 ms total) [----------] 3 tests from HostImageTest [ RUN ] HostImageTest.FindResource TEST_LOOP_RANDOM_SEED="2851287762" [ OK ] HostImageTest.FindResource (20 ms) [ RUN ] HostImageTest.RgbaImport TEST_LOOP_RANDOM_SEED="1693558366" [WARNING:garnet/lib/ui/gfx/resources/host_image.cc(162)] No BatchGpuUploader, cannot UpdatePixels. [ OK ] HostImageTest.RgbaImport (13 ms) [ RUN ] HostImageTest.YuvImportOnUmaPlatform TEST_LOOP_RANDOM_SEED="2960008585" [ OK ] HostImageTest.YuvImportOnUmaPlatform (25 ms) [----------] 3 tests from HostImageTest (58 ms total) [----------] 7 tests from ImagePipeTest [ RUN ] ImagePipeTest.ImagePipeImageIdMustNotBeZero TEST_LOOP_RANDOM_SEED="1273780228" [INFO:default_frame_scheduler.cc(237)] ScheduleUpdateForSession session_id: 1 presentation_time: 0 [INFO:default_frame_scheduler.cc(115)] RequestFrame [ OK ] ImagePipeTest.ImagePipeImageIdMustNotBeZero (0 ms) [ RUN ] ImagePipeTest.PresentImagesOutOfOrder TEST_LOOP_RANDOM_SEED="2099078813" [INFO:default_frame_scheduler.cc(237)] ScheduleUpdateForSession session_id: 1 presentation_time: 0 [INFO:default_frame_scheduler.cc(115)] RequestFrame [ OK ] ImagePipeTest.PresentImagesOutOfOrder (1 ms) [ RUN ] ImagePipeTest.PresentImagesInOrder TEST_LOOP_RANDOM_SEED="2789942959" [ OK ] ImagePipeTest.PresentImagesInOrder (0 ms) [ RUN ] ImagePipeTest.PresentImagesWithOffset TEST_LOOP_RANDOM_SEED="2108178685" [ OK ] ImagePipeTest.PresentImagesWithOffset (0 ms) [ RUN ] ImagePipeTest.ImagePipePresentTwoFrames TEST_LOOP_RANDOM_SEED="2710112792" [INFO:default_frame_scheduler.cc(237)] ScheduleUpdateForSession session_id: 1 presentation_time: 0 [INFO:default_frame_scheduler.cc(115)] RequestFrame [INFO:default_frame_scheduler.cc(148)] MaybeRenderFrame presentation_time=1016666687 wakeup_time=1008666687 frame_number=0 [INFO:default_frame_scheduler.cc(250)] ApplyScheduledSessionUpdates presentation_time=1016666687 frame_number=0 [INFO:default_frame_scheduler.cc(189)] Calling RenderFrame presentation_time=1016666687 frame_number=0 [WARNING:garnet/lib/ui/gfx/engine/default_frame_scheduler.cc(216)] RenderFrame failed. There may not be any calls to OnFrameRendered or OnFramePresented, and no callbacks may be invoked. [INFO:default_frame_scheduler.cc(237)] ScheduleUpdateForSession session_id: 1 presentation_time: 0 [INFO:default_frame_scheduler.cc(115)] RequestFrame [INFO:default_frame_scheduler.cc(148)] MaybeRenderFrame presentation_time=3016666727 wakeup_time=3008666727 frame_number=1 [INFO:default_frame_scheduler.cc(250)] ApplyScheduledSessionUpdates presentation_time=3016666727 frame_number=1 [INFO:default_frame_scheduler.cc(189)] Calling RenderFrame presentation_time=3016666727 frame_number=1 [WARNING:garnet/lib/ui/gfx/engine/default_frame_scheduler.cc(216)] RenderFrame failed. There may not be any calls to OnFrameRendered or OnFramePresented, and no callbacks may be invoked. [ OK ] ImagePipeTest.ImagePipePresentTwoFrames (1 ms) [ RUN ] ImagePipeTest.ImagePipeUpdateTwoFrames TEST_LOOP_RANDOM_SEED="1158171321" [INFO:default_frame_scheduler.cc(237)] ScheduleUpdateForSession session_id: 1 presentation_time: 0 [INFO:default_frame_scheduler.cc(115)] RequestFrame [INFO:default_frame_scheduler.cc(237)] ScheduleUpdateForSession session_id: 1 presentation_time: 0 [INFO:default_frame_scheduler.cc(115)] RequestFrame [INFO:default_frame_scheduler.cc(148)] MaybeRenderFrame presentation_time=16666667 wakeup_time=8666667 frame_number=0 [INFO:default_frame_scheduler.cc(250)] ApplyScheduledSessionUpdates presentation_time=16666667 frame_number=0 [INFO:default_frame_scheduler.cc(189)] Calling RenderFrame presentation_time=16666667 frame_number=0 [WARNING:garnet/lib/ui/gfx/engine/default_frame_scheduler.cc(216)] RenderFrame failed. There may not be any calls to OnFrameRendered or OnFramePresented, and no callbacks may be invoked. [INFO:default_frame_scheduler.cc(237)] ScheduleUpdateForSession session_id: 1 presentation_time: 0 [INFO:default_frame_scheduler.cc(115)] RequestFrame [INFO:default_frame_scheduler.cc(148)] MaybeRenderFrame presentation_time=1016666687 wakeup_time=1008666687 frame_number=1 [INFO:default_frame_scheduler.cc(250)] ApplyScheduledSessionUpdates presentation_time=1016666687 frame_number=1 [INFO:default_frame_scheduler.cc(189)] Calling RenderFrame presentation_time=1016666687 frame_number=1 [WARNING:garnet/lib/ui/gfx/engine/default_frame_scheduler.cc(216)] RenderFrame failed. There may not be any calls to OnFrameRendered or OnFramePresented, and no callbacks may be invoked. [INFO:default_frame_scheduler.cc(237)] ScheduleUpdateForSession session_id: 1 presentation_time: 0 [INFO:default_frame_scheduler.cc(115)] RequestFrame [INFO:default_frame_scheduler.cc(148)] MaybeRenderFrame presentation_time=2016666707 wakeup_time=2008666707 frame_number=2 [INFO:default_frame_scheduler.cc(250)] ApplyScheduledSessionUpdates presentation_time=2016666707 frame_number=2 [INFO:default_frame_scheduler.cc(189)] Calling RenderFrame presentation_time=2016666707 frame_number=2 [WARNING:garnet/lib/ui/gfx/engine/default_frame_scheduler.cc(216)] RenderFrame failed. There may not be any calls to OnFrameRendered or OnFramePresented, and no callbacks may be invoked. [ OK ] ImagePipeTest.ImagePipeUpdateTwoFrames (0 ms) [ RUN ] ImagePipeTest.ImagePipeRemoveImageThatIsPendingPresent TEST_LOOP_RANDOM_SEED="2660306664" [INFO:default_frame_scheduler.cc(237)] ScheduleUpdateForSession session_id: 1 presentation_time: 0 [INFO:default_frame_scheduler.cc(115)] RequestFrame [INFO:default_frame_scheduler.cc(148)] MaybeRenderFrame presentation_time=1016666687 wakeup_time=1008666687 frame_number=0 [INFO:default_frame_scheduler.cc(250)] ApplyScheduledSessionUpdates presentation_time=1016666687 frame_number=0 [INFO:default_frame_scheduler.cc(189)] Calling RenderFrame presentation_time=1016666687 frame_number=0 [WARNING:garnet/lib/ui/gfx/engine/default_frame_scheduler.cc(216)] RenderFrame failed. There may not be any calls to OnFrameRendered or OnFramePresented, and no callbacks may be invoked. [INFO:default_frame_scheduler.cc(237)] ScheduleUpdateForSession session_id: 1 presentation_time: 0 [INFO:default_frame_scheduler.cc(115)] RequestFrame [INFO:default_frame_scheduler.cc(148)] MaybeRenderFrame presentation_time=4016666747 wakeup_time=4008666747 frame_number=1 [INFO:default_frame_scheduler.cc(250)] ApplyScheduledSessionUpdates presentation_time=4016666747 frame_number=1 [INFO:default_frame_scheduler.cc(189)] Calling RenderFrame presentation_time=4016666747 frame_number=1 [WARNING:garnet/lib/ui/gfx/engine/default_frame_scheduler.cc(216)] RenderFrame failed. There may not be any calls to OnFrameRendered or OnFramePresented, and no callbacks may be invoked. [ OK ] ImagePipeTest.ImagePipeRemoveImageThatIsPendingPresent (1 ms) [----------] 7 tests from ImagePipeTest (3 ms total) [----------] 16 tests from ImportTest [ RUN ] ImportTest.ExportsResourceViaCmd TEST_LOOP_RANDOM_SEED="203891441" [ OK ] ImportTest.ExportsResourceViaCmd (0 ms) [ RUN ] ImportTest.ImportsUnlinkedImportViaCmd TEST_LOOP_RANDOM_SEED="80836984" [ OK ] ImportTest.ImportsUnlinkedImportViaCmd (0 ms) [ RUN ] ImportTest.PerformsFullLinking TEST_LOOP_RANDOM_SEED="2596185937" [ OK ] ImportTest.PerformsFullLinking (0 ms) [ RUN ] ImportTest.HandlesDeadSourceHandle TEST_LOOP_RANDOM_SEED="3047075410" [ OK ] ImportTest.HandlesDeadSourceHandle (0 ms) [ RUN ] ImportTest.HandlesDeadDestinationHandle TEST_LOOP_RANDOM_SEED="279439522" [ OK ] ImportTest.HandlesDeadDestinationHandle (0 ms) [ RUN ] ImportTest.DestroyingExportedResourceSendsEvent TEST_LOOP_RANDOM_SEED="4273346368" [ OK ] ImportTest.DestroyingExportedResourceSendsEvent (0 ms) [ RUN ] ImportTest.ImportingNodeAfterDestroyingExportedResourceSendsEvent TEST_LOOP_RANDOM_SEED="1585582776" [ OK ] ImportTest.ImportingNodeAfterDestroyingExportedResourceSendsEvent (0 ms) [ RUN ] ImportTest.KillingImportedResourceEvictsFromResourceLinker TEST_LOOP_RANDOM_SEED="1398532898" [ OK ] ImportTest.KillingImportedResourceEvictsFromResourceLinker (0 ms) [ RUN ] ImportTest.ResourceUnexportedAfterImportsAndImportHandlesDie1 TEST_LOOP_RANDOM_SEED="32581129" [ OK ] ImportTest.ResourceUnexportedAfterImportsAndImportHandlesDie1 (0 ms) [ RUN ] ImportTest.ResourceUnexportedAfterImportsAndImportHandlesDie2 TEST_LOOP_RANDOM_SEED="3851682390" [ OK ] ImportTest.ResourceUnexportedAfterImportsAndImportHandlesDie2 (0 ms) [ RUN ] ImportTest.ResourceUnexportedAfterImportsAndImportHandlesDie3 TEST_LOOP_RANDOM_SEED="401645257" [ OK ] ImportTest.ResourceUnexportedAfterImportsAndImportHandlesDie3 (0 ms) [ RUN ] ImportTest.ResourceUnexportedAfterImportsAndImportHandlesDie4 TEST_LOOP_RANDOM_SEED="923211096" [ OK ] ImportTest.ResourceUnexportedAfterImportsAndImportHandlesDie4 (0 ms) [ RUN ] ImportTest.ProxiesCanBeFoundByTheirContainerOrTheirUnderlyingEntityType TEST_LOOP_RANDOM_SEED="2279417774" [ OK ] ImportTest.ProxiesCanBeFoundByTheirContainerOrTheirUnderlyingEntityType (1 ms) [ RUN ] ImportTest.UnlinkedImportedResourceCanAcceptCommands TEST_LOOP_RANDOM_SEED="726459714" [ OK ] ImportTest.UnlinkedImportedResourceCanAcceptCommands (0 ms) [ RUN ] ImportTest.LinkedResourceShouldBeAbleToAcceptCommands TEST_LOOP_RANDOM_SEED="1391308856" [ OK ] ImportTest.LinkedResourceShouldBeAbleToAcceptCommands (0 ms) [ RUN ] ImportTest.EmbedderCanEmbedNodesFromElsewhere TEST_LOOP_RANDOM_SEED="3864982534" [ OK ] ImportTest.EmbedderCanEmbedNodesFromElsewhere (0 ms) [----------] 16 tests from ImportTest (1 ms total) [----------] 1 test from MemoryTest [ RUN ] MemoryTest.MemoryAllocationSizeValidation TEST_LOOP_RANDOM_SEED="487574276" [ OK ] MemoryTest.MemoryAllocationSizeValidation (0 ms) [----------] 1 test from MemoryTest (0 ms total) [----------] 5 tests from VkMemoryTest [ RUN ] VkMemoryTest.ImportDeviceMemory TEST_LOOP_RANDOM_SEED="748649038" [ OK ] VkMemoryTest.ImportDeviceMemory (29 ms) [ RUN ] VkMemoryTest.ImportReadOnlyHostMemory TEST_LOOP_RANDOM_SEED="2958819209" [INFO:memory.cc(167)] Host memory VMO could not be imported to any valid Vulkan memory types. [ OK ] VkMemoryTest.ImportReadOnlyHostMemory (13 ms) [ RUN ] VkMemoryTest.ImportReadOnlyHostMemoryAsDeviceMemory TEST_LOOP_RANDOM_SEED="1470987506" [ OK ] VkMemoryTest.ImportReadOnlyHostMemoryAsDeviceMemory (13 ms) [ RUN ] VkMemoryTest.ImportReadOnlyDeviceMemory TEST_LOOP_RANDOM_SEED="2620443273" [ OK ] VkMemoryTest.ImportReadOnlyDeviceMemory (24 ms) [ RUN ] VkMemoryTest.ImportMaliciousClient TEST_LOOP_RANDOM_SEED="2971734558" [ OK ] VkMemoryTest.ImportMaliciousClient (13 ms) [----------] 5 tests from VkMemoryTest (93 ms total) [----------] 5 tests from NodeTest [ RUN ] NodeTest.Tagging TEST_LOOP_RANDOM_SEED="1398499529" [ OK ] NodeTest.Tagging (0 ms) [ RUN ] NodeTest.ShapeNodeMaterialAndShape TEST_LOOP_RANDOM_SEED="918693335" [ OK ] NodeTest.ShapeNodeMaterialAndShape (0 ms) [ RUN ] NodeTest.NodesWithChildren TEST_LOOP_RANDOM_SEED="1239722104" [ OK ] NodeTest.NodesWithChildren (0 ms) [ RUN ] NodeTest.SettingHitTestBehavior TEST_LOOP_RANDOM_SEED="886321855" [ OK ] NodeTest.SettingHitTestBehavior (0 ms) [ RUN ] NodeTest.SettingClipPlanes TEST_LOOP_RANDOM_SEED="3561031484" [ OK ] NodeTest.SettingClipPlanes (0 ms) [----------] 5 tests from NodeTest (0 ms total) [----------] 20 tests from ObjectLinkerTest [ RUN ] ObjectLinkerTest.InitialState TEST_LOOP_RANDOM_SEED="3455872590" [ OK ] ObjectLinkerTest.InitialState (0 ms) [ RUN ] ObjectLinkerTest.AllowsExport TEST_LOOP_RANDOM_SEED="3752123202" [ OK ] ObjectLinkerTest.AllowsExport (0 ms) [ RUN ] ObjectLinkerTest.CannotExportInvalidToken TEST_LOOP_RANDOM_SEED="2204703475" [ OK ] ObjectLinkerTest.CannotExportInvalidToken (0 ms) [ RUN ] ObjectLinkerTest.CannotExportWithDeadExportToken TEST_LOOP_RANDOM_SEED="2203175669" [ OK ] ObjectLinkerTest.CannotExportWithDeadExportToken (0 ms) [ RUN ] ObjectLinkerTest.CanExportWithDeadImportToken TEST_LOOP_RANDOM_SEED="1659831416" [ OK ] ObjectLinkerTest.CanExportWithDeadImportToken (0 ms) [ RUN ] ObjectLinkerTest.CannotExportSameTokenTwice TEST_LOOP_RANDOM_SEED="2858135530" [ OK ] ObjectLinkerTest.CannotExportSameTokenTwice (0 ms) [ RUN ] ObjectLinkerTest.LinkDeathRemovesExport TEST_LOOP_RANDOM_SEED="860530931" [ OK ] ObjectLinkerTest.LinkDeathRemovesExport (0 ms) [ RUN ] ObjectLinkerTest.AllowsImport TEST_LOOP_RANDOM_SEED="2533572527" [ OK ] ObjectLinkerTest.AllowsImport (0 ms) [ RUN ] ObjectLinkerTest.CannotImportInvalidToken TEST_LOOP_RANDOM_SEED="2777916999" [ OK ] ObjectLinkerTest.CannotImportInvalidToken (0 ms) [ RUN ] ObjectLinkerTest.CannotImportWithDeadImportToken TEST_LOOP_RANDOM_SEED="1617206431" [ OK ] ObjectLinkerTest.CannotImportWithDeadImportToken (0 ms) [ RUN ] ObjectLinkerTest.CanImportWithDeadExportToken TEST_LOOP_RANDOM_SEED="676252592" [ OK ] ObjectLinkerTest.CanImportWithDeadExportToken (0 ms) [ RUN ] ObjectLinkerTest.CannotImportSameTokenTwice TEST_LOOP_RANDOM_SEED="3602121069" [ OK ] ObjectLinkerTest.CannotImportSameTokenTwice (0 ms) [ RUN ] ObjectLinkerTest.LinkDeathRemovesImport TEST_LOOP_RANDOM_SEED="3660488924" [ OK ] ObjectLinkerTest.LinkDeathRemovesImport (0 ms) [ RUN ] ObjectLinkerTest.InitializeLinksMatchingPeers TEST_LOOP_RANDOM_SEED="1053878029" [ OK ] ObjectLinkerTest.InitializeLinksMatchingPeers (0 ms) [ RUN ] ObjectLinkerTest.InitializeLinksMatchingPeersWithImportBeforeExport TEST_LOOP_RANDOM_SEED="874906063" [ OK ] ObjectLinkerTest.InitializeLinksMatchingPeersWithImportBeforeExport (0 ms) [ RUN ] ObjectLinkerTest.InitializeDoesNotLinkNonMatchingPeers TEST_LOOP_RANDOM_SEED="791507625" [ OK ] ObjectLinkerTest.InitializeDoesNotLinkNonMatchingPeers (0 ms) [ RUN ] ObjectLinkerTest.EarlyImportTokenDeathCausesExportDisconnection TEST_LOOP_RANDOM_SEED="3006186047" [ OK ] ObjectLinkerTest.EarlyImportTokenDeathCausesExportDisconnection (0 ms) [ RUN ] ObjectLinkerTest.ImportTokenDeathCausesExportDisconnection TEST_LOOP_RANDOM_SEED="1598723187" [ OK ] ObjectLinkerTest.ImportTokenDeathCausesExportDisconnection (0 ms) [ RUN ] ObjectLinkerTest.EarlyExportTokenDeathCausesImportDisconnection TEST_LOOP_RANDOM_SEED="2797730040" [ OK ] ObjectLinkerTest.EarlyExportTokenDeathCausesImportDisconnection (0 ms) [ RUN ] ObjectLinkerTest.ExportTokenDeathCausesImportDisconnection TEST_LOOP_RANDOM_SEED="1248471634" [ OK ] ObjectLinkerTest.ExportTokenDeathCausesImportDisconnection (0 ms) [----------] 20 tests from ObjectLinkerTest (0 ms total) [----------] 1 test from PoseBufferTest [ RUN ] PoseBufferTest.Validation TEST_LOOP_RANDOM_SEED="4059733016" [ OK ] PoseBufferTest.Validation (25 ms) [----------] 1 test from PoseBufferTest (25 ms total) [----------] 15 tests from ResourceLinkerTest [ RUN ] ResourceLinkerTest.AllowsExport TEST_LOOP_RANDOM_SEED="2563820740" [ OK ] ResourceLinkerTest.AllowsExport (0 ms) [ RUN ] ResourceLinkerTest.AllowsImport TEST_LOOP_RANDOM_SEED="248410692" [ OK ] ResourceLinkerTest.AllowsImport (0 ms) [ RUN ] ResourceLinkerTest.CannotImportWithDeadSourceAndDestinationHandles TEST_LOOP_RANDOM_SEED="3675433201" [ OK ] ResourceLinkerTest.CannotImportWithDeadSourceAndDestinationHandles (0 ms) [ RUN ] ResourceLinkerTest.CannotImportWithDeadDestinationHandles TEST_LOOP_RANDOM_SEED="2121581868" [ OK ] ResourceLinkerTest.CannotImportWithDeadDestinationHandles (0 ms) [ RUN ] ResourceLinkerTest.CanImportWithDeadSourceHandle TEST_LOOP_RANDOM_SEED="1993831616" [ OK ] ResourceLinkerTest.CanImportWithDeadSourceHandle (0 ms) [ RUN ] ResourceLinkerTest.CannotExportWithDeadSourceAndDestinationHandles TEST_LOOP_RANDOM_SEED="965789841" [ OK ] ResourceLinkerTest.CannotExportWithDeadSourceAndDestinationHandles (0 ms) [ RUN ] ResourceLinkerTest.CannotExportWithDeadSourceHandle TEST_LOOP_RANDOM_SEED="2136478340" [ OK ] ResourceLinkerTest.CannotExportWithDeadSourceHandle (0 ms) [ RUN ] ResourceLinkerTest.CanExportWithDeadDestinationHandle TEST_LOOP_RANDOM_SEED="1905274804" [ OK ] ResourceLinkerTest.CanExportWithDeadDestinationHandle (0 ms) [ RUN ] ResourceLinkerTest.DestinationHandleDeathAutomaticallyCleansUpResourceExport TEST_LOOP_RANDOM_SEED="1990494259" [ OK ] ResourceLinkerTest.DestinationHandleDeathAutomaticallyCleansUpResourceExport (0 ms) [ RUN ] ResourceLinkerTest.SourceHandleDeathAutomaticallyCleansUpUnresolvedImports TEST_LOOP_RANDOM_SEED="2131998802" [ OK ] ResourceLinkerTest.SourceHandleDeathAutomaticallyCleansUpUnresolvedImports (0 ms) [ RUN ] ResourceLinkerTest.ResourceDeathAutomaticallyCleansUpResourceExport TEST_LOOP_RANDOM_SEED="2139003772" [ OK ] ResourceLinkerTest.ResourceDeathAutomaticallyCleansUpResourceExport (0 ms) [ RUN ] ResourceLinkerTest.ImportsBeforeExportsAreServiced TEST_LOOP_RANDOM_SEED="2082460606" [ OK ] ResourceLinkerTest.ImportsBeforeExportsAreServiced (0 ms) [ RUN ] ResourceLinkerTest.ImportAfterReleasedExportedResourceFails TEST_LOOP_RANDOM_SEED="1610183973" [ OK ] ResourceLinkerTest.ImportAfterReleasedExportedResourceFails (0 ms) [ RUN ] ResourceLinkerTest.DuplicatedDestinationHandlesAllowMultipleImports TEST_LOOP_RANDOM_SEED="3862667081" [ OK ] ResourceLinkerTest.DuplicatedDestinationHandlesAllowMultipleImports (0 ms) [ RUN ] ResourceLinkerTest.UnresolvedImportIsRemovedIfDestroyed TEST_LOOP_RANDOM_SEED="1390567713" [ OK ] ResourceLinkerTest.UnresolvedImportIsRemovedIfDestroyed (1 ms) [----------] 15 tests from ResourceLinkerTest (2 ms total) [----------] 3 tests from SceneGraphTest [ RUN ] SceneGraphTest.CompositorsGetAddedAndRemoved TEST_LOOP_RANDOM_SEED="3279357852" [ OK ] SceneGraphTest.CompositorsGetAddedAndRemoved (0 ms) [ RUN ] SceneGraphTest.LookupCompositor TEST_LOOP_RANDOM_SEED="3031574042" [ OK ] SceneGraphTest.LookupCompositor (0 ms) [ RUN ] SceneGraphTest.FirstCompositorIsStable TEST_LOOP_RANDOM_SEED="3217752268" [ OK ] SceneGraphTest.FirstCompositorIsStable (0 ms) [----------] 3 tests from SceneGraphTest (0 ms total) [----------] 1 test from SceneTest [ RUN ] SceneTest.Lighting TEST_LOOP_RANDOM_SEED="4103664589" [ OK ] SceneTest.Lighting (0 ms) [----------] 1 test from SceneTest (0 ms total) [----------] 1 test from SessionHandlerTest [ RUN ] SessionHandlerTest.WhenSessionHandlerDestroyed_ShouldRemoveSessionHandlerPtrFromSessionManager TEST_LOOP_RANDOM_SEED="1954875583" [ OK ] SessionHandlerTest.WhenSessionHandlerDestroyed_ShouldRemoveSessionHandlerPtrFromSessionManager (0 ms) [----------] 1 test from SessionHandlerTest (0 ms total) [----------] 5 tests from SessionTest [ RUN ] SessionTest.ScheduleUpdateOutOfOrder TEST_LOOP_RANDOM_SEED="2793458636" [ OK ] SessionTest.ScheduleUpdateOutOfOrder (0 ms) [ RUN ] SessionTest.ScheduleUpdateInOrder TEST_LOOP_RANDOM_SEED="3258581563" [ OK ] SessionTest.ScheduleUpdateInOrder (0 ms) [ RUN ] SessionTest.ResourceIdAlreadyUsed TEST_LOOP_RANDOM_SEED="1328572869" [ OK ] SessionTest.ResourceIdAlreadyUsed (0 ms) [ RUN ] SessionTest.AddAndRemoveResource TEST_LOOP_RANDOM_SEED="154933147" [ OK ] SessionTest.AddAndRemoveResource (0 ms) [ RUN ] SessionTest.Labeling TEST_LOOP_RANDOM_SEED="104906841" [ OK ] SessionTest.Labeling (0 ms) [----------] 5 tests from SessionTest (0 ms total) [----------] 1 test from BufferSessionTest [ RUN ] BufferSessionTest.BufferAliasing TEST_LOOP_RANDOM_SEED="2602013035" [ OK ] BufferSessionTest.BufferAliasing (25 ms) [----------] 1 test from BufferSessionTest (25 ms total) [----------] 2 tests from ShapeTest [ RUN ] ShapeTest.Circle TEST_LOOP_RANDOM_SEED="2736769776" [ OK ] ShapeTest.Circle (0 ms) [ RUN ] ShapeTest.Rectangle TEST_LOOP_RANDOM_SEED="2034213498" [ OK ] ShapeTest.Rectangle (0 ms) [----------] 2 tests from ShapeTest (0 ms total) [----------] 1 test from SizeChangeHintTest [ RUN ] SizeChangeHintTest.SendingSizeChangeEventWorks TEST_LOOP_RANDOM_SEED="203824018" [ OK ] SizeChangeHintTest.SendingSizeChangeEventWorks (0 ms) [----------] 1 test from SizeChangeHintTest (0 ms total) [----------] 1 test from StereoCameraTest [ RUN ] StereoCameraTest.Basic TEST_LOOP_RANDOM_SEED="29142418" [ OK ] StereoCameraTest.Basic (0 ms) [----------] 1 test from StereoCameraTest (0 ms total) [----------] 23 tests from ViewTest [ RUN ] ViewTest.ChildrenCanBeAddedToViewWithoutViewHolder TEST_LOOP_RANDOM_SEED="2839309512" [ OK ] ViewTest.ChildrenCanBeAddedToViewWithoutViewHolder (0 ms) [ RUN ] ViewTest.ExportsViewHolderViaCmd TEST_LOOP_RANDOM_SEED="1016788927" [ OK ] ViewTest.ExportsViewHolderViaCmd (0 ms) [ RUN ] ViewTest.ImportsViewViaCmd TEST_LOOP_RANDOM_SEED="3362520215" [ OK ] ViewTest.ImportsViewViaCmd (0 ms) [ RUN ] ViewTest.PairedViewAndHolderAreLinked TEST_LOOP_RANDOM_SEED="1082996855" [ OK ] ViewTest.PairedViewAndHolderAreLinked (0 ms) [ RUN ] ViewTest.ExportViewHolderWithDeadHandleFails TEST_LOOP_RANDOM_SEED="1955323425" [ OK ] ViewTest.ExportViewHolderWithDeadHandleFails (0 ms) [ RUN ] ViewTest.ViewHolderDestroyedBeforeView TEST_LOOP_RANDOM_SEED="605424232" [ OK ] ViewTest.ViewHolderDestroyedBeforeView (0 ms) [ RUN ] ViewTest.ViewDestroyedBeforeViewHolder TEST_LOOP_RANDOM_SEED="3827465412" [ OK ] ViewTest.ViewDestroyedBeforeViewHolder (0 ms) [ RUN ] ViewTest.ViewAndViewHolderConnectedEvents TEST_LOOP_RANDOM_SEED="956193982" [ OK ] ViewTest.ViewAndViewHolderConnectedEvents (0 ms) [ RUN ] ViewTest.ViewHolderConnectsToScene TEST_LOOP_RANDOM_SEED="4127042443" [ OK ] ViewTest.ViewHolderConnectsToScene (0 ms) [ RUN ] ViewTest.ViewHolderDetachedAndReleased TEST_LOOP_RANDOM_SEED="413546693" [ OK ] ViewTest.ViewHolderDetachedAndReleased (1 ms) [ RUN ] ViewTest.ViewHolderChildrenReleasedFromSceneGraphWhenViewDestroyed TEST_LOOP_RANDOM_SEED="1540878978" [ OK ] ViewTest.ViewHolderChildrenReleasedFromSceneGraphWhenViewDestroyed (0 ms) [ RUN ] ViewTest.ViewNodeChildAddedToViewHolder TEST_LOOP_RANDOM_SEED="991212581" [ OK ] ViewTest.ViewNodeChildAddedToViewHolder (0 ms) [ RUN ] ViewTest.ViewHolderCannotAddArbitraryChildNodes TEST_LOOP_RANDOM_SEED="1058683904" [ OK ] ViewTest.ViewHolderCannotAddArbitraryChildNodes (0 ms) [ RUN ] ViewTest.ViewNodePairedToView TEST_LOOP_RANDOM_SEED="2263671418" [ OK ] ViewTest.ViewNodePairedToView (0 ms) [ RUN ] ViewTest.ViewNodeNotInResourceMap TEST_LOOP_RANDOM_SEED="3916034721" [ OK ] ViewTest.ViewNodeNotInResourceMap (0 ms) [ RUN ] ViewTest.ViewHolderGrandchildGetsSceneRefreshed TEST_LOOP_RANDOM_SEED="68693303" [ OK ] ViewTest.ViewHolderGrandchildGetsSceneRefreshed (0 ms) [ RUN ] ViewTest.ViewLinksAfterViewHolderConnectsToScene TEST_LOOP_RANDOM_SEED="2371630374" [ OK ] ViewTest.ViewLinksAfterViewHolderConnectsToScene (0 ms) [ RUN ] ViewTest.ViewStateChangeNotifiesViewHolder TEST_LOOP_RANDOM_SEED="2074465593" [ OK ] ViewTest.ViewStateChangeNotifiesViewHolder (0 ms) [ RUN ] ViewTest.RenderStateAcrossManyFrames TEST_LOOP_RANDOM_SEED="4071575318" [ OK ] ViewTest.RenderStateAcrossManyFrames (0 ms) [ RUN ] ViewTest.RenderStateFalseWhenViewDisconnects TEST_LOOP_RANDOM_SEED="198231423" [ OK ] ViewTest.RenderStateFalseWhenViewDisconnects (1 ms) [ RUN ] ViewTest.ViewHolderRenderWaitClearedWhenViewDestroyed TEST_LOOP_RANDOM_SEED="4016709738" [ OK ] ViewTest.ViewHolderRenderWaitClearedWhenViewDestroyed (0 ms) [ RUN ] ViewTest.RenderSignalDoesntCrashWhenViewHolderDestroyed TEST_LOOP_RANDOM_SEED="2978872687" [ OK ] ViewTest.RenderSignalDoesntCrashWhenViewHolderDestroyed (0 ms) [ RUN ] ViewTest.RenderStateFalseWhenViewHolderDisconnectsFromScene TEST_LOOP_RANDOM_SEED="2101207277" [ OK ] ViewTest.RenderStateFalseWhenViewHolderDisconnectsFromScene (0 ms) [----------] 23 tests from ViewTest (2 ms total) [----------] Global test environment tear-down [==========] 156 tests from 29 test suites ran. (222 ms total) [ PASSED ] 156 tests. YOU HAVE 5 DISABLED TESTS PASSED: /pkgfs/packages/scenic_tests/0/test/gfx_unittests passed SUMMARY: Ran 1 tests: 0 failed (0.548 sec) ok 5 //garnet/bin/ui:gfx_unittests (1.760590839s) ------------------------------------------------ RUNNING TEST: /pkgfs/packages/scenic_tests/0/test/geometry_util_unittests Running main() from ../../third_party/googletest/googletest/src/gtest_main.cc [==========] Running 10 tests from 4 test suites. [----------] Global test environment set-up. [----------] 1 test from RectTest [ RUN ] RectTest.Comparisons [ OK ] RectTest.Comparisons (0 ms) [----------] 1 test from RectTest (0 ms total) [----------] 1 test from SizeTest [ RUN ] SizeTest.Comparisons [ OK ] SizeTest.Comparisons (0 ms) [----------] 1 test from SizeTest (0 ms total) [----------] 1 test from PointTest [ RUN ] PointTest.Comparisons [ OK ] PointTest.Comparisons (0 ms) [----------] 1 test from PointTest (0 ms total) [----------] 7 tests from TransformFunctionsTest [ RUN ] TransformFunctionsTest.SetIdentityTransform [ OK ] TransformFunctionsTest.SetIdentityTransform (0 ms) [ RUN ] TransformFunctionsTest.SetTranslationTransform [ OK ] TransformFunctionsTest.SetTranslationTransform (0 ms) [ RUN ] TransformFunctionsTest.Translate [ OK ] TransformFunctionsTest.Translate (0 ms) [ RUN ] TransformFunctionsTest.Scale [ OK ] TransformFunctionsTest.Scale (0 ms) [ RUN ] TransformFunctionsTest.CreateIdentityTransform [ OK ] TransformFunctionsTest.CreateIdentityTransform (0 ms) [ RUN ] TransformFunctionsTest.CreateTranslationTransform [ OK ] TransformFunctionsTest.CreateTranslationTransform (0 ms) [ RUN ] TransformFunctionsTest.CreateScaleTransform [ OK ] TransformFunctionsTest.CreateScaleTransform (0 ms) [----------] 7 tests from TransformFunctionsTest (0 ms total) [----------] Global test environment tear-down [==========] 10 tests from 4 test suites ran. (0 ms total) [ PASSED ] 10 tests. PASSED: /pkgfs/packages/scenic_tests/0/test/geometry_util_unittests passed SUMMARY: Ran 1 tests: 0 failed (0.052 sec) ok 6 //garnet/bin/ui:geometry_util_unittests (1.266529128s) ------------------------------------------------ RUNNING TEST: /pkgfs/packages/scenic_tests/0/test/input_apptests Running main() from ../../third_party/googletest/googletest/src/gtest_main.cc [==========] Running 9 tests from 2 test suites. [----------] Global test environment set-up. [----------] 7 tests from ReaderInterpreterInputTest [ RUN ] ReaderInterpreterInputTest.BootMouse TEST_LOOP_RANDOM_SEED="3151872797" [ OK ] ReaderInterpreterInputTest.BootMouse (0 ms) [ RUN ] ReaderInterpreterInputTest.BootKeyboard TEST_LOOP_RANDOM_SEED="2383736743" [ OK ] ReaderInterpreterInputTest.BootKeyboard (0 ms) [ RUN ] ReaderInterpreterInputTest.EgalaxTouchScreen TEST_LOOP_RANDOM_SEED="322318680" [INFO:touch.cc(106)] Touch descriptor: Failed to find any touch points [INFO:input_interpreter.cc(323)] Can't process HID report descriptor for MockHidDecoder; Failed to do generic device parsing [INFO:input_interpreter.cc(329)] hid-parser successful for MockHidDecoder with usage page 1 and usage 1 [INFO:input_interpreter.cc(329)] hid-parser successful for MockHidDecoder with usage page 13 and usage 4 [ OK ] ReaderInterpreterInputTest.EgalaxTouchScreen (1 ms) [ RUN ] ReaderInterpreterInputTest.ParadiseTouchscreen TEST_LOOP_RANDOM_SEED="788652448" [INFO:input_interpreter.cc(329)] hid-parser successful for MockHidDecoder with usage page 13 and usage 4 [INFO:input_interpreter.cc(329)] hid-parser successful for MockHidDecoder with usage page 13 and usage 2 [INFO:input_interpreter.cc(329)] hid-parser successful for MockHidDecoder with usage page 1 and usage 2 [ OK ] ReaderInterpreterInputTest.ParadiseTouchscreen (0 ms) [ RUN ] ReaderInterpreterInputTest.ParadiseTouchpad TEST_LOOP_RANDOM_SEED="1053700629" [INFO:input_interpreter.cc(329)] hid-parser successful for MockHidDecoder with usage page 13 and usage 5 [ OK ] ReaderInterpreterInputTest.ParadiseTouchpad (0 ms) [ RUN ] ReaderInterpreterInputTest.SensorTest TEST_LOOP_RANDOM_SEED="750758758" [INFO:input_interpreter.cc(329)] hid-parser successful for MockHidDecoder with usage page 32 and usage 1 [ OK ] ReaderInterpreterInputTest.SensorTest (0 ms) [ RUN ] ReaderInterpreterInputTest.MediaButtonsTest TEST_LOOP_RANDOM_SEED="2792306696" [INFO:input_interpreter.cc(329)] hid-parser successful for MockHidDecoder with usage page 12 and usage 1 [ OK ] ReaderInterpreterInputTest.MediaButtonsTest (0 ms) [----------] 7 tests from ReaderInterpreterInputTest (1 ms total) [----------] 2 tests from InputInterfaceTest [ RUN ] InputInterfaceTest.RegisterKeyboardTest TEST_LOOP_RANDOM_SEED="1445913315" [ OK ] InputInterfaceTest.RegisterKeyboardTest (0 ms) [ RUN ] InputInterfaceTest.InputKeyboardTest TEST_LOOP_RANDOM_SEED="3584317205" [ OK ] InputInterfaceTest.InputKeyboardTest (0 ms) [----------] 2 tests from InputInterfaceTest (0 ms total) [----------] Global test environment tear-down [==========] 9 tests from 2 test suites ran. (1 ms total) [ PASSED ] 9 tests. PASSED: /pkgfs/packages/scenic_tests/0/test/input_apptests passed SUMMARY: Ran 1 tests: 0 failed (0.070 sec) ok 7 //garnet/bin/ui:input_apptests (1.285103086s) ------------------------------------------------ RUNNING TEST: /pkgfs/packages/scenic_tests/0/test/input_reader_unittests Running main() from ../../third_party/googletest/googletest/src/gtest_main.cc [==========] Running 15 tests from 5 test suites. [----------] Global test environment set-up. [----------] 1 test from MouseTest [ RUN ] MouseTest.BootMouse [INFO:mouse.cc(108)] Mouse report 255 does not match report id 0 [ OK ] MouseTest.BootMouse (0 ms) [----------] 1 test from MouseTest (0 ms total) [----------] 2 tests from SensorTest [ RUN ] SensorTest.LightMeter [ OK ] SensorTest.LightMeter (0 ms) [ RUN ] SensorTest.Accelerometer [ OK ] SensorTest.Accelerometer (0 ms) [----------] 2 tests from SensorTest (0 ms total) [----------] 2 tests from StylusTest [ RUN ] StylusTest.Paradise [ OK ] StylusTest.Paradise (0 ms) [ RUN ] StylusTest.Acer12 [ OK ] StylusTest.Acer12 (0 ms) [----------] 2 tests from StylusTest (0 ms total) [----------] 2 tests from TouchpadTest [ RUN ] TouchpadTest.ParadiseV1 [ OK ] TouchpadTest.ParadiseV1 (0 ms) [ RUN ] TouchpadTest.ParadiseV2 PASSED: /pkgfs/packages/scenic_tests/0/test/input_reader_unittests passed [ OK ] TouchpadTest.ParadiseV2 (0 ms) [----------] 2 tests from TouchpadTest (0 ms total) [----------] 8 tests from TouchscreenTest [ RUN ] TouchscreenTest.Gechic1101 [ OK ] TouchscreenTest.Gechic1101 (0 ms) [ RUN ] TouchscreenTest.CoolTouch [ OK ] TouchscreenTest.CoolTouch (0 ms) [ RUN ] TouchscreenTest.WaveShare [ OK ] TouchscreenTest.WaveShare (0 ms) [ RUN ] TouchscreenTest.Gechic1303 [ OK ] TouchscreenTest.Gechic1303 (0 ms) [ RUN ] TouchscreenTest.ParadiseV1 [ OK ] TouchscreenTest.ParadiseV1 (1 ms) [ RUN ] TouchscreenTest.ParadiseV2 [ OK ] TouchscreenTest.ParadiseV2 (0 ms) [ RUN ] TouchscreenTest.ParadiseV3 [ OK ] TouchscreenTest.ParadiseV3 (0 ms) [ RUN ] TouchscreenTest.Ft3x27 [ OK ] TouchscreenTest.Ft3x27 (0 ms) [----------] 8 tests from TouchscreenTest (1 ms total) [----------] Global test environment tear-down [==========] 15 tests from 5 test suites ran. (1 ms total) [ PASSED ] 15 tests. SUMMARY: Ran 1 tests: 0 failed (0.061 sec) ok 8 //garnet/bin/ui:input_reader_unittests (1.277580058s) ------------------------------------------------ RUNNING TEST: /pkgfs/packages/scenic_tests/0/test/input_unittests [==========] Running 5 tests from 4 test suites. [----------] Global test environment set-up. [----------] 1 test from CoordinateTransformTest [ RUN ] CoordinateTransformTest.CoordinateTransform TEST_LOOP_RANDOM_SEED="2871444145" [INFO:gfx_system.cc(196)] No Vulkan found, but using a test-only "display". [INFO:input_system.cc(203)] Scenic input system initialized. [ERROR:garnet/lib/ui/input/input_system.cc(200)] Scenic lost connection to TextSync [INFO:default_frame_scheduler.cc(237)] ScheduleUpdateForSession session_id: 1 presentation_time: 0 [INFO:default_frame_scheduler.cc(115)] RequestFrame [INFO:default_frame_scheduler.cc(148)] MaybeRenderFrame presentation_time=3540083404135 wakeup_time=3540075404135 frame_number=0 [INFO:default_frame_scheduler.cc(250)] ApplyScheduledSessionUpdates presentation_time=3540083404135 frame_number=0 [INFO:default_frame_scheduler.cc(189)] Calling RenderFrame presentation_time=3540083404135 frame_number=0 [WARNING:garnet/lib/ui/gfx/engine/default_frame_scheduler.cc(216)] RenderFrame failed. There may not be any calls to OnFrameRendered or OnFramePresented, and no callbacks may be invoked. [INFO:default_frame_scheduler.cc(237)] ScheduleUpdateForSession session_id: 2 presentation_time: 0 [INFO:default_frame_scheduler.cc(115)] RequestFrame [INFO:default_frame_scheduler.cc(148)] MaybeRenderFrame presentation_time=3540100070802 wakeup_time=3540092070802 frame_number=1 [INFO:default_frame_scheduler.cc(250)] ApplyScheduledSessionUpdates presentation_time=3540100070802 frame_number=1 [INFO:default_frame_scheduler.cc(189)] Calling RenderFrame presentation_time=3540100070802 frame_number=1 [WARNING:garnet/lib/ui/gfx/engine/default_frame_scheduler.cc(216)] RenderFrame failed. There may not be any calls to OnFrameRendered or OnFramePresented, and no callbacks may be invoked. [INFO:default_frame_scheduler.cc(237)] ScheduleUpdateForSession session_id: 3 presentation_time: 0 [INFO:default_frame_scheduler.cc(115)] RequestFrame [INFO:default_frame_scheduler.cc(148)] MaybeRenderFrame presentation_time=3540116737469 wakeup_time=3540108737469 frame_number=2 [INFO:default_frame_scheduler.cc(250)] ApplyScheduledSessionUpdates presentation_time=3540116737469 frame_number=2 [INFO:default_frame_scheduler.cc(189)] Calling RenderFrame presentation_time=3540116737469 frame_number=2 [WARNING:garnet/lib/ui/gfx/engine/default_frame_scheduler.cc(216)] RenderFrame failed. There may not be any calls to OnFrameRendered or OnFramePresented, and no callbacks may be invoked. [ OK ] CoordinateTransformTest.CoordinateTransform (1 ms) [----------] 1 test from CoordinateTransformTest (1 ms total) [----------] 1 test from FocusAvoidanceTest [ RUN ] FocusAvoidanceTest.ViewHierarchyByScenic TEST_LOOP_RANDOM_SEED="1092838580" [INFO:gfx_system.cc(196)] No Vulkan found, but using a test-only "display". [INFO:input_system.cc(203)] Scenic input system initialized. [ERROR:garnet/lib/ui/input/input_system.cc(200)] Scenic lost connection to TextSync [INFO:default_frame_scheduler.cc(237)] ScheduleUpdateForSession session_id: 1 presentation_time: 0 [INFO:default_frame_scheduler.cc(115)] RequestFrame [INFO:default_frame_scheduler.cc(148)] MaybeRenderFrame presentation_time=16666667 wakeup_time=8666667 frame_number=0 [INFO:default_frame_scheduler.cc(250)] ApplyScheduledSessionUpdates presentation_time=16666667 frame_number=0 [INFO:default_frame_scheduler.cc(189)] Calling RenderFrame presentation_time=16666667 frame_number=0 [WARNING:garnet/lib/ui/gfx/engine/default_frame_scheduler.cc(216)] RenderFrame failed. There may not be any calls to OnFrameRendered or OnFramePresented, and no callbacks may be invoked. [INFO:default_frame_scheduler.cc(237)] ScheduleUpdateForSession session_id: 2 presentation_time: 0 [INFO:default_frame_scheduler.cc(115)] RequestFrame [INFO:default_frame_scheduler.cc(148)] MaybeRenderFrame presentation_time=33333334 wakeup_time=25333334 frame_number=1 [INFO:default_frame_scheduler.cc(250)] ApplyScheduledSessionUpdates presentation_time=33333334 frame_number=1 [INFO:default_frame_scheduler.cc(189)] Calling RenderFrame presentation_time=33333334 frame_number=1 [WARNING:garnet/lib/ui/gfx/engine/default_frame_scheduler.cc(216)] RenderFrame failed. There may not be any calls to OnFrameRendered or OnFramePresented, and no callbacks may be invoked. [INFO:default_frame_scheduler.cc(237)] ScheduleUpdateForSession session_id: 3 presentation_time: 0 [INFO:default_frame_scheduler.cc(115)] RequestFrame [INFO:default_frame_scheduler.cc(148)] MaybeRenderFrame presentation_time=50000001 wakeup_time=42000001 frame_number=2 [INFO:default_frame_scheduler.cc(250)] ApplyScheduledSessionUpdates presentation_time=50000001 frame_number=2 [INFO:default_frame_scheduler.cc(189)] Calling RenderFrame presentation_time=50000001 frame_number=2 [WARNING:garnet/lib/ui/gfx/engine/default_frame_scheduler.cc(216)] RenderFrame failed. There may not be any calls to OnFrameRendered or OnFramePresented, and no callbacks may be invoked. [ OK ] FocusAvoidanceTest.ViewHierarchyByScenic (1 ms) [----------] 1 test from FocusAvoidanceTest (1 ms total) [----------] 1 test from HardKeyboardDeliveryTest [ RUN ] HardKeyboardDeliveryTest.Test TEST_LOOP_RANDOM_SEED="1519764342" [INFO:gfx_system.cc(196)] No Vulkan found, but using a test-only "display". [INFO:input_system.cc(203)] Scenic input system initialized. [ERROR:garnet/lib/ui/input/input_system.cc(200)] Scenic lost connection to TextSync [INFO:default_frame_scheduler.cc(237)] ScheduleUpdateForSession session_id: 1 presentation_time: 0 [INFO:default_frame_scheduler.cc(115)] RequestFrame [INFO:default_frame_scheduler.cc(148)] MaybeRenderFrame presentation_time=3540083404135 wakeup_time=3540075404135 frame_number=0 [INFO:default_frame_scheduler.cc(250)] ApplyScheduledSessionUpdates presentation_time=3540083404135 frame_number=0 [INFO:default_frame_scheduler.cc(189)] Calling RenderFrame presentation_time=3540083404135 frame_number=0 [WARNING:garnet/lib/ui/gfx/engine/default_frame_scheduler.cc(216)] RenderFrame failed. There may not be any calls to OnFrameRendered or OnFramePresented, and no callbacks may be invoked. [INFO:default_frame_scheduler.cc(237)] ScheduleUpdateForSession session_id: 2 presentation_time: 0 [INFO:default_frame_scheduler.cc(115)] RequestFrame [INFO:default_frame_scheduler.cc(148)] MaybeRenderFrame presentation_time=3540100070802 wakeup_time=3540092070802 frame_number=1 [INFO:default_frame_scheduler.cc(250)] ApplyScheduledSessionUpdates presentation_time=3540100070802 frame_number=1 [INFO:default_frame_scheduler.cc(189)] Calling RenderFrame presentation_time=3540100070802 frame_number=1 [WARNING:garnet/lib/ui/gfx/engine/default_frame_scheduler.cc(216)] RenderFrame failed. There may not be any calls to OnFrameRendered or OnFramePresented, and no callbacks may be invoked. [ OK ] HardKeyboardDeliveryTest.Test (2 ms) [----------] 1 test from HardKeyboardDeliveryTest (2 ms total) [----------] 2 tests from MouseDeliveryTest [ RUN ] MouseDeliveryTest.StandardTest TEST_LOOP_RANDOM_SEED="1532077877" [INFO:gfx_system.cc(196)] No Vulkan found, but using a test-only "display". [INFO:input_system.cc(203)] Scenic input system initialized. [ERROR:garnet/lib/ui/input/input_system.cc(200)] Scenic lost connection to TextSync [INFO:default_frame_scheduler.cc(237)] ScheduleUpdateForSession session_id: 1 presentation_time: 0 [INFO:default_frame_scheduler.cc(115)] RequestFrame [INFO:default_frame_scheduler.cc(148)] MaybeRenderFrame presentation_time=3540083404135 wakeup_time=3540075404135 frame_number=0 [INFO:default_frame_scheduler.cc(250)] ApplyScheduledSessionUpdates presentation_time=3540083404135 frame_number=0 [INFO:default_frame_scheduler.cc(189)] Calling RenderFrame presentation_time=3540083404135 frame_number=0 [WARNING:garnet/lib/ui/gfx/engine/default_frame_scheduler.cc(216)] RenderFrame failed. There may not be any calls to OnFrameRendered or OnFramePresented, and no callbacks may be invoked. [INFO:default_frame_scheduler.cc(237)] ScheduleUpdateForSession session_id: 2 presentation_time: 0 [INFO:default_frame_scheduler.cc(115)] RequestFrame [INFO:default_frame_scheduler.cc(148)] MaybeRenderFrame presentation_time=3540100070802 wakeup_time=3540092070802 frame_number=1 [INFO:default_frame_scheduler.cc(250)] ApplyScheduledSessionUpdates presentation_time=3540100070802 frame_number=1 [INFO:default_frame_scheduler.cc(189)] Calling RenderFrame presentation_time=3540100070802 frame_number=1 [WARNING:garnet/lib/ui/gfx/engine/default_frame_scheduler.cc(216)] RenderFrame failed. There may not be any calls to OnFrameRendered or OnFramePresented, and no callbacks may be invoked. [INFO:default_frame_scheduler.cc(237)] ScheduleUpdateForSession session_id: 3 presentation_time: 0 [INFO:default_frame_scheduler.cc(115)] RequestFrame [INFO:default_frame_scheduler.cc(148)] MaybeRenderFrame presentation_time=3540116737469 wakeup_time=3540108737469 frame_number=2 [INFO:default_frame_scheduler.cc(250)] ApplyScheduledSessionUpdates presentation_time=3540116737469 frame_number=2 [INFO:default_frame_scheduler.cc(189)] Calling RenderFrame presentation_time=3540116737469 frame_number=2 [WARNING:garnet/lib/ui/gfx/engine/default_frame_scheduler.cc(216)] RenderFrame failed. There may not be any calls to OnFrameRendered or OnFramePresented, and no callbacks may be invoked. [ OK ] MouseDeliveryTest.StandardTest (1 ms) [ RUN ] MouseDeliveryTest.NoFocusTest TEST_LOOP_RANDOM_SEED="2734249841" [INFO:gfx_system.cc(196)] No Vulkan found, but using a test-only "display". [INFO:input_system.cc(203)] Scenic input system initialized. [ERROR:garnet/lib/ui/input/input_system.cc(200)] Scenic lost connection to TextSync [INFO:default_frame_scheduler.cc(237)] ScheduleUpdateForSession session_id: 1 presentation_time: 0 [INFO:default_frame_scheduler.cc(115)] RequestFrame [INFO:default_frame_scheduler.cc(148)] MaybeRenderFrame presentation_time=3540083404135 wakeup_time=3540075404135 frame_number=0 [INFO:default_frame_scheduler.cc(250)] ApplyScheduledSessionUpdates presentation_time=3540083404135 frame_number=0 [INFO:default_frame_scheduler.cc(189)] Calling RenderFrame presentation_time=3540083404135 frame_number=0 [WARNING:garnet/lib/ui/gfx/engine/default_frame_scheduler.cc(216)] RenderFrame failed. There may not be any calls to OnFrameRendered or OnFramePresented, and no callbacks may be invoked. [INFO:default_frame_scheduler.cc(237)] ScheduleUpdateForSession session_id: 2 presentation_time: 0 [INFO:default_frame_scheduler.cc(115)] RequestFrame [INFO:default_frame_scheduler.cc(148)] MaybeRenderFrame presentation_time=3540100070802 wakeup_time=3540092070802 frame_number=1 [INFO:default_frame_scheduler.cc(250)] ApplyScheduledSessionUpdates presentation_time=3540100070802 frame_number=1 [INFO:default_frame_scheduler.cc(189)] Calling RenderFrame presentation_time=3540100070802 frame_number=1 [WARNING:garnet/lib/ui/gfx/engine/default_frame_scheduler.cc(216)] RenderFrame failed. There may not be any calls to OnFrameRendered or OnFramePresented, and no callbacks may be invoked. [INFO:default_frame_scheduler.cc(237)] ScheduleUpdateForSession session_id: 3 presentation_time: 0 [INFO:default_frame_scheduler.cc(115)] RequestFrame [INFO:default_frame_scheduler.cc(148)] MaybeRenderFrame presentation_time=3540116737469 wakeup_time=3540108737469 frame_number=2 [INFO:default_frame_scheduler.cc(250)] ApplyScheduledSessionUpdates presentation_time=3540116737469 frame_number=2 [INFO:default_frame_scheduler.cc(189)] Calling RenderFrame presentation_time=3540116737469 frame_number=2 [WARNING:garnet/lib/ui/gfx/engine/default_frame_scheduler.cc(216)] RenderFrame failed. There may not be any calls to OnFrameRendered or OnFramePresented, and no callbacks may be invoked. [ OK ] MouseDeliveryTest.NoFocusTest (2 ms) [----------] 2 tests from MouseDeliveryTest (3 ms total) [----------] Global test environment tear-down [==========] 5 tests from 4 test suites ran. (7 ms total) [ PASSED ] 5 tests. PASSED: /pkgfs/packages/scenic_tests/0/test/input_unittests passed SUMMARY: Ran 1 tests: 0 failed (0.105 sec) ok 9 //garnet/bin/ui:input_unittests (1.325446955s) [03540.060] 05791.05805> [WARNING:garnet/bin/appmgr/service_provider_dir_impl.cc(127)] Component fuchsia-pkg://fuchsia.com/scenic_tests#meta/input_unittests.cmx is not allowed to connect to fuchsia.sysmem.Allocator because this service is not presen [03540.060] 05791.05805> t in the component's sandbox. [03540.060] 05791.05805> Refer to https://fuchsia.googlesource.com/fuchsia/+/master/docs/the-book/sandboxing.md#services for more information. [03540.062] 05791.05805> [WARNING:garnet/bin/appmgr/service_provider_dir_impl.cc(127)] Component fuchsia-pkg://fuchsia.com/scenic_tests#meta/input_unittests.cmx is not allowed to connect to fuchsia.sysmem.Allocator because this service is not presen [03540.062] 05791.05805> t in the component's sandbox. [03540.062] 05791.05805> Refer to https://fuchsia.googlesource.com/fuchsia/+/master/docs/the-book/sandboxing.md#services for more information. [03540.063] 05791.05805> [WARNING:garnet/bin/appmgr/service_provider_dir_impl.cc(127)] Component fuchsia-pkg://fuchsia.com/scenic_tests#meta/input_unittests.cmx is not allowed to connect to fuchsia.sysmem.Allocator because this service is not presen [03540.063] 05791.05805> t in the component's sandbox. [03540.063] 05791.05805> Refer to https://fuchsia.googlesource.com/fuchsia/+/master/docs/the-book/sandboxing.md#services for more information. [03540.064] 05791.05805> [WARNING:garnet/bin/appmgr/service_provider_dir_impl.cc(127)] Component fuchsia-pkg://fuchsia.com/scenic_tests#meta/input_unittests.cmx is not allowed to connect to fuchsia.sysmem.Allocator because this service is not presen [03540.064] 05791.05805> t in the component's sandbox. [03540.064] 05791.05805> Refer to https://fuchsia.googlesource.com/fuchsia/+/master/docs/the-book/sandboxing.md#services for more information. [03540.065] 05791.05805> [WARNING:garnet/bin/appmgr/service_provider_dir_impl.cc(127)] Component fuchsia-pkg://fuchsia.com/scenic_tests#meta/input_unittests.cmx is not allowed to connect to fuchsia.sysmem.Allocator because this service is not presen [03540.065] 05791.05805> t in the component's sandbox. [03540.065] 05791.05805> Refer to https://fuchsia.googlesource.com/fuchsia/+/master/docs/the-book/sandboxing.md#services for more information. ------------------------------------------------ RUNNING TEST: /pkgfs/packages/scenic_tests/0/test/input_tool_unittests Running main() from ../../third_party/googletest/googletest/src/gtest_main.cc [==========] Running 5 tests from 1 test suite. [----------] Global test environment set-up. [----------] 5 tests from InverseKeymapTest [ RUN ] InverseKeymapTest.PlainKey [ OK ] InverseKeymapTest.PlainKey (0 ms) [ RUN ] InverseKeymapTest.ShiftKey [ OK ] InverseKeymapTest.ShiftKey (0 ms) [ RUN ] InverseKeymapTest.Lowercase [ OK ] InverseKeymapTest.Lowercase (0 ms) [ RUN ] InverseKeymapTest.Sentence [ OK ] InverseKeymapTest.Sentence (0 ms) [ RUN ] InverseKeymapTest.HoldShift [ OK ] InverseKeymapTest.HoldShift (0 ms) [----------] 5 tests from InverseKeymapTest (0 ms total) [----------] Global test environment tear-down [==========] 5 tests from 1 test suite ran. (0 ms total) [ PASSED ] 5 tests. PASSED: /pkgfs/packages/scenic_tests/0/test/input_tool_unittests passed SUMMARY: Ran 1 tests: 0 failed (0.059 sec) ok 10 //garnet/bin/ui:input_tool_unittests (1.290471865s) ------------------------------------------------ RUNNING TEST: /pkgfs/packages/scenic_tests/0/test/presentation_mode_unittests Running main() from ../../third_party/googletest/googletest/src/gtest_main.cc [==========] Running 7 tests from 3 test suites. [----------] Global test environment set-up. [----------] 1 test from PositiveData [ RUN ] PositiveData.MovingAverage [ OK ] PositiveData.MovingAverage (0 ms) [----------] 1 test from PositiveData (0 ms total) [----------] 1 test from NegativeData [ RUN ] NegativeData.MovingAverage [ OK ] NegativeData.MovingAverage (0 ms) [----------] 1 test from NegativeData (0 ms total) [----------] 5 tests from Detector [ RUN ] Detector.Closed [ OK ] Detector.Closed (0 ms) [ RUN ] Detector.Laptop [ OK ] Detector.Laptop (0 ms) [ RUN ] Detector.Tablet [ OK ] Detector.Tablet (0 ms) [ RUN ] Detector.Tent [ OK ] Detector.Tent (0 ms) [ RUN ] Detector.NonAccelerometer [ OK ] Detector.NonAccelerometer (0 ms) [----------] 5 tests from Detector (0 ms total) [----------] Global test environment tear-down [==========] 7 tests from 3 test suites ran. (0 ms total) [ PASSED ] 7 tests. PASSED: /pkgfs/packages/scenic_tests/0/test/presentation_mode_unittests passed SUMMARY: Ran 1 tests: 0 failed (0.058 sec) ok 11 //garnet/bin/ui:presentation_mode_unittests (1.282343297s) ------------------------------------------------ RUNNING TEST: /pkgfs/packages/scenic_tests/0/test/root_presenter_unittests Running main() from ../../third_party/googletest/googletest/src/gtest_main.cc [==========] Running 4 tests from 1 test suite. [----------] Global test environment set-up. [----------] 4 tests from DisplayConfiguration [ RUN ] DisplayConfiguration.Basic_2160x1440 [INFO:display_configuration.cc(62)] RootPresenter: treating device as an Acer Switch 12 Alpha. [ OK ] DisplayConfiguration.Basic_2160x1440 (0 ms) [ RUN ] DisplayConfiguration.Basic_2400x1600 [INFO:display_configuration.cc(67)] RootPresenter: treating device as a Google Pixelbook. [ OK ] DisplayConfiguration.Basic_2400x1600 (0 ms) [ RUN ] DisplayConfiguration.Basic_3840x2160 [INFO:display_configuration.cc(71)] RootPresenter: treating display as a 24in 4K monitor. [ OK ] DisplayConfiguration.Basic_3840x2160 (0 ms) [ RUN ] DisplayConfiguration.Basic_1920x1200 [INFO:display_configuration.cc(75)] RootPresenter: treating display as a 24in monitor. [ OK ] DisplayConfiguration.Basic_1920x1200 (0 ms) [----------] 4 tests from DisplayConfiguration (0 ms total) [----------] Global test environment tear-down [==========] 4 tests from 1 test suite ran. (0 ms total) [ PASSED ] 4 tests. PASSED: /pkgfs/packages/scenic_tests/0/test/root_presenter_unittests passed SUMMARY: Ran 1 tests: 0 failed (0.049 sec) ok 12 //garnet/bin/ui:root_presenter_unittests (1.279468711s) ------------------------------------------------ RUNNING TEST: /pkgfs/packages/scenic_tests/0/test/scenic_unittests Running main() from ../../third_party/googletest/googletest/src/gtest_main.cc [==========] Running 2 tests from 2 test suites. [----------] Global test environment set-up. [----------] 1 test from ScenicTest [ RUN ] ScenicTest.SessionCreatedAfterAllSystemsInitialized TEST_LOOP_RANDOM_SEED="2133011931" [ OK ] ScenicTest.SessionCreatedAfterAllSystemsInitialized (0 ms) [----------] 1 test from ScenicTest (0 ms total) [----------] 1 test from ScenicGfxTest [ RUN ] ScenicGfxTest.InvalidPresentCall_ShouldDestroySession TEST_LOOP_RANDOM_SEED="2177237865" [INFO:gfx_system.cc(196)] No Vulkan found, but using a test-only "display". [INFO:default_frame_scheduler.cc(237)] ScheduleUpdateForSession session_id: 1 presentation_time: 10 [INFO:default_frame_scheduler.cc(115)] RequestFrame [ERROR:garnet/lib/ui/scenic/session.cc(159)] scenic_impl::gfx::Session: Present called with out-of-order presentation time. requested presentation time=0, last scheduled presentation time=10. Session error: scenic_impl::gfx::Session: Present called with out-of-order presentation time. requested presentation time=0, last scheduled presentation time=10.[ OK ] ScenicGfxTest.InvalidPresentCall_ShouldDestroySession (1 ms) [----------] 1 test from ScenicGfxTest (1 ms total) [----------] Global test environment tear-down [==========] 2 tests from 2 test suites ran. (1 ms total) [ PASSED ] 2 tests. PASSED: /pkgfs/packages/scenic_tests/0/test/scenic_unittests passed SUMMARY: Ran 1 tests: 0 failed (0.077 sec) ok 13 //garnet/bin/ui:scenic_unittests (1.294236311s) [03545.218] 05791.05805> [WARNING:garnet/bin/appmgr/service_provider_dir_impl.cc(127)] Component fuchsia-pkg://fuchsia.com/scenic_tests#meta/scenic_unittests.cmx is not allowed to connect to fuchsia.sysmem.Allocator because this service is not prese [03545.218] 05791.05805> nt in the component's sandbox. [03545.218] 05791.05805> Refer to https://fuchsia.googlesource.com/fuchsia/+/master/docs/the-book/sandboxing.md#services for more information. ------------------------------------------------ RUNNING TEST: /pkgfs/packages/default_hardware_ime_tests/0/test/default_hardware_ime_unittests running 1 test test tests::state_sends_edits_on_input_and_retries ... ok test result: ok. 1 passed; 0 failed; 0 ignored; 0 measured; 0 filtered out PASSED: /pkgfs/packages/default_hardware_ime_tests/0/test/default_hardware_ime_unittests passed SUMMARY: Ran 1 tests: 0 failed (0.048 sec) ok 14 //garnet/bin/ui/text/default_hardware_ime:default_hardware_ime_bin_test (1.276358066s) ------------------------------------------------ RUNNING TEST: /pkgfs/packages/shortcut_test/0/test/shortcut_bin_test DEBUG: stopping or rebooting the node "upper-stoop-folk-grape" [03740.567] 07997.08260> [03740.567866][1230184835][0][netstack] INFO: socket_conv.go(523): unimplemented setsockopt: SOL_IPV6 name=67 optVal=20000000 [03740.567] 233782.233794> setsockopt IPV6_TCLASS 32: Protocol not available: