Initial CoreClr Android logcat log integration. (#113416)

Initial CoreClr Android logcat integration was removed from cf2aae6. This PR adds a unified approach re-routing runtime console logging though a central log API defined in native/minipal/log.h potential shared between components as well as runtimes.

This initial PR starts out defining a new header under native/minipal/log.h that includes a straightforward API to log formatted and raw output using different priority. It includes regular printf/vprintf style functions as well as low level none crt direct write capabilities, usable in high speed or async safe logging.

API closely mimics Mono's logging API defined in glib.h and the idea is to potentially rewire Mono's logging to use this new API going forward potentially adding more capabilities into native/minipal/log.h

Ability to log different log message using different priority is inherited from Mono and maps close to logcat priority levels, where different priorities can be filtered directly in logcat, creating virtual log streams. API includes a way to log directly to virtual standard error/output streams in case no specific need for fine grained priority-based logging exists. On platforms supporting stderr/stdout this will be a 1:1 mapping, but on platforms like logcat, stderr/stdout will be mapped to similar priority levels (error, info).

There is no buffering when calling logcat log functions, each log call will end up as a new log entry. Code that relies on ability to do multiple logging calls and expect to get a new line only when writing \n into the log buffer, won't behave as expected when using logcat. This PR adjust a couple of places where such assumptions are made, appending logging into a string buffer before passed to minipal_log_write API's. Logcat has an internal buffer limitation of 4068 bytes, buffers larger than that will be truncated. To mitigate this logging targeting Android includes a mechanism splitting up the bigger buffer into smaller chunks based on \n in log message, if there is no \n in bigger log message, message will still be logged in chunks, but each chunk ending up as a separate logcat message. Internal chunk size has been defined to 4000 bytes, making room for future internal logcat buffer reduction. Regular console logging enforces a buffer size limit as well on low level write calls, this limitation was directly inherited from previous implementation in src/coreclr/vm/util.cpp into native/minipal/log.c, if buffer exceeds chunk size, it will be split into multiple chunks where each chunk is written "as is" to underlying write function.

On Mono, formatted print style logcat implementation uses dynamic memory allocation + vsnprintf and low level __android_log_write. Current implementation in native/minipal/log.h adapt a similar schema but tries to first use a smaller stack buffer, inline with Androids internal implementation of __android_log_vprint use of 1024 bytes buffer. If log message is below 1024, implementation will match __android_log_vprint and use stack memory, but if exceeding 1024, implementation fallbacks to dynamic memory allocation, format message into dynamic memory buffer and then pass it through minipal_log_write to correctly handle max payload limitations as described above.

This initial PR adapts a smaller set of source files under src/coreclr to use the new logging API as a first step adaption. It makes sure the LOG macro as well as exception handling gets emitted through the new log API ending up in logcat. PR also adapts jit logging as well as diagnostic servers pause message, currently written directly to console.

This PR will be followed by an additional PR adapting more sources under src/coreclr/vm to use the new logging API enabling more log messages to end up in logcat on Android. Once the initial pass is done, adaption to new logging API will probably happen on a case-by-case basis.

Author: lateralusX

src/coreclr/inc/utilcode.h

@@ -37,6 +37,7 @@ using std::nothrow;
 
 #include <stddef.h>
 #include <minipal/guid.h>
+#include <minipal/log.h>
 #include <dn-u16.h>
 
 #include "clrnt.h"

src/coreclr/jit/ee_il_dll.cpp

@@ -29,9 +29,7 @@ XXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXX
 #define DLLEXPORT
 #endif // !DLLEXPORT
 
-#if defined(HOST_ANDROID)
-#include <android/log.h>
-#endif
+#include "minipal/log.h"
 
 /*****************************************************************************/
 
@@ -150,16 +148,19 @@ FILE* jitstdout()
 // Like printf/logf, but only outputs to jitstdout -- skips call back into EE.
 int jitprintf(const char* fmt, ...)
 {
+    int     status;
     va_list vl;
     va_start(vl, fmt);
-#if defined(HOST_ANDROID)
-    int status = jitstdout() == procstdout()
-                     ? __android_log_vprint(ANDROID_LOG_VERBOSE, MAIN_CLR_MODULE_NAME_A, fmt, vl)
-                     : vfprintf(jitstdout(), fmt, vl);
-#else
-    int status = vfprintf(jitstdout(), fmt, vl);
-#endif
+    if (jitstdout() == procstdout())
+    {
+        status = minipal_log_vprint_verbose(fmt, vl);
+    }
+    else
+    {
+        status = vfprintf(jitstdout(), fmt, vl);
+    }
     va_end(vl);
+
     return status;
 }
 

src/coreclr/jit/error.cpp

@@ -15,6 +15,7 @@ XXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXX
 #pragma hdrstop
 #endif
 #include "compiler.h"
+#include "minipal/log.h"
 
 #if MEASURE_FATAL
 unsigned fatal_badCode;
@@ -318,7 +319,14 @@ int vflogf(FILE* file, const char* fmt, va_list args)
     // 0-length string means flush
     if (fmt[0] == '\0')
     {
-        fflush(file);
+        if (file == procstdout())
+        {
+            minipal_log_flush_verbose();
+        }
+        else
+        {
+            fflush(file);
+        }
         return 0;
     }
 
@@ -331,8 +339,15 @@ int vflogf(FILE* file, const char* fmt, va_list args)
         OutputDebugStringA(buffer);
     }
 
-    // We use fputs here so that this executes as fast a possible
-    fputs(&buffer[0], file);
+    if (file == procstdout())
+    {
+        minipal_log_write_verbose(buffer);
+    }
+    else
+    {
+        fputs(&buffer[0], file);
+    }
+
     return written;
 }
 

src/coreclr/pal/src/thread/process.cpp

@@ -2452,6 +2452,16 @@ PAL_GenerateCoreDump(
 
 (no return value)
 --*/
+#ifdef HOST_ANDROID
+#include <minipal/log.h>
+VOID
+PROCCreateCrashDumpIfEnabled(int signal, siginfo_t* siginfo, bool serialize)
+{
+    // TODO: Dump all managed threads callstacks into logcat and/or file?
+    // TODO: Dump stress log into logcat and/or file when enabled?
+    minipal_log_write_fatal("Aborting process.\n");
+}
+#else
 VOID
 PROCCreateCrashDumpIfEnabled(int signal, siginfo_t* siginfo, bool serialize)
 {
@@ -2520,6 +2530,7 @@ PROCCreateCrashDumpIfEnabled(int signal, siginfo_t* siginfo, bool serialize)
         free(signalAddressArg);
     }
 }
+#endif
 
 /*++
 Function:

src/coreclr/utilcode/log.cpp

@@ -372,10 +372,9 @@ VOID LogSpewAlwaysValist(const char *fmt, va_list args)
 
     if (LogFlags & LOG_ENABLE_CONSOLE_LOGGING)
     {
-        WriteFile(GetStdHandle(STD_OUTPUT_HANDLE), pBuffer, buflen, &written, 0);
-        //<TODO>@TODO ...Unnecessary to flush console?</TODO>
+        minipal_log_write_info(pBuffer);
         if (LogFlags & LOG_ENABLE_FLUSH_FILE)
-            FlushFileBuffers( GetStdHandle(STD_OUTPUT_HANDLE) );
+            minipal_log_sync_info();
     }
 
     if (LogFlags & LOG_ENABLE_DEBUGGER_LOGGING)
@@ -415,6 +414,5 @@ VOID LogSpewAlways (const char *fmt, ... )
     LogSpewValist (LF_ALWAYS, LL_ALWAYS, fmt, args);
     va_end(args);
 }
-
 #endif // LOGGING
 

src/coreclr/vm/eepolicy.cpp

@@ -48,7 +48,7 @@ void SafeExitProcess(UINT exitCode, ShutdownCompleteAction sca = SCA_ExitProcess
             {
                 _ASSERTE(!"Bad Exit value");
                 FAULT_NOT_FATAL();      // if we OOM we can simply give up
-                fprintf(stderr, "Error 0x%08x.\n\nBreakOnBadExit: returning bad exit code.", exitCode);
+                minipal_log_print_error("Error 0x%08x.\n\nBreakOnBadExit: returning bad exit code.", exitCode);
                 DebugBreak();
             }
         }
@@ -233,8 +233,9 @@ class CallStackLogger
 
         MethodDesc* pMD = m_frames[index];
         TypeString::AppendMethodInternal(str, pMD, TypeString::FormatNamespace|TypeString::FormatFullInst|TypeString::FormatSignature);
+        str.Append(W("\n"));
+
         PrintToStdErrW(str.GetUnicode());
-        PrintToStdErrA("\n");
     }
 
 public:
@@ -265,6 +266,7 @@ class CallStackLogger
             repeatStr.AppendPrintf("Repeated %d times:\n", m_largestCommonStartRepeat);
 
             PrintToStdErrW(repeatStr.GetUnicode());
+
             PrintToStdErrA("--------------------------------\n");
             for (int i = 0; i < m_largestCommonStartLength; i++)
             {
@@ -373,11 +375,11 @@ void LogInfoForFatalError(UINT exitCode, LPCWSTR pszMessage, PEXCEPTION_POINTERS
     {
         if (exitCode == (UINT)COR_E_FAILFAST)
         {
-            PrintToStdErrA("Process terminated. ");
+            PrintToStdErrA("Process terminated.\n");
         }
         else
         {
-            PrintToStdErrA("Fatal error. ");
+            PrintToStdErrA("Fatal error.\n");
         }
 
         if (errorSource != NULL)
@@ -393,9 +395,9 @@ void LogInfoForFatalError(UINT exitCode, LPCWSTR pszMessage, PEXCEPTION_POINTERS
         else
         {
             // If no message was passed in, generate it from the exitCode
-            SString exitCodeMessage;
+            InlineSString<256> exitCodeMessage;
             GetHRMsg(exitCode, exitCodeMessage);
-            PrintToStdErrW((LPCWSTR)exitCodeMessage);
+            PrintToStdErrW(exitCodeMessage.GetUnicode());
         }
 
         PrintToStdErrA("\n");

src/coreclr/vm/eventing/eventpipe/ds-rt-coreclr.h

@@ -11,6 +11,7 @@
 #include "ep-rt-coreclr.h"
 #include <clrconfignocache.h>
 #include <generatedumpflags.h>
+#include <minipal/log.h>
 #include <eventpipe/ds-process-protocol.h>
 #include <eventpipe/ds-profiler-protocol.h>
 #include <eventpipe/ds-dump-protocol.h>
@@ -404,10 +405,10 @@ ds_rt_server_log_pause_message (void)
 
 	uint32_t port_suspended = ds_rt_config_value_get_default_port_suspend();
 
-	printf("The runtime has been configured to pause during startup and is awaiting a Diagnostics IPC ResumeStartup command from a Diagnostic Port.\n");
-	printf("DOTNET_%s=\"%s\"\n", diagPortsName, ports == nullptr ? "" : ports);
-	printf("DOTNET_DefaultDiagnosticPortSuspend=%u\n", port_suspended);
-	fflush(stdout);
+	minipal_log_print_info("The runtime has been configured to pause during startup and is awaiting a Diagnostics IPC ResumeStartup command from a Diagnostic Port.\n");
+	minipal_log_print_info("DOTNET_%s=\"%s\"\n", diagPortsName, ports == nullptr ? "" : ports);
+	minipal_log_print_info("DOTNET_DefaultDiagnosticPortSuspend=%u\n", port_suspended);
+	minipal_log_flush_info();
 }
 
 #endif /* ENABLE_PERFTRACING */

src/coreclr/vm/excep.cpp

@@ -4756,8 +4756,6 @@ LONG __stdcall COMUnhandledExceptionFilter(     // EXCEPTION_CONTINUE_SEARCH or
 #pragma code_seg(pop, uef)
 #endif // !TARGET_UNIX
 
-void PrintStackTraceToStdout();
-
 static SString GetExceptionMessageWrapper(Thread* pThread, OBJECTREF throwable)
 {
     STATIC_CONTRACT_THROWS;
@@ -4788,17 +4786,17 @@ DefaultCatchHandlerExceptionMessageWorker(Thread* pThread,
             wcsncpy_s(buf, buf_size, SZ_UNHANDLED_EXCEPTION, SZ_UNHANDLED_EXCEPTION_CHARLEN);
         }
 
-        PrintToStdErrW(buf);
-        PrintToStdErrA(" ");
-
-        SString message = GetExceptionMessageWrapper(pThread, throwable);
+        SString message(buf);
+        SString exceptionMessage = GetExceptionMessageWrapper(pThread, throwable);
 
-        if (!message.IsEmpty())
+        message.Append(W(" "));
+        if (!exceptionMessage.IsEmpty())
         {
-            PrintToStdErrW(message);
+            message.Append(exceptionMessage);
         }
+        message.Append(W("\n"));
 
-        PrintToStdErrA("\n");
+        PrintToStdErrW(message.GetUnicode());
 
 #if defined(FEATURE_EVENT_TRACE) && !defined(TARGET_UNIX)
         // Send the log to Windows Event Log
@@ -5005,10 +5003,13 @@ DefaultCatchHandler(PEXCEPTION_POINTERS pExceptionPointers,
             EX_CATCH
             {
                 LOG((LF_EH, LL_INFO10, "Exception occurred while processing uncaught exception\n"));
-                UtilLoadStringRC(IDS_EE_EXCEPTION_TOSTRING_FAILED, buf, buf_size);
-                PrintToStdErrA("\n   ");
+
+                _ASSERTE(buf_size > 6);
+                wcscpy_s(buf, buf_size, W("\n   "));
+                UtilLoadStringRC(IDS_EE_EXCEPTION_TOSTRING_FAILED, buf + 4, buf_size - 6);
+                wcscat_s(buf, buf_size, W("\n"));
+
                 PrintToStdErrW(buf);
-                PrintToStdErrA("\n");
             }
             EX_END_CATCH(SwallowAllExceptions);
         }

src/coreclr/vm/util.cpp

@@ -15,10 +15,6 @@
 
 #ifndef DACCESS_COMPILE
 
-#if defined(TARGET_ANDROID)
-#include <android/log.h>
-#endif // defined(TARGET_ANDROID)
-
 thread_local size_t t_ThreadType;
 
 void ClrFlsSetThreadType(TlsThreadTypeFlag flag)
@@ -124,8 +120,7 @@ LPVOID CQuickHeap::Alloc(UINT sz)
 // Output functions that avoid the crt's.
 //----------------------------------------------------------------------------
 
-static
-void NPrintToHandleA(HANDLE Handle, const char *pszString, size_t BytesToWrite)
+void PrintToStdErrA(const char *pszString)
 {
     CONTRACTL
     {
@@ -135,58 +130,7 @@ void NPrintToHandleA(HANDLE Handle, const char *pszString, size_t BytesToWrite)
     }
     CONTRACTL_END
 
-    if (Handle == INVALID_HANDLE_VALUE || Handle == NULL)
-        return;
-
-    BOOL success;
-    DWORD   dwBytesWritten;
-    const size_t maxWriteFileSize = 32767; // This is somewhat arbitrary limit, but 2**16-1 doesn't work
-
-    while (BytesToWrite > 0) {
-        DWORD dwChunkToWrite = (DWORD) min(BytesToWrite, maxWriteFileSize);
-
-        // Try to write to handle.  If this is not a CUI app, then this is probably
-        // not going to work unless the dev took special pains to set their own console
-        // handle during CreateProcess.  So try it, but don't yell if it doesn't work in
-        // that case.  Also, if we redirect stdout to a pipe then the pipe breaks (ie, we
-        // write to something like the UNIX head command), don't complain.
-        success = WriteFile(Handle, pszString, dwChunkToWrite, &dwBytesWritten, NULL);
-        if (!success)
-        {
-#if defined(_DEBUG)
-            // This can happen if stdout is a closed pipe.  This might not help
-            // much, but we'll have half a chance of seeing this.
-            OutputDebugStringA("CLR: Writing out an unhandled exception to stdout failed!\n");
-            OutputDebugStringA(pszString);
-#endif //_DEBUG
-
-            break;
-        }
-        else {
-            _ASSERTE(dwBytesWritten == dwChunkToWrite);
-        }
-        pszString = pszString + dwChunkToWrite;
-        BytesToWrite -= dwChunkToWrite;
-    }
-
-}
-
-void PrintToStdErrA(const char *pszString) {
-    CONTRACTL
-    {
-        NOTHROW;
-        GC_NOTRIGGER;
-        FORBID_FAULT;
-    }
-    CONTRACTL_END
-
-#if defined(TARGET_ANDROID)
-    __android_log_write(ANDROID_LOG_FATAL, MAIN_CLR_MODULE_NAME_A, pszString);
-#else
-    HANDLE Handle = GetStdHandle(STD_ERROR_HANDLE);
-    size_t len = strlen(pszString);
-    NPrintToHandleA(Handle, pszString, len);
-#endif // defined(TARGET_ANDROID)
+    minipal_log_write_error(pszString);
 }
 
 void PrintToStdErrW(const WCHAR *pwzString)

src/mono/CMakeLists.txt

@@ -882,7 +882,6 @@ endif()
 ### End of OS specific checks
 
 include_directories("${CLR_SRC_NATIVE_DIR}")
-add_subdirectory(${CLR_SRC_NATIVE_DIR}/minipal minipal)
 
 if(NOT DISABLE_LIBS)
   set(INSTALL_MONO_API 1)

src/mono/mono/CMakeLists.txt

@@ -1,6 +1,7 @@
 project(mono)
 
 set(subdirs
+  minipal
   eglib
   utils
   sgen

src/mono/mono/minipal/CMakeLists.txt

@@ -0,0 +1,10 @@
+
+if (HOST_WIN32)
+    add_definitions(-DHOST_WINDOWS)
+endif (HOST_WIN32)
+
+if (HOST_DARWIN OR HOST_ANDROID OR HOST_LINUX OR HOST_FREEBSD OR HOST_SOLARIS OR HOST_HAIKU OR HOST_BROWSER)
+    add_definitions(-DHOST_UNIX)
+endif (HOST_DARWIN OR HOST_ANDROID OR HOST_LINUX OR HOST_FREEBSD OR HOST_SOLARIS OR HOST_HAIKU OR HOST_BROWSER)
+
+add_subdirectory(${CLR_SRC_NATIVE_DIR}/minipal minipal)

src/native/minipal/CMakeLists.txt

@@ -10,6 +10,7 @@ set(SOURCES
     unicodedata.c
     utf8.c
     xoshiro128pp.c
+    log.c
 )
 
 # Provide an object library for scenarios where we ship static libraries
@@ -36,6 +37,10 @@ endif()
 add_library(minipal STATIC)
 target_link_libraries(minipal PRIVATE minipal_objects)
 
+if(CLR_CMAKE_HOST_ANDROID)
+  target_link_libraries(minipal PRIVATE log)
+endif(CLR_CMAKE_HOST_ANDROID)
+
 add_library(minipal_sanitizer_support OBJECT
     sansupport.c)
 # Exclude this target from the default build as we may not have sanitzer headers available