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.

Sign up for GitHub

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

Jump to bottom

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

Open
brendanzagaeski opened this issue Aug 6, 2020 · 2 comments
Open

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

brendanzagaeski opened this issue Aug 6, 2020 · 2 comments
Assignees
@jonpryor
Labels
Area: App Runtime Issues in `libmonodroid.so`.
Milestone
Under Consideration

Comments

@brendanzagaeski
Copy link
Member

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
@brendanzagaeski brendanzagaeski added the Area: App Runtime Issues in `libmonodroid.so`. label Aug 6, 2020
@brendanzagaeski brendanzagaeski added this to the Under Consideration milestone Aug 6, 2020
@brendanzagaeski brendanzagaeski mentioned this issue Aug 6, 2020
Closed
@roubachof
Copy link

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

@roubachof roubachof mentioned this issue Aug 6, 2020
Closed
@grendello grendello removed their assignment Jan 5, 2021
@jonpryor
Copy link
Member

jonpryor commented Jan 5, 2021

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.

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Assignees

@jonpryor jonpryor

Labels
Area: App Runtime Issues in `libmonodroid.so`.
Projects
None yet
Milestone
Under Consideration
Development

No branches or pull requests
4 participants
@jonpryor @grendello @roubachof @brendanzagaeski