Add string literal logger to LogBuffer.
This also adds an exception field to the LogMessage and logs it to logcat.
The new method relies on @CompileTimeConstant errorprone annotation to
ensure that method is not called with string that is built dynamically.
Test: atest LogBufferTest
Bug: 239819049
Change-Id: I38560fb144b32f611f1d6a5b238a00cbf3bf0f7c
diff --git a/packages/SystemUI/src/com/android/systemui/log/LogBuffer.kt b/packages/SystemUI/src/com/android/systemui/log/LogBuffer.kt
index db446c3..dc23684d 100644
--- a/packages/SystemUI/src/com/android/systemui/log/LogBuffer.kt
+++ b/packages/SystemUI/src/com/android/systemui/log/LogBuffer.kt
@@ -20,14 +20,19 @@
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 @@
* @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 @@
* 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
- * obtained and is passed to the [initializer]. The initializer stores any relevant data on the
- * message's fields. The message is then inserted into the buffer where it waits until it 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
+ * this, logging a message is a two-step process. First, a fresh instance of [LogMessage] is
+ * obtained and is passed to the [messageInitializer]. The initializer stores any relevant data
+ * on the message's fields. The message is then inserted into the buffer where it waits until it
+ * is either pushed out by newer messages or it needs to printed. If and when this latter moment
+ * 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,27 +131,49 @@
* 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
- * 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
- * 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.
+ * @param messageInitializer 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.
+ * @param messagePrinter 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.
+ * @param exception Provide any exception that need to be logged. This is saved as
+ * [LogMessage.exception]
*/
+ @JvmOverloads
inline fun log(
- tag: String,
- level: LogLevel,
- initializer: LogMessage.() -> Unit,
- noinline printer: LogMessage.() -> String
+ tag: String,
+ level: LogLevel,
+ messageInitializer: MessageInitializer,
+ noinline messagePrinter: MessagePrinter,
+ exception: Throwable? = null,
) {
- val message = obtain(tag, level, printer)
- initializer(message)
+ val message = obtain(tag, level, messagePrinter, exception)
+ 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.
*
* Obtains the next [LogMessage] from the ring buffer. If the buffer is not yet at max size,
@@ -151,15 +184,16 @@
*/
@Synchronized
fun obtain(
- tag: String,
- level: LogLevel,
- printer: (LogMessage) -> String
- ): LogMessageImpl {
+ tag: String,
+ level: LogLevel,
+ messagePrinter: MessagePrinter,
+ 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 @@
}
}
- private fun dumpMessage(message: LogMessage, pw: PrintWriter) {
- pw.print(DATE_FORMAT.format(message.timestamp))
+ private fun dumpMessage(
+ 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 @@
private fun echoToLogcat(message: LogMessage, strMessage: String) {
when (message.level) {
- LogLevel.VERBOSE -> Log.v(message.tag, strMessage)
- LogLevel.DEBUG -> Log.d(message.tag, strMessage)
- LogLevel.INFO -> Log.i(message.tag, strMessage)
- LogLevel.WARNING -> Log.w(message.tag, strMessage)
- LogLevel.ERROR -> Log.e(message.tag, strMessage)
- LogLevel.WTF -> Log.wtf(message.tag, strMessage)
+ LogLevel.VERBOSE -> Log.v(message.tag, strMessage, message.exception)
+ LogLevel.DEBUG -> Log.d(message.tag, strMessage, message.exception)
+ LogLevel.INFO -> Log.i(message.tag, strMessage, message.exception)
+ LogLevel.WARNING -> Log.w(message.tag, strMessage, message.exception)
+ LogLevel.ERROR -> Log.e(message.tag, strMessage, message.exception)
+ 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()
\ No newline at end of file
+private val FROZEN_MESSAGE = LogMessageImpl.create()
diff --git a/packages/SystemUI/src/com/android/systemui/log/LogMessage.kt b/packages/SystemUI/src/com/android/systemui/log/LogMessage.kt
index 2a0a2aa6..987aea8 100644
--- a/packages/SystemUI/src/com/android/systemui/log/LogMessage.kt
+++ b/packages/SystemUI/src/com/android/systemui/log/LogMessage.kt
@@ -25,7 +25,7 @@
*
* 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 @@
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 @@
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
diff --git a/packages/SystemUI/src/com/android/systemui/log/LogMessageImpl.kt b/packages/SystemUI/src/com/android/systemui/log/LogMessageImpl.kt
index d33ac4b..4dd6f65 100644
--- a/packages/SystemUI/src/com/android/systemui/log/LogMessageImpl.kt
+++ b/packages/SystemUI/src/com/android/systemui/log/LogMessageImpl.kt
@@ -23,7 +23,8 @@
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 @@
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 @@
LogLevel.DEBUG,
DEFAULT_TAG,
0,
- DEFAULT_RENDERER,
+ DEFAULT_PRINTER,
+ null,
null,
null,
null,
@@ -86,4 +90,4 @@
}
private const val DEFAULT_TAG = "UnknownTag"
-private val DEFAULT_RENDERER: LogMessage.() -> String = { "Unknown message: $this" }
+private val DEFAULT_PRINTER: MessagePrinter = { "Unknown message: $this" }
diff --git a/packages/SystemUI/src/com/android/systemui/statusbar/notification/collection/listbuilder/ShadeListBuilderLogger.kt b/packages/SystemUI/src/com/android/systemui/statusbar/notification/collection/listbuilder/ShadeListBuilderLogger.kt
index 4c406e3..d8dae5d 100644
--- a/packages/SystemUI/src/com/android/systemui/statusbar/notification/collection/listbuilder/ShadeListBuilderLogger.kt
+++ b/packages/SystemUI/src/com/android/systemui/statusbar/notification/collection/listbuilder/ShadeListBuilderLogger.kt
@@ -336,7 +336,7 @@
}
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"
diff --git a/packages/SystemUI/tests/src/com/android/systemui/log/LogBufferTest.kt b/packages/SystemUI/tests/src/com/android/systemui/log/LogBufferTest.kt
new file mode 100644
index 0000000..4abb973
--- /dev/null
+++ b/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()
+ }
+}