LogcatLog: add tracing functionality to trace()

Some people have the crazy idea that the trace()
method should help trace program execution.

I don't know why they would think that, but
I'll relent and make it so.

Along the way: refactor how we filter trace/debug
messages, so that we don't pay the cost of
a stack trace unnecessarily.

Bug: 73972044
Bug: 30737821
Test: tests/wifitests/runtests.sh (on walleye)

Change-Id: Ida435642af81945bfcb16db5cf39b20e5bebc5bb

4 files changed, 157 insertions, 15 deletions

diff --git a/service/java/com/android/server/wifi/FakeWifiLog.java b/service/java/com/android/server/wifi/FakeWifiLog.java
index a58d77f59..4c5128114 100644
--- a/service/java/com/android/server/wifi/FakeWifiLog.java
+++ b/service/java/com/android/server/wifi/FakeWifiLog.java
@@ -42,6 +42,11 @@ public class FakeWifiLog implements WifiLog {
     }
 
     @Override
+    public LogMessage trace(String format, int numFramesToIgnore) {
+        return sDummyLogMessage;
+    }
+
+    @Override
     public LogMessage dump(String format) {
         return sDummyLogMessage;
     }
diff --git a/service/java/com/android/server/wifi/LogcatLog.java b/service/java/com/android/server/wifi/LogcatLog.java
index ffe89505e..ce296009f 100644
--- a/service/java/com/android/server/wifi/LogcatLog.java
+++ b/service/java/com/android/server/wifi/LogcatLog.java
@@ -19,6 +19,7 @@ package com.android.server.wifi;
 import android.util.Log;
 
 import com.android.internal.annotations.Immutable;
+import com.android.internal.annotations.VisibleForTesting;
 
 import javax.annotation.concurrent.ThreadSafe;
 
@@ -34,6 +35,7 @@ import javax.annotation.concurrent.ThreadSafe;
 class LogcatLog implements WifiLog {
     private final String mTag;
     private static volatile boolean sVerboseLogging = false;
+    private static final DummyLogMessage sDummyLogMessage = new DummyLogMessage();
 
     LogcatLog(String tag) {
         mTag = tag;
@@ -50,27 +52,46 @@ class LogcatLog implements WifiLog {
     /* New-style methods */
     @Override
     public LogMessage err(String format) {
-        return makeLogMessage(Log.ERROR, format);
+        return new RealLogMessage(Log.ERROR, mTag, format);
     }
 
     @Override
     public LogMessage warn(String format) {
-        return makeLogMessage(Log.WARN, format);
+        return new RealLogMessage(Log.WARN, mTag, format);
     }
 
     @Override
     public LogMessage info(String format) {
-        return makeLogMessage(Log.INFO, format);
+        return new RealLogMessage(Log.INFO, mTag, format);
     }
 
     @Override
     public LogMessage trace(String format) {
-        return makeLogMessage(Log.DEBUG, format);
+        if (sVerboseLogging) {
+            return new RealLogMessage(Log.DEBUG, mTag, format,
+                    getNameOfCallingMethod(0));
+        } else {
+            return sDummyLogMessage;
+        }
+    }
+
+    @Override
+    public LogMessage trace(String format, int numFramesToIgnore) {
+        if (sVerboseLogging) {
+            return new RealLogMessage(Log.DEBUG, mTag, format,
+                    getNameOfCallingMethod(numFramesToIgnore));
+        } else {
+            return sDummyLogMessage;
+        }
     }
 
     @Override
     public LogMessage dump(String format) {
-        return makeLogMessage(Log.VERBOSE, format);
+        if (sVerboseLogging) {
+            return new RealLogMessage(Log.VERBOSE, mTag, format);
+        } else {
+            return sDummyLogMessage;
+        }
     }
 
     @Override
@@ -128,11 +149,18 @@ class LogcatLog implements WifiLog {
         private int mNextFormatCharPos;
 
         RealLogMessage(int logLevel, String tag, String format) {
+            this(logLevel, tag, format, null);
+        }
+
+        RealLogMessage(int logLevel, String tag, String format, String prefix) {
             mLogLevel = logLevel;
             mTag = tag;
             mFormat = format;
             mStringBuilder = new StringBuilder();
             mNextFormatCharPos = 0;
+            if (prefix != null) {
+                mStringBuilder.append(prefix).append(" ");
+            }
         }
 
         @Override
@@ -187,12 +215,10 @@ class LogcatLog implements WifiLog {
             if (mNextFormatCharPos < mFormat.length()) {
                 mStringBuilder.append(mFormat, mNextFormatCharPos, mFormat.length());
             }
-            if (sVerboseLogging || mLogLevel > Log.DEBUG) {
-                Log.println(mLogLevel, mTag, mStringBuilder.toString());
-            }
+            Log.println(mLogLevel, mTag, mStringBuilder.toString());
         }
 
-        /* Should generally not be used; implemented primarily to aid in testing. */
+        @VisibleForTesting
         public String toString() {
             return mStringBuilder.toString();
         }
@@ -212,8 +238,25 @@ class LogcatLog implements WifiLog {
         }
     }
 
-    private LogMessage makeLogMessage(int logLevel, String format) {
-        // TODO(b/30737821): Consider adding an isLoggable() check.
-        return new RealLogMessage(logLevel, mTag, format);
+    private static final String[] TRACE_FRAMES_TO_IGNORE = {
+            "getNameOfCallingMethod()", "trace()"
+    };
+    private String getNameOfCallingMethod(int callerFramesToIgnore) {
+        final int frameNumOfInterest = callerFramesToIgnore + TRACE_FRAMES_TO_IGNORE.length;
+        // In some environments, it's much faster to get a stack trace from a Throwable
+        // https://bugs.java.com/bugdatabase/view_bug.do?bug_id=6375302.
+        //
+        // While Dalvik optimizes the same-thread-stack-trace case,
+        // Throwable_nativeGetStackTrace() is still simpler than
+        // VMStack_getThreadStackTrace().
+        //
+        // Some crude benchmarking suggests that the cost of this approach is about
+        // 50 usec. go/logcatlog-trace-benchmark
+        StackTraceElement[] stackTrace = (new Throwable()).getStackTrace();
+        try {
+            return stackTrace[frameNumOfInterest].getMethodName();
+        } catch (ArrayIndexOutOfBoundsException e) {
+            return ("<unknown>");
+        }
     }
 }
diff --git a/service/java/com/android/server/wifi/WifiLog.java b/service/java/com/android/server/wifi/WifiLog.java
index 24dcda67c..c7ec606e5 100644
--- a/service/java/com/android/server/wifi/WifiLog.java
+++ b/service/java/com/android/server/wifi/WifiLog.java
@@ -91,18 +91,33 @@ public interface WifiLog {
     LogMessage info(@NonNull String format);
 
     /**
-     * Like {@link #err(String) err()}, except that a trace-level message is
-     * allocated.
+     * Like {@link #err(String) err()}, except:
+     * - a trace-level message is allocated
+     * - the log message is prefixed with the caller's name
      *
      * Trace-level messages should be used to report progress or status messages
      * that help understand the program's internal behavior. For example:
-     * "Reached myCoolMethod()".
+     * "invoked with verbose=%".
      */
     @CheckReturnValue
     @NonNull
     LogMessage trace(@NonNull String format);
 
     /**
+     * Like {@link #trace(String) trace(String)}, except that, rather than logging
+     * the immediate caller, the |numFramesToIgnore + 1|-th caller will be logged.
+     *
+     * E.g. if numFramesToIgnore == 1, then the caller's caller will be logged.
+     *
+     * Trace-level messages should be used to report progress or status messages
+     * that help understand the program's internal behavior. For example:
+     * "invoked with verbose=%".
+     */
+    @CheckReturnValue
+    @NonNull
+    LogMessage trace(@NonNull String format, int numFramesToIgnore);
+
+    /**
      * Like {@link #err(String) err()}, except that a dump-level message is
      * allocated.
      *
diff --git a/tests/wifitests/src/com/android/server/wifi/LogcatLogTest.java b/tests/wifitests/src/com/android/server/wifi/LogcatLogTest.java
index 9a847d347..9e80af8d3 100644
--- a/tests/wifitests/src/com/android/server/wifi/LogcatLogTest.java
+++ b/tests/wifitests/src/com/android/server/wifi/LogcatLogTest.java
@@ -16,6 +16,8 @@
 
 package com.android.server.wifi;
 
+import static org.hamcrest.MatcherAssert.assertThat;
+import static org.hamcrest.Matchers.instanceOf;
 import static org.junit.Assert.assertEquals;
 
 import android.support.test.filters.SmallTest;
@@ -247,4 +249,81 @@ public class LogcatLogTest {
         logMessage.c("hello\t").c("big\\").flush();
         assertEquals("hello\tbig\\world", logMessage.toString());
     }
+
+    @Test
+    public void traceLogMessageIncludesCallerName() {
+        try {
+            LogcatLog.enableVerboseLogging(1);
+            WifiLog.LogMessage logMessage = mLogger.trace("%");
+            logMessage.c("says hello").flush();
+            assertEquals("traceLogMessageIncludesCallerName says hello",
+                    logMessage.toString());
+        } finally {
+            LogcatLog.enableVerboseLogging(0);
+        }
+    }
+
+    @Test
+    public void traceLogMessageRespectsNumFramesToIgnore() {
+        try {
+            LogcatLog.enableVerboseLogging(1);
+            WifiLog.LogMessage logMessage = traceHelper("%");
+            logMessage.c("says hello").flush();
+            assertEquals("traceLogMessageRespectsNumFramesToIgnore says hello",
+                    logMessage.toString());
+        } finally {
+            LogcatLog.enableVerboseLogging(0);
+        }
+    }
+
+    @Test
+    public void traceLogMessageDoesNotCrashOnOversizedNumFramesToIgnore() {
+        try {
+            LogcatLog.enableVerboseLogging(1);
+            WifiLog.LogMessage logMessage = mLogger.trace("%",
+                    (new Throwable()).getStackTrace().length);
+            logMessage.c("says hello").flush();
+            assertEquals("<unknown> says hello", logMessage.toString());
+        } finally {
+            LogcatLog.enableVerboseLogging(0);
+        }
+    }
+
+    @Test
+    public void traceLogMessageDoesNotCrashOnOverflowingNumFramesToIgnore() {
+        try {
+            LogcatLog.enableVerboseLogging(1);
+            WifiLog.LogMessage logMessage = mLogger.trace("%", Integer.MAX_VALUE);
+            logMessage.c("says hello").flush();
+            assertEquals("<unknown> says hello", logMessage.toString());
+        } finally {
+            LogcatLog.enableVerboseLogging(0);
+        }
+    }
+
+    @Test
+    public void traceLogMessageDoesNotCrashOnUndersizedNumFramesToIgnore() {
+        try {
+            LogcatLog.enableVerboseLogging(1);
+            WifiLog.LogMessage logMessage = mLogger.trace("%", Integer.MIN_VALUE);
+            logMessage.c("says hello").flush();
+            assertEquals("<unknown> says hello", logMessage.toString());
+        } finally {
+            LogcatLog.enableVerboseLogging(0);
+        }
+    }
+
+    @Test
+    public void traceLogMessageReturnsDummyLogMessageByDefault() {
+        assertThat(mLogger.trace("%"), instanceOf(DummyLogMessage.class));
+    }
+
+    @Test
+    public void dumpLogMessageReturnsDummyLogMessageByDefault() {
+        assertThat(mLogger.dump("%"), instanceOf(DummyLogMessage.class));
+    }
+
+    private WifiLog.LogMessage traceHelper(String format) {
+        return mLogger.trace(format, 1);
+    }
 }