Android + Console.WriteLine + format strings = possible unexpected extra newlines

[jonpryor]

Description

Context: dotnet/android#6119
Context: dotnet/android#6119 (comment)

.NET for Android "forwards" Console.WriteLine() invocations to adb logcat. This is good and proper.

However, messages are written to adb logcat via __android_log_print, and the __android_log* family of functions emits a newline after every invocation.

An odd "hiccup" is that if you use Console.WriteLine() with format strings to write a string which exceeds 11 characters (?!) in length, the value is written to adb logcat across two or more lines:

using System;
using Android.App;

namespace android_hw
{
    [Activity(Label = "@string/app_name", MainLauncher = true)]
    public class MainActivity : Activity
    {
        protected override void OnCreate(Android.OS.Bundle savedInstanceState)
        {
            base.OnCreate(savedInstanceState);
            SetContentView(Resource.Layout.activity_main);

            Console.WriteLine ("{0}", new string ('x', 12));
        }
    }
}

…build & run…

% adb logcat > log.txt &
% ~/android-toolchain/dotnet/dotnet build /t:Install,StartAndroidActivity

…and adb logcat contains:

08-12 13:44:14.019 21107 21107 I DOTNET  : xxxxxxxxxxx
08-12 13:44:14.019 21107 21107 I DOTNET  : x

…which is, you know, weird.

There also doesn't appear to be any rhyme or reason for where the line wrap occurs, e.g. dotnet/android#6119 (comment)

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

results in:

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

Why does this matter?

Sometimes you write tooling which reads adb logcat to see if a message was printed. It is extremely handy if what you get is what you expect, and nobody expects "randomly inserted" newlines.

For example, xamarin-android unit tests.

For comparison, "traditional"/"legacy" Xamarin.Android only splits on \n boundaries before sending to __android_log_print(), so no "unexpected" newlines are present in adb logcat with legacy Xamarin.Android.

Conjecture:

What might be happening is StreamWriter.WriteSpan():

runtime/src/libraries/System.Private.CoreLib/src/System/IO/StreamWriter.cs

Lines 449 to 466 in dbb2b53

	while (count > 0)
	{
	if (dstPos == charBuffer.Length)
	{
	Flush(false, false);
	dstPos = 0;
	}
	int n = Math.Min(charBuffer.Length - dstPos, count);
	int bytesToCopy = n * sizeof(char);
	Buffer.MemoryCopy(srcPtr, dstPtr + dstPos, bytesToCopy, bytesToCopy);
	_charPos += n;
	dstPos += n;
	srcPtr += n;
	count -= n;
	}

StreamWriter.Flush(bool, bool) calls LogcatStream.Write(ReadOnlySpan<byte>):

runtime/src/libraries/System.Console/src/System/ConsolePal.Android.cs

Line 16 in dbb2b53

public override unsafe void Write(ReadOnlySpan<byte> buffer)

Interop.Logcat.AndroidLogPrint(), meanwhile, is __android_log_print():

runtime/src/libraries/Common/src/Interop/Android/Interop.Logcat.cs

Line 15 in dbb2b53

__android_log_print(level, tag, "%s", message, IntPtr.Zero);

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 elsewhere.

Configuration

• Which version of .NET is the code running on? dotnet/installer@db9e71c7 6.0.100-rc.1.21408
• What OS and version, and what distro if applicable? Android 11 on a Pixel 5, plus various other Android targets
• What is the architecture (x64, x86, ARM, ARM64)? arm64, x86_64 (via emulator)
• Do you know whether it is specific to that configuration? It doesn't appear to be specific to Android version or hardware. It instead appears to be specific to the Android-related .NET PAL & related code.

Regression?

This is not a .NET regression, but it is a "regression" or "semantic change" from legacy Xamarin.Android.

[dotnet-issue-labeler]

I couldn't figure out the best area label to add to this issue. If you have write-permissions please help me learn by adding exactly one area label.

[steveisok]

/cc @MaximLipnin

I'm marking the milestone as 7, but will consider fixing as we have something similar almost in place for iOS.