Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

[8.0.0-preview.5.8529] [Android] DeviceSensors produce an ANR at irregular intervals when built in Release mode. #15829

Closed
lordstyx opened this issue Jun 23, 2023 · 11 comments
Labels
area-essentials Essentials: Device, Display, Connectivity, Secure Storage, Sensors, App Info partner/android Issues for the Android SDK platform/android 🤖 s/needs-attention Issue has more information and needs another look s/no-repro Can no longer be reproduced on latest t/bug Something isn't working

Comments

@lordstyx
Copy link

lordstyx commented Jun 23, 2023

Description

In an app we collect device sensor data, such as geolocation, connectivity status and battery info.

Trying out .NET 8-preview 5 because it has an event-based Geolocation sensor implementation (see #9572), we notice that, when the app is built in Release mode, the interface randomly freezes and produces an ANR.

image

Steps to Reproduce

This happens both on the emulator as on actual devices.
The problem can be reproduced with the sample app.

  1. Make sure you build and run the sample in Release mode.
  2. In the advanced settings of the emulator, under Location, configure a route and make it play on repeat.
  3. Wait a bit. The issue occurs to anywhere between 30 seconds and 5 minutes for me.
  4. Click anywhere on the main page, or to make it more clear, try to open the flyout menu.

These interactions will freeze the application, leading to an ANR shortly.

Link to public reproduction project repository

https://github.com/lordstyx/MauiAndroidDeviceSensorAnr

Version with bug

8.0.0-preview.3.8149
8.0.0-preview.4.8333
8.0.0-preview.5.8529
8.0.0-preview.6.8686

Last version that worked well

Unknown/Other

Affected platforms

Android

Affected platform versions

Android 8 and up.

Did you find any workaround?

No response

Relevant log output

06-23 14:43:11.478  6467  6467 I DOTNET  : Accelerometer_ReadingChanged
06-23 14:43:11.506  1933  1933 E wifi_forwarder: RemoteConnection failed to initialize: RemoteConnection failed to open pipe
06-23 14:43:11.546  6467  6467 I DOTNET  : Accelerometer_ReadingChanged
06-23 14:43:13.467  6467  6467 I chatty  : uid=10235(com.companyname.mauiapp1) identical 29 lines
06-23 14:43:13.533  6467  6467 I DOTNET  : Accelerometer_ReadingChanged
06-23 14:43:13.586  6467  6467 I DOTNET  : IsDifferent: long (3.66774 vs 3.6669399999999994)
06-23 14:43:13.586  6467  6467 I DOTNET  : DeviceLocationChanged
06-23 14:43:13.600  6467  6467 I DOTNET  : Accelerometer_ReadingChanged
06-23 14:43:16.052  6467  6467 I chatty  : uid=10235(com.companyname.mauiapp1) identical 37 lines
06-23 14:43:16.118  6467  6467 I DOTNET  : Accelerometer_ReadingChanged
06-23 14:43:16.158  6467  6467 I DOTNET  : IsDifferent: long (3.6685183333333335 vs 3.66774)
06-23 14:43:16.158  6467  6467 I DOTNET  : DeviceLocationChanged
06-23 14:43:16.184  6467  6467 I DOTNET  : Accelerometer_ReadingChanged
06-23 14:43:18.697  6467  6467 I chatty  : uid=10235(com.companyname.mauiapp1) identical 38 lines
06-23 14:43:18.762  6467  6467 I DOTNET  : Accelerometer_ReadingChanged
06-23 14:43:18.798  6467  6467 I DOTNET  : IsDifferent: long (3.6693000000000002 vs 3.6685183333333335)
06-23 14:43:18.798  6467  6467 I DOTNET  : DeviceLocationChanged
06-23 14:43:18.829  6467  6467 I DOTNET  : Accelerometer_ReadingChanged
06-23 14:43:21.013  6467  6467 I chatty  : uid=10235(com.companyname.mauiapp1) identical 33 lines
06-23 14:43:21.079  6467  6467 I DOTNET  : Accelerometer_ReadingChanged
06-23 14:43:21.142  6467  6467 I DOTNET  : IsDifferent: long (3.6699900000000003 vs 3.6693000000000002)
06-23 14:43:21.142  6467  6467 I DOTNET  : DeviceLocationChanged
06-23 14:43:21.146  6467  6467 I DOTNET  : Accelerometer_ReadingChanged
06-23 14:43:23.399  6467  6467 I chatty  : uid=10235(com.companyname.mauiapp1) identical 34 lines
06-23 14:43:23.465  6467  6467 I DOTNET  : Accelerometer_ReadingChanged
06-23 14:43:23.503  6467  6467 I DOTNET  : IsDifferent: long (3.67069 vs 3.6699900000000003)
06-23 14:43:23.503  6467  6467 I DOTNET  : DeviceLocationChanged
06-23 14:43:23.532  6467  6467 I DOTNET  : Accelerometer_ReadingChanged
06-23 14:43:26.115  6467  6467 I chatty  : uid=10235(com.companyname.mauiapp1) identical 39 lines
06-23 14:43:26.181  6467  6467 I DOTNET  : Accelerometer_ReadingChanged
06-23 14:43:26.193  6467  6467 I DOTNET  : IsDifferent: long (3.67152 vs 3.67069)
06-23 14:43:26.193  6467  6467 I DOTNET  : DeviceLocationChanged
06-23 14:43:26.247  6467  6467 I DOTNET  : Accelerometer_ReadingChanged
06-23 14:43:28.565  6467  6467 I chatty  : uid=10235(com.companyname.mauiapp1) identical 35 lines
06-23 14:43:28.632  6467  6467 I DOTNET  : Accelerometer_ReadingChanged
06-23 14:43:28.661  6467  6467 I DOTNET  : IsDifferent: long (3.6722900000000003 vs 3.67152)
06-23 14:43:28.661  6467  6467 I DOTNET  : DeviceLocationChanged
06-23 14:43:28.698  6467  6467 I DOTNET  : Accelerometer_ReadingChanged
06-23 14:43:30.420  6467  6467 I chatty  : uid=10235(com.companyname.mauiapp1) identical 26 lines
06-23 14:43:30.431  6467  6467 I DOTNET  : Accelerometer_ReadingChanged
06-23 14:43:30.434  2009  2039 E memtrack: Couldn't load memtrack module
06-23 14:43:30.434  2009  2039 W android.os.Debug: failed to get memory consumption info: -1
06-23 14:43:30.451  6467  6467 I DOTNET  : Accelerometer_ReadingChanged
06-23 14:43:31.090  6467  6467 I chatty  : uid=10235(com.companyname.mauiapp1) identical 28 lines
06-23 14:43:31.158  6467  6467 I DOTNET  : Accelerometer_ReadingChanged
06-23 14:43:31.180  6467  6467 I DOTNET  : IsDifferent: long (3.6730566666666666 vs 3.6722900000000003)
06-23 14:43:31.180  6467  6467 I DOTNET  : DeviceLocationChanged
06-23 14:43:31.223  6467  6467 I DOTNET  : Accelerometer_ReadingChanged
06-23 14:43:31.266  2009  6075 D WificondControl: Scan result ready event
06-23 14:43:31.290  6467  6467 I DOTNET  : Accelerometer_ReadingChanged
06-23 14:43:33.871  6467  6467 I chatty  : uid=10235(com.companyname.mauiapp1) identical 39 lines
06-23 14:43:33.938  6467  6467 I DOTNET  : Accelerometer_ReadingChanged
06-23 14:43:33.979  6467  6467 I DOTNET  : IsDifferent: long (3.673926666666667 vs 3.6730566666666666)
06-23 14:43:33.979  6467  6467 I DOTNET  : DeviceLocationChanged
06-23 14:43:34.004  6467  6467 I DOTNET  : Accelerometer_ReadingChanged
06-23 14:43:35.462  6467  6467 I chatty  : uid=10235(com.companyname.mauiapp1) identical 22 lines
06-23 14:43:35.528  6467  6467 I DOTNET  : Accelerometer_ReadingChanged
06-23 14:43:45.242  2009  2099 I InputDispatcher: Application is not responding: Window{5d8dc25 u0 com.companyname.mauiapp1/crc64e632a077a20c694c.MainActivity}.  It has been 5005.6ms since event, 5005.0ms since wait started.  Reason: Waiting because the touched window's input channel is full.  Outbound queue length: 1.  Wait queue length: 52.
06-23 14:43:45.243  2009  2099 I WindowManager: Input event dispatching timed out sending to com.companyname.mauiapp1/crc64e632a077a20c694c.MainActivity.  Reason: Waiting because the touched window's input channel is full.  Outbound queue length: 1.  Wait queue length: 52.
06-23 14:43:45.254  2009  2099 I ActivityManager: dumpStackTraces pids={2670=true, 2713=true, 2815=true, 2979=true, 3170=true, 3297=true, 3317=true, 3353=true, 3400=true, 4086=true, 6202=true, 8446=true, 15898=true, 16077=true, 16900=true, 22393=true, 27512=true, 28236=true, 32421=true} nativepids=[1661, 1796, 1800, 1842, 1843, 1854, 1856, 1859, 1860, 1862, 1866, 1868]
06-23 14:43:45.532  2009  2099 I ActivityManager: Skipping next CPU consuming process, not a java proc: 2009
06-23 14:43:45.532  2009  2099 I ActivityManager: Skipping next CPU consuming process, not a java proc: 1768
06-23 14:43:45.532  2009  2099 I ActivityManager: Skipping next CPU consuming process, not a java proc: 1800
06-23 14:43:45.532  2009  2099 I ActivityManager: Skipping next CPU consuming process, not a java proc: 2160
06-23 14:43:45.533  2009  2099 I ActivityManager: Dumping to /data/anr/anr_2023-06-23-14-43-45-533
06-23 14:43:45.533  2009  2099 I ActivityManager: Collecting stacks for pid 6467
06-23 14:43:45.533  2009  2099 I system_server: libdebuggerd_client: started dumping process 6467
06-23 14:43:45.534  1872  1872 I /system/bin/tombstoned: registered intercept for pid 6467 and type kDebuggerdJavaBacktrace
06-23 14:43:46.733  2009  2045 D KernelCpuUidUserSysTimeReader: Removing uids 10233-10233
06-23 14:43:50.312  2009  2045 E BluetoothAdapter: Bluetooth binder is null
06-23 14:43:50.385  1747  7868 I netd    : trafficSwapActiveStatsMap() <59.70ms>
06-23 14:43:50.386  1747  7868 I netd    : tetherGetStats() <0.60ms>
06-23 14:43:51.275  2009  6075 D WificondControl: Scan result ready event
06-23 14:43:55.544  1872  1872 I /system/bin/tombstoned: intercept for pid 6467 and type kDebuggerdJavaBacktrace terminated: due to timeout
06-23 14:43:55.545  2009  2099 E system_server: libdebuggerd_client: failed to read status response from tombstoned: timeout reached?
06-23 14:43:55.545  2009  2099 W ActivityManager: Dumping Java threads failed, initiating native stack dump.
06-23 14:43:55.545  2009  2099 I system_server: libdebuggerd_client: started dumping process 6467
06-23 14:43:55.546  1872  1872 I /system/bin/tombstoned: registered intercept for pid 6467 and type kDebuggerdNativeBacktrace
06-23 14:43:55.546  6467  6467 I libc    : Requested dump for tid 6467 (nyname.mauiapp1)
06-23 14:43:55.564  6529  6529 I crash_dump64: obtaining output fd from tombstoned, type: kDebuggerdNativeBacktrace
06-23 14:43:55.564  1872  1872 I /system/bin/tombstoned: received crash request for pid 6467
06-23 14:43:55.564  1872  1872 I /system/bin/tombstoned: found intercept fd 512 for pid 6467 and type kDebuggerdNativeBacktrace
06-23 14:43:55.564  6529  6529 I crash_dump64: performing dump of process 6467 (target tid = 6467)
06-23 14:43:55.652  2009  2099 I system_server: libdebuggerd_client: done dumping process 6467
06-23 14:43:55.654  2009  2099 I ActivityManager: Collecting stacks for pid 2009
06-23 14:43:55.654  2009  2099 I system_server: libdebuggerd_client: started dumping process 2009
06-23 14:43:55.655  1872  1872 I /system/bin/tombstoned: registered intercept for pid 2009 and type kDebuggerdJavaBacktrace
06-23 14:43:55.655  2009  2021 I system_server: Thread[7,tid=2021,WaitingInMainSignalCatcherLoop,Thread*=0x755ed52e0800,peer=0x136c01e0,"Signal Catcher"]: reacting to signal 3
06-23 14:43:55.655  2009  2021 I system_server: 
06-23 14:43:55.758  1872  1872 I /system/bin/tombstoned: received crash request for pid 2009
06-23 14:43:55.758  1872  1872 I /system/bin/tombstoned: found intercept fd 512 for pid 2009 and type kDebuggerdJavaBacktrace
06-23 14:43:55.758  2009  2021 I system_server: Wrote stack traces to tombstoned
06-23 14:43:55.766  2009  2099 I system_server: libdebuggerd_client: done dumping process 2009
06-23 14:43:55.768  2009  2099 I ActivityManager: Collecting stacks for pid 17556
06-23 14:43:55.768  2009  2099 I system_server: libdebuggerd_client: started dumping process 17556
06-23 14:43:55.768  1872  1872 I /system/bin/tombstoned: registered intercept for pid 17556 and type kDebuggerdJavaBacktrace
06-23 14:43:55.768 17556 17567 I putmethod.lati: Thread[5,tid=17567,WaitingInMainSignalCatcherLoop,Thread*=0x755ed52cd400,peer=0x139001a8,"Signal Catcher"]: reacting to signal 3
06-23 14:43:55.768 17556 17567 I putmethod.lati: 
06-23 14:43:55.807  1872  1872 I /system/bin/tombstoned: received crash request for pid 17556
06-23 14:43:55.807  1872  1872 I /system/bin/tombstoned: found intercept fd 512 for pid 17556 and type kDebuggerdJavaBacktrace
06-23 14:43:55.808 17556 17567 I putmethod.lati: Wrote stack traces to tombstoned
06-23 14:43:55.810  2009  2099 I system_server: libdebuggerd_client: done dumping process 17556
06-23 14:43:55.812  2009  2099 I ActivityManager: Collecting stacks for pid 2932
06-23 14:43:55.812  2009  2099 I system_server: libdebuggerd_client: started dumping process 2932
06-23 14:43:55.813  1872  1872 I /system/bin/tombstoned: registered intercept for pid 2932 and type kDebuggerdJavaBacktrace
06-23 14:43:55.813  2932  2951 I or.multidispla: Thread[4,tid=2951,WaitingInMainSignalCatcherLoop,Thread*=0x755ed6e11800,peer=0x12d00220,"Signal Catcher"]: reacting to signal 3
06-23 14:43:55.813  2932  2951 I or.multidispla: 
06-23 14:43:55.828  1872  1872 I /system/bin/tombstoned: received crash request for pid 2932
06-23 14:43:55.828  1872  1872 I /system/bin/tombstoned: found intercept fd 512 for pid 2932 and type kDebuggerdJavaBacktrace
06-23 14:43:55.828  2932  2951 I or.multidispla: Wrote stack traces to tombstoned
06-23 14:43:55.830  2009  2099 I system_server: libdebuggerd_client: done dumping process 2932
06-23 14:43:55.831  2009  2099 I ActivityManager: Collecting stacks for pid 2913
06-23 14:43:55.831  2009  2099 I system_server: libdebuggerd_client: started dumping process 2913
06-23 14:43:55.831  1872  1872 I /system/bin/tombstoned: registered intercept for pid 2913 and type kDebuggerdJavaBacktrace
06-23 14:43:55.832  2913  2926 I .ims.rcsservic: Thread[3,tid=2926,WaitingInMainSignalCatcherLoop,Thread*=0x755f6679bc00,peer=0x12d00220,"Signal Catcher"]: reacting to signal 3
06-23 14:43:55.832  2913  2926 I .ims.rcsservic: 
06-23 14:43:55.846  1872  1872 I /system/bin/tombstoned: received crash request for pid 2913
06-23 14:43:55.846  1872  1872 I /system/bin/tombstoned: found intercept fd 512 for pid 2913 and type kDebuggerdJavaBacktrace
06-23 14:43:55.847  2913  2926 I .ims.rcsservic: Wrote stack traces to tombstoned
06-23 14:43:55.848  2009  2099 I system_server: libdebuggerd_client: done dumping process 2913
06-23 14:43:55.850  2009  2099 I ActivityManager: Collecting stacks for pid 2890
06-23 14:43:55.850  2009  2099 I system_server: libdebuggerd_client: started dumping process 2890
06-23 14:43:55.850  1872  1872 I /system/bin/tombstoned: registered intercept for pid 2890 and type kDebuggerdJavaBacktrace
06-23 14:43:55.850  2890  2901 I com.android.se: Thread[5,tid=2901,WaitingInMainSignalCatcherLoop,Thread*=0x755ed52edc00,peer=0x12d00220,"Signal Catcher"]: reacting to signal 3
06-23 14:43:55.850  2890  2901 I com.android.se: 
06-23 14:43:55.871  1872  1872 I /system/bin/tombstoned: received crash request for pid 2890
06-23 14:43:55.871  1872  1872 I /system/bin/tombstoned: found intercept fd 512 for pid 2890 and type kDebuggerdJavaBacktrace
06-23 14:43:55.871  2890  2901 I com.android.se: Wrote stack traces to tombstoned
06-23 14:43:55.872  2009  2099 I system_server: libdebuggerd_client: done dumping process 2890
06-23 14:43:55.874  2009  2099 I ActivityManager: Collecting stacks for pid 2502
06-23 14:43:55.874  2009  2099 I system_server: libdebuggerd_client: started dumping process 2502
06-23 14:43:55.874  1872  1872 I /system/bin/tombstoned: registered intercept for pid 2502 and type kDebuggerdJavaBacktrace
06-23 14:43:55.874  2502  2513 I m.android.phon: Thread[7,tid=2513,WaitingInMainSignalCatcherLoop,Thread*=0x755ed52db400,peer=0x12d80220,"Signal Catcher"]: reacting to signal 3
06-23 14:43:55.875  2502  2513 I m.android.phon: 
06-23 14:43:55.902  1872  1872 I /system/bin/tombstoned: received crash request for pid 2502
06-23 14:43:55.902  1872  1872 I /system/bin/tombstoned: found intercept fd 512 for pid 2502 and type kDebuggerdJavaBacktrace
06-23 14:43:55.903  2502  2513 I m.android.phon: Wrote stack traces to tombstoned
06-23 14:43:55.906  2009  2099 I system_server: libdebuggerd_client: done dumping process 2502
06-23 14:43:55.908  2009  2099 I ActivityManager: Collecting stacks for pid 2434
06-23 14:43:55.908  2009  2099 I system_server: libdebuggerd_client: started dumping process 2434
06-23 14:43:55.908  1872  1872 I /system/bin/tombstoned: registered intercept for pid 2434 and type kDebuggerdJavaBacktrace
06-23 14:43:55.908  2434  2440 I id.networkstac: Thread[5,tid=2440,WaitingInMainSignalCatcherLoop,Thread*=0x755ed52c9c00,peer=0x13140220,"Signal Catcher"]: reacting to signal 3
06-23 14:43:55.908  2434  2440 I id.networkstac: 
06-23 14:43:55.943  1872  1872 I /system/bin/tombstoned: received crash request for pid 2434
06-23 14:43:55.943  1872  1872 I /system/bin/tombstoned: found intercept fd 512 for pid 2434 and type kDebuggerdJavaBacktrace
06-23 14:43:55.944  2434  2440 I id.networkstac: Wrote stack traces to tombstoned
06-23 14:43:55.946  2009  2099 I system_server: libdebuggerd_client: done dumping process 2434
06-23 14:43:55.947  2009  2099 I ActivityManager: Collecting stacks for pid 2160
06-23 14:43:55.948  2009  2099 I system_server: libdebuggerd_client: started dumping process 2160
06-23 14:43:55.948  1872  1872 I /system/bin/tombstoned: registered intercept for pid 2160 and type kDebuggerdJavaBacktrace
06-23 14:43:55.948  2160  2184 I ndroid.systemu: Thread[5,tid=2184,WaitingInMainSignalCatcherLoop,Thread*=0x755ed52c9c00,peer=0x12d40220,"Signal Catcher"]: reacting to signal 3
06-23 14:43:55.948  2160  2184 I ndroid.systemu: 
06-23 14:43:56.012  1872  1872 I /system/bin/tombstoned: received crash request for pid 2160
06-23 14:43:56.013  1872  1872 I /system/bin/tombstoned: found intercept fd 512 for pid 2160 and type kDebuggerdJavaBacktrace
06-23 14:43:56.013  2160  2184 I ndroid.systemu: Wrote stack traces to tombstoned
06-23 14:43:56.016  2009  2099 I system_server: libdebuggerd_client: done dumping process 2160
06-23 14:43:56.018  2009  2099 I ActivityManager: Collecting stacks for native pid 1661
06-23 14:43:56.018  2009  2099 I system_server: libdebuggerd_client: started dumping process 1661
06-23 14:43:56.018  1872  1872 I /system/bin/tombstoned: registered intercept for pid 1661 and type kDebuggerdNativeBacktrace
06-23 14:43:56.018  1661  1661 I libc    : Requested dump for tid 1661 (Binder:1661_2)
06-23 14:43:56.026  6534  6534 I crash_dump64: obtaining output fd from tombstoned, type: kDebuggerdNativeBacktrace
06-23 14:43:56.026  1872  1872 I /system/bin/tombstoned: received crash request for pid 1661
06-23 14:43:56.026  1872  1872 I /system/bin/tombstoned: found intercept fd 512 for pid 1661 and type kDebuggerdNativeBacktrace
06-23 14:43:56.026  6534  6534 I crash_dump64: performing dump of process 1661 (target tid = 1661)
06-23 14:43:56.029  2009  2099 I system_server: libdebuggerd_client: done dumping process 1661
06-23 14:43:56.031  2009  2099 I ActivityManager: Collecting stacks for native pid 1796
06-23 14:43:56.031  2009  2099 I system_server: libdebuggerd_client: started dumping process 1796
06-23 14:43:56.032  1872  1872 I /system/bin/tombstoned: registered intercept for pid 1796 and type kDebuggerdNativeBacktrace
06-23 14:43:56.032  1796  1796 I libc    : Requested dump for tid 1796 (audioserver)
06-23 14:43:56.042  6539  6539 I crash_dump64: obtaining output fd from tombstoned, type: kDebuggerdNativeBacktrace
06-23 14:43:56.043  1872  1872 I /system/bin/tombstoned: received crash request for pid 1796
06-23 14:43:56.043  1872  1872 I /system/bin/tombstoned: found intercept fd 512 for pid 1796 and type kDebuggerdNativeBacktrace
06-23 14:43:56.043  6539  6539 I crash_dump64: performing dump of process 1796 (target tid = 1796)
06-23 14:43:56.050  2009  2099 I system_server: libdebuggerd_client: done dumping process 1796
06-23 14:43:56.052  2009  2099 I ActivityManager: Collecting stacks for native pid 1800
06-23 14:43:56.052  2009  2099 I system_server: libdebuggerd_client: started dumping process 1800
06-23 14:43:56.052  1872  1872 I /system/bin/tombstoned: registered intercept for pid 1800 and type kDebuggerdNativeBacktrace
06-23 14:43:56.053  1800  1800 I libc    : Requested dump for tid 1800 (surfaceflinger)
06-23 14:43:56.062  6544  6544 I crash_dump64: obtaining output fd from tombstoned, type: kDebuggerdNativeBacktrace
06-23 14:43:56.063  1872  1872 I /system/bin/tombstoned: received crash request for pid 1800
06-23 14:43:56.063  1872  1872 I /system/bin/tombstoned: found intercept fd 512 for pid 1800 and type kDebuggerdNativeBacktrace
06-23 14:43:56.063  6544  6544 I crash_dump64: performing dump of process 1800 (target tid = 1800)
06-23 14:43:56.071  2009  2099 I system_server: libdebuggerd_client: done dumping process 1800
06-23 14:43:56.072  2009  2099 I ActivityManager: Collecting stacks for native pid 1842
06-23 14:43:56.073  2009  2099 I system_server: libdebuggerd_client: started dumping process 1842
06-23 14:43:56.073  1872  1872 I /system/bin/tombstoned: registered intercept for pid 1842 and type kDebuggerdNativeBacktrace
06-23 14:43:56.073  1842  1842 I libc    : Requested dump for tid 1842 (cameraserver)
06-23 14:43:56.085  6549  6549 I crash_dump64: obtaining output fd from tombstoned, type: kDebuggerdNativeBacktrace
06-23 14:43:56.085  1872  1872 I /system/bin/tombstoned: received crash request for pid 1842
06-23 14:43:56.085  1872  1872 I /system/bin/tombstoned: found intercept fd 512 for pid 1842 and type kDebuggerdNativeBacktrace
06-23 14:43:56.085  6549  6549 I crash_dump64: performing dump of process 1842 (target tid = 1842)
06-23 14:43:56.089  2009  2099 I system_server: libdebuggerd_client: done dumping process 1842
06-23 14:43:56.091  2009  2099 I ActivityManager: Collecting stacks for native pid 1843
06-23 14:43:56.091  2009  2099 I system_server: libdebuggerd_client: started dumping process 1843
06-23 14:43:56.092  1872  1872 I /system/bin/tombstoned: registered intercept for pid 1843 and type kDebuggerdNativeBacktrace
06-23 14:43:56.092  1843  1843 I libc    : Requested dump for tid 1843 (drmserver)
06-23 14:43:56.100  6554  6554 I crash_dump32: obtaining output fd from tombstoned, type: kDebuggerdNativeBacktrace
06-23 14:43:56.100  1872  1872 I /system/bin/tombstoned: received crash request for pid 1843
06-23 14:43:56.100  1872  1872 I /system/bin/tombstoned: found intercept fd 512 for pid 1843 and type kDebuggerdNativeBacktrace
06-23 14:43:56.100  6554  6554 I crash_dump32: performing dump of process 1843 (target tid = 1843)
06-23 14:43:56.103  2009  2099 I system_server: libdebuggerd_client: done dumping process 1843
06-23 14:43:56.105  2009  2099 I ActivityManager: Collecting stacks for native pid 1854
06-23 14:43:56.105  2009  2099 I system_server: libdebuggerd_client: started dumping process 1854
06-23 14:43:56.105  1872  1872 I /system/bin/tombstoned: registered intercept for pid 1854 and type kDebuggerdNativeBacktrace
06-23 14:43:56.105  1854  1854 I libc    : Requested dump for tid 1854 (mediadrmserver)
06-23 14:43:56.113  6559  6559 I crash_dump32: obtaining output fd from tombstoned, type: kDebuggerdNativeBacktrace
06-23 14:43:56.113  1872  1872 I /system/bin/tombstoned: received crash request for pid 1854
06-23 14:43:56.113  1872  1872 I /system/bin/tombstoned: found intercept fd 512 for pid 1854 and type kDebuggerdNativeBacktrace
06-23 14:43:56.113  6559  6559 I crash_dump32: performing dump of process 1854 (target tid = 1854)
06-23 14:43:56.116  2009  2099 I system_server: libdebuggerd_client: done dumping process 1854
06-23 14:43:56.117  2009  2099 I ActivityManager: Collecting stacks for native pid 1856
06-23 14:43:56.118  2009  2099 I system_server: libdebuggerd_client: started dumping process 1856
06-23 14:43:56.118  1872  1872 I /system/bin/tombstoned: registered intercept for pid 1856 and type kDebuggerdNativeBacktrace
06-23 14:43:56.118  1872  1872 I /system/bin/tombstoned: received crash request for pid 1856
06-23 14:43:56.118  1872  1872 I /system/bin/tombstoned: found intercept fd 512 for pid 1856 and type kDebuggerdNativeBacktrace
06-23 14:43:56.151  2009  2099 I system_server: libdebuggerd_client: done dumping process 1856
06-23 14:43:56.153  2009  2099 I ActivityManager: Collecting stacks for native pid 1859
06-23 14:43:56.153  2009  2099 I system_server: libdebuggerd_client: started dumping process 1859
06-23 14:43:56.153  1872  1872 I /system/bin/tombstoned: registered intercept for pid 1859 and type kDebuggerdNativeBacktrace
06-23 14:43:56.154  1859  1859 I libc    : Requested dump for tid 1859 (mediametrics)
06-23 14:43:56.162  6564  6564 I crash_dump64: obtaining output fd from tombstoned, type: kDebuggerdNativeBacktrace
06-23 14:43:56.162  1872  1872 I /system/bin/tombstoned: received crash request for pid 1859
06-23 14:43:56.162  1872  1872 I /system/bin/tombstoned: found intercept fd 512 for pid 1859 and type kDebuggerdNativeBacktrace
06-23 14:43:56.162  6564  6564 I crash_dump64: performing dump of process 1859 (target tid = 1859)
06-23 14:43:56.166  2009  2099 I system_server: libdebuggerd_client: done dumping process 1859
06-23 14:43:56.167  2009  2099 I ActivityManager: Collecting stacks for native pid 1860
06-23 14:43:56.167  2009  2099 I system_server: libdebuggerd_client: started dumping process 1860
06-23 14:43:56.168  1872  1872 I /system/bin/tombstoned: registered intercept for pid 1860 and type kDebuggerdNativeBacktrace
06-23 14:43:56.168  1860  1860 I libc    : Requested dump for tid 1860 (mediaserver)
06-23 14:43:56.176  6569  6569 I crash_dump32: obtaining output fd from tombstoned, type: kDebuggerdNativeBacktrace
06-23 14:43:56.176  1872  1872 I /system/bin/tombstoned: received crash request for pid 1860
06-23 14:43:56.176  1872  1872 I /system/bin/tombstoned: found intercept fd 512 for pid 1860 and type kDebuggerdNativeBacktrace
06-23 14:43:56.177  6569  6569 I crash_dump32: performing dump of process 1860 (target tid = 1860)
06-23 14:43:56.181  2009  2099 I system_server: libdebuggerd_client: done dumping process 1860
06-23 14:43:56.183  2009  2099 I ActivityManager: Collecting stacks for native pid 1862
06-23 14:43:56.183  2009  2099 I system_server: libdebuggerd_client: started dumping process 1862
06-23 14:43:56.183  1872  1872 I /system/bin/tombstoned: registered intercept for pid 1862 and type kDebuggerdNativeBacktrace
06-23 14:43:56.184  1862  1862 I libc    : Requested dump for tid 1862 (Binder:1862_2)
06-23 14:43:56.192  6574  6574 I crash_dump64: obtaining output fd from tombstoned, type: kDebuggerdNativeBacktrace
06-23 14:43:56.193  1872  1872 I /system/bin/tombstoned: received crash request for pid 1862
06-23 14:43:56.193  1872  1872 I /system/bin/tombstoned: found intercept fd 512 for pid 1862 and type kDebuggerdNativeBacktrace
06-23 14:43:56.193  6574  6574 I crash_dump64: performing dump of process 1862 (target tid = 1862)
06-23 14:43:56.200  2009  2099 I system_server: libdebuggerd_client: done dumping process 1862
06-23 14:43:56.201  2009  2099 I ActivityManager: Collecting stacks for native pid 1866
06-23 14:43:56.201  2009  2099 I system_server: libdebuggerd_client: started dumping process 1866
06-23 14:43:56.202  1872  1872 I /system/bin/tombstoned: registered intercept for pid 1866 and type kDebuggerdNativeBacktrace
06-23 14:43:56.203  1872  1872 I /system/bin/tombstoned: received crash request for pid 1866
06-23 14:43:56.203  1872  1872 I /system/bin/tombstoned: found intercept fd 512 for pid 1866 and type kDebuggerdNativeBacktrace
06-23 14:43:56.225  2009  2099 I system_server: libdebuggerd_client: done dumping process 1866
06-23 14:43:56.227  2009  2099 I ActivityManager: Collecting stacks for native pid 1868
06-23 14:43:56.227  2009  2099 I system_server: libdebuggerd_client: started dumping process 1868
06-23 14:43:56.227  1872  1872 I /system/bin/tombstoned: registered intercept for pid 1868 and type kDebuggerdNativeBacktrace
06-23 14:43:56.227  1872  1872 I /system/bin/tombstoned: received crash request for pid 1868
06-23 14:43:56.227  1872  1872 I /system/bin/tombstoned: found intercept fd 512 for pid 1868 and type kDebuggerdNativeBacktrace
06-23 14:43:56.235  2009  2099 I system_server: libdebuggerd_client: done dumping process 1868
06-23 14:43:56.236  2009  2099 I ActivityManager: Done dumping
06-23 14:43:56.242  2009  2099 E ActivityManager: ANR in com.companyname.mauiapp1 (com.companyname.mauiapp1/crc64e632a077a20c694c.MainActivity)
06-23 14:43:56.242  2009  2099 E ActivityManager: PID: 6467
06-23 14:43:56.242  2009  2099 E ActivityManager: Reason: Input dispatching timed out (Waiting because the touched window's input channel is full.  Outbound queue length: 1.  Wait queue length: 52.)
06-23 14:43:56.242  2009  2099 E ActivityManager: Parent: com.companyname.mauiapp1/crc64e632a077a20c694c.MainActivity
06-23 14:43:56.242  2009  2099 E ActivityManager: Load: 0.08 / 0.1 / 0.09
06-23 14:43:56.242  2009  2099 E ActivityManager: CPU usage from 5058ms to 10988ms later (2023-06-23 14:43:50.305 to 2023-06-23 14:43:56.236):
06-23 14:43:56.242  2009  2099 E ActivityManager:   6.9% 2009/system_server: 2.5% user + 4.3% kernel / faults: 2413 minor 2 major
06-23 14:43:56.242  2009  2099 E ActivityManager:   3% 2160/com.android.systemui: 1.6% user + 1.3% kernel / faults: 2286 minor 1 major
06-23 14:43:56.242  2009  2099 E ActivityManager:   2.5% 1800/surfaceflinger: 0.1% user + 2.3% kernel / faults: 97 minor
06-23 14:43:56.242  2009  2099 E ActivityManager:   1.5% 15898/com.google.android.gms.persistent: 0.1% user + 1.3% kernel / faults: 115 minor
06-23 14:43:56.242  2009  2099 E ActivityManager:   0.8% 1753/[email protected]: 0% user + 0.8% kernel
06-23 14:43:56.242  2009  2099 E ActivityManager:   0.6% 8446/com.google.process.gapps: 0% user + 0.6% kernel / faults: 107 minor
06-23 14:43:56.242  2009  2099 E ActivityManager:   0.3% 21962/adbd: 0% user + 0.3% kernel / faults: 1 minor
06-23 14:43:56.242  2009  2099 E ActivityManager:   0% 1/init: 0% user + 0% kernel
06-23 14:43:56.242  2009  2099 E ActivityManager:   0% 1856/media.extractor: 0% user + 0% kernel / faults: 3008 minor
06-23 14:43:56.242  2009  2099 E ActivityManager:   0.2% 2502/com.android.phone: 0% user + 0.2% kernel / faults: 564 minor
06-23 14:43:56.242  2009  2099 E ActivityManager:   0.2% 17556/com.google.android.inputmethod.latin: 0% user + 0.1% kernel / faults: 1668 minor
06-23 14:43:56.242  2009  2099 E ActivityManager:   0.3% 1650/logd: 0% user + 0.3% kernel
06-23 14:43:56.242  2009  2099 E ActivityManager:   0.3% 1787/[email protected]: 0% user + 0.3% kernel
06-23 14:43:56.242  2009  2099 E ActivityManager:   0% 1866/media.codec: 0% user + 0% kernel / faults: 2171 minor
06-23 14:43:56.242  2009  2099 E ActivityManager:   0% 2434/com.google.android.networkstack: 0% user + 0% kernel / faults: 483 minor 1 major
06-23 14:43:56.242  2009  2099 E ActivityManager:   0% 2890/com.android.se: 0% user + 0% kernel / faults: 360 minor
06-23 14:43:56.242  2009  2099 E ActivityManager:   0.1% 1768/[email protected]: 0% user + 0.1% kernel
06-23 14:43:56.242  2009  2099 E ActivityManager:   0% 1803/logcat: 0% user + 0% kernel
06-23 14:43:56.242  2009  2099 E ActivityManager:   0% 1859/media.metrics: 0% user + 0% kernel / faults: 171 minor
06-23 14:43:56.242  2009  2099 E ActivityManager:   0% 1860/mediaserver: 0% user + 0% kernel / faults: 139 minor
06-23 14:43:56.242  2009  2099 E ActivityManager:   0.1% 1862/statsd: 0.1% user + 0% kernel / faults: 33 minor
06-23 14:43:56.242  2009  2099 E ActivityManager:   0% 1868/media.swcodec: 0% user + 0% kernel / faults: 756 minor
06-23 14:43:56.242  2009  2099 E ActivityManager:   0% 1872/tombstoned: 0% user + 0% kernel
06-23 14:43:56.242  2009  2099 E ActivityManager:   0% 2807/kworker/u8:1: 0% user + 0% kernel
06-23 14:43:56.242  2009  2099 E ActivityManager:   0% 2913/com.android.ims.rcsservice: 0% user + 0% kernel / faults: 408 minor
06-23 14:43:56.242  2009  2099 E ActivityManager:   0% 2932/com.android.emulator.multidisplay: 0% user + 0% kernel / faults: 416 minor
06-23 14:43:56.242  2009  2099 E ActivityManager:   0% 6467/com.companyname.mauiapp1: 0% user + 0% kernel / faults: 174 minor
06-23 14:43:56.242  2009  2099 E ActivityManager:   0% 6511/logcat: 0% user + 0% kernel
06-23 14:43:56.242  2009  2099 E ActivityManager: 4.1% TOTAL: 1.6% user + 2.4% kernel + 0% iowait
06-23 14:43:56.242  2009  2099 E ActivityManager: CPU usage from 7ms to 274ms later (2023-06-23 14:43:45.254 to 2023-06-23 14:43:45.521):
06-23 14:43:56.242  2009  2099 E ActivityManager:   28% 2009/system_server: 4% user + 24% kernel / faults: 634 minor
06-23 14:43:56.242  2009  2099 E ActivityManager:     16% 2099/InputDispatcher: 0% user + 16% kernel
06-23 14:43:56.242  2009  2099 E ActivityManager:     8% 2023/HeapTaskDaemon: 4% user + 4% kernel
06-23 14:43:56.242  2009  2099 E ActivityManager:     4% 2024/ReferenceQueueD: 0% user + 4% kernel
06-23 14:43:56.242  2009  2099 E ActivityManager:   3.8% 1768/[email protected]: 0% user + 3.8% kernel
06-23 14:43:56.242  2009  2099 E ActivityManager:   3.8% 1800/surfaceflinger: 0% user + 3.8% kernel
06-23 14:43:56.242  2009  2099 E ActivityManager:     3.8% 1836/app: 0% user + 3.8% kernel
06-23 14:43:56.242  2009  2099 E ActivityManager:   4% 2160/com.android.systemui: 0% user + 4% kernel / faults: 4 minor
06-23 14:43:56.242  2009  2099 E ActivityManager:     4% 2160/ndroid.systemui: 0% user + 4% kernel
06-23 14:43:56.242  2009  2099 E ActivityManager: 11% TOTAL: 1.8% user + 9.4% kernel
@lordstyx lordstyx added the t/bug Something isn't working label Jun 23, 2023
@Eilon Eilon added the area-essentials Essentials: Device, Display, Connectivity, Secure Storage, Sensors, App Info label Jun 23, 2023
@BaY1251
Copy link

BaY1251 commented Jun 25, 2023

This issue occurred as early as Microsoft Visual Studio 17.6 and inexplicably flashed back,
The final error was' Channel is unrecoverably broken and will be disposed '.
Deeper error information cannot be obtained through current debugging methods

@lordstyx
Copy link
Author

Just confirmed that the issue is present in preview 6 as well.

@jonathanpeppers
Copy link
Member

I let the app (built in Release) run for a few minutes on a Pixel 5 and an emulator, but I'm not getting an ANR. I can tap the flyout.

Can you share the route file (GPX/KML) you're using here?

image

@jonathanpeppers jonathanpeppers added the s/needs-info Issue needs more info from the author label Aug 21, 2023
@ghost
Copy link

ghost commented Aug 21, 2023

Hi @lordstyx. We have added the "s/needs-info" label to this issue, which indicates that we have an open question for you before we can take further action. This issue will be closed automatically in 7 days if we do not hear back from you by then - please feel free to re-open it if you come back to this issue after that time.

@lordstyx
Copy link
Author

lordstyx commented Aug 21, 2023

Sample_route.zip

I'm not sure what happened, but just like you're showing in your screenshot, the Location feature of the Extended Controls in my Emulator has broken. The map in both the Single Point and Routes tab doesn't show, and I can't load a saved route, nor import an externally created route. I've attached a test route either way, but the emulator might also not load it for you as well.

You can however just run the app on a local device, and walk around for a bit. After a few location updates, the app also crashes as described.

[Edit]: I seem to get it more quickly when I change the location permission from "Allowed only while in use" to "Allowed all the time".

@ghost ghost added s/needs-attention Issue has more information and needs another look and removed s/needs-info Issue needs more info from the author labels Aug 21, 2023
@jonathanpeppers
Copy link
Member

Yeah, I can't get the routes to work in the emulator either. It just spins forever loading the file...

So, I tried on my Pixel 5 device, but the app also seems to be working.

I think you could enable Mono's tracing and the runtime will log every method called:

# clear the log
adb logcat -c
# enable tracing
adb shell setprop debug.mono.trace all
# run the app again, cause an ANR
# save the log
adb logcat -d > log.txt

You should see lines like this:

08-21 16:23:36.002 29755 29755 V mono    : [0x78158e04f8: 217.54216 39]
08-21 16:23:36.002 29755 29755 V mono    : LEAVE:c Microsoft.Maui.Devices.Sensors.AccelerometerImplementation/<>c__DisplayClass17_0:<OnChanged>b__0 ()(
08-21 16:23:36.002 29755 29755 V mono    :
08-21 16:23:36.002 29755 29755 V mono    : [0x78158e04f8: 217.54218 38]
08-21 16:23:36.002 29755 29755 V mono    : LEAVE:c Microsoft.Maui.ApplicationModel.MainThread:BeginInvokeOnMainThread (System.Action)(
08-21 16:23:36.002 29755 29755 V mono    :
08-21 16:23:36.002 29755 29755 V mono    : [0x78158e04f8: 217.54222 37]
08-21 16:23:36.002 29755 29755 V mono    : LEAVE:c Microsoft.Maui.Devices.Sensors.AccelerometerImplementation:OnChanged (Microsoft.Maui.Devices.Sensors.AccelerometerChangedEventArgs)(
08-21 16:23:36.002 29755 29755 V mono    :
08-21 16:23:36.002 29755 29755 V mono    : [0x78158e04f8: 217.54223 36]
08-21 16:23:36.002 29755 29755 V mono    : LEAVE:c Microsoft.Maui.Devices.Sensors.AccelerometerImplementation:OnChanged (Microsoft.Maui.Devices.Sensors.AccelerometerData)(
08-21 16:23:36.002 29755 29755 V mono    :
08-21 16:23:36.002 29755 29755 V mono    : [0x78158e04f8: 217.54226 35]
08-21 16:23:36.002 29755 29755 V mono    : LEAVE:c Microsoft.Maui.Devices.Sensors.AccelerometerListener:Android.Hardware.ISensorEventListener.OnSensorChanged (Android.Hardware.SensorEvent)(
08-21 16:23:36.002 29755 29755 V mono    :
08-21 16:23:36.002 29755 29755 V mono    : [0x78158e04f8: 217.54229 34]
08-21 16:23:36.002 29755 29755 V mono    : LEAVE:c Android.Hardware.ISensorEventListenerInvoker:n_OnSensorChanged_Landroid_hardware_SensorEvent_ (intptr,intptr,intptr)(

The class that looks questionable to me is CircularBuffer<T>. It seems like it could deadlock causing a problem like this.

Tracing will make the app very slow. To clear this later you can either reboot the device or run adb shell setprop debug.mono.trace "''".

@jonathanpeppers jonathanpeppers added s/needs-info Issue needs more info from the author and removed s/needs-attention Issue has more information and needs another look labels Aug 21, 2023
@ghost
Copy link

ghost commented Aug 21, 2023

Hi @lordstyx. We have added the "s/needs-info" label to this issue, which indicates that we have an open question for you before we can take further action. This issue will be closed automatically in 7 days if we do not hear back from you by then - please feel free to re-open it if you come back to this issue after that time.

@lordstyx
Copy link
Author

I was able to produce such a log with an ANR, the dump starts at timestamp 08-22 00:53:17.166.
mono_trace_log.zip

As to your comment about CircularBuffer<T>, it's been a while since I created the repro sample, but I've definitely been able to reproduce this without the AccelerationInfo.Start() being invoked. I've tried disabling all the various sensor sources one by one, but kept getting the crash without being able to identify a single perpetrator, that's why I left them all in.

To reproduce on my real device, I need to receive about three location updates, which requires me to walk ~50m.

@ghost ghost added s/needs-attention Issue has more information and needs another look and removed s/needs-info Issue needs more info from the author labels Aug 21, 2023
@jonathanpeppers
Copy link
Member

To reproduce on my real device, I need to receive about three location updates,

I had the app running on a Pixel 5 and drove around the block, and it was working? I'll look into your logs tomorrow, thanks.

One difference, is I'm using dotnet/maui/net8.0 branch and all the versions here, so these are nightly RC 1 builds of everything:

https://github.com/dotnet/maui/blob/net8.0/eng/Version.Details.xml

@jonathanpeppers
Copy link
Member

Hmm, it appears the last managed method is about 10 seconds from the ANR:

08-22 00:52:49.178 27207 27207 V mono    : LEAVE:c Android.Runtime.JNIEnv:_GetFloatArrayRegion (intptr,int,int,single[])(
08-22 00:52:49.178 27207 27207 V mono    : 
08-22 00:52:49.178 27207 27207 V mono    : [0x7a38a88500: 147.90739 17] 
08-22 00:52:49.178 27207 27207 V mono    : ENTER:c (wrapper alloc) object:AllocSmall (intptr,intptr)(
08-22 00:52:49.178 27207 27207 V mono    : 0x7898671ad8
08-22 00:52:49.178 27207 27207 V mono    : , 
08-22 00:52:49.178 27207 27207 V mono    : 0x14
08-22 00:52:49.178 27207 27207 V mono    : )
08-22 00:52:49.178 27207 27207 V mono    : [0x7a38a88500: 147.90743 18] 
08-22 00:52:49.178 27207 27207 V mono    : ENTER:c (wrapper managed-to-native) object:__icall_wrapper_mono_gc_alloc_obj (intptr,intptr)(
08-22 00:52:49.178 27207 27207 V mono    : 0x7898671ad8
08-22 00:52:49.178 27207 27207 V mono    : , 
08-22 00:52:49.178 27207 27207 V mono    : 0x18
08-22 00:52:49.178 27207 27207 V mono    : )
...
08-22 00:52:59.208  1517  2880 I WindowManager: ANR in Window{2a2df11 u0 com.companyname.mauiapp1/crc64e632a077a20c694c.MainActivity}. Reason:2a2df11 com.companyname.mauiapp1/crc64e632a077a20c694c.MainActivity (server) is not responding. Waited 10000ms for MotionEvent

So, it's in native code/runtime side where things are stuck. Somewhere in __icall_wrapper_mono_gc_alloc_obj.

@lordstyx are you using .NET 8 Preview 7? We disabled a feature in Release mode in the latest release:

dotnet/android@6836818

Can you try the latest release? Or set <AndroidEnableMarshalMethod>false</AndroidEnableMarshalMethods> in your project?

@lordstyx
Copy link
Author

I had so far still been using preview 6, from when originally reporting the issue.
After updating to preview 7 I can no longer reproduce the issue with the provided sample app.

In our actual app we also notice a big reduction in ANR's when building with preview 7, but they're not completely gone.
That might however be unrelated, and with the emulator's location simulation being broken it'll take some time to figure out what that is. Until then I think this issue can be closed.

Thank you.

@samhouts samhouts added the s/no-repro Can no longer be reproduced on latest label Aug 28, 2023
@samhouts samhouts added this to the .NET 8 + Servicing milestone Aug 28, 2023
@ghost ghost locked as resolved and limited conversation to collaborators Sep 27, 2023
Sign up for free to subscribe to this conversation on GitHub. Already have an account? Sign in.
Labels
area-essentials Essentials: Device, Display, Connectivity, Secure Storage, Sensors, App Info partner/android Issues for the Android SDK platform/android 🤖 s/needs-attention Issue has more information and needs another look s/no-repro Can no longer be reproduced on latest t/bug Something isn't working
Projects
None yet
Development

No branches or pull requests

5 participants