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.util.Log
20 import com.android.systemui.log.dagger.LogModule
21 import java.io.PrintWriter
22 import java.text.SimpleDateFormat
23 import java.util.ArrayDeque
24 import java.util.Locale
25 
26 /**
27  * A simple ring buffer of recyclable log messages
28  *
29  * The goal of this class is to enable logging that is both extremely chatty and extremely
30  * lightweight. If done properly, logging a message will not result in any heap allocations or
31  * string generation. Messages are only converted to strings if the log is actually dumped (usually
32  * as the result of taking a bug report).
33  *
34  * You can dump the entire buffer at any time by running:
35  *
36  * ```
37  * $ adb shell dumpsys activity service com.android.systemui/.SystemUIService <bufferName>
38  * ```
39  *
40  * ...where `bufferName` is the (case-sensitive) [name] passed to the constructor.
41  *
42  * By default, only messages of WARN level or higher are echoed to logcat, but this can be adjusted
43  * locally (usually for debugging purposes).
44  *
45  * To enable logcat echoing for an entire buffer:
46  *
47  * ```
48  * $ adb shell settings put global systemui/buffer/<bufferName> <level>
49  * ```
50  *
51  * To enable logcat echoing for a specific tag:
52  *
53  * ```
54  * $ adb shell settings put global systemui/tag/<tag> <level>
55  * ```
56  *
57  * In either case, `level` can be any of `verbose`, `debug`, `info`, `warn`, `error`, `assert`, or
58  * the first letter of any of the previous.
59  *
60  * Buffers are provided by [LogModule]. Instances should be created using a [LogBufferFactory].
61  *
62  * @param name The name of this buffer
63  * @param maxLogs The maximum number of messages to keep in memory at any one time, including the
64  * unused pool. Must be >= [poolSize].
65  * @param poolSize The maximum amount that the size of the buffer is allowed to flex in response to
66  * sequential calls to [document] that aren't immediately followed by a matching call to [push].
67  */
68 class LogBuffer(
69     private val name: String,
70     private val maxLogs: Int,
71     private val poolSize: Int,
72     private val logcatEchoTracker: LogcatEchoTracker
73 ) {
74     init {
75         if (maxLogs < poolSize) {
76             throw IllegalArgumentException("maxLogs must be greater than or equal to poolSize, " +
77                     "but maxLogs=$maxLogs < $poolSize=poolSize")
78         }
79     }
80 
81     private val buffer: ArrayDeque<LogMessageImpl> = ArrayDeque()
82 
83     var frozen = false
84         private set
85 
86     /**
87      * Logs a message to the log buffer
88      *
89      * May also log the message to logcat if echoing is enabled for this buffer or tag.
90      *
91      * The actual string of the log message is not constructed until it is needed. To accomplish
92      * this, logging a message is a two-step process. First, a fresh instance  of [LogMessage] is
93      * obtained and is passed to the [initializer]. The initializer stores any relevant data on the
94      * message's fields. The message is then inserted into the buffer where it waits until it is
95      * either pushed out by newer messages or it needs to printed. If and when this latter moment
96      * occurs, the [printer] function is called on the message. It reads whatever data the
97      * initializer stored and converts it to a human-readable log message.
98      *
99      * @param tag A string of at most 23 characters, used for grouping logs into categories or
100      * subjects. If this message is echoed to logcat, this will be the tag that is used.
101      * @param level Which level to log the message at, both to the buffer and to logcat if it's
102      * echoed. In general, a module should split most of its logs into either INFO or DEBUG level.
103      * INFO level should be reserved for information that other parts of the system might care
104      * about, leaving the specifics of code's day-to-day operations to DEBUG.
105      * @param initializer A function that will be called immediately to store relevant data on the
106      * log message. The value of `this` will be the LogMessage to be initialized.
107      * @param printer A function that will be called if and when the message needs to be dumped to
108      * logcat or a bug report. It should read the data stored by the initializer and convert it to
109      * a human-readable string. The value of `this` will be the LogMessage to be printed.
110      * **IMPORTANT:** The printer should ONLY ever reference fields on the LogMessage and NEVER any
111      * variables in its enclosing scope. Otherwise, the runtime will need to allocate a new instance
112      * of the printer for each call, thwarting our attempts at avoiding any sort of allocation.
113      */
114     inline fun log(
115         tag: String,
116         level: LogLevel,
117         initializer: LogMessage.() -> Unit,
118         noinline printer: LogMessage.() -> String
119     ) {
120         if (!frozen) {
121             val message = obtain(tag, level, printer)
122             initializer(message)
123             push(message)
124         }
125     }
126 
127     /**
128      * Same as [log], but doesn't push the message to the buffer. Useful if you need to supply a
129      * "reason" for doing something (the thing you supply the reason to will presumably call [push]
130      * on that message at some point).
131      */
132     inline fun document(
133         tag: String,
134         level: LogLevel,
135         initializer: LogMessage.() -> Unit,
136         noinline printer: LogMessage.() -> String
137     ): LogMessage {
138         val message = obtain(tag, level, printer)
139         initializer(message)
140         return message
141     }
142 
143     /**
144      * Obtains an instance of [LogMessageImpl], usually from the object pool. If the pool has been
145      * exhausted, creates a new instance.
146      *
147      * In general, you should call [log] or [document] instead of this method.
148      */
149     @Synchronized
150     fun obtain(
151         tag: String,
152         level: LogLevel,
153         printer: (LogMessage) -> String
154     ): LogMessageImpl {
155         val message = when {
156             frozen -> LogMessageImpl.create()
157             buffer.size > maxLogs - poolSize -> buffer.removeFirst()
158             else -> LogMessageImpl.create()
159         }
160         message.reset(tag, level, System.currentTimeMillis(), printer)
161         return message
162     }
163 
164     /**
165      * Pushes a message into buffer, possibly evicting an older message if the buffer is full.
166      */
167     @Synchronized
168     fun push(message: LogMessage) {
169         if (frozen) {
170             return
171         }
172         if (buffer.size == maxLogs) {
173             Log.e(TAG, "LogBuffer $name has exceeded its pool size")
174             buffer.removeFirst()
175         }
176         buffer.add(message as LogMessageImpl)
177         if (logcatEchoTracker.isBufferLoggable(name, message.level) ||
178                 logcatEchoTracker.isTagLoggable(message.tag, message.level)) {
179             echoToLogcat(message)
180         }
181     }
182 
183     /** Converts the entire buffer to a newline-delimited string */
184     @Synchronized
185     fun dump(pw: PrintWriter, tailLength: Int) {
186         val start = if (tailLength <= 0) { 0 } else { buffer.size - tailLength }
187 
188         for ((i, message) in buffer.withIndex()) {
189             if (i >= start) {
190                 dumpMessage(message, pw)
191             }
192         }
193     }
194 
195     /**
196      * "Freezes" the contents of the buffer, making them immutable until [unfreeze] is called.
197      * Calls to [log], [document], [obtain], and [push] will not affect the buffer and will return
198      * dummy values if necessary.
199      */
200     @Synchronized
201     fun freeze() {
202         if (!frozen) {
203             log(TAG, LogLevel.DEBUG, { str1 = name }, { "$str1 frozen" })
204             frozen = true
205         }
206     }
207 
208     /**
209      * Undoes the effects of calling [freeze].
210      */
211     @Synchronized
212     fun unfreeze() {
213         if (frozen) {
214             log(TAG, LogLevel.DEBUG, { str1 = name }, { "$str1 unfrozen" })
215             frozen = false
216         }
217     }
218 
219     private fun dumpMessage(message: LogMessage, pw: PrintWriter) {
220         pw.print(DATE_FORMAT.format(message.timestamp))
221         pw.print(" ")
222         pw.print(message.level.shortString)
223         pw.print(" ")
224         pw.print(message.tag)
225         pw.print(": ")
226         pw.println(message.printer(message))
227     }
228 
229     private fun echoToLogcat(message: LogMessage) {
230         val strMessage = message.printer(message)
231         when (message.level) {
232             LogLevel.VERBOSE -> Log.v(message.tag, strMessage)
233             LogLevel.DEBUG -> Log.d(message.tag, strMessage)
234             LogLevel.INFO -> Log.i(message.tag, strMessage)
235             LogLevel.WARNING -> Log.w(message.tag, strMessage)
236             LogLevel.ERROR -> Log.e(message.tag, strMessage)
237             LogLevel.WTF -> Log.wtf(message.tag, strMessage)
238         }
239     }
240 }
241 
242 private const val TAG = "LogBuffer"
243 private val DATE_FORMAT = SimpleDateFormat("MM-dd HH:mm:ss.SSS", Locale.US)
244