Merge "Add string literal logger to LogBuffer." into tm-qpr-dev

packages/SystemUI/src/com/android/systemui/log/LogBuffer.kt

@@ -20,14 +20,19 @@ import android.os.Trace
 import android.util.Log
 import com.android.systemui.log.dagger.LogModule
 import com.android.systemui.util.collection.RingBuffer
+import com.google.errorprone.annotations.CompileTimeConstant
 import java.io.PrintWriter
 import java.text.SimpleDateFormat
+import java.util.Arrays.stream
 import java.util.Locale
 import java.util.concurrent.ArrayBlockingQueue
 import java.util.concurrent.BlockingQueue
 import kotlin.concurrent.thread
 import kotlin.math.max
 
+const val UNBOUNDED_STACK_TRACE = -1
+const val NESTED_TRACE_DEPTH = 10
+
 /**
  * A simple ring buffer of recyclable log messages
  *
@@ -69,12 +74,18 @@ import kotlin.math.max
  * @param maxSize The maximum number of messages to keep in memory at any one time. Buffers start
  * out empty and grow up to [maxSize] as new messages are logged. Once the buffer's size reaches
  * the maximum, it behaves like a ring buffer.
+ * @param rootStackTraceDepth The number of stack trace elements to be logged for an exception when
+ * the logBuffer is dumped. Defaulted to -1 [UNBOUNDED_STACK_TRACE] to print the entire stack trace.
+ * @param nestedStackTraceDepth The number of stack trace elements to be logged for any nested
+ * exceptions present in [Throwable.cause] or [Throwable.suppressedExceptions].
  */
 class LogBuffer @JvmOverloads constructor(
     private val name: String,
     private val maxSize: Int,
     private val logcatEchoTracker: LogcatEchoTracker,
-    private val systrace: Boolean = true
+    private val systrace: Boolean = true,
+    private val rootStackTraceDepth: Int = UNBOUNDED_STACK_TRACE,
+    private val nestedStackTraceDepth: Int = NESTED_TRACE_DEPTH,
 ) {
     private val buffer = RingBuffer(maxSize) { LogMessageImpl.create() }
 
@@ -107,11 +118,11 @@ class LogBuffer @JvmOverloads constructor(
      * May also log the message to logcat if echoing is enabled for this buffer or tag.
      *
      * The actual string of the log message is not constructed until it is needed. To accomplish
-     * this, logging a message is a two-step process. First, a fresh instance  of [LogMessage] is
+     * this, logging a message is a two-step process. First, a fresh instance of [LogMessage] is
-     * obtained and is passed to the [initializer]. The initializer stores any relevant data on the
+     * obtained and is passed to the [messageInitializer]. The initializer stores any relevant data
-     * message's fields. The message is then inserted into the buffer where it waits until it is
+     * on the message's fields. The message is then inserted into the buffer where it waits until it
-     * either pushed out by newer messages or it needs to printed. If and when this latter moment
+     * is either pushed out by newer messages or it needs to printed. If and when this latter moment
-     * occurs, the [printer] function is called on the message. It reads whatever data the
+     * occurs, the [messagePrinter] function is called on the message. It reads whatever data the
      * initializer stored and converts it to a human-readable log message.
      *
      * @param tag A string of at most 23 characters, used for grouping logs into categories or
@@ -120,26 +131,48 @@ class LogBuffer @JvmOverloads constructor(
      * echoed. In general, a module should split most of its logs into either INFO or DEBUG level.
      * INFO level should be reserved for information that other parts of the system might care
      * about, leaving the specifics of code's day-to-day operations to DEBUG.
-     * @param initializer A function that will be called immediately to store relevant data on the
+     * @param messageInitializer A function that will be called immediately to store relevant data
-     * log message. The value of `this` will be the LogMessage to be initialized.
+     * on the log message. The value of `this` will be the LogMessage to be initialized.
-     * @param printer A function that will be called if and when the message needs to be dumped to
+     * @param messagePrinter A function that will be called if and when the message needs to be
-     * logcat or a bug report. It should read the data stored by the initializer and convert it to
+     * dumped to logcat or a bug report. It should read the data stored by the initializer and
-     * a human-readable string. The value of `this` will be the LogMessage to be printed.
+     * convert it to a human-readable string. The value of `this` will be the LogMessage to be
-     * **IMPORTANT:** The printer should ONLY ever reference fields on the LogMessage and NEVER any
+     * printed. **IMPORTANT:** The printer should ONLY ever reference fields on the LogMessage and
-     * variables in its enclosing scope. Otherwise, the runtime will need to allocate a new instance
+     * NEVER any variables in its enclosing scope. Otherwise, the runtime will need to allocate a
-     * of the printer for each call, thwarting our attempts at avoiding any sort of allocation.
+     * new instance of the printer for each call, thwarting our attempts at avoiding any sort of
+     * allocation.
+     * @param exception Provide any exception that need to be logged. This is saved as
+     * [LogMessage.exception]
      */
+    @JvmOverloads
     inline fun log(
-        tag: String,
+            tag: String,
-        level: LogLevel,
+            level: LogLevel,
-        initializer: LogMessage.() -> Unit,
+            messageInitializer: MessageInitializer,
-        noinline printer: LogMessage.() -> String
+            noinline messagePrinter: MessagePrinter,
+            exception: Throwable? = null,
     ) {
-        val message = obtain(tag, level, printer)
+        val message = obtain(tag, level, messagePrinter, exception)
-        initializer(message)
+        messageInitializer(message)
         commit(message)
     }
 
+    /**
+     * Logs a compile-time string constant [message] to the log buffer. Use sparingly.
+     *
+     * May also log the message to logcat if echoing is enabled for this buffer or tag. This is for
+     * simpler use-cases where [message] is a compile time string constant. For use-cases where the
+     * log message is built during runtime, use the [LogBuffer.log] overloaded method that takes in
+     * an initializer and a message printer.
+     *
+     * Log buffers are limited by the number of entries, so logging more frequently
+     * will limit the time window that the LogBuffer covers in a bug report.  Richer logs, on the
+     * other hand, make a bug report more actionable, so using the [log] with a messagePrinter to
+     * add more detail to every log may do more to improve overall logging than adding more logs
+     * with this method.
+     */
+    fun log(tag: String, level: LogLevel, @CompileTimeConstant message: String) =
+            log(tag, level, {str1 = message}, { str1!! })
+
     /**
      * You should call [log] instead of this method.
      *
@@ -151,15 +184,16 @@ class LogBuffer @JvmOverloads constructor(
      */
     @Synchronized
     fun obtain(
-        tag: String,
+            tag: String,
-        level: LogLevel,
+            level: LogLevel,
-        printer: (LogMessage) -> String
+            messagePrinter: MessagePrinter,
-    ): LogMessageImpl {
+            exception: Throwable? = null,
+    ): LogMessage {
         if (!mutable) {
             return FROZEN_MESSAGE
         }
         val message = buffer.advance()
-        message.reset(tag, level, System.currentTimeMillis(), printer)
+        message.reset(tag, level, System.currentTimeMillis(), messagePrinter, exception)
         return message
     }
 
@@ -230,19 +264,79 @@ class LogBuffer @JvmOverloads constructor(
         }
     }
 
-    private fun dumpMessage(message: LogMessage, pw: PrintWriter) {
+    private fun dumpMessage(
-        pw.print(DATE_FORMAT.format(message.timestamp))
+        message: LogMessage,
+        pw: PrintWriter
+    ) {
+        val formattedTimestamp = DATE_FORMAT.format(message.timestamp)
+        val shortLevel = message.level.shortString
+        val messageToPrint = message.messagePrinter(message)
+        val tag = message.tag
+        printLikeLogcat(pw, formattedTimestamp, shortLevel, tag, messageToPrint)
+        message.exception?.let { ex ->
+            printException(
+                pw,
+                formattedTimestamp,
+                shortLevel,
+                ex,
+                tag,
+                stackTraceDepth = rootStackTraceDepth)
+        }
+    }
+
+    private fun printException(
+            pw: PrintWriter,
+            timestamp: String,
+            level: String,
+            exception: Throwable,
+            tag: String,
+            exceptionMessagePrefix: String = "",
+            stackTraceDepth: Int = UNBOUNDED_STACK_TRACE
+    ) {
+        val message = "$exceptionMessagePrefix$exception"
+        printLikeLogcat(pw, timestamp, level, tag, message)
+        var stacktraceStream = stream(exception.stackTrace)
+        if (stackTraceDepth != UNBOUNDED_STACK_TRACE) {
+            stacktraceStream = stacktraceStream.limit(stackTraceDepth.toLong())
+        }
+        stacktraceStream.forEach { line ->
+            printLikeLogcat(pw, timestamp, level, tag, "\tat $line")
+        }
+        exception.cause?.let { cause ->
+            printException(pw, timestamp, level, cause, tag, "Caused by: ", nestedStackTraceDepth)
+        }
+        exception.suppressedExceptions.forEach { suppressed ->
+            printException(
+                pw,
+                timestamp,
+                level,
+                suppressed,
+                tag,
+                "Suppressed: ",
+                nestedStackTraceDepth
+            )
+        }
+    }
+
+    private fun printLikeLogcat(
+        pw: PrintWriter,
+        formattedTimestamp: String,
+        shortLogLevel: String,
+        tag: String,
+        message: String
+    ) {
+        pw.print(formattedTimestamp)
         pw.print(" ")
-        pw.print(message.level.shortString)
+        pw.print(shortLogLevel)
         pw.print(" ")
-        pw.print(message.tag)
+        pw.print(tag)
         pw.print(": ")
-        pw.println(message.printer(message))
+        pw.println(message)
     }
 
     private fun echo(message: LogMessage, toLogcat: Boolean, toSystrace: Boolean) {
         if (toLogcat || toSystrace) {
-            val strMessage = message.printer(message)
+            val strMessage = message.messagePrinter(message)
             if (toSystrace) {
                 echoToSystrace(message, strMessage)
             }
@@ -259,16 +353,22 @@ class LogBuffer @JvmOverloads constructor(
 
     private fun echoToLogcat(message: LogMessage, strMessage: String) {
         when (message.level) {
-            LogLevel.VERBOSE -> Log.v(message.tag, strMessage)
+            LogLevel.VERBOSE -> Log.v(message.tag, strMessage, message.exception)
-            LogLevel.DEBUG -> Log.d(message.tag, strMessage)
+            LogLevel.DEBUG -> Log.d(message.tag, strMessage, message.exception)
-            LogLevel.INFO -> Log.i(message.tag, strMessage)
+            LogLevel.INFO -> Log.i(message.tag, strMessage, message.exception)
-            LogLevel.WARNING -> Log.w(message.tag, strMessage)
+            LogLevel.WARNING -> Log.w(message.tag, strMessage, message.exception)
-            LogLevel.ERROR -> Log.e(message.tag, strMessage)
+            LogLevel.ERROR -> Log.e(message.tag, strMessage, message.exception)
-            LogLevel.WTF -> Log.wtf(message.tag, strMessage)
+            LogLevel.WTF -> Log.wtf(message.tag, strMessage, message.exception)
         }
     }
 }
 
+/**
+ * A function that will be called immediately to store relevant data on the log message. The value
+ * of `this` will be the LogMessage to be initialized.
+ */
+typealias MessageInitializer = LogMessage.() -> Unit
+
 private const val TAG = "LogBuffer"
 private val DATE_FORMAT = SimpleDateFormat("MM-dd HH:mm:ss.SSS", Locale.US)
 private val FROZEN_MESSAGE = LogMessageImpl.create()

packages/SystemUI/src/com/android/systemui/log/LogMessage.kt

@@ -25,7 +25,7 @@ package com.android.systemui.log
  *
  * When a message is logged, the code doing the logging stores data in one or more of the generic
  * fields ([str1], [int1], etc). When it comes time to dump the message to logcat/bugreport/etc, the
- * [printer] function reads the data stored in the generic fields and converts that to a human-
+ * [messagePrinter] function reads the data stored in the generic fields and converts that to a human-
  * readable string. Thus, for every log type there must be a specialized initializer function that
  * stores data specific to that log type and a specialized printer function that prints that data.
  *
@@ -35,7 +35,8 @@ interface LogMessage {
     val level: LogLevel
     val tag: String
     val timestamp: Long
-    val printer: LogMessage.() -> String
+    val messagePrinter: MessagePrinter
+    val exception: Throwable?
 
     var str1: String?
     var str2: String?
@@ -50,3 +51,13 @@ interface LogMessage {
     var bool3: Boolean
     var bool4: Boolean
 }
+
+/**
+ * A function that will be called if and when the message needs to be dumped to
+ * logcat or a bug report. It should read the data stored by the initializer and convert it to
+ * a human-readable string. The value of `this` will be the LogMessage to be printed.
+ * **IMPORTANT:** The printer should ONLY ever reference fields on the LogMessage and NEVER any
+ * variables in its enclosing scope. Otherwise, the runtime will need to allocate a new instance
+ * of the printer for each call, thwarting our attempts at avoiding any sort of allocation.
+ */
+typealias MessagePrinter = LogMessage.() -> String

packages/SystemUI/src/com/android/systemui/log/LogMessageImpl.kt

@@ -23,7 +23,8 @@ data class LogMessageImpl(
     override var level: LogLevel,
     override var tag: String,
     override var timestamp: Long,
-    override var printer: LogMessage.() -> String,
+    override var messagePrinter: MessagePrinter,
+    override var exception: Throwable?,
     override var str1: String?,
     override var str2: String?,
     override var str3: String?,
@@ -35,19 +36,21 @@ data class LogMessageImpl(
     override var bool1: Boolean,
     override var bool2: Boolean,
     override var bool3: Boolean,
-    override var bool4: Boolean
+    override var bool4: Boolean,
 ) : LogMessage {
 
     fun reset(
         tag: String,
         level: LogLevel,
         timestamp: Long,
-        renderer: LogMessage.() -> String
+        renderer: MessagePrinter,
+        exception: Throwable? = null,
     ) {
         this.level = level
         this.tag = tag
         this.timestamp = timestamp
-        this.printer = renderer
+        this.messagePrinter = renderer
+        this.exception = exception
         str1 = null
         str2 = null
         str3 = null
@@ -68,7 +71,8 @@ data class LogMessageImpl(
                     LogLevel.DEBUG,
                     DEFAULT_TAG,
                     0,
-                    DEFAULT_RENDERER,
+                    DEFAULT_PRINTER,
+                    null,
                     null,
                     null,
                     null,
@@ -86,4 +90,4 @@ data class LogMessageImpl(
 }
 
 private const val DEFAULT_TAG = "UnknownTag"
-private val DEFAULT_RENDERER: LogMessage.() -> String = { "Unknown message: $this" }
+private val DEFAULT_PRINTER: MessagePrinter = { "Unknown message: $this" }

packages/SystemUI/src/com/android/systemui/statusbar/notification/collection/listbuilder/ShadeListBuilderLogger.kt

@@ -336,7 +336,7 @@ class ShadeListBuilderLogger @Inject constructor(
     }
 
     fun logPipelineRunSuppressed() =
-        buffer.log(TAG, INFO, {}) { "Suppressing pipeline run during animation." }
+        buffer.log(TAG, INFO, {}, { "Suppressing pipeline run during animation." })
 }
 
 private const val TAG = "ShadeListBuilder"

packages/SystemUI/tests/src/com/android/systemui/log/LogBufferTest.kt

@@ -0,0 +1,167 @@
+package com.android.systemui.log
+
+import androidx.test.filters.SmallTest
+import com.android.systemui.SysuiTestCase
+import com.google.common.truth.Truth.assertThat
+import java.io.PrintWriter
+import java.io.StringWriter
+import org.junit.Before
+import org.junit.Test
+import org.junit.runner.RunWith
+import org.mockito.Mock
+import org.mockito.junit.MockitoJUnitRunner
+
+@SmallTest
+@RunWith(MockitoJUnitRunner::class)
+class LogBufferTest : SysuiTestCase() {
+    private lateinit var buffer: LogBuffer
+
+    private lateinit var outputWriter: StringWriter
+
+    @Mock
+    private lateinit var logcatEchoTracker: LogcatEchoTracker
+
+    @Before
+    fun setup() {
+        outputWriter = StringWriter()
+        buffer = createBuffer(UNBOUNDED_STACK_TRACE, NESTED_TRACE_DEPTH)
+    }
+
+    private fun createBuffer(rootTraceDepth: Int, nestedTraceDepth: Int): LogBuffer {
+        return LogBuffer("TestBuffer",
+                1,
+                logcatEchoTracker,
+                false,
+                rootStackTraceDepth = rootTraceDepth,
+                nestedStackTraceDepth = nestedTraceDepth)
+    }
+
+    @Test
+    fun log_shouldSaveLogToBuffer() {
+        buffer.log("Test", LogLevel.INFO, "Some test message")
+
+        val dumpedString = dumpBuffer()
+
+        assertThat(dumpedString).contains("Some test message")
+    }
+
+    @Test
+    fun log_shouldRotateIfLogBufferIsFull() {
+        buffer.log("Test", LogLevel.INFO, "This should be rotated")
+        buffer.log("Test", LogLevel.INFO, "New test message")
+
+        val dumpedString = dumpBuffer()
+
+        assertThat(dumpedString).contains("New test message")
+    }
+
+    @Test
+    fun dump_writesExceptionAndStacktraceLimitedToGivenDepth() {
+        buffer = createBuffer(rootTraceDepth = 2, nestedTraceDepth = -1)
+        // stack trace depth of 5
+        val exception = createTestException("Exception message", "TestClass", 5)
+        buffer.log("Tag", LogLevel.ERROR, { str1 = "Extra message" }, { str1!! }, exception)
+
+        val dumpedString = dumpBuffer()
+
+        // logs are limited to depth 2
+        assertThat(dumpedString).contains("E Tag: Extra message")
+        assertThat(dumpedString).contains("E Tag: java.lang.RuntimeException: Exception message")
+        assertThat(dumpedString).contains("E Tag: \tat TestClass.TestMethod(TestClass.java:1)")
+        assertThat(dumpedString).contains("E Tag: \tat TestClass.TestMethod(TestClass.java:2)")
+        assertThat(dumpedString)
+                .doesNotContain("E Tag: \tat TestClass.TestMethod(TestClass.java:3)")
+    }
+
+    @Test
+    fun dump_writesCauseAndStacktraceLimitedToGivenDepth() {
+        buffer = createBuffer(rootTraceDepth = 0, nestedTraceDepth = 2)
+        val exception = createTestException("Exception message",
+                "TestClass",
+                1,
+                cause = createTestException("The real cause!", "TestClass", 5))
+        buffer.log("Tag", LogLevel.ERROR, { str1 = "Extra message" }, { str1!! }, exception)
+
+        val dumpedString = dumpBuffer()
+
+        // logs are limited to depth 2
+        assertThat(dumpedString)
+                .contains("E Tag: Caused by: java.lang.RuntimeException: The real cause!")
+        assertThat(dumpedString).contains("E Tag: \tat TestClass.TestMethod(TestClass.java:1)")
+        assertThat(dumpedString).contains("E Tag: \tat TestClass.TestMethod(TestClass.java:2)")
+        assertThat(dumpedString)
+                .doesNotContain("E Tag: \tat TestClass.TestMethod(TestClass.java:3)")
+    }
+
+    @Test
+    fun dump_writesSuppressedExceptionAndStacktraceLimitedToGivenDepth() {
+        buffer = createBuffer(rootTraceDepth = 0, nestedTraceDepth = 2)
+        val exception = RuntimeException("Root exception message")
+        exception.addSuppressed(
+                createTestException(
+                        "First suppressed exception",
+                        "FirstClass",
+                        5,
+                        createTestException("Cause of suppressed exp", "ThirdClass", 5)
+                ))
+        exception.addSuppressed(
+                createTestException("Second suppressed exception", "SecondClass", 5))
+        buffer.log("Tag", LogLevel.ERROR, { str1 = "Extra message" }, { str1!! }, exception)
+
+        val dumpedStr = dumpBuffer()
+
+        // logs are limited to depth 2
+        // first suppressed exception
+        assertThat(dumpedStr)
+                .contains("E Tag: Suppressed: " +
+                        "java.lang.RuntimeException: First suppressed exception")
+        assertThat(dumpedStr).contains("E Tag: \tat FirstClass.TestMethod(FirstClass.java:1)")
+        assertThat(dumpedStr).contains("E Tag: \tat FirstClass.TestMethod(FirstClass.java:2)")
+        assertThat(dumpedStr)
+                .doesNotContain("E Tag: \tat FirstClass.TestMethod(FirstClass.java:3)")
+
+        assertThat(dumpedStr)
+                .contains("E Tag: Caused by: java.lang.RuntimeException: Cause of suppressed exp")
+        assertThat(dumpedStr).contains("E Tag: \tat ThirdClass.TestMethod(ThirdClass.java:1)")
+        assertThat(dumpedStr).contains("E Tag: \tat ThirdClass.TestMethod(ThirdClass.java:2)")
+        assertThat(dumpedStr)
+                .doesNotContain("E Tag: \tat ThirdClass.TestMethod(ThirdClass.java:3)")
+
+        // second suppressed exception
+        assertThat(dumpedStr)
+                .contains("E Tag: Suppressed: " +
+                        "java.lang.RuntimeException: Second suppressed exception")
+        assertThat(dumpedStr).contains("E Tag: \tat SecondClass.TestMethod(SecondClass.java:1)")
+        assertThat(dumpedStr).contains("E Tag: \tat SecondClass.TestMethod(SecondClass.java:2)")
+        assertThat(dumpedStr)
+                .doesNotContain("E Tag: \tat SecondClass.TestMethod(SecondClass.java:3)")
+    }
+
+    private fun createTestException(
+        message: String,
+        errorClass: String,
+        stackTraceLength: Int,
+        cause: Throwable? = null
+    ): Exception {
+        val exception = RuntimeException(message, cause)
+        exception.stackTrace = createStackTraceElements(errorClass, stackTraceLength)
+        return exception
+    }
+
+    private fun dumpBuffer(): String {
+        buffer.dump(PrintWriter(outputWriter), tailLength = 100)
+        return outputWriter.toString()
+    }
+
+    private fun createStackTraceElements(
+        errorClass: String,
+        stackTraceLength: Int
+    ): Array<StackTraceElement> {
+        return (1..stackTraceLength).map { lineNumber ->
+            StackTraceElement(errorClass,
+                    "TestMethod",
+                    "$errorClass.java",
+                    lineNumber)
+        }.toTypedArray()
+    }
+}