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.internal.protolog;
18 
19 import static com.android.internal.protolog.ProtoLogFileProto.LOG;
20 import static com.android.internal.protolog.ProtoLogFileProto.MAGIC_NUMBER;
21 import static com.android.internal.protolog.ProtoLogFileProto.MAGIC_NUMBER_H;
22 import static com.android.internal.protolog.ProtoLogFileProto.MAGIC_NUMBER_L;
23 import static com.android.internal.protolog.ProtoLogFileProto.REAL_TIME_TO_ELAPSED_TIME_OFFSET_MILLIS;
24 import static com.android.internal.protolog.ProtoLogFileProto.VERSION;
25 import static com.android.internal.protolog.ProtoLogMessage.BOOLEAN_PARAMS;
26 import static com.android.internal.protolog.ProtoLogMessage.DOUBLE_PARAMS;
27 import static com.android.internal.protolog.ProtoLogMessage.ELAPSED_REALTIME_NANOS;
28 import static com.android.internal.protolog.ProtoLogMessage.MESSAGE_HASH;
29 import static com.android.internal.protolog.ProtoLogMessage.SINT64_PARAMS;
30 import static com.android.internal.protolog.ProtoLogMessage.STR_PARAMS;
31 
32 import android.annotation.Nullable;
33 import android.os.ShellCommand;
34 import android.os.SystemClock;
35 import android.text.TextUtils;
36 import android.util.Slog;
37 import android.util.proto.ProtoOutputStream;
38 
39 import com.android.internal.annotations.VisibleForTesting;
40 import com.android.internal.protolog.common.IProtoLogGroup;
41 import com.android.internal.protolog.common.LogDataType;
42 import com.android.internal.util.TraceBuffer;
43 
44 import java.io.File;
45 import java.io.IOException;
46 import java.io.PrintWriter;
47 import java.util.ArrayList;
48 import java.util.TreeMap;
49 import java.util.stream.Collectors;
50 
51 
52 /**
53  * A service for the ProtoLog logging system.
54  */
55 public class BaseProtoLogImpl {
56     protected static final TreeMap<String, IProtoLogGroup> LOG_GROUPS = new TreeMap<>();
57 
58     /**
59      * A runnable to update the cached output of {@link #isEnabled}.
60      *
61      * Must be invoked after every action that could change the result of {@link #isEnabled}, eg.
62      * starting / stopping proto log, or enabling / disabling log groups.
63      */
64     public static Runnable sCacheUpdater = () -> { };
65 
addLogGroupEnum(IProtoLogGroup[] config)66     protected static void addLogGroupEnum(IProtoLogGroup[] config) {
67         for (IProtoLogGroup group : config) {
68             LOG_GROUPS.put(group.name(), group);
69         }
70     }
71 
72     private static final String TAG = "ProtoLog";
73     private static final long MAGIC_NUMBER_VALUE = ((long) MAGIC_NUMBER_H << 32) | MAGIC_NUMBER_L;
74     static final String PROTOLOG_VERSION = "1.0.0";
75     private static final int DEFAULT_PER_CHUNK_SIZE = 0;
76 
77     private final File mLogFile;
78     private final String mViewerConfigFilename;
79     private final TraceBuffer mBuffer;
80     protected final ProtoLogViewerConfigReader mViewerConfig;
81     private final int mPerChunkSize;
82 
83     private boolean mProtoLogEnabled;
84     private boolean mProtoLogEnabledLockFree;
85     private final Object mProtoLogEnabledLock = new Object();
86 
87     @VisibleForTesting
88     public enum LogLevel {
89         DEBUG, VERBOSE, INFO, WARN, ERROR, WTF
90     }
91 
92     /**
93      * Main log method, do not call directly.
94      */
95     @VisibleForTesting
log(LogLevel level, IProtoLogGroup group, int messageHash, int paramsMask, @Nullable String messageString, Object[] args)96     public void log(LogLevel level, IProtoLogGroup group, int messageHash, int paramsMask,
97             @Nullable String messageString, Object[] args) {
98         if (group.isLogToProto()) {
99             logToProto(messageHash, paramsMask, args);
100         }
101         if (group.isLogToLogcat()) {
102             logToLogcat(group.getTag(), level, messageHash, messageString, args);
103         }
104     }
105 
logToLogcat(String tag, LogLevel level, int messageHash, @Nullable String messageString, Object[] args)106     private void logToLogcat(String tag, LogLevel level, int messageHash,
107             @Nullable String messageString, Object[] args) {
108         String message = null;
109         if (messageString == null) {
110             messageString = mViewerConfig.getViewerString(messageHash);
111         }
112         if (messageString != null) {
113             if (args != null) {
114                 try {
115                     message = TextUtils.formatSimple(messageString, args);
116                 } catch (Exception ex) {
117                     Slog.w(TAG, "Invalid ProtoLog format string.", ex);
118                 }
119             } else {
120                 message = messageString;
121             }
122         }
123         if (message == null) {
124             StringBuilder builder = new StringBuilder("UNKNOWN MESSAGE (" + messageHash + ")");
125             for (Object o : args) {
126                 builder.append(" ").append(o);
127             }
128             message = builder.toString();
129         }
130         passToLogcat(tag, level, message);
131     }
132 
133     /**
134      * SLog wrapper.
135      */
136     @VisibleForTesting
passToLogcat(String tag, LogLevel level, String message)137     public void passToLogcat(String tag, LogLevel level, String message) {
138         switch (level) {
139             case DEBUG:
140                 Slog.d(tag, message);
141                 break;
142             case VERBOSE:
143                 Slog.v(tag, message);
144                 break;
145             case INFO:
146                 Slog.i(tag, message);
147                 break;
148             case WARN:
149                 Slog.w(tag, message);
150                 break;
151             case ERROR:
152                 Slog.e(tag, message);
153                 break;
154             case WTF:
155                 Slog.wtf(tag, message);
156                 break;
157         }
158     }
159 
logToProto(int messageHash, int paramsMask, Object[] args)160     private void logToProto(int messageHash, int paramsMask, Object[] args) {
161         if (!isProtoEnabled()) {
162             return;
163         }
164         try {
165             ProtoOutputStream os = new ProtoOutputStream(mPerChunkSize);
166             long token = os.start(LOG);
167             os.write(MESSAGE_HASH, messageHash);
168             os.write(ELAPSED_REALTIME_NANOS, SystemClock.elapsedRealtimeNanos());
169 
170             if (args != null) {
171                 int argIndex = 0;
172                 ArrayList<Long> longParams = new ArrayList<>();
173                 ArrayList<Double> doubleParams = new ArrayList<>();
174                 ArrayList<Boolean> booleanParams = new ArrayList<>();
175                 for (Object o : args) {
176                     int type = LogDataType.bitmaskToLogDataType(paramsMask, argIndex);
177                     try {
178                         switch (type) {
179                             case LogDataType.STRING:
180                                 os.write(STR_PARAMS, o.toString());
181                                 break;
182                             case LogDataType.LONG:
183                                 longParams.add(((Number) o).longValue());
184                                 break;
185                             case LogDataType.DOUBLE:
186                                 doubleParams.add(((Number) o).doubleValue());
187                                 break;
188                             case LogDataType.BOOLEAN:
189                                 booleanParams.add((boolean) o);
190                                 break;
191                         }
192                     } catch (ClassCastException ex) {
193                         // Should not happen unless there is an error in the ProtoLogTool.
194                         os.write(STR_PARAMS, "(INVALID PARAMS_MASK) " + o.toString());
195                         Slog.e(TAG, "Invalid ProtoLog paramsMask", ex);
196                     }
197                     argIndex++;
198                 }
199                 if (longParams.size() > 0) {
200                     os.writePackedSInt64(SINT64_PARAMS,
201                             longParams.stream().mapToLong(i -> i).toArray());
202                 }
203                 if (doubleParams.size() > 0) {
204                     os.writePackedDouble(DOUBLE_PARAMS,
205                             doubleParams.stream().mapToDouble(i -> i).toArray());
206                 }
207                 if (booleanParams.size() > 0) {
208                     boolean[] arr = new boolean[booleanParams.size()];
209                     for (int i = 0; i < booleanParams.size(); i++) {
210                         arr[i] = booleanParams.get(i);
211                     }
212                     os.writePackedBool(BOOLEAN_PARAMS, arr);
213                 }
214             }
215             os.end(token);
216             mBuffer.add(os);
217         } catch (Exception e) {
218             Slog.e(TAG, "Exception while logging to proto", e);
219         }
220     }
221 
BaseProtoLogImpl(File file, String viewerConfigFilename, int bufferCapacity, ProtoLogViewerConfigReader viewerConfig)222     public BaseProtoLogImpl(File file, String viewerConfigFilename, int bufferCapacity,
223             ProtoLogViewerConfigReader viewerConfig) {
224         this(file, viewerConfigFilename, bufferCapacity, viewerConfig, DEFAULT_PER_CHUNK_SIZE);
225     }
226 
BaseProtoLogImpl(File file, String viewerConfigFilename, int bufferCapacity, ProtoLogViewerConfigReader viewerConfig, int perChunkSize)227     public BaseProtoLogImpl(File file, String viewerConfigFilename, int bufferCapacity,
228             ProtoLogViewerConfigReader viewerConfig, int perChunkSize) {
229         mLogFile = file;
230         mBuffer = new TraceBuffer(bufferCapacity);
231         mViewerConfigFilename = viewerConfigFilename;
232         mViewerConfig = viewerConfig;
233         mPerChunkSize = perChunkSize;
234     }
235 
236     /**
237      * Starts the logging a circular proto buffer.
238      *
239      * @param pw Print writer
240      */
startProtoLog(@ullable PrintWriter pw)241     public void startProtoLog(@Nullable PrintWriter pw) {
242         if (isProtoEnabled()) {
243             return;
244         }
245         synchronized (mProtoLogEnabledLock) {
246             logAndPrintln(pw, "Start logging to " + mLogFile + ".");
247             mBuffer.resetBuffer();
248             mProtoLogEnabled = true;
249             mProtoLogEnabledLockFree = true;
250         }
251         sCacheUpdater.run();
252     }
253 
254     /**
255      * Stops logging to proto.
256      *
257      * @param pw          Print writer
258      * @param writeToFile If the current buffer should be written to disk or not
259      */
stopProtoLog(@ullable PrintWriter pw, boolean writeToFile)260     public void stopProtoLog(@Nullable PrintWriter pw, boolean writeToFile) {
261         if (!isProtoEnabled()) {
262             return;
263         }
264         synchronized (mProtoLogEnabledLock) {
265             logAndPrintln(pw, "Stop logging to " + mLogFile + ". Waiting for log to flush.");
266             mProtoLogEnabled = mProtoLogEnabledLockFree = false;
267             if (writeToFile) {
268                 writeProtoLogToFileLocked();
269                 logAndPrintln(pw, "Log written to " + mLogFile + ".");
270                 mBuffer.resetBuffer();
271             }
272             if (mProtoLogEnabled) {
273                 logAndPrintln(pw, "ERROR: logging was re-enabled while waiting for flush.");
274                 throw new IllegalStateException("logging enabled while waiting for flush.");
275             }
276         }
277         sCacheUpdater.run();
278     }
279 
280     /**
281      * Returns {@code true} iff logging to proto is enabled.
282      */
isProtoEnabled()283     public boolean isProtoEnabled() {
284         return mProtoLogEnabledLockFree;
285     }
286 
setLogging(boolean setTextLogging, boolean value, PrintWriter pw, String... groups)287     protected int setLogging(boolean setTextLogging, boolean value, PrintWriter pw,
288             String... groups) {
289         for (int i = 0; i < groups.length; i++) {
290             String group = groups[i];
291             IProtoLogGroup g = LOG_GROUPS.get(group);
292             if (g != null) {
293                 if (setTextLogging) {
294                     g.setLogToLogcat(value);
295                 } else {
296                     g.setLogToProto(value);
297                 }
298             } else {
299                 logAndPrintln(pw, "No IProtoLogGroup named " + group);
300                 return -1;
301             }
302         }
303         sCacheUpdater.run();
304         return 0;
305     }
306 
unknownCommand(PrintWriter pw)307     private int unknownCommand(PrintWriter pw) {
308         pw.println("Unknown command");
309         pw.println("Window manager logging options:");
310         pw.println("  start: Start proto logging");
311         pw.println("  stop: Stop proto logging");
312         pw.println("  enable [group...]: Enable proto logging for given groups");
313         pw.println("  disable [group...]: Disable proto logging for given groups");
314         pw.println("  enable-text [group...]: Enable logcat logging for given groups");
315         pw.println("  disable-text [group...]: Disable logcat logging for given groups");
316         return -1;
317     }
318 
319     /**
320      * Responds to a shell command.
321      */
onShellCommand(ShellCommand shell)322     public int onShellCommand(ShellCommand shell) {
323         PrintWriter pw = shell.getOutPrintWriter();
324         String cmd = shell.getNextArg();
325         if (cmd == null) {
326             return unknownCommand(pw);
327         }
328         ArrayList<String> args = new ArrayList<>();
329         String arg;
330         while ((arg = shell.getNextArg()) != null) {
331             args.add(arg);
332         }
333         String[] groups = args.toArray(new String[args.size()]);
334         switch (cmd) {
335             case "start":
336                 startProtoLog(pw);
337                 return 0;
338             case "stop":
339                 stopProtoLog(pw, true);
340                 return 0;
341             case "status":
342                 logAndPrintln(pw, getStatus());
343                 return 0;
344             case "enable":
345                 return setLogging(false, true, pw, groups);
346             case "enable-text":
347                 mViewerConfig.loadViewerConfig(pw, mViewerConfigFilename);
348                 return setLogging(true, true, pw, groups);
349             case "disable":
350                 return setLogging(false, false, pw, groups);
351             case "disable-text":
352                 return setLogging(true, false, pw, groups);
353             default:
354                 return unknownCommand(pw);
355         }
356     }
357 
358     /**
359      * Returns a human-readable ProtoLog status text.
360      */
getStatus()361     public String getStatus() {
362         return "ProtoLog status: "
363                 + ((isProtoEnabled()) ? "Enabled" : "Disabled")
364                 + "\nEnabled log groups: \n  Proto: "
365                 + LOG_GROUPS.values().stream().filter(
366                     it -> it.isEnabled() && it.isLogToProto())
367                 .map(IProtoLogGroup::name).collect(Collectors.joining(" "))
368                 + "\n  Logcat: "
369                 + LOG_GROUPS.values().stream().filter(
370                     it -> it.isEnabled() && it.isLogToLogcat())
371                 .map(IProtoLogGroup::name).collect(Collectors.joining(" "))
372                 + "\nLogging definitions loaded: " + mViewerConfig.knownViewerStringsNumber();
373     }
374 
writeProtoLogToFileLocked()375     private void writeProtoLogToFileLocked() {
376         try {
377             long offset =
378                     (System.currentTimeMillis() - (SystemClock.elapsedRealtimeNanos() / 1000000));
379             ProtoOutputStream proto = new ProtoOutputStream(mPerChunkSize);
380             proto.write(MAGIC_NUMBER, MAGIC_NUMBER_VALUE);
381             proto.write(VERSION, PROTOLOG_VERSION);
382             proto.write(REAL_TIME_TO_ELAPSED_TIME_OFFSET_MILLIS, offset);
383             mBuffer.writeTraceToFile(mLogFile, proto);
384         } catch (IOException e) {
385             Slog.e(TAG, "Unable to write buffer to file", e);
386         }
387     }
388 
logAndPrintln(@ullable PrintWriter pw, String msg)389     static void logAndPrintln(@Nullable PrintWriter pw, String msg) {
390         Slog.i(TAG, msg);
391         if (pw != null) {
392             pw.println(msg);
393             pw.flush();
394         }
395     }
396 }
397 
398