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