Clean up log initialization

- Make sure RuntimeInit.redirectLogStreams() is always called even
  without RavenwoodRule is used.

- In RuntimeInit.redirectLogStreams(), make sure the Log class is
  initialized properly before setting up the redirect. Otherwise,
  we'd end up trying to use the Log APIs before the Log native code
  is loaded, which would cause an UnsatisfiedLinkError.

- Use $RAVENWOOD_VERBOSE_LOGGING to force enable verbose logging.
  If it's not set, the normal $ANDROID_LOG_TAGS would be used.

Fix: 363315644
Test: $ANDROID_BUILD_TOP/frameworks/base/ravenwood/scripts/run-ravenwood-tests.sh
Flag: EXEMPT host test change only

Change-Id: Ifa4e4859c39380ebb3500cfb6570dfb78f839c0a

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 */)