[sdks] Use runtime logging features to intercept Console.{Out,Error} and runtime logs for instrumentation (mono#6083)

* [sdks] Fix Android pick of mono runtime

* [android] Have Console.{Out,Error} go through the runtime log mechanism to ease their interception

* [sdks] Intercept runtime logs instead of Console to send back for instrumentation

* [sdks] Intercept Android test runner logging

Author: luhenry

mcs/class/corlib/System.IO/LogcatTextWriter.cs

@@ -3,6 +3,7 @@
 using System;
 using System.IO;
 using System.Text;
+using System.Runtime.CompilerServices;
 using System.Runtime.InteropServices;
 
 namespace System.IO {
@@ -12,13 +13,14 @@ class LogcatTextWriter : TextWriter {
 		const string LibLog = "/system/lib/liblog.so";
 		const string LibLog64 = "/system/lib64/liblog.so";
 
+		readonly byte[] appname;
+
 		TextWriter stdout;
-		readonly string appname;
 		StringBuilder line = new StringBuilder ();
 
 		public LogcatTextWriter (string appname, TextWriter stdout)
 		{
-			this.appname = appname;
+			this.appname = Encoding.UTF8.GetBytes (appname);
 			this.stdout = stdout;
 		}
 
@@ -46,34 +48,22 @@ public override void WriteLine ()
 			var o = line.ToString ();
 			line.Clear ();
 
-			Log (LogLevel.Info, appname, o);
+			unsafe {
+				fixed (byte *b_appname = appname)
+				fixed (byte *b_message = Encoding.UTF8.GetBytes(o)) {
+					Log (b_appname, 1 << 5 /* G_LOG_LEVEL_MESSAGE */, b_message);
+				}
+			}
 			stdout.WriteLine (o);
 		}
 
-		enum LogLevel {
-			Unknown,
-			Default,
-			Verbose,
-			Debug,
-			Info,
-			Warn,
-			Error,
-			Fatal,
-			Silent
-		}
-
 		public static bool IsRunningOnAndroid ()
 		{
 			return File.Exists (LibLog) || File.Exists (LibLog64);
 		}
 
-		[DllImport ("liblog")]
-		static extern void __android_log_print (LogLevel level, string appname, string format, string args, IntPtr zero);
-
-		static void Log (LogLevel level, string appname, string log)
-		{
-			__android_log_print (level, appname, "%s", log, IntPtr.Zero);
-		}
+		[MethodImpl(MethodImplOptions.InternalCall)]
+		static unsafe extern void Log (byte *appname, int level, byte *message);
 	}
 }
 

mono/metadata/icall-def.h

@@ -346,6 +346,9 @@ ICALL(INOW_3, "RemoveWatch", ves_icall_System_IO_InotifyWatcher_RemoveWatch)
 ICALL_TYPE(KQUEM, "System.IO.KqueueMonitor", KQUEM_1)
 ICALL(KQUEM_1, "kevent_notimeout", ves_icall_System_IO_KqueueMonitor_kevent_notimeout)
 
+ICALL_TYPE(LOGCATEXTWRITER, "System.IO.LogcatTextWriter", LOGCATEXTWRITER_1)
+HANDLES(ICALL(LOGCATEXTWRITER_1, "Log", ves_icall_System_IO_LogcatTextWriter_Log))
+
 ICALL_TYPE(MMAPIMPL, "System.IO.MemoryMappedFiles.MemoryMapImpl", MMAPIMPL_1)
 ICALL(MMAPIMPL_1, "CloseMapping", mono_mmap_close)
 ICALL(MMAPIMPL_2, "ConfigureHandleInheritability", mono_mmap_configure_inheritability)

mono/metadata/icall.c

@@ -7898,6 +7898,11 @@ ves_icall_System_Runtime_InteropServices_WindowsRuntime_UnsafeNativeMethods_Wind
 
 #endif
 
+ICALL_EXPORT void
+ves_icall_System_IO_LogcatTextWriter_Log (const char *appname, gint32 level, const char *message)
+{
+	g_log (appname, (GLogLevelFlags)level, message);
+}
 
 #ifndef DISABLE_ICALL_TABLES
 

mono/utils/mono-logger-internals.h

@@ -12,34 +12,24 @@
 G_BEGIN_DECLS
 
 typedef enum {
-	MONO_TRACE_ASSEMBLY		= (1<<0),
-	MONO_TRACE_TYPE			= (1<<1),
-	MONO_TRACE_DLLIMPORT		= (1<<2),
-	MONO_TRACE_GC			= (1<<3),
-        MONO_TRACE_CONFIG		= (1<<4),
-	MONO_TRACE_AOT			= (1<<5),
-	MONO_TRACE_SECURITY		= (1<<6),
-	MONO_TRACE_THREADPOOL		= (1<<7),
-	MONO_TRACE_IO_THREADPOOL	= (1<<8),
-	MONO_TRACE_IO_LAYER		= (1<<9),
-	MONO_TRACE_W32HANDLE	= (1<<10),
-	MONO_TRACE_ALL			= MONO_TRACE_ASSEMBLY |
-					  MONO_TRACE_TYPE |
-					  MONO_TRACE_DLLIMPORT |
-					  MONO_TRACE_GC |
-					  MONO_TRACE_CONFIG |
-					  MONO_TRACE_AOT |
-					  MONO_TRACE_SECURITY |
-					  MONO_TRACE_THREADPOOL |
-					  MONO_TRACE_IO_THREADPOOL |
-					  MONO_TRACE_IO_LAYER |
-					  MONO_TRACE_W32HANDLE
+	MONO_TRACE_ASSEMBLY      =  (gint32)(1 << 0),
+	MONO_TRACE_TYPE          =  (gint32)(1 << 1),
+	MONO_TRACE_DLLIMPORT     =  (gint32)(1 << 2),
+	MONO_TRACE_GC            =  (gint32)(1 << 3),
+	MONO_TRACE_CONFIG        =  (gint32)(1 << 4),
+	MONO_TRACE_AOT           =  (gint32)(1 << 5),
+	MONO_TRACE_SECURITY      =  (gint32)(1 << 6),
+	MONO_TRACE_THREADPOOL    =  (gint32)(1 << 7),
+	MONO_TRACE_IO_THREADPOOL =  (gint32)(1 << 8),
+	MONO_TRACE_IO_LAYER      =  (gint32)(1 << 9),
+	MONO_TRACE_W32HANDLE     =  (gint32)(1 << 10),
+	MONO_TRACE_ALL           = ~(gint32)(0)
 } MonoTraceMask;
 
 MONO_API extern GLogLevelFlags mono_internal_current_level;
 MONO_API extern MonoTraceMask mono_internal_current_mask;
 
-void 
+MONO_API void
 mono_trace_init (void);
 
 void 
@@ -163,7 +153,7 @@ typedef void (*MonoLoggerOpen) (const char *, void *);
 typedef void (*MonoLoggerWrite) (const char *, GLogLevelFlags, mono_bool, const char *);
 typedef void (*MonoLoggerClose) (void);
 
-typedef struct _MonoLogCallParm_ {
+typedef struct {
 	MonoLoggerOpen 	opener;		/* Routine to open logging */
 	MonoLoggerWrite	writer;		/* Routine to write log data */
 	MonoLoggerClose closer; 	/* Routine to close logging */

sdks/android/jni/runtime-bootstrap.c

@@ -62,6 +62,9 @@ typedef struct MonoImage_ MonoImage;
 typedef struct MonoObject_ MonoObject;
 typedef struct MonoThread_ MonoThread;
 
+/* Imported from `mono-logger.h` */
+typedef void (*MonoLogCallback) (const char *log_domain, const char *log_level, const char *message, int32_t fatal, void *user_data);
+
 /*
  * The "err" variable contents must be allocated using g_malloc or g_strdup
  */
@@ -93,6 +96,8 @@ typedef void (*mono_domain_set_config_fn) (MonoDomain *, const char *, const cha
 typedef int (*mono_runtime_set_main_args_fn) (int argc, char* argv[]);
 typedef MonoMethod* (*mono_class_get_methods_fn) (MonoClass* klass, void **iter);
 typedef const char* (*mono_method_get_name_fn) (MonoMethod *method);
+typedef void (*mono_trace_init_fn) (void);
+typedef void (*mono_trace_set_log_handler_fn) (MonoLogCallback callback, void *user_data);
 
 static JavaVM *jvm;
 
@@ -119,6 +124,8 @@ static mono_domain_set_config_fn mono_domain_set_config;
 static mono_runtime_set_main_args_fn mono_runtime_set_main_args;
 static mono_class_get_methods_fn mono_class_get_methods;
 static mono_method_get_name_fn mono_method_get_name;
+static mono_trace_init_fn mono_trace_init;
+static mono_trace_set_log_handler_fn mono_trace_set_log_handler;
 
 static MonoAssembly *main_assembly;
 static void *runtime_bootstrap_dso;
@@ -131,13 +138,82 @@ static void* my_dlopen (const char *name, int flags, char **err, void *user_data
 
 
 //stuff
+
+static void
+_runtime_log (const char *log_domain, const char *log_level, const char *message, int32_t fatal, void *user_data)
+{
+	static jclass AndroidRunner_klass = NULL;
+	static jmethodID AndroidRunner_WriteLineToInstrumentation_method = NULL;
+	JNIEnv *env;
+	jstring j_message;
+
+	if (jvm == NULL)
+		__android_log_assert ("", "mono-sdks", "%s: jvm is NULL", __func__);
+
+	(*jvm)->GetEnv (jvm, (void**)&env, JNI_VERSION_1_6);
+
+	if (AndroidRunner_klass == NULL || AndroidRunner_WriteLineToInstrumentation_method == NULL) {
+		AndroidRunner_klass = (*env)->FindClass (env, "org/mono/android/AndroidRunner");
+		AndroidRunner_WriteLineToInstrumentation_method = (*env)->GetStaticMethodID (env, AndroidRunner_klass, "WriteLineToInstrumentation", "(Ljava/lang/String;)V");
+	}
+
+	j_message = (*env)->NewStringUTF(env, message);
+
+	(*env)->CallStaticVoidMethod (env, AndroidRunner_klass, AndroidRunner_WriteLineToInstrumentation_method, j_message);
+
+	(*env)->DeleteLocalRef (env, j_message);
+
+	/* Still print it on the logcat */
+
+	android_LogPriority android_log_level;
+	switch (*log_level) {
+	case 'e': /* error */
+		android_log_level = ANDROID_LOG_FATAL;
+		break;
+	case 'c': /* critical */
+		android_log_level = ANDROID_LOG_ERROR;
+		break;
+	case 'w': /* warning */
+		android_log_level = ANDROID_LOG_WARN;
+		break;
+	case 'm': /* message */
+		android_log_level = ANDROID_LOG_INFO;
+		break;
+	case 'i': /* info */
+		android_log_level = ANDROID_LOG_DEBUG;
+		break;
+	case 'd': /* debug */
+		android_log_level = ANDROID_LOG_VERBOSE;
+		break;
+	default:
+		android_log_level = ANDROID_LOG_UNKNOWN;
+		break;
+	}
+
+	__android_log_write (android_log_level, log_domain, message);
+	if (android_log_level == ANDROID_LOG_FATAL)
+		abort ();
+}
+
 static void
 _log (const char *format, ...)
 {
 	va_list args;
+	char *buf;
+	int nbuf;
+
+	errno = 0;
+
 	va_start (args, format);
-	__android_log_vprint (ANDROID_LOG_INFO, "MONO", format, args);
+	nbuf = vasprintf (&buf, format, args);
 	va_end (args);
+
+	if (buf == NULL || nbuf == -1)
+		__android_log_assert ("", "mono-sdks", "%s: vasprintf failed, error: \"%s\" (%d), nbuf = %d, buf = \"%s\"", __func__, strerror(errno), errno, nbuf, buf ? buf : "(null)");
+
+	_runtime_log ("mono-sdks", "debug", buf, 0, NULL);
+
+	free (buf);
 }
 
 static void
@@ -243,10 +319,10 @@ Java_org_mono_android_AndroidRunner_runTests (JNIEnv* env, jobject thiz, jstring
 	strncpy_str (env, data_dir, j_data_dir, sizeof(data_dir));
 	strncpy_str (env, assemblies_dir, j_assembly_dir, sizeof(assemblies_dir));
 
-	_log ("-- file dir %s\n", file_dir);
-	_log ("-- cache dir %s\n", cache_dir);
-	_log ("-- data dir %s\n", data_dir);
-	_log ("-- assembly dir %s\n", assemblies_dir);
+	_log ("-- file dir %s", file_dir);
+	_log ("-- cache dir %s", cache_dir);
+	_log ("-- data dir %s", data_dir);
+	_log ("-- assembly dir %s", assemblies_dir);
 	prctl (PR_SET_DUMPABLE, 1);
 
 	snprintf (buff, sizeof(buff), "%s/libmonosgen-2.0.so", data_dir);
@@ -279,6 +355,8 @@ Java_org_mono_android_AndroidRunner_runTests (JNIEnv* env, jobject thiz, jstring
 	mono_runtime_set_main_args = dlsym (libmono, "mono_runtime_set_main_args");
 	mono_class_get_methods = dlsym (libmono, "mono_class_get_methods");
 	mono_method_get_name = dlsym (libmono, "mono_method_get_name");
+	mono_trace_init = dlsym (libmono, "mono_trace_init");
+	mono_trace_set_log_handler = dlsym (libmono, "mono_trace_set_log_handler");
 
 	//MUST HAVE envs
 	setenv ("TMPDIR", cache_dir, 1);
@@ -290,9 +368,13 @@ Java_org_mono_android_AndroidRunner_runTests (JNIEnv* env, jobject thiz, jstring
 	create_and_set (file_dir, "home/.config", "XDG_CONFIG_HOME");
 
 	//Debug flags
-	// setenv ("MONO_LOG_LEVEL", "debug", 1);
+	setenv ("MONO_LOG_LEVEL", "info", 1);
+	setenv ("MONO_LOG_MASK", "all", 1);
 	// setenv ("MONO_VERBOSE_METHOD", "GetCallingAssembly", 1);
 
+	mono_trace_init ();
+	mono_trace_set_log_handler (_runtime_log, NULL);
+
 	mono_set_assemblies_path (assemblies_dir);
 	mono_set_crash_chaining (1);
 	mono_set_signal_chaining (1);
@@ -558,24 +640,6 @@ _monodroid_get_dns_servers (void **dns_servers_array)
 	return count;
 }
 
-MONO_API void
-AndroidIntrumentationWriter_WriteLineToInstrumentation (char *chars)
-{
-	JNIEnv *env;
-	jclass AndroidRunner_klass;
-	jmethodID AndroidRunner_WriteLineToInstrumentation_method;
-	jstring j_chars;
-
-	(*jvm)->GetEnv (jvm, (void**)&env, JNI_VERSION_1_6);
-
-	AndroidRunner_klass = (*env)->FindClass (env, "org/mono/android/AndroidRunner");
-	AndroidRunner_WriteLineToInstrumentation_method = (*env)->GetStaticMethodID (env, AndroidRunner_klass, "WriteLineToInstrumentation", "(Ljava/lang/String;)V");
-
-	j_chars = (*env)->NewStringUTF(env, chars);
-
-	(*env)->CallStaticVoidMethod (env, AndroidRunner_klass, AndroidRunner_WriteLineToInstrumentation_method, j_chars);
-}
-
 JNIEXPORT jint JNICALL
 JNI_OnLoad (JavaVM *vm, void *reserved)
 {

sdks/android/managed/main.cs

@@ -14,9 +14,6 @@ public class Driver
 
 	public static void RunTests ()
 	{
-		Console.SetOut (TextWriter.Synchronized (new AndroidIntrumentationWriter (Console.Out)));
-		Console.SetError (TextWriter.Synchronized (new AndroidIntrumentationWriter (Console.Error)));
-
 		string assembly = File.ReadAllText ($"{AppDomain.CurrentDomain.BaseDirectory}/testassembly.txt");
 
 		Console.WriteLine ($"Testing assembly \"{assembly}\"");
@@ -40,45 +37,4 @@ public static void Main ()
 	{
 		Environment.Exit (1);
 	}
-
-	class AndroidIntrumentationWriter : TextWriter
-	{
-		readonly StringBuilder Line = new StringBuilder ();
-
-		readonly TextWriter Inner;
-
-		public override Encoding Encoding => Inner.Encoding;
-
-		public AndroidIntrumentationWriter (TextWriter inner)
-		{
-			Inner = inner;
-		}
-
-		public override void Write(char value)
-		{
-			if (value == '\n')
-				WriteLine ();
-			else
-				Line.Append (value);
-		}
-
-		public override void WriteLine ()
-		{
-			var l = Line.ToString ();
-			Line.Clear ();
-
-			unsafe
-			{
-				fixed (byte *chars = Encoding.UTF8.GetBytes (l + '\0'))
-				{
-					WriteLineToInstrumentation (chars);
-				}
-			}
-
-			Inner.WriteLine (l);
-		}
-
-		[DllImport ("__Internal", EntryPoint = "AndroidIntrumentationWriter_WriteLineToInstrumentation", CharSet = CharSet.Unicode)]
-		static unsafe extern void WriteLineToInstrumentation (byte *chars);
-	}
 }