The Android logging support has broken a diagnostics exception handling test

[janvorli]

The change #113416 has broken the UnhandledExceptionTest in the dotnet diagnostic tests. It looks like the test can see added extra newlines in the unhandled exception stack trace dumped to the console. The test verifies that the output matches an expected result and it fails due to that.
Interestingly, when the output is printed to console, there are no extra newlines, it only happens when the output is redirected. Even redirecting to a file causes this problem.

[dotnet-policy-service]

Tagging subscribers to this area: @mangod9
See info in area-owners.md if you want to be subscribed.

[janvorli]

FYI: @dotnet/dotnet-diag

[lateralusX]

@janvorli I'm aware of one place where the format slightly changed as agreed here, (#113416 (comment)) breaking up the logging on two lines as part of that PR and added a newline after printing the first error:

   -         PrintToStdErrA("Process terminated. ");
   +        PrintToStdErrA("Process terminated.\n");

or

   -         PrintToStdErrA("Fatal error. ");
   +        PrintToStdErrA("Fatal error.\n");

so, it was at least a conscious decision, but that is when logging fatal errors. For the actual stack trace I don't think we changed anything explicit around that, except that we format in buffer and convert from unicode to console codepage before writing parts of data into console that previously was written using multiple calls, that won't work on Android due to being split into multiple outputs.

What test is currently failing due to this? I can take a look and see what's going on.

[janvorli]

@lateralusX the problem is not due to this message, but every line of the exception message and stack trace having an extra newline. You can repro it using a simple test app that just throws an exception from couple of levels of function calls and doesn't catch it. Then redirect the stderr of the test into a file. You'll see double CRLF at each line of the exception stack trace and exception message.
This is what you get in the file with your change:

Unhandled exception. System.Reflection.TargetInvocationException: Exception has been thrown by the target of an invocation.

 ---> System.Exception: Exception of type 'System.Exception' was thrown.

   at SymbolTestDll.TestClass.Foo7() in D:\git\dotnet-diagnostictests\src\Debugger.Tests\Debuggees\SymbolTestApp\SymbolTestDll\TestClass.cs:line 28

   at SymbolTestDll.TestClass.Foo6(Int32 x) in D:\git\dotnet-diagnostictests\src\Debugger.Tests\Debuggees\SymbolTestApp\SymbolTestDll\TestClass.cs:line 22

   at SymbolTestDll.TestClass.Foo5(Int32 x) in D:\git\dotnet-diagnostictests\src\Debugger.Tests\Debuggees\SymbolTestApp\SymbolTestDll\TestClass.cs:line 17

   at SymbolTestDll.TestClass.ThrowException() in D:\git\dotnet-diagnostictests\src\Debugger.Tests\Debuggees\SymbolTestApp\SymbolTestDll\TestClass.cs:line 12

   at System.RuntimeMethodHandle.InvokeMethod(ObjectHandleOnStack target, Void** arguments, ObjectHandleOnStack sig, BOOL isConstructor, ObjectHandleOnStack result)

   at System.Reflection.MethodBaseInvoker.InterpretedInvoke_Method(Object obj, IntPtr* args)

   at System.Reflection.MethodBaseInvoker.InvokeWithNoArgs(Object obj, BindingFlags invokeAttr)

   --- End of inner exception stack trace ---

   at System.Reflection.MethodBaseInvoker.InvokeWithNoArgs(Object obj, BindingFlags invokeAttr)

   at System.Reflection.RuntimeMethodInfo.Invoke(Object obj, BindingFlags invokeAttr, Binder binder, Object[] parameters, CultureInfo culture)

   at System.Reflection.MethodBase.Invoke(Object obj, Object[] parameters)

   at SymbolTestApp.Program.Foo4(String dllPath) in D:\git\dotnet-diagnostictests\src\Debugger.Tests\Debuggees\SymbolTestApp\SymbolTestApp\SymbolTestApp.cs:line 54

   at SymbolTestApp.Program.Foo2(Int32 x, String dllPath) in D:\git\dotnet-diagnostictests\src\Debugger.Tests\Debuggees\SymbolTestApp\SymbolTestApp\SymbolTestApp.cs:line 29

   at SymbolTestApp.Program.Foo1(Int32 x, String dllPath) in D:\git\dotnet-diagnostictests\src\Debugger.Tests\Debuggees\SymbolTestApp\SymbolTestApp\SymbolTestApp.cs:line 24

   at SymbolTestApp.Program.Main(String[] args) in D:\git\dotnet-diagnostictests\src\Debugger.Tests\Debuggees\SymbolTestApp\SymbolTestApp\SymbolTestApp.cs:line 19

and this is before your change:

Unhandled exception. System.Reflection.TargetInvocationException: Exception has been thrown by the target of an invocation.
 ---> System.Exception: Exception of type 'System.Exception' was thrown.
   at SymbolTestDll.TestClass.Foo7() in D:\git\dotnet-diagnostictests\src\Debugger.Tests\Debuggees\SymbolTestApp\SymbolTestDll\TestClass.cs:line 28
   at SymbolTestDll.TestClass.Foo6(Int32 x) in D:\git\dotnet-diagnostictests\src\Debugger.Tests\Debuggees\SymbolTestApp\SymbolTestDll\TestClass.cs:line 22
   at SymbolTestDll.TestClass.Foo5(Int32 x) in D:\git\dotnet-diagnostictests\src\Debugger.Tests\Debuggees\SymbolTestApp\SymbolTestDll\TestClass.cs:line 17
   at SymbolTestDll.TestClass.ThrowException() in D:\git\dotnet-diagnostictests\src\Debugger.Tests\Debuggees\SymbolTestApp\SymbolTestDll\TestClass.cs:line 12
   at System.Reflection.MethodBaseInvoker.InterpretedInvoke_Method(Object obj, IntPtr* args)
   at System.Reflection.MethodBaseInvoker.InvokeWithNoArgs(Object obj, BindingFlags invokeAttr)
   --- End of inner exception stack trace ---
   at System.Reflection.MethodBaseInvoker.InvokeWithNoArgs(Object obj, BindingFlags invokeAttr)
   at System.Reflection.RuntimeMethodInfo.Invoke(Object obj, BindingFlags invokeAttr, Binder binder, Object[] parameters, CultureInfo culture)
   at System.Reflection.MethodBase.Invoke(Object obj, Object[] parameters)
   at SymbolTestApp.Program.Foo4(String dllPath) in D:\git\dotnet-diagnostictests\src\Debugger.Tests\Debuggees\SymbolTestApp\SymbolTestApp\SymbolTestApp.cs:line 54
   at SymbolTestApp.Program.Foo2(Int32 x, String dllPath) in D:\git\dotnet-diagnostictests\src\Debugger.Tests\Debuggees\SymbolTestApp\SymbolTestApp\SymbolTestApp.cs:line 29
   at SymbolTestApp.Program.Foo1(Int32 x, String dllPath) in D:\git\dotnet-diagnostictests\src\Debugger.Tests\Debuggees\SymbolTestApp\SymbolTestApp\SymbolTestApp.cs:line 24
   at SymbolTestApp.Program.Main(String[] args) in D:\git\dotnet-diagnostictests\src\Debugger.Tests\Debuggees\SymbolTestApp\SymbolTestApp\SymbolTestApp.cs:line 19

[lateralusX]

Thanks, sounds like we get hit by some internal implementation details between _write and WriteFile when it comes to redirecting stdout/stderr. I take a look.

[lateralusX]

stdout/stderr defaults to text mode, while STD_OUTPUT_HANDLE/STD_ERR_HANDLE defaults to binary, so using _write on stdout/stderrs fds will run in text mode, converting \n to \r\n on Windows. Problem is that above callstack gets formatted by managed code that adds \r\n as newline + combined with text from native code that uses \n, so when this is then written to an fd in text mode it will conver \n to \r\n again, so new lines generated in managed code end up as \r\r\n. This didn't full work as expected in the past either since we would end up with output that would use mixed line endings at least when running through cmd, where \n from native code would just end up as \n and not \r\n, it seems like Powershell behaves differently, formatting single \n into \r\n giving the whole output a consistent newline output.

[lateralusX]

I don't believe we can change stdout/stderr to be binary since that will affect every usage, we could get hold of the fd for STD_OUTPUT_HANDLE/STD_ERR_HANDLE, but then we would need to use _open_osfhandle and then _close on the returned handle, that would add overhead on every logging. The better option is probably to move back to FileWrite using STD_OUTPUT_HANDLE/STD_ERR_HANDLE but I don't like that different logging will end up in different modes. To keep things consistent, we should probably fix this special case at call site on Windows, replace \r\n with \n before written through existing implementation of minipal_log_write.