Skip to content

Conversation

@jonathanpeppers
Copy link
Member

Context: c1a2ee7
Context: dotnet/runtime#44526

If c1a2ee7 is working now, we should be able to enable this test.

@jonpryor
Copy link
Contributor

Unexpectedly, the SubscribeToAppDomainUnhandledException test is failing:

Output did not contain # Unhandled Exception: sender=RootDomain; e.IsTerminating=True; e.ExceptionObject=System.Exception: CRASH!
Expected: True
But was:  False

Recall that the SubscribeToAppDomainUnhandledException test explicitly write out # Unhandled Exception as part of the event: https://github.com/xamarin/xamarin-android/blob/e4debf72015549e6e19cbfb247a47fead6ce7a01/tests/MSBuildDeviceIntegration/Tests/InstallAndRunTests.cs#L74

yet the logcat we see does not contain # Unhandled Exception (logcat-failed.log): https://devdiv.visualstudio.com/DevDiv/_build/results?buildId=5012995&view=ms.vss-test-web.build-test-results-tab&runId=23879608&resultId=100030&paneView=attachments

--------- beginning of crash
07-23 17:12:34.676 13747 13747 E AndroidRuntime: FATAL EXCEPTION: main
07-23 17:12:34.676 13747 13747 E AndroidRuntime: Process: com.xamarin.subscribetoappdomainunhandledexception, PID: 13747
07-23 17:12:34.676 13747 13747 E AndroidRuntime: android.runtime.JavaProxyThrowable: System.Exception: CRASH
07-23 17:12:34.676 13747 13747 E AndroidRuntime:    at UnnamedProject.MainActivity.OnCreate(Bundle bundle) in UnnamedProject.dll:token 0x6000001+0x70
07-23 17:12:34.676 13747 13747 E AndroidRuntime:    at Android.App.Activity.n_OnCreate_Landroid_os_Bundle_(IntPtr , IntPtr , IntPtr ) in Mono.Android.dll:token 0x60000e6+0xf
07-23 17:12:34.676 13747 13747 E AndroidRuntime: 	at com.xamarin.subscribetoappdomainunhandledexception.MainActivity.n_onCreate(Native Method)
07-23 17:12:34.676 13747 13747 E AndroidRuntime: 	at com.xamarin.subscribetoappdomainunhandledexception.MainActivity.onCreate(MainActivity.java:29)
07-23 17:12:34.676 13747 13747 E AndroidRuntime: 	at android.app.Activity.performCreate(Activity.java:7802)
07-23 17:12:34.676 13747 13747 E AndroidRuntime: 	at android.app.Activity.performCreate(Activity.java:7791)
07-23 17:12:34.676 13747 13747 E AndroidRuntime: 	at android.app.Instrumentation.callActivityOnCreate(Instrumentation.java:1299)
07-23 17:12:34.676 13747 13747 E AndroidRuntime: 	at android.app.ActivityThread.performLaunchActivity(ActivityThread.java:3245)
07-23 17:12:34.676 13747 13747 E AndroidRuntime: 	at android.app.ActivityThread.handleLaunchActivity(ActivityThread.java:3409)
07-23 17:12:34.676 13747 13747 E AndroidRuntime: 	at android.app.servertransaction.LaunchActivityItem.execute(LaunchActivityItem.java:83)
07-23 17:12:34.676 13747 13747 E AndroidRuntime: 	at android.app.servertransaction.TransactionExecutor.executeCallbacks(TransactionExecutor.java:135)
07-23 17:12:34.676 13747 13747 E AndroidRuntime: 	at android.app.servertransaction.TransactionExecutor.execute(TransactionExecutor.java:95)
07-23 17:12:34.676 13747 13747 E AndroidRuntime: 	at android.app.ActivityThread$H.handleMessage(ActivityThread.java:2016)
07-23 17:12:34.676 13747 13747 E AndroidRuntime: 	at android.os.Handler.dispatchMessage(Handler.java:107)
07-23 17:12:34.676 13747 13747 E AndroidRuntime: 	at android.os.Looper.loop(Looper.java:214)
07-23 17:12:34.676 13747 13747 E AndroidRuntime: 	at android.app.ActivityThread.main(ActivityThread.java:7356)
07-23 17:12:34.676 13747 13747 E AndroidRuntime: 	at java.lang.reflect.Method.invoke(Native Method)
07-23 17:12:34.676 13747 13747 E AndroidRuntime: 	at com.android.internal.os.RuntimeInit$MethodAndArgsCaller.run(RuntimeInit.java:492)
07-23 17:12:34.676 13747 13747 E AndroidRuntime: 	at com.android.internal.os.ZygoteInit.main(ZygoteInit.java:930)
…
07-23 17:12:34.985 13747 13747 F libc    : Fatal signal 6 (SIGABRT), code -1 (SI_QUEUE) in tid 13747 (andledexception), pid 13747 (andledexception)
…
07-23 17:12:35.045 13775 13775 F DEBUG   : Build fingerprint: 'Android/sdk_phone_x86_64/generic_x86_64:10/QPP6.190730.005.B1/5775370:userdebug/test-keys'
07-23 17:12:35.045 13775 13775 F DEBUG   : Revision: '0'
07-23 17:12:35.045 13775 13775 F DEBUG   : ABI: 'x86_64'
07-23 17:12:35.045 13775 13775 F DEBUG   : Timestamp: 2021-07-23 17:12:35+0000
07-23 17:12:35.045 13775 13775 F DEBUG   : pid: 13747, tid: 13747, name: andledexception  >>> com.xamarin.subscribetoappdomainunhandledexception <<<
07-23 17:12:35.045 13775 13775 F DEBUG   : uid: 10123
07-23 17:12:35.045 13775 13775 F DEBUG   : signal 6 (SIGABRT), code -1 (SI_QUEUE), fault addr --------
07-23 17:12:35.045 13775 13775 F DEBUG   :     rax 0000000000000000  rbx 00000000000035b3  rcx 000070960f5a33f8  rdx 0000000000000006
07-23 17:12:35.045 13775 13775 F DEBUG   :     r8  00007095383fdad8  r9  0000000000000000  r10 00007ffe1db58040  r11 0000000000000246
07-23 17:12:35.045 13775 13775 F DEBUG   :     r12 00007095383fdad8  r13 0000709582b17740  r14 00007ffe1db580c8  r15 00000000000035b3
07-23 17:12:35.046 13775 13775 F DEBUG   :     rdi 00000000000035b3  rsi 00000000000035b3
07-23 17:12:35.046 13775 13775 F DEBUG   :     rbp 0000000000000004  rsp 00007ffe1db58038  rip 000070960f5a33f8
07-23 17:12:35.197 13775 13775 F DEBUG   : 
07-23 17:12:35.197 13775 13775 F DEBUG   : backtrace:
07-23 17:12:35.197 13775 13775 F DEBUG   :       #00 pc 00000000000943f8  /apex/com.android.runtime/lib64/bionic/libc.so (syscall+24) (BuildId: a08a19770d6696739c847e29c3f5f650)
07-23 17:12:35.197 13775 13775 F DEBUG   :       #01 pc 0000000000097146  /apex/com.android.runtime/lib64/bionic/libc.so (abort+182) (BuildId: a08a19770d6696739c847e29c3f5f650)
07-23 17:12:35.197 13775 13775 F DEBUG   :       #02 pc 0000000000022b39  /data/app/com.xamarin.subscribetoappdomainunhandledexception-4dgowy4M8xJBQg_xhoeYfQ==/lib/x86_64/libmonodroid.so (xamarin::android::internal::MonodroidRuntime::mono_log_handler(char const*, char const*, char const*, int, void*)+105) (BuildId: d24ca129dde113a1011489c5e8050f507bff0e13)
07-23 17:12:35.197 13775 13775 F DEBUG   :       #03 pc 00000000002981fa  /data/app/com.xamarin.subscribetoappdomainunhandledexception-4dgowy4M8xJBQg_xhoeYfQ==/lib/x86_64/libmonosgen-2.0.so (BuildId: 82a6deae9c57db33d97a8ba2f3a0befc347711c2)
07-23 17:12:35.197 13775 13775 F DEBUG   :       #04 pc 00000000002982ad  /data/app/com.xamarin.subscribetoappdomainunhandledexception-4dgowy4M8xJBQg_xhoeYfQ==/lib/x86_64/libmonosgen-2.0.so (BuildId: 82a6deae9c57db33d97a8ba2f3a0befc347711c2)
07-23 17:12:35.197 13775 13775 F DEBUG   :       #05 pc 000000000010a54b  /data/app/com.xamarin.subscribetoappdomainunhandledexception-4dgowy4M8xJBQg_xhoeYfQ==/lib/x86_64/libmonosgen-2.0.so (BuildId: 82a6deae9c57db33d97a8ba2f3a0befc347711c2)
07-23 17:12:35.197 13775 13775 F DEBUG   :       #06 pc 000000000010bd10  /data/app/com.xamarin.subscribetoappdomainunhandledexception-4dgowy4M8xJBQg_xhoeYfQ==/lib/x86_64/libmonosgen-2.0.so (BuildId: 82a6deae9c57db33d97a8ba2f3a0befc347711c2)
07-23 17:12:35.197 13775 13775 F DEBUG   :       #07 pc 00000000000979d8  /data/app/com.xamarin.subscribetoappdomainunhandledexception-4dgowy4M8xJBQg_xhoeYfQ==/lib/x86_64/libmonosgen-2.0.so (BuildId: 82a6deae9c57db33d97a8ba2f3a0befc347711c2)
07-23 17:12:35.197 13775 13775 F DEBUG   :       #08 pc 00000000001ac0a5  /data/app/com.xamarin.subscribetoappdomainunhandledexception-4dgowy4M8xJBQg_xhoeYfQ==/lib/x86_64/libmonosgen-2.0.so (BuildId: 82a6deae9c57db33d97a8ba2f3a0befc347711c2)
07-23 17:12:35.197 13775 13775 F DEBUG   :       #09 pc 000000000001244a  <anonymous:62d25000>

@grendello: could you please investigate?

Does Console.WriteLine() work properly on .NET 6?

@grendello
Copy link
Contributor

grendello commented Jul 26, 2021

@jonpryor Console.WriteLine does work in NET6, the test added c1a2ee7 to uses it and it succeeded under NET6. I'll investigate this

@grendello
Copy link
Contributor

I looked at the test enabled in this PR, and c1a2ee7 cannot make it work because it deals with Java-to-Managed exception propagation, not with exceptions thrown from the managed code, like in the failing test. The dotnet issue is still there and I don't think this is something that Xamarin.Android should fix (e.g. by intercepting an "uncaught" exception somehow and calling mono_unhandled_exception).

@jonathanpeppers
Copy link
Member Author

Do we need to reopen dotnet/runtime#44526?

@grendello
Copy link
Contributor

Do we need to reopen dotnet/runtime#44526?

Yep

@grendello
Copy link
Contributor

With @jonpryor's change we now see the native mono_unhandled_exception function called via the monodroid_unhandled_exception icall (I modified our sources to print the icall function name on entry):

07-27 09:34:16.297 16947 16947 W monodroid: static void xamarin::android::internal::MonodroidRuntime::monodroid_unhandled_exception(MonoObject *)
07-27 09:34:16.303 16947 16947 E andledexceptio: (null) Cannot transition thread 0x7e452274f8 from STATE_BLOCKING with DO_BLOCKING
07-27 09:34:16.305 16947 16947 F libc    : Fatal signal 6 (SIGABRT), code -1 (SI_QUEUE) in tid 16947 (andledexception), pid 16947 (andledexception)
07-27 09:34:16.347 16975 16975 I crash_dump64: obtaining output fd from tombstoned, type: kDebuggerdTombstoneProto
07-27 09:34:16.348   882   882 I tombstoned: received crash request for pid 16947
07-27 09:34:16.348 16975 16975 I crash_dump64: performing dump of process 16947 (target tid = 16947)
07-27 09:34:16.363 16210 16353 I tflite  : Initialized TensorFlow Lite runtime.
07-27 09:34:16.375 16975 16975 E DEBUG   : failed to read /proc/uptime: Permission denied
07-27 09:34:16.847 16975 16975 F DEBUG   : *** *** *** *** *** *** *** *** *** *** *** *** *** *** *** ***
07-27 09:34:16.847 16975 16975 F DEBUG   : Build fingerprint: 'google/crosshatch/crosshatch:S/SPB2.210513.011/7465093:user/release-keys'
07-27 09:34:16.847 16975 16975 F DEBUG   : Revision: 'MP1.0'
07-27 09:34:16.847 16975 16975 F DEBUG   : ABI: 'arm64'
07-27 09:34:16.847 16975 16975 F DEBUG   : Timestamp: 2021-07-27 09:34:16.375092804+0200
07-27 09:34:16.847 16975 16975 F DEBUG   : Process uptime: 0s
07-27 09:34:16.847 16975 16975 F DEBUG   : Cmdline: com.xamarin.subscribetoappdomainunhandledexception
07-27 09:34:16.847 16975 16975 F DEBUG   : pid: 16947, tid: 16947, name: andledexception  >>> com.xamarin.subscribetoappdomainunhandledexception <<<
07-27 09:34:16.847 16975 16975 F DEBUG   : uid: 10426
07-27 09:34:16.847 16975 16975 F DEBUG   : signal 6 (SIGABRT), code -1 (SI_QUEUE), fault addr --------
07-27 09:34:16.847 16975 16975 F DEBUG   :     x0  0000000000000000  x1  0000000000004233  x2  0000000000000006  x3  0000007fd2ff47e0
07-27 09:34:16.847 16975 16975 F DEBUG   :     x4  1f6360647167731f  x5  1f6360647167731f  x6  1f6360647167731f  x7  7f7f7f7f7f7f7f7f
07-27 09:34:16.847 16975 16975 F DEBUG   :     x8  00000000000000f0  x9  77863297e2a4b1dd  x10 0000000000000000  x11 ffffff80fffffbdf
07-27 09:34:16.847 16975 16975 F DEBUG   :     x12 0000000000000001  x13 0000000000000052  x14 0000007c07f315b0  x15 0011f094d3a0f58d
07-27 09:34:16.847 16975 16975 F DEBUG   :     x16 0000007e3a8d9058  x17 0000007e3a8b5ec0  x18 0000007e44282000  x19 0000000000004233
07-27 09:34:16.847 16975 16975 F DEBUG   :     x20 0000000000004233  x21 00000000ffffffff  x22 0000007b19b0f000  x23 0000007b19b1f798
07-27 09:34:16.847 16975 16975 F DEBUG   :     x24 0000007c07f2fdb8  x25 0000007cb7f22010  x26 0000007c97fc0970  x27 0000007d17feaea0
07-27 09:34:16.847 16975 16975 F DEBUG   :     x28 0000007cd7f24870  x29 0000007fd2ff4860
07-27 09:34:16.847 16975 16975 F DEBUG   :     lr  0000007e3a868b7c  sp  0000007fd2ff47c0  pc  0000007e3a868ba8  pst 0000000000000000
07-27 09:34:16.847 16975 16975 F DEBUG   : backtrace:
07-27 09:34:16.847 16975 16975 F DEBUG   :       #00 pc 000000000004fba8  /apex/com.android.runtime/lib64/bionic/libc.so (abort+164) (BuildId: 8955af85d8857f3d34c01c417042bb85)
07-27 09:34:16.847 16975 16975 F DEBUG   :       #01 pc 00000000000202a0  /data/app/~~WGzlJqoXcJAxg3MqgIETrw==/com.xamarin.subscribetoappdomainunhandledexception-MS3ExbrN3P6rmyqfwgfA_g==/lib/arm64/libmonodroid.so (xamarin::android::internal::MonodroidRuntime::mono_log_handler(char const*, char const*, char const*, int, void*)+144) (BuildId: a51175cc7642482edf081242e71d8c3c8068e255)
07-27 09:34:16.847 16975 16975 F DEBUG   :       #02 pc 0000000000263018  /data/app/~~WGzlJqoXcJAxg3MqgIETrw==/com.xamarin.subscribetoappdomainunhandledexception-MS3ExbrN3P6rmyqfwgfA_g==/lib/arm64/libmonosgen-2.0.so (BuildId: a4973039d62bfbd82ebd74464acfa3feac913079)
07-27 09:34:16.847 16975 16975 F DEBUG   :       #03 pc 00000000002630a0  /data/app/~~WGzlJqoXcJAxg3MqgIETrw==/com.xamarin.subscribetoappdomainunhandledexception-MS3ExbrN3P6rmyqfwgfA_g==/lib/arm64/libmonosgen-2.0.so (BuildId: a4973039d62bfbd82ebd74464acfa3feac913079)
07-27 09:34:16.847 16975 16975 F DEBUG   :       #04 pc 000000000010aaac  /data/app/~~WGzlJqoXcJAxg3MqgIETrw==/com.xamarin.subscribetoappdomainunhandledexception-MS3ExbrN3P6rmyqfwgfA_g==/lib/arm64/libmonosgen-2.0.so (BuildId: a4973039d62bfbd82ebd74464acfa3feac913079)
07-27 09:34:16.847 16975 16975 F DEBUG   :       #05 pc 000000000010c324  /data/app/~~WGzlJqoXcJAxg3MqgIETrw==/com.xamarin.subscribetoappdomainunhandledexception-MS3ExbrN3P6rmyqfwgfA_g==/lib/arm64/libmonosgen-2.0.so (BuildId: a4973039d62bfbd82ebd74464acfa3feac913079)
07-27 09:34:16.847 16975 16975 F DEBUG   :       #06 pc 0000000000097a00  /data/app/~~WGzlJqoXcJAxg3MqgIETrw==/com.xamarin.subscribetoappdomainunhandledexception-MS3ExbrN3P6rmyqfwgfA_g==/lib/arm64/libmonosgen-2.0.so (BuildId: a4973039d62bfbd82ebd74464acfa3feac913079)
07-27 09:34:16.847 16975 16975 F DEBUG   :       #07 pc 00000000001a45dc  /data/app/~~WGzlJqoXcJAxg3MqgIETrw==/com.xamarin.subscribetoappdomainunhandledexception-MS3ExbrN3P6rmyqfwgfA_g==/lib/arm64/libmonosgen-2.0.so (BuildId: a4973039d62bfbd82ebd74464acfa3feac913079)
07-27 09:34:16.847 16975 16975 F DEBUG   :       #08 pc 0000000000008c50  <anonymous:7e3c781000>

After that the runtime calls abort() and the process is terminated, however we still don't appear to see the AppDomain.UnhandledException event. This line looks suspicious:

07-27 09:34:16.303 16947 16947 E andledexceptio: (null) Cannot transition thread 0x7e452274f8 from STATE_BLOCKING with DO_BLOCKING

The fatal error is reported by Mono, perhaps that's what eventually prevents the event from being raised? Perhaps the runtime is aborted before it even gets to the stage where it would raise the event?

@jonpryor
Copy link
Contributor

This should fix the Cannot transition thread message: dotnet/runtime#56380

Thanks @thaystg!

jonathanpeppers and others added 2 commits July 31, 2021 09:17
Context: c1a2ee7
Context: dotnet/runtime#44526

If c1a2ee7 is working now, we should be able to enable this test.
Context: dotnet/runtime#44526 (comment)
Context: dotnet/runtime#44526 (comment)
Context: start: https://discord.com/channels/732297728826277939/732297837953679412/869330822262587392
Context:   end? https://discord.com/channels/732297728826277939/732297837953679412/869343082552893440

On .NET 6, `JNIEnv.mono_unhandled_exception` is
`monodroid_debugger_unhandled_exception()`, which calls
`mono_debugger_agent_unhandled_exception()`; see also e4debf7.

The problem is that in our current world order of "Mono components"
(0f7a0cd), if the debugger isn't used, then we get "debugger stubs"
for the mono debugger agent, which turns
`mono_debugger_agent_unhandled_exception()` into an [*assertion*][0]:

	static void
	stub_debugger_unhandled_exception (MonoException *exc)
	{
		g_assert_not_reached ();
	}

The result is that when an exception is thrown, *before* the
`AppDomain.UnhandledException` event can be raised, the runtime dies
in a horrible flaming assertion death:

	E andledexceptio: * Assertion: should not be reached at /__w/1/s/src/mono/mono/component/debugger-stub.c:175

Avoid this issue by checking `Debugger.IsAttached` *before* calling
`monodroid_debugger_unhandled_exception()`.

Additionally, remove some obsolete comments: .NET 6 couldn't resolve
`Debugger.Mono_UnhandledException()` because .NET 6 never had it, so
the linker was right to warn about its absence.

[0]: https://github.com/dotnet/runtime/blob/16b456426dfb5212a24bfb78bfd5d9adfcc95185/src/mono/mono/component/debugger-stub.c#L172-L176
@jonathanpeppers jonathanpeppers force-pushed the subscribetoappdomainunhandledexception branch from 51f1b8d to 87849be Compare July 31, 2021 14:17
@jonathanpeppers
Copy link
Member Author

@grendello we should have dotnet/runtime#56380 now. But it's still failing:

image

Do we need 87849be? Maybe we don't actually need to check Debugger.IsAttached?

@grendello
Copy link
Contributor

@grendello we should have dotnet/runtime#56380 now. But it's still failing:

image

Do we need 87849be? Maybe we don't actually need to check Debugger.IsAttached?

I think we need both. The runtime fix was for the earlier error, 87849be was to fix an issue that was masked by the dotnet/runtime fix.

@jonpryor
Copy link
Contributor

Back on the unit test review front…

SubscribeToAppDomainUnhandledException is failing:

Output did not contain # Unhandled Exception: sender=RootDomain; e.IsTerminating=True; e.ExceptionObject=System.Exception: CRASH!
Expected: True
But was:  False

However, what's odd is that startup-logcat.log kinda contains that message!

07-31 16:38:04.882 13727 13727 I DOTNET  : # Unhandled Exception: sender=System.Object; e.IsTerminating=True; e.ExceptionObject=System.Exception
07-31 16:38:04.882 13727 13727 I DOTNET  : : CRASH
07-31 16:38:04.882 13727 13727 I DOTNET  :    at UnnamedProject.MainActivity.OnCreate(Bundle bundle) in UnnamedProject.dll:token 0x6000001+0x70
07-31 16:38:04.882 13727 13727 I DOTNET  :    at Android.App.Activity.n_OnCreate_Landroid_os_Bundle_(IntPtr , IntPtr , IntPtr ) in Mono.Android.dll:token 0x60000e6+0xf

Apparently CRASH is on a new line?

@thaystg : is this expected behavior in .NET 6+?

@thaystg
Copy link
Member

thaystg commented Aug 10, 2021

I really don't know, I tried to run on android sample on dotnet/runtime repo, something like this, without using AppDomainUnhandledException:

        try {
                throw new System.Exception("CRASH");
        }
        catch(System.Exception e)
        {
            Console.WriteLine("# Unhandled Exception: e.ExceptionObject={0}", e);
        }

And I got this on logcat:

08-10 16:02:49.498 16240 16267 I DOTNET  : # Unhandled Exception: e.ExceptionObject=System.Exce
08-10 16:02:49.498 16240 16267 I DOTNET  : ption: CRASH
08-10 16:02:49.498 16240 16267 I DOTNET  :    at Program.Main(String[] args) in /Users/thaysgrazia/runtime/src/mono/sample/Android/Program.cs:line 63

So, I think you cannot believe that the behavior would be print in one line.

@jonpryor
Copy link
Contributor

What might be happening is StreamWriter.WriteSpan(): https://github.com/dotnet/runtime/blob/dbb2b53e0caeeb32888f83a5c6fe6db8525398de/src/libraries/System.Private.CoreLib/src/System/IO/StreamWriter.cs#L449-L466

StreamWriter.Flush(bool, bool) calls LogcatStream.Write(ReadOnlySpan<byte>): https://github.com/dotnet/runtime/blob/dbb2b53e0caeeb32888f83a5c6fe6db8525398de/src/libraries/System.Console/src/System/ConsolePal.Android.cs#L16

Interop.Logcat.AndroidLogPrint(), meanwhile, is __android_log_print(): https://github.com/dotnet/runtime/blob/dbb2b53e0caeeb32888f83a5c6fe6db8525398de/src/libraries/Common/src/Interop/Android/Interop.Logcat.cs#L15

Every time __android_log_print() is invoked, a newline is written to adb logcat.

Thus, if the while loop in StreamWriter.WriteSpan() is executed more than once while trying to write the # Unhandled Exception: message, that could explain why CRASH is written on a separate line, and would explain what @thaystg described above.

This is "less than ideal behavior", shall we say? Regardless, to fix it, we'd have to "fix" dotnet/runtime…whatever that means/looks like.

Which means we instead need to look into fixing the test itself?

Context: dotnet#6119 (comment)

Looks like under .NET 6, `Console.WriteLine(s)` output isn't
guaranteed to be on a single (assuming `s` doesn't contain a newline).
This causes the existing `SubscribeToAppDomainUnhandledException()`
check to fail, because while it *wants*

	# Unhandled Exception: sender=RootDomain; e.IsTerminating=True; e.ExceptionObject=System.Exception: CRASH!

it's *actually* getting:

	# Unhandled Exception: sender=RootDomain; e.IsTerminating=True; e.ExceptionObject=System.Exception
	: CRASH!

Try to "add magic" around the line check so that expected output can
span multiple lines.  Let's see if that fixes things.
@jonpryor
Copy link
Contributor

The run MSBuildDeviceIntegration On Device - macOS - One .NET stage is consistently failing, but in a manner that means the Tests tab doesn't show any failures:

Starting test execution, please wait...
A total of 1 test files matched the specified pattern.
  Skipped CheckResouceIsOverridden(False) [142 ms]
The active test run was aborted. Reason: Test host process crashed : Unhandled exception. System.ArgumentOutOfRangeException: Count must be positive and count must refer to a location within the string/array/collection. (Parameter 'count')
   at System.Globalization.CompareInfo.IndexOf(String source, String value, Int32 startIndex, Int32 count, CompareOptions options)
   at System.String.IndexOf(String value, Int32 startIndex, Int32 count, StringComparison comparisonType)
   at Xamarin.Android.Build.Tests.InstallAndRunTests.<>c__DisplayClass5_0.<CreateLineChecker>b__0(String line) in /Users/builder/azdo/_work/2/s/xamarin-android/tests/MSBuildDeviceIntegration/Tests/InstallAndRunTests.cs:line 101
   at Xamarin.Android.Build.Tests.DeviceTest.<>c__DisplayClass19_0.<MonitorAdbLogcat>b__0(Object sender, DataReceivedEventArgs e) in /Users/builder/azdo/_work/2/s/xamarin-android/src/Xamarin.Android.Build.Tasks/Tests/Xamarin.Android.Build.Tests/Utilities/DeviceTest.cs:line 169
   at System.Diagnostics.AsyncStreamReader.FlushMessageQueue(Boolean rethrowInNewThread)
--- End of stack trace from previous location ---
   at System.Diagnostics.AsyncStreamReader.<>c.<FlushMessageQueue>b__18_0(Object edi)
   at System.Threading.QueueUserWorkItemCallback.<>c.<.cctor>b__6_0(QueueUserWorkItemCallback quwi)
   at System.Threading.ExecutionContext.RunForThreadPoolUnsafe[TState](ExecutionContext executionContext, Action`1 callback, TState& state)
   at System.Threading.QueueUserWorkItemCallback.Execute()
   at System.Threading.ThreadPoolWorkQueue.Dispatch()
   at System.Threading.PortableThreadPool.WorkerThread.WorkerThreadStart()
   at System.Threading.Thread.StartCallback()

Results File: /Users/runner/work/1/s/TestResult-MSBuildDeviceIntegration-mac_dotnetdevice_tests-Release.xml

Passed!  - Failed:     0, Passed:    27, Skipped:     1, Total:    28, Duration: 43 m 13 s - /Users/runner/work/1/s/bin/TestRelease/MSBuildDeviceIntegration/net6.0/MSBuildDeviceIntegration.dll (net6.0)
Test Run Aborted with error System.Exception: One or more errors occurred.
 ---> System.Exception: Unable to read beyond the end of the stream.
   at System.IO.BinaryReader.Read7BitEncodedInt()
   at System.IO.BinaryReader.ReadString()
   at Microsoft.VisualStudio.TestPlatform.CommunicationUtilities.LengthPrefixCommunicationChannel.NotifyDataAvailable()
   at Microsoft.VisualStudio.TestPlatform.CommunicationUtilities.TcpClientExtensions.MessageLoopAsync(TcpClient client, ICommunicationChannel channel, Action`1 errorHandler, CancellationToken cancellationToken)
   --- End of inner exception stack trace ---.

I saw this both before and after merging origin/main to this branch. I can only assume it's caused by c37f58a, as it didn't happen before that commit, but I don't see how c37f58a would be responsible. :-(

@jonpryor
Copy link
Contributor

I should learn to read better:

   at System.String.IndexOf(String value, Int32 startIndex, Int32 count, StringComparison comparisonType)
   at Xamarin.Android.Build.Tests.InstallAndRunTests.<>c__DisplayClass5_0.<CreateLineChecker>b__0(String line) in /Users/builder/azdo/_work/2/s/xamarin-android/tests/MSBuildDeviceIntegration/Tests/InstallAndRunTests.cs:line 101
   at Xamarin.Android.Build.Tests.DeviceTest.<>c__DisplayClass19_0.<MonitorAdbLogcat>b__0(Object sender, DataReceivedEventArgs e) in /Users/builder/azdo/_work/2/s/xamarin-android/src/Xamarin.Android.Build.Tasks/Tests/Xamarin.Android.Build.Tests/Utilities/DeviceTest.cs:line 169

This is within CreateLineChecker(), which is part of c37f58a. The callback is broken.

@jonpryor
Copy link
Contributor

…and once again, it would be nice if I could read

Expected text:

# Unhandled Exception: sender=RootDomain; e.IsTerminating=True; e.ExceptionObject=System.Exception: CRASH!

Actual text:

08-11 21:16:33.716 13697 13697 I DOTNET  : # Unhandled Exception: sender=System.Object; e.IsTerminating=True; e.ExceptionObject=System.Exception
08-11 21:16:33.716 13697 13697 I DOTNET  : : CRASH

In particular, note the sender value: we expect sender=RootDomain, while on net6 we instead have sender=System.Object. In addition to the output spanning two lines, there is also this overlooked difference.

@jonpryor
Copy link
Contributor

Finally, it works!!!!

@jonpryor
Copy link
Contributor

[tests] enable SubscribeToAppDomainUnhandledException in .NET 6 (#6119)

Context: c1a2ee70214e86757541b5759c9ed54941bd4680
Context: https://github.com/dotnet/runtime/issues/44526
Context: https://github.com/dotnet/runtime/issues/44526#issuecomment-886998881
Context: https://github.com/dotnet/runtime/issues/44526#issuecomment-887052471
Context: start: https://discord.com/channels/732297728826277939/732297837953679412/869330822262587392
Context:   end? https://discord.com/channels/732297728826277939/732297837953679412/869343082552893440
Context: https://github.com/dotnet/runtime/issues/57304

Now that we are calling `mono_unhandled_exception()` when an unhandled
exception is reported (c1a2ee70), we should be able re-enable the
`InstallAndRunTests.SubscribeToAppDomainUnhandledException()` unit
test on .NET 6, which was disabled in 6e3e3831af.

What seemed like it should have been a 1-line removal ballooned a bit
due to a confluence of factors:

 1. Debugger component stubs, and
 2. .NET 6 `Console.WriteLine()` behavior.

On .NET 6, `JNIEnv.mono_unhandled_exception()` is
`monodroid_debugger_unhandled_exception()`, which calls
`mono_debugger_agent_unhandled_exception()`; see also e4debf72.

The problem is that in our current world order of "Mono components"
(0f7a0cde), if the debugger isn't used, then we get "debugger stubs"
for the mono debugger agent, which turns
`mono_debugger_agent_unhandled_exception()` into an [*assertion*][0]:

	static void
	stub_debugger_unhandled_exception (MonoException *exc)
	{
		g_assert_not_reached ();
	}

The result is that when an exception is thrown, *before* the
`AppDomain.UnhandledException` event can be raised, the runtime dies
in a horrible flaming assertion death:

	E andledexceptio: * Assertion: should not be reached at /__w/1/s/src/mono/mono/component/debugger-stub.c:175

Avoid this issue by checking `Debugger.IsAttached` *before* calling
`monodroid_debugger_unhandled_exception()`.

Additionally, remove some obsolete comments: .NET 6 couldn't resolve
`Debugger.Mono_UnhandledException()` because .NET 6 never had it, so
the linker was right to warn about its absence.

The problem with .NET 6 & `Console.WriteLine()` is that when format
strings are used, the output may be line-wrapped in unexpected ways;
see also dotnet/runtime@#57304.  Additionally, the `sender` parameter
value differs under .NET 6.  These two issues broke our unit test;
we *expected* `adb logcat` to contain:

	# Unhandled Exception: sender=RootDomain; e.IsTerminating=True; e.ExceptionObject=System.Exception: CRASH

Under .NET 6, `adb logcat` *instead* contained:

	# Unhandled Exception: sender=System.Object; e.IsTerminating=True; e.ExceptionObject=System.Exception
	: CRASH

Yes, `: CRASH` was on a separate `adb logcat` line.

Fix the `SubscribeToAppDomainUnhandledException()` unit test so that
`adb logcat` messages can now span multiple lines (which is sure to
cause all sorts of GC garbage!), and update the expected message so
that we look for the right message under legacy & .NET 6.

Co-authored-by: Jonathan Pryor <jonpryor@vt.edu>

[0]: https://github.com/dotnet/runtime/blob/16b456426dfb5212a24bfb78bfd5d9adfcc95185/src/mono/mono/component/debugger-stub.c#L172-L176

@jonpryor jonpryor merged commit ab0ed93 into dotnet:main Aug 12, 2021
@jonathanpeppers jonathanpeppers deleted the subscribetoappdomainunhandledexception branch August 12, 2021 19:00
@github-actions github-actions bot locked and limited conversation to collaborators Jan 25, 2024
Sign up for free to subscribe to this conversation on GitHub. Already have an account? Sign in.

Labels

None yet

Projects

None yet

Development

Successfully merging this pull request may close these issues.

4 participants