Stack trace keeps getting longer when an exception instance that is propagated through both Java and managed code is thrown and handled repeatedly

[brendanzagaeski]

Context: #4632 (comment)

Steps to reproduce

1. Create a new Android App (Xamarin) > Single View App.

2. Similar to Fix XA_BROKEN_EXCEPTION_TRANSITIONS support #4548 (comment), add the following C# class:

   // C#
   public class CSharpThrows : Java.Lang.Object, Java.Lang.IRunnable
   {
       class StopException : Exception
       {
       }
   
       static StopException STOP_EXCEPTION = new StopException();
   
       public void Run()
       {
           throw STOP_EXCEPTION;
       }
   }

   And add the following in a JavaRunner.java file with the Build Action set to AndroidJavaSource:

   // Java
   public class JavaRunner {
       public void callRun(Runnable r) {
           r.run();
       }
   }

3. Add the following to the FabOnClick() method:

   try
   {
       IntPtr class_ref = JNIEnv.FindClass("JavaRunner");
       IntPtr id_ctor_I = JNIEnv.GetMethodID(class_ref, "<init>", "()V");
       IntPtr lrefInstance = JNIEnv.NewObject(class_ref, id_ctor_I, new JValue());
       var value = new Java.Lang.Object(lrefInstance, JniHandleOwnership.TransferLocalRef);
       IntPtr id_callRun = JNIEnv.GetMethodID(class_ref, "callRun", "(Ljava/lang/Runnable;)V");
       JNIEnv.CallVoidMethod(value.Handle, id_callRun, new JValue(new CSharpThrows()));
   }
   catch (Exception ex)
   {
       Console.WriteLine($"EXCEPTION: {ex}");
   }

4. Launch the app without the debugger attached.

5. Monitor the adb logcat 'mono-stdout:* *:S' output.

6. Tap the envelope icon button in the lower right of the app screen a few times.

Expected behavior

The catch block should produce the same output every time:

I mono-stdout: EXCEPTION: AndroidAppSingleView1.CSharpThrows+StopException: Exception of type 'AndroidAppSingleView1.CSharpThrows+StopException' was thrown.
I mono-stdout:   at AndroidAppSingleView1.CSharpThrows.Run () [0x00001] in <f2bb278a39884bc397fa66ae82cc4a31>:0
I mono-stdout:   at Java.Lang.IRunnableInvoker.n_Run (System.IntPtr jnienv, System.IntPtr native__this) [0x00008] in <9a644cc3d16a46d188196736019b9821>:0
I mono-stdout:   at (wrapper dynamic-method) Android.Runtime.DynamicMethodNameCounter.16(intptr,intptr)
I mono-stdout: --- End of stack trace from previous location where exception was thrown ---
I mono-stdout:
I mono-stdout:   at Java.Interop.JniEnvironment+InstanceMethods.CallVoidMethod (Java.Interop.JniObjectReference instance, Java.Interop.JniMethodInfo method, Java.Interop.JniArgumentValue* args) [0x0006e] in <6cbf2f3a8f4443d6971b2a070eb221ce>:0
I mono-stdout:   at Android.Runtime.JNIEnv.CallVoidMethod (System.IntPtr jobject, System.IntPtr jmethod, Android.Runtime.JValue* parms) [0x0000e] in <9a644cc3d16a46d188196736019b9821>:0
I mono-stdout:   at Android.Runtime.JNIEnv.CallVoidMethod (System.IntPtr jobject, System.IntPtr jmethod, Android.Runtime.JValue[] parms) [0x00018] in <9a644cc3d16a46d188196736019b9821>:0
I mono-stdout:   at AndroidAppSingleView1.MainActivity.FabOnClick (System.Object sender, System.EventArgs eventArgs) [0x00060] in <f2bb278a39884bc397fa66ae82cc4a31>:0

Actual behavior

The stack trace in the catch block output gets longer each time it runs.

First time:

I mono-stdout: EXCEPTION: AndroidAppSingleView1.CSharpThrows+StopException: Exception of type 'AndroidAppSingleView1.CSharpThrows+StopException' was thrown.
I mono-stdout:   at AndroidAppSingleView1.CSharpThrows.Run () [0x00001] in <f2bb278a39884bc397fa66ae82cc4a31>:0
I mono-stdout:   at Java.Lang.IRunnableInvoker.n_Run (System.IntPtr jnienv, System.IntPtr native__this) [0x00008] in <9a644cc3d16a46d188196736019b9821>:0
I mono-stdout:   at (wrapper dynamic-method) Android.Runtime.DynamicMethodNameCounter.16(intptr,intptr)
I mono-stdout: --- End of stack trace from previous location where exception was thrown ---
I mono-stdout:
I mono-stdout:   at Java.Interop.JniEnvironment+InstanceMethods.CallVoidMethod (Java.Interop.JniObjectReference instance, Java.Interop.JniMethodInfo method, Java.Interop.JniArgumentValue* args) [0x0006e] in <6cbf2f3a8f4443d6971b2a070eb221ce>:0
I mono-stdout:   at Android.Runtime.JNIEnv.CallVoidMethod (System.IntPtr jobject, System.IntPtr jmethod, Android.Runtime.JValue* parms) [0x0000e] in <9a644cc3d16a46d188196736019b9821>:0
I mono-stdout:   at Android.Runtime.JNIEnv.CallVoidMethod (System.IntPtr jobject, System.IntPtr jmethod, Android.Runtime.JValue[] parms) [0x00018] in <9a644cc3d16a46d188196736019b9821>:0
I mono-stdout:   at AndroidAppSingleView1.MainActivity.FabOnClick (System.Object sender, System.EventArgs eventArgs) [0x00060] in <f2bb278a39884bc397fa66ae82cc4a31>:0

Second time:

I mono-stdout: EXCEPTION: AndroidAppSingleView1.CSharpThrows+StopException: Exception of type 'AndroidAppSingleView1.CSharpThrows+StopException' was thrown.
I mono-stdout:   at AndroidAppSingleView1.CSharpThrows.Run () [0x00001] in <f2bb278a39884bc397fa66ae82cc4a31>:0
I mono-stdout:   at Java.Lang.IRunnableInvoker.n_Run (System.IntPtr jnienv, System.IntPtr native__this) [0x00008] in <9a644cc3d16a46d188196736019b9821>:0
I mono-stdout:   at (wrapper dynamic-method) Android.Runtime.DynamicMethodNameCounter.16(intptr,intptr)
I mono-stdout: --- End of stack trace from previous location where exception was thrown ---
I mono-stdout:
I mono-stdout:   at AndroidAppSingleView1.CSharpThrows.Run () [0x00001] in <f2bb278a39884bc397fa66ae82cc4a31>:0
I mono-stdout:   at Java.Lang.IRunnableInvoker.n_Run (System.IntPtr jnienv, System.IntPtr native__this) [0x00008] in <9a644cc3d16a46d188196736019b9821>:0
I mono-stdout:   at (wrapper dynamic-method) Android.Runtime.DynamicMethodNameCounter.16(intptr,intptr)
I mono-stdout: --- End of stack trace from previous location where exception was thrown ---
I mono-stdout:
I mono-stdout:   at Java.Interop.JniEnvironment+InstanceMethods.CallVoidMethod (Java.Interop.JniObjectReference instance, Java.Interop.JniMethodInfo method, Java.Interop.JniArgumentValue* args) [0x0006e] in <6cbf2f3a8f4443d6971b2a070eb221ce>:0
I mono-stdout:   at Android.Runtime.JNIEnv.CallVoidMethod (System.IntPtr jobject, System.IntPtr jmethod, Android.Runtime.JValue* parms) [0x0000e] in <9a644cc3d16a46d188196736019b9821>:0
I mono-stdout:   at Android.Runtime.JNIEnv.CallVoidMethod (System.IntPtr jobject, System.IntPtr jmethod, Android.Runtime.JValue[] parms) [0x00018] in <9a644cc3d16a46d188196736019b9821>:0
I mono-stdout:   at AndroidAppSingleView1.MainActivity.FabOnClick (System.Object sender, System.EventArgs eventArgs) [0x00060] in <f2bb278a39884bc397fa66ae82cc4a31>:0

Third time:

I mono-stdout: EXCEPTION: AndroidAppSingleView1.CSharpThrows+StopException: Exception of type 'AndroidAppSingleView1.CSharpThrows+StopException' was thrown.
I mono-stdout:   at AndroidAppSingleView1.CSharpThrows.Run () [0x00001] in <f2bb278a39884bc397fa66ae82cc4a31>:0
I mono-stdout:   at Java.Lang.IRunnableInvoker.n_Run (System.IntPtr jnienv, System.IntPtr native__this) [0x00008] in <9a644cc3d16a46d188196736019b9821>:0
I mono-stdout:   at (wrapper dynamic-method) Android.Runtime.DynamicMethodNameCounter.16(intptr,intptr)
I mono-stdout: --- End of stack trace from previous location where exception was thrown ---
I mono-stdout:
I mono-stdout:   at AndroidAppSingleView1.CSharpThrows.Run () [0x00001] in <f2bb278a39884bc397fa66ae82cc4a31>:0
I mono-stdout:   at Java.Lang.IRunnableInvoker.n_Run (System.IntPtr jnienv, System.IntPtr native__this) [0x00008] in <9a644cc3d16a46d188196736019b9821>:0
I mono-stdout:   at (wrapper dynamic-method) Android.Runtime.DynamicMethodNameCounter.16(intptr,intptr)
I mono-stdout: --- End of stack trace from previous location where exception was thrown ---
I mono-stdout:
I mono-stdout:   at AndroidAppSingleView1.CSharpThrows.Run () [0x00001] in <f2bb278a39884bc397fa66ae82cc4a31>:0
I mono-stdout:   at Java.Lang.IRunnableInvoker.n_Run (System.IntPtr jnienv, System.IntPtr native__this) [0x00008] in <9a644cc3d16a46d188196736019b9821>:0
I mono-stdout:   at (wrapper dynamic-method) Android.Runtime.DynamicMethodNameCounter.16(intptr,intptr)
I mono-stdout: --- End of stack trace from previous location where exception was thrown ---
I mono-stdout:
I mono-stdout:   at Java.Interop.JniEnvironment+InstanceMethods.CallVoidMethod (Java.Interop.JniObjectReference instance, Java.Interop.JniMethodInfo method, Java.Interop.JniArgumentValue* args) [0x0006e] in <6cbf2f3a8f4443d6971b2a070eb221ce>:0
I mono-stdout:   at Android.Runtime.JNIEnv.CallVoidMethod (System.IntPtr jobject, System.IntPtr jmethod, Android.Runtime.JValue* parms) [0x0000e] in <9a644cc3d16a46d188196736019b9821>:0
I mono-stdout:   at Android.Runtime.JNIEnv.CallVoidMethod (System.IntPtr jobject, System.IntPtr jmethod, Android.Runtime.JValue[] parms) [0x00018] in <9a644cc3d16a46d188196736019b9821>:0
I mono-stdout:   at AndroidAppSingleView1.MainActivity.FabOnClick (System.Object sender, System.EventArgs eventArgs) [0x00060] in <f2bb278a39884bc397fa66ae82cc4a31>:0

Partial workaround

Change CSharpThrows.Run() to create a new instance of StopException each time it is invoked:

 public void Run()
 {
-    throw STOP_EXCEPTION;
+    throw new StopException();
 }

This is only a partial workaround because in other contexts, like calling CSharpThrows.Run() directly from FabOnClick(), the stack trace behaves as expected without this workaround, so some user code might have scenarios where creating new StopException instances on each throw is not desirable.

Version information

Xamarin.Android SDK 11.0.99.9 (d16-8/2bd5c33)

Testing device: arm64-v8a Android 9.0 Pie (API level 28) Google Pixel 3

[roubachof]

Wow thank you so much @brendanzagaeski to go deep down and investigate this :)

[jonpryor]

This is probably a "won't fix", as I can't think of a fix that won't cause more problems than it solves.

First, why is the exception growing in the first place? The exception message grows because our exception marshaling code uses ExceptionDispatchInfo.Capture(Exception) and ExceptionDispatchInfo.Throw(). Exception marshaling occurs around every JNI call, e.g. for JNIEnv::NewObjectArray(), we use:

IntPtr thrown;
var tmp = NativeMethods.java_interop_jnienv_new_object_array (JniEnvironment.EnvironmentPointer, out thrown, length, elementClass.Handle, initialElement.Handle);

Exception __e = JniEnvironment.GetExceptionForLastThrowable (thrown);
if (__e != null)
	ExceptionDispatchInfo.Capture (__e).Throw ();

Because throw STOP_EXCEPTION causes the exception to be raised within Java code, and then later caught within the C# code calling the intermediate Java code, the exception marshaler behavior is equivalent to:

ExceptionDispatchInfo.Capture (STOP_EXCEPTION).Throw ();

The use of ExcpetionDispatchInfo.Throw() causes the continually growing stack trace.

The fundamental question is, how do we fix this? I don't know of any way to check if an exception has already been logged, and even if there were it might not be a good idea to use such a mechanism! Consider a Java > Managed > Java > Managed > Java > Managed stack trace. If the rightmost stack frame throws an exception which is caught by the leftmost stack frame, you want to see the intervening managed frames!

I suppose a fix could be to use ExceptionDispatchInfo.Throw(Exception) -- which didn't exist until .NET Standard 2.1, and thus didn't exist when this was first written -- but I don't currently know if that is an actual fix, because we want the call stack to be updated! We just don't want it to be constantly updated with the "same" current call stack.

[dotnet-policy-service]

We suspect this issue is stale and no longer relevant. It will be closed if no further activity occurs within 14 more days. Any new comment (by anyone, not necessarily the author) will undo this process.

[dotnet-policy-service]

This issue will now be closed since it had been marked "possibly-stale" but received no further activity in the past 14 days. It is still possible to reopen or comment on the issue, but please note that the issue will be locked if it remains inactive for another 30 days.