1 /*
2  * Copyright (C) 2020 The Android Open Source Project
3  *
4  * Licensed under the Apache License, Version 2.0 (the "License");
5  * you may not use this file except in compliance with the License.
6  * You may obtain a copy of the License at
7  *
8  *      http://www.apache.org/licenses/LICENSE-2.0
9  *
10  * Unless required by applicable law or agreed to in writing, software
11  * distributed under the License is distributed on an "AS IS" BASIS,
12  * WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied.
13  * See the License for the specific language governing permissions and
14  * limitations under the License.
15  */
16 
17 package com.android.systemui.log
18 
19 import android.os.Trace
20 import android.util.Log
21 import com.android.systemui.common.buffer.RingBuffer
22 import com.android.systemui.log.core.LogLevel
23 import com.android.systemui.log.core.LogMessage
24 import com.android.systemui.log.core.MessageBuffer
25 import com.android.systemui.log.core.MessageInitializer
26 import com.android.systemui.log.core.MessagePrinter
27 import com.google.errorprone.annotations.CompileTimeConstant
28 import java.io.PrintWriter
29 import kotlin.math.max
30 
31 /**
32  * A simple ring buffer of recyclable log messages
33  *
34  * The goal of this class is to enable logging that is both extremely chatty and extremely
35  * lightweight. If done properly, logging a message will not result in any heap allocations or
36  * string generation. Messages are only converted to strings if the log is actually dumped (usually
37  * as the result of taking a bug report).
38  *
39  * You can dump the entire buffer at any time by running:
40  * ```
41  * $ adb shell dumpsys activity service com.android.systemui/.SystemUIService <bufferName>
42  * ```
43  *
44  * ...where `bufferName` is the (case-sensitive) [name] passed to the constructor.
45  *
46  * By default, only messages of WARN level or higher are echoed to logcat, but this can be adjusted
47  * locally (usually for debugging purposes).
48  *
49  * To enable logcat echoing for an entire buffer:
50  * ```
51  * $ adb shell cmd statusbar echo -b <bufferName>:<level>
52  * ```
53  *
54  * To enable logcat echoing for a specific tag:
55  * ```
56  * $ adb shell cmd statusbar echo -t <tagName>:<level>
57  * ```
58  *
59  * In either case, `level` can be any of `verbose`, `debug`, `info`, `warn`, `error`, `assert`, or
60  * the first letter of any of the previous.
61  *
62  * In SystemUI, buffers are provided by LogModule. Instances should be created using a SysUI
63  * LogBufferFactory.
64  *
65  * @param name The name of this buffer, printed when the buffer is dumped and in some other
66  *   situations.
67  * @param maxSize The maximum number of messages to keep in memory at any one time. Buffers start
68  *   out empty and grow up to [maxSize] as new messages are logged. Once the buffer's size reaches
69  *   the maximum, it behaves like a ring buffer.
70  */
71 class LogBuffer
72 @JvmOverloads
73 constructor(
74     private val name: String,
75     private val maxSize: Int,
76     private val logcatEchoTracker: LogcatEchoTracker,
77     private val systrace: Boolean = true,
78 ) : MessageBuffer {
<lambda>null79     private val buffer = RingBuffer(maxSize) { LogMessageImpl.create() }
80 
81     var frozen = false
82         private set
83 
84     private val mutable
85         get() = !frozen && maxSize > 0
86 
87     /**
88      * Logs a message to the log buffer
89      *
90      * May also log the message to logcat if echoing is enabled for this buffer or tag.
91      *
92      * The actual string of the log message is not constructed until it is needed. To accomplish
93      * this, logging a message is a two-step process. First, a fresh instance of [LogMessage] is
94      * obtained and is passed to the [messageInitializer]. The initializer stores any relevant data
95      * on the message's fields. The message is then inserted into the buffer where it waits until it
96      * is either pushed out by newer messages or it needs to printed. If and when this latter moment
97      * occurs, the [messagePrinter] function is called on the message. It reads whatever data the
98      * initializer stored and converts it to a human-readable log message.
99      *
100      * @param tag A string of at most 23 characters, used for grouping logs into categories or
101      *   subjects. If this message is echoed to logcat, this will be the tag that is used.
102      * @param level Which level to log the message at, both to the buffer and to logcat if it's
103      *   echoed. In general, a module should split most of its logs into either INFO or DEBUG level.
104      *   INFO level should be reserved for information that other parts of the system might care
105      *   about, leaving the specifics of code's day-to-day operations to DEBUG.
106      * @param messageInitializer A function that will be called immediately to store relevant data
107      *   on the log message. The value of `this` will be the LogMessage to be initialized.
108      * @param messagePrinter A function that will be called if and when the message needs to be
109      *   dumped to logcat or a bug report. It should read the data stored by the initializer and
110      *   convert it to a human-readable string. The value of `this` will be the LogMessage to be
111      *   printed. **IMPORTANT:** The printer should ONLY ever reference fields on the LogMessage and
112      *   NEVER any variables in its enclosing scope. Otherwise, the runtime will need to allocate a
113      *   new instance of the printer for each call, thwarting our attempts at avoiding any sort of
114      *   allocation.
115      * @param exception Provide any exception that need to be logged. This is saved as
116      *   [LogMessage.exception]
117      */
118     @JvmOverloads
lognull119     inline fun log(
120         tag: String,
121         level: LogLevel,
122         messageInitializer: MessageInitializer,
123         noinline messagePrinter: MessagePrinter,
124         exception: Throwable? = null,
125     ) {
126         val message = obtain(tag, level, messagePrinter, exception)
127         messageInitializer(message)
128         commit(message)
129     }
130 
131     /**
132      * Logs a compile-time string constant [message] to the log buffer. Use sparingly.
133      *
134      * May also log the message to logcat if echoing is enabled for this buffer or tag. This is for
135      * simpler use-cases where [message] is a compile time string constant. For use-cases where the
136      * log message is built during runtime, use the [LogBuffer.log] overloaded method that takes in
137      * an initializer and a message printer.
138      *
139      * Log buffers are limited by the number of entries, so logging more frequently will limit the
140      * time window that the LogBuffer covers in a bug report. Richer logs, on the other hand, make a
141      * bug report more actionable, so using the [log] with a messagePrinter to add more detail to
142      * every log may do more to improve overall logging than adding more logs with this method.
143      */
144     @JvmOverloads
lognull145     fun log(
146         tag: String,
147         level: LogLevel,
148         @CompileTimeConstant message: String,
149         exception: Throwable? = null,
150     ) = log(tag, level, { str1 = message }, { str1!! }, exception)
151 
152     /**
153      * You should call [log] instead of this method.
154      *
155      * Obtains the next [LogMessage] from the ring buffer. If the buffer is not yet at max size,
156      * grows the buffer by one.
157      *
158      * After calling [obtain], the message will now be at the end of the buffer. The caller must
159      * store any relevant data on the message and then call [commit].
160      */
161     @Synchronized
obtainnull162     override fun obtain(
163         tag: String,
164         level: LogLevel,
165         messagePrinter: MessagePrinter,
166         exception: Throwable?,
167     ): LogMessage {
168         if (!mutable) {
169             return FROZEN_MESSAGE
170         }
171         val message = buffer.advance()
172         message.reset(tag, level, System.currentTimeMillis(), messagePrinter, exception)
173         return message
174     }
175 
176     /**
177      * You should call [log] instead of this method.
178      *
179      * After acquiring a message via [obtain], call this method to signal to the buffer that you
180      * have finished filling in its data fields. The message will be echoed to logcat if necessary.
181      */
182     @Synchronized
commitnull183     override fun commit(message: LogMessage) {
184         if (!mutable) {
185             return
186         }
187         echoToDesiredEndpoints(message)
188     }
189 
190     /** Sends message to echo after determining whether to use Logcat and/or systrace. */
echoToDesiredEndpointsnull191     private fun echoToDesiredEndpoints(message: LogMessage) {
192         val includeInLogcat =
193             logcatEchoTracker.isBufferLoggable(name, message.level) ||
194                 logcatEchoTracker.isTagLoggable(message.tag, message.level)
195 
196         val includeInSystrace = systrace && Trace.isTagEnabled(Trace.TRACE_TAG_APP)
197 
198         if (includeInLogcat || includeInSystrace) {
199             val strMessage = message.messagePrinter(message)
200             if (includeInLogcat) {
201                 echoToLogcat(message, strMessage)
202             }
203             if (includeInSystrace) {
204                 echoToSystrace(message.level, message.tag, strMessage)
205             }
206         }
207     }
208 
209     /** Converts the entire buffer to a newline-delimited string */
210     @Synchronized
dumpnull211     fun dump(pw: PrintWriter, tailLength: Int) {
212         val iterationStart =
213             if (tailLength <= 0) {
214                 0
215             } else {
216                 max(0, buffer.size - tailLength)
217             }
218 
219         for (i in iterationStart until buffer.size) {
220             buffer[i].dump(pw)
221         }
222     }
223 
224     /**
225      * "Freezes" the contents of the buffer, making it immutable until [unfreeze] is called. Calls
226      * to [log], [obtain], and [commit] will not affect the buffer and will return dummy values if
227      * necessary.
228      */
229     @Synchronized
freezenull230     fun freeze() {
231         if (!frozen) {
232             log(TAG, LogLevel.DEBUG, { str1 = name }, { "$str1 frozen" })
233             frozen = true
234         }
235     }
236 
237     /** Undoes the effects of calling [freeze]. */
238     @Synchronized
unfreezenull239     fun unfreeze() {
240         if (frozen) {
241             frozen = false
242             log(TAG, LogLevel.DEBUG, { str1 = name }, { "$str1 unfrozen" })
243         }
244     }
245 
echoToSystracenull246     private fun echoToSystrace(level: LogLevel, tag: String, strMessage: String) {
247         Trace.instantForTrack(
248             Trace.TRACE_TAG_APP,
249             "UI Events",
250             "$name - ${level.shortString} $tag: $strMessage"
251         )
252     }
253 
echoToLogcatnull254     private fun echoToLogcat(message: LogMessage, strMessage: String) {
255         when (message.level) {
256             LogLevel.VERBOSE -> Log.v(message.tag, strMessage, message.exception)
257             LogLevel.DEBUG -> Log.d(message.tag, strMessage, message.exception)
258             LogLevel.INFO -> Log.i(message.tag, strMessage, message.exception)
259             LogLevel.WARNING -> Log.w(message.tag, strMessage, message.exception)
260             LogLevel.ERROR -> Log.e(message.tag, strMessage, message.exception)
261             LogLevel.WTF -> Log.wtf(message.tag, strMessage, message.exception)
262         }
263     }
264 }
265 
266 private const val TAG = "LogBuffer"
267 private val FROZEN_MESSAGE = LogMessageImpl.create()
268