Search Unity

  1. Welcome to the Unity Forums! Please take the time to read our Code of Conduct to familiarize yourself with the forum rules and how to post constructively.
  2. Unite 2023 Registrations are now LIVE! We are thrilled to announce that Unite 2023 Registration is now live and open for all!
    Dismiss Notice
New Forum User Notice Unite 2023 Registrations are now LIVE!

Bug Disabling Quest Passthrough at runtime leads to Freezes

Discussion in 'VR' started by rwblodgett, Jul 22, 2022.

  1. rwblodgett

    rwblodgett

    Joined:
    Apr 4, 2017
    Posts:
    66
    I thought this was working in our application, but then I noticed this freeze happening sometimes. If I enable passthrough, and disable passthrough, enough times in the same session of our app, the app will freeze when disabling the passthrough at some point. Some times it happens on the first time, and sometimes it happens on the seventh time, etc. But no matter how many times it happens, they are unacceptably too many times. I notice in logcat there is this error: "MR_PT: pause failed with error code: -5" but I don't know if it's related. I'm also seeing tons of these messages: "MIXEDREALITY: MrServiceView: renderIteration: onPause(). (b)" which makes me think it is pausing correctly, but Unity is just not rendering properly afterword, and is caught up in a deadlock.

    I am enabling the passthrough by calling this:

    OVRManager.instance.isInsightPassthroughEnabled = true;

    I am disabling the passthrough by calling this:

    OVRManager.instance.isInsightPassthroughEnabled = false;

    Any help or workarounds to turn off the passthrough camera at runtime? I have also tried hiding the layer in conjunction with the above command, but doesn't seem to change anything.

    Here is more of the logcat:

    Code (CSharp):
    1. 7 8638-8638/? D/wifitelemetry: Will use the default report interval
    2. 2022-07-22 10:11:22.917 8638-8638/? I/wifitelemetry: Property ro.build.fingerprint = oculus/hollywood/hollywood:10/QQ3A.200805.001/35444700575000000:user/release-keys
    3. 2022-07-22 10:11:22.917 8638-8638/? I/wifitelemetry: Property ro.product.device = hollywood
    4. 2022-07-22 10:11:22.918 8638-8638/? I/wifitelemetry: Report rate is set to 30
    5. 2022-07-22 10:11:22.924 18097-19552/? E/AppOps: startOperation
    6.     java.lang.SecurityException: Specified package wifitelemetry under uid 1000 but it is really -1
    7.         at com.android.server.appop.AppOpsService.verifyAndGetIsPrivileged(AppOpsService.java:2654)
    8.         at com.android.server.appop.AppOpsService.startOperation(AppOpsService.java:2235)
    9.         at android.app.AppOpsManager.startOpNoThrow(AppOpsManager.java:5469)
    10.         at android.app.AppOpsManager.startOpNoThrow(AppOpsManager.java:5450)
    11.         at com.android.server.power.Notifier.onWakeLockAcquired(Notifier.java:224)
    12.         at com.android.server.power.PowerManagerService.notifyWakeLockAcquiredLocked(PowerManagerService.java:1270)
    13.         at com.android.server.power.PowerManagerService.acquireWakeLockInternal(PowerManagerService.java:1105)
    14.         at com.android.server.power.PowerManagerService.access$3900(PowerManagerService.java:116)
    15.         at com.android.server.power.PowerManagerService$BinderService.acquireWakeLock(PowerManagerService.java:4333)
    16.         at android.os.IPowerManager$Stub.onTransact(IPowerManager.java:349)
    17.         at android.os.Binder.execTransactInternal(Binder.java:1021)
    18.         at android.os.Binder.execTransact(Binder.java:994)
    19. 2022-07-22 10:11:22.924 8638-8638/? I/wifitelemetry: report() is invoked
    20. 2022-07-22 10:11:22.931 8638-8638/? I/wifitelemetry: Entering: getStation
    21. 2022-07-22 10:11:22.932 8638-8638/? I/wifitelemetry: Entering: getPowerManagement
    22. 2022-07-22 10:11:22.932 8638-8638/? I/wifitelemetry: Entering: getChannelSurvey
    23. 2022-07-22 10:11:22.932 8638-8638/? D/wifitelemetry: powerSaveEnabled = 1, gotPowerSaveSettings = 1
    24. 2022-07-22 10:11:22.932 8638-8638/? I/wifitelemetry: Entering: triggerScan
    25. 2022-07-22 10:11:23.376 18037-18050/? D/audio_hw_primary: out_standby: enter: stream (0xef239000) usecase(1: low-latency-playback)
    26. 2022-07-22 10:11:23.403 18037-18050/? I/audio_hw_primary: disable_audio_route: reset and update mixer path: low-latency-playback
    27. 2022-07-22 10:11:23.404 18037-18050/? D/msm8974_platform: platform_split_snd_device: snd_device(2) num devices(0) new_snd_devices(0)
    28. 2022-07-22 10:11:23.404 18037-18050/? I/msm8974_platform: platform_get_custom_mtmx_params: no matching param with id 0 ip_ch 2 op_ch 2 uc_id 1 snd_dev 2
    29. 2022-07-22 10:11:23.404 18037-18050/? D/hardware_info: hw_info_append_hw_type : device_name = speaker
    30. 2022-07-22 10:11:23.404 18037-18050/? D/audio_hw_primary: disable_snd_device: snd_device(2: speaker)
    31. 2022-07-22 10:11:23.404 18037-18050/? D/msm8974_platform: platform_split_snd_device: snd_device(2) num devices(0) new_snd_devices(0)
    32. 2022-07-22 10:11:23.410 18037-18050/? D/audio_hw_primary: out_standby: exit
    33. 2022-07-22 10:11:24.423 18548-18870/? D/DeviceCertLibrary: verifyKeyForCurrentSecureState for device_registration_key returned status: 0
    34. 2022-07-22 10:11:24.423 18548-18870/? D/DeviceCertLibrary: containsAlias for device_registration_key received status: 0
    35. 2022-07-22 10:11:26.229 8638-8638/? I/wifitelemetry: Event 34
    36. 2022-07-22 10:11:26.229 8638-8638/? I/wifitelemetry: Entering: getCurrentScan
    37. 2022-07-22 10:11:26.231 18036-18036/? I/wificond: Received external scan result notification from kernel.
    38. 2022-07-22 10:11:26.231 18097-18407/? D/WificondControl: Scan result ready event
    39. 2022-07-22 10:11:26.231 8638-8638/? E/wifitelemetry: netlink connection failed
    40. 2022-07-22 10:11:26.235 8638-8638/? I/wifitelemetry: Connected to the WiFi HAL
    41. 2022-07-22 10:11:26.347 8638-8638/? I/wifitelemetry: TelemetryConnector has been initialized
    42. 2022-07-22 10:11:26.348 536-536/? E/SELinux: avc:  denied  { find } for service=GatekeeperService pid=8638 uid=1000 scontext=u:r:wifitelemetry:s0 tcontext=u:object_r:ovr_gatekeeper_service:s0 tclass=service_manager permissive=0
    43. 2022-07-22 10:11:26.348 8638-8641/? E/GatekeeperClient: Failed to connect to GatekeeperService.
    44. 2022-07-22 10:11:26.350 8638-8638/? D/wifitelemetry: Recorded the telemetry event
    45. 2022-07-22 10:11:26.351 18097-18407/? E/AppOps: Cannot finishOperation
    46.     java.lang.SecurityException: Specified package wifitelemetry under uid 1000 but it is really -1
    47.         at com.android.server.appop.AppOpsService.verifyAndGetIsPrivileged(AppOpsService.java:2654)
    48.         at com.android.server.appop.AppOpsService.finishOperation(AppOpsService.java:2329)
    49.         at android.app.AppOpsManager.finishOp(AppOpsManager.java:5485)
    50.         at com.android.server.power.Notifier.onWakeLockReleased(Notifier.java:334)
    51.         at com.android.server.power.PowerManagerService.notifyWakeLockReleasedLocked(PowerManagerService.java:1327)
    52.         at com.android.server.power.PowerManagerService.removeWakeLockLocked(PowerManagerService.java:1211)
    53.         at com.android.server.power.PowerManagerService.releaseWakeLockInternal(PowerManagerService.java:1183)
    54.         at com.android.server.power.PowerManagerService.access$4000(PowerManagerService.java:116)
    55.         at com.android.server.power.PowerManagerService$BinderService.releaseWakeLock(PowerManagerService.java:4349)
    56.         at android.os.IPowerManager$Stub.onTransact(IPowerManager.java:377)
    57.         at android.os.Binder.execTransactInternal(Binder.java:1021)
    58.         at android.os.Binder.execTransact(Binder.java:994)
    59. 2022-07-22 10:11:26.351 8638-8638/? W/OsSdk: Events discarded = 0
    60. 2022-07-22 10:11:27.156 18594-19976/? I/[CT]: MIXEDREALITY: MrServiceView: renderIteration: (every 10 seconds), screen is: OFF, PT is: OFF, ID is: OFF
    61. 2022-07-22 10:11:27.156 18594-19976/? I/[CT]: MIXEDREALITY: MrServiceModel: commitLayerState: (every 10 seconds), ImagesAndCompute: false, ImagesOnly: false, NoRequirement: true.
    62. 2022-07-22 10:11:28.012 18594-20099/? I/Telemetry: App memory usage: PSS=33MB DalvikPSS=12 MB PrivateDirty=26MB PrivateClean=1MB
    63. 2022-07-22 10:11:29.022 18752-20368/? I/Telemetry: App memory usage: PSS=39MB DalvikPSS=2 MB PrivateDirty=28MB PrivateClean=5MB
    64. 2022-07-22 10:11:29.612 18035-18070/? I/netd: firewallSetUidRule(2, 10018, 2) <0.08ms>
    65. 2022-07-22 10:11:29.613 18035-18070/? I/netd: firewallSetUidRule(2, 1010018, 2) <0.05ms>
    66. 2022-07-22 10:11:35.125 18097-18126/? I/UsageStatsService: User[0] Flushing usage stats to disk
    67. 2022-07-22 10:11:35.151 18097-18126/? W/AppIdleHistory: Skipping App Idle write for unexpected null package
    68. 2022-07-22 10:11:35.153 18097-18126/? I/UsageStatsService: User[10] Flushing usage stats to disk
    69. 2022-07-22 10:11:35.167 18097-18126/? W/AppIdleHistory: Skipping App Idle write for unexpected null package
    70. 2022-07-22 10:11:36.441 18035-18070/? I/netd: firewallSetUidRule(2, 10018, 1) <0.05ms>
    71. 2022-07-22 10:11:36.901 18035-18070/? I/netd: firewallSetUidRule(2, 10018, 2) <0.03ms>
    72. 2022-07-22 10:11:37.169 18594-19976/? I/[CT]: MIXEDREALITY: MrServiceView: renderIteration: (every 10 seconds), screen is: OFF, PT is: OFF, ID is: OFF
    73. 2022-07-22 10:11:37.169 18594-19976/? I/[CT]: MIXEDREALITY: MrServiceModel: commitLayerState: (every 10 seconds), ImagesAndCompute: false, ImagesOnly: false, NoRequirement: true.
    74. 2022-07-22 10:11:38.116 18097-18407/? W/ActivityManager: Package for pid 850: no process record found
    75. 2022-07-22 10:11:47.176 18594-19976/? I/[CT]: MIXEDREALITY: MrServiceView: renderIteration: (every 10 seconds), screen is: OFF, PT is: OFF, ID is: OFF
    76. 2022-07-22 10:11:47.176 18594-19976/? I/[CT]: MIXEDREALITY: MrServiceModel: commitLayerState: (every 10 seconds), ImagesAndCompute: false, ImagesOnly: false, NoRequirement: true.
    77. 2022-07-22 10:11:48.025 18594-20099/? I/Telemetry: App memory usage: PSS=33MB DalvikPSS=12 MB PrivateDirty=26MB PrivateClean=1MB
    78. 2022-07-22 10:11:49.021 18752-20368/? I/Telemetry: App memory usage: PSS=39MB DalvikPSS=2 MB PrivateDirty=28MB PrivateClean=5MB
    79. 2022-07-22 10:11:57.184 18594-19976/? I/[CT]: MIXEDREALITY: MrServiceView: renderIteration: (every 10 seconds), screen is: OFF, PT is: OFF, ID is: OFF
    80. 2022-07-22 10:11:57.184 18594-19976/? I/[CT]: MIXEDREALITY: MrServiceModel: commitLayerState: (every 10 seconds), ImagesAndCompute: false, ImagesOnly: false, NoRequirement: true.
    81. 2022-07-22 10:12:03.480 31716-31716/? D/[OAO] LowStorageNotificationScheduler: Storage Checks: Internal Free (50830729216)
    82. 2022-07-22 10:12:05.013 31879-1295/? W/msys: W[S sync-state-machine]MCDSyncStateMachineScheduleDelayedRetry(172)=>skipping the new retry with longer delay
    83. 2022-07-22 10:12:05.013 31879-1295/? W/msys: W[S sync]_scheduleNextCursorRetry(394)=>skipping delayed retry due to state machine state decision
    84. 2022-07-22 10:12:07.192 18594-19976/? I/[CT]: MIXEDREALITY: MrServiceView: renderIteration: (every 10 seconds), screen is: OFF, PT is: OFF, ID is: OFF
    85. 2022-07-22 10:12:07.192 18594-19976/? I/[CT]: MIXEDREALITY: MrServiceModel: commitLayerState: (every 10 seconds), ImagesAndCompute: false, ImagesOnly: false, NoRequirement: true.
    86. 2022-07-22 10:12:08.028 18594-20099/? I/Telemetry: App memory usage: PSS=33MB DalvikPSS=12 MB PrivateDirty=26MB PrivateClean=1MB
    87. 2022-07-22 10:12:08.982 18594-18620/? W/culus.mrservic: Reducing the number of considered missed Gc histogram windows from 225 to 100
    88. 2022-07-22 10:12:09.021 18752-20368/? I/Telemetry: App memory usage: PSS=39MB DalvikPSS=2 MB PrivateDirty=28MB PrivateClean=5MB
    89. 2022-07-22 10:12:14.772 1484-1742/? W/msys: W[S sync-state-machine]MCDSyncStateMachineScheduleDelayedRetry(172)=>skipping the new retry with longer delay
    90. 2022-07-22 10:12:14.772 1484-1742/? W/msys: W[S sync]_scheduleNextCursorRetry(394)=>skipping delayed retry due to state machine state decision
    91. 2022-07-22 10:12:17.200 18594-19976/? I/[CT]: MIXEDREALITY: MrServiceView: renderIteration: (every 10 seconds), screen is: OFF, PT is: OFF, ID is: OFF
    92. 2022-07-22 10:12:17.200 18594-19976/? I/[CT]: MIXEDREALITY: MrServiceModel: commitLayerState: (every 10 seconds), ImagesAndCompute: false, ImagesOnly: false, NoRequirement: true.
    93. 2022-07-22 10:12:27.212 18594-19976/? I/[CT]: MIXEDREALITY: MrServiceView: renderIteration: (every 10 seconds), screen is: OFF, PT is: OFF, ID is: OFF
    94. 2022-07-22 10:12:27.212 18594-19976/? I/[CT]: MIXEDREALITY: MrServiceModel: commitLayerState: (every 10 seconds), ImagesAndCompute: false, ImagesOnly: false, NoRequirement: true.
    95. 2022-07-22 10:12:28.028 18594-20099/? I/Telemetry: App memory usage: PSS=20MB DalvikPSS=1 MB PrivateDirty=13MB PrivateClean=1MB
    96. 2022-07-22 10:12:29.036 18752-20368/? I/Telemetry: App memory usage: PSS=39MB DalvikPSS=2 MB PrivateDirty=28MB PrivateClean=5MB
    97. 2022-07-22 10:12:29.609 18097-18127/? W/ActivityManager: Stopping service due to app idle: u0a18 -1m9s997ms com.oculus.appsafety/.AppSafetyService
    98. 2022-07-22 10:12:29.610 2748-2748/? D/AppSafetyService: Service stopping
    99. 2022-07-22 10:12:29.612 18097-551/? I/ActivityManager: Killing 2601:com.android.permissioncontroller/u0a12 (adj 995): empty #17
    100. 2022-07-22 10:12:29.612 18097-551/? I/ActivityManager: Killing 2552:com.oculus.identitymanagement.service/u0a32 (adj 995): empty #18
    101. 2022-07-22 10:12:29.615 18035-18070/? I/netd: firewallSetUidRule(2, 10032, 1) <0.02ms>
    102. 2022-07-22 10:12:29.615 18035-18070/? I/netd: firewallSetUidRule(2, 10018, 1) <0.02ms>
    103. 2022-07-22 10:12:29.634 18031-18031/? I/Zygote: Process 2601 exited due to signal 9 (Killed)
    104. 2022-07-22 10:12:29.634 18031-18031/? I/Zygote: Process 2552 exited due to signal 9 (Killed)
    105. 2022-07-22 10:12:29.635 18097-18407/? W/ActivityManager: Scheduling restart of crashed service com.oculus.identitymanagement.service/.job.IdentityManagementJobService in 1000ms
    106. 2022-07-22 10:12:29.643 18097-18129/? I/libprocessgroup: Successfully killed process cgroup uid 10012 pid 2601 in 29ms
    107. 2022-07-22 10:12:29.643 18097-18129/? I/libprocessgroup: Successfully killed process cgroup uid 10032 pid 2552 in 0ms
    108. 2022-07-22 10:12:30.026 18035-18070/? I/netd: firewallSetUidRule(2, 10018, 2) <0.03ms>
    109. 2022-07-22 10:12:30.655 18031-18031/? D/Zygote: Forked child process 8658
    110. 2022-07-22 10:12:30.657 18097-18128/? I/ActivityManager: Start proc 8658:com.oculus.identitymanagement.service/u0a32 for service {com.oculus.identitymanagement.service/com.oculus.identitymanagement.service.job.IdentityManagementJobService}
    111. 2022-07-22 10:12:30.668 8658-8658/? E/agement.servic: Not starting debugger since process cannot load the jdwp agent.
    112. 2022-07-22 10:12:30.698 8658-8658/? D/ApplicationLoaders: Returning zygote-cached class loader: /system/framework/android.hidl.base-V1.0-java.jar
    113. 2022-07-22 10:12:30.698 8658-8658/? D/ApplicationLoaders: Returning zygote-cached class loader: /system/framework/android.hidl.manager-V1.0-java.jar
    114. 2022-07-22 10:12:30.698 8658-8658/? D/ApplicationLoaders: Returning zygote-cached class loader: /system/framework/android.hidl.base-V1.0-java.jar
    115. 2022-07-22 10:12:30.700 8658-8658/? I/agement.servic: The ClassLoaderContext is a special shared library.
    116. 2022-07-22 10:12:30.715 8658-8658/? D/CapabilitiesDatabase: Build Capabilities Database
    117. 2022-07-22 10:12:30.727 8658-8658/? D/IdentityManagementJobService: onStartJob - starting async IMS jobs
    118. 2022-07-22 10:12:30.728 8658-8678/? D/IdentityManagementAsyncTask: doInBackground - working on IMS async tasks
    119. 2022-07-22 10:12:30.739 8658-8678/? D/UnifiedTelemetryLogger: UnifiedTelemetryLogger instance created
    120. 2022-07-22 10:12:30.739 8658-8678/? D/UnifiedTelemetryLogger: binding with UnifiedTelemetryService
    121. 2022-07-22 10:12:30.751 8658-8683/? D/MobileConfigBaseClient: connect()
    122. 2022-07-22 10:12:30.757 18035-18070/? I/netd: firewallSetUidRule(2, 10032, 2) <0.03ms>
    123. 2022-07-22 10:12:30.761 8658-8683/? D/MobileConfigBaseClient: awaitService()
    124. 2022-07-22 10:12:30.765 18035-18070/? I/netd: firewallSetUidRule(2, 10032, 1) <0.02ms>
    125. 2022-07-22 10:12:30.765 8658-8658/? D/MobileConfigBaseClient: Connected to MobileConfigService
    126. 2022-07-22 10:12:30.766 18097-19552/? I/ActivityManager: Killing 6517:oculus.platform/1000 (adj 995): empty #17
    127. 2022-07-22 10:12:30.781 18097-18407/? D/ConnectivityService: requestNetwork for uid/pid:10032/8658 NetworkRequest [ TRACK_DEFAULT id=87, [ Capabilities: INTERNET&NOT_RESTRICTED&TRUSTED Uid: 10032] ]
    128. 2022-07-22 10:12:30.782 18031-18031/? I/Zygote: Process 6517 exited due to signal 9 (Killed)
    129. 2022-07-22 10:12:30.784 624-8686/? I/mobileconfig: Using asset manager to stream (unitType: kMobileConfigSessionless) params_map_v4_u0.txt
    130. 2022-07-22 10:12:30.785 624-8686/? I/mobileconfig: parsed v4 resource file for unittype: 1, config count: 31
    131. 2022-07-22 10:12:30.785 624-8686/? I/mobileconfig: Successfully parsed resource file for (unitType: kMobileConfigSessionless)
    132. 2022-07-22 10:12:30.788 18097-18240/? D/WIFI_AWARE_FACTORY: got request NetworkRequest [ TRACK_DEFAULT id=87, [ Capabilities: INTERNET&NOT_RESTRICTED&TRUSTED Uid: 10032] ] with score 60 and serial -1
    133. 2022-07-22 10:12:30.789 18097-18205/? D/WifiNetworkFactory: got request NetworkRequest [ TRACK_DEFAULT id=87, [ Capabilities: INTERNET&NOT_RESTRICTED&TRUSTED Uid: 10032] ] with score 60 and serial -1
    134. 2022-07-22 10:12:30.789 18097-18205/? D/UntrustedWifiNetworkFactory: got request NetworkRequest [ TRACK_DEFAULT id=87, [ Capabilities: INTERNET&NOT_RESTRICTED&TRUSTED Uid: 10032] ] with score 60 and serial -1
    135. 2022-07-22 10:12:30.789 18097-18241/? D/Ethernet: got request NetworkRequest [ TRACK_DEFAULT id=87, [ Capabilities: INTERNET&NOT_RESTRICTED&TRUSTED Uid: 10032] ] with score 60 and serial -1
    136. 2022-07-22 10:12:30.791 624-8686/? I/mobileconfig: Parsed params maps: success=20; skipped=21; duplicates=19
    137. 2022-07-22 10:12:30.792 624-8686/? I/mobileconfig: Read one query hash from asset, it is = 2de83e156160585bd0daf6bd5d3d07d20a874483417eda6163448e766574a581
    138. 2022-07-22 10:12:30.792 624-8686/? I/mobileconfig: Initialized MobileConfig - directory: /data/user/0/com.oculus.horizon/files, unitType:1, appVersion: 42.0.0.109.252, paramHash: 8327075ce06077028c24a0491218c303, readOnly: false bufferPathPostfix: 885
    139. 2022-07-22 10:12:30.806 8658-8690/? D/AccessTokenWorker: doWork fetch accesstoken
    140. 2022-07-22 10:12:30.808 8658-8691/? D/AccessTokenWorker: doWork fetch accesstoken
    141. 2022-07-22 10:12:30.809 624-8686/? I/mobileconfig: Using asset manager to stream (unitType: kMobileConfigSessionbased) params_map_v4_u0.txt
    142. 2022-07-22 10:12:30.809 18097-18129/? I/libprocessgroup: Successfully killed process cgroup uid 1000 pid 6517 in 41ms
    143. 2022-07-22 10:12:30.809 624-8686/? I/mobileconfig: parsed v4 resource file for unittype: 2, config count: 31
    144. 2022-07-22 10:12:30.810 624-8686/? I/mobileconfig: Successfully parsed resource file for (unitType: kMobileConfigSessionbased)
    145. 2022-07-22 10:12:30.816 624-8686/? I/mobileconfig: Parsed params maps: success=20; skipped=21; duplicates=19
    146. 2022-07-22 10:12:30.817 624-8686/? I/mobileconfig: Read one query hash from asset, it is = 2de83e156160585bd0daf6bd5d3d07d20a874483417eda6163448e766574a581
    147. 2022-07-22 10:12:30.817 624-8686/? I/mobileconfig: Initialized MobileConfig - directory: /data/user/0/com.oculus.horizon/files, unitType:2, appVersion: 42.0.0.109.252, paramHash: 8327075ce06077028c24a0491218c303, readOnly: false bufferPathPostfix: 843
    148. 2022-07-22 10:12:30.820 8658-8690/? D/WorkerLoggerHelper: log success for access_token_worker
    149. 2022-07-22 10:12:30.820 8658-8691/? D/WorkerLoggerHelper: log success for access_token_worker
    150. 2022-07-22 10:12:30.821 8658-8682/? I/WM-WorkerWrapper: Worker result SUCCESS for Work [ id=4347ab04-422a-4bf4-9da0-cac4ebf7d534, tags={ com.oculus.identitymanagement.service.workers.AccessTokenWorker } ]
    151. 2022-07-22 10:12:30.823 8658-8682/? I/WM-WorkerWrapper: Setting status to enqueued for 940c5dba-0869-409c-8dea-90cc97171343
    152. 2022-07-22 10:12:30.826 18035-18070/? I/netd: firewallSetUidRule(2, 10032, 2) <0.03ms>
    153. 2022-07-22 10:12:30.827 18097-18208/? D/ConnectivityService: Blocked status changed to true for 10032(87) on netId 101
    154. 2022-07-22 10:12:30.827 18035-18070/? I/netd: firewallSetUidRule(2, 10032, 1) <0.01ms>
    155. 2022-07-22 10:12:30.828 18097-18208/? D/ConnectivityService: Blocked status changed to false for 10032(87) on netId 101
    156. 2022-07-22 10:12:30.830 18035-18070/? I/netd: firewallSetUidRule(2, 10032, 2) <0.02ms>
    157. 2022-07-22 10:12:30.830 18097-18208/? D/ConnectivityService: Blocked status changed to true for 10032(87) on netId 101
    158. 2022-07-22 10:12:30.835 8658-8682/? I/WM-WorkerWrapper: Worker result SUCCESS for Work [ id=c1cc518e-5399-46c9-b1f3-6fa2228f14b4, tags={ com.oculus.identitymanagement.service.workers.AccessTokenWorker } ]
    159. 2022-07-22 10:12:30.836 8658-8682/? I/WM-WorkerWrapper: Setting status to enqueued for 587efc4a-27e7-4666-b0f0-78043f2283dc
    160. 2022-07-22 10:12:30.856 8658-8689/? D/MVanDatabase: Build ScreenTime Database
    161. 2022-07-22 10:12:30.867 18097-18208/? D/ConnectivityService: releasing NetworkRequest [ TRACK_DEFAULT id=87, [ Capabilities: INTERNET&NOT_RESTRICTED&TRUSTED Uid: 10032] ] (release request)
    162. 2022-07-22 10:12:30.870 8658-8658/? D/NetworkSecurityConfig: No Network Security Config specified, using platform default
    163. 2022-07-22 10:12:30.880 8658-8698/? D/MVanScreenTimeUploadWorker: doWork MVanScreenTimeUploadWorker
    164. 2022-07-22 10:12:30.887 8658-8698/? D/WorkerLoggerHelper: log success for mvan_screen_time_upload_worker
    165. 2022-07-22 10:12:30.888 8658-8689/? I/WM-WorkerWrapper: Worker result SUCCESS for Work [ id=587efc4a-27e7-4666-b0f0-78043f2283dc, tags={ com.oculus.identitymanagement.service.workers.MVanScreenTimeUploadWorker } ]
    166. 2022-07-22 10:12:31.806 18097-18097/? I/RoleManagerService: Granting default permissions...
    167. 2022-07-22 10:12:31.806 18097-18126/? W/Searchables: No global search activity found
    168. 2022-07-22 10:12:31.809 18097-18194/? I/InputReader: Reconfiguring input devices.  changes=0x00000010
    169. 2022-07-22 10:12:31.822 18031-18031/? D/Zygote: Forked child process 8706
    170. 2022-07-22 10:12:31.823 18097-18128/? I/ActivityManager: Start proc 8706:com.android.permissioncontroller/u0a12 for service {com.android.permissioncontroller/com.android.packageinstaller.role.service.RoleControllerServiceImpl}
    171. 2022-07-22 10:12:31.830 8706-8706/? E/ssioncontrolle: Not starting debugger since process cannot load the jdwp agent.
    172. 2022-07-22 10:12:31.886 8706-8706/? W/ExclusiveDefaultHolderMixin: Cannot get ApplicationInfo for default holder, config: config_defaultSms, package: com.android.messaging
    173. 2022-07-22 10:12:31.895 8706-8726/? W/ExclusiveDefaultHolderMixin: Cannot get ApplicationInfo for default holder, config: config_defaultSms, package: com.android.messaging
    174. 2022-07-22 10:12:32.122 18097-18126/? I/RoleUserState: Wrote roles.xml successfully
    175. 2022-07-22 10:12:37.220 18594-19976/? I/[CT]: MIXEDREALITY: MrServiceView: renderIteration: (every 10 seconds), screen is: OFF, PT is: OFF, ID is: OFF
    176. 2022-07-22 10:12:37.220 18594-19976/? I/[CT]: MIXEDREALITY: MrServiceModel: commitLayerState: (every 10 seconds), ImagesAndCompute: false, ImagesOnly: false, NoRequirement: true.
    177. 2022-07-22 10:12:40.889 8658-8697/? E/UserIdentityContextWorker: Request failed
    178.     java.net.SocketTimeoutException: failed to connect to graph.oculus.com/157.240.3.49 (port 443) from /10.8.46.16 (port 44498) after 10000ms
    179.         at libcore.io.IoBridge.connectErrno(IoBridge.java:191)
    180.         at libcore.io.IoBridge.connect(IoBridge.java:135)
    181.         at java.net.PlainSocketImpl.socketConnect(PlainSocketImpl.java:142)
    182.         at java.net.AbstractPlainSocketImpl.doConnect(AbstractPlainSocketImpl.java:390)
    183.         at java.net.AbstractPlainSocketImpl.connectToAddress(AbstractPlainSocketImpl.java:230)
    184.         at java.net.AbstractPlainSocketImpl.connect(AbstractPlainSocketImpl.java:212)
    185.         at java.net.SocksSocketImpl.connect(SocksSocketImpl.java:436)
    186.         at java.net.Socket.connect(Socket.java:621)
    187.         at okhttp3.internal.platform.AndroidPlatform.connectSocket(AndroidPlatform.java:68)
    188.         at okhttp3.internal.connection.RealConnection.connectSocket(RealConnection.java:220)
    189.         at okhttp3.internal.connection.RealConnection.connect(RealConnection.java:146)
    190.         at okhttp3.internal.connection.StreamAllocation.findConnection(StreamAllocation.java:186)
    191.         at okhttp3.internal.connection.StreamAllocation.findHealthyConnection(StreamAllocation.java:121)
    192.         at okhttp3.internal.connection.StreamAllocation.newStream(StreamAllocation.java:100)
    193.         at okhttp3.internal.connection.ConnectInterceptor.intercept(ConnectInterceptor.java:42)
    194.         at okhttp3.internal.http.RealInterceptorChain.proceed(RealInterceptorChain.java:92)
    195.         at okhttp3.internal.http.RealInterceptorChain.proceed(RealInterceptorChain.java:67)
    196.         at okhttp3.internal.cache.CacheInterceptor.intercept(CacheInterceptor.java:93)
    197.         at okhttp3.internal.http.RealInterceptorChain.proceed(RealInterceptorChain.java:92)
    198.         at okhttp3.internal.http.RealInterceptorChain.proceed(RealInterceptorChain.java:67)
    199.         at okhttp3.internal.http.BridgeInterceptor.intercept(BridgeInterceptor.java:93)
    200.         at okhttp3.internal.http.RealInterceptorChain.proceed(RealInterceptorChain.java:92)
    201.         at okhttp3.internal.http.RetryAndFollowUpInterceptor.intercept(RetryAndFollowUpInterceptor.java:120)
    202.         at okhttp3.internal.http.RealInterceptorChain.proceed(RealInterceptorChain.java:92)
    203.         at okhttp3.internal.http.RealInterceptorChain.proceed(RealInterceptorChain.java:67)
    204.         at okhttp3.RealCall$AsyncCall.execute(RealCall.java:2179)
    205.         at okhttp3.internal.NamedRunnable.run(NamedRunnable.java:32)
    206.         at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1167)
    207.         at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:641)
    208.         at java.lang.Thread.run(Thread.java:919)
    209. 2022-07-22 10:12:40.889 8658-8697/? D/WorkerLoggerHelper: log failure for user_identity_context_worker
    210. 2022-07-22 10:12:40.891 8658-8687/? I/WM-WorkerWrapper: Worker result FAILURE for Work [ id=940c5dba-0869-409c-8dea-90cc97171343, tags={ com.oculus.identitymanagement.service.workers.UserIdentityContextWorker } ]
    211. 2022-07-22 10:12:41.936 18097-18126/? W/Searchables: No global search activity found
    212. 2022-07-22 10:12:41.936 18097-18097/? I/RoleManagerService: Granting default permissions...
    213. 2022-07-22 10:12:41.938 18097-18194/? I/InputReader: Reconfiguring input devices.  changes=0x00000010
    214. 2022-07-22 10:12:41.940 8706-8726/? W/ExclusiveDefaultHolderMixin: Cannot get ApplicationInfo for default holder, config: config_defaultSms, package: com.android.messaging
    215. 2022-07-22 10:12:42.181 18097-18126/? I/RoleUserState: Wrote roles.xml successfully
    216. 2022-07-22 10:12:47.228 18594-19976/? I/[CT]: MIXEDREALITY: MrServiceView: renderIteration: (every 10 seconds), screen is: OFF, PT is: OFF, ID is: OFF
    217. 2022-07-22 10:12:47.228 18594-19976/? I/[CT]: MIXEDREALITY: MrServiceModel: commitLayerState: (every 10 seconds), ImagesAndCompute: false, ImagesOnly: false, NoRequirement: true.
    218. 2022-07-22 10:12:48.035 18594-20099/? I/Telemetry: App memory usage: PSS=20MB DalvikPSS=1 MB PrivateDirty=13MB PrivateClean=1MB
    219. 2022-07-22 10:12:49.024 18752-20368/? I/Telemetry: App memory usage: PSS=39MB DalvikPSS=2 MB PrivateDirty=28MB PrivateClean=5MB
    220. 2022-07-22 10:12:56.961 18097-19552/? I/ActivityManager: Killing 3022:com.oculus.identitymanagement.service/u10a32 (adj 995): empty #17
    221. 2022-07-22 10:12:56.978 18031-18031/? I/Zygote: Process 3022 exited due to signal 9 (Killed)
    222. 2022-07-22 10:12:56.996 18097-18129/? I/libprocessgroup: Successfully killed process cgroup uid 1010032 pid 3022 in 33ms
    223. 2022-07-22 10:12:57.236 18594-19976/? I/[CT]: MIXEDREALITY: MrServiceView: renderIteration: (every 10 seconds), screen is: OFF, PT is: OFF, ID is: OFF
    224. 2022-07-22 10:12:57.236 18594-19976/? I/[CT]: MIXEDREALITY: MrServiceModel: commitLayerState: (every 10 seconds), ImagesAndCompute: false, ImagesOnly: false, NoRequirement: true.
    225. 2022-07-22 10:12:59.215 31705-31750/? W/System: A resource failed to call close.
    226. 2022-07-22 10:13:07.243 18594-19976/? I/[CT]: MIXEDREALITY: MrServiceView: renderIteration: (every 10 seconds), screen is: OFF, PT is: OFF, ID is: OFF
    227. 2022-07-22 10:13:07.244 18594-19976/? I/[CT]: MIXEDREALITY: MrServiceModel: commitLayerState: (every 10 seconds), ImagesAndCompute: false, ImagesOnly: false, NoRequirement: true.
    228. 2022-07-22 10:13:08.029 18594-20099/? I/Telemetry: App memory usage: PSS=20MB DalvikPSS=1 MB PrivateDirty=13MB PrivateClean=1MB
    229. 2022-07-22 10:13:09.024 18752-20368/? I/Telemetry: App memory usage: PSS=39MB DalvikPSS=2 MB PrivateDirty=28MB PrivateClean=5MB
    230. 2022-07-22 10:13:15.652 18506-8732/? W/ContextImpl: Calling a method in the system process without a qualified user: android.app.ContextImpl.sendBroadcast:1057 android.content.ContextWrapper.sendBroadcast:448 X.oC.A00:143 X.o1.A00:17 X.o1.handleMessage:90
    231. 2022-07-22 10:13:15.660 18035-18070/? I/netd: firewallSetUidRule(2, 10018, 1) <0.05ms>
    232. 2022-07-22 10:13:16.030 18035-18070/? I/netd: firewallSetUidRule(2, 10018, 2) <0.03ms>
    233. 2022-07-22 10:13:17.251 18594-19976/? I/[CT]: MIXEDREALITY: MrServiceView: renderIteration: (every 10 seconds), screen is: OFF, PT is: OFF, ID is: OFF
    234. 2022-07-22 10:13:17.251 18594-19976/? I/[CT]: MIXEDREALITY: MrServiceModel: commitLayerState: (every 10 seconds), ImagesAndCompute: false, ImagesOnly: false, NoRequirement: true.
    235. 2022-07-22 10:13:27.259 18594-19976/? I/[CT]: MIXEDREALITY: MrServiceView: renderIteration: (every 10 seconds), screen is: OFF, PT is: OFF, ID is: OFF
    236. 2022-07-22 10:13:27.259 18594-19976/? I/[CT]: MIXEDREALITY: MrServiceModel: commitLayerState: (every 10 seconds), ImagesAndCompute: false, ImagesOnly: false, NoRequirement: true.
    237. 2022-07-22 10:13:28.032 18594-20099/? I/Telemetry: App memory usage: PSS=20MB DalvikPSS=1 MB PrivateDirty=13MB PrivateClean=1MB
    238. 2022-07-22 10:13:29.037 18752-20368/? I/Telemetry: App memory usage: PSS=39MB DalvikPSS=2 MB PrivateDirty=28MB PrivateClean=5MB
    239. 2022-07-22 10:13:37.267 18594-19976/? I/[CT]: MIXEDREALITY: MrServiceView: renderIteration: (every 10 seconds), screen is: OFF, PT is: OFF, ID is: OFF
    240. 2022-07-22 10:13:37.267 18594-19976/? I/[CT]: MIXEDREALITY: MrServiceModel: commitLayerState: (every 10 seconds), ImagesAndCompute: false, ImagesOnly: false, NoRequirement: true.
    241. 2022-07-22 10:13:38.377 18097-18291/? W/ActivityManager: Package for pid 850: no process record found
    242. 2022-07-22 10:13:47.274 18594-19976/? I/[CT]: MIXEDREALITY: MrServiceView: renderIteration: (every 10 seconds), screen is: OFF, PT is: OFF, ID is: OFF
    243. 2022-07-22 10:13:47.274 18594-19976/? I/[CT]: MIXEDREALITY: MrServiceModel: commitLayerState: (every 10 seconds), ImagesAndCompute: false, ImagesOnly: false, NoRequirement: true.
    244. 2022-07-22 10:13:48.045 18594-20099/? I/Telemetry: App memory usage: PSS=20MB DalvikPSS=1 MB PrivateDirty=13MB PrivateClean=1MB
    245. 2022-07-22 10:13:49.039 18752-20368/? I/Telemetry: App memory usage: PSS=39MB DalvikPSS=2 MB PrivateDirty=28MB PrivateClean=5MB
    246. 2022-07-22 10:13:57.282 18594-19976/? I/[CT]: MIXEDREALITY: MrServiceView: renderIteration: (every 10 seconds), screen is: OFF, PT is: OFF, ID is: OFF
    247. 2022-07-22 10:13:57.282 18594-19976/? I/[CT]: MIXEDREALITY: MrServiceModel: commitLayerState: (every 10 seconds), ImagesAndCompute: false, ImagesOnly: false, NoRequirement: true.
    248. 2022-07-22 10:14:07.290 18594-19976/? I/[CT]: MIXEDREALITY: MrServiceView: renderIteration: (every 10 seconds), screen is: OFF, PT is: OFF, ID is: OFF
    249. 2022-07-22 10:14:07.290 18594-19976/? I/[CT]: MIXEDREALITY: MrServiceModel: commitLayerState: (every 10 seconds), ImagesAndCompute: false, ImagesOnly: false, NoRequirement: true.
    250. 2022-07-22 10:14:08.044 18594-20099/? I/Telemetry: App memory usage: PSS=20MB DalvikPSS=1 MB PrivateDirty=13MB PrivateClean=1MB
    251. 2022-07-22 10:14:09.029 18752-20368/? I/Telemetry: App memory usage: PSS=39MB DalvikPSS=2 MB PrivateDirty=28MB PrivateClean=5MB
    252. 2022-07-22 10:14:17.297 18594-19976/? I/[CT]: MIXEDREALITY: MrServiceView: renderIteration: (every 10 seconds), screen is: OFF, PT is: OFF, ID is: OFF
    253. 2022-07-22 10:14:17.297 18594-19976/? I/[CT]: MIXEDREALITY: MrServiceModel: commitLayerState: (every 10 seconds), ImagesAndCompute: false, ImagesOnly: false, NoRequirement: true.
    254. 2022-07-22 10:14:24.253 18548-18870/? D/DeviceCertLibrary: verifyKeyForCurrentSecureState for device_registration_key returned status: 0
    255. 2022-07-22 10:14:24.253 18548-18870/? D/DeviceCertLibrary: containsAlias for device_registration_key received status: 0
    256. 2022-07-22 10:14:27.305 18594-19976/? I/[CT]: MIXEDREALITY: MrServiceView: renderIteration: (every 10 seconds), screen is: OFF, PT is: OFF, ID is: OFF
    257. 2022-07-22 10:14:27.305 18594-19976/? I/[CT]: MIXEDREALITY: MrServiceModel: commitLayerState: (every 10 seconds), ImagesAndCompute: false, ImagesOnly: false, NoRequirement: true.
    258. 2022-07-22 10:14:28.033 18594-20099/? I/Telemetry: App memory usage: PSS=20MB DalvikPSS=1 MB PrivateDirty=14MB PrivateClean=1MB
    259. 2022-07-22 10:14:29.054 18752-20368/? I/Telemetry: App memory usage: PSS=39MB DalvikPSS=2 MB PrivateDirty=28MB PrivateClean=5MB
    260. 2022-07-22 10:14:37.313 18594-19976/? I/[CT]: MIXEDREALITY: MrServiceView: renderIteration: (every 10 seconds), screen is: OFF, PT is: OFF, ID is: OFF
    261. 2022-07-22 10:14:37.313 18594-19976/? I/[CT]: MIXEDREALITY: MrServiceModel: commitLayerState: (every 10 seconds), ImagesAndCompute: false, ImagesOnly: false, NoRequirement: true.
    262. 2022-07-22 10:14:41.076 18097-18112/? I/system_server: Background young concurrent copying GC freed 92876(6595KB) AllocSpace objects, 235(5976KB) LOS objects, 39% free, 19MB/32MB, paused 135us total 125.047ms
    263. 2022-07-22 10:14:47.320 18594-19976/? I/[CT]: MIXEDREALITY: MrServiceView: renderIteration: (every 10 seconds), screen is: OFF, PT is: OFF, ID is: OFF
    264. 2022-07-22 10:14:47.320 18594-19976/? I/[CT]: MIXEDREALITY: MrServiceModel: commitLayerState: (every 10 seconds), ImagesAndCompute: false, ImagesOnly: false, NoRequirement: true.
    265. 2022-07-22 10:14:48.052 18594-20099/? I/Telemetry: App memory usage: PSS=20MB DalvikPSS=1 MB PrivateDirty=14MB PrivateClean=1MB
    266. 2022-07-22 10:14:49.042 18752-20368/? I/Telemetry: App memory usage: PSS=39MB DalvikPSS=2 MB PrivateDirty=28MB PrivateClean=5MB
    267. 2022-07-22 10:14:57.328 18594-19976/? I/[CT]: MIXEDREALITY: MrServiceView: renderIteration: (every 10 seconds), screen is: OFF, PT is: OFF, ID is: OFF
    268. 2022-07-22 10:14:57.328 18594-19976/? I/[CT]: MIXEDREALITY: MrServiceModel: commitLayerState: (every 10 seconds), ImagesAndCompute: false, ImagesOnly: false, NoRequirement: true.
    269. 2022-07-22 10:15:07.335 18594-19976/? I/[CT]: MIXEDREALITY: MrServiceView: renderIteration: (every 10 seconds), screen is: OFF, PT is: OFF, ID is: OFF
    270. 2022-07-22 10:15:07.336 18594-19976/? I/[CT]: MIXEDREALITY: MrServiceModel: commitLayerState: (every 10 seconds), ImagesAndCompute: false, ImagesOnly: false, NoRequirement: true.
    271. 2022-07-22 10:15:08.038 18594-20099/? I/Telemetry: App memory usage: PSS=20MB DalvikPSS=1 MB PrivateDirty=14MB PrivateClean=1MB
    272. 2022-07-22 10:15:09.043 18752-20368/? I/Telemetry: App memory usage: PSS=39MB DalvikPSS=2 MB PrivateDirty=28MB PrivateClean=5MB
    273. 2022-07-22 10:15:11.607 18097-2918/? W/JavaBinder: Unexpectedly many live BinderProxies: 35000
    274. 2022-07-22 10:15:14.945 832-1341/? I/crash-uploader: [Crash Reporter Rate Limiting] reset data
    275. 2022-07-22 10:15:17.343 18594-19976/? I/[CT]: MIXEDREALITY: MrServiceView: renderIteration: (every 10 seconds), screen is: OFF, PT is: OFF, ID is: OFF
    276. 2022-07-22 10:15:17.343 18594-19976/? I/[CT]: MIXEDREALITY: MrServiceModel: commitLayerState: (every 10 seconds), ImagesAndCompute: false, ImagesOnly: false, NoRequirement: true.
    277. 2022-07-22 10:15:27.351 18594-19976/? I/[CT]: MIXEDREALITY: MrServiceView: renderIteration: (every 10 seconds), screen is: OFF, PT is: OFF, ID is: OFF
    278. 2022-07-22 10:15:27.351 18594-19976/? I/[CT]: MIXEDREALITY: MrServiceModel: commitLayerState: (every 10 seconds), ImagesAndCompute: false, ImagesOnly: false, NoRequirement: true.
    279. 2022-07-22 10:15:28.051 18594-20099/? I/Telemetry: App memory usage: PSS=20MB DalvikPSS=1 MB PrivateDirty=14MB PrivateClean=1MB
    280. 2022-07-22 10:15:29.054 18752-20368/? I/Telemetry: App memory usage: PSS=39MB DalvikPSS=2 MB PrivateDirty=28MB PrivateClean=5MB
    281. 2022-07-22 10:15:37.359 18594-19976/? I/[CT]: MIXEDREALITY: MrServiceView: renderIteration: (every 10 seconds), screen is: OFF, PT is: OFF, ID is: OFF
    282. 2022-07-22 10:15:37.359 18594-19976/? I/[CT]: MIXEDREALITY: MrServiceModel: commitLayerState: (every 10 seconds), ImagesAndCompute: false, ImagesOnly: false, NoRequirement: true.
    283. 2022-07-22 10:15:38.623 18097-31846/? W/ActivityManager: Package for pid 850: no process record found
    284. 2022-07-22 10:15:47.366 18594-19976/? I/[CT]: MIXEDREALITY: MrServiceView: renderIteration: (every 10 seconds), screen is: OFF, PT is: OFF, ID is: OFF
    285. 2022-07-22 10:15:47.366 18594-19976/? I/[CT]: MIXEDREALITY: MrServiceModel: commitLayerState: (every 10 seconds), ImagesAndCompute: false, ImagesOnly: false, NoRequirement: true.
    286. 2022-07-22 10:15:48.049 18594-20099/? I/Telemetry: App memory usage: PSS=20MB DalvikPSS=1 MB PrivateDirty=14MB PrivateClean=1MB
    287. 2022-07-22 10:15:49.044 18752-20368/? I/Telemetry: App memory usage: PSS=40MB DalvikPSS=2 MB PrivateDirty=28MB PrivateClean=5MB
    288. 2022-07-22 10:15:57.374 18594-19976/? I/[CT]: MIXEDREALITY: MrServiceView: renderIteration: (every 10 seconds), screen is: OFF, PT is: OFF, ID is: OFF
    289. 2022-07-22 10:15:57.374 18594-19976/? I/[CT]: MIXEDREALITY: MrServiceModel: commitLayerState: (every 10 seconds), ImagesAndCompute: false, ImagesOnly: false, NoRequirement: true.
    290. 2022-07-22 10:16:07.382 18594-19976/? I/[CT]: MIXEDREALITY: MrServiceView: renderIteration: (every 10 seconds), screen is: OFF, PT is: OFF, ID is: OFF
    291. 2022-07-22 10:16:07.382 18594-19976/? I/[CT]: MIXEDREALITY: MrServiceModel: commitLayerState: (every 10 seconds), ImagesAndCompute: false, ImagesOnly: false, NoRequirement: true.
    292. 2022-07-22 10:16:08.052 18594-20099/? I/Telemetry: App memory usage: PSS=20MB DalvikPSS=1 MB PrivateDirty=14MB PrivateClean=1MB
    293. 2022-07-22 10:16:09.059 18752-20368/? I/Telemetry: App memory usage: PSS=40MB DalvikPSS=2 MB PrivateDirty=28MB PrivateClean=5MB
    294. 2022-07-22 10:16:17.390 18594-19976/? I/[CT]: MIXEDREALITY: MrServiceView: renderIteration: (every 10 seconds), screen is: OFF, PT is: OFF, ID is: OFF
    295. 2022-07-22 10:16:17.390 18594-19976/? I/[CT]: MIXEDREALITY: MrServiceModel: commitLayerState: (every 10 seconds), ImagesAndCompute: false, ImagesOnly: false, NoRequirement: true.
    296. 2022-07-22 10:16:27.404 18594-19976/? I/[CT]: MIXEDREALITY: MrServiceView: renderIteration: (every 10 seconds), screen is: OFF, PT is: OFF, ID is: OFF
    297. 2022-07-22 10:16:27.404 18594-19976/? I/[CT]: MIXEDREALITY: MrServiceModel: commitLayerState: (every 10 seconds), ImagesAndCompute: false, ImagesOnly: false, NoRequirement: true.
    298. 2022-07-22 10:16:28.052 18594-20099/? I/Telemetry: App memory usage: PSS=20MB DalvikPSS=1 MB PrivateDirty=14MB PrivateClean=1MB
    299. 2022-07-22 10:16:29.060 18752-20368/? I/Telemetry: App memory usage: PSS=40MB DalvikPSS=2 MB PrivateDirty=28MB PrivateClean=5MB
    300. 2022-07-22 10:16:37.412 18594-19976/? I/[CT]: MIXEDREALITY: MrServiceView: renderIteration: (every 10 seconds), screen is: OFF, PT is: OFF, ID is: OFF
    301. 2022-07-22 10:16:37.412 18594-19976/? I/[CT]: MIXEDREALITY: MrServiceModel: commitLayerState: (every 10 seconds), ImagesAndCompute: false, ImagesOnly: false, NoRequirement: true.
    302. 2022-07-22 10:16:47.419 18594-19976/? I/[CT]: MIXEDREALITY: MrServiceView: renderIteration: (every 10 seconds), screen is: OFF, PT is: OFF, ID is: OFF
    303. 2022-07-22 10:16:47.419 18594-19976/? I/[CT]: MIXEDREALITY: MrServiceModel: commitLayerState: (every 10 seconds), ImagesAndCompute: false, ImagesOnly: false, NoRequirement: true.
    304. 2022-07-22 10:16:48.048 18594-20099/? I/Telemetry: App memory usage: PSS=20MB DalvikPSS=1 MB PrivateDirty=14MB PrivateClean=1MB
    305. 2022-07-22 10:16:49.061 18752-20368/? I/Telemetry: App memory usage: PSS=40MB DalvikPSS=2 MB PrivateDirty=28MB PrivateClean=5MB
    306. 2022-07-22 10:16:57.429 18594-19976/? I/[CT]: MIXEDREALITY: MrServiceView: renderIteration: (every 10 seconds), screen is: OFF, PT is: OFF, ID is: OFF
    307. 2022-07-22 10:16:57.429 18594-19976/? I/[CT]: MIXEDREALITY: MrServiceModel: commitLayerState: (every 10 seconds), ImagesAndCompute: false, ImagesOnly: false, NoRequirement: true.
    308. 2022-07-22 10:17:03.540 31716-31716/? D/[OAO] LowStorageNotificationScheduler: Storage Checks: Internal Free (50830528512)
    309. 2022-07-22 10:17:07.443 18594-19976/? I/[CT]: MIXEDREALITY: MrServiceView: renderIteration: (every 10 seconds), screen is: OFF, PT is: OFF, ID is: OFF
    310. 2022-07-22 10:17:07.443 18594-19976/? I/[CT]: MIXEDREALITY: MrServiceModel: commitLayerState: (every 10 seconds), ImagesAndCompute: false, ImagesOnly: false, NoRequirement: true.
    311. 2022-07-22 10:17:08.066 18594-20099/? I/Telemetry: App memory usage: PSS=20MB DalvikPSS=1 MB PrivateDirty=14MB PrivateClean=1MB
    312. 2022-07-22 10:17:09.072 18752-20368/? I/Telemetry: App memory usage: PSS=40MB DalvikPSS=2 MB PrivateDirty=29MB PrivateClean=5MB
    313. 2022-07-22 10:17:12.525 760-969/? I/SyncBossHAL: [info   ] syncboss_hal_powerstate.c(50): Reporting powerstate event: PROX_ON
    314. 2022-07-22 10:17:12.526 18097-18248/? D/VrPowerManagerService: processing message: sensor changed
    315. 2022-07-22 10:17:12.526 18097-18248/? I/VrPowerManagerService: transition from STANDBY to HEADSET_MOUNTED
    316. 2022-07-22 10:17:12.526 18097-18248/? I/PowerManagerService: Waking up from Asleep (uid=1000, reason=WAKE_REASON_UNKNOWN, details=VrPwMng:leave-standby)...
    317. 2022-07-22 10:17:12.526 18097-18097/? W/UsageStatsService: Event reported without a package name, eventType:15
    318. 2022-07-22 10:17:12.528 18097-18136/? I/DisplayPowerController: Blocking screen on until initial contents have been drawn.
    319. 2022-07-22 10:17:12.528 850-850/? D/SensorClientUtils: Cancelling delayed transition to SLEEP
    320. 2022-07-22 10:17:12.528 850-850/? D/SensorClientUtils: Received transition request to RUNNING current is SLEEP
    321. 2022-07-22 10:17:12.528 850-850/? D/SensorClientUtils: Executing transition from SLEEP to STANDBY
    322. 2022-07-22 10:17:12.528 850-850/? D/SensorClientUtils: Setting power state to STANDBY
    323. 2022-07-22 10:17:12.528 852-1100/? D/SensorClientUtils: Cancelling delayed transition to SLEEP
    324. 2022-07-22 10:17:12.528 850-850/? E/libwakelock: MrSystemService: Failed to acquire wakelock mrsystemservice.powermonitor; refcnt=0, powerManager=true, status=-32
    325. 2022-07-22 10:17:12.528 850-850/? D/SensorClientUtils: Executing transition from STANDBY to RUNNING
    326. 2022-07-22 10:17:12.528 850-850/? D/SensorClientUtils: Setting power state to RUNNING
    327. 2022-07-22 10:17:12.529 852-1100/? D/SensorClientUtils: Received transition request to RUNNING current is SLEEP
    328. 2022-07-22 10:17:12.529 852-1100/? D/SensorClientUtils: Executing transition from SLEEP to STANDBY
    329. 2022-07-22 10:17:12.529 852-1100/? D/SensorClientUtils: Setting power state to STANDBY
    330. 2022-07-22 10:17:12.529 850-850/? E/libwakelock: MrSystemService: Failed to acquire wakelock mrsystemservice.powermonitor; refcnt=0, powerManager=true, status=-32
    331. 2022-07-22 10:17:12.529 852-1100/? E/libwakelock: system: Failed to acquire wakelock trackingservice.powermonitor; refcnt=0, powerManager=true, status=-32
    332. 2022-07-22 10:17:12.531 852-1103/? D/SensorClientUtils: Cancelling delayed transition to SLEEP
    333. 2022-07-22 10:17:12.531 852-1103/? D/SensorClientUtils: Received transition request to RUNNING current is SLEEP
    334. 2022-07-22 10:17:12.531 852-1103/? D/SensorClientUtils: Executing transition from SLEEP to STANDBY
    335. 2022-07-22 10:17:12.531 852-1103/? D/SensorClientUtils: Setting power state to STANDBY
    336. 2022-07-22 10:17:12.531 18527-18573/? D/VrPowerManagerClient: Headset state: 1
    337. 2022-07-22 10:17:12.532 18527-18573/? V/ControllerNotifications: Headset was mounted, requesting that notifications are enabled
    338. 2022-07-22 10:17:12.532 18527-18573/? V/ControllerNotifications: Queueing enable of notifications in 5000ms
    339. 2022-07-22 10:17:12.533 852-1102/? I/TrackingService: [ vision_manager] SLEEP -> STANDBY transition time: 4 ms
    340. 2022-07-22 10:17:12.534 852-1103/? E/libwakelock: system: Failed to acquire wakelock trackingservice.powermonitor; refcnt=0, powerManager=true, status=-32
    341. 2022-07-22 10:17:12.534 852-1103/? D/OVRRemoteService: ControllerGlue: setting expected mode to Streaming
    342. 2022-07-22 10:17:12.534 852-1103/? D/OVRRemoteService: ControllerGlue: Setting current mode to Streaming
    343. 2022-07-22 10:17:12.534 852-1103/? D/OVRRemoteService: ControllerGlue: leave mode Disabled
    344. 2022-07-22 10:17:12.534 852-1103/? D/OVRRemoteService: ControllerGlue: Setting mode to Streaming
    345. 2022-07-22 10:17:12.534 852-1103/? D/OVRRemoteService: ControllerGlue: enter mode Streaming
    346. 2022-07-22 10:17:12.535 852-1102/? I/TrackingService: [            iad] SLEEP -> STANDBY transition time: 1 ms
    347. 2022-07-22 10:17:12.535 852-1102/? I/[CT]: BoltMemoryAllocationCapabilityImpl: onStart
    348. 2022-07-22 10:17:12.535 852-1102/? I/[CT]: BoltSDK::Soc-Hexagon: BoltMemoryAllocationCapability: Hexagon ref count changed from 0 to 1
    349. 2022-07-22 10:17:12.535 852-1102/? I/[CT]: BoltSDK::Soc-Hexagon: Acquiring all Hexagon resources from Bolt SDK
    350. 2022-07-22 10:17:12.535 852-1102/? I/[CT]: BOLT:HexagonShim: HexagonStart
    351. 2022-07-22 10:17:12.535 18033-2456/? D/AF::TrackHandle: OpPlayAudio: track:62 uid:1010016 pkg:com.oculus.shellenv usage:1 muted
    352. 2022-07-22 10:17:12.535 32217-32217/? V/AvrcpMediaPlayerList: onPlaybackConfigChanged(): Configs list size=5
    353. 2022-07-22 10:17:12.547 18033-2456/? D/AF::TrackHandle: OpPlayAudio: track:62 uid:1010016 pkg:com.oculus.shellenv usage:1 muted
    354. 2022-07-22 10:17:12.547 760-760/? I/SyncBossHAL: [info   ] syncboss_hal_impl_android_driver.c(541): Starting logging thread from UART path /dev/ttyHS14
    355. 2022-07-22 10:17:12.547 760-760/? D/SensorService: ControllerProvider: acquiring StreamingSession
    356. 2022-07-22 10:17:12.547 760-760/? D/SensorService: SyncbossEventHandler: starting all streams
    357. 2022-07-22 10:17:12.547 760-8755/? D/SensorService: SyncbossEventHandler::producerThreadFunc() start
    358. 2022-07-22 10:17:12.547 760-8755/? W/SensorService: Data for sensor type HMD_IMU dropped because of failure to update clock drift from vsync. 1 drops in the last 0s.
    359. 2022-07-22 10:17:12.547 18033-2456/? D/AF::TrackHandle: OpPlayAudio: track:62 uid:1010016 pkg:com.oculus.shellenv usage:1 muted
    360. 2022-07-22 10:17:12.548 18034-18071/? D/NuPlayerDriver: NuPlayerDriver(0xeee2e5a0) created, clientPid(18097)
    361. 2022-07-22 10:17:12.548 18033-18033/? D/AF::RecordHandle: OpRecordAudio: track:61 uid:1010016 pkg:com.oculus.shellenv usage:0 muted
    362. 2022-07-22 10:17:12.549 18097-18136/? V/DisplayPowerController: Brightness [127] reason changing to: 'manual', previous reason: 'screen_off'.
    363. 2022-07-22 10:17:12.548 18033-18033/? I/chatty: uid=1041(audioserver) /system/bin/audioserver identical 1 line
    364. 2022-07-22 10:17:12.549 18033-18033/? D/AF::RecordHandle: OpRecordAudio: track:61 uid:1010016 pkg:com.oculus.shellenv usage:0 muted
    365. 2022-07-22 10:17:12.549 18033-2626/? D/AF::TrackHandle: OpPlayAudio: track:60 uid:1000 pkg:com.android.networkstack.inprocess usage:13 not muted
    366. 2022-07-22 10:17:12.550 18033-2626/? I/chatty: uid=1041(audioserver) Binder:18033_8 identical 1 line
    367. 2022-07-22 10:17:12.550 18033-2626/? D/AF::TrackHandle: OpPlayAudio: track:60 uid:1000 pkg:com.android.networkstack.inprocess usage:13 not muted
    368. 2022-07-22 10:17:12.551 18034-18071/? I/Codec2Client: Creating a Codec2 client to service "software"
    369. 2022-07-22 10:17:12.551 760-760/? I/SyncBossHAL: [info   ] syncboss_hal_impl_input.c(277): No pulsar frequency blocklist set
    370. 2022-07-22 10:17:12.551 760-760/? I/SyncBossHAL: [info   ] syncboss_hal_impl_input.c(304): No AFH behavior specified, enabled by default
    371. 2022-07-22 10:17:12.551 760-760/? I/SyncBossHAL: [info   ] syncboss_hal_impl_input.c(344): Input device auto-whitelisting disabled
    372. 2022-07-22 10:17:12.551 18097-18136/? I/DisplayPowerController: Unblocked screen on after 23 ms
    373. 2022-07-22 10:17:12.551 760-8753/? I/SyncBossFW: 1689077 [info   ] {APPI}: Enabling display timestamping
    374. 2022-07-22 10:17:12.551 18033-18033/? D/AF::TrackHandle: OpPlayAudio: track:60 uid:1000 pkg:com.android.networkstack.inprocess usage:13 not muted
    375. 2022-07-22 10:17:12.551 852-1102/? I/[CT]: boltlib: Waited 0.016418177 for SFRPC invoker thread to start
    376. 2022-07-22 10:17:12.551 18033-2626/? D/AF::TrackHandle: OpPlayAudio: track:62 uid:1010016 pkg:com.oculus.shellenv usage:1 muted
    377. 2022-07-22 10:17:12.552 18097-18121/? I/DisplayManagerService: Display device changed state: "Built-in Screen", ON
    378. 2022-07-22 10:17:12.552 793-793/? D/SurfaceFlinger: Setting power mode 2 on display 19261214226499457
    379. 2022-07-22 10:17:12.552 18034-18071/? I/Codec2Client: Client to Codec2 service "software" created
    380. 2022-07-22 10:17:12.554 18033-2626/? D/AF::RecordHandle: OpRecordAudio: track:61 uid:1010016 pkg:com.oculus.shellenv usage:0 muted
    381. 2022-07-22 10:17:12.555 18033-18033/? D/AF::TrackHandle: OpPlayAudio: track:62 uid:1010016 pkg:com.oculus.shellenv usage:1 muted
    382. 2022-07-22 10:17:12.555 18033-2626/? D/AF::RecordHandle: OpRecordAudio: track:61 uid:1010016 pkg:com.oculus.shellenv usage:0 muted
    383. 2022-07-22 10:17:12.555 18033-18033/? D/AF::TrackHandle: OpPlayAudio: track:62 uid:1010016 pkg:com.oculus.shellenv usage:1 muted
    384. 2022-07-22 10:17:12.555 18033-2626/? D/AF::RecordHandle: OpRecordAudio: track:61 uid:1010016 pkg:com.oculus.shellenv usage:0 muted
    385. 2022-07-22 10:17:12.556 18033-2456/? D/AF::TrackHandle: OpPlayAudio: track:60 uid:1000 pkg:com.android.networkstack.inprocess usage:13 not muted
    386. 2022-07-22 10:17:12.556 760-760/? D/SensorService: ControllerProvider: acquiring StreamingClient impl; approx # alive: 1
    387. 2022-07-22 10:17:12.556 760-760/? D/libsensorscommon: ControllerProvider: acquiring StreamingClient hidl
    388. 2022-07-22 10:17:12.556 18033-2456/? D/AF::TrackHandle: OpPlayAudio: track:60 uid:1000 pkg:com.android.networkstack.inprocess usage:13 not muted
    389. 2022-07-22 10:17:12.556 18033-18220/? D/AF::RecordHandle: OpRecordAudio: track:61 uid:1010016 pkg:com.oculus.shellenv usage:0 muted
    390. 2022-07-22 10:17:12.556 766-1054/? I/SDM: DisplayBase::SetDisplayState: Set state = 1, display 29-0, teardown = 0
    391. 2022-07-22 10:17:12.557 760-8753/? I/SyncBossFW: 1689082 [info   ] {WIHO}: Pulsar device auto-whitelisting disabled
    392. 2022-07-22 10:17:12.557 760-8753/? I/SyncBossFW: 1689083 [info   ] {APPI}: Starting input
    393. 2022-07-22 10:17:12.557 18033-2456/? D/AF::TrackHandle: OpPlayAudio: track:60 uid:1000 pkg:com.android.networkstack.inprocess usage:13 not muted
    394. 2022-07-22 10:17:12.557 852-1103/? D/OVRRemoteService: [controller] SLEEP -> STANDBY
    395. 2022-07-22 10:17:12.557 852-1103/? D/SensorClientUtils: Executing transition from STANDBY to RUNNING
    396. 2022-07-22 10:17:12.557 852-1103/? D/SensorClientUtils: Setting power state to RUNNING
    397. 2022-07-22 10:17:12.557 852-8762/? D/OVRRemoteService: processStateChange([PairedControllerInfo JEDI 4a4d8199d5955b23 disconnected mcnt=0])
    398. 2022-07-22 10:17:12.557 852-8762/? D/OVRRemoteService: processStateChange([PairedControllerInfo JEDI e6e349e957f83390 disconnected mcnt=0])
    399. 2022-07-22 10:17:12.557 18033-2456/? D/AF::TrackHandle: OpPlayAudio: track:60 uid:1000 pkg:com.android.networkstack.inprocess usage:13 not muted
    400. 2022-07-22 10:17:12.557 852-1103/? E/libwakelock: system: Failed to acquire wakelock trackingservice.powermonitor; refcnt=0, powerManager=true, status=-32
    401. 2022-07-22 10:17:12.558 852-1103/? D/OVRRemoteService: [controller] STANDBY -> RUNNING
    402. 2022-07-22 10:17:12.558 18033-18220/? D/AF::RecordHandle: OpRecordAudio: track:61 uid:1010016 pkg:com.oculus.shellenv usage:0 muted
    403. 2022-07-22 10:17:12.558 18033-2456/? D/AF::TrackHandle: OpPlayAudio: track:60 uid:1000 pkg:com.android.networkstack.inprocess usage:13 not muted
    404. 2022-07-22 10:17:12.558 852-1102/? I/[CT]: boltlib: Waited 0.006646198 for all SFRPC worker threads
    405. 2022-07-22 10:17:12.558 18033-2456/? D/AF::TrackHandle: OpPlayAudio: track:60 uid:1000 pkg:com.android.networkstack.inprocess usage:13 not muted
    406. 2022-07-22 10:17:12.558 18033-18220/? D/AF::RecordHandle: OpRecordAudio: track:61 uid:1010016 pkg:com.oculus.shellenv usage:0 muted
    407. 2022-07-22 10:17:12.558 18033-18033/? D/AF::TrackHandle: OpPlayAudio: track:62 uid:1010016 pkg:com.oculus.shellenv usage:1 muted
    408. 2022-07-22 10:17:12.559 18033-18033/? D/AF::TrackHandle: OpPlayAudio: track:62 uid:1010016 pkg:com.oculus.shellenv usage:1 muted
    409. 2022-07-22 10:17:12.559 18033-18220/? D/AF::TrackHandle: OpPlayAudio: track:60 uid:1000 pkg:com.android.networkstack.inprocess usage:13 not muted
    410. 2022-07-22 10:17:12.560 18033-2626/? D/AF::RecordHandle: OpRecordAudio: track:61 uid:1010016 pkg:com.oculus.shellenv usage:0 muted
    411. 2022-07-22 10:17:12.560 18033-18220/? D/AF::TrackHandle: OpPlayAudio: track:60 uid:1000 pkg:com.android.networkstack.inprocess usage:13 not muted
    412. 2022-07-22 10:17:12.560 760-8754/? D/SensorService: Syncboss input e6e349e957f83390 hardware type 4, subtype 1, revision
    413. 2022-07-22 10:17:12.560 760-8754/? I/SensorService: preparePairedControllerInfo is adding device with valid 1
    414. 2022-07-22 10:17:12.560 760-8754/? D/SensorService: Syncboss input 4a4d8199d5955b23 hardware type 4, subtype 2, revision
    415. 2022-07-22 10:17:12.560 760-8754/? I/SensorService: preparePairedControllerInfo is adding device with valid 1
    416. 2022-07-22 10:17:12.560 18033-2626/? D/AF::RecordHandle: OpRecordAudio: track:61 uid:1010016 pkg:com.oculus.shellenv usage:0 muted
    417. 2022-07-22 10:17:12.560 18033-18220/? D/AF::TrackHandle: OpPlayAudio: track:60 uid:1000 pkg:com.android.networkstack.inprocess usage:13 not muted
    418. 2022-07-22 10:17:12.560 18033-18033/? D/AF::TrackHandle: OpPlayAudio: track:62 uid:1010016 pkg:com.oculus.shellenv usage:1 muted
    419. 2022-07-22 10:17:12.560 760-8754/? D/SensorService: stateChangeNotifierFunc(): Reporting controller info. Change token: 258, paired=2 connected=0
    420. 2022-07-22 10:17:12.560 852-8762/? D/OVRRemoteService: processStateChange([PairedControllerInfo JEDI e6e349e957f83390 disconnected update-required mcnt=0])
    421. 2022-07-22 10:17:12.560 852-8762/? D/OVRRemoteService: processStateChange([PairedControllerInfo JEDI 4a4d8199d5955b23 disconnected update-required mcnt=0])
    422. 2022-07-22 10:17:12.560 852-1102/? I/[CT]: BoltSDK::Soc-Hexagon: Acquiring memory pool resources from Bolt SDK
    423. 2022-07-22 10:17:12.560 852-1102/? D//system/bin/trackingservice: src/rpcmem_android.c:172::info: calling: NULL != (m = malloc(sizeof(*m)))
    424. 2022-07-22 10:17:12.561 852-1102/? D//system/bin/trackingservice: src/rpcmem_android.c:172::info: passed: NULL != (m = malloc(sizeof(*m)))
    425. 2022-07-22 10:17:12.561 852-1102/? D//system/bin/trackingservice: src/rpcmem_android.c:193::info: calling: !(rpc_flags & RPCMEM_HEAP_UNCACHED)
    426. 2022-07-22 10:17:12.561 852-1102/? D//system/bin/trackingservice: src/rpcmem_android.c:193::info: passed: !(rpc_flags & RPCMEM_HEAP_UNCACHED)
    427. 2022-07-22 10:17:12.561 852-1102/? D//system/bin/trackingservice: src/rpcmem_android.c:426:ION version is new
    428. 2022-07-22 10:17:12.561 852-1102/? D//system/bin/trackingservice: src/rpcmem_android.c:331::info: calling: 0 < rpcmem_ionfd
    429. 2022-07-22 10:17:12.561 852-1102/? D//system/bin/trackingservice: src/rpcmem_android.c:331::info: passed: 0 < rpcmem_ionfd
    430. 2022-07-22 10:17:12.561 852-1102/? D//system/bin/trackingservice: src/rpcmem_android.c:340:alloc data 0x0x7b0b595e20, heap mask 0x2000000, flags 0x1
    431. 2022-07-22 10:17:12.561 852-1102/? D//system/bin/trackingservice: src/rpcmem_android.c:347:mmap data 0x0x7b0b595e20
    432. 2022-07-22 10:17:12.561 852-1102/? D//system/bin/trackingservice: src/rpcmem_android.c:355::info: calling: MAP_FAILED != (m->paddr = (void *)mmap(NULL, alloc.len, PROT_READ|PROT_WRITE, MAP_SHARED, m->data.fd, 0))
    433. 2022-07-22 10:17:12.561 852-1102/? D//system/bin/trackingservice: src/rpcmem_android.c:355::info: passed: MAP_FAILED != (m->paddr = (void *)mmap(NULL, alloc.len, PROT_READ|PROT_WRITE, MAP_SHARED, m->data.fd, 0))
    434. 2022-07-22 10:17:12.561 852-1102/? D//system/bin/trackingservice: src/rpcmem_android.c:215:rpcmem register buf: heap mask: 0x2000000
    435. 2022-07-22 10:17:12.561 18033-2626/? D/AF::RecordHandle: OpRecordAudio: track:61 uid:1010016 pkg:com.oculus.shellenv usage:0 muted
    436. 2022-07-22 10:17:12.561 18033-18033/? D/AF::TrackHandle: OpPlayAudio: track:62 uid:1010016 pkg:com.oculus.shellenv usage:1 muted
    437. 2022-07-22 10:17:12.561 852-1102/? I/[CT]: HexagonMemMgr: Allocated addr 0x7af96f0000, with FD 20, and virtAddr 0x86400000
    438. 2022-07-22 10:17:12.561 18033-18220/? D/AF::TrackHandle: OpPlayAudio: track:60 uid:1000 pkg:com.android.networkstack.inprocess usage:13 not muted
    439. 2022-07-22 10:17:12.561 18033-18033/? D/AF::TrackHandle: OpPlayAudio: track:62 uid:1010016 pkg:com.oculus.shellenv usage:1 muted
    440. 2022-07-22 10:17:12.561 852-1102/? I/[CT]: BOLT:HexagonShim: memtest is a success
    441. 2022-07-22 10:17:12.561 852-1102/? I/[CT]: HexagonMemMgr: HexagonMemTest returned 0
    442. 2022-07-22 10:17:12.561 852-1102/? I/[CT]: BoltSDK::Soc-Hexagon: Reserved RpcMemory bytes = 10485760
    443. 2022-07-22 10:17:12.561 852-1102/? I/TrackingService: [           bolt] SLEEP -> STANDBY transition time: 26 ms
    444. 2022-07-22 10:17:12.561 852-1102/? I/[CT]: VisionInterface: Stopping IOTE PostProcessing
    445. 2022-07-22 10:17:12.562 18033-18033/? D/AF::TrackHandle: OpPlayAudio: track:62 uid:1010016 pkg:com.oculus.shellenv usage:1 muted
    446. 2022-07-22 10:17:12.562 18033-18033/? D/AF::TrackHandle: OpPlayAudio: track:62 uid:1010016 pkg:com.oculus.shellenv usage:1 muted
    447. 2022-07-22 10:17:12.562 18033-18220/? D/AF::TrackHandle: OpPlayAudio: track:60 uid:1000 pkg:com.android.networkstack.inprocess usage:13 not muted
    448. 2022-07-22 10:17:12.562 18034-8764/? D/GenericSource: FileSource remote
    449. 2022-07-22 10:17:12.563 18033-18033/? D/AF::TrackHandle: OpPlayAudio: track:62 uid:1010016 pkg:com.oculus.shellenv usage:1 muted
    450. 2022-07-22 10:17:12.563 18033-18033/? I/chatty: uid=1041(audioserver) /system/bin/audioserver identical 1 line
    451. 2022-07-22 10:17:12.564 18033-18033/? D/AF::TrackHandle: OpPlayAudio: track:62 uid:1010016 pkg:com.oculus.shellenv usage:1 muted
    452. 2022-07-22 10:17:12.564 18033-8570/? D/AF::RecordHandle: OpRecordAudio: track:61 uid:1010016 pkg:com.oculus.shellenv usage:0 muted
    453. 2022-07-22 10:17:12.565 18033-8570/? D/AF::RecordHandle: OpRecordAudio: track:61 uid:1010016 pkg:com.oculus.shellenv usage:0 muted
    454. 2022-07-22 10:17:12.565 18033-3951/? D/AF::RecordHandle: OpRecordAudio: track:61 uid:1010016 pkg:com.oculus.shellenv usage:0 muted
    455. 2022-07-22 10:17:12.565 18033-3951/? I/chatty: uid=1041(audioserver) Binder:18033_9 identical 1 line
    456. 2022-07-22 10:17:12.565 18033-3951/? D/AF::RecordHandle: OpRecordAudio: track:61 uid:1010016 pkg:com.oculus.shellenv usage:0 muted
    457. 2022-07-22 10:17:12.566 18033-18220/? D/AF::TrackHandle: OpPlayAudio: track:60 uid:1000 pkg:com.android.networkstack.inprocess usage:13 not muted
    458. 2022-07-22 10:17:12.566 18033-3951/? D/AF::RecordHandle: OpRecordAudio: track:61 uid:1010016 pkg:com.oculus.shellenv usage:0 muted
    459. 2022-07-22 10:17:12.566 18033-18220/? D/AF::TrackHandle: OpPlayAudio: track:60 uid:1000 pkg:com.android.networkstack.inprocess usage:13 not muted
    460. 2022-07-22 10:17:12.566 18033-18220/? I/chatty: uid=1041(audioserver) Binder:18033_4 identical 1 line
    461. 2022-07-22 10:17:12.566 18033-18220/? D/AF::TrackHandle: OpPlayAudio: track:60 uid:1000 pkg:com.android.networkstack.inprocess usage:13 not muted
    462. 2022-07-22 10:17:12.567 18033-18033/? D/AF::TrackHandle: OpPlayAudio: track:62 uid:1010016 pkg:com.oculus.shellenv usage:1 muted
    463. 2022-07-22 10:17:12.567 18033-18220/? D/AF::TrackHandle: OpPlayAudio: track:60 uid:1000 pkg:com.android.networkstack.inprocess usage:13 not muted
    464. 2022-07-22 10:17:12.567 18033-18033/? D/AF::TrackHandle: OpPlayAudio: track:62 uid:1010016 pkg:com.oculus.shellenv usage:1 muted
    465. 2022-07-22 10:17:12.567 18033-18033/? I/chatty: uid=1041(audioserver) /system/bin/audioserver identical 1 line
    466. 2022-07-22 10:17:12.568 18033-18033/? D/AF::TrackHandle: OpPlayAudio: track:62 uid:1010016 pkg:com.oculus.shellenv usage:1 muted
    467. 2022-07-22 10:17:12.572 852-1102/? I/[CT]: InsideOutTrackingCapabilityTranslation: onStart
    468. 2022-07-22 10:17:12.572 18037-18050/? D/audio_hw_primary: adev_set_parameters: enter: screen_state=on
    469. 2022-07-22 10:17:12.572 852-1102/? I/[CT]: VisionInterface: Starting the IO Engine
    470. 2022-07-22 10:17:12.572 852-1102/? I/[CT]: VisionInterface: GK check: 'oculus_enable_abort_on_over_memory2': false
    471. 2022-07-22 10:17:12.573 852-1102/? I/[CT]: VisionInterface: GK check: 'oculus_enable_half_rate_slam': false
    472. 2022-07-22 10:17:12.573 852-1102/? I/[CT]: VisionInterface: GK check: 'oculus_enable_granular_perfmonitoring': false
    473. 2022-07-22 10:17:12.573 18034-8757/? I/GenericSource: start
    474. 2022-07-22 10:17:12.573 32217-32217/? V/AvrcpMediaPlayerList: onPlaybackConfigChanged(): Configs list size=5
    475. 2022-07-22 10:17:12.574 852-1102/? W/[CT]: CALIBRATION: Imu ID does not exist or could not be parsed
    476. 2022-07-22 10:17:12.574 852-1102/? W/[CT]: SensorRegistration: Unable to convert sensor ID '' to int: stoi: no conversion
    477. 2022-07-22 10:17:12.574 852-1102/? W/[CT]: SensorRegistration: Unable to find IMU calibration for device ID 0! As only a single calibration was available we are continuing with that one.
    478. 2022-07-22 10:17:12.574 852-1102/? I/[CT]: VIPER: Loading noise parameters for: ICM42688
    479. 2022-07-22 10:17:12.574 852-1102/? W/[CT]: VIPER: Loading noise parameters from config. [SensorModel: ICM42688]
    480. 2022-07-22 10:17:12.574 852-1102/? I/[CT]: viper::viper::imu_types: Creating PiecewiseLinearTemperatureImuModel:
    481.     -------
    482.     Accel:
    483.    
    484.     Rectification
    485.     -0.00212448    0.998882 -0.00633324
    486.        0.998649  0.00210648 -0.00441399
    487.     -0.00587179 -0.00646054   -0.998633
    488.     Number of TemperatureOffsetPairs: 37
    489.     -------
    490.     Gyro:
    491.    
    492.     Rectification
    493.     -9.26208e-05      1.00098   -0.0064596
    494.         0.999918   0.00282039  -0.00451789
    495.      -0.00763225  -0.00675573    -0.999874
    496.     Number of TemperatureOffsetPairs: 37
    497.     -------
    498.     T_deviceFromImu: so3[0.000000 0.000000 0.000000] r3[0.038400 0.032100 -0.067400]
    499. 2022-07-22 10:17:12.574 852-1102/? I/[CT]: OtWrapper: Online calibration used for IMU.
    500. 2022-07-22 10:17:12.574 852-1102/? I/[CT]: OtWrapper: Using magnetometer for 3dof pipeline with nominal rate 30Hz
    501. 2022-07-22 10:17:12.575 852-1102/? I/[CT]: VisionInterface: GK check: 'oculus_enable_bolt_ramdump': false
    502. 2022-07-22 10:17:12.575 852-1102/? I/[CT]: VisionInterface: GK check: 'oculus_enable_bolt_v24_mitigations': true
    503. 2022-07-22 10:17:12.575 852-1102/? I/[CT]: boltlib: Enabled Bolt V24 mitigations
    504. 2022-07-22 10:17:12.576 852-1102/? I/[CT]: VisionInterface: GK check: 'oculus_enable_bolt_multithreaded_dsp': false
    505. 2022-07-22 10:17:12.576 852-1102/? I/[CT]: boltlib: Setting Bolt Hexagon Multithreaded access to false
    506. 2022-07-22 10:17:12.576 852-1102/? I/[CT]: BoltSDK::Soc-Hexagon: ViperPlatform: Hexagon ref count changed from 1 to 2
    507. 2022-07-22 10:17:12.576 852-1102/? I/[CT]: BoltSdkFramework: ViperPlatform: RMgr ref count changed from 0 to 1
    508. 2022-07-22 10:17:12.576 852-1102/? I/[CT]: BoltSDK::Soc-Hexagon: BoltMemDetail: Hexagon ref count changed from 2 to 3
    509. 2022-07-22 10:17:12.576 852-1102/? I/[CT]: BoltSdkFramework: HarrisCornerObject: RMgr ref count changed from 1 to 2
    510. 2022-07-22 10:17:12.576 852-1102/? I/[CT]: BoltSdkFramework: HarrisCorner: RMgr ref count changed from 2 to 3
    511. 2022-07-22 10:17:12.576 852-1102/? I/[CT]: BoltSDK::Soc-Hexagon: defaultMemPool: Hexagon ref count changed from 3 to 4
    512. 2022-07-22 10:17:12.576 852-1102/? I/[CT]: BoltSDK::Soc-Hexagon: DEFAULT HexagonPool:HarrisCorner: Hexagon ref count changed from 4 to 5
    513. 2022-07-22 10:17:12.576 852-1102/? I/[CT]: BoltSDK::Soc-Hexagon: defaultMemPool: Hexagon ref count changed from 5 to 4
    514. 2022-07-22 10:17:12.576 18663-18663/? D/VrRuntimeService: Received broadcast: com.oculus.intent.action.MOUNT_STATE_CHANGED
    515. 2022-07-22 10:17:12.576 18663-18663/? D/VrRuntimeService: mounted state: true
    516. 2022-07-22 10:17:12.576 833-932/? I/PerfStream: BatteryStatsStates::activeStartEvent()
    517. 2022-07-22 10:17:12.576 18663-18663/? I/VrRuntimeService: nativeScreenStateChanged to on
    518. 2022-07-22 10:17:12.576 18663-18663/? I/VrRuntimeService: Service entering RUNNING Mode
    519. 2022-07-22 10:17:12.576 18663-18663/? I/VrRuntimeService: Resetting vsync state
    520. 2022-07-22 10:17:12.576 18663-18663/? I/VrRuntimeServer: RuntimeServer: Resuming operation
    521. 2022-07-22 10:17:12.576 18663-18663/? I/TelemetryServer: StartTelemetryServer start
    522. 2022-07-22 10:17:12.576 18663-18663/? I/TelemetryServer: StartTelemetryServer end - 0.07ms
    523. 2022-07-22 10:17:12.576 18594-18594/? I/[CT]: MIXEDREALITY: MrService: MountStateChanged: true
    524. 2022-07-22 10:17:12.577 31716-31716/? D/[OAO] BaseOverlayService: screenStateReceiver Received broadcast: com.oculus.intent.action.MOUNT_STATE_CHANGED
    525. 2022-07-22 10:17:12.577 31716-31716/? D/[OAO] ShellOverlayService: onMountStateChanged: true
    526. 2022-07-22 10:17:12.577 31716-31716/? I/[OAO] ShellOverlayServiceJNI: NativeSendOverlayCommand
    527. 2022-07-22 10:17:12.577 31716-31716/? I/[OAO] ShellOverlayServiceJNI: NativeWake
    528. 2022-07-22 10:17:12.577 31716-31716/? I/[OAO] ShellOverlayMain: WakeVrThread
    529. 2022-07-22 10:17:12.577 31716-31716/? I/[OAO] ShellOverlayMain: WakeVrThread - notifying vr thread
    530. 2022-07-22 10:17:12.577 31716-32053/? I/[OAO] ShellOverlayApp: VrThread woke up
    531. 2022-07-22 10:17:12.577 31716-32053/? I/[OAO] ShellOverlayApp: 0xc263abd0 msg: overlayCommand:
    532.     command = mountStateChanged
    533.     state = 1
    534. 2022-07-22 10:17:12.577 31716-32053/? I/[OAO] ShellOverlayApp: Process_OverlayCommand command : mountStateChanged
    535. 2022-07-22 10:17:12.577 31716-32053/? I/[OAO] ShellOverlayApp: mountStateChanged message received
    536. 2022-07-22 10:17:12.577 32703-32703/? D/[SUI] AnytimeUIBroadcastReceiver: action: com.oculus.intent.action.MOUNT_STATE_CHANGED
    537. 2022-07-22 10:17:12.577 31879-32159/? W/PresenceAPKNative(hyperspace_controller_module): is_mounted: 1
    538. 2022-07-22 10:17:12.577 31716-32053/? I/[OAO] ShellOverlayApp: ResolveDeviceState: change from Sleep to Awake
    539. 2022-07-22 10:17:12.577 31716-32053/? D/[OAO] ShellApplication: ShellApplication isDeviceLocked
    540. 2022-07-22 10:17:12.577 18663-18663/? I/Distortion: SetLensPositions - iad=0.063, left offset=0.000250001,0, right offset=-0.000250001,0
    541. 2022-07-22 10:17:12.577 852-1102/? I/[CT]: BoltSdkFramework: Orb::setup(): RMgr ref count changed from 3 to 4
    542. 2022-07-22 10:17:12.577 852-1102/? I/[CT]: BoltSdkFramework: OrbDescriptor: RMgr ref count changed from 4 to 5
    543. 2022-07-22 10:17:12.577 852-1102/? I/[CT]: BoltSDK::Soc-Hexagon: defaultMemPool: Hexagon ref count changed from 4 to 5
    544. 2022-07-22 10:17:12.577 852-1102/? I/[CT]: BoltSDK::Soc-Hexagon: DEFAULT HexagonPool:OrbDescriptor::init: Hexagon ref count changed from 5 to 6
    545. 2022-07-22 10:17:12.577 18663-18663/? I/Distortion: SetLensPositions - iad=0.063, left offset=0.000250001,0, right offset=-0.000250001,0
    546. 2022-07-22 10:17:12.577 852-1102/? I/[CT]: BoltSDK::Soc-Hexagon: defaultMemPool: Hexagon ref count changed from 6 to 5
    547. 2022-07-22 10:17:12.577 18663-18663/? I/CompositorVR: ---------------- CompositorVR() ----------------
    548. 2022-07-22 10:17:12.577 852-1102/? I/[CT]: BoltSDK::Soc-Hexagon: defaultMemPool: Hexagon ref count changed from 5 to 6
    549. 2022-07-22 10:17:12.577 852-1102/? I/[CT]: BoltSDK::Soc-Hexagon: DEFAULT HexagonPool:OrbDescriptorCreateKernel: Hexagon ref count changed from 6 to 7
    550. 2022-07-22 10:17:12.577 852-1102/? I/[CT]: BoltSDK::Soc-Hexagon: defaultMemPool: Hexagon ref count changed from 7 to 6
    551. 2022-07-22 10:17:12.577 32347-32347/? D/[SEO] BaseOverlayService: screenStateReceiver Received broadcast: com.oculus.intent.action.MOUNT_STATE_CHANGED
    552. 2022-07-22 10:17:12.577 18663-18663/? I/CompositorVR: AbuseReportCaptureEnabled=0
    553. 2022-07-22 10:17:12.577 18663-18663/? I/CompositorVR: ForceChroma on
    554. 2022-07-22 10:17:12.578 18663-18663/? I/CompositorVR: CheckDebuggerConnected: debugger 0
    555. 2022-07-22 10:17:12.578 18663-18663/? I/CompositorVR: warpMeshClipMode = 1
    556. 2022-07-22 10:17:12.578 852-1102/? I/[CT]: BoltSdkFramework: ViperPlatform: RMgr ref count changed from 5 to 6
    557. 2022-07-22 10:17:12.578 18663-18663/? I/CompositorVR: colorScale: 1.000000 1.000000 1.000000
    558. 2022-07-22 10:17:12.578 852-1102/? I/[CT]: BoltSdkFramework: HarrisCornerObject: RMgr ref count changed from 6 to 7
    559. 2022-07-22 10:17:12.578 852-1102/? I/[CT]: BoltSdkFramework: Orb::setup(): RMgr ref count changed from 7 to 8
    560. 2022-07-22 10:17:12.578 852-1102/? I/[CT]: MontereyPyramidPoolAllocator: allocating 25Mb
    561. 2022-07-22 10:17:12.578 852-1102/? I/[CT]: BoltSDK::Soc-Hexagon: TrackerImagePyramidAllocator: Hexagon ref count changed from 6 to 7
    562. 2022-07-22 10:17:12.578 852-1102/? D//system/bin/trackingservice: src/rpcmem_android.c:172::info: calling: NULL != (m = malloc(sizeof(*m)))
    563. 2022-07-22 10:17:12.578 852-1102/? D//system/bin/trackingservice: src/rpcmem_android.c:172::info: passed: NULL != (m = malloc(sizeof(*m)))
    564. 2022-07-22 10:17:12.578 852-1102/? D//system/bin/trackingservice: src/rpcmem_android.c:193::info: calling: !(rpc_flags & RPCMEM_HEAP_UNCACHED)
    565. 2022-07-22 10:17:12.578 852-1102/? D//system/bin/trackingservice: src/rpcmem_android.c:193::info: passed: !(rpc_flags & RPCMEM_HEAP_UNCACHED)
    566. 2022-07-22 10:17:12.578 852-1102/? D//system/bin/trackingservice: src/rpcmem_android.c:426:ION version is new
    567. 2022-07-22 10:17:12.578 852-1102/? D//system/bin/trackingservice: src/rpcmem_android.c:331::info: calling: 0 < rpcmem_ionfd
    568. 2022-07-22 10:17:12.578 852-1102/? D//system/bin/trackingservice: src/rpcmem_android.c:331::info: passed: 0 < rpcmem_ionfd
    569. 2022-07-22 10:17:12.578 852-1102/? D//system/bin/trackingservice: src/rpcmem_android.c:340:alloc data 0x0x7b0b595fa0, heap mask 0x2000000, flags 0x1
    570. 2022-07-22 10:17:12.578 852-1102/? D//system/bin/trackingservice: src/rpcmem_android.c:347:mmap data 0x0x7b0b595fa0
    571. 2022-07-22 10:17:12.578 852-1102/? D//system/bin/trackingservice: src/rpcmem_android.c:355::info: calling: MAP_FAILED != (m->paddr = (void *)mmap(NULL, alloc.len, PROT_READ|PROT_WRITE, MAP_SHARED, m->data.fd, 0))
    572. 2022-07-22 10:17:12.578 18663-18663/? W/CompositorVR: GetNightShiftWhitePoint: night_shift_activated is not set
    573. 2022-07-22 10:17:12.578 852-1102/? D//system/bin/trackingservice: src/rpcmem_android.c:355::info: passed: MAP_FAILED != (m->paddr = (void *)mmap(NULL, alloc.len, PROT_READ|PROT_WRITE, MAP_SHARED, m->data.fd, 0))
    574. 2022-07-22 10:17:12.578 852-1102/? D//system/bin/trackingservice: src/rpcmem_android.c:215:rpcmem register buf: heap mask: 0x2000000
    575. 2022-07-22 10:17:12.579 1484-1548/? W/PresenceAPKNative(hyperspace_controller_module): is_mounted: 1
    576. 2022-07-22 10:17:12.579 7462-7462/? W/VRLifecycleManager: onHeadsetMounted
    577. 2022-07-22 10:17:12.579 18034-8768/? D/CCodec: allocate(c2.android.vorbis.decoder)
    578. 2022-07-22 10:17:12.579 18097-18248/? D/VrPowerManagerService: processing message: system wakeup
    579. 2022-07-22 10:17:12.579 18097-18248/? I/AutomationTest: ResumeFromSuspendTimeTests: system wakeup
    580. 2022-07-22 10:17:12.579 852-1102/? I/[CT]: HexagonMemMgr: Allocated addr 0x7aebbf0000, with FD 27, and virtAddr 0xa000000
    581. 2022-07-22 10:17:12.579 852-1102/? I/[CT]: BOLT:HexagonShim: memtest is a success
    582. 2022-07-22 10:17:12.579 852-1102/? I/[CT]: HexagonMemMgr: HexagonMemTest returned 0
    583. 2022-07-22 10:17:12.579 852-1102/? I/[CT]: BoltSDK::Soc-Hexagon: Reserved RpcMemory bytes = 27866592
    584. 2022-07-22 10:17:12.580 852-1102/? I/[CT]: ImagePyramid: Creating pyramid pool of size 60 for resolution 640x480, subsample method 3x3
    585. 2022-07-22 10:17:12.580 852-1102/? I/[CT]: VIPER: Setting calibration handler.
    586. 2022-07-22 10:17:12.580 852-1102/? I/[CT]: SlamFactory: Constructing SLAM type: VegaSlam (=0)
    587. 2022-07-22 10:17:12.580 852-1102/? I/[CT]: SlamFactory:   Available SLAM types: 1
    588. 2022-07-22 10:17:12.580 852-1102/? I/[CT]: TrackerFactoryVega: Constructing tracker factory vega: 0
    589. 2022-07-22 10:17:12.580 18663-18663/? I/Vsync: ---------------- Vsync::Init ----------------
    590. 2022-07-22 10:17:12.580 18663-18663/? I/Vsync: Adjusting vsync display refresh rate 72.000000 -> 72.000000
    591. 2022-07-22 10:17:12.580 852-1102/? W/[CT]: VIPER:VIO: Treating initial calibration as nominal. Ocal not allowed to change the camera extrinsics by more than 2 mm
    592. 2022-07-22 10:17:12.580 845-1047/? V/C2Store: in init
    593. 2022-07-22 10:17:12.580 852-1102/? W/[CT]: SQRFilter: Adjusting extraTimestampPaddingMicroSec from 0.002000000 [sec] to 0.000000000 [sec]
    594. 2022-07-22 10:17:12.580 845-1047/? V/C2Store: loading dll
    595. 2022-07-22 10:17:12.580 852-1102/? W/[CT]: SQRFilter: Adjusting filterMaxActiveObservations from -1 to 28800
    596. 2022-07-22 10:17:12.580 852-1102/? W/[CT]: SQRFilter: Adjusting covInflationSettings.epsilon from 3e-05 to 0
    597. 2022-07-22 10:17:12.584 18034-8768/? I/CCodec: Created component [c2.android.vorbis.decoder]
    598. 2022-07-22 10:17:12.585 18034-8768/? D/CCodecConfig: read media type: audio/vorbis
    599. 2022-07-22 10:17:12.586 6810-6810/? W/VRLifecycleManager: onHeadsetMounted
    600. 2022-07-22 10:17:12.586 6810-6810/? W/VRLifecycleManager: onHeadsetMounted
    601. 2022-07-22 10:17:12.588 852-1102/? I/[CT]: SQRLinAlgContainer: Initialized matrices with maximumSize 324
    602. 2022-07-22 10:17:12.588 852-1102/? I/[CT]: BoltSDK::Soc-Hexagon: defaultMemPool: Hexagon ref count changed from 7 to 8
    603. 2022-07-22 10:17:12.588 852-1102/? I/[CT]: BoltSDK::Soc-Hexagon: DEFAULT HexagonPool:HarrisCornersDetector: Hexagon ref count changed from 8 to 9
    604. 2022-07-22 10:17:12.588 852-1102/? I/[CT]: BoltSDK::Soc-Hexagon: defaultMemPool: Hexagon ref count changed from 9 to 8
    605. 2022-07-22 10:17:12.588 852-1102/? I/[CT]: BoltSDK::Soc-Hexagon: defaultMemPool: Hexagon ref count changed from 8 to 9
    606. 2022-07-22 10:17:12.588 852-1102/? I/[CT]: BoltSDK::Soc-Hexagon: DEFAULT HexagonPool:HarrisCorners: Hexagon ref count changed from 9 to 10
    607. 2022-07-22 10:17:12.588 852-1102/? I/[CT]: BoltSDK::Soc-Hexagon: defaultMemPool: Hexagon ref count changed from 10 to 9
    608. 2022-07-22 10:17:12.589 18034-8768/? D/ReflectedParamUpdater: extent() != 1 for single value type: algo.buffers.max-count.values
    609. 2022-07-22 10:17:12.589 18034-8768/? D/ReflectedParamUpdater: extent() != 1 for single value type: output.subscribed-indices.values
    610. 2022-07-22 10:17:12.589 18034-8768/? D/ReflectedParamUpdater: extent() != 1 for single value type: input.buffers.allocator-ids.values
    611. 2022-07-22 10:17:12.589 18034-8768/? D/ReflectedParamUpdater: extent() != 1 for single value type: output.buffers.allocator-ids.values
    612. 2022-07-22 10:17:12.589 18034-8768/? D/ReflectedParamUpdater: extent() != 1 for single value type: algo.buffers.allocator-ids.values
    613. 2022-07-22 10:17:12.589 18034-8768/? D/ReflectedParamUpdater: extent() != 1 for single value type: output.buffers.pool-ids.values
    614. 2022-07-22 10:17:12.590 18034-8768/? D/ReflectedParamUpdater: extent() != 1 for single value type: algo.buffers.pool-ids.values
    615. 2022-07-22 10:17:12.590 852-1102/? I/[CT]: BoltSDK::Soc-Hexagon: defaultMemPool: Hexagon ref count changed from 9 to 10
    616. 2022-07-22 10:17:12.590 852-1102/? I/[CT]: BoltSDK::Soc-Hexagon: DEFAULT HexagonPool:LineSearch: Hexagon ref count changed from 10 to 11
    617. 2022-07-22 10:17:12.590 852-1102/? I/[CT]: BoltSDK::Soc-Hexagon: defaultMemPool: Hexagon ref count changed from 11 to 10
    618. 2022-07-22 10:17:12.590 852-1102/? I/[CT]: BoltSDK::Soc-Hexagon: defaultMemPool: Hexagon ref count changed from 10 to 11
    619. 2022-07-22 10:17:12.590 852-1102/? I/[CT]: BoltSDK::Soc-Hexagon: DEFAULT HexagonPool:PatchMatcherBoltCV: Hexagon ref count changed from 11 to 12
    620. 2022-07-22 10:17:12.590 852-1102/? I/[CT]: BoltSDK::Soc-Hexagon: defaultMemPool: Hexagon ref count changed from 12 to 11
    621. 2022-07-22 10:17:12.590 852-1102/? I/[CT]: VIPER: start initialization called.
    622. 2022-07-22 10:17:12.590 852-1102/? I/[CT]: VegaTracker: Clearing VegaTracker
    623. 2022-07-22 10:17:12.590 852-1102/? I/[CT]: VegaTrackTracker: Resetting VegaTrackTracker!
    624. 2022-07-22 10:17:12.590 852-1102/? I/[CT]: VEGA:PERCEPTUAL_HM: Forcing PerceptualTrackingStatus to Orientation because we're initializing.
    625. 2022-07-22 10:17:12.590 852-1102/? W/[CT]: VIPER:VIO: Treating initial calibration as nominal. Ocal not allowed to change the camera extrinsics by more than 2 mm
    626. 2022-07-22 10:17:12.590 852-1102/? W/[CT]: SQRFilter: Adjusting extraTimestampPaddingMicroSec from 0.002000000 [sec] to 0.000000000 [sec]
    627. 2022-07-22 10:17:12.590 852-1102/? W/[CT]: SQRFilter: Adjusting filterMaxActiveObservations from -1 to 28800
    628. 2022-07-22 10:17:12.590 852-1102/? W/[CT]: SQRFilter: Adjusting covInflationSettings.epsilon from 3e-05 to 0
    629. 2022-07-22 10:17:12.592 18034-8768/? I/CCodecConfig: query failed after returning 7 values (BAD_INDEX)
    630. 2022-07-22 10:17:12.592 18034-8768/? D/CCodecConfig: c2 config diff is Dict {
    631.      c2::u32 coded.bitrate.value = 64000
    632.      c2::u32 input.buffers.max-size.value = 32768
    633.      c2::u32 input.delay.value = 0
    634.      string input.media-type.value = "audio/vorbis"
    635.      string output.media-type.value = "audio/raw"
    636.      c2::u32 raw.channel-count.value = 1
    637.      c2::u32 raw.sample-rate.value = 48000
    638.    }
    639. 2022-07-22 10:17:12.593 852-1102/? I/[CT]: SQRLinAlgContainer: Initialized matrices with maximumSize 324
    640. 2022-07-22 10:17:12.594 852-1102/? I/[CT]: VIPER:MAP_MANAGER_INTERNAL: Initializing MapManagerInternal.
    641. 2022-07-22 10:17:12.594 852-1102/? I/[CT]: VIPER:MAP_MANAGER: Map Manager: SLEEP -> STANDBY
    642. 2022-07-22 10:17:12.594 852-1102/? I/[CT]: BoltSDK::Soc-Hexagon: defaultMemPool: Hexagon ref count changed from 11 to 12
    643. 2022-07-22 10:17:12.594 852-1102/? I/[CT]: BoltSDK::Soc-Hexagon: DEFAULT HexagonPool:HarrisCornersDetector: Hexagon ref count changed from 12 to 13
    644. 2022-07-22 10:17:12.594 852-1102/? I/[CT]: BoltSDK::Soc-Hexagon: defaultMemPool: Hexagon ref count changed from 13 to 12
    645. 2022-07-22 10:17:12.594 852-1102/? I/[CT]: BoltSDK::Soc-Hexagon: defaultMemPool: Hexagon ref count changed from 12 to 13
    646. 2022-07-22 10:17:12.594 852-1102/? I/[CT]: BoltSDK::Soc-Hexagon: DEFAULT HexagonPool:HarrisCorners: Hexagon ref count changed from 13 to 14
    647. 2022-07-22 10:17:12.594 852-1102/? I/[CT]: BoltSDK::Soc-Hexagon: defaultMemPool: Hexagon ref count changed from 14 to 13
    648. 2022-07-22 10:17:12.594 852-1102/? I/[CT]: BoltSdkFramework: Orb::setup(): RMgr ref count changed from 8 to 9
    649. 2022-07-22 10:17:12.594 852-1102/? I/[CT]: DescriptorExtractor: Creating descriptor extractor: boltcv
    650. 2022-07-22 10:17:12.594 852-1102/? I/[CT]: BoltSDK::Soc-Hexagon: defaultMemPool: Hexagon ref count changed from 13 to 14
    651. 2022-07-22 10:17:12.594 852-1102/? I/[CT]: BoltSDK::Soc-Hexagon: DEFAULT HexagonPool:OrbDescriptorCreateKernel: Hexagon ref count changed from 14 to 15
    652. 2022-07-22 10:17:12.594 852-1102/? I/[CT]: BoltSDK::Soc-Hexagon: defaultMemPool: Hexagon ref count changed from 15 to 14
    653. 2022-07-22 10:17:12.595 852-1102/? E/[CT]: InternalAnchorApiServerCapabilityImpl: onHeartbeat called when capability is stopped!
    654. 2022-07-22 10:17:12.595 852-1102/? I/[CT]: InternalAnchorApiServerCapabilityImpl: onStart
    655. 2022-07-22 10:17:12.595 852-1102/? I/ipcLoader_static: RuntimeIPC: Loader: IPC Service API Loader Version: 29 Jul  7 2022 10:23:09
    656. 2022-07-22 10:17:12.595 852-1102/? I/RuntimeIPCApi: ipc_Initialize
    657. 2022-07-22 10:17:12.597 31716-32053/? D/DeviceHelper: isDeviceLocked = true
    658. 2022-07-22 10:17:12.597 31716-32053/? I/[OAO] ShellOverlayApp: ResolveDeviceState: checking device lock status : 1
    659. 2022-07-22 10:17:12.597 31716-32053/? I/[OAO] ShellOverlayApp: ResolveDeviceState: Setting device state to Locked
    660. 2022-07-22 10:17:12.597 31716-32053/? I/[OAO] ShellOverlayApp: Start sleep timeout. Now:736122.929412, Timeout:736124.929412
    661. 2022-07-22 10:17:12.602 18034-8768/? D/CCodecConfig: no c2 equivalents for durationUs
    662. 2022-07-22 10:17:12.602 18034-8768/? D/CCodecConfig: no c2 equivalents for csd-1
    663. 2022-07-22 10:17:12.602 18034-8768/? D/CCodecConfig: no c2 equivalents for channel-mask
    664. 2022-07-22 10:17:12.602 18034-8768/? D/CCodecConfig: c2 config diff is   c2::u32 raw.channel-count.value = 2
    665. 2022-07-22 10:17:12.604 18034-8768/? W/Codec2Client: query -- param skipped: index = 1107298332.
    666. 2022-07-22 10:17:12.604 18034-8768/? D/CCodec: setup formats input: AMessage(what = 0x00000000) = {
    667.      int32_t channel-count = 2
    668.      int32_t max-input-size = 32768
    669.      string mime = "audio/vorbis"
    670.      int32_t sample-rate = 48000
    671.    } and output: AMessage(what = 0x00000000) = {
    672.      int32_t channel-count = 2
    673.      string mime = "audio/raw"
    674.      int32_t sample-rate = 48000
    675.      int32_t channel-mask = 3
    676.    }
    677. 2022-07-22 10:17:12.604 18034-8768/? I/MediaCodec: MediaCodec will operate in async mode
    678. 2022-07-22 10:17:12.604 18034-8768/? W/Codec2Client: query -- param skipped: index = 1342179345.
    679. 2022-07-22 10:17:12.604 18034-8768/? W/Codec2Client: query -- param skipped: index = 2415921170.
    680. 2022-07-22 10:17:12.606 18034-8768/? D/CCodecBufferChannel: [c2.android.vorbis.decoder#941] Created input block pool with allocatorID 16 => poolID 33 - OK (0)
    681. 2022-07-22 10:17:12.606 845-1047/? D/BufferPoolAccessor: bufferpool2 0x2fa3e07830 : 0(0 size) total buffers - 0(0 size) used buffers - 10/13 (recycle/alloc) - 3/12 (fetch/transfer)
    682. 2022-07-22 10:17:12.606 845-1047/? D/BufferPoolAccessor: Destruction - bufferpool2 0x2fa3e07830 cached: 0/0M, 0/0% in use; allocs: 13, 77% recycled; transfers: 12, 75% unfetced
    683. 2022-07-22 10:17:12.606 18034-18298/? D/BufferPoolAccessor: bufferpool2 0xeee9a410 : 0(0 size) total buffers - 0(0 size) used buffers - 8/19 (recycle/alloc) - 11/30 (fetch/transfer)
    684. 2022-07-22 10:17:12.606 18034-18298/? D/BufferPoolAccessor: Destruction - bufferpool2 0xeee9a410 cached: 0/0M, 0/0% in use; allocs: 19, 42% recycled; transfers: 30, 63% unfetced
    685. 2022-07-22 10:17:12.607 18034-8768/? I/CCodecBufferChannel: [c2.android.vorbis.decoder#941] Created output block pool with allocatorID 16 => poolID 489 - OK
    686. 2022-07-22 10:17:12.607 18034-8768/? D/CCodecBufferChannel: [c2.android.vorbis.decoder#941] Configured output block pool ids 489 => OK
    687. 2022-07-22 10:17:12.607 852-1102/? I/DeadlockObserver: Init SUCCESS
    688. 2022-07-22 10:17:12.607 852-8777/? I/DeadlockObserver: MainLoop starting
    689. 2022-07-22 10:17:12.608 852-1102/? I/RuntimeIPCServiceClient: Using OS RuntimeIPC Service
    690. 2022-07-22 10:17:12.608 852-8778/? I/AsyncTaskMgr: MainLoop starting
    691. 2022-07-22 10:17:12.608 852-1102/? I/AsyncTaskMgr: Init SUCCESS
    692. 2022-07-22 10:17:12.608 852-1102/? I/ServerStateMgr: Init
    693. 2022-07-22 10:17:12.608 852-1102/? I/RuntimeIPCServiceClientRPC: InitRPCToServiceInternal: Calling Methods->GetConnectInfo
    694. 2022-07-22 10:17:12.609 817-26895/? I/RuntimeIPCService: CreateBrokerConnection: 852:native_process.system:/system/bin/trackingservice
    695. 2022-07-22 10:17:12.610 852-1102/? I/RuntimeIPCServiceClientRPC: InitRPCToServiceInternal: Calling Helper.Init
    696. 2022-07-22 10:17:12.610 852-1102/? I/RuntimeIPCServiceClientRPC: InitRPCToServiceInternal: Calling InitBrokerHandler
    697. 2022-07-22 10:17:12.613 852-1102/? I/RuntimeIPCServiceClientRPC: InitRPCToServiceInternal: Success
    698. 2022-07-22 10:17:12.613 852-1102/? I/ServerStateMgr: Init
    699. 2022-07-22 10:17:12.613 852-1102/? I/RuntimeIPCServiceClient: IPCMainLoopHandler: Init SUCCESS
    700. 2022-07-22 10:17:12.613 852-1102/? I/ServerStateBuffer: MaxEntries=64 MaxBufferSize=32768 StateBufferOffset=2600
    701. 2022-07-22 10:17:12.613 852-1102/? I/ServerStateMgr: Init
    702. 2022-07-22 10:17:12.613 852-1102/? I/RuntimeIPCServerMgr: RegisterServer: SUCCESS: native_process.system:/system/bin/trackingservice (SlamAnchorServer)
    703. 2022-07-22 10:17:12.613 852-1102/? I/[CT]: SpatialPersistenceCapabilityImpl: onStart
    704. 2022-07-22 10:17:12.617 760-8753/? I/SyncBossFW: 1689144 [info   ] {APPI}: Enabling IMU
    705. 2022-07-22 10:17:12.618 18035-18070/? I/netd: firewallSetUidRule(2, 10018, 1) <0.02ms>
    706. 2022-07-22 10:17:12.621 845-8772/? D/SimpleC2Component: Using output block pool with poolID 489 => got 489 - 0
    707. 2022-07-22 10:17:12.622 852-1102/? I/TrackingService: [            iot] SLEEP -> STANDBY transition time: 60 ms
    708. 2022-07-22 10:17:12.623 852-8783/? D/TrackingService: starting IOT motion thread, imu batch dispatch enabled=false
    709. 2022-07-22 10:17:12.624 760-8753/? I/SyncBossFW: 1689148 [info   ] {APPI}: Enabling magnetometer
    710. 2022-07-22 10:17:12.624 760-8753/? I/SyncBossFW: 1689149 [info   ] {APPI}: Enabling mag streaming.  Temperature comp enabled
    711. 2022-07-22 10:17:12.645 852-1102/? I/[CT]: ConstellationTrackingCapabilityTranslation: onStart
    712. 2022-07-22 10:17:12.646 852-1102/? I/[CT]: INPUT_TRACKING:Behavior:AtRest: [Right] reset
    713. 2022-07-22 10:17:12.646 852-1102/? I/[CT]: INPUT_TRACKING:Behavior:AtRest: [Left] reset
    714. 2022-07-22 10:17:12.646 852-1102/? I/[CT]: INPUT_TRACKING:Blackboard: reset
    715. 2022-07-22 10:17:12.647 852-1102/? I/TrackingService: ConstellationTrackingGlue: setEnableExtendedDeadreckoning to false
    716. 2022-07-22 10:17:12.647 852-1102/? I/TrackingService: [  constellation] SLEEP -> STANDBY transition time: 24 ms
    717. 2022-07-22 10:17:12.647 852-1102/? I/TrackingService: [           hand] SLEEP -> STANDBY transition time: 0 ms
    718. 2022-07-22 10:17:12.660 852-1102/? I/[CT]: ObjectTrackingCapabilityTranslation: onStart
    719. 2022-07-22 10:17:12.660 852-1102/? I/[CT]: KEYBOARD: ObjectTrackingEngine::onStart() - Current State: Configured.
    720. 2022-07-22 10:17:12.660 852-1102/? I/TrackingService: [         object] SLEEP -> STANDBY transition time: 12 ms
    721. 2022-07-22 10:17:12.660 760-8753/? W/SyncBossFW: 1689186 [warning] {SPTH}: [rate_lim=1000] Big IMU diff (404695058us)
    722. 2022-07-22 10:17:12.662 852-1102/? I/TrackingService: [     controller] SLEEP -> STANDBY transition time: 2 ms
    723. 2022-07-22 10:17:12.662 852-1102/? I/[CT]: ExposureControlCapabilityImpl: onStart
    724. 2022-07-22 10:17:12.662 852-1102/? I/TrackingService: [ExposureControl] SLEEP -> STANDBY transition time: 0 ms
    725. 2022-07-22 10:17:12.662 852-1100/? D/TrackingService: setPowerState: STANDBY
    726. 2022-07-22 10:17:12.662 852-1100/? D/SensorClientUtils: Executing transition from STANDBY to RUNNING
    727. 2022-07-22 10:17:12.662 852-1100/? D/SensorClientUtils: Setting power state to RUNNING
    728. 2022-07-22 10:17:12.662 760-760/? D/SensorService: ControllerProvider: acquiring StreamingClient impl; approx # alive: 2
    729. 2022-07-22 10:17:12.662 760-760/? D/libsensorscommon: ControllerProvider: acquiring StreamingClient hidl
    730. 2022-07-22 10:17:12.662 852-8762/? D/OVRRemoteService: processStateChange([PairedControllerInfo JEDI e6e349e957f83390 disconnected update-required mcnt=0])
    731. 2022-07-22 10:17:12.662 852-8762/? D/OVRRemoteService: processStateChange([PairedControllerInfo JEDI 4a4d8199d5955b23 disconnected update-required mcnt=0])
    732. 2022-07-22 10:17:12.662 852-1100/? E/libwakelock: system: Failed to acquire wakelock trackingservice.powermonitor; refcnt=0, powerManager=true, status=-32
    733. 2022-07-22 10:17:12.663 852-1102/? I/TrackingService: [ vision_manager] STANDBY -> RUNNING transition time: 0 ms
    734. 2022-07-22 10:17:12.663 18037-18050/? I/audio_hw_primary: getting vr mode to 0
    735. 2022-07-22 10:17:12.664 852-8788/? D/RemoteService: RemoteService - Registering status callback
    736. 2022-07-22 10:17:12.664 18033-3951/? I/AudioPolicyManagerCustom: VR mode is 0, switch to primary output if request is for fast|raw
    737. 2022-07-22 10:17:12.664 852-1102/? I/TrackingService: [            iad] STANDBY -> RUNNING transition time: 1 ms
    738. 2022-07-22 10:17:12.664 852-1102/? I/TrackingService: [           bolt] STANDBY -> RUNNING transition time: 0 ms
    739. 2022-07-22 10:17:12.664 18033-3951/? I/AudioPolicyManagerCustom: FLAG None hence request for a primary output
    740. 2022-07-22 10:17:12.664 18033-3951/? D/AudioFlinger: Client defaulted notificationFrames to 12000 for frameCount 24000
    741. 2022-07-22 10:17:12.665 18033-3951/? D/AF::TrackHandle: OpPlayAudio: not muting track:108 flags 0xc40 have FLAG_BYPASS_INTERRUPTION_POLICY
    742. 2022-07-22 10:17:12.667 760-8755/? W/SensorService: Data for sensor type HMD_MAG dropped because of failure to update clock drift from vsync. 1 drops in the last 0s.
    743. 2022-07-22 10:17:12.658 760-760/? W/sensors@1.0-ser: type=1400 audit(0.0:1597): avc: denied { getattr } for path="/proc/852" dev="proc" ino=16462 scontext=u:r:hal_oculus_sensors:s0 tcontext=u:r:trackingserver:s0 tclass=dir permissive=0
    744. 2022-07-22 10:17:12.670 760-760/? E/libosutils: failed to get real path of file /proc/852/cmdline, err: Permission denied
    745. 2022-07-22 10:17:12.671 18037-19747/? D/audio_hw_primary: start_output_stream: enter: stream(0xef239000)usecase(1: low-latency-playback) devices(0x2) is_haptic_usecase(0)
    746. 2022-07-22 10:17:12.671 18037-19747/? I/audio_hw_primary: select_devices for use case (low-latency-playback)
    747. 2022-07-22 10:17:12.671 18037-19747/? I/msm8974_platform: platform_check_and_set_codec_backend_cfg:becf: afe: bitwidth 16, samplerate 48000 channels 2, backend_idx 0 usecase = 1 device (speaker)
    748. 2022-07-22 10:17:12.671 18037-19747/? D/msm8974_platform: platform_split_snd_device: snd_device(2) num devices(1) new_snd_devices(0)
    749. 2022-07-22 10:17:12.671 18037-19747/? I/msm8974_platform: platform_check_and_set_codec_backend_cfg: new_snd_devices[0] is 2
    750. 2022-07-22 10:17:12.671 18037-19747/? I/msm8974_platform: platform_check_codec_backend_cfg:becf: afe: bitwidth 16, samplerate 48000 channels 2, backend_idx 0 usecase = 1 device (speaker)
    751. 2022-07-22 10:17:12.672 760-760/? I/FrameSetDispatcher: [HEADSET] Client thread started
    752. 2022-07-22 10:17:12.672 760-760/? I/CameraClientManager: [HEADSET] Added client - started clients: 1
    753. 2022-07-22 10:17:12.672 18037-19747/? D/audio_hw_extn: audio_extn_enable_hifi_filter: mixer_value set 0
    754. 2022-07-22 10:17:12.672 18037-19747/? D/msm8974_platform: platform_check_codec_backend_cfg:becf: updated afe: bitwidth 16, samplerate 48000 channels 2,backend_idx 0 usecase = 1 device (speaker)
    755. 2022-07-22 10:17:12.672 18037-19747/? D/msm8974_platform: platform_check_codec_backend_cfg:becf: afe: playback on codec device not supporting native playback set default Sample Rate(48k)
    756. 2022-07-22 10:17:12.672 18037-19747/? I/msm8974_platform: platform_check_codec_backend_cfg:becf: afe: Codec selected backend: 0 updated bit width: 16 and sample rate: 48000
    757. 2022-07-22 10:17:12.672 18037-19747/? D/audio_hw_primary: check_usecases_codec_backend:becf: force routing 0
    758. 2022-07-22 10:17:12.672 18037-19747/? E/msm8974_platform: platform_check_backends_match: Invalid snd_device =
    759. 2022-07-22 10:17:12.672 18037-19747/? D/audio_hw_primary: check_usecases_codec_backend:becf: (75) check_usecases curr device: speaker, usecase device: backends match 0
    760. 2022-07-22 10:17:12.672 18037-19747/? D/audio_hw_primary: check_usecases_codec_backend:becf: check_usecases num.of Usecases to switch 0
    761. 2022-07-22 10:17:12.672 18037-19747/? D/hardware_info: hw_info_append_hw_type : device_name = speaker
    762. 2022-07-22 10:17:12.672 18037-19747/? D/msm8974_platform: platform_split_snd_device: snd_device(2) num devices(0) new_snd_devices(0)
    763. 2022-07-22 10:17:12.672 18037-19747/? D/audio_hw_primary: enable_snd_device: snd_device(2: speaker)
    764. 2022-07-22 10:17:12.672 18037-19747/? D/audio_route: Apply path: speaker
    765. 2022-07-22 10:17:12.674 18034-8768/? D/CCodecBufferChannel: [c2.android.vorbis.decoder#941] buffers after EOS ignored (0 us)
    766. 2022-07-22 10:17:12.675 18034-8768/? I/chatty: uid=1013(media) NPDecoder-CL identical 1 line
    767. 2022-07-22 10:17:12.675 18034-8768/? D/CCodecBufferChannel: [c2.android.vorbis.decoder#941] buffers after EOS ignored (0 us)
    768. 2022-07-22 10:17:12.677 18037-19747/? I/audio_hw_utils: audio_extn_utils_update_stream_output_app_type_cfg Allowing 24 and above bits playback on speaker ONLY at default sampling rate
    769. 2022-07-22 10:17:12.677 18037-19747/? D/audio_hw_utils: audio_extn_utils_send_app_type_cfg: usecase->out_snd_device speaker
    770. 2022-07-22 10:17:12.677 18037-19747/? D/msm8974_platform: platform_split_snd_device: snd_device(2) num devices(0) new_snd_devices(0)
    771. 2022-07-22 10:17:12.677 18034-8766/? D/AudioTrack: stop(85): called with 11233 frames delivered
    772. 2022-07-22 10:17:12.677 18037-19747/? D/audio_hw_utils: audio_extn_btsco_get_sample_rate:Not a BT SCO device, need not update sampling rate
    773. 2022-07-22 10:17:12.677 18037-19747/? I/audio_hw_utils: send_app_type_cfg_for_device PLAYBACK app_type 69943, acdb_dev_id 15, sample_rate 48000, snd_device_be_idx 43
    774. 2022-07-22 10:17:12.677 18037-19747/? D/msm8974_platform: platform_split_snd_device: snd_device(2) num devices(1) new_snd_devices(0)
    775. 2022-07-22 10:17:12.677 18037-19747/? D/audio_hw_utils: audio_extn_btsco_get_sample_rate:Not a BT SCO device, need not update sampling rate
    776. 2022-07-22 10:17:12.677 18037-19747/? D/ACDB-LOADER: ACDB -> send_audio_cal, acdb_id = 15, path = 0, app id = 0x11137, sample rate = 48000, afe_sample_rate = 48000
    777. 2022-07-22 10:17:12.677 18037-19747/? D/ACDB-LOADER: ACDB -> send_asm_topology
    778. 2022-07-22 10:17:12.677 18037-19747/? D/ACDB-LOADER: ACDB -> ACDB_CMD_GET_AUDPROC_STREAM_TOPOLOGY_ID
    779. 2022-07-22 10:17:12.678 18037-19747/? D/ACDB-LOADER: ACDB -> send_adm_topology
    780. 2022-07-22 10:17:12.678 18037-19747/? D/ACDB-LOADER: ACDB -> ACDB_CMD_GET_AUDPROC_COMMON_TOPOLOGY_ID
    781. 2022-07-22 10:17:12.678 18037-19747/? D/ACDB-LOADER: ACDB -> send_audtable
    782. 2022-07-22 10:17:12.678 18037-19747/? D/ACDB-LOADER: ACDB -> ACDB_CMD_GET_AUDPROC_INSTANCE_COMMON_TABLE_SIZE
    783. 2022-07-22 10:17:12.678 18037-19747/? D/ACDB-LOADER: ACDB -> ACDB_CMD_GET_AUDPROC_INSTANCE_COMMON_TABLE
    784. 2022-07-22 10:17:12.678 18037-19747/? D/ACDB-LOADER: ACDB -> AUDIO_SET_AUDPROC_CAL cal_type[11] acdb_id[15] app_type[69943]
    785. 2022-07-22 10:17:12.678 18037-19747/? D/ACDB-LOADER: ACDB -> ACDB_CMD_GET_PERSISTENT_AUDPROC_INSTANCE_COMMON_TABLE_SIZE
    786. 2022-07-22 10:17:12.678 18037-19747/? D/ACDB-LOADER: Error: ACDB_CMD_GET_PERSISTENT_AUDPROC_INSTANCE_COMMON_TABLE_SIZE returned -18
    787. 2022-07-22 10:17:12.678 18037-19747/? D/ACDB-LOADER: ACDB -> send_audproc_persist_table -18
    788. 2022-07-22 10:17:12.678 18037-19747/? D/ACDB-LOADER: Error: Invalid Audproc persist size = -18
    789. 2022-07-22 10:17:12.678 18037-19747/? D/ACDB-LOADER: ACDB -> send_audvoltable
    790. 2022-07-22 10:17:12.678 18037-19747/? D/ACDB-LOADER: ACDB -> ACDB_CMD_GET_AUDPROC_INSTANCE_GAIN_DEP_STEP_TABLE_SIZE
    791. 2022-07-22 10:17:12.678 18037-19747/? D/ACDB-LOADER: Error: ACDB_CMD_GET_AUDPROC_INSTANCE_GAIN_DEP_STEP_TABLE_SIZE Returned = -19
    792. 2022-07-22 10:17:12.678 18037-19747/? D/ACDB-LOADER: ACDB -> ACDB_CMD_GET_AUDPROC_INSTANCE_GAIN_DEP_STEP_TABLE, vol index 0
    793. 2022-07-22 10:17:12.678 18037-19747/? D/ACDB-LOADER: Error: ACDB AudProc vol returned = -19
    794. 2022-07-22 10:17:12.678 18037-19747/? D/ACDB-LOADER: ACDB -> AUDIO_SET_VOL_CAL cal type = 12
    795. 2022-07-22 10:17:12.678 18037-19747/? D/ACDB-LOADER: ACDB -> ACDB_CMD_GET_AUDPROC_INSTANCE_STREAM_TABLE_SIZE
    796. 2022-07-22 10:17:12.678 18037-19747/? D/ACDB-LOADER: ACDB -> send_audstrmtable
    797. 2022-07-22 10:17:12.678 18037-19747/? D/ACDB-LOADER: ACDB -> ACDB_CMD_GET_AUDPROC_INSTANCE_STREAM_TABLE
    798. 2022-07-22 10:17:12.678 18037-19747/? D/ACDB-LOADER: ACDB -> audstrm_cal->cal_type.cal_data.cal_size = 20
    799. 2022-07-22 10:17:12.678 18037-19747/? D/ACDB-LOADER: ACDB -> send_afe_topology
    800. 2022-07-22 10:17:12.678 18037-19747/? D/ACDB-LOADER: ACDB -> ACDB_CMD_GET_AFE_TOPOLOGY_ID
    801. 2022-07-22 10:17:12.678 18037-19747/? D/ACDB-LOADER: ACDB -> GET_AFE_TOPOLOGY_ID for adcd_id 15, Topology Id 112fc
    802. 2022-07-22 10:17:12.678 18037-19747/? D/ACDB-LOADER: ACDB -> send_afe_cal
    803. 2022-07-22 10:17:12.678 18037-19747/? D/ACDB-LOADER: ACDB -> ACDB_CMD_GET_AFE_INSTANCE_COMMON_TABLE_SIZE
    804. 2022-07-22 10:17:12.678 18037-19747/? D/ACDB-LOADER: Error: ACDB_CMD_GET_AFE_INSTANCE_COMMON_TABLE_SIZE Returned = -19
    805. 2022-07-22 10:17:12.678 18037-19747/? D/ACDB-LOADER: ACDB -> ACDB_CMD_GET_AFE_INSTANCE_COMMON_TABLE
    806. 2022-07-22 10:17:12.678 18037-19747/? D/ACDB-LOADER: Error: ACDB AFE returned = -19
    807. 2022-07-22 10:17:12.678 18037-19747/? D/ACDB-LOADER: ACDB -> AUDIO_SET_AFE_CAL cal_type[16] acdb_id[15]
    808. 2022-07-22 10:17:12.678 18037-19747/? D/ACDB-LOADER: ACDB -> send_hw_delay : acdb_id = 15 path = 0
    809. 2022-07-22 10:17:12.678 18037-19747/? D/ACDB-LOADER: ACDB -> ACDB_AVSYNC_INFO: ACDB_CMD_GET_DEVICE_PROPERTY
    810. 2022-07-22 10:17:12.678 18037-19747/? D/msm8974_platform: platform_split_snd_device: snd_device(2) num devices(0) new_snd_devices(0)
    811. 2022-07-22 10:17:12.678 18037-19747/? I/msm8974_platform: platform_get_custom_mtmx_params: no matching param with id 0 ip_ch 2 op_ch 2 uc_id 1 snd_dev 2
    812. 2022-07-22 10:17:12.678 18037-19747/? I/audio_hw_primary: enable_audio_route: apply mixer and update path: low-latency-playback
    813. 2022-07-22 10:17:12.678 18037-19747/? D/audio_route: Apply path: low-latency-playback
    814. 2022-07-22 10:17:12.678 18037-19747/? D/audio_hw_primary: select_devices: done
    815. 2022-07-22 10:17:12.699 18037-19747/? D/msm8974_platform: platform_set_channel_map mixer_ctl_name:Playback Channel Map9
    816. 2022-07-22 10:17:12.699 18037-19747/? D/msm8974_platform: platform_set_channel_map: set mapping(1 2 0 0 0 0 0 0) for channel:2
    817. 2022-07-22 10:17:12.700 18037-19747/? D/audio_hw_primary: start_output_stream: exit
    818. 2022-07-22 10:17:12.700 18037-19747/? D/audio_hw_primary: out_write: retry previous failed cal level set
    819. 2022-07-22 10:17:12.700 18037-19747/? D/msm8974_platform: platform_split_snd_device: snd_device(2) num devices(1) new_snd_devices(0)
    820. 2022-07-22 10:17:12.772 18752-18780/? I/StateMachine: StateMachine::Update GuardianInitializationStateMachine: mountEvent -> MountedTransition_Black
    821. 2022-07-22 10:17:12.772 18752-18780/? I/GuardianSystem: Headset was mounted
    822. 2022-07-22 10:17:12.772 18752-18780/? I/GuardianSystem: Start pushing black after mount.
    823. 2022-07-22 10:17:12.772 18663-18779/? I/VrRuntimeService: RuntimeServiceSDKServer::SetGuardianSystemState: 280799707
    824. 2022-07-22 10:17:12.816 760-8753/? I/SyncBossFW: 1689342 [info   ] {BCAM}: OV7251 sensors found - 0xf
    825. 2022-07-22 10:17:12.841 760-8753/? I/SyncBossFW: 1689368 [info   ] {APPI}: Camera probe, found: 0xf
    826. 2022-07-22 10:17:12.853 760-760/? I/HollywoodCameraProvider: [HollywoodCameraProvider] Set cameras to 10 bpp (format 0x00000007)
    827. 2022-07-22 10:17:12.858 760-964/? W/SyncBossHAL: [warning] pulsar_manager_type_info.c(23): Unexpected pulsar hardware type received: 0.  Cannot retrieve type info (old unsupported device?)
    828. 2022-07-22 10:17:12.860 760-964/? I/chatty: uid=1000(system) sb_pulsar identical 14 lines
    829. 2022-07-22 10:17:12.861 760-964/? W/SyncBossHAL: [warning] pulsar_manager_type_info.c(23): Unexpected pulsar hardware type received: 0.  Cannot retrieve type info (old unsupported device?)
    830. 2022-07-22 10:17:12.861 760-964/? I/SyncBossHAL: [info   ] pulsar_manager.c(791): No IRLED tracked controllers connected/ready
    831. 2022-07-22 10:17:12.896 852-1102/? I/[CT]: InsideOutTrackingCapabilityTranslation: onResume
    832. 2022-07-22 10:17:12.897 852-1102/? I/[CT]: TELEMETRY_COLLECTOR: Starting periodic telemetry polling...
    833. 2022-07-22 10:17:12.898 852-1102/? I/[CT]: NIMBLE:HLOG: NimbleTelemetryAggregator::populateTelemetry
    834. 2022-07-22 10:17:12.901 852-1102/? I/[CT]: VisionInterface: Activating IO Engine
    835. 2022-07-22 10:17:12.901 852-1102/? I/[CT]: VIPER:MAP_MANAGER: Map Manager: STANDBY -> RUNNING
    836. 2022-07-22 10:17:12.901 852-1102/? I/[CT]: InternalAnchorApiServerCapabilityImpl: onResume
    837. 2022-07-22 10:17:12.901 852-1102/? I/[CT]: SpatialPersistenceCapabilityImpl: onResume
    838. 2022-07-22 10:17:12.901 852-1102/? I/TrackingService: [            iot] STANDBY -> RUNNING transition time: 237 ms
    839. 2022-07-22 10:17:12.901 760-760/? E/libosutils: failed to get real path of file /proc/852/cmdline, err: Permission denied
    840. 2022-07-22 10:17:12.888 760-760/? W/sensors@1.0-ser: type=1400 audit(0.0:1598): avc: denied { getattr } for path="/proc/852" dev="proc" ino=16462 scontext=u:r:hal_oculus_sensors:s0 tcontext=u:r:trackingserver:s0 tclass=dir permissive=0
    841. 2022-07-22 10:17:12.902 760-8753/? I/SyncBossFW: 1689427 [info   ] {APPI}: Starting camera streaming
    842. 2022-07-22 10:17:12.902 760-8753/? I/SyncBossFW: 1689428 [info   ] {BCAM}: Camera streaming started
    843. 2022-07-22 10:17:12.903 760-760/? I/FrameSetDispatcher: [CONTROLLER] Client thread started
    844. 2022-07-22 10:17:12.903 760-760/? I/CameraClientManager: [CONTROLLER] Added client - started clients: 1
    845. 2022-07-22 10:17:12.903 852-1102/? I/[CT]: ConstellationTrackingCapabilityTranslation: onResume
    846. 2022-07-22 10:17:12.903 852-1102/? I/TrackingService: ConstellationTrackingGlue: setEnableExtendedDeadreckoning to false
    847. 2022-07-22 10:17:12.903 852-1102/? I/TrackingService: [  constellation] STANDBY -> RUNNING transition time: 2 ms
    848. 2022-07-22 10:17:12.903 852-1102/? I/TrackingService: [           hand] STANDBY -> RUNNING transition time: 0 ms
    849. 2022-07-22 10:17:12.904 760-760/? E/libosutils: failed to get real path of file /proc/852/cmdline, err: Permission denied
    850. 2022-07-22 10:17:12.888 760-760/? W/sensors@1.0-ser: type=1400 audit(0.0:1599): avc: denied { getattr } for path="/proc/852" dev="proc" ino=16462 scontext=u:r:hal_oculus_sensors:s0 tcontext=u:r:trackingserver:s0 tclass=dir permissive=0
    851. 2022-07-22 10:17:12.905 760-760/? I/FrameSetDispatcher: [HEADSET] Client thread started
    852. 2022-07-22 10:17:12.905 760-760/? I/CameraClientManager: [HEADSET] Added client - started clients: 2
    853. 2022-07-22 10:17:12.905 852-1102/? I/[CT]: ObjectTrackingCapabilityTranslation: onResume
    854. 2022-07-22 10:17:12.905 852-1102/? I/TrackingService: [         object] STANDBY -> RUNNING transition time: 1 ms
    855. 2022-07-22 10:17:12.905 852-1102/? I/TrackingService: [     controller] STANDBY -> RUNNING transition time: 0 ms
    856. 2022-07-22 10:17:12.913 793-793/? D/SurfaceFlinger: setCacPowerMode: mode=2
    857. 2022-07-22 10:17:12.913 32217-32217/? V/AvrcpMediaPlayerList: onPlaybackConfigChanged(): Configs list size=5
    858. 2022-07-22 10:17:12.913 793-793/? I/HWC2: Creating virtual display
    859. 2022-07-22 10:17:12.898 760-760/? W/sensors@1.0-ser: type=1400 audit(0.0:1600): avc: denied { getattr } for path="/proc/852" dev="proc" ino=16462 scontext=u:r:hal_oculus_sensors:s0 tcontext=u:r:trackingserver:s0 tclass=dir permissive=0
    860. 2022-07-22 10:17:12.913 852-1102/? I/TrackingService: Setting initial exposure: 0.005000, initial gain: 3.000000
    861. 2022-07-22 10:17:12.914 760-760/? E/libosutils: failed to get real path of file /proc/852/cmdline, err: Permission denied
    862. 2022-07-22 10:17:12.915 760-760/? I/FrameSetDispatcher: [HEADSET] Client thread started
    863. 2022-07-22 10:17:12.915 760-760/? I/CameraClientManager: [HEADSET] Added client - started clients: 3
    864. 2022-07-22 10:17:12.915 766-1055/? I/SDM: HWCVirtualDisplayFactory::Create: Created DPU based virtual display
    865. 2022-07-22 10:17:12.915 852-1102/? I/[CT]: ExposureControlCapabilityImpl: onResume
    866. 2022-07-22 10:17:12.916 32217-32217/? V/AvrcpMediaPlayerList: onPlaybackConfigChanged(): Configs list size=4
    867. 2022-07-22 10:17:12.916 852-1102/? I/TrackingService: [ExposureControl] STANDBY -> RUNNING transition time: 10 ms
    868. 2022-07-22 10:17:12.916 852-1100/? D/TrackingService: setPowerState: RUNNING
    869. 2022-07-22 10:17:12.916 18097-18248/? V/MediaPlayer: resetDrmState:  mDrmInfo=null mDrmProvisioningThread=null mPrepareDrmInProgress=false mActiveDrmScheme=false
    870. 2022-07-22 10:17:12.916 18097-18248/? V/MediaPlayer: cleanDrmObj: mDrmObj=null mDrmSessionId=null
    871. 2022-07-22 10:17:12.916 18034-1844/? D/NuPlayerDriver: reset(0xeee2e5a0) at state 6
    872. 2022-07-22 10:17:12.917 766-1055/? W/SDM: HWDeviceDRM::PopulateDisplayAttributes: Driver doesn't report panel physical width and height - defaulting to 320dpi
    873. 2022-07-22 10:17:12.918 766-1055/? I/chatty: uid=1000(system) HwBinder:766_2 identical 34 lines
    874. 2022-07-22 10:17:12.918 766-1055/? W/SDM: HWDeviceDRM::PopulateDisplayAttributes: Driver doesn't report panel physical width and height - defaulting to 320dpi
    875. 2022-07-22 10:17:12.918 766-1055/? I/SDM: HWDeviceDRM::UpdateMixerAttributes: Mixer WxH 4096x2160-1 for Virtual
    876. 2022-07-22 10:17:12.918 766-1055/? I/SDM: HWCDisplay::UpdateConfigs: num_configs = 1
    877. 2022-07-22 10:17:12.920 766-1055/? I/SDM: HWCDisplay::Init: Display created with id: 1, game_supported_: 0
    878. 2022-07-22 10:17:12.920 766-1055/? I/SDM: HWDeviceDRM::UpdateMixerAttributes: Mixer WxH 1920x3664-1 for Virtual
    879. 2022-07-22 10:17:12.920 766-1055/? I/SDM: HWVirtualDRM::SetDisplayAttributes: New WB Resolution: 1920x3664 cur_mode_index 2
    880. 2022-07-22 10:17:12.920 766-1055/? I/SDM: InitHDRinterface():127 HDR init done
    881. 2022-07-22 10:17:12.921 766-1055/? I/SDM: HDRIntfClient::GetParameter: Version info is: 2.0
    882. 2022-07-22 10:17:12.921 766-1055/? I/SDM: StrategyImpl::InitializeHdrInfo: HDRLib version = 2.0
    883. 2022-07-22 10:17:12.921 766-1055/? I/SDM: Deinit():195 HDR De-init done
    884. 2022-07-22 10:17:12.921 766-1055/? I/SDM: ResourceImpl::RegisterDisplay: Registering display 47-2 with hw_block 47-4
    885. 2022-07-22 10:17:12.921 766-1055/? I/SDM: InitHDRinterface():127 HDR init done
    886. 2022-07-22 10:17:12.922 766-1055/? I/SDM: HDRIntfClient::GetParameter: Version info is: 2.0
    887. 2022-07-22 10:17:12.922 766-1055/? I/SDM: panel_HDMI_sink_load():30 panel's peak brightness isn't unreasonably, should be in unit of nits. Default val is used!
    888. 2022-07-22 10:17:12.922 766-1055/? I/SDM: ColorIntfClient::Init: Init successful
    889. 2022-07-22 10:17:12.922 766-1055/? I/SDM: DisplayVirtual::SetActiveConfig: Virtual display resolution changed to[1920x3664]
    890. 2022-07-22 10:17:12.922 766-1055/? I/SDM: DisplayBase::SetDisplayState: Set state = 1, display 47-2, teardown = 0
    891. 2022-07-22 10:17:12.922 766-1055/? I/SDM: DisplayBase::SetFrameBufferConfig: New framebuffer resolution (1920x3664)
    892. 2022-07-22 10:17:12.922 766-1055/? I/SDM: HWCDisplay::SetFrameBufferConfig: New framebuffer resolution (1920x3664)
    893. 2022-07-22 10:17:12.922 766-1055/? I/SDM: HWCVirtualDisplayFactory::Create: Creating virtual display: w: 1920 h:3664 format:0x1
    894. 2022-07-22 10:17:12.922 766-1055/? I/SDM: HWCSession::CreateVirtualDisplayObj: Created virtual display id:1 with res: 1920x3664
    895. 2022-07-22 10:17:12.922 766-1055/? I/SDM: HWCSession::CreateVirtualDisplay: Created virtual display id:1, res: 1920x3664
    896. 2022-07-22 10:17:12.923 793-793/? I/HWC2: Created virtual display
    897. 2022-07-22 10:17:12.923 760-8755/? W/SensorService: Data for sensor type HMD_FSIN dropped because of failure to update clock drift from vsync. 1 drops in the last 0s.
    898. 2022-07-22 10:17:12.924 793-793/? D/SurfaceFlinger: Finished setting power mode 2 on display 19261214226499457
    899. 2022-07-22 10:17:12.924 18097-18243/? D/SurfaceControl: Excessive delay in setPowerMode()
    900. 2022-07-22 10:17:12.924 18097-18136/? W/PowerManagerService: Screen on took 398 ms
    901. 2022-07-22 10:17:12.926 18424-18424/? D/VrEmptyLockscreen: showLockscreen() called
    902. 2022-07-22 10:17:12.927 18424-18424/? D/UserSwitchHelper: hide()
    903. 2022-07-22 10:17:12.927 856-3727/? D/VrApiService: refresh-rate changed to 72Hz
    904. 2022-07-22 10:17:12.927 18663-18663/? I/Vsync: Opened /sys/class/drm/sde-crtc-0/lineptr_event
    905. 2022-07-22 10:17:12.927 18663-18663/? I/CompositorTiming: ---------------- CompositorTiming::Init ----------------
    906. 2022-07-22 10:17:12.927 18663-18663/? I/CompositorVR: Application context EGL_CONTEXT_CLIENT_VERSION = 3
    907. 2022-07-22 10:17:12.927 18663-18663/? I/CompositorVR_EGL: EGLSurfaceInit: createSurface( vr_compositor, 3664, 1920 )
    908. 2022-07-22 10:17:12.928 18424-8810/? I/VrApi: ---------- vrapi_EnterVrMode [start] ----------
    909. 2022-07-22 10:17:12.928 18424-8810/? I/VrRuntimeClient: Tracing is disabled
    910. 2022-07-22 10:17:12.928 18424-8810/? I/VrRuntimeClient: SysProp debug mode is disabled on Client side
    911. 2022-07-22 10:17:12.928 18663-18663/? I/CompositorVR_EGL: EGLSurfaceInit: getSurfaceWindow returned 0x7ec68e9010
    912. 2022-07-22 10:17:12.928 18663-18663/? I/CompositorVR_EGL: EGLSurfaceInit: frontBufferWidth = 3664
    913. 2022-07-22 10:17:12.928 18663-18663/? I/CompositorVR_EGL: EGLSurfaceInit: frontBufferHeight = 1920
    914. 2022-07-22 10:17:12.928 18663-18663/? I/CompositorVR: createSurface( vr_compositor, 3664, 1920 )
    915. 2022-07-22 10:17:12.928 18663-8811/? I/CompositorVR: WarpThreadInit()
    916. 2022-07-22 10:17:12.929 18034-8757/? D/NuPlayerDriver: notifyResetComplete(0xeee2e5a0)
    917. 2022-07-22 10:17:12.930 845-13631/? V/C2Store: in ~ComponentModule
    918. 2022-07-22 10:17:12.930 845-13631/? V/C2Store: unloading dll
    919. 2022-07-22 10:17:12.930 18034-1844/? W/AMessage: failed to post message as target looper for handler 0 is gone.
    920. 2022-07-22 10:17:12.931 18424-8810/? D/VrApi: targetSDKVersion 29
    921. 2022-07-22 10:17:12.932 18424-8810/? I/VrRuntimeClient: DEVICE MODEL NUMBER = Quest 2
    922. 2022-07-22 10:17:12.932 18424-8810/? I/VrRuntimeClient: DEVICE BUILD NAME = user-35444700575000000
    923. 2022-07-22 10:17:12.932 18424-8810/? I/VrRuntimeClient: DEVICE BUILD TYPE = user
    924. 2022-07-22 10:17:12.932 18424-8810/? I/VrRuntimeClient: DEVICE OS VERSION = 10
    925. 2022-07-22 10:17:12.932 18424-8810/? I/VrRuntimeClient: API LOADER VERSION = 1.56.0
    926. 2022-07-22 10:17:12.932 18424-8810/? I/VrRuntimeClient: RUNTIME API VERSION = 1.59.0
    927. 2022-07-22 10:17:12.932 18424-8810/? I/VrRuntimeClient: RUNTIME VERSION = 42.0.0.130.250 Jul  7 2022 10:22:23 RELEASE
    928. 2022-07-22 10:17:12.932 18424-8810/? I/VrRuntimeClient: APP NAME = com.oculus.os.vrlockscreen
    929. 2022-07-22 10:17:12.932 18424-8810/? I/VrRuntimeClient: APP VERSION = 10 versionCode 29 internalVersionName <none>
    930. 2022-07-22 10:17:12.932 18424-8810/? I/VrRuntimeClient: APP VR TYPE = <none>
    931. 2022-07-22 10:17:12.932 18424-8810/? I/VrRuntimeClient: APP MODE TYPE = <none>
    932. 2022-07-22 10:17:12.932 18424-8810/? I/VrRuntimeClient: APP PACKAGE NAME = com.oculus.os.vrlockscreen
    933. 2022-07-22 10:17:12.932 18424-8810/? I/VrRuntimeClient: APP ACTIVITY CLASS = com.oculus.os.DialogContext
    934. 2022-07-22 10:17:12.932 18424-8810/? I/Sensor: OSSDKTRACKING Initializing head tracking
    935. 2022-07-22 10:17:12.932 18424-8810/? D/OsSdk: TrackingServiceConnection ctor
    936. 2022-07-22 10:17:12.932 18424-8810/? I/Sensor: OSSDKTRACKING Head tracker != nullpointer 0x7ebcb5ecd8, 1
    937. 2022-07-22 10:17:12.932 18424-8810/? I/Sensor: OSSDKTRACKING Initializing controller tracking
    938. 2022-07-22 10:17:12.932 18424-8810/? I/Sensor: OSSDKTRACKING Controller tracker != nullpointer 0x7f203f65d0, 1
    939. 2022-07-22 10:17:12.932 18424-8810/? D/BatteryReceiver: Registering battery receiver
    940. 2022-07-22 10:17:12.936 852-8783/? I/[CT]: TIMESTAMPCHECKER: Received first IMU-IOHM capture timestamp: 1689.463129000 [sec]
    941. 2022-07-22 10:17:12.936 852-8783/? W/[CT]: VisionInterface: [Throttled count=16] Delayed IMU measurements detected! Capture Time: 736123.249931317 [sec], Arrival Time: 736123.268706189 [sec], Time Delta: 0.018774872 [sec]
    942. 2022-07-22 10:17:12.937 18424-8810/? D/HeadsetReceiver: getCurrentHeadsetState: false
    943. 2022-07-22 10:17:12.937 852-8783/? W/[CT]: VIPER: dropping gyro data, because accelerometer cannot be interpolated.
    944. 2022-07-22 10:17:12.937 18424-8810/? I/DeviceStatus: nativeHeadsetEvent(0)
    945. 2022-07-22 10:17:12.937 852-8783/? W/[CT]: VIPER: dropping gyro data, because accelerometer cannot be interpolated.
    946. 2022-07-22 10:17:12.937 852-8783/? I/[CT]: VisionInterface: HMD Tracking switching to 3dof (from unknown) - Engine State: Running
    947. 2022-07-22 10:17:12.944 18424-8810/? I/VrRuntimeClient: SetCompositorClientFeatureFlag ClientFeatureFlag 0
    948. 2022-07-22 10:17:12.945 18752-8454/? I/RuntimeIPCServerMgr: GetServerStatesConfig -> {MaxBufferSize=32768, MaxEntries=64}
    949. 2022-07-22 10:17:12.945 18424-8810/? I/RuntimeIPCClientMgr: GetServerStatesConfig returned maxEntries=64, maxBuffSize=32768
    950. 2022-07-22 10:17:12.945 18424-8810/? I/RuntimeIPCClientMgr: InitServerStateForGroup: SUCCESS. 0, Client: com.oculus.os.vrlockscreen:com.oculus.os.vrlockscreen:18424, Server: com.oculus.guardian:com.oculus.vrguardianservice (guardianserver)
    951. 2022-07-22 10:17:12.945 18424-8810/? I/LogTimer: CPUTIME: VrRuntimeClient_BeginSession took 17.5824 ms
    952. 2022-07-22 10:17:12.946 18424-8810/? I/ClientInputInterface: DEADRECKONING SetControllerTrackingExtendedDeadreckoning 0
    953. 2022-07-22 10:17:12.946 18424-8810/? I/ClientInputSettings: HANDTRACKING package name is com.oculus.os.vrlockscreen
    954. 2022-07-22 10:17:12.947 18424-8810/? I/ClientInputSettings: HANDTRACKING: Manifest Permission request for com.oculus.os.vrlockscreen
    955. 2022-07-22 10:17:12.948 18424-8810/? I/ClientInputSettings: HANDTRACKING:  'com.oculus.os.vrlockscreen' Is hands or controller.
    956. 2022-07-22 10:17:12.948 18424-8810/? I/ClientInputSettings: HANDTRACKING: feature flag set to 2
    957. 2022-07-22 10:17:12.948 18424-8810/? I/ClientInputInterface: HANDTRACKING sethandmanifest 2
    958. 2022-07-22 10:17:12.948 18424-8810/? D/InputHooksJava: Enabling Java Input Hooks
    959. 2022-07-22 10:17:12.948 18424-8810/? I/InputDeviceManager: ovrInputDeviceManager::Initialize
    960. 2022-07-22 10:17:12.948 18424-8810/? D/OsSdk: TrackingServiceConnection registered
    961. 2022-07-22 10:17:12.949 18424-8812/? I/InputDeviceManager: HANDTRACKING Pointer filter profile changed to: 0
    962. 2022-07-22 10:17:12.949 18424-8812/? I/InputDeviceManager: HANDTRACKING Pointer filter profile changed to: 0
    963. 2022-07-22 10:17:12.949 852-8783/? I/[CT]: TIMESTAMPCHECKER: Identified IMU-IOHM sampling rate: 1011.12 Hz
    964. 2022-07-22 10:17:12.950 852-8212/? D/TrackingService: getSharedMemory: com.oculus.os.vrlockscreen, HeadTracker
    965. 2022-07-22 10:17:12.950 18424-8810/? I/Distortion: Initializing Mesh Decenter Correction
    966. 2022-07-22 10:17:12.951 847-11019/? E/CalibrationProvider: loadCalibration(LDISP_SN) failed: Calibration store didn't load any info
    967. 2022-07-22 10:17:12.951 847-11019/? E/CalibrationProvider: loadCalibration(RDISP_SN) failed: Calibration store didn't load any info
    968. 2022-07-22 10:17:12.951 18424-8810/? I/Distortion: SetLensPositions - iad=0.0630907, left offset=-0.000218965,-0.00108839, right offset=9.11728e-05,-0.00115272
    969. 2022-07-22 10:17:12.951 18424-8810/? I/Distortion: Initializing Mesh Decenter Correction
    970. 2022-07-22 10:17:12.952 847-11019/? E/CalibrationProvider: loadCalibration(LDISP_SN) failed: Calibration store didn't load any info
    971. 2022-07-22 10:17:12.952 847-11019/? E/CalibrationProvider: loadCalibration(RDISP_SN) failed: Calibration store didn't load any info
    972. 2022-07-22 10:17:12.953 18424-8810/? I/Distortion: SetLensPositions - iad=0.0630907, left offset=-0.000218965,-0.00108839, right offset=9.11728e-05,-0.00115272
    973. 2022-07-22 10:17:12.953 18424-8810/? I/Distortion: Created custom distortion mesh.
    974. 2022-07-22 10:17:12.953 18424-8810/? I/VrApi: ovrModeParms::VRAPI_MODE_FLAG_RESET_WINDOW_FULLSCREEN = 1
    975. 2022-07-22 10:17:12.953 18424-8810/? I/VrApi: ovrModeParms::VRAPI_MODE_FLAG_NATIVE_WINDOW = 1
    976. 2022-07-22 10:17:12.953 18424-8810/? I/VrApi: ovrModeParms::VRAPI_MODE_FLAG_FRONT_BUFFER_SRGB = 0
    977. 2022-07-22 10:17:12.953 18424-8810/? I/VrApi: ovrModeParms::VRAPI_MODE_FLAG_PHASE_SYNC = 0
    978. 2022-07-22 10:17:12.953 18424-8810/? I/VrApi: ovrModeParms::VRAPI_MODE_FLAG_APP_SPACE_WARP = 0
    979. 2022-07-22 10:17:12.953 18424-8810/? I/VrRuntimeClient: SetPhaseSyncMode 0
    980. 2022-07-22 10:17:12.953 18424-8810/? I/VrApi: PhaseSync disabled
    981. 2022-07-22 10:17:12.953 18424-8810/? I/VrApi: HMD sensor attached.
    982. 2022-07-22 10:17:12.953 18424-8810/? D/VrRuntimeClient: pokeGuardianUserServiceForThisClient: com.oculus.os.vrlockscreen:1000
    983. 2022-07-22 10:17:12.953 18424-8810/? W/ContextImpl: Calling a method in the system process without a qualified user: android.app.ContextImpl.startService:1582 android.content.ContextWrapper.startService:669 android.content.ContextWrapper.startService:669 com.oculus.vrapi.VrRuntimeClient.pokeGuardianUserServiceForThisClient:428 com.oculus.vrapi.VrRuntimeClient.safePokeGuardianUserServiceForThisClient:393
    984. 2022-07-22 10:17:12.954 18752-18752/? D/VrGuardianUserService: onStartCommandIntent { act=FOREGROUND_CLIENT cmp=com.oculus.guardian/com.oculus.vrguardianservice.VrGuardianUserService (has extras) }
    985. 2022-07-22 10:17:12.954 18424-8810/? D/VrRuntimeClient: VrRuntimeClient: getClientWindow: dialog client
    986. 2022-07-22 10:17:12.954 18752-18752/? D/VrGuardianUserService: maybeSubscribeDeviceConfig
    987. 2022-07-22 10:17:12.954 18752-18752/? D/VrGuardianUserService: onStartCommand FOREGROUND_CLIENT user = 10
    988. 2022-07-22 10:17:12.955 18752-18752/? D/VrGuardianService: setCurrentUser() called with: userId = [10]
    989. 2022-07-22 10:17:12.955 18752-18752/? I/VrGuardianService: nativeSetCurrentUser userid = 10
    990. 2022-07-22 10:17:12.955 18752-18752/? I/GuardianSystem: GuardianSystem::SetCurrentUser: 10
    991. 2022-07-22 10:17:12.955 18663-8451/? I/VrRuntimeService: RuntimeServiceSDKServer::EnableRendering: 0x7f2046eac0, 2, com.oculus.os.vrlockscreen
    992. 2022-07-22 10:17:12.961 18663-8811/? I/CompositorVR: SetSchedFifo( tid=8811, pol=5, pri=2 ) succeeded
    993. 2022-07-22 10:17:12.962 18663-8811/? I/CompositorVR_EGL: Context is EGL_CONTEXT_PRIORITY_HIGH_IMG
    994. 2022-07-22 10:17:12.963 847-11019/? E/CalibrationProvider: loadCalibration(LDISP_SN) failed: Calibration store didn't load any info
    995. 2022-07-22 10:17:12.964 847-11019/? E/CalibrationProvider: loadCalibration(RDISP_SN) failed: Calibration store didn't load any info
    996. 2022-07-22 10:17:12.964 852-8783/? I/[CT]: TIMESTAMPCHECKER: Received first Magnetometer-IOHM capture timestamp: 1689.491926000 [sec]
    997. 2022-07-22 10:17:12.965 847-11019/? E/CalibrationProvider: loadCalibration(LDISP_SN) failed: Calibration store didn't load any info
    998. 2022-07-22 10:17:12.965 847-11019/? E/CalibrationProvider: loadCalibration(RDISP_SN) failed: Calibration store didn't load any info
    999. 2022-07-22 10:17:12.971 18663-8811/? I/DirectRender: 0x7fb734b960 DirectRender::Init()
    1000. 2022-07-22 10:17:12.971 18663-8811/? I/DirectRender: Performing an initial swapbuffers.
    1001. 2022-07-22 10:17:12.972 18663-8811/? I/DirectRender: surface size: 3664 x 1920
    1002. 2022-07-22 10:17:12.972 18663-8811/? I/DirectRender: Supports KHR_mutable_render_buffer!
    1003. 2022-07-22 10:17:12.972 18663-8811/? I/DirectRender: Set EGL_RENDER_BUFFER to EGL_SINGLE_BUFFER
    1004. 2022-07-22 10:17:12.972 18663-8811/? I/DirectRender: Setting auto refresh on surface 0x7ec54d0c00 to 1
    1005. 2022-07-22 10:17:12.973 18663-8811/? I/DirectRender: Adreno GPU
    1006. 2022-07-22 10:17:12.973 18663-8811/? I/CompositorVR: Viewport updated HO: 0 VO: 0 W: 3664 H: 1920
    1007. 2022-07-22 10:17:12.973 18663-8811/? I/CompositorVR: CompositorVR::LoadHmdInfoMesh
    1008. 2022-07-22 10:17:12.973 18663-8811/? I/Distortion: Initializing Mesh Decenter Correction
    1009. 2022-07-22 10:17:12.974 847-11019/? E/CalibrationProvider: loadCalibration(LDISP_SN) failed: Calibration store didn't load any info
    1010. 2022-07-22 10:17:12.974 847-11019/? E/CalibrationProvider: loadCalibration(RDISP_SN) failed: Calibration store didn't load any info
    1011. 2022-07-22 10:17:12.975 18663-8811/? I/Distortion: SetLensPositions - iad=0.0630907, left offset=-0.000218965,-0.00108839, right offset=9.11728e-05,-0.00115272
    1012. 2022-07-22 10:17:12.975 18663-8811/? I/Distortion: Initializing Mesh Decenter Correction
    1013. 2022-07-22 10:17:12.976 847-11019/? E/CalibrationProvider: loadCalibration(LDISP_SN) failed: Calibration store didn't load any info
    1014. 2022-07-22 10:17:12.976 847-11019/? E/CalibrationProvider: loadCalibration(RDISP_SN) failed: Calibration store didn't load any info
    1015. 2022-07-22 10:17:12.977 18663-8811/? I/Distortion: SetLensPositions - iad=0.0630907, left offset=-0.000218965,-0.00108839, right offset=9.11728e-05,-0.00115272
    1016. 2022-07-22 10:17:12.977 18663-8811/? I/Distortion: Created custom distortion mesh.
    1017. 2022-07-22 10:17:12.977 18663-8811/? I/DistortionMesh: LoadDistortionMeshFromMemory
    1018. 2022-07-22 10:17:12.981 760-8794/? W/SensorService: frameset capture timestamp out of spec by -1689464.80 ms. FrameType=HEADSET, observed=1689498134000 expected=33333000. FrameSyncPeriod is: 33.33 ms
    1019. 2022-07-22 10:17:12.981 852-8808/? W/[CT]: EXPCTRL: [Throttled count=1] Failed to find exposure settings in history.Setting the exposure commands is probably taking more than 3/4 frames
    1020. 2022-07-22 10:17:12.982 18663-8811/? I/DistortionMesh: distortion mesh clipping saved 14.77% fill
    1021. 2022-07-22 10:17:12.982 852-8798/? I/[CT]: TIMESTAMPCHECKER: Received first Camera-IOHM capture timestamp: 1689.498134000 [sec]
    1022. 2022-07-22 10:17:12.983 852-8798/? W/[CT]: VIPER: [Throttled count=33] StateBuffer: Could not get velocity from buffer. Not currently tracking in 6dof.
    1023. 2022-07-22 10:17:12.983 18663-8811/? I/Distortion: Initializing Mesh Decenter Correction
    1024. 2022-07-22 10:17:12.983 852-8752/? I/[CT]: boltlib: DSP utilization: 0.00 % (14 / 525345 ms)
    1025. 2022-07-22 10:17:12.985 852-8798/? I/[CT]: VegaTracker: [Throttled count=8] Performing big search to recover from bad map tracking or new reloc.
    1026. 2022-07-22 10:17:12.988 847-11019/? E/CalibrationProvider: loadCalibration(LDISP_SN) failed: Calibration store didn't load any info
    1027. 2022-07-22 10:17:12.988 847-1033/? E/CalibrationProvider: loadCalibration(RDISP_SN) failed: Calibration store didn't load any info
    1028. 2022-07-22 10:17:12.989 18663-8811/? I/Distortion: SetLensPositions - iad=0.0630907, left offset=-0.000218965,-0.00108839, right offset=9.11728e-05,-0.00115272
    1029. 2022-07-22 10:17:12.990 18663-8811/? I/Distortion: Created custom distortion mesh.
    1030. 2022-07-22 10:17:12.991 18663-8811/? I/DistortionMesh: LoadDistortionMeshFromMemory
    1031. 2022-07-22 10:17:12.994 852-8798/? W/[CT]: F2F_TRACKER: Descriptor Matching | No active tracks available. Skipping matching!
    1032. 2022-07-22 10:17:12.994 852-8798/? W/[CT]: F2F_TRACKER: Low ratio of valid tracks for available capacity (0/300=0.00<0.50). Verify corner detection and track creation!
    1033. 2022-07-22 10:17:12.994 852-8798/? W/[CT]: VegaTrackTracker: Frame-to-frame tracker returned 0 track measurements
    1034. 2022-07-22 10:17:12.994 852-8798/? I/[CT]: VIPER:VIO: VIO refused to initialize: VIO did not try to initialize, most likely because not enough frames have been added.
    1035. 2022-07-22 10:17:12.995 852-8798/? I/[CT]: VEGA:PERCEPTUAL_HM: Forcing PerceptualTrackingStatus to Orientation because we're initializing.
    1036. 2022-07-22 10:17:12.995 852-8798/? I/[CT]: VIPER: Added a frame to tracking initialization
    1037. 2022-07-22 10:17:12.997 852-8798/? W/[CT]: VIPER: Mode=Vega,Status=3DoF,INITIALIZING,Inl=-1,Mem=77.5,Jit=0.0mm,Issues(Cam/min=5.2,IMU/min=0.0),Exp=(5.0ms,g=3.0,I=102,Ir=6822.3)(5.0ms,g=3.0,I=40,Ir=2716.0)(5.0ms,g=3.0,I=30,Ir=2058.5)(5.0ms,g=3.0,I=60,Ir=4057.8)
    1038. 2022-07-22 10:17:12.998 852-8804/? I/[CT]: TIMESTAMPCHECKER: Received first Camera-CHM capture timestamp: 1689.516438000 [sec]
    1039. 2022-07-22 10:17:12.998 852-8804/? W/[CT]: CONSTELLATION: No tracked objects initialized!!
    1040. 2022-07-22 10:17:13.008 18663-8811/? I/DistortionMesh: distortion mesh clipping saved 14.62% fill
    1041. 2022-07-22 10:17:13.009 18663-8811/? I/CompositorVR: High quality distortion mesh dimensions: 57x60 in 0.025895
    1042. 2022-07-22 10:17:13.009 18663-8811/? I/CompositorVR: No Timewarp Decenter Correction
    1043. 2022-07-22 10:17:13.009 18663-8811/? I/Distortion: Initializing Mesh Decenter Correction
    1044. 2022-07-22 10:17:13.010 847-1033/? E/CalibrationProvider: loadCalibration(LDISP_SN) failed: Calibration store didn't load any info
    1045. 2022-07-22 10:17:13.010 847-1033/? E/CalibrationProvider: loadCalibration(RDISP_SN) failed: Calibration store didn''com.oculus.os.vrlockscreen' 'com.oculus.os.vrlockscreen'  updated AnytimeUI processname 1
    1046. 2022-07-22 10:17:13.044 18663-18747/? D/VrRuntimeService: sendPrimaryPackageChangeBroadcast
    1047. 2022-07-22 10:17:13.053 18663-8811/? I/Vsync: Vsync 34:  2 x 13.92 ms (72.01 Hz, at 736123.385)
    1048. 2022-07-22 10:17:13.053 18663-8811/? I/AADT: SetAADTLutDataX. Thread. SizeX: 0
    1049. 2022-07-22 10:17:13.053 18663-8811/? I/AADT: SetAADTLutDataY. Thread. SizeY: 0
    1050. 2022-07-22 10:17:13.054 852-8798/? I/[CT]: VIPER:LOCALIZER_MANAGER: [Throttled count=18] Localization received no current map. Triggering localization!
    1051. 2022-07-22 10:17:13.055 852-8798/? I/[CT]: VIPER:LOCALIZER_MANAGER: [Throttled count=23] Number of frames to try relocalization on 3 maps: 149
    1052. 2022-07-22 10:17:13.055 31716-31716/? D/[OAO] BaseOverlayService: screenStateReceiver Received broadcast: com.oculus.vrshell.intent.action.PRIMARY_PACKAGE_CHANGED
    1053. 2022-07-22 10:17:13.055 31716-31716/? I/[OAO] ShellOverlayServiceJNI: NativeSendOverlayCommand
    1054. 2022-07-22 10:17:13.055 852-8798/? I/[CT]: VIPER: Added a frame to tracking initialization
    1055. 2022-07-22 10:17:13.055 31716-31716/? I/[OAO] ShellOverlayServiceJNI: NativeWake
    1056. 2022-07-22 10:17:13.055 31716-31716/? I/[OAO] ShellOverlayMain: WakeVrThread
    1057. 2022-07-22 10:17:13.055 31716-31716/? I/[OAO] ShellOverlayMain: WakeVrThread - notifying vr thread
    1058. 2022-07-22 10:17:13.056 852-1302/? I/[CT]: VIPER:LOCALIZER: Extracting non-gravity-aligned descriptors on query.
    1059. 2022-07-22 10:17:13.056 18663-18747/? I/AADT: SetAADTLutDataX: 0
    1060. 2022-07-22 10:17:13.056 18663-18747/? I/AADT: SetAADTLutDataY: 0
    1061. 2022-07-22 10:17:13.056 32347-32347/? D/[SEO] BaseOverlayService: screenStateReceiver Received broadcast: com.oculus.vrshell.intent.action.PRIMARY_PACKAGE_CHANGED
    1062. 2022-07-22 10:17:13.056 18663-18747/? I/ServiceInputManager: InhibitHandleHomeKey has changed on the service. New value: 1
    1063. 2022-07-22 10:17:13.056 18663-18747/? I/ServiceInputManager: DEADRECKONING deadReckoning mode on ClientMgr from server is 0
    1064. 2022-07-22 10:17:13.056 18663-18747/? I/PerformanceManager_V0: SetClockLevels: Apply pending clock request change: -1,-1 -> 0,0
    1065. 2022-07-22 10:17:13.056 18663-18743/? I/Clocks: ReleaseClocks - start
    1066. 2022-07-22 10:17:13.057 32347-32488/? I/[SEO] ShellFrameAnalytics: ShellFrame frameFunction: 61020625us/524376954us, trace: 0us/26us, process commands: 0us/6489us, system update: 0us/6134us, render 0us/12193us, post render 0us/0us
    1067. 2022-07-22 10:17:13.057 32347-32488/? I/[SEO] ShellFrameAnalytics: Shell Heartbeat focusedPanelTimeSpent: {"16":100} visibleTimeSpent: {"15":100,"16":100} inputTimeSpent: {"controller":100} inputClickCount: {} mouseMoveTimeSpent: 0 mouseScrollTimeSpent: 0 physicalKeyboardConnectedTimeSpent: 0 physicalKeyboardTrackedTimeSpent: 0 quickActionsMenuActivations: 0 quickActionsMenuTimeSpent: 0 quickActionsMenuSessionLengths: [] quickActionsMenuSelections: {} handTrackingOptIn: 0 handTrackingAutoTransition: 1
    1068. 2022-07-22 10:17:13.057 18663-8451/? I/VrRuntimeService: CreateSwapChain: 873969066
    1069. 2022-07-22 10:17:13.057 18663-8451/? I/VrRuntimeService: CreateSwapChain: api:gles 3 0x8058 1000 1000 1 1 1 0 14
    1070. 2022-07-22 10:17:13.059 18663-18747/? I/UnifiedTelemetryWrapper: Started UT session don
    1071. 2022-07-22 10:17:13.059 18663-18747/? I/TimeWarpClientMgr: Enable client 0
    1072. 2022-07-22 10:17:13.059 18663-18747/? I/VrRuntimeServer: EnableCompositorClient client(0): layer placement(2147483643) flags(8) sm(0x7ed05b7160)
    1073. 2022-07-22 10:17:13.059 18663-18743/? I/Clocks: ReleaseClocks - end (2.9 ms)
    1074. 2022-07-22 10:17:13.059 18663-18743/? I/Clocks: LockClocks( cpu=0, gpu=0 ) - start
    1075. 2022-07-22 10:17:13.059 18663-8451/? I/VrRuntimeServer: CreateTextureSwapChain: result importswapchaingles 1
    1076. 2022-07-22 10:17:13.061 18663-8811/? I/TimeWarpProgs: loaded binary layerProgram 0:0x48083:0x0 in 1.1 ms
    1077. 2022-07-22 10:17:13.061 18424-8834/? D/VrApi: targetSDKVersion 29
    1078. 2022-07-22 10:17:13.062 18424-8834/? I/JniUtils: ovr_GetCurrentPackageSignature
    1079. 2022-07-22 10:17:13.062 18663-18743/? I/Clocks: CPU levels [0, 4]
    1080. 2022-07-22 10:17:13.062 18663-18743/? I/Clocks: GPU levels [0, 5]
    1081. 2022-07-22 10:17:13.062 18663-18743/? I/Clocks: LockClocks( cpu=0, gpu=0 ) - end (2.8 ms)
    1082. 2022-07-22 10:17:13.062 18424-8834/? I/Metrics: device name = Oculus Quest 2
    1083. 2022-07-22 10:17:13.065 18663-8811/? I/AADT: SetAADTLutDataX. Thread. SizeX: 0
    1084. 2022-07-22 10:17:13.065 18663-8811/? I/AADT: SetAADTLutDataY. Thread. SizeY: 0
    1085. 2022-07-22 10:17:13.071 18594-18594/? I/[CT]: MIXEDREALITY: MrService: ScreenStateChanged: true
    1086. 2022-07-22 10:17:13.071 18594-18594/? I/[CT]: MIXEDREALITY: MrService: onWakeup
    1087. 2022-07-22 10:17:13.073 18918-8842/? I/OSUpdateService: Intent with action system_interactive_changed
    1088. 2022-07-22 10:17:13.075 18663-8811/? I/TimeWarpProgs: loaded binary layerProgram 0:0x58083:0x0 in 1.2 ms
    1089. 2022-07-22 10:17:13.077 18506-18506/? E/FuelGaugeCollector: could not read battery_cycle_count
    1090.     java.io.IOException: Get battery metric file failed for fake_aggregate_cycle_count
    1091.         at com.oculus.unifiedtelemetry.collectors.FuelGaugeCollector.A34(:136)
    1092.         at com.oculus.unifiedtelemetry.collectors.CollectorsControl.A31(:99)
    1093.         at X.oX.onReceive(:164)
    1094.         at android.app.LoadedApk$ReceiverDispatcher$Args.lambda$getRunnable$0$LoadedApk$ReceiverDispatcher$Args(LoadedApk.java:1556)
    1095.         at android.app.-$$Lambda$LoadedApk$ReceiverDispatcher$Args$_BumDX2UKsnxLVrE6UJsJZkotuA.run(Unknown Source:2)
    1096.         at android.os.Handler.handleCallback(Handler.java:886)
    1097.         at android.os.Handler.dispatchMessage(Handler.java:102)
    1098.         at android.os.Looper.loop(Looper.java:214)
    1099.         at android.app.ActivityThread.main(ActivityThread.java:7400)
    1100.         at java.lang.reflect.Method.invoke(Native Method)
    1101.         at com.android.internal.os.RuntimeInit$MethodAndArgsCaller.run(RuntimeInit.java:492)
    1102.         at com.android.internal.os.ZygoteInit.main(ZygoteInit.java:936)
    1103. 2022-07-22 10:17:13.078 18663-8451/? I/VrRuntimeService: CreateSwapChain: 873969066
    1104. 2022-07-22 10:17:13.078 18663-8451/? I/VrRuntimeService: CreateSwapChain: api:gles 0 0x8c43 1440 1584 1 3 1 0 14
    1105. 2022-07-22 10:17:13.081 18663-8451/? I/VrRuntimeServer: CreateTextureSwapChain: result importswapchaingles 1
    1106. 2022-07-22 10:17:13.085 18663-8451/? I/VrRuntimeService: CreateSwapChain: 873969066
    1107. 2022-07-22 10:17:13.085 18663-8451/? I/VrRuntimeService: CreateSwapChain: api:gles 0 0x8c43 1440 1584 1 3 1 0 14
    1108. 2022-07-22 10:17:13.086 18527-18527/? D/OculusNotificationListenerService: Notification posted: 0|com.oculus.horizon|135234|null|10054
    1109. 2022-07-22 10:17:13.091 852-8798/? I/[CT]: VIPER: Added a frame to tracking initialization
    1110. 2022-07-22 10:17:13.091 18663-8451/? I/VrRuntimeServer: CreateTextureSwapChain: result importswapchaingles 1
    1111. 2022-07-22 10:17:13.092 31716-31716/? D/[OAO] BaseOverlayService: screenStateReceiver Received broadcast: android.intent.action.SCREEN_ON
    1112. 2022-07-22 10:17:13.092 760-8755/? W/SensorService: Arrival timestamp too late
    1113. 2022-07-22 10:17:13.092 31716-31716/? D/[OAO] ShellOverlayService: onScreenStateChanged: true
    1114. 2022-07-22 10:17:13.092 31716-31716/? I/[OAO] ShellOverlayServiceJNI: NativeSendOverlayCommand
    1115. 2022-07-22 10:17:13.092 31716-31716/? I/[OAO] ShellOverlayServiceJNI: NativeWake
    1116. 2022-07-22 10:17:13.092 31716-31716/? I/[OAO] ShellOverlayMain: WakeVrThread
    1117. 2022-07-22 10:17:13.092 31716-31716/? I/[OAO] ShellOverlayMain: WakeVrThread - notifying vr thread
    1118. 2022-07-22 10:17:13.094 31879-32159/? W/PresenceAPKNative(hyperspace_controller_module): is_screen_on: 1
    1119. 2022-07-22 10:17:13.096 852-8212/? D/TrackingService: getSharedMemory: com.oculus.os.vrlockscreen, Controller
    1120. 2022-07-22 10:17:13.096 18424-8810/? D/VrRuntimeClient: loadDriverResource - resourceName: 'hand_left'
    1121. 2022-07-22 10:17:13.100 18424-8810/? I/VrApi_Input: vrapi_GetMeshForHand_Internal: mesh->Header.Version = df000001 mesh->NumVertices = 1360 mesh->NumIndices = 6942
    1122. 2022-07-22 10:17:13.101 32347-32347/? D/[SEO] BaseOverlayService: screenStateReceiver Received broadcast: android.intent.action.SCREEN_ON
    1123. 2022-07-22 10:17:13.103 18424-8810/? D/VrRuntimeClient: loadDriverResource - resourceName: 'hand_right'
    1124. 2022-07-22 10:17:13.104 31716-32053/? I/[OAO] ShellOverlayApp: 0xc263abd0 msg: overlayCommand:
    1125.     command = primaryPackageChanged
    1126. 2022-07-22 10:17:13.104 31716-32053/? I/[OAO] ShellOverlayApp: Process_OverlayCommand command : primaryPackageChanged
    1127. 2022-07-22 10:17:13.104 31716-32053/? I/[OAO] ShellOverlayApp: UpdatePrimaryPackage forceSilentUpdate:0
    1128. 2022-07-22 10:17:13.104 31716-32053/? I/[OAO] ShellOverlayApp: UpdatePrimaryPackage Requested for PackageName:com.oculus.os.vrlockscreen
    1129. 2022-07-22 10:17:13.104 31716-32053/? I/[OAO] ShellOverlayApp: UpdatePrimaryPackage - Package change:0 Previous package:[com.oculus.os.vrlockscreen] immersive app changed:0
    1130. 2022-07-22 10:17:13.104 31716-32053/? I/[OAO] OverlayFlowController: OnPrimaryPackageChange primaryPackage:com.oculus.os.vrlockscreen immersiveAppChanged:0 forceSilentUpdate:0
    1131. 2022-07-22 10:17:13.104 31716-32053/? I/[OAO] OverlaySystemUxOsDialogFlow: OverlaySystemUxOsDialogFlow UpdatePrimaryPackage isVrShellPackage:0 isSystemPackage:1
    1132. 2022-07-22 10:17:13.104 31716-32053/? I/[OAO] ShellOverlayApp: 0xc263abd0 msg: overlayCommand:
    1133.     command = screenStateChanged
    1134.     state = 1
    1135. 2022-07-22 10:17:13.104 31716-32053/? I/[OAO] ShellOverlayApp: Process_OverlayCommand command : screenStateChanged
    1136. 2022-07-22 10:17:13.104 31716-32053/? I/[OAO] ShellOverlayApp: screenStateChanged message received
    1137. 2022-07-22 10:17:13.105 18424-8810/? I/VrApi_Input: vrapi_GetMeshForHand_Internal: mesh->Header.Version = df000001 mesh->NumVertices = 1360 mesh->NumIndices = 6942
    1138. 2022-07-22 10:17:13.106 32703-32703/? D/[SUI] NotificationBroadcastReceiver: action: com.oculus.intent.action.NOTIF_CHANGE
    1139. 2022-07-22 10:17:13.106 31716-31716/? D/VrNotificationAnalytics: logNotificationPosted: key(0|com.oculus.horizon|135234|null|10054), type(first_party_unspecified), isToast(false)
    1140. 2022-07-22 10:17:13.107 31716-31716/? I/[OAO] VrNotificationListenerService: onNotificationPosted() - key = 0|com.oculus.horizon|135234|null|10054, type = first_party_unspecified, isToast = false, isBlocked with reason = true Blocked by does not contain all markers for a toast notification
    1141. 2022-07-22 10:17:13.108 31716-31716/? D/[OAO] VrBroadcastReceiver: action: com.oculus.vrshell.intent.action.NOTIFICATION_WAKE
    1142. 2022-07-22 10:17:13.109 7998-7998/? D/VrNotificationAnalytics: logNotificationPosted: key(0|com.oculus.horizon|135234|null|10054), type(first_party_unspecified), isToast(false)
    1143. 2022-07-22 10:17:13.109 18663-8451/? I/VrRuntimeService: CreateSwapChain: 873969066
    1144. 2022-07-22 10:17:13.109 18663-8451/? I/VrRuntimeService: CreateSwapChain: api:gles 0 0x8c43 64 64 1 3 1 0 14
    1145. 2022-07-22 10:17:13.110 7998-7998/? I/[OAO] VrNotificationListenerService: onNotificationPosted() - key = 0|com.oculus.horizon|135234|null|10054, type = first_party_unspecified, isToast = false, isBlocked with reason = true Blocked by does not contain all markers for a toast notification
    1146. 2022-07-22 10:17:13.110 18663-8451/? I/VrRuntimeServer: CreateTextureSwapChain: result importswapchaingles 1
    1147. 2022-07-22 10:17:13.112 31716-31716/? D/[OAO] VrNotificationService: VrNotificationService onStartCommand() Intent { cmp=com.oculus.vrshell/.VrNotificationService }
    1148. 2022-07-22 10:17:13.113 18424-8810/? D/UI: Creating window texture with size 725 x 725
    1149. 2022-07-22 10:17:13.113 18663-8451/? I/VrRuntimeService: CreateAndroidSurfaceSwapChain: 873969066
    1150. 2022-07-22 10:17:13.113 18663-8451/? I/VrRuntimeService: CreateAndroidSurfaceSwapChain: 65536 1 32856 725 725 1 1 1 0 0
    1151. 2022-07-22 10:17:13.113 18663-18731/? I/SwapChain_Surface: CreateAndroidSurfaceSwapChainGLES: 0x7e86457000: SurfaceTexture 0x2b96 Surface 0x2ba6
    1152. 2022-07-22 10:17:13.113 18663-8451/? I/VrRuntimeServer: CreateAndroidSurfaceSwapChain: result surface 0x7e86457000
    1153. 2022-07-22 10:17:13.114 18424-8810/? I/VrRuntimeClient: SetTextureSwapChainSamplerState: No change in sampler state.
    1154. 2022-07-22 10:17:13.115 18663-8451/? I/VrRuntimeService: UpdateSwapChainSamplerState: 336
    1155. 2022-07-22 10:17:13.115 18663-8451/? I/VrRuntimeService: UpdateSwapChainSamplerState: minFilter=1 magFilter=1 wrapModeS=2 warpModeT=2 maxAniso=1.000000 border={0.000000,0.000000,0.000000,0.000000} swizzle={0,1,2,3}
    1156. 2022-07-22 10:17:13.115 18424-8810/? D/VrRuntimeClient: pokeGuardianUserServiceForThisClient: com.oculus.os.vrlockscreen:1000
    1157. 2022-07-22 10:17:13.115 18424-8810/? W/ContextImpl: Calling a method in the system process without a qualified user: android.app.ContextImpl.startService:1582 android.content.ContextWrapper.startService:669 android.content.ContextWrapper.startService:669 com.oculus.vrapi.VrRuntimeClient.pokeGuardianUserServiceForThisClient:428 com.oculus.vrapi.VrRuntimeClient.safePokeGuardianUserServiceForThisClient:393
    1158. 2022-07-22 10:17:13.122 760-8755/? W/SensorService: Arrival timestamp too early
    1159. 2022-07-22 10:17:13.123 18752-18752/? D/VrGuardianUserService: onStartCommandIntent { act=FOREGROUND_CLIENT cmp=com.oculus.guardian/com.oculus.vrguardianservice.VrGuardianUserService (has extras) }
    1160. 2022-07-22 10:17:13.123 18752-18752/? D/VrGuardianUserService: maybeSubscribeDeviceConfig
    1161. 2022-07-22 10:17:13.124 18752-18752/? D/VrGuardianUserService: onStartCommand FOREGROUND_CLIENT user = 10
    1162. 2022-07-22 10:17:13.124 18663-8451/? I/VrRuntimeService: RuntimeServiceSDKServer::SetPerformanceIdealFeatureState: 4 0 4
    1163. 2022-07-22 10:17:13.125 18663-8451/? I/VrRuntimeService: RuntimeServiceSDKServer::SetPerformanceIdealFeatureState: 5 0 4
    1164. 2022-07-22 10:17:13.125 18663-8451/? I/VrRuntimeService: RuntimeServiceSDKServer::SetPerformanceIdealFeatureState: 8 0 4
    1165. 2022-07-22 10:17:13.125 18663-8451/? I/VrRuntimeService: RuntimeServiceSDKServer::SetPerformanceIdealFeatureState: 9 0 4
    1166. 2022-07-22 10:17:13.125 18752-18752/? D/VrGuardianService: setCurrentUser() called with: userId = [10]
    1167. 2022-07-22 10:17:13.125 18752-18752/? I/VrGuardianService: nativeSetCurrentUser userid = 10
    1168. 2022-07-22 10:17:13.125 18752-18752/? I/GuardianSystem: GuardianSystem::SetCurrentUser: 10
    1169. 2022-07-22 10:17:13.125 18424-8853/? I/FenceChecker: FenceChecker::MainLoop - started
    1170. 2022-07-22 10:17:13.128 18663-18747/? I/PerformanceManager_V0: SetClockLevels: Apply pending clock request change: 0,0 -> 1,1
    1171. 2022-07-22 10:17:13.128 18663-18743/? I/Clocks: ReleaseClocks - start
    1172. 2022-07-22 10:17:13.129 18663-18743/? I/Clocks: ReleaseClocks - end (0.6 ms)
    1173. 2022-07-22 10:17:13.129 18663-18743/? I/Clocks: LockClocks( cpu=1, gpu=1 ) - start
    1174. 2022-07-22 10:17:13.131 18663-8811/? I/TimeWarpProgs: loaded binary layerProgram 3:0x40080:0x0 in 1.1 ms
    1175. 2022-07-22 10:17:13.132 18663-8811/? I/TimeWarpProgs: loaded binary layerProgram 0:0x100000058002:0x0 in 1.0 ms
    1176. 2022-07-22 10:17:13.133 18663-18743/? I/Clocks: CPU levels [0, 4]
    1177. 2022-07-22 10:17:13.133 18663-18743/? I/Clocks: GPU levels [0, 5]
    1178. 2022-07-22 10:17:13.133 18663-18743/? I/Clocks: LockClocks( cpu=1, gpu=1 ) - end (4.5 ms)
    1179. 2022-07-22 10:17:13.134 18663-8811/? I/ScreenCaptureBase: GlobalInhibitState changed to 1
    1180. 2022-07-22 10:17:13.135 18663-8811/? I/CompositorVR: SetSchedFifo( tid=8853, pol=3, pri=0 ) succeeded
    1181. 2022-07-22 10:17:13.135 18663-8811/? I/CompositorVR: SetClientSurfaceSecureFlag: secure=1
    1182. 2022-07-22 10:17:13.144 18663-8811/? I/SwapChain_Surface: AttachSurfaceSwapChainGLES: 0x7e86457000 with SurfaceTexture 0x2b96 attached on init
    1183. 2022-07-22 10:17:13.145 18663-8811/? I/TimeWarpProgs: loaded binary layerProgram 1:0x100000048001:0x0 in 1.1 ms
    1184. 2022-07-22 10:17:13.146 624-624/? E/OVRMediaServiceManager: LivestreamingManager Not initialized
    1185. 2022-07-22 10:17:13.148 760-8790/? E/FrameSetDispatcher: [HEADSET] Client pid=852 (852): Failed to read from receive FMQ for 1 packets in 5000ms.
    1186.     This probably means this client is taking more than 33 ms to process the frame.
    1187.     Retrying.
    1188. 2022-07-22 10:17:13.151 624-624/? W/VRLifecycleManager: onHeadsetMounted
    1189. 2022-07-22 10:17:13.152 6810-6845/? W/ipcLoader_static: RuntimeIPC: Loader: ipc_GetTimestamp was called but missing from vtable!
    1190. 2022-07-22 10:17:13.152 6810-6845/? W/ipcLoader_static: RuntimeIPC: Loader: ipc_IsThisRpcSampled was called but missing from vtable!
    1191. 2022-07-22 10:17:13.156 852-8798/? W/[CT]: MatchOutlierRejection: Too few stereo matches, performs non-stereo outlier rejection
    1192. 2022-07-22 10:17:13.157 852-8798/? I/[CT]: MatchOutlierRejection: Matches: 181, Stereo matches: 0, Inlier ratio: 0.3756906
    1193. 2022-07-22 10:17:13.157 852-8798/? I/[CT]: VIPER:VIO: VIO refused to initialize: VIO did not try to initialize, most likely because not enough frames have been added.
    1194. 2022-07-22 10:17:13.159 852-8798/? I/[CT]: VEGA:PERCEPTUAL_HM: Forcing PerceptualTrackingStatus to Orientation because we're initializing.
    1195. 2022-07-22 10:17:13.159 624-624/? D/PlatformPlugin: [PlatformPluginManager] Acquiring lock: nativeInit
    1196. 2022-07-22 10:17:13.159 624-624/? D/PlatformPlugin: [PlatformPluginManager] Successfully acquired lock: nativeInit
    1197. 2022-07-22 10:17:13.159 624-624/? I/PlatformPlugin: [PlatformPluginManager] Init
    1198. 2022-07-22 10:17:13.159 852-8798/? I/[CT]: VIPER: Added a frame to tracking initialization
    1199. 2022-07-22 10:17:13.159 852-8798/? W/[CT]: VIPER: Frame Tracking [0.042666770 [sec]s] exceeded camera sampling time [0.033333333 [sec]s].
    1200. 2022-07-22 10:17:13.160 624-624/? I/OVRPlatform: [Context] ConfigOption DisableFbns =>  1
    1201. 2022-07-22 10:17:13.160 624-624/? I/OVRPlatform: [Context] Didn't find config(DisableP2pNetworking), returning default(0)
    1202. 2022-07-22 10:17:13.161 624-624/? I/OVRPlatform: [AndroidPlatformIntegration] SetThreadCPUAffinity thread 0, cpu mask 0x0000007f
    1203. 2022-07-22 10:17:13.161 852-8798/? I/[CT]: VIPER: Added a frame to tracking initialization
    1204. 2022-07-22 10:17:13.163 852-1302/? I/[CT]: VIPER: Removed 1 duplicate inliers from the localization result (before: 32, after: 31).
    1205. 2022-07-22 10:17:13.175 624-8866/? I/libjingle: [4798:223] [8866] (RenderFrameCapturerImpl.cpp:351): InitializeAndroid
    1206. 2022-07-22 10:17:13.175 624-8866/? D/JVM: JVM::Initialize@[tid=8866]
    1207. 2022-07-22 10:17:13.175 624-8866/? D/JVM: JVM::JVM@[tid=8866]
    1208. 2022-07-22 10:17:13.176 624-8866/? I/org.webrtc.Logging: MediaCodecVideoEncoder: Found target encoder for mime video/x-vnd.on2.vp8 : OMX.qcom.video.encoder.vp8. Color: 0x15
    1209. 2022-07-22 10:17:13.176 624-8866/? I/MediaCodecVideoEncoder: [4798:224] [8866] MediaCodecVideoEncoder: VP8 HW Encoder supported.
    1210. 2022-07-22 10:17:13.176 624-8866/? I/org.webrtc.Logging: MediaCodecVideoEncoder: Found target encoder for mime video/avc : OMX.qcom.video.encoder.avc. Color: 0x15
    1211. 2022-07-22 10:17:13.176 624-8866/? I/MediaCodecVideoEncoder: [4798:224] [8866] MediaCodecVideoEncoder: H.264 HW Encoder supported.
    1212. 2022-07-22 10:17:13.176 6810-6810/? W/VRLifecycleManager: onHeadsetMounted
    1213. 2022-07-22 10:17:13.179 624-8866/? I/MediaCodecVideoEncoder: [4798:227] [8866] MediaCodecVideoEncoder: MediaCodecVideoEncoderFactory::SetEGLContext
    1214. 2022-07-22 10:17:13.179 624-8866/? I/MediaCodecVideoDecoder: [4798:227] [8866] MediaCodecVideoDecoder: MediaCodecVideoDecoderFactory ctor
    1215. 2022-07-22 10:17:13.179 624-8866/? I/org.webrtc.Logging: MediaCodecVideoDecoder: Trying to find HW decoder for mime video/x-vnd.on2.vp8
    1216. 2022-07-22 10:17:13.179 624-8866/? I/org.webrtc.Logging: MediaCodecVideoDecoder: Found candidate decoder OMX.qcom.video.decoder.vp8
    1217. 2022-07-22 10:17:13.179 624-8866/? I/org.webrtc.Logging: MediaCodecVideoDecoder: Found target decoder OMX.qcom.video.decoder.vp8. Color: 0x13
    1218. 2022-07-22 10:17:13.179 624-8866/? I/MediaCodecVideoDecoder: [4798:227] [8866] MediaCodecVideoDecoder: VP8 HW Decoder supported.
    1219. 2022-07-22 10:17:13.179 624-8866/? I/org.webrtc.Logging: MediaCodecVideoDecoder: Trying to find HW decoder for mime video/x-vnd.on2.vp9