Merge "Clean up log initialization" into main

9 files changed, 90 insertions, 31 deletions

diff --git a/core/java/com/android/internal/os/RuntimeInit.java b/core/java/com/android/internal/os/RuntimeInit.java
index cdac09796137..1709ca78af4b 100644
--- a/core/java/com/android/internal/os/RuntimeInit.java
+++ b/core/java/com/android/internal/os/RuntimeInit.java
@@ -404,6 +404,17 @@ public class RuntimeInit {
     }
 
     public static void redirectLogStreams$ravenwood() {
+        if (sOut$ravenwood != null && sErr$ravenwood != null) {
+            return; // Already initialized.
+        }
+
+        // Make sure the Log class is loaded and the JNI methods are hooked up,
+        // before redirecting System.out/err.
+        // Otherwise, because ClassLoadHook tries to write to System.out, this would cause
+        // a circular initialization problem and would cause a UnsatisfiedLinkError
+        // on the JNI methods.
+        Log.isLoggable("X", Log.VERBOSE);
+
         if (sOut$ravenwood == null) {
             sOut$ravenwood = System.out;
             System.setOut(new AndroidPrintStream(Log.INFO, "System.out"));
diff --git a/ravenwood/Android.bp b/ravenwood/Android.bp
index 9b0c8e554d64..333fe4c8147f 100644
--- a/ravenwood/Android.bp
+++ b/ravenwood/Android.bp
@@ -127,6 +127,7 @@ java_library {
     libs: [
         "framework-minus-apex.ravenwood",
         "ravenwood-junit",
+        "ravenwood-helper-libcore-runtime",
     ],
     visibility: ["//visibility:private"],
 }
diff --git a/ravenwood/junit-impl-src/android/platform/test/ravenwood/RavenwoodAwareTestRunnerHook.java b/ravenwood/junit-impl-src/android/platform/test/ravenwood/RavenwoodAwareTestRunnerHook.java
index f237ba908507..1d182da5e7fd 100644
--- a/ravenwood/junit-impl-src/android/platform/test/ravenwood/RavenwoodAwareTestRunnerHook.java
+++ b/ravenwood/junit-impl-src/android/platform/test/ravenwood/RavenwoodAwareTestRunnerHook.java
@@ -27,6 +27,9 @@ import android.util.Log;
 
 import androidx.test.platform.app.InstrumentationRegistry;
 
+import com.android.internal.os.RuntimeInit;
+import com.android.ravenwood.common.RavenwoodCommonUtils;
+
 import org.junit.runner.Description;
 import org.junit.runner.Runner;
 import org.junit.runners.model.TestClass;
@@ -35,7 +38,7 @@ import org.junit.runners.model.TestClass;
  * Provide hook points created by {@link RavenwoodAwareTestRunner}.
  */
 public class RavenwoodAwareTestRunnerHook {
-    private static final String TAG = "RavenwoodAwareTestRunnerHook";
+    private static final String TAG = RavenwoodAwareTestRunner.TAG;
 
     private RavenwoodAwareTestRunnerHook() {
     }
@@ -56,20 +59,36 @@ public class RavenwoodAwareTestRunnerHook {
      * Called when a runner starts, before the inner runner gets a chance to run.
      */
     public static void onRunnerInitializing(Runner runner, TestClass testClass) {
+        // TODO: Move the initialization code to a better place.
+
+        initOnce();
+
         // This log call also ensures the framework JNI is loaded.
         Log.i(TAG, "onRunnerInitializing: testClass=" + testClass.getJavaClass()
                 + " runner=" + runner);
 
-        // TODO: Move the initialization code to a better place.
+        // This is needed to make AndroidJUnit4ClassRunner happy.
+        InstrumentationRegistry.registerInstance(null, Bundle.EMPTY);
+    }
+
+    private static boolean sInitialized = false;
+
+    private static void initOnce() {
+        if (sInitialized) {
+            return;
+        }
+        sInitialized = true;
+
+        // We haven't initialized liblog yet, so directly write to System.out here.
+        RavenwoodCommonUtils.log(TAG, "initOnce()");
+
+        // Redirect stdout/stdin to liblog.
+        RuntimeInit.redirectLogStreams();
 
         // This will let AndroidJUnit4 use the original runner.
         System.setProperty("android.junit.runner",
                 "androidx.test.internal.runner.junit4.AndroidJUnit4ClassRunner");
         System.setProperty(RAVENWOOD_VERSION_JAVA_SYSPROP, "1");
-
-
-        // This is needed to make AndroidJUnit4ClassRunner happy.
-        InstrumentationRegistry.registerInstance(null, Bundle.EMPTY);
     }
 
     /**
@@ -87,7 +106,7 @@ public class RavenwoodAwareTestRunnerHook {
      */
     public static boolean onBefore(RavenwoodAwareTestRunner runner, Description description,
             Scope scope, Order order) {
-        Log.i(TAG, "onBefore: description=" + description + ", " + scope + ", " + order);
+        Log.v(TAG, "onBefore: description=" + description + ", " + scope + ", " + order);
 
         if (scope == Scope.Class && order == Order.First) {
             // Keep track of the current class.
@@ -113,7 +132,7 @@ public class RavenwoodAwareTestRunnerHook {
      */
     public static boolean onAfter(RavenwoodAwareTestRunner runner, Description description,
             Scope scope, Order order, Throwable th) {
-        Log.i(TAG, "onAfter: description=" + description + ", " + scope + ", " + order + ", " + th);
+        Log.v(TAG, "onAfter: description=" + description + ", " + scope + ", " + order + ", " + th);
 
         if (scope == Scope.Instance && order == Order.First) {
             getStats().onTestFinished(sCurrentClassDescription, description,
diff --git a/ravenwood/junit-impl-src/android/platform/test/ravenwood/RavenwoodRuleImpl.java b/ravenwood/junit-impl-src/android/platform/test/ravenwood/RavenwoodRuleImpl.java
index a2088fd0b77f..0059360a0a29 100644
--- a/ravenwood/junit-impl-src/android/platform/test/ravenwood/RavenwoodRuleImpl.java
+++ b/ravenwood/junit-impl-src/android/platform/test/ravenwood/RavenwoodRuleImpl.java
@@ -36,7 +36,6 @@ import android.view.DisplayAdjustments;
 
 import androidx.test.platform.app.InstrumentationRegistry;
 
-import com.android.internal.os.RuntimeInit;
 import com.android.server.LocalServices;
 
 import org.junit.runner.Description;
@@ -92,8 +91,6 @@ public class RavenwoodRuleImpl {
             Thread.setDefaultUncaughtExceptionHandler(sUncaughtExceptionHandler);
         }
 
-        RuntimeInit.redirectLogStreams();
-
         android.os.Process.init$ravenwood(rule.mUid, rule.mPid);
         android.os.Binder.init$ravenwood();
         setSystemProperties(rule.mSystemProperties);
diff --git a/ravenwood/junit-src/android/platform/test/ravenwood/RavenwoodAwareTestRunner.java b/ravenwood/junit-src/android/platform/test/ravenwood/RavenwoodAwareTestRunner.java
index 7d991663f4b1..bfde9cb7099e 100644
--- a/ravenwood/junit-src/android/platform/test/ravenwood/RavenwoodAwareTestRunner.java
+++ b/ravenwood/junit-src/android/platform/test/ravenwood/RavenwoodAwareTestRunner.java
@@ -23,7 +23,6 @@ import static java.lang.annotation.ElementType.TYPE;
 
 import android.util.Log;
 
-import com.android.ravenwood.common.RavenwoodCommonUtils;
 import com.android.ravenwood.common.SneakyThrow;
 
 import org.junit.Assume;
@@ -75,7 +74,7 @@ import java.lang.reflect.InvocationTargetException;
  * (no hooks, etc.)
  */
 public class RavenwoodAwareTestRunner extends Runner implements Filterable, Orderable {
-    private static final String TAG = "RavenwoodAwareTestRunner";
+    public static final String TAG = "Ravenwood";
 
     @Inherited
     @Target({TYPE})
@@ -142,16 +141,9 @@ public class RavenwoodAwareTestRunner extends Runner implements Filterable, Orde
     private Description mDescription = null;
     private Throwable mExceptionInConstructor = null;
 
-    /** Simple logging method. */
-    private void log(String message) {
-        RavenwoodCommonUtils.log(TAG, "[" + getTestClass().getJavaClass() + "  @" + this + "] "
-                + message);
-    }
-
-    private Error logAndFail(String message, Throwable innerException) {
-        log(message);
-        log("    Exception=" + innerException);
-        throw new AssertionError(message, innerException);
+    private Error logAndFail(String message, Throwable exception) {
+        Log.e(TAG, message, exception);
+        throw new AssertionError(message, exception);
     }
 
     public TestClass getTestClass() {
@@ -165,6 +157,8 @@ public class RavenwoodAwareTestRunner extends Runner implements Filterable, Orde
         try {
             mTestClass = new TestClass(testClass);
 
+            onRunnerInitializing();
+
             /*
              * If the class has @DisabledOnRavenwood, then we'll delegate to
              * ClassSkippingTestRunner, which simply skips it.
@@ -186,10 +180,8 @@ public class RavenwoodAwareTestRunner extends Runner implements Filterable, Orde
                 realRunnerClass = BlockJUnit4ClassRunner.class;
             }
 
-            onRunnerInitializing();
-
             try {
-                log("Initializing the inner runner: " + realRunnerClass);
+                Log.i(TAG, "Initializing the inner runner: " + realRunnerClass);
 
                 mRealRunner = instantiateRealRunner(realRunnerClass, testClass);
                 mDescription = mRealRunner.getDescription();
@@ -201,8 +193,7 @@ public class RavenwoodAwareTestRunner extends Runner implements Filterable, Orde
         } catch (Throwable th) {
             // If we throw in the constructor, Tradefed may not report it and just ignore the class,
             // so record it and throw it when the test actually started.
-            log("Fatal: Exception detected in constructor: " + th.getMessage() + "\n"
-                    + Log.getStackTraceString(th));
+            Log.e(TAG, "Fatal: Exception detected in constructor", th);
             mExceptionInConstructor = new RuntimeException("Exception detected in constructor",
                     th);
             mDescription = Description.createTestDescription(testClass, "Constructor");
@@ -236,8 +227,7 @@ public class RavenwoodAwareTestRunner extends Runner implements Filterable, Orde
         if (!isOnRavenwood()) {
             return;
         }
-
-        log("onRunnerInitializing");
+        // DO NOT USE android.util.Log before calling onRunnerInitializing().
 
         RavenwoodAwareTestRunnerHook.onRunnerInitializing(this, mTestClass);
 
@@ -250,7 +240,7 @@ public class RavenwoodAwareTestRunner extends Runner implements Filterable, Orde
         if (!isOnRavenwood()) {
             return;
         }
-        log("runAnnotatedMethodsOnRavenwood() " + annotationClass.getName());
+        Log.v(TAG, "runAnnotatedMethodsOnRavenwood() " + annotationClass.getName());
 
         for (var method : getTestClass().getAnnotatedMethods(annotationClass)) {
             ensureIsPublicVoidMethod(method.getMethod(), /* isStatic=*/ instance == null);
diff --git a/ravenwood/runtime-helper-src/framework/com/android/platform/test/ravenwood/runtimehelper/ClassLoadHook.java b/ravenwood/runtime-helper-src/framework/com/android/platform/test/ravenwood/runtimehelper/ClassLoadHook.java
index 0f955e772445..c519204d0586 100644
--- a/ravenwood/runtime-helper-src/framework/com/android/platform/test/ravenwood/runtimehelper/ClassLoadHook.java
+++ b/ravenwood/runtime-helper-src/framework/com/android/platform/test/ravenwood/runtimehelper/ClassLoadHook.java
@@ -15,6 +15,9 @@
  */
 package com.android.platform.test.ravenwood.runtimehelper;
 
+import android.system.ErrnoException;
+import android.system.Os;
+
 import com.android.ravenwood.common.RavenwoodCommonUtils;
 
 import java.io.File;
@@ -37,6 +40,14 @@ public class ClassLoadHook {
     private static final boolean SKIP_LOADING_LIBANDROID = "1".equals(System.getenv(
             "RAVENWOOD_SKIP_LOADING_LIBANDROID"));
 
+    /**
+     * If set to 1, and if $ANDROID_LOG_TAGS isn't set, we enable the verbose logging.
+     *
+     * (See also InitLogging() in http://ac/system/libbase/logging.cpp)
+     */
+    private static final boolean RAVENWOOD_VERBOSE_LOGGING = "1".equals(System.getenv(
+            "RAVENWOOD_VERBOSE"));
+
     public static final String CORE_NATIVE_CLASSES = "core_native_classes";
     public static final String ICU_DATA_PATH = "icu.data.path";
     public static final String KEYBOARD_PATHS = "keyboard_paths";
@@ -123,6 +134,15 @@ public class ClassLoadHook {
             return;
         }
 
+        if (RAVENWOOD_VERBOSE_LOGGING) {
+            log("Force enabling verbose logging");
+            try {
+                Os.setenv("ANDROID_LOG_TAGS", "*:v", true);
+            } catch (ErrnoException e) {
+                // Shouldn't happen.
+            }
+        }
+
         // Make sure these properties are not set.
         ensurePropertyNotSet(CORE_NATIVE_CLASSES);
         ensurePropertyNotSet(ICU_DATA_PATH);
diff --git a/ravenwood/runtime-helper-src/libcore-fake/android/system/Os.java b/ravenwood/runtime-helper-src/libcore-fake/android/system/Os.java
index a5c0b54a8637..c94ef31a5e5e 100644
--- a/ravenwood/runtime-helper-src/libcore-fake/android/system/Os.java
+++ b/ravenwood/runtime-helper-src/libcore-fake/android/system/Os.java
@@ -93,4 +93,8 @@ public final class Os {
             throw new ErrnoException("pread", OsConstants.EIO, e);
         }
     }
+
+    public static void setenv(String name, String value, boolean overwrite) throws ErrnoException {
+        RavenwoodRuntimeNative.setenv(name, value, overwrite);
+    }
 }
diff --git a/ravenwood/runtime-helper-src/libcore-fake/com/android/ravenwood/RavenwoodRuntimeNative.java b/ravenwood/runtime-helper-src/libcore-fake/com/android/ravenwood/RavenwoodRuntimeNative.java
index 0d8408c12033..ad80d92686ab 100644
--- a/ravenwood/runtime-helper-src/libcore-fake/com/android/ravenwood/RavenwoodRuntimeNative.java
+++ b/ravenwood/runtime-helper-src/libcore-fake/com/android/ravenwood/RavenwoodRuntimeNative.java
@@ -53,6 +53,9 @@ public class RavenwoodRuntimeNative {
 
     private static native int nOpen(String path, int flags, int mode) throws ErrnoException;
 
+    public static native void setenv(String name, String value, boolean overwrite)
+            throws ErrnoException;
+
     public static long lseek(FileDescriptor fd, long offset, int whence) throws ErrnoException {
         return nLseek(JvmWorkaround.getInstance().getFdInt(fd), offset, whence);
     }
diff --git a/ravenwood/runtime-jni/ravenwood_runtime.cpp b/ravenwood/runtime-jni/ravenwood_runtime.cpp
index f5cb019f4e7e..c255be5f61aa 100644
--- a/ravenwood/runtime-jni/ravenwood_runtime.cpp
+++ b/ravenwood/runtime-jni/ravenwood_runtime.cpp
@@ -214,6 +214,19 @@ static jint Linux_open(JNIEnv* env, jobject, jstring javaPath, jint flags, jint
     return throwIfMinusOne(env, "open", TEMP_FAILURE_RETRY(open(path.c_str(), flags, mode)));
 }
 
+static void Linux_setenv(JNIEnv* env, jobject, jstring javaName, jstring javaValue,
+        jboolean overwrite) {
+    ScopedRealUtf8Chars name(env, javaName);
+    if (name.c_str() == NULL) {
+        jniThrowNullPointerException(env);
+    }
+    ScopedRealUtf8Chars value(env, javaValue);
+    if (value.c_str() == NULL) {
+        jniThrowNullPointerException(env);
+    }
+    throwIfMinusOne(env, "setenv", setenv(name.c_str(), value.c_str(), overwrite ? 1 : 0));
+}
+
 // ---- Registration ----
 
 static const JNINativeMethod sMethods[] =
@@ -227,6 +240,7 @@ static const JNINativeMethod sMethods[] =
     { "lstat", "(Ljava/lang/String;)Landroid/system/StructStat;", (void*)Linux_lstat },
     { "stat", "(Ljava/lang/String;)Landroid/system/StructStat;", (void*)Linux_stat },
     { "nOpen", "(Ljava/lang/String;II)I", (void*)Linux_open },
+    { "setenv", "(Ljava/lang/String;Ljava/lang/String;Z)V", (void*)Linux_setenv },
 };
 
 extern "C" jint JNI_OnLoad(JavaVM* vm, void* /* reserved */)