diff --git a/core/java/android/tracing/perfetto/DataSource.java b/core/java/android/tracing/perfetto/DataSource.java index 4e08aeef88e6859899de43744c74cfb536c23a7a..d0c719b86ac9609cfaa2a8f48b415948282b8bd1 100644 --- a/core/java/android/tracing/perfetto/DataSource.java +++ b/core/java/android/tracing/perfetto/DataSource.java @@ -18,6 +18,8 @@ package android.tracing.perfetto; import android.util.proto.ProtoInputStream; +import com.android.internal.annotations.VisibleForTesting; + /** * Templated base class meant to be derived by embedders to create a custom data * source. @@ -87,7 +89,8 @@ public abstract class DataSource<DataSourceInstanceType extends DataSourceInstan * * NOTE: Should only be called from native side. */ - protected TlsStateType createTlsState(CreateTlsStateArgs<DataSourceInstanceType> args) { + @VisibleForTesting + public TlsStateType createTlsState(CreateTlsStateArgs<DataSourceInstanceType> args) { return null; } diff --git a/core/java/android/tracing/perfetto/DataSourceInstance.java b/core/java/android/tracing/perfetto/DataSourceInstance.java index 3710b4df33e8bb7c0f22e420f9ec93a7f43f8ea1..904cf55e014ac3cd2c3c58f27398fe4a424105b9 100644 --- a/core/java/android/tracing/perfetto/DataSourceInstance.java +++ b/core/java/android/tracing/perfetto/DataSourceInstance.java @@ -16,6 +16,8 @@ package android.tracing.perfetto; +import com.android.internal.annotations.VisibleForTesting; + /** * @hide */ @@ -66,7 +68,8 @@ public abstract class DataSourceInstance implements AutoCloseable { * Only required to be called when instance was retrieved with * `DataSource#getDataSourceInstanceLocked`. */ - public final void release() { + @VisibleForTesting + public void release() { mDataSource.releaseDataSourceInstance(mInstanceIndex); } diff --git a/core/java/com/android/internal/protolog/PerfettoProtoLogImpl.java b/core/java/com/android/internal/protolog/PerfettoProtoLogImpl.java new file mode 100644 index 0000000000000000000000000000000000000000..53062d837cfa55b26cbada04627f0d8730d7a521 --- /dev/null +++ b/core/java/com/android/internal/protolog/PerfettoProtoLogImpl.java @@ -0,0 +1,559 @@ +/* + * Copyright (C) 2024 The Android Open Source Project + * + * Licensed under the Apache License, Version 2.0 (the "License"); + * you may not use this file except in compliance with the License. + * You may obtain a copy of the License at + * + * http://www.apache.org/licenses/LICENSE-2.0 + * + * Unless required by applicable law or agreed to in writing, software + * distributed under the License is distributed on an "AS IS" BASIS, + * WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied. + * See the License for the specific language governing permissions and + * limitations under the License. + */ + +package com.android.internal.protolog; + +import static perfetto.protos.PerfettoTrace.InternedData.PROTOLOG_STACKTRACE; +import static perfetto.protos.PerfettoTrace.InternedData.PROTOLOG_STRING_ARGS; +import static perfetto.protos.PerfettoTrace.InternedString.IID; +import static perfetto.protos.PerfettoTrace.InternedString.STR; +import static perfetto.protos.PerfettoTrace.ProtoLogMessage.BOOLEAN_PARAMS; +import static perfetto.protos.PerfettoTrace.ProtoLogMessage.DOUBLE_PARAMS; +import static perfetto.protos.PerfettoTrace.ProtoLogMessage.STACKTRACE_IID; +import static perfetto.protos.PerfettoTrace.ProtoLogMessage.MESSAGE_ID; +import static perfetto.protos.PerfettoTrace.ProtoLogMessage.SINT64_PARAMS; +import static perfetto.protos.PerfettoTrace.ProtoLogMessage.STR_PARAM_IIDS; +import static perfetto.protos.PerfettoTrace.ProtoLogViewerConfig.GROUPS; +import static perfetto.protos.PerfettoTrace.ProtoLogViewerConfig.Group.ID; +import static perfetto.protos.PerfettoTrace.ProtoLogViewerConfig.Group.NAME; +import static perfetto.protos.PerfettoTrace.ProtoLogViewerConfig.Group.TAG; +import static perfetto.protos.PerfettoTrace.ProtoLogViewerConfig.MESSAGES; +import static perfetto.protos.PerfettoTrace.ProtoLogViewerConfig.MessageData.GROUP_ID; +import static perfetto.protos.PerfettoTrace.ProtoLogViewerConfig.MessageData.LEVEL; +import static perfetto.protos.PerfettoTrace.ProtoLogViewerConfig.MessageData.MESSAGE; +import static perfetto.protos.PerfettoTrace.TracePacket.INTERNED_DATA; +import static perfetto.protos.PerfettoTrace.TracePacket.PROTOLOG_MESSAGE; +import static perfetto.protos.PerfettoTrace.TracePacket.PROTOLOG_VIEWER_CONFIG; +import static perfetto.protos.PerfettoTrace.TracePacket.SEQUENCE_FLAGS; +import static perfetto.protos.PerfettoTrace.TracePacket.SEQ_INCREMENTAL_STATE_CLEARED; +import static perfetto.protos.PerfettoTrace.TracePacket.SEQ_NEEDS_INCREMENTAL_STATE; +import static perfetto.protos.PerfettoTrace.TracePacket.TIMESTAMP; + +import android.annotation.Nullable; +import android.os.ShellCommand; +import android.os.SystemClock; +import android.os.Trace; +import android.text.TextUtils; +import android.tracing.perfetto.DataSourceParams; +import android.tracing.perfetto.InitArguments; +import android.tracing.perfetto.Producer; +import android.tracing.perfetto.TracingContext; +import android.util.LongArray; +import android.util.Slog; +import android.util.proto.ProtoInputStream; +import android.util.proto.ProtoOutputStream; + +import com.android.internal.annotations.VisibleForTesting; +import com.android.internal.protolog.common.ILogger; +import com.android.internal.protolog.common.IProtoLog; +import com.android.internal.protolog.common.IProtoLogGroup; +import com.android.internal.protolog.common.LogDataType; +import com.android.internal.protolog.common.LogLevel; + +import java.io.FileInputStream; +import java.io.FileNotFoundException; +import java.io.PrintWriter; +import java.io.StringWriter; +import java.util.ArrayList; +import java.util.Map; +import java.util.TreeMap; +import java.util.concurrent.atomic.AtomicInteger; + +import perfetto.protos.PerfettoTrace.ProtoLogViewerConfig.MessageData; + +/** + * A service for the ProtoLog logging system. + */ +public class PerfettoProtoLogImpl implements IProtoLog { + private final TreeMap<String, IProtoLogGroup> mLogGroups = new TreeMap<>(); + private static final String LOG_TAG = "ProtoLog"; + private final AtomicInteger mTracingInstances = new AtomicInteger(); + + private final ProtoLogDataSource mDataSource = new ProtoLogDataSource( + this.mTracingInstances::incrementAndGet, + this::dumpTransitionTraceConfig, + this.mTracingInstances::decrementAndGet + ); + private final ProtoLogViewerConfigReader mViewerConfigReader; + private final ViewerConfigInputStreamProvider mViewerConfigInputStreamProvider; + + public PerfettoProtoLogImpl(String viewerConfigFilePath) { + this(() -> { + try { + return new ProtoInputStream(new FileInputStream(viewerConfigFilePath)); + } catch (FileNotFoundException e) { + Slog.w(LOG_TAG, "Failed to load viewer config file " + viewerConfigFilePath, e); + return null; + } + }); + } + + public PerfettoProtoLogImpl(ViewerConfigInputStreamProvider viewerConfigInputStreamProvider) { + this(viewerConfigInputStreamProvider, + new ProtoLogViewerConfigReader(viewerConfigInputStreamProvider)); + } + + @VisibleForTesting + public PerfettoProtoLogImpl( + ViewerConfigInputStreamProvider viewerConfigInputStreamProvider, + ProtoLogViewerConfigReader viewerConfigReader + ) { + Producer.init(InitArguments.DEFAULTS); + mDataSource.register(DataSourceParams.DEFAULTS); + this.mViewerConfigInputStreamProvider = viewerConfigInputStreamProvider; + this.mViewerConfigReader = viewerConfigReader; + } + + /** + * Main log method, do not call directly. + */ + @VisibleForTesting + @Override + public void log(LogLevel level, IProtoLogGroup group, long messageHash, int paramsMask, + @Nullable String messageString, Object[] args) { + Trace.traceBegin(Trace.TRACE_TAG_WINDOW_MANAGER, "log"); + + long tsNanos = SystemClock.elapsedRealtimeNanos(); + try { + logToProto(level, group.name(), messageHash, paramsMask, args, tsNanos); + if (group.isLogToLogcat()) { + logToLogcat(group.getTag(), level, messageHash, messageString, args); + } + } finally { + Trace.traceEnd(Trace.TRACE_TAG_WINDOW_MANAGER); + } + } + + private void dumpTransitionTraceConfig() { + ProtoInputStream pis = mViewerConfigInputStreamProvider.getInputStream(); + + if (pis == null) { + Slog.w(LOG_TAG, "Failed to get viewer input stream."); + return; + } + + mDataSource.trace(ctx -> { + final ProtoOutputStream os = ctx.newTracePacket(); + + os.write(TIMESTAMP, SystemClock.elapsedRealtimeNanos()); + + final long outProtologViewerConfigToken = os.start(PROTOLOG_VIEWER_CONFIG); + while (pis.nextField() != ProtoInputStream.NO_MORE_FIELDS) { + if (pis.getFieldNumber() == (int) MESSAGES) { + final long inMessageToken = pis.start(MESSAGES); + final long outMessagesToken = os.start(MESSAGES); + + while (pis.nextField() != ProtoInputStream.NO_MORE_FIELDS) { + switch (pis.getFieldNumber()) { + case (int) MessageData.MESSAGE_ID: + os.write(MessageData.MESSAGE_ID, + pis.readLong(MessageData.MESSAGE_ID)); + break; + case (int) MESSAGE: + os.write(MESSAGE, pis.readString(MESSAGE)); + break; + case (int) LEVEL: + os.write(LEVEL, pis.readInt(LEVEL)); + break; + case (int) GROUP_ID: + os.write(GROUP_ID, pis.readInt(GROUP_ID)); + break; + default: + throw new RuntimeException( + "Unexpected field id " + pis.getFieldNumber()); + } + } + + pis.end(inMessageToken); + os.end(outMessagesToken); + } + + if (pis.getFieldNumber() == (int) GROUPS) { + final long inGroupToken = pis.start(GROUPS); + final long outGroupToken = os.start(GROUPS); + + while (pis.nextField() != ProtoInputStream.NO_MORE_FIELDS) { + switch (pis.getFieldNumber()) { + case (int) ID: + int id = pis.readInt(ID); + os.write(ID, id); + break; + case (int) NAME: + String name = pis.readString(NAME); + os.write(NAME, name); + break; + case (int) TAG: + String tag = pis.readString(TAG); + os.write(TAG, tag); + break; + default: + throw new RuntimeException( + "Unexpected field id " + pis.getFieldNumber()); + } + } + + pis.end(inGroupToken); + os.end(outGroupToken); + } + } + + os.end(outProtologViewerConfigToken); + + ctx.flush(); + }); + + mDataSource.flush(); + } + + private void logToLogcat(String tag, LogLevel level, long messageHash, + @Nullable String messageString, Object[] args) { + Trace.traceBegin(Trace.TRACE_TAG_WINDOW_MANAGER, "logToLogcat"); + try { + doLogToLogcat(tag, level, messageHash, messageString, args); + } finally { + Trace.traceEnd(Trace.TRACE_TAG_WINDOW_MANAGER); + } + } + + private void doLogToLogcat(String tag, LogLevel level, long messageHash, + @androidx.annotation.Nullable String messageString, Object[] args) { + String message = null; + if (messageString == null) { + messageString = mViewerConfigReader.getViewerString(messageHash); + } + if (messageString != null) { + if (args != null) { + try { + message = TextUtils.formatSimple(messageString, args); + } catch (Exception ex) { + Slog.w(LOG_TAG, "Invalid ProtoLog format string.", ex); + } + } else { + message = messageString; + } + } + if (message == null) { + StringBuilder builder = new StringBuilder("UNKNOWN MESSAGE (" + messageHash + ")"); + for (Object o : args) { + builder.append(" ").append(o); + } + message = builder.toString(); + } + passToLogcat(tag, level, message); + } + + /** + * SLog wrapper. + */ + @VisibleForTesting + public void passToLogcat(String tag, LogLevel level, String message) { + switch (level) { + case DEBUG: + Slog.d(tag, message); + break; + case VERBOSE: + Slog.v(tag, message); + break; + case INFO: + Slog.i(tag, message); + break; + case WARN: + Slog.w(tag, message); + break; + case ERROR: + Slog.e(tag, message); + break; + case WTF: + Slog.wtf(tag, message); + break; + } + } + + private void logToProto(LogLevel level, String groupName, long messageHash, int paramsMask, + Object[] args, long tsNanos) { + if (!isProtoEnabled()) { + return; + } + + Trace.traceBegin(Trace.TRACE_TAG_WINDOW_MANAGER, "logToProto"); + try { + doLogToProto(level, groupName, messageHash, paramsMask, args, tsNanos); + } finally { + Trace.traceEnd(Trace.TRACE_TAG_WINDOW_MANAGER); + } + } + + private void doLogToProto(LogLevel level, String groupName, long messageHash, int paramsMask, + Object[] args, long tsNanos) { + mDataSource.trace(ctx -> { + final ProtoLogDataSource.TlsState tlsState = ctx.getCustomTlsState(); + final LogLevel logFrom = tlsState.getLogFromLevel(groupName); + + if (level.ordinal() < logFrom.ordinal()) { + return; + } + + if (args != null) { + // Intern all string params before creating the trace packet for the proto + // message so that the interned strings appear before in the trace to make the + // trace processing easier. + int argIndex = 0; + for (Object o : args) { + int type = LogDataType.bitmaskToLogDataType(paramsMask, argIndex); + if (type == LogDataType.STRING) { + internStringArg(ctx, o.toString()); + } + argIndex++; + } + } + + int internedStacktrace = 0; + if (tlsState.getShouldCollectStacktrace(groupName)) { + // Intern stackstraces before creating the trace packet for the proto message so + // that the interned stacktrace strings appear before in the trace to make the + // trace processing easier. + String stacktrace = collectStackTrace(); + internedStacktrace = internStacktraceString(ctx, stacktrace); + } + + final ProtoOutputStream os = ctx.newTracePacket(); + os.write(TIMESTAMP, tsNanos); + long token = os.start(PROTOLOG_MESSAGE); + os.write(MESSAGE_ID, messageHash); + + boolean needsIncrementalState = false; + + if (args != null) { + + int argIndex = 0; + LongArray longParams = new LongArray(); + ArrayList<Double> doubleParams = new ArrayList<>(); + ArrayList<Boolean> booleanParams = new ArrayList<>(); + for (Object o : args) { + int type = LogDataType.bitmaskToLogDataType(paramsMask, argIndex); + try { + switch (type) { + case LogDataType.STRING: + final int internedStringId = internStringArg(ctx, o.toString()); + os.write(STR_PARAM_IIDS, internedStringId); + needsIncrementalState = true; + break; + case LogDataType.LONG: + longParams.add(((Number) o).longValue()); + break; + case LogDataType.DOUBLE: + doubleParams.add(((Number) o).doubleValue()); + break; + case LogDataType.BOOLEAN: + booleanParams.add((boolean) o); + break; + } + } catch (ClassCastException ex) { + Slog.e(LOG_TAG, "Invalid ProtoLog paramsMask", ex); + } + argIndex++; + } + + for (int i = 0; i < longParams.size(); ++i) { + os.write(SINT64_PARAMS, longParams.get(i)); + } + doubleParams.forEach(it -> os.write(DOUBLE_PARAMS, it)); + // Converting booleans to int because Perfetto doesn't yet support repeated + // booleans, so we use a repeated integers instead (b/313651412). + booleanParams.forEach(it -> os.write(BOOLEAN_PARAMS, it ? 1 : 0)); + } + + if (tlsState.getShouldCollectStacktrace(groupName)) { + os.write(STACKTRACE_IID, internedStacktrace); + } + + os.end(token); + + if (needsIncrementalState) { + os.write(SEQUENCE_FLAGS, SEQ_NEEDS_INCREMENTAL_STATE); + } + + }); + } + + private static final int STACK_SIZE_TO_PROTO_LOG_ENTRY_CALL = 12; + + private String collectStackTrace() { + StackTraceElement[] stackTrace = Thread.currentThread().getStackTrace(); + StringWriter sw = new StringWriter(); + try (PrintWriter pw = new PrintWriter(sw)) { + for (int i = STACK_SIZE_TO_PROTO_LOG_ENTRY_CALL; i < stackTrace.length; ++i) { + pw.println("\tat " + stackTrace[i]); + } + } + + return sw.toString(); + } + + private int internStacktraceString(TracingContext<ProtoLogDataSource.Instance, + ProtoLogDataSource.TlsState, + ProtoLogDataSource.IncrementalState> ctx, + String stacktrace) { + final ProtoLogDataSource.IncrementalState incrementalState = ctx.getIncrementalState(); + return internString(ctx, incrementalState.stacktraceInterningMap, + PROTOLOG_STACKTRACE, stacktrace); + } + + private int internStringArg( + TracingContext<ProtoLogDataSource.Instance, + ProtoLogDataSource.TlsState, + ProtoLogDataSource.IncrementalState> ctx, + String string + ) { + final ProtoLogDataSource.IncrementalState incrementalState = ctx.getIncrementalState(); + return internString(ctx, incrementalState.argumentInterningMap, + PROTOLOG_STRING_ARGS, string); + } + + private int internString( + TracingContext<ProtoLogDataSource.Instance, + ProtoLogDataSource.TlsState, + ProtoLogDataSource.IncrementalState> ctx, + Map<String, Integer> internMap, + long fieldId, + String string + ) { + final ProtoLogDataSource.IncrementalState incrementalState = ctx.getIncrementalState(); + + if (!incrementalState.clearReported) { + final ProtoOutputStream os = ctx.newTracePacket(); + os.write(SEQUENCE_FLAGS, SEQ_INCREMENTAL_STATE_CLEARED); + incrementalState.clearReported = true; + } + + if (!internMap.containsKey(string)) { + final int internedIndex = internMap.size() + 1; + internMap.put(string, internedIndex); + + final ProtoOutputStream os = ctx.newTracePacket(); + final long token = os.start(INTERNED_DATA); + final long innerToken = os.start(fieldId); + os.write(IID, internedIndex); + os.write(STR, string.getBytes()); + os.end(innerToken); + os.end(token); + } + + return internMap.get(string); + } + + /** + * Responds to a shell command. + */ + public int onShellCommand(ShellCommand shell) { + PrintWriter pw = shell.getOutPrintWriter(); + String cmd = shell.getNextArg(); + if (cmd == null) { + return unknownCommand(pw); + } + ArrayList<String> args = new ArrayList<>(); + String arg; + while ((arg = shell.getNextArg()) != null) { + args.add(arg); + } + final ILogger logger = (msg) -> logAndPrintln(pw, msg); + String[] groups = args.toArray(new String[args.size()]); + switch (cmd) { + case "enable-text": + return this.startLoggingToLogcat(groups, logger); + case "disable-text": + return this.stopLoggingToLogcat(groups, logger); + default: + return unknownCommand(pw); + } + } + + private int unknownCommand(PrintWriter pw) { + pw.println("Unknown command"); + pw.println("Window manager logging options:"); + pw.println(" enable-text [group...]: Enable logcat logging for given groups"); + pw.println(" disable-text [group...]: Disable logcat logging for given groups"); + return -1; + } + + /** + * Returns {@code true} iff logging to proto is enabled. + */ + public boolean isProtoEnabled() { + return mTracingInstances.get() > 0; + } + + /** + * Start text logging + * @param groups Groups to start text logging for + * @param logger A logger to write status updates to + * @return status code + */ + public int startLoggingToLogcat(String[] groups, ILogger logger) { + mViewerConfigReader.loadViewerConfig(logger); + return setTextLogging(true, logger, groups); + } + + /** + * Stop text logging + * @param groups Groups to start text logging for + * @param logger A logger to write status updates to + * @return status code + */ + public int stopLoggingToLogcat(String[] groups, ILogger logger) { + mViewerConfigReader.unloadViewerConfig(); + return setTextLogging(false, logger, groups); + } + + /** + * Start logging the stack trace of the when the log message happened for target groups + * @return status code + */ + public int startLoggingStackTrace(String[] groups, ILogger logger) { + return -1; + } + + /** + * Stop logging the stack trace of the when the log message happened for target groups + * @return status code + */ + public int stopLoggingStackTrace() { + return -1; + } + + private int setTextLogging(boolean value, ILogger logger, String... groups) { + for (int i = 0; i < groups.length; i++) { + String group = groups[i]; + IProtoLogGroup g = mLogGroups.get(group); + if (g != null) { + g.setLogToLogcat(value); + } else { + logger.log("No IProtoLogGroup named " + group); + return -1; + } + } + return 0; + } + + static void logAndPrintln(@Nullable PrintWriter pw, String msg) { + Slog.i(LOG_TAG, msg); + if (pw != null) { + pw.println(msg); + pw.flush(); + } + } +} + diff --git a/core/java/com/android/internal/protolog/ProtoLogDataSource.java b/core/java/com/android/internal/protolog/ProtoLogDataSource.java new file mode 100644 index 0000000000000000000000000000000000000000..a8ff75d6595e60d4931df31aa8366fe05bbb9c73 --- /dev/null +++ b/core/java/com/android/internal/protolog/ProtoLogDataSource.java @@ -0,0 +1,294 @@ +/* + * Copyright (C) 2023 The Android Open Source Project + * + * Licensed under the Apache License, Version 2.0 (the "License"); + * you may not use this file except in compliance with the License. + * You may obtain a copy of the License at + * + * http://www.apache.org/licenses/LICENSE-2.0 + * + * Unless required by applicable law or agreed to in writing, software + * distributed under the License is distributed on an "AS IS" BASIS, + * WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied. + * See the License for the specific language governing permissions and + * limitations under the License. + */ + +package com.android.internal.protolog; + +import static perfetto.protos.PerfettoTrace.DataSourceConfig.PROTOLOG_CONFIG; +import static perfetto.protos.PerfettoTrace.ProtoLogConfig.GROUP_OVERRIDES; +import static perfetto.protos.PerfettoTrace.ProtoLogConfig.TRACING_MODE; +import static perfetto.protos.PerfettoTrace.ProtoLogGroup.COLLECT_STACKTRACE; +import static perfetto.protos.PerfettoTrace.ProtoLogGroup.LOG_FROM; +import static perfetto.protos.PerfettoTrace.ProtoLogGroup.GROUP_NAME; + +import android.tracing.perfetto.CreateIncrementalStateArgs; +import android.tracing.perfetto.CreateTlsStateArgs; +import android.tracing.perfetto.DataSource; +import android.tracing.perfetto.DataSourceInstance; +import android.tracing.perfetto.FlushCallbackArguments; +import android.tracing.perfetto.StartCallbackArguments; +import android.tracing.perfetto.StopCallbackArguments; +import android.util.proto.ProtoInputStream; +import android.util.proto.WireTypeMismatchException; + +import com.android.internal.protolog.common.LogLevel; + +import java.io.IOException; +import java.util.HashMap; +import java.util.Map; + +import perfetto.protos.PerfettoTrace; + +public class ProtoLogDataSource extends DataSource<ProtoLogDataSource.Instance, + ProtoLogDataSource.TlsState, + ProtoLogDataSource.IncrementalState> { + + private final Runnable mOnStart; + private final Runnable mOnFlush; + private final Runnable mOnStop; + + public ProtoLogDataSource(Runnable onStart, Runnable onFlush, Runnable onStop) { + super("android.protolog"); + this.mOnStart = onStart; + this.mOnFlush = onFlush; + this.mOnStop = onStop; + } + + @Override + public Instance createInstance(ProtoInputStream configStream, int instanceIndex) { + ProtoLogConfig config = null; + + try { + while (configStream.nextField() != ProtoInputStream.NO_MORE_FIELDS) { + try { + if (configStream.getFieldNumber() == (int) PROTOLOG_CONFIG) { + if (config != null) { + throw new RuntimeException("ProtoLog config already set in loop"); + } + config = readProtoLogConfig(configStream); + } + } catch (WireTypeMismatchException e) { + throw new RuntimeException("Failed to parse ProtoLog DataSource config", e); + } + } + } catch (IOException e) { + throw new RuntimeException("Failed to read ProtoLog DataSource config", e); + } + + if (config == null) { + // No config found + config = ProtoLogConfig.DEFAULT; + } + + return new Instance( + this, instanceIndex, config, mOnStart, mOnFlush, mOnStop); + } + + @Override + public TlsState createTlsState(CreateTlsStateArgs<Instance> args) { + try (Instance dsInstance = args.getDataSourceInstanceLocked()) { + if (dsInstance == null) { + // Datasource instance has been removed + return new TlsState(ProtoLogConfig.DEFAULT); + } + return new TlsState(dsInstance.mConfig); + } + } + + @Override + public IncrementalState createIncrementalState(CreateIncrementalStateArgs<Instance> args) { + return new IncrementalState(); + } + + public static class TlsState { + private final ProtoLogConfig mConfig; + + private TlsState(ProtoLogConfig config) { + this.mConfig = config; + } + + /** + * Get the log from level for a group. + * @param groupTag The tag of the group to get the log from level. + * @return The lowest LogLevel (inclusive) to log message from. + */ + public LogLevel getLogFromLevel(String groupTag) { + return getConfigFor(groupTag).logFrom; + } + + /** + * Get if the stacktrace for the log message should be collected for this group. + * @param groupTag The tag of the group to get whether or not a stacktrace was requested. + * @return True iff a stacktrace was requested to be collected from this group in the + * tracing config. + */ + public boolean getShouldCollectStacktrace(String groupTag) { + return getConfigFor(groupTag).collectStackTrace; + } + + private GroupConfig getConfigFor(String groupTag) { + return mConfig.getConfigFor(groupTag); + } + } + + public static class IncrementalState { + public final Map<String, Integer> argumentInterningMap = new HashMap<>(); + public final Map<String, Integer> stacktraceInterningMap = new HashMap<>(); + public boolean clearReported = false; + } + + private static class ProtoLogConfig { + private final LogLevel mDefaultLogFromLevel; + private final Map<String, GroupConfig> mGroupConfigs; + + private static final ProtoLogConfig DEFAULT = + new ProtoLogConfig(LogLevel.WTF, new HashMap<>()); + + private ProtoLogConfig( + LogLevel defaultLogFromLevel, Map<String, GroupConfig> groupConfigs) { + this.mDefaultLogFromLevel = defaultLogFromLevel; + this.mGroupConfigs = groupConfigs; + } + + private GroupConfig getConfigFor(String groupTag) { + return mGroupConfigs.getOrDefault(groupTag, getDefaultGroupConfig()); + } + + private GroupConfig getDefaultGroupConfig() { + return new GroupConfig(mDefaultLogFromLevel, false); + } + } + + public static class GroupConfig { + public final LogLevel logFrom; + public final boolean collectStackTrace; + + public GroupConfig(LogLevel logFromLevel, boolean collectStackTrace) { + this.logFrom = logFromLevel; + this.collectStackTrace = collectStackTrace; + } + } + + private ProtoLogConfig readProtoLogConfig(ProtoInputStream configStream) + throws IOException { + final long config_token = configStream.start(PROTOLOG_CONFIG); + + LogLevel defaultLogFromLevel = LogLevel.WTF; + final Map<String, GroupConfig> groupConfigs = new HashMap<>(); + + while (configStream.nextField() != ProtoInputStream.NO_MORE_FIELDS) { + if (configStream.getFieldNumber() == (int) TRACING_MODE) { + int tracingMode = configStream.readInt(TRACING_MODE); + switch (tracingMode) { + case PerfettoTrace.ProtoLogConfig.DEFAULT: + break; + case PerfettoTrace.ProtoLogConfig.ENABLE_ALL: + defaultLogFromLevel = LogLevel.DEBUG; + break; + default: + throw new RuntimeException("Unhandled ProtoLog tracing mode type"); + } + } + if (configStream.getFieldNumber() == (int) GROUP_OVERRIDES) { + final long group_overrides_token = configStream.start(GROUP_OVERRIDES); + + String tag = null; + LogLevel logFromLevel = defaultLogFromLevel; + boolean collectStackTrace = false; + while (configStream.nextField() != ProtoInputStream.NO_MORE_FIELDS) { + if (configStream.getFieldNumber() == (int) GROUP_NAME) { + tag = configStream.readString(GROUP_NAME); + } + if (configStream.getFieldNumber() == (int) LOG_FROM) { + final int logFromInt = configStream.readInt(LOG_FROM); + switch (logFromInt) { + case (PerfettoTrace.PROTOLOG_LEVEL_DEBUG): { + logFromLevel = LogLevel.DEBUG; + break; + } + case (PerfettoTrace.PROTOLOG_LEVEL_VERBOSE): { + logFromLevel = LogLevel.VERBOSE; + break; + } + case (PerfettoTrace.PROTOLOG_LEVEL_INFO): { + logFromLevel = LogLevel.INFO; + break; + } + case (PerfettoTrace.PROTOLOG_LEVEL_WARN): { + logFromLevel = LogLevel.WARN; + break; + } + case (PerfettoTrace.PROTOLOG_LEVEL_ERROR): { + logFromLevel = LogLevel.ERROR; + break; + } + case (PerfettoTrace.PROTOLOG_LEVEL_WTF): { + logFromLevel = LogLevel.WTF; + break; + } + default: { + throw new RuntimeException("Unhandled log level"); + } + } + } + if (configStream.getFieldNumber() == (int) COLLECT_STACKTRACE) { + collectStackTrace = configStream.readBoolean(COLLECT_STACKTRACE); + } + } + + if (tag == null) { + throw new RuntimeException("Failed to decode proto config. " + + "Got a group override without a group tag."); + } + + groupConfigs.put(tag, new GroupConfig(logFromLevel, collectStackTrace)); + + configStream.end(group_overrides_token); + } + } + + configStream.end(config_token); + + return new ProtoLogConfig(defaultLogFromLevel, groupConfigs); + } + + public static class Instance extends DataSourceInstance { + + private final Runnable mOnStart; + private final Runnable mOnFlush; + private final Runnable mOnStop; + private final ProtoLogConfig mConfig; + + public Instance( + DataSource<Instance, TlsState, IncrementalState> dataSource, + int instanceIdx, + ProtoLogConfig config, + Runnable onStart, + Runnable onFlush, + Runnable onStop + ) { + super(dataSource, instanceIdx); + this.mOnStart = onStart; + this.mOnFlush = onFlush; + this.mOnStop = onStop; + this.mConfig = config; + } + + @Override + public void onStart(StartCallbackArguments args) { + this.mOnStart.run(); + } + + @Override + public void onFlush(FlushCallbackArguments args) { + this.mOnFlush.run(); + } + + @Override + public void onStop(StopCallbackArguments args) { + this.mOnStop.run(); + } + } +} diff --git a/core/java/com/android/internal/protolog/ProtoLogImpl.java b/core/java/com/android/internal/protolog/ProtoLogImpl.java index 43af68d7f9a5dd15acfb86e5e304609aa7226cf4..78bed9478d841efdb80d0c1148126b7da8f53c63 100644 --- a/core/java/com/android/internal/protolog/ProtoLogImpl.java +++ b/core/java/com/android/internal/protolog/ProtoLogImpl.java @@ -17,8 +17,8 @@ package com.android.internal.protolog; import static com.android.internal.protolog.common.ProtoLogToolInjected.Value.LEGACY_OUTPUT_FILE_PATH; -import static com.android.internal.protolog.common.ProtoLogToolInjected.Value.VIEWER_CONFIG_PATH; import static com.android.internal.protolog.common.ProtoLogToolInjected.Value.LEGACY_VIEWER_CONFIG_PATH; +import static com.android.internal.protolog.common.ProtoLogToolInjected.Value.VIEWER_CONFIG_PATH; import android.annotation.Nullable; @@ -100,7 +100,7 @@ public class ProtoLogImpl { if (sServiceInstance == null) { if (android.tracing.Flags.perfettoProtolog()) { sServiceInstance = - new PerfettoProtoLogImpl(sViewerConfigPath, sLegacyViewerConfigPath); + new PerfettoProtoLogImpl(sViewerConfigPath); } else { sServiceInstance = new LegacyProtoLogImpl(sLegacyOutputFilePath, sLegacyViewerConfigPath); diff --git a/core/java/com/android/internal/protolog/ProtoLogViewerConfigReader.java b/core/java/com/android/internal/protolog/ProtoLogViewerConfigReader.java index 49c70b97b221597ae95b77299e6c2424d53a17cf..3c206acf7c0ff496519359f8807c6f35845e8b20 100644 --- a/core/java/com/android/internal/protolog/ProtoLogViewerConfigReader.java +++ b/core/java/com/android/internal/protolog/ProtoLogViewerConfigReader.java @@ -1,49 +1,29 @@ -/* - * Copyright (C) 2020 The Android Open Source Project - * - * Licensed under the Apache License, Version 2.0 (the "License"); - * you may not use this file except in compliance with the License. - * You may obtain a copy of the License at - * - * http://www.apache.org/licenses/LICENSE-2.0 - * - * Unless required by applicable law or agreed to in writing, software - * distributed under the License is distributed on an "AS IS" BASIS, - * WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied. - * See the License for the specific language governing permissions and - * limitations under the License. - */ - package com.android.internal.protolog; -import android.annotation.Nullable; -import android.util.Slog; +import static perfetto.protos.PerfettoTrace.ProtoLogViewerConfig.MESSAGES; +import static perfetto.protos.PerfettoTrace.ProtoLogViewerConfig.MessageData.MESSAGE; +import static perfetto.protos.PerfettoTrace.ProtoLogViewerConfig.MessageData.MESSAGE_ID; -import com.android.internal.protolog.common.ILogger; +import android.util.proto.ProtoInputStream; -import org.json.JSONException; -import org.json.JSONObject; +import com.android.internal.protolog.common.ILogger; -import java.io.BufferedReader; -import java.io.FileInputStream; -import java.io.FileNotFoundException; import java.io.IOException; -import java.io.InputStream; -import java.io.InputStreamReader; -import java.io.PrintWriter; -import java.util.Iterator; import java.util.Map; -import java.util.TreeMap; -import java.util.zip.GZIPInputStream; -/** - * Handles loading and parsing of ProtoLog viewer configuration. - */ public class ProtoLogViewerConfigReader { - private static final String TAG = "ProtoLogViewerConfigReader"; + private final ViewerConfigInputStreamProvider mViewerConfigInputStreamProvider; private Map<Long, String> mLogMessageMap = null; - /** Returns message format string for its hash or null if unavailable. */ + public ProtoLogViewerConfigReader( + ViewerConfigInputStreamProvider viewerConfigInputStreamProvider) { + this.mViewerConfigInputStreamProvider = viewerConfigInputStreamProvider; + } + + /** + * Returns message format string for its hash or null if unavailable + * or the viewer config is not loaded into memory. + */ public synchronized String getViewerString(long messageHash) { if (mLogMessageMap != null) { return mLogMessageMap.get(messageHash); @@ -53,75 +33,61 @@ public class ProtoLogViewerConfigReader { } /** - * Reads the specified viewer configuration file. Does nothing if the config is already loaded. - */ - public synchronized void loadViewerConfig(ILogger logger, String viewerConfigFilename) { - try { - loadViewerConfig(new GZIPInputStream(new FileInputStream(viewerConfigFilename))); - logger.log("Loaded " + mLogMessageMap.size() - + " log definitions from " + viewerConfigFilename); - } catch (FileNotFoundException e) { - logger.log("Unable to load log definitions: File " - + viewerConfigFilename + " not found." + e); - } catch (IOException e) { - logger.log("Unable to load log definitions: IOException while reading " - + viewerConfigFilename + ". " + e); - } catch (JSONException e) { - logger.log("Unable to load log definitions: JSON parsing exception while reading " - + viewerConfigFilename + ". " + e); - } - } - - /** - * Reads the specified viewer configuration input stream. - * Does nothing if the config is already loaded. + * Loads the viewer config into memory. No-op if already loaded in memory. */ - public synchronized void loadViewerConfig(InputStream viewerConfigInputStream) - throws IOException, JSONException { + public synchronized void loadViewerConfig(ILogger logger) { if (mLogMessageMap != null) { return; } - InputStreamReader config = new InputStreamReader(viewerConfigInputStream); - BufferedReader reader = new BufferedReader(config); - StringBuilder builder = new StringBuilder(); - String line; - while ((line = reader.readLine()) != null) { - builder.append(line).append('\n'); - } - reader.close(); - JSONObject json = new JSONObject(builder.toString()); - JSONObject messages = json.getJSONObject("messages"); - - mLogMessageMap = new TreeMap<>(); - Iterator it = messages.keys(); - while (it.hasNext()) { - String key = (String) it.next(); - try { - long hash = Long.parseLong(key); - JSONObject val = messages.getJSONObject(key); - String msg = val.getString("message"); - mLogMessageMap.put(hash, msg); - } catch (NumberFormatException expected) { - // Not a messageHash - skip it - } + + try { + doLoadViewerConfig(); + logger.log("Loaded " + mLogMessageMap.size() + " log definitions"); + } catch (IOException e) { + logger.log("Unable to load log definitions: " + + "IOException while processing viewer config" + e); } } /** - * Returns the number of loaded log definitions kept in memory. + * Unload the viewer config from memory. */ - public synchronized int knownViewerStringsNumber() { - if (mLogMessageMap != null) { - return mLogMessageMap.size(); - } - return 0; + public synchronized void unloadViewerConfig() { + mLogMessageMap = null; } - static void logAndPrintln(@Nullable PrintWriter pw, String msg) { - Slog.i(TAG, msg); - if (pw != null) { - pw.println(msg); - pw.flush(); + private void doLoadViewerConfig() throws IOException { + final ProtoInputStream pis = mViewerConfigInputStreamProvider.getInputStream(); + + while (pis.nextField() != ProtoInputStream.NO_MORE_FIELDS) { + if (pis.getFieldNumber() == (int) MESSAGES) { + final long inMessageToken = pis.start(MESSAGES); + + long messageId = 0; + String message = null; + while (pis.nextField() != ProtoInputStream.NO_MORE_FIELDS) { + switch (pis.getFieldNumber()) { + case (int) MESSAGE_ID: + messageId = pis.readLong(MESSAGE_ID); + break; + case (int) MESSAGE: + message = pis.readString(MESSAGE); + break; + } + } + + if (messageId == 0) { + throw new IOException("Failed to get message id"); + } + + if (message == null) { + throw new IOException("Failed to get message string"); + } + + mLogMessageMap.put(messageId, message); + + pis.end(inMessageToken); + } } } } diff --git a/core/java/com/android/internal/protolog/ViewerConfigInputStreamProvider.java b/core/java/com/android/internal/protolog/ViewerConfigInputStreamProvider.java new file mode 100644 index 0000000000000000000000000000000000000000..334f5488425ac0463d3bdc3dce52ab3cd12d9edb --- /dev/null +++ b/core/java/com/android/internal/protolog/ViewerConfigInputStreamProvider.java @@ -0,0 +1,26 @@ +/* + * Copyright (C) 2024 The Android Open Source Project + * + * Licensed under the Apache License, Version 2.0 (the "License"); + * you may not use this file except in compliance with the License. + * You may obtain a copy of the License at + * + * http://www.apache.org/licenses/LICENSE-2.0 + * + * Unless required by applicable law or agreed to in writing, software + * distributed under the License is distributed on an "AS IS" BASIS, + * WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied. + * See the License for the specific language governing permissions and + * limitations under the License. + */ + +package com.android.internal.protolog; + +import android.util.proto.ProtoInputStream; + +public interface ViewerConfigInputStreamProvider { + /** + * @return a ProtoInputStream. + */ + ProtoInputStream getInputStream(); +} diff --git a/tests/Internal/src/com/android/internal/protolog/PerfettoDataSourceTest.java b/tests/Internal/src/com/android/internal/protolog/PerfettoDataSourceTest.java new file mode 100644 index 0000000000000000000000000000000000000000..b9f1738f9bb71853243a8a746198679bd3033f90 --- /dev/null +++ b/tests/Internal/src/com/android/internal/protolog/PerfettoDataSourceTest.java @@ -0,0 +1,167 @@ +/* + * Copyright (C) 2024 The Android Open Source Project + * + * Licensed under the Apache License, Version 2.0 (the "License"); + * you may not use this file except in compliance with the License. + * You may obtain a copy of the License at + * + * http://www.apache.org/licenses/LICENSE-2.0 + * + * Unless required by applicable law or agreed to in writing, software + * distributed under the License is distributed on an "AS IS" BASIS, + * WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied. + * See the License for the specific language governing permissions and + * limitations under the License. + */ + +package com.android.internal.protolog; + +import static org.junit.Assert.assertThrows; +import static org.junit.Assume.assumeTrue; + +import android.tracing.perfetto.CreateTlsStateArgs; +import android.util.proto.ProtoInputStream; + +import com.android.internal.protolog.common.LogLevel; + +import com.google.common.truth.Truth; + +import org.junit.Before; +import org.junit.Test; +import org.mockito.Mockito; + +import perfetto.protos.DataSourceConfigOuterClass; +import perfetto.protos.ProtologCommon; +import perfetto.protos.ProtologConfig; + +public class PerfettoDataSourceTest { + @Before + public void before() { + assumeTrue(android.tracing.Flags.perfettoProtolog()); + } + + @Test + public void noConfig() { + final ProtoLogDataSource.TlsState tlsState = createTlsState( + DataSourceConfigOuterClass.DataSourceConfig.newBuilder().build()); + + Truth.assertThat(tlsState.getLogFromLevel("SOME_TAG")).isEqualTo(LogLevel.WTF); + Truth.assertThat(tlsState.getShouldCollectStacktrace("SOME_TAG")).isFalse(); + } + + @Test + public void defaultTraceMode() { + final ProtoLogDataSource.TlsState tlsState = createTlsState( + DataSourceConfigOuterClass.DataSourceConfig.newBuilder() + .setProtologConfig( + ProtologConfig.ProtoLogConfig.newBuilder() + .setTracingMode( + ProtologConfig.ProtoLogConfig.TracingMode + .ENABLE_ALL) + .build() + ).build()); + + Truth.assertThat(tlsState.getLogFromLevel("SOME_TAG")).isEqualTo(LogLevel.DEBUG); + Truth.assertThat(tlsState.getShouldCollectStacktrace("SOME_TAG")).isFalse(); + } + + @Test + public void allEnabledTraceMode() { + final ProtoLogDataSource ds = new ProtoLogDataSource(() -> {}, () -> {}, () -> {}); + + final ProtoLogDataSource.TlsState tlsState = createTlsState( + DataSourceConfigOuterClass.DataSourceConfig.newBuilder().setProtologConfig( + ProtologConfig.ProtoLogConfig.newBuilder() + .setTracingMode( + ProtologConfig.ProtoLogConfig.TracingMode.ENABLE_ALL) + .build() + ).build() + ); + + Truth.assertThat(tlsState.getLogFromLevel("SOME_TAG")).isEqualTo(LogLevel.DEBUG); + Truth.assertThat(tlsState.getShouldCollectStacktrace("SOME_TAG")).isFalse(); + } + + @Test + public void requireGroupTagInOverrides() { + Exception exception = assertThrows(RuntimeException.class, () -> { + createTlsState(DataSourceConfigOuterClass.DataSourceConfig.newBuilder() + .setProtologConfig( + ProtologConfig.ProtoLogConfig.newBuilder() + .addGroupOverrides( + ProtologConfig.ProtoLogGroup.newBuilder() + .setLogFrom( + ProtologCommon.ProtoLogLevel + .PROTOLOG_LEVEL_WARN) + .setCollectStacktrace(true) + ) + .build() + ).build()); + }); + + Truth.assertThat(exception).hasMessageThat().contains("group override without a group tag"); + } + + @Test + public void stackTraceCollection() { + final ProtoLogDataSource.TlsState tlsState = createTlsState( + DataSourceConfigOuterClass.DataSourceConfig.newBuilder().setProtologConfig( + ProtologConfig.ProtoLogConfig.newBuilder() + .addGroupOverrides( + ProtologConfig.ProtoLogGroup.newBuilder() + .setGroupName("SOME_TAG") + .setCollectStacktrace(true) + ) + .build() + ).build()); + + Truth.assertThat(tlsState.getShouldCollectStacktrace("SOME_TAG")).isTrue(); + } + + @Test + public void groupLogFromOverrides() { + final ProtoLogDataSource.TlsState tlsState = createTlsState( + DataSourceConfigOuterClass.DataSourceConfig.newBuilder().setProtologConfig( + ProtologConfig.ProtoLogConfig.newBuilder() + .addGroupOverrides( + ProtologConfig.ProtoLogGroup.newBuilder() + .setGroupName("SOME_TAG") + .setLogFrom( + ProtologCommon.ProtoLogLevel + .PROTOLOG_LEVEL_DEBUG) + .setCollectStacktrace(true) + ) + .addGroupOverrides( + ProtologConfig.ProtoLogGroup.newBuilder() + .setGroupName("SOME_OTHER_TAG") + .setLogFrom( + ProtologCommon.ProtoLogLevel + .PROTOLOG_LEVEL_WARN) + ) + .build() + ).build()); + + Truth.assertThat(tlsState.getLogFromLevel("SOME_TAG")).isEqualTo(LogLevel.DEBUG); + Truth.assertThat(tlsState.getShouldCollectStacktrace("SOME_TAG")).isTrue(); + + Truth.assertThat(tlsState.getLogFromLevel("SOME_OTHER_TAG")).isEqualTo(LogLevel.WARN); + Truth.assertThat(tlsState.getShouldCollectStacktrace("SOME_OTHER_TAG")).isFalse(); + + Truth.assertThat(tlsState.getLogFromLevel("UNKNOWN_TAG")).isEqualTo(LogLevel.WTF); + Truth.assertThat(tlsState.getShouldCollectStacktrace("UNKNOWN_TAG")).isFalse(); + } + + private ProtoLogDataSource.TlsState createTlsState( + DataSourceConfigOuterClass.DataSourceConfig config) { + final ProtoLogDataSource ds = + Mockito.spy(new ProtoLogDataSource(() -> {}, () -> {}, () -> {})); + + ProtoInputStream configStream = new ProtoInputStream(config.toByteArray()); + final ProtoLogDataSource.Instance dsInstance = Mockito.spy( + ds.createInstance(configStream, 8)); + Mockito.doNothing().when(dsInstance).release(); + final CreateTlsStateArgs mockCreateTlsStateArgs = Mockito.mock(CreateTlsStateArgs.class); + Mockito.when(mockCreateTlsStateArgs.getDataSourceInstanceLocked()).thenReturn(dsInstance); + return ds.createTlsState(mockCreateTlsStateArgs); + } +} diff --git a/tests/Internal/src/com/android/internal/protolog/PerfettoProtoLogImplTest.java b/tests/Internal/src/com/android/internal/protolog/PerfettoProtoLogImplTest.java new file mode 100644 index 0000000000000000000000000000000000000000..4c311050568bfc2d22593b36bdae2760c1ab5ccf --- /dev/null +++ b/tests/Internal/src/com/android/internal/protolog/PerfettoProtoLogImplTest.java @@ -0,0 +1,586 @@ +/* + * Copyright (C) 2024 The Android Open Source Project + * + * Licensed under the Apache License, Version 2.0 (the "License"); + * you may not use this file except in compliance with the License. + * You may obtain a copy of the License at + * + * http://www.apache.org/licenses/LICENSE-2.0 + * + * Unless required by applicable law or agreed to in writing, software + * distributed under the License is distributed on an "AS IS" BASIS, + * WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied. + * See the License for the specific language governing permissions and + * limitations under the License. + */ + +package com.android.internal.protolog; + +import static androidx.test.platform.app.InstrumentationRegistry.getInstrumentation; + +import static org.junit.Assert.assertFalse; +import static org.junit.Assert.assertThrows; +import static org.junit.Assert.assertTrue; +import static org.mockito.ArgumentMatchers.any; +import static org.mockito.ArgumentMatchers.anyLong; +import static org.mockito.ArgumentMatchers.eq; +import static org.mockito.Mockito.never; +import static org.mockito.Mockito.verify; +import static org.mockito.Mockito.when; + +import static java.io.File.createTempFile; +import static java.nio.file.Files.createTempDirectory; + +import android.content.Context; +import android.os.SystemClock; +import android.platform.test.annotations.Presubmit; +import android.tools.common.ScenarioBuilder; +import android.tools.common.traces.protolog.ProtoLogTrace; +import android.tools.device.traces.TraceConfig; +import android.tools.device.traces.TraceConfigs; +import android.tools.device.traces.io.ResultReader; +import android.tools.device.traces.io.ResultWriter; +import android.tools.device.traces.monitors.PerfettoTraceMonitor; +import android.tracing.perfetto.DataSource; +import android.util.proto.ProtoInputStream; + +import androidx.test.filters.SmallTest; + +import com.android.internal.protolog.common.IProtoLogGroup; +import com.android.internal.protolog.common.LogDataType; +import com.android.internal.protolog.common.LogLevel; + +import com.google.common.truth.Truth; + +import org.junit.After; +import org.junit.Before; +import org.junit.Test; +import org.junit.runner.RunWith; +import org.junit.runners.JUnit4; +import org.mockito.Mockito; +import org.mockito.MockitoAnnotations; + +import java.io.File; +import java.io.IOException; +import java.util.List; +import java.util.Random; + +import perfetto.protos.Protolog; +import perfetto.protos.ProtologCommon; + +/** + * Test class for {@link ProtoLogImpl}. + */ +@SuppressWarnings("ConstantConditions") +@SmallTest +@Presubmit +@RunWith(JUnit4.class) +public class PerfettoProtoLogImplTest { + private final File mTracingDirectory = createTempDirectory("temp").toFile(); + + private final ResultWriter mWriter = new ResultWriter() + .forScenario(new ScenarioBuilder() + .forClass(createTempFile("temp", "").getName()).build()) + .withOutputDir(mTracingDirectory) + .setRunComplete(); + + private final TraceConfigs mTraceConfig = new TraceConfigs( + new TraceConfig(false, true, false), + new TraceConfig(false, true, false), + new TraceConfig(false, true, false), + new TraceConfig(false, true, false) + ); + + private PerfettoProtoLogImpl mProtoLog; + private Protolog.ProtoLogViewerConfig.Builder mViewerConfigBuilder; + private File mFile; + + private ProtoLogViewerConfigReader mReader; + + public PerfettoProtoLogImplTest() throws IOException { + } + + @Before + public void setUp() throws Exception { + MockitoAnnotations.initMocks(this); + final Context testContext = getInstrumentation().getContext(); + mFile = testContext.getFileStreamPath("tracing_test.dat"); + //noinspection ResultOfMethodCallIgnored + mFile.delete(); + + mViewerConfigBuilder = Protolog.ProtoLogViewerConfig.newBuilder() + .addGroups( + Protolog.ProtoLogViewerConfig.Group.newBuilder() + .setId(1) + .setName(TestProtoLogGroup.TEST_GROUP.toString()) + .setTag(TestProtoLogGroup.TEST_GROUP.getTag()) + ).addMessages( + Protolog.ProtoLogViewerConfig.MessageData.newBuilder() + .setMessageId(1) + .setMessage("My Test Debug Log Message %b") + .setLevel(ProtologCommon.ProtoLogLevel.PROTOLOG_LEVEL_DEBUG) + .setGroupId(1) + ).addMessages( + Protolog.ProtoLogViewerConfig.MessageData.newBuilder() + .setMessageId(2) + .setMessage("My Test Verbose Log Message %b") + .setLevel(ProtologCommon.ProtoLogLevel.PROTOLOG_LEVEL_VERBOSE) + .setGroupId(1) + ).addMessages( + Protolog.ProtoLogViewerConfig.MessageData.newBuilder() + .setMessageId(3) + .setMessage("My Test Warn Log Message %b") + .setLevel(ProtologCommon.ProtoLogLevel.PROTOLOG_LEVEL_WARN) + .setGroupId(1) + ).addMessages( + Protolog.ProtoLogViewerConfig.MessageData.newBuilder() + .setMessageId(4) + .setMessage("My Test Error Log Message %b") + .setLevel(ProtologCommon.ProtoLogLevel.PROTOLOG_LEVEL_ERROR) + .setGroupId(1) + ).addMessages( + Protolog.ProtoLogViewerConfig.MessageData.newBuilder() + .setMessageId(5) + .setMessage("My Test WTF Log Message %b") + .setLevel(ProtologCommon.ProtoLogLevel.PROTOLOG_LEVEL_WTF) + .setGroupId(1) + ); + + ViewerConfigInputStreamProvider viewerConfigInputStreamProvider = Mockito.mock( + ViewerConfigInputStreamProvider.class); + Mockito.when(viewerConfigInputStreamProvider.getInputStream()) + .thenAnswer(it -> new ProtoInputStream(mViewerConfigBuilder.build().toByteArray())); + + mReader = Mockito.spy(new ProtoLogViewerConfigReader(viewerConfigInputStreamProvider)); + mProtoLog = new PerfettoProtoLogImpl(viewerConfigInputStreamProvider, mReader); + } + + @After + public void tearDown() { + if (mFile != null) { + //noinspection ResultOfMethodCallIgnored + mFile.delete(); + } + ProtoLogImpl.setSingleInstance(null); + } + + @Test + public void isEnabled_returnsFalseByDefault() { + assertFalse(mProtoLog.isProtoEnabled()); + } + + @Test + public void isEnabled_returnsTrueAfterStart() { + PerfettoTraceMonitor traceMonitor = + PerfettoTraceMonitor.newBuilder().enableProtoLog().build(); + try { + traceMonitor.start(); + assertTrue(mProtoLog.isProtoEnabled()); + } finally { + traceMonitor.stop(mWriter); + } + } + + @Test + public void isEnabled_returnsFalseAfterStop() { + PerfettoTraceMonitor traceMonitor = + PerfettoTraceMonitor.newBuilder().enableProtoLog().build(); + try { + traceMonitor.start(); + assertTrue(mProtoLog.isProtoEnabled()); + } finally { + traceMonitor.stop(mWriter); + } + + assertFalse(mProtoLog.isProtoEnabled()); + } + + @Test + public void defaultMode() throws IOException { + PerfettoTraceMonitor traceMonitor = + PerfettoTraceMonitor.newBuilder().enableProtoLog(false).build(); + try { + traceMonitor.start(); + // Shouldn't be logging anything except WTF unless explicitly requested in the group + // override. + mProtoLog.log(LogLevel.DEBUG, TestProtoLogGroup.TEST_GROUP, 1, + LogDataType.BOOLEAN, null, new Object[]{true}); + mProtoLog.log(LogLevel.VERBOSE, TestProtoLogGroup.TEST_GROUP, 2, + LogDataType.BOOLEAN, null, new Object[]{true}); + mProtoLog.log(LogLevel.WARN, TestProtoLogGroup.TEST_GROUP, 3, + LogDataType.BOOLEAN, null, new Object[]{true}); + mProtoLog.log(LogLevel.ERROR, TestProtoLogGroup.TEST_GROUP, 4, + LogDataType.BOOLEAN, null, new Object[]{true}); + mProtoLog.log(LogLevel.WTF, TestProtoLogGroup.TEST_GROUP, 5, + LogDataType.BOOLEAN, null, new Object[]{true}); + } finally { + traceMonitor.stop(mWriter); + } + + final ResultReader reader = new ResultReader(mWriter.write(), mTraceConfig); + final ProtoLogTrace protolog = reader.readProtoLogTrace(); + + Truth.assertThat(protolog.messages).hasSize(1); + Truth.assertThat(protolog.messages.getFirst().getLevel()).isEqualTo(LogLevel.WTF); + } + + @Test + public void respectsOverrideConfigs_defaultMode() throws IOException { + PerfettoTraceMonitor traceMonitor = + PerfettoTraceMonitor.newBuilder().enableProtoLog(true, + List.of(new PerfettoTraceMonitor.Builder.ProtoLogGroupOverride( + TestProtoLogGroup.TEST_GROUP.toString(), LogLevel.DEBUG, true))) + .build(); + try { + traceMonitor.start(); + mProtoLog.log(LogLevel.DEBUG, TestProtoLogGroup.TEST_GROUP, 1, + LogDataType.BOOLEAN, null, new Object[]{true}); + mProtoLog.log(LogLevel.VERBOSE, TestProtoLogGroup.TEST_GROUP, 2, + LogDataType.BOOLEAN, null, new Object[]{true}); + mProtoLog.log(LogLevel.WARN, TestProtoLogGroup.TEST_GROUP, 3, + LogDataType.BOOLEAN, null, new Object[]{true}); + mProtoLog.log(LogLevel.ERROR, TestProtoLogGroup.TEST_GROUP, 4, + LogDataType.BOOLEAN, null, new Object[]{true}); + mProtoLog.log(LogLevel.WTF, TestProtoLogGroup.TEST_GROUP, 5, + LogDataType.BOOLEAN, null, new Object[]{true}); + } finally { + traceMonitor.stop(mWriter); + } + + final ResultReader reader = new ResultReader(mWriter.write(), mTraceConfig); + final ProtoLogTrace protolog = reader.readProtoLogTrace(); + + Truth.assertThat(protolog.messages).hasSize(5); + Truth.assertThat(protolog.messages.get(0).getLevel()).isEqualTo(LogLevel.DEBUG); + Truth.assertThat(protolog.messages.get(1).getLevel()).isEqualTo(LogLevel.VERBOSE); + Truth.assertThat(protolog.messages.get(2).getLevel()).isEqualTo(LogLevel.WARN); + Truth.assertThat(protolog.messages.get(3).getLevel()).isEqualTo(LogLevel.ERROR); + Truth.assertThat(protolog.messages.get(4).getLevel()).isEqualTo(LogLevel.WTF); + } + + @Test + public void respectsOverrideConfigs_allEnabledMode() throws IOException { + PerfettoTraceMonitor traceMonitor = + PerfettoTraceMonitor.newBuilder().enableProtoLog(true, + List.of(new PerfettoTraceMonitor.Builder.ProtoLogGroupOverride( + TestProtoLogGroup.TEST_GROUP.toString(), LogLevel.WARN, false))) + .build(); + try { + traceMonitor.start(); + mProtoLog.log(LogLevel.DEBUG, TestProtoLogGroup.TEST_GROUP, 1, + LogDataType.BOOLEAN, null, new Object[]{true}); + mProtoLog.log(LogLevel.VERBOSE, TestProtoLogGroup.TEST_GROUP, 2, + LogDataType.BOOLEAN, null, new Object[]{true}); + mProtoLog.log(LogLevel.WARN, TestProtoLogGroup.TEST_GROUP, 3, + LogDataType.BOOLEAN, null, new Object[]{true}); + mProtoLog.log(LogLevel.ERROR, TestProtoLogGroup.TEST_GROUP, 4, + LogDataType.BOOLEAN, null, new Object[]{true}); + mProtoLog.log(LogLevel.WTF, TestProtoLogGroup.TEST_GROUP, 5, + LogDataType.BOOLEAN, null, new Object[]{true}); + } finally { + traceMonitor.stop(mWriter); + } + + final ResultReader reader = new ResultReader(mWriter.write(), mTraceConfig); + final ProtoLogTrace protolog = reader.readProtoLogTrace(); + + Truth.assertThat(protolog.messages).hasSize(3); + Truth.assertThat(protolog.messages.get(0).getLevel()).isEqualTo(LogLevel.WARN); + Truth.assertThat(protolog.messages.get(1).getLevel()).isEqualTo(LogLevel.ERROR); + Truth.assertThat(protolog.messages.get(2).getLevel()).isEqualTo(LogLevel.WTF); + } + + @Test + public void respectsAllEnabledMode() throws IOException { + PerfettoTraceMonitor traceMonitor = + PerfettoTraceMonitor.newBuilder().enableProtoLog(true, List.of()) + .build(); + try { + traceMonitor.start(); + mProtoLog.log(LogLevel.DEBUG, TestProtoLogGroup.TEST_GROUP, 1, + LogDataType.BOOLEAN, null, new Object[]{true}); + mProtoLog.log(LogLevel.VERBOSE, TestProtoLogGroup.TEST_GROUP, 2, + LogDataType.BOOLEAN, null, new Object[]{true}); + mProtoLog.log(LogLevel.WARN, TestProtoLogGroup.TEST_GROUP, 3, + LogDataType.BOOLEAN, null, new Object[]{true}); + mProtoLog.log(LogLevel.ERROR, TestProtoLogGroup.TEST_GROUP, 4, + LogDataType.BOOLEAN, null, new Object[]{true}); + mProtoLog.log(LogLevel.WTF, TestProtoLogGroup.TEST_GROUP, 5, + LogDataType.BOOLEAN, null, new Object[]{true}); + } finally { + traceMonitor.stop(mWriter); + } + + final ResultReader reader = new ResultReader(mWriter.write(), mTraceConfig); + final ProtoLogTrace protolog = reader.readProtoLogTrace(); + + Truth.assertThat(protolog.messages).hasSize(5); + Truth.assertThat(protolog.messages.get(0).getLevel()).isEqualTo(LogLevel.DEBUG); + Truth.assertThat(protolog.messages.get(1).getLevel()).isEqualTo(LogLevel.VERBOSE); + Truth.assertThat(protolog.messages.get(2).getLevel()).isEqualTo(LogLevel.WARN); + Truth.assertThat(protolog.messages.get(3).getLevel()).isEqualTo(LogLevel.ERROR); + Truth.assertThat(protolog.messages.get(4).getLevel()).isEqualTo(LogLevel.WTF); + } + + @Test + public void log_logcatEnabledExternalMessage() { + when(mReader.getViewerString(anyLong())).thenReturn("test %b %d %% 0x%x %s %f"); + PerfettoProtoLogImpl implSpy = Mockito.spy(mProtoLog); + TestProtoLogGroup.TEST_GROUP.setLogToLogcat(true); + TestProtoLogGroup.TEST_GROUP.setLogToProto(false); + + implSpy.log( + LogLevel.INFO, TestProtoLogGroup.TEST_GROUP, 1234, 4321, null, + new Object[]{true, 10000, 30000, "test", 0.000003}); + + verify(implSpy).passToLogcat(eq(TestProtoLogGroup.TEST_GROUP.getTag()), eq( + LogLevel.INFO), + eq("test true 10000 % 0x7530 test 3.0E-6")); + verify(mReader).getViewerString(eq(1234L)); + } + + @Test + public void log_logcatEnabledInvalidMessage() { + when(mReader.getViewerString(anyLong())).thenReturn("test %b %d %% %x %s %f"); + PerfettoProtoLogImpl implSpy = Mockito.spy(mProtoLog); + TestProtoLogGroup.TEST_GROUP.setLogToLogcat(true); + TestProtoLogGroup.TEST_GROUP.setLogToProto(false); + + implSpy.log( + LogLevel.INFO, TestProtoLogGroup.TEST_GROUP, 1234, 4321, null, + new Object[]{true, 10000, 0.0001, 0.00002, "test"}); + + verify(implSpy).passToLogcat(eq(TestProtoLogGroup.TEST_GROUP.getTag()), eq( + LogLevel.INFO), + eq("UNKNOWN MESSAGE (1234) true 10000 1.0E-4 2.0E-5 test")); + verify(mReader).getViewerString(eq(1234L)); + } + + @Test + public void log_logcatEnabledInlineMessage() { + when(mReader.getViewerString(anyLong())).thenReturn("test %d"); + PerfettoProtoLogImpl implSpy = Mockito.spy(mProtoLog); + TestProtoLogGroup.TEST_GROUP.setLogToLogcat(true); + TestProtoLogGroup.TEST_GROUP.setLogToProto(false); + + implSpy.log( + LogLevel.INFO, TestProtoLogGroup.TEST_GROUP, 1234, 4321, "test %d", + new Object[]{5}); + + verify(implSpy).passToLogcat(eq(TestProtoLogGroup.TEST_GROUP.getTag()), eq( + LogLevel.INFO), eq("test 5")); + verify(mReader, never()).getViewerString(anyLong()); + } + + @Test + public void log_logcatEnabledNoMessage() { + when(mReader.getViewerString(anyLong())).thenReturn(null); + PerfettoProtoLogImpl implSpy = Mockito.spy(mProtoLog); + TestProtoLogGroup.TEST_GROUP.setLogToLogcat(true); + TestProtoLogGroup.TEST_GROUP.setLogToProto(false); + + implSpy.log( + LogLevel.INFO, TestProtoLogGroup.TEST_GROUP, 1234, 4321, null, + new Object[]{5}); + + verify(implSpy).passToLogcat(eq(TestProtoLogGroup.TEST_GROUP.getTag()), eq( + LogLevel.INFO), eq("UNKNOWN MESSAGE (1234) 5")); + verify(mReader).getViewerString(eq(1234L)); + } + + @Test + public void log_logcatDisabled() { + when(mReader.getViewerString(anyLong())).thenReturn("test %d"); + PerfettoProtoLogImpl implSpy = Mockito.spy(mProtoLog); + TestProtoLogGroup.TEST_GROUP.setLogToLogcat(false); + + implSpy.log( + LogLevel.INFO, TestProtoLogGroup.TEST_GROUP, 1234, 4321, "test %d", + new Object[]{5}); + + verify(implSpy, never()).passToLogcat(any(), any(), any()); + verify(mReader, never()).getViewerString(anyLong()); + } + + @Test + public void log_protoEnabled() throws Exception { + final long messageHash = addMessageToConfig( + ProtologCommon.ProtoLogLevel.PROTOLOG_LEVEL_INFO, + "My test message :: %s, %d, %o, %x, %f, %e, %g, %b"); + + PerfettoTraceMonitor traceMonitor = + PerfettoTraceMonitor.newBuilder().enableProtoLog().build(); + long before; + long after; + try { + traceMonitor.start(); + assertTrue(mProtoLog.isProtoEnabled()); + + before = SystemClock.elapsedRealtimeNanos(); + mProtoLog.log( + LogLevel.INFO, TestProtoLogGroup.TEST_GROUP, messageHash, + 0b1110101001010100, null, + new Object[]{"test", 1, 2, 3, 0.4, 0.5, 0.6, true}); + after = SystemClock.elapsedRealtimeNanos(); + } finally { + traceMonitor.stop(mWriter); + } + + final ResultReader reader = new ResultReader(mWriter.write(), mTraceConfig); + final ProtoLogTrace protolog = reader.readProtoLogTrace(); + + Truth.assertThat(protolog.messages).hasSize(1); + Truth.assertThat(protolog.messages.getFirst().getTimestamp().getElapsedNanos()) + .isAtLeast(before); + Truth.assertThat(protolog.messages.getFirst().getTimestamp().getElapsedNanos()) + .isAtMost(after); + Truth.assertThat(protolog.messages.getFirst().getMessage()) + .isEqualTo("My test message :: test, 2, 4, 6, 0.400000, 5.000000e-01, 0.6, true"); + } + + private long addMessageToConfig(ProtologCommon.ProtoLogLevel logLevel, String message) { + final long messageId = new Random().nextLong(); + mViewerConfigBuilder.addMessages(Protolog.ProtoLogViewerConfig.MessageData.newBuilder() + .setMessageId(messageId) + .setMessage(message) + .setLevel(logLevel) + .setGroupId(1) + ); + + return messageId; + } + + @Test + public void log_invalidParamsMask() { + final long messageHash = addMessageToConfig( + ProtologCommon.ProtoLogLevel.PROTOLOG_LEVEL_INFO, + "My test message :: %s, %d, %f, %b"); + PerfettoTraceMonitor traceMonitor = + PerfettoTraceMonitor.newBuilder().enableProtoLog().build(); + long before; + long after; + try { + traceMonitor.start(); + before = SystemClock.elapsedRealtimeNanos(); + mProtoLog.log( + LogLevel.INFO, TestProtoLogGroup.TEST_GROUP, messageHash, + 0b01100100, null, + new Object[]{"test", 1, 0.1, true}); + after = SystemClock.elapsedRealtimeNanos(); + } finally { + traceMonitor.stop(mWriter); + } + + final ResultReader reader = new ResultReader(mWriter.write(), mTraceConfig); + assertThrows(IllegalStateException.class, reader::readProtoLogTrace); + } + + @Test + public void log_protoDisabled() throws Exception { + PerfettoTraceMonitor traceMonitor = + PerfettoTraceMonitor.newBuilder().enableProtoLog(false).build(); + try { + traceMonitor.start(); + mProtoLog.log(LogLevel.DEBUG, TestProtoLogGroup.TEST_GROUP, 1, + 0b11, null, new Object[]{true}); + } finally { + traceMonitor.stop(mWriter); + } + + final ResultReader reader = new ResultReader(mWriter.write(), mTraceConfig); + final ProtoLogTrace protolog = reader.readProtoLogTrace(); + + Truth.assertThat(protolog.messages).isEmpty(); + } + + @Test + public void stackTraceTrimmed() throws IOException { + PerfettoTraceMonitor traceMonitor = + PerfettoTraceMonitor.newBuilder().enableProtoLog(true, + List.of(new PerfettoTraceMonitor.Builder.ProtoLogGroupOverride( + TestProtoLogGroup.TEST_GROUP.toString(), LogLevel.DEBUG, true))) + .build(); + try { + traceMonitor.start(); + + ProtoLogImpl.setSingleInstance(mProtoLog); + ProtoLogImpl.d(TestProtoLogGroup.TEST_GROUP, 1, + 0b11, null, true); + } finally { + traceMonitor.stop(mWriter); + } + + final ResultReader reader = new ResultReader(mWriter.write(), mTraceConfig); + final ProtoLogTrace protolog = reader.readProtoLogTrace(); + + Truth.assertThat(protolog.messages).hasSize(1); + String stacktrace = protolog.messages.getFirst().getStacktrace(); + Truth.assertThat(stacktrace) + .doesNotContain(PerfettoProtoLogImpl.class.getSimpleName() + ".java"); + Truth.assertThat(stacktrace).doesNotContain(DataSource.class.getSimpleName() + ".java"); + Truth.assertThat(stacktrace) + .doesNotContain(ProtoLogImpl.class.getSimpleName() + ".java"); + Truth.assertThat(stacktrace).contains(PerfettoProtoLogImplTest.class.getSimpleName()); + Truth.assertThat(stacktrace).contains("stackTraceTrimmed"); + } + + private enum TestProtoLogGroup implements IProtoLogGroup { + TEST_GROUP(true, true, false, "TEST_TAG"); + + private final boolean mEnabled; + private volatile boolean mLogToProto; + private volatile boolean mLogToLogcat; + private final String mTag; + + /** + * @param enabled set to false to exclude all log statements for this group from + * compilation, + * they will not be available in runtime. + * @param logToProto enable binary logging for the group + * @param logToLogcat enable text logging for the group + * @param tag name of the source of the logged message + */ + TestProtoLogGroup(boolean enabled, boolean logToProto, boolean logToLogcat, String tag) { + this.mEnabled = enabled; + this.mLogToProto = logToProto; + this.mLogToLogcat = logToLogcat; + this.mTag = tag; + } + + @Override + public boolean isEnabled() { + return mEnabled; + } + + @Override + public boolean isLogToProto() { + return mLogToProto; + } + + @Override + public boolean isLogToLogcat() { + return mLogToLogcat; + } + + @Override + public boolean isLogToAny() { + return mLogToLogcat || mLogToProto; + } + + @Override + public String getTag() { + return mTag; + } + + @Override + public void setLogToProto(boolean logToProto) { + this.mLogToProto = logToProto; + } + + @Override + public void setLogToLogcat(boolean logToLogcat) { + this.mLogToLogcat = logToLogcat; + } + + } +}