Merge "Add string literal logger to LogBuffer." into tm-qpr-dev (f16401f0) · Commits · e / os / android_frameworks_base

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

+138 −38

Original line number	Diff line number	Diff line
		@@ -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() }

		@@ -108,10 +119,10 @@ class LogBuffer @JvmOverloads constructor(
		*
		* 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
		* 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,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
		* 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
		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.
		*
		@@ -153,13 +186,14 @@ class LogBuffer @JvmOverloads constructor(
		fun obtain(
		tag: String,
		level: LogLevel,
		printer: (LogMessage) -> String
		): LogMessageImpl {
		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 @@ class LogBuffer @JvmOverloads constructor(
		}
		}

		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 @@ class LogBuffer @JvmOverloads constructor(

		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()

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

+13 −2

Original line number	Diff line number	Diff line
		@@ -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

+10 −6

Original line number	Diff line number	Diff line
		@@ -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

+1 −1

Original line number	Diff line number	Diff line
		@@ -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 → 100644

+167 −0

Original line number	Diff line number	Diff line
		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()
		}
		}