[Bug] Connectivity causes app crash on Android since EssentialsNetworkCallback is already disposed (Java.Interop.JavaLocationException)

cpraehaus commented 2 years ago

Description

Recently we experienced app crashes in our app on Android after we upgraded to XE 1.7.2. Probably due to #1568 . In our app we subscribe and unsubscribe to Connectivity.ConnectivityChanged event a few times during startup (not often). In some cases we observe app crashes where the app terminates with JavaLocationException shortly after starting (when the connectivity events are subscribed).

We think the reason is that by unsubscribing the event Connectivity stops and removes the listeners and disposes EssentialsNetworkCallback. However there is a (not so low) chance that callback invocation is already scheduled while managed wrapper EssentialsNetworkCallback is disposed (even if listener was currectly unregistered before). In this case the Java native/JNI domain cannot invoke the callback anymore causing the exception shown below which terminates the app.

Note that other XE modules like Magnetometer might also be affected by the same problem, see for example #1272 .

This is the exception we see (note that the stack trace might be slightly different depending on which network event is being delivered):

04-15 13:17:35.653 31179 31227 E AndroidRuntime: FATAL EXCEPTION: ConnectivityThread
04-15 13:17:35.653 31179 31227 E AndroidRuntime: Process: ***, PID: 31179
04-15 13:17:35.653 31179 31227 E AndroidRuntime: android.runtime.JavaProxyThrowable: System.NotSupportedException: Unable to activate instance of type Xamarin.Essentials.Connectivity+EssentialsNetworkCallback from native handle 0x780d4cef34 (key_handle 0x522746d). ---> System.MissingMethodException: No constructor found for Xamarin.Essentials.Connectivity+EssentialsNetworkCallback::.ctor(System.IntPtr, Android.Runtime.JniHandleOwnership) ---> Java.Interop.JavaLocationException: Exception of type 'Java.Interop.JavaLocationException' was thrown.
04-15 13:17:35.653 31179 31227 E AndroidRuntime:    --- End of inner exception stack trace ---
04-15 13:17:35.653 31179 31227 E AndroidRuntime:   at Java.Interop.TypeManager.CreateProxy (System.Type type, System.IntPtr handle, Android.Runtime.JniHandleOwnership transfer) [0x000b5] in <e41c0215a1b34d5f990de0d09dbe0e84>:0
04-15 13:17:35.653 31179 31227 E AndroidRuntime:   at Java.Interop.TypeManager.CreateInstance (System.IntPtr handle, Android.Runtime.JniHandleOwnership transfer, System.Type targetType) [0x00111] in <e41c0215a1b34d5f990de0d09dbe0e84>:0
04-15 13:17:35.653 31179 31227 E AndroidRuntime:    --- End of inner exception stack trace ---
04-15 13:17:35.653 31179 31227 E AndroidRuntime:   at Java.Interop.TypeManager.CreateInstance (System.IntPtr handle, Android.Runtime.JniHandleOwnership transfer, System.Type targetType) [0x0017e] in <e41c0215a1b34d5f990de0d09dbe0e84>:0
04-15 13:17:35.653 31179 31227 E AndroidRuntime:   at Java.Lang.Object.GetObject (System.IntPtr handle, Android.Runtime.JniHandleOwnership transfer, System.Type type) [0x00023] in <e41c0215a1b34d5f990de0d09dbe0e84>:0
04-15 13:17:35.653 31179 31227 E AndroidRuntime:   at Java.Lang.Object._GetObject[T] (System.IntPtr handle, Android.Runtime.JniHandleOwnership transfer) [0x00017] in <e41c0215a1b34d5f990de0d09dbe0e84>:0
04-15 13:17:35.653 31179 31227 E AndroidRuntime:   at Java.Lang.Object.GetObject[T] (System.IntPtr handle, Android.Runtime.JniHandleOwnership transfer) [0x00000] in <e41c0215a1b34d5f990de0d09dbe0e84>:0
04-15 13:17:35.653 31179 31227 E AndroidRuntime:   at Java.Lang.Object.GetObject[T] (System.IntPtr jnienv, System.IntPtr handle, Android.Runtime.JniHandleOwnership transfer) [0x00006] in <e41c0215a1b34d5f990de0d09dbe0e84>:0
04-15 13:17:35.653 31179 31227 E AndroidRuntime:   at Android.Net.ConnectivityManager+NetworkCallback.n_OnCapabilitiesChanged_Landroid_net_Network_Landroid_net_NetworkCapabilities_ (System.IntPtr jnienv, System.IntPtr native__this, System.IntPtr native_network, System.IntPtr native_networkCapabilities) [0x00000] in <e41c0215a1b34d5f990de0d09dbe0e84>:0
04-15 13:17:35.653 31179 31227 E AndroidRuntime:   at (wrapper dynamic-method) Android.Runtime.DynamicMethodNameCounter.42(intptr,intptr,intptr,intptr)
04-15 13:17:35.653 31179 31227 E AndroidRuntime:    at crc64a0e0a82d0db9a07d.Connectivity_EssentialsNetworkCallback.n_onCapabilitiesChanged(Native Method)
04-15 13:17:35.653 31179 31227 E AndroidRuntime:    at crc64a0e0a82d0db9a07d.Connectivity_EssentialsNetworkCallback.onCapabilitiesChanged(Connectivity_EssentialsNetworkCallback.java:50)
04-15 13:17:35.653 31179 31227 E AndroidRuntime:    at android.net.ConnectivityManager$NetworkCallback.onAvailable(ConnectivityManager.java:3580)
04-15 13:17:35.653 31179 31227 E AndroidRuntime:    at android.net.ConnectivityManager$CallbackHandler.handleMessage(ConnectivityManager.java:3793)
04-15 13:17:35.653 31179 31227 E AndroidRuntime:    at android.os.Handler.dispatchMessage(Handler.java:107)
04-15 13:17:35.653 31179 31227 E AndroidRuntime:    at android.os.Looper.loop(Looper.java:237)
04-15 13:17:35.653 31179 31227 E AndroidRuntime:    at android.os.HandlerThread.run(HandlerThread.java:67)

Here we see the course of events during a local repro:

Try no.: 0
// ConnectivityChanged subscribed
[App]  INFO 2022-04-20 10:54:48.8057 [1/NetworkConnectivity] Subscribe ConnectivityChanged 
[ConnectivityManager] requestNetwork; CallingUid : 10262, CallingPid : 6993
Thread started:  #12
// ConnectivityChanged unsubscribed and subscribed again immediately afterwards
[App]  INFO 2022-04-20 10:54:48.9300 [1/NetworkConnectivity] Un-subscribe ConnectivityChanged 
[ConnectivityManager] unregisterNetworkCallback; CallingUid : 10262, CallingPid : 6993
Try no.: 1
// ConnectivityChanged subscribed again ...
[App]  INFO 2022-04-20 10:54:48.9387 [1/NetworkConnectivity] Subscribe ConnectivityChanged 
[ConnectivityManager] requestNetwork; CallingUid : 10262, CallingPid : 6993
[App]  INFO 2022-04-20 10:54:48.9689 [1/NetworkConnectivity] Un-subscribe ConnectivityChanged 
[ConnectivityManager] unregisterNetworkCallback; CallingUid : 10262, CallingPid : 6993
Try no.: 2
[ConnectivityManager.CallbackHandler] callback not found for CALLBACK_AVAILABLE message
[App]  INFO 2022-04-20 10:54:48.9744 [1/NetworkConnectivity] Subscribe ConnectivityChanged 
[ConnectivityManager] requestNetwork; CallingUid : 10262, CallingPid : 6993
[App]  INFO 2022-04-20 10:54:49.0019 [1/NetworkConnectivity] Un-subscribe ConnectivityChanged 
[ConnectivityManager] unregisterNetworkCallback; CallingUid : 10262, CallingPid : 6993
Try no.: 3
[ConnectivityManager.CallbackHandler] callback not found for CALLBACK_AVAILABLE message
[App]  INFO 2022-04-20 10:54:49.0071 [1/NetworkConnectivity] Subscribe ConnectivityChanged 
[ConnectivityManager] requestNetwork; CallingUid : 10262, CallingPid : 6993
[App]  INFO 2022-04-20 10:54:49.0336 [1/NetworkConnectivity] Un-subscribe ConnectivityChanged 
[ConnectivityManager] unregisterNetworkCallback; CallingUid : 10262, CallingPid : 6993
Try no.: 4
[App]  INFO 2022-04-20 10:54:49.0364 [1/NetworkConnectivity] Subscribe ConnectivityChanged 
[ConnectivityManager.CallbackHandler] callback not found for CALLBACK_AVAILABLE message
[ConnectivityManager] requestNetwork; CallingUid : 10262, CallingPid : 6993
[App]  INFO 2022-04-20 10:54:49.0649 [1/NetworkConnectivity] Un-subscribe ConnectivityChanged 
[ConnectivityManager] unregisterNetworkCallback; CallingUid : 10262, CallingPid : 6993
Try no.: 5
[App]  INFO 2022-04-20 10:54:49.0698 [1/NetworkConnectivity] Subscribe ConnectivityChanged 
[ConnectivityManager.CallbackHandler] callback not found for CALLBACK_AVAILABLE message
[ConnectivityManager] requestNetwork; CallingUid : 10262, CallingPid : 6993
[App]  INFO 2022-04-20 10:54:49.1251 [1/NetworkConnectivity] Un-subscribe ConnectivityChanged 
[ConnectivityManager] unregisterNetworkCallback; CallingUid : 10262, CallingPid : 6993
Try no.: 6
[App]  INFO 2022-04-20 10:54:49.1314 [1/NetworkConnectivity] Subscribe ConnectivityChanged 
[ConnectivityManager] requestNetwork; CallingUid : 10262, CallingPid : 6993
[App]  INFO 2022-04-20 10:54:49.1907 [1/NetworkConnectivity] Un-subscribe ConnectivityChanged 
[ConnectivityManager] unregisterNetworkCallback; CallingUid : 10262, CallingPid : 6993
[ConnectivityManager.CallbackHandler] callback not found for CALLBACK_AVAILABLE message
Try no.: 7
[App]  INFO 2022-04-20 10:54:49.1987 [1/NetworkConnectivity] Subscribe ConnectivityChanged 
[ConnectivityManager] requestNetwork; CallingUid : 10262, CallingPid : 6993
[App]  INFO 2022-04-20 10:54:49.2554 [1/NetworkConnectivity] Un-subscribe ConnectivityChanged 
[ConnectivityManager] unregisterNetworkCallback; CallingUid : 10262, CallingPid : 6993
Try no.: 8
[App]  INFO 2022-04-20 10:54:49.2633 [1/NetworkConnectivity] Subscribe ConnectivityChanged 
**System.NotSupportedException:** 'Unable to activate instance of type Xamarin.Essentials.Connectivity+EssentialsNetworkCallback from native handle 0x71172f5744 (key_handle 0x69dc2ec).'

[ConnectivityManager] requestNetwork; CallingUid : 10262, CallingPid : 6993
[App]  INFO 2022-04-20 10:54:49.6225 [1/NetworkConnectivity] Un-subscribe ConnectivityChanged 
[ConnectivityManager] unregisterNetworkCallback; CallingUid : 10262, CallingPid : 6993
Try no.: 9
[App]  INFO 2022-04-20 10:54:49.6395 [1/NetworkConnectivity] Subscribe ConnectivityChanged

Steps to Reproduce

Ensure no other delegate is subscribed to ConnectivityChanged
Perform the following steps in a loop (usually appears after a few hundred iterations) a. Subscribe to ConnectivityChanged b. Unsubscribe to ConnectivityChanged

Expected Behavior

ConnectivityChanged can be subscribed/unsubscribed multiple times without problems.

Actual Behavior

App crashes when ConnectivityChanged is subscribed/unsubscribed multiple times.

Basic Information

Version with issue: 1.7.2
Last known good version: 1.7.0
Platform Target Frameworks:
- Android: >= 7.1

Screenshots

None

Reproduction Link

On request

jonpryor commented 1 year ago

The problem is that the Xamarin.Essentials.Connectivity.EssentialsNetworkCallback instance is being collected when Java still wants to invoke methods on it.

This suggests a premature .Dispose() call or a GC bug.

Please collect and provide GREF logs; see also:

https://github.com/xamarin/xamarin-android/blob/ff5455ca95fc83c788e957353114578abf3b4f54/Documentation/guides/internals/debug-jni-objrefs.md#crash-via-unhandled-exception

jonpryor commented 1 year ago

With a quick (quick!) code review, I suspect that the "problem" is actually networkCallback?.Dispose():

https://github.com/xamarin/Essentials/blob/25ceeea887c50e5194d746bd159be1f143e26157/Xamarin.Essentials/Connectivity/Connectivity.android.cs#L89-L92

If we assume a multithreaded environment, it is possible that while "Thead 1" calls Connectivity.UnregisterNetworkCallback() + ConnectivityManager.UnregisterNetworkCallback() + EssentialsNetworkCallback.Dispose(), another Java thread may attempt to attempt to invoke networkCallback methods after the dispose:

Thread 2 (Java): ConnectivityManager.NetworkCallback cb = /* something that gets the EssentialsNetworkCallback instance */
Thread 1 (C#): Connectivity.UnregisterNetworkCallback() (doesn't impact (1))
Thread 1 (C#): ConnectivityManager.UnregisterNetworkCallback(networkCallback) (doesn't impact (1))
Thread 1 (C#) : networkCallback.Dispose() (removes association between cb and networkCallback)
Thread 2 (Java): cb.onUnavailable() (or any other NetworkCallback method)

At this point there is no association between the Java instance and the C# instance, so Xamarin.Android attempts to create one via the (IntPtr, JniHandleOwnership) constructor, which doesn't exist, which results in the reported JavaProxyThrowable + NotSupportedException.

If this is the case, the fix is to not call .Dispose(), and simply remove this line:

https://github.com/xamarin/Essentials/blob/25ceeea887c50e5194d746bd159be1f143e26157/Xamarin.Essentials/Connectivity/Connectivity.android.cs#L91

Redth commented 1 year ago

@jfversluis could you please take a look?

borrrden commented 1 year ago

Will the dispose removal be committed to Xamarin Essentials?

xamarin / Essentials