[Mono-2018-02] BCL Test suite is regularly crashing with a TypeInitializationException

[pjcollins]

Steps to Reproduce

1. Install the bcl-test suite on device and run the NUnit instrumentation as shown below:

adb shell am instrument -w Xamarin.Android.Bcl_Tests/xamarin.android.bcltests.NUnitInstrumentation

Expected Behavior

Suite runs to completion.

Actual Behavior

I'm seeing the following unhandled exception when executing this suite on many devices against the mono-2018-02 branch, however I don't believe it to be directly related to mono changes based on the JNI related stack trace:

04-13 17:22:13.032 E/mono-rt ( 2310): [ERROR] FATAL UNHANDLED EXCEPTION: System.TypeInitializationException: The type initializer for 'Types' threw an exception. ---> System.DllNotFoundException: jvm.dll
04-13 17:22:13.032 E/mono-rt ( 2310):   at (wrapper managed-to-native) Java.Interop.NativeMethods.JNI_GetCreatedJavaVMs(intptr[],int,int&)
04-13 17:22:13.032 E/mono-rt ( 2310):   at Java.Interop.JniRuntime.GetAvailableInvocationPointers () [0x00000] in <24e668a472b84815ba42576d196fd0e0>:0 
04-13 17:22:13.032 E/mono-rt ( 2310):   at Java.Interop.JniRuntime.get_CurrentRuntime () [0x0007b] in <24e668a472b84815ba42576d196fd0e0>:0 
04-13 17:22:13.032 E/mono-rt ( 2310):   at Java.Interop.JniEnvironmentInfo..ctor () [0x00006] in <24e668a472b84815ba42576d196fd0e0>:0 
04-13 17:22:13.032 E/mono-rt ( 2310):   at Java.Interop.JniEnvironment+<>c.<.cctor>b__35_0 () [0x00000] in <24e668a472b84815ba42576d196fd0e0>:0 
04-13 17:22:13.032 E/mono-rt ( 2310):   at System.Threading.ThreadLocal`1[T].GetValueSlow () [0x00031] in <4775dd050ce546a9814a2d17717c9d37>:0 
04-13 17:22:13.032 E/mono-rt ( 2310):   at System.Threading.ThreadLocal`1[T].get_Value () [0x0003e] in <4775dd050ce546a9814a2d17717c9d37>:0 
04-13 17:22:13.032 E/mono-rt ( 2310):   at Java.Interop.JniEnvironment.get_CurrentInfo () [0x00000] in <24e668a472b84815ba42576d196fd0e0>:0 
04-13 17:22:13.032 E/mono-rt ( 2310):   at Java.Interop.JniEnvironment+Types.FindClass (System.String classname) [0x00026] in <24e668a472b84815ba42576d196fd0e0>:0 
04-13 17:22:13.032 E/mono-rt ( 2310):   at Java.Interop.JniType..ctor (System.String classname) [0x00006] in <24e668a472b84815ba42576d196fd0e0>:0 
04-13 17:22:13.032 E/mono-rt ( 2310):   at Java.Interop.JniEnvironment+Types..cctor () [0x000d2] in <24e668a472b84815ba42576d196fd0e0>:0 
04-13 17:22:13.032 E/mono-rt ( 2310):    --- End of inner exception stack trace ---
04-13 17:22:13.032 E/mono-rt ( 2310):   at Java.Interop.JniType..ctor (System.String classname) [0x00006] in <24e668a472b84815ba42576d196fd0e0>:0 
04-13 17:22:13.032 E/mono-rt ( 2310):   at Java.Interop.JniType.GetCachedJniType (Java.Interop.JniType& cachedType, System.String classname) [0x00018] in <24e668a472b84815ba42576d196fd0e0>:0 
04-13 17:22:13.032 E/mono-rt ( 2310):   at Java.Interop.JniPeerMembers.get_JniPeerType () [0x0000c] in <24e668a472b84815ba42576d196fd0e0>:0 
04-13 17:22:13.032 E/mono-rt ( 2310):   at Java.Interop.JniPeerMembers+JniStaticMethods.GetMethodInfo (System.String encodedMember) [0x0002b] in <24e668a472b84815ba42576d196fd0e0>:0 
04-13 17:22:13.032 E/mono-rt ( 2310):   at Java.Interop.JniPeerMembers+JniStaticMethods.InvokeObjectMethod (System.String encodedMember, Java.Interop.JniArgumentValue* parameters) [0x00000] in <24e668a472b84815ba42576d196fd0e0>:0 
04-13 17:22:13.032 E/mono-rt ( 2310):   at Android.OS.Looper.get_MainLooper () [0x00000] in /Users/builder/data/lanes/5930/9aa1f0c7/source/monodroid/external/xamarin-android/src/Mono.Android/obj/Release/android-27/mcw/Android.OS.Looper.cs:68 
04-13 17:22:13.032 E/mono-rt ( 2310):   at Android.Runtime.AndroidEnvironment.GetDefaultSyncContext () [0x00000] in /Users/builder/data/lanes/5930/9aa1f0c7/source/monodroid/external/xamarin-android/src/Mono.Android/Android.Runtime/AndroidEnvironment.cs:259 
04-13 17:22:13.032 E/mono-rt ( 2310):   at System.AndroidPlatform.GetDefaultSyncContext () [0x00000] in <4775dd050ce546a9814a2d17717c9d37>:0 
04-13 17:22:13.032 E/mono-rt ( 2310):   at System.Threading.SynchronizationContext.GetThreadLocalContext () [0x00005] in <4775dd050ce546a9814a2d17717c9d37>:0 
04-13 17:22:13.032 E/mono-rt ( 2310):   at System.Threading.SynchronizationContext.get_Current () [0x00016] in <4775dd050ce546a9814a2d17717c9d37>:0 
04-13 17:22:13.032 E/mono-rt ( 2310):   at System.Threading.WaitHandle.WaitOneNative (System.Runtime.InteropServices.SafeHandle waitableSafeHandle, System.UInt32 millisecondsTimeout, System.Boolean hasThreadAffinity, System.Boolean exitContext) [0x00002] in <4775dd050ce546a9814a2d17717c9d37>:0 
04-13 17:22:13.032 E/mono-rt ( 2310):   at System.Threading.WaitHandle.InternalWaitOne (System.Runtime.InteropServices.SafeHandle waitableSafeHandle, System.Int64 millisecondsTimeout, System.Boolean hasThreadAffinity, System.Boolean exitContext) [0x00014] in <4775dd050ce546a9814a2d17717c9d37>:0 
04-13 17:22:13.032 E/mono-rt ( 2310):   at System.Threading.WaitHandle.WaitOne (System.Int64 timeout, System.Boolean exitContext) [0x00000] in <4775dd050ce546a9814a2d17717c9d37>:0 
04-13 17:22:13.032 E/mono-rt ( 2310):   at System.Threading.WaitHandle.WaitOne (System.Int32 millisecondsTimeout, System.Boolean exitContext) [0x00019] in <4775dd050ce546a9814a2d17717c9d37>:0 
04-13 17:22:13.032 E/mono-rt ( 2310):   at System.Threading.WaitHandle.WaitOne (System.Int32 millisecondsTimeout) [0x00000] in <4775dd050ce546a9814a2d17717c9d37>:0 
04-13 17:22:13.032 E/mono-rt ( 2310):   at System.Threading.Timer+Scheduler.SchedulerThread () [0x0020b] in <4775dd050ce546a9814a2d17717c9d37>:0 
04-13 17:22:13.032 E/mono-rt ( 2310):   at System.Threading.ThreadHelper.ThreadStart_Context (System.Object state) [0x00014] in <4775dd050ce546a9814a2d17717c9d37>:0 

Version Information

Operating System: Mac OS X 10.12.3
Product Name: Xamarin.Android
Branch Name: mono-2018-02
Build Revision: 998d3039edf500b71ccc2a2e0aac076aa62516eb

[Device] Manufacturer: Google, Model: Pixel XL, Version: 8.0.0, ABI: arm64-v8a
[Device] Manufacturer: HUAWEI, Model: VTR-L29, Version: 7.0, ABI: arm64-v8a
[Device] Manufacturer: LENOVO, Model: Lenovo K900_ROW, Version: 4.2.1, ABI: x86

Log File

http://xqa.blob.core.windows.net/gist/log-e9dea303ade84275a91249d678efb5d5.txt
http://xqa.blob.core.windows.net/gist/log-0331d118f1e047a39556bdc81129fd60.txt
http://xqa.blob.core.windows.net/gist/log-73af3bd7f90c4806bc618b515cd5be9e.txt

[jonpryor]

@luhenry: Did mono unit tests change in mono/2018-02 to run NUnit tests on a new AppDomain?

Nothing stands out to me from:

git diff origin/2017-12..origin/2018-02 mcs/class/corlib/Test

Here's what I think is happening is as follows:

1. Test creates a new thread.
2. New thread calls SynchronizationContext.Current property.
3. (2) calls Android.Runtime.AndroidEnvironment.GetDefaultSyncContext(), which needs to call some Java code.
4. Calling Java code requires a thread-local JNIEnv* value, bound as JniEnvironment.EnvironmentPointer.
5. Obtaining JniEnvironment.EnvironmentPointer in turn requires obtaining JavaVM*, which is done via the JniRuntime.CurrentRuntime property.

(5) is where things go "wonky". In normal use, there should be only one JVM in the process. The JVM is "registered" into JniRuntime.Runtimes in the JniRuntime(CreationOptions) constructor, which certainly should have finished executing long before the method in (1) has executed. (JNIEnv.Initialize() creates an AndroidRuntime instance which calls the above JniRuntime(CreationOptions) constructor, so this is all finished during process startup.)

This is where "something" is going horrifically wrong: JniRuntime.current is (somehow?!) null -- and this is not a thread-local value, so it should have certainly been long before e.g. TestInstrumentation<T>.OnCreate() is invoked, which in turn is invoked before any unit tests are executed.

Because JniRuntime.current is null, we then look into JniRuntime.Runtimes.Values, which must have zero values: if it had one, we'd be be fine, as it would be returned. If there were more than one, we'd throw a NotSupportedException. Neither occurs, and instead we progress onto lines 138 and call GetAvailableInvocationPointers(), which tries to P/Invoke into jvm.dll, which doesn't exist on Android (boom).

Since nothing makes sense, and JniRuntime.current is null and no Runtimes can be found, I have to surmise that we're executing in a new AppDomain.

Doing Java calls outside the default AppDomain is not behavior that we've previously supported. (It's arguably something we should support, but we'd need to figure out how, and this hasn't been important enough to figure out yet.)

[luhenry]

@jonpryor AFAIK we haven't change the way we run NUnit tests, especially on devices; @marek-safar @akoeplinger @lexas could you please confirm? As for verifying your hypothesis, would it be possible to Debug.Assert we are currently on the root AppDomain when accessing any JniRuntime fields or methods? A check in the static constructor could help us diagnose that. @pjcollins could you provide us with exactly what's getting invoked (package + command line) so we can try to verify locally. Thank you.

[lewurm]

There were changes to nunit-lite, but imho this should have been already a problem with 2017-12 if they are the cause of this issue. They mess with around with ExecutionContext, so it might be related?

2017-12 diff: mono/NUnitLite@a8bef89 (only one commit)
2018-02 diff: mono/NUnitLite@a8bef89...70bb70b
together: mono/NUnitLite@764656c...70bb70b

edit: XA doesn't use mono/external/nunit-lite:

Alexander Köplinger [22:37]
are you using nunitlite from mono?
Jonathan Pryor [22:38]
no. We remap nunitlite to Xamarin,Android.NUnitLite

[jonpryor]

Regarding XA doesn't use mono/external/nunit-lite, it's specifically the _RemapAssemblies target which invokes remap-assembly-ref to "replace" assembly references to nunitlite with references to Xamarin.Android.NUnitLite.

We may want to look into updating Xamarin.Android.NUnitLite to use nunitlite instead of "replacing" it, but that's a separate project entirely.

[jonpryor]

@luhenry asked:

would it be possible to Debug.Assert we are currently on the root AppDomain when accessing any JniRuntime fields or methods

I'm not at all sure how to do that. There is no AppDomain.IsRootDomain property or anything, so how can I tell that the current AppDomain is the root domain?

[jonpryor]

Hm, perhaps the AppDomain.IsDefaultAppDomain() method?

[jonpryor]

In largely unrelated observations, log-e9dea303ade84275a91249d678efb5d5.txt contains a truncated stack trace:

...
04-13 22:14:25.711 E/mono-rt (22802):   at System.Threading.ThreadHelper.ThreadStart_Context (System.Object state) [0x00014] in <4775dd050ce546a9814a2d17717c9d37>:0 
04-13 22:14:25.711 E/mono-rt (22802):   at System.Threading.ExecutionCont

The FATAL UNHANDLED EXCEPTION message is produced by mono_runtime_printf_err(), which calls g_log() (mono/utils/mono-logger-internals.h), which eventually calls __android_log_write(). The problem with __android_log_write() is that historically it may not print the entire message; it only prints the first X characters. (Historically, X was ~1024; now it appears to be closer to 4096, but it's still limited.)

We are thus "losing" some of the stack trace because of this call.

Console.WriteLine() split on newlines by using LogcatTextWriter before calling Log(string) (which calls g_log()).

[jonpryor]

@luhenry: Unfortunately we can't easily update JniRuntime to check the current AppDomain, because the PCL profile it current targets doesn't export AppDomains.

That said, I'm not sure we need JniRuntime here, as the call stack hits Android.Runtime.AndroidEnvironment.GetDefaultSyncContext() first.

Thus:

@pjcollins: Are you able to build xamarin-android yourself? If so, can you apply this patch, then rebuild and rerun the BCL tests?

diff --git a/src/Mono.Android/Android.Runtime/AndroidEnvironment.cs b/src/Mono.Android/Android.Runtime/AndroidEnvironment.cs
index e0ee094..fc443a5 100644
--- a/src/Mono.Android/Android.Runtime/AndroidEnvironment.cs
+++ b/src/Mono.Android/Android.Runtime/AndroidEnvironment.cs
@@ -256,6 +256,10 @@ namespace Android.Runtime {
 		// DO NOT REMOVE
 		static SynchronizationContext GetDefaultSyncContext ()
 		{
+			if (!AppDomain.CurrentDomain.IsDefaultAppDomain ()) {
+				Console.WriteLine ("# jonp: ERROR: Executing GetDefaultSyncContext() from outside the default AppDomain!");
+				Console.WriteLine (new System.Diagnostics.StackTrace (true).ToString ());
+			}
 			var looper = Android.OS.Looper.MainLooper;
 			if (Android.OS.Looper.MyLooper() == looper)
 				return Android.App.Application.SynchronizationContext;

[pjcollins]

@jonpryor: This seems to confirm your suspicion:

04-17 13:51:36.457 I/mono-stdout(29120): # jonp: ERROR: Executing GetDefaultSyncContext() from outside the default AppDomain!
04-17 13:51:36.458 I/NUnit   (29120): 	Passed
04-17 13:51:36.458 I/NUnit   (29120): FindLastIndexTest 
04-17 13:51:36.460 I/NUnit   (29120): 	Passed
04-17 13:51:36.460 I/NUnit   (29120): FindLastNullTest 
04-17 13:51:36.462 I/NUnit   (29120): 	Passed
04-17 13:51:36.462 I/NUnit   (29120): ICollection_IsReadOnly 
04-17 13:51:36.463 I/NUnit   (29120): 	Passed
04-17 13:51:36.463 I/NUnit   (29120): ICollectionNull 
04-17 13:51:36.466 I/NUnit   (29120): 	Passed
04-17 13:51:36.466 I/NUnit   (29120): IEnumerator_Current_Finished 
04-17 13:51:36.468 I/NUnit   (29120): 	Passed
04-17 13:51:36.468 I/NUnit   (29120): IEnumerator_Current_NotStarted 
04-17 13:51:36.469 I/NUnit   (29120): 	Passed
04-17 13:51:36.469 I/NUnit   (29120): IEnumerator_Current_Reset 
04-17 13:51:36.471 I/NUnit   (29120): 	Passed
04-17 13:51:36.471 I/NUnit   (29120): IEnumerator_Dispose 
04-17 13:51:36.472 I/NUnit   (29120): 	Passed
04-17 13:51:36.472 I/NUnit   (29120): IEnumerator_Reset 
04-17 13:51:36.473 I/NUnit   (29120): 	Passed
04-17 13:51:36.473 I/NUnit   (29120): IEnumerator_ZeroSize 
04-17 13:51:36.474 I/NUnit   (29120): 	Passed
04-17 13:51:36.474 I/NUnit   (29120): IListNull 
04-17 13:51:36.477 I/NUnit   (29120): 	Passed
04-17 13:51:36.477 I/NUnit   (29120): IStructuralEquatable_Equals 
04-17 13:51:36.480 I/NUnit   (29120): 	Passed
04-17 13:51:36.481 I/NUnit   (29120): IStructuralEquatable_Equals_ComparerThrows 
04-17 13:51:36.482 I/NUnit   (29120): 	Passed
04-17 13:51:36.483 I/NUnit   (29120): IStructuralEquatable_Equals_NoComparer 
04-17 13:51:36.483 I/NUnit   (29120): 	Passed
04-17 13:51:36.483 I/NUnit   (29120): IStructuralEquatable_GetHashCode 
04-17 13:51:36.485 I/NUnit   (29120): 	Passed
04-17 13:51:36.485 I/NUnit   (29120): IStructuralEquatable_GetHashCode_NullComparer 
04-17 13:51:36.486 I/NUnit   (29120): 	Passed
04-17 13:51:36.486 I/NUnit   (29120): JaggedArrayCtor 
04-17 13:51:36.487 I/NUnit   (29120): 	Passed
04-17 13:51:36.488 I/NUnit   (29120): LastIndexOf_0LengthArray 
04-17 13:51:36.488 I/mono-stdout(29120):   at Android.Runtime.AndroidEnvironment.GetDefaultSyncContext () [0x00000] in <79fa5d328cda49e3814075edd7cfe7b2>:0 
04-17 13:51:36.488 I/mono-stdout(29120):   at System.AndroidPlatform.GetDefaultSyncContext () [0x00000] in <40eb1ee749d24202bfb814ad0631ab5e>:0 
04-17 13:51:36.489 I/mono-stdout(29120):   at System.Threading.SynchronizationContext.GetThreadLocalContext () [0x00000] in <40eb1ee749d24202bfb814ad0631ab5e>:0 
04-17 13:51:36.489 I/mono-stdout(29120):   at System.Threading.SynchronizationContext.get_Current () [0x00000] in <40eb1ee749d24202bfb814ad0631ab5e>:0 
04-17 13:51:36.489 I/mono-stdout(29120):   at System.Threading.WaitHandle.WaitOneNative (System.Runtime.InteropServices.SafeHandle waitableSafeHandle, System.UInt32 millisecondsTimeout, System.Boolean hasThreadAffinity, System.Boolean exitContext) [0x00000] in <40eb1ee749d24202bfb814ad0631ab5e>:0 
04-17 13:51:36.489 I/mono-stdout(29120):   at System.Threading.WaitHandle.InternalWaitOne (System.Runtime.InteropServices.SafeHandle waitableSafeHandle, System.Int64 millisecondsTimeout, System.Boolean hasThreadAffinity, System.Boolean exitContext) [0x00000] in <40eb1ee749d24202bfb814ad0631ab5e>:0 
04-17 13:51:36.489 I/mono-stdout(29120):   at System.Threading.WaitHandle.WaitOne (System.Int64 timeout, System.Boolean exitContext) [0x00000] in <40eb1ee749d24202bfb814ad0631ab5e>:0 
04-17 13:51:36.489 I/mono-stdout(29120):   at System.Threading.WaitHandle.WaitOne (System.Int32 millisecondsTimeout, System.Boolean exitContext) [0x00000] in <40eb1ee749d24202bfb814ad0631ab5e>:0 
04-17 13:51:36.489 I/mono-stdout(29120):   at System.Threading.WaitHandle.WaitOne (System.Int32 millisecondsTimeout) [0x00000] in <40eb1ee749d24202bfb814ad0631ab5e>:0 
04-17 13:51:36.489 I/mono-stdout(29120):   at System.Threading.Timer+Scheduler.SchedulerThread () [0x00000] in <40eb1ee749d24202bfb814ad0631ab5e>:0 
04-17 13:51:36.489 I/mono-stdout(29120):   at System.Threading.ThreadHelper.ThreadStart_Context (System.Object state) [0x00000] in <40eb1ee749d24202bfb814ad0631ab5e>:0 
04-17 13:51:36.489 I/mono-stdout(29120):   at System.Threading.ExecutionContext.RunInternal (System.Threading.ExecutionContext executionContext, System.Threading.ContextCallback callback, System.Object state, System.Boolean preserveSyncCtx) [0x00000] in <40eb1ee749d24202bfb814ad0631ab5e>:0 
04-17 13:51:36.489 I/mono-stdout(29120):   at System.Threading.ExecutionContext.Run (System.Threading.ExecutionContext executionContext, System.Threading.ContextCallback callback, System.Object state, System.Boolean preserveSyncCtx) [0x00000] in <40eb1ee749d24202bfb814ad0631ab5e>:0 
04-17 13:51:36.489 I/mono-stdout(29120):   at System.Threading.ExecutionContext.Run (System.Threading.ExecutionContext executionContext, System.Threading.ContextCallback callback, System.Object state) [0x00000] in <40eb1ee749d24202bfb814ad0631ab5e>:0 
04-17 13:51:36.489 I/mono-stdout(29120):   at System.Threading.ThreadHelper.ThreadStart () [0x00000] in <40eb1ee749d24202bfb814ad0631ab5e>:0

[luhenry]

mono/mono@252d61d would explain this crash and is first released in 2018-02.