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