From 85a400893eee7f65ec4a76b55752ea2c53ce1880 Mon Sep 17 00:00:00 2001 From: Ben Miles Date: Wed, 3 Nov 2021 11:49:28 +0000 Subject: [PATCH] Log ANRs in critical event log Change-Id: I4a851cb57f8624c44b06b8c243bf1671aedbfaea Test: atest CriticalEventLogTest Bug: b/200263868 --- .../criticalevents/critical_event_log.proto | 31 +++ .../java/com/android/server/Watchdog.java | 6 +- .../server/am/ProcessErrorStateRecord.java | 8 +- .../criticalevents/CriticalEventLog.java | 131 ++++++++++- .../com/android/server/wm/AnrController.java | 2 +- .../criticalevents/CriticalEventLogTest.java | 213 ++++++++++++++++-- 6 files changed, 363 insertions(+), 28 deletions(-) diff --git a/proto/src/criticalevents/critical_event_log.proto b/proto/src/criticalevents/critical_event_log.proto index 27787c25699f3..0e0343461d9e3 100644 --- a/proto/src/criticalevents/critical_event_log.proto +++ b/proto/src/criticalevents/critical_event_log.proto @@ -56,6 +56,7 @@ message CriticalEventProto { oneof event { Watchdog watchdog = 2; HalfWatchdog half_watchdog = 3; + AppNotResponding anr = 4; } message Watchdog { @@ -75,4 +76,34 @@ message CriticalEventProto { // Required. optional string subject = 1; } + + message AppNotResponding { + // The ANR subject. + // Optional, may be redacted for privacy. + optional string subject = 1; + + // Name of the ANRing process. + // Optional, may be redacted for privacy. + optional string process = 2; + + // PID of the ANRing process. + // Required. + optional int32 pid = 3; + + // UID of the ANRing process. + // Required. + optional int32 uid = 4; + + // Category of the ANRing process (DATA_APP, SYSTEM_APP, etc). + // Required. + optional ProcessClass process_class = 5; + } + + // Mirrors definition & values in {@link android.server.ServerProtoEnums}. + enum ProcessClass { + PROCESS_CLASS_UNKNOWN = 0; + DATA_APP = 1; + SYSTEM_APP = 2; + SYSTEM_SERVER = 3; + } } \ No newline at end of file diff --git a/services/core/java/com/android/server/Watchdog.java b/services/core/java/com/android/server/Watchdog.java index 0fde6fae7ff54..b019789e1982e 100644 --- a/services/core/java/com/android/server/Watchdog.java +++ b/services/core/java/com/android/server/Watchdog.java @@ -666,7 +666,8 @@ public class Watchdog { if (doWaitedHalfDump) { // Get critical event log before logging the half watchdog so that it doesn't // occur in the log. - String criticalEvents = CriticalEventLog.getInstance().logLinesForAnrFile(); + String criticalEvents = + CriticalEventLog.getInstance().logLinesForSystemServerTraceFile(); CriticalEventLog.getInstance().logHalfWatchdog(subject); // We've waited half the deadlock-detection interval. Pull a stack @@ -693,7 +694,8 @@ public class Watchdog { // Get critical event log before logging the watchdog so that it doesn't occur in the // log. - String criticalEvents = CriticalEventLog.getInstance().logLinesForAnrFile(); + String criticalEvents = + CriticalEventLog.getInstance().logLinesForSystemServerTraceFile(); CriticalEventLog.getInstance().logWatchdog(subject, errorId); long anrTime = SystemClock.uptimeMillis(); diff --git a/services/core/java/com/android/server/am/ProcessErrorStateRecord.java b/services/core/java/com/android/server/am/ProcessErrorStateRecord.java index b7ea3dc68c50e..42205060e5d50 100644 --- a/services/core/java/com/android/server/am/ProcessErrorStateRecord.java +++ b/services/core/java/com/android/server/am/ProcessErrorStateRecord.java @@ -332,6 +332,13 @@ class ProcessErrorStateRecord { } } + // Get critical event log before logging the ANR so that it doesn't occur in the log. + final String criticalEventLog = + CriticalEventLog.getInstance().logLinesForTraceFile( + mApp.getProcessClassEnum(), mApp.processName, mApp.uid); + CriticalEventLog.getInstance().logAnr(annotation, mApp.getProcessClassEnum(), + mApp.processName, mApp.uid, mApp.mPid); + // Log the ANR to the main log. StringBuilder info = new StringBuilder(); info.setLength(0); @@ -401,7 +408,6 @@ class ProcessErrorStateRecord { StringWriter tracesFileException = new StringWriter(); // To hold the start and end offset to the ANR trace file respectively. final long[] offsets = new long[2]; - final String criticalEventLog = CriticalEventLog.getInstance().logLinesForAnrFile(); File tracesFile = ActivityManagerService.dumpStackTraces(firstPids, isSilentAnr ? null : processCpuTracker, isSilentAnr ? null : lastPids, nativePids, tracesFileException, offsets, annotation, criticalEventLog); diff --git a/services/core/java/com/android/server/criticalevents/CriticalEventLog.java b/services/core/java/com/android/server/criticalevents/CriticalEventLog.java index d5fe9c9f22a93..30b3524dfb1ba 100644 --- a/services/core/java/com/android/server/criticalevents/CriticalEventLog.java +++ b/services/core/java/com/android/server/criticalevents/CriticalEventLog.java @@ -18,6 +18,7 @@ package com.android.server.criticalevents; import android.os.Handler; import android.os.HandlerThread; +import android.server.ServerProtoEnums; import android.util.Slog; import com.android.framework.protobuf.nano.MessageNanoPrinter; @@ -26,6 +27,7 @@ import com.android.internal.util.RingBuffer; import com.android.server.criticalevents.nano.CriticalEventLogProto; import com.android.server.criticalevents.nano.CriticalEventLogStorageProto; import com.android.server.criticalevents.nano.CriticalEventProto; +import com.android.server.criticalevents.nano.CriticalEventProto.AppNotResponding; import com.android.server.criticalevents.nano.CriticalEventProto.HalfWatchdog; import com.android.server.criticalevents.nano.CriticalEventProto.Watchdog; @@ -49,6 +51,9 @@ import java.util.UUID; public class CriticalEventLog { private static final String TAG = CriticalEventLog.class.getSimpleName(); + /** UID for system_server. */ + private static final int AID_SYSTEM = 1000; + private static CriticalEventLog sInstance; /** Name of the file the log is saved to. */ @@ -153,6 +158,27 @@ public class CriticalEventLog { log(event); } + /** + * Logs an ANR. + * + * @param subject the ANR subject line. + * @param processClassEnum {@link android.server.ServerProtoEnums} value for the ANRing process. + * @param processName name of the ANRing process. + * @param uid uid of the ANRing process. + * @param pid pid of the ANRing process. + */ + public void logAnr(String subject, int processClassEnum, String processName, int uid, int pid) { + AppNotResponding anr = new AppNotResponding(); + anr.subject = subject; + anr.processClass = processClassEnum; + anr.process = processName; + anr.uid = uid; + anr.pid = pid; + CriticalEventProto event = new CriticalEventProto(); + event.setAnr(anr); + log(event); + } + private void log(CriticalEventProto event) { event.timestampMs = getWallTimeMillis(); mEvents.append(event); @@ -160,14 +186,37 @@ public class CriticalEventLog { } /** - * Returns recent critical events in text format to include in logs such as ANR files. + * Returns recent critical events in text format to include in system server ANR stack trace + * file. * * Includes all events in the ring buffer with age less than or equal to {@code mWindowMs}. */ - public String logLinesForAnrFile() { + public String logLinesForSystemServerTraceFile() { + return logLinesForTraceFile(ServerProtoEnums.SYSTEM_SERVER, "AID_SYSTEM", AID_SYSTEM); + } + + /** + * Returns recent critical events in text format to include in logs such as ANR stack trace + * files. + * + * Includes all events in the ring buffer with age less than or equal to {@code mWindowMs}. + * + * Some data in the returned log may be redacted for privacy. For example, a log for a data + * app will not include specific crash information for a different data app. See + * {@link LogSanitizer} for more information. + * + * @param traceProcessClassEnum {@link android.server.ServerProtoEnums} value for the process + * the ANR trace file is for. + * @param traceProcessName name of the process the ANR trace file is for. + * @param traceUid uid of the process the ANR trace file is for. + */ + public String logLinesForTraceFile(int traceProcessClassEnum, String traceProcessName, + int traceUid) { + CriticalEventLogProto outputLogProto = getOutputLogProto(traceProcessClassEnum, + traceProcessName, traceUid); return new StringBuilder() .append("--- CriticalEventLog ---\n") - .append(MessageNanoPrinter.print(getRecentEvents())) + .append(MessageNanoPrinter.print(outputLogProto)) .append('\n').toString(); } @@ -177,12 +226,20 @@ public class CriticalEventLog { * Includes all events in the ring buffer with age less than or equal to {@code mWindowMs}. */ @VisibleForTesting - protected CriticalEventLogProto getRecentEvents() { + protected CriticalEventLogProto getOutputLogProto(int traceProcessClassEnum, + String traceProcessName, int traceUid) { CriticalEventLogProto log = new CriticalEventLogProto(); log.timestampMs = getWallTimeMillis(); log.windowMs = mWindowMs; log.capacity = mEvents.capacity(); - log.events = recentEventsWithMinTimestamp(log.timestampMs - mWindowMs); + + CriticalEventProto[] events = recentEventsWithMinTimestamp(log.timestampMs - mWindowMs); + LogSanitizer sanitizer = new LogSanitizer(traceProcessClassEnum, traceProcessName, + traceUid); + for (int i = 0; i < events.length; i++) { + events[i] = sanitizer.process(events[i]); + } + log.events = events; return log; } @@ -325,4 +382,68 @@ public class CriticalEventLog { } } } + + /** + * Redacts private data app fields from the critical event protos. + * + * When a critical event log is requested, this class is used to redact specific information + * so that the trace file for a data app does not leak private information about other data + * apps. + */ + private static class LogSanitizer { + /** + * The {@link CriticalEventProto.ProcessClass} of the process the output trace file is for. + */ + int mTraceProcessClassEnum; + + /** The name of the process that the output trace file is for. */ + String mTraceProcessName; + + /** The uid of the process that the output trace file is for. */ + int mTraceUid; + + LogSanitizer(int traceProcessClassEnum, String traceProcessName, int traceUid) { + mTraceProcessClassEnum = traceProcessClassEnum; + mTraceProcessName = traceProcessName; + mTraceUid = traceUid; + } + + /** + * Redacts information from a critical event proto where necessary. + * + * This function does not mutate its input. If redaction happens, it returns a new proto. + * Otherwise, it returns the original proto. + */ + CriticalEventProto process(CriticalEventProto event) { + if (event.hasAnr()) { + AppNotResponding anr = event.getAnr(); + if (shouldSanitize(anr.processClass, anr.process, anr.uid)) { + return sanitizeAnr(event); + } + } + return event; + } + + private boolean shouldSanitize(int processClassEnum, String processName, int uid) { + boolean sameApp = processName != null && processName.equals(mTraceProcessName) + && mTraceUid == uid; + + // Only sanitize when both the ANR event and trace file are for different data apps. + return processClassEnum == CriticalEventProto.DATA_APP + && mTraceProcessClassEnum == CriticalEventProto.DATA_APP + && !sameApp; + } + + private static CriticalEventProto sanitizeAnr(CriticalEventProto base) { + CriticalEventProto sanitized = new CriticalEventProto(); + sanitized.timestampMs = base.timestampMs; + AppNotResponding anr = new AppNotResponding(); + sanitized.setAnr(anr); + // Do not set subject and process. + anr.processClass = base.getAnr().processClass; + anr.uid = base.getAnr().uid; + anr.pid = base.getAnr().pid; + return sanitized; + } + } } diff --git a/services/core/java/com/android/server/wm/AnrController.java b/services/core/java/com/android/server/wm/AnrController.java index fa43b39765337..98cd40a11c6f6 100644 --- a/services/core/java/com/android/server/wm/AnrController.java +++ b/services/core/java/com/android/server/wm/AnrController.java @@ -213,7 +213,7 @@ class AnrController { } } - String criticalEvents = CriticalEventLog.getInstance().logLinesForAnrFile(); + String criticalEvents = CriticalEventLog.getInstance().logLinesForSystemServerTraceFile(); final File tracesFile = ActivityManagerService.dumpStackTraces(firstPids, null /* processCpuTracker */, null /* lastPids */, nativePids, null /* logExceptionCreatingFile */, "Pre-dump", criticalEvents); diff --git a/services/tests/servicestests/src/com/android/server/criticalevents/CriticalEventLogTest.java b/services/tests/servicestests/src/com/android/server/criticalevents/CriticalEventLogTest.java index dca666cda6b6f..54e75aacaf061 100644 --- a/services/tests/servicestests/src/com/android/server/criticalevents/CriticalEventLogTest.java +++ b/services/tests/servicestests/src/com/android/server/criticalevents/CriticalEventLogTest.java @@ -19,12 +19,15 @@ package com.android.server.criticalevents; import static com.google.common.truth.Truth.assertThat; import static com.google.common.truth.Truth.assertWithMessage; +import android.server.ServerProtoEnums; + import com.android.framework.protobuf.nano.MessageNano; import com.android.server.criticalevents.CriticalEventLog.ILogLoader; import com.android.server.criticalevents.CriticalEventLog.LogLoader; import com.android.server.criticalevents.nano.CriticalEventLogProto; import com.android.server.criticalevents.nano.CriticalEventLogStorageProto; import com.android.server.criticalevents.nano.CriticalEventProto; +import com.android.server.criticalevents.nano.CriticalEventProto.AppNotResponding; import com.android.server.criticalevents.nano.CriticalEventProto.HalfWatchdog; import com.android.server.criticalevents.nano.CriticalEventProto.Watchdog; @@ -63,6 +66,13 @@ public class CriticalEventLogTest { private static final String UUID_STRING = "123e4567-e89b-12d3-a456-556642440000"; + private static final int SYSTEM_SERVER_UID = 1000; + private static final int SYSTEM_APP_UID = 1001; + + private static final int DATA_APP_UID = 10_001; + private static final int DATA_APP_UID_2 = 10_002; + private static final int DATA_APP_UID_3 = 10_003; + @Rule public TemporaryFolder mFolder = new TemporaryFolder(); @@ -80,7 +90,7 @@ public class CriticalEventLogTest { createTestFileWithEvents(2); setLogInstance(); // Log instance reads the proto file at initialization. - CriticalEventLogProto logProto = mCriticalEventLog.getRecentEvents(); + CriticalEventLogProto logProto = getLogOutput(); assertThat(logProto.timestampMs).isEqualTo(START_TIME_MS); assertProtoArrayEquals( @@ -96,7 +106,7 @@ public class CriticalEventLogTest { mTestFile.delete(); setLogInstance(); - CriticalEventLogProto logProto = mCriticalEventLog.getRecentEvents(); + CriticalEventLogProto logProto = getLogOutput(); assertThat(logProto.timestampMs).isEqualTo(START_TIME_MS); assertThat(logProto.events).isEmpty(); @@ -107,7 +117,7 @@ public class CriticalEventLogTest { mFolder.delete(); setLogInstance(); - CriticalEventLogProto logProto = mCriticalEventLog.getRecentEvents(); + CriticalEventLogProto logProto = getLogOutput(); assertThat(logProto.timestampMs).isEqualTo(START_TIME_MS); assertThat(logProto.events).isEmpty(); @@ -119,7 +129,7 @@ public class CriticalEventLogTest { mTestFile.setReadable(false); setLogInstance(); - CriticalEventLogProto logProto = mCriticalEventLog.getRecentEvents(); + CriticalEventLogProto logProto = getLogOutput(); assertThat(logProto.timestampMs).isEqualTo(START_TIME_MS); assertThat(logProto.events).isEmpty(); @@ -132,7 +142,7 @@ public class CriticalEventLogTest { } setLogInstance(); - CriticalEventLogProto logProto = mCriticalEventLog.getRecentEvents(); + CriticalEventLogProto logProto = getLogOutput(); assertThat(logProto.timestampMs).isEqualTo(START_TIME_MS); assertThat(logProto.events).isEmpty(); @@ -143,7 +153,7 @@ public class CriticalEventLogTest { createTestFileWithEvents(0); setLogInstance(); - CriticalEventLogProto logProto = mCriticalEventLog.getRecentEvents(); + CriticalEventLogProto logProto = getLogOutput(); assertThat(logProto.timestampMs).isEqualTo(START_TIME_MS); assertThat(logProto.events).isEmpty(); @@ -154,7 +164,7 @@ public class CriticalEventLogTest { createTestFileWithEvents(10); // Ring buffer capacity is 5 setLogInstance(); - CriticalEventLogProto logProto = mCriticalEventLog.getRecentEvents(); + CriticalEventLogProto logProto = getLogOutput(); assertThat(logProto.timestampMs).isEqualTo(START_TIME_MS); // Log contains the last 5 events only. @@ -170,7 +180,7 @@ public class CriticalEventLogTest { } @Test - public void logLinesForAnrFile() { + public void logLinesForTraceFile() { mCriticalEventLog.incTimeSeconds(1); mCriticalEventLog.logWatchdog("Watchdog subject", UUID.fromString("123e4567-e89b-12d3-a456-556642440000")); @@ -178,7 +188,7 @@ public class CriticalEventLogTest { mCriticalEventLog.logHalfWatchdog("Half watchdog subject"); mCriticalEventLog.incTimeSeconds(1); - assertThat(mCriticalEventLog.logLinesForAnrFile()).isEqualTo( + assertThat(mCriticalEventLog.logLinesForSystemServerTraceFile()).isEqualTo( "--- CriticalEventLog ---\n" + "capacity: 5\n" + "events <\n" @@ -205,7 +215,7 @@ public class CriticalEventLogTest { UUID.fromString("123e4567-e89b-12d3-a456-556642440000")); mCriticalEventLog.incTimeSeconds(1); - CriticalEventLogProto logProto = mCriticalEventLog.getRecentEvents(); + CriticalEventLogProto logProto = getLogOutput(); assertThat(logProto.timestampMs).isEqualTo(START_TIME_MS + 2000); assertProtoArrayEquals(logProto.events, new CriticalEventProto[]{ @@ -220,7 +230,7 @@ public class CriticalEventLogTest { mCriticalEventLog.logHalfWatchdog("Subject 1"); mCriticalEventLog.incTimeSeconds(1); - CriticalEventLogProto logProto = mCriticalEventLog.getRecentEvents(); + CriticalEventLogProto logProto = getLogOutput(); assertThat(logProto.timestampMs).isEqualTo(START_TIME_MS + 2000); assertProtoArrayEquals(logProto.events, new CriticalEventProto[]{ @@ -228,6 +238,108 @@ public class CriticalEventLogTest { }); } + @Test + public void logAnr() { + mCriticalEventLog.incTimeSeconds(1); + mCriticalEventLog.logAnr("Subject 1", ServerProtoEnums.SYSTEM_SERVER, "AID_SYSTEM", + SYSTEM_SERVER_UID, 0); + mCriticalEventLog.incTimeSeconds(1); + + CriticalEventLogProto logProto = getLogOutput(); + + assertThat(logProto.timestampMs).isEqualTo(START_TIME_MS + 2000); + assertProtoArrayEquals(logProto.events, new CriticalEventProto[]{ + anr(START_TIME_MS + 1000, "Subject 1", ServerProtoEnums.SYSTEM_SERVER, + "AID_SYSTEM", SYSTEM_SERVER_UID, 0) + }); + } + + @Test + public void privacyRedaction_anr() { + mCriticalEventLog.incTimeSeconds(1); + mCriticalEventLog.logAnr("Subject 1", ServerProtoEnums.SYSTEM_SERVER, "AID_SYSTEM", + SYSTEM_SERVER_UID, 0); + mCriticalEventLog.incTimeSeconds(1); + mCriticalEventLog.logAnr("Subject 2", ServerProtoEnums.SYSTEM_APP, "AID_RADIO", + SYSTEM_APP_UID, 1); + mCriticalEventLog.incTimeSeconds(1); + mCriticalEventLog.logAnr("Subject 3", ServerProtoEnums.DATA_APP, "com.foo", + DATA_APP_UID, 2); + mCriticalEventLog.incTimeSeconds(1); + mCriticalEventLog.logAnr("Subject 4", ServerProtoEnums.DATA_APP, "com.foo", + DATA_APP_UID_2, 3); + mCriticalEventLog.incTimeSeconds(1); + mCriticalEventLog.logAnr("Subject 5", ServerProtoEnums.DATA_APP, "com.bar", + DATA_APP_UID_3, 4); + mCriticalEventLog.incTimeSeconds(1); + + CriticalEventProto systemServerAnr = anr(START_TIME_MS + 1000, "Subject 1", + CriticalEventProto.SYSTEM_SERVER, "AID_SYSTEM", SYSTEM_SERVER_UID, 0); + CriticalEventProto systemAppAnr = anr(START_TIME_MS + 2000, "Subject 2", + CriticalEventProto.SYSTEM_APP, + "AID_RADIO", SYSTEM_APP_UID, 1); + CriticalEventProto fooAppAnr = anr(START_TIME_MS + 3000, "Subject 3", + CriticalEventProto.DATA_APP, "com.foo", DATA_APP_UID, 2); + CriticalEventProto fooAppAnrUid2 = anr(START_TIME_MS + 4000, "Subject 4", + CriticalEventProto.DATA_APP, "com.foo", DATA_APP_UID_2, 3); + CriticalEventProto fooAppAnrUid2Redacted = anr(START_TIME_MS + 4000, "", + CriticalEventProto.DATA_APP, "", DATA_APP_UID_2, 3); + CriticalEventProto barAppAnr = anr(START_TIME_MS + 5000, "Subject 5", + CriticalEventProto.DATA_APP, "com.bar", DATA_APP_UID_3, 4); + CriticalEventProto barAppAnrRedacted = anr(START_TIME_MS + 5000, "", + CriticalEventProto.DATA_APP, "", DATA_APP_UID_3, 4); + + assertProtoArrayEquals( + getLogOutput(ServerProtoEnums.DATA_APP, "com.foo", DATA_APP_UID).events, + new CriticalEventProto[]{ + systemServerAnr, + systemAppAnr, + fooAppAnr, + // Redacted since the trace file and ANR are for different uids. + fooAppAnrUid2Redacted, + // Redacted since the trace file and ANR are for different data apps. + barAppAnrRedacted + }); + + assertProtoArrayEquals( + getLogOutput(ServerProtoEnums.SYSTEM_SERVER, "AID_SYSTEM", + SYSTEM_SERVER_UID).events, + new CriticalEventProto[]{ + systemServerAnr, + systemAppAnr, + fooAppAnr, + fooAppAnrUid2, + barAppAnr + }); + + assertProtoArrayEquals( + getLogOutput(ServerProtoEnums.SYSTEM_APP, "AID_RADIO", + SYSTEM_APP_UID).events, + new CriticalEventProto[]{ + systemServerAnr, + systemAppAnr, + fooAppAnr, + fooAppAnrUid2, + barAppAnr + }); + } + + @Test + public void privacyRedaction_anr_doesNotMutateLogState() { + mCriticalEventLog.logAnr("Subject", ServerProtoEnums.DATA_APP, "com.foo", + 10_001, DATA_APP_UID); + + CriticalEventLogProto unredactedLogBefore = getLogOutput(ServerProtoEnums.SYSTEM_SERVER, + "AID_SYSTEM", SYSTEM_SERVER_UID); + CriticalEventLogProto redactedLog = getLogOutput(ServerProtoEnums.DATA_APP, "com.bar", + DATA_APP_UID); + CriticalEventLogProto unredactedLogAfter = getLogOutput(ServerProtoEnums.SYSTEM_SERVER, + "AID_SYSTEM", SYSTEM_SERVER_UID); + + assertProtoNotEqual(unredactedLogBefore, redactedLog); // verify some redaction took place. + assertProtoEquals(unredactedLogBefore, unredactedLogAfter); + } + @Test public void getOutputLogProto_numberOfEventsExceedsCapacity() { // Log 10 events in 10 sec (capacity = 5) @@ -237,7 +349,7 @@ public class CriticalEventLogTest { mCriticalEventLog.incTimeSeconds(1); } - CriticalEventLogProto logProto = mCriticalEventLog.getRecentEvents(); + CriticalEventLogProto logProto = getLogOutput(); assertThat(logProto.timestampMs).isEqualTo(START_TIME_MS + 10000); assertThat(logProto.windowMs).isEqualTo(300_000); // 5 minutes @@ -270,7 +382,7 @@ public class CriticalEventLogTest { mCriticalEventLog.logHalfWatchdog("New event 2"); // 5m59s old mCriticalEventLog.setCurrentTimeMillis(logTimestamp); - CriticalEventLogProto logProto = mCriticalEventLog.getRecentEvents(); + CriticalEventLogProto logProto = getLogOutput(); assertThat(logProto.timestampMs).isEqualTo(logTimestamp); assertThat(logProto.windowMs).isEqualTo(300_000); // 5 minutes @@ -288,7 +400,7 @@ public class CriticalEventLogTest { createTestFileWithEvents(5); setLogInstance(new NoOpLogLoader()); - CriticalEventLogProto logProto = mCriticalEventLog.getRecentEvents(); + CriticalEventLogProto logProto = getLogOutput(); // Output log is empty. assertThat(logProto.timestampMs).isEqualTo(START_TIME_MS); @@ -350,7 +462,7 @@ public class CriticalEventLogTest { log2.logHalfWatchdog("New subject"); log2.incTimeSeconds(1); - CriticalEventLogProto logProto = log2.getRecentEvents(); + CriticalEventLogProto logProto = getLogOutput(log2); // Log contains 4 + 1 events. assertThat(logProto.timestampMs).isEqualTo(START_TIME_MS + 21_000); @@ -363,6 +475,38 @@ public class CriticalEventLogTest { }); } + @Test + public void processClassEnumParity() { + String message = "CriticalEventProto.ProcessClass and ServerProtoEnum are out of sync."; + assertWithMessage(message).that(CriticalEventProto.PROCESS_CLASS_UNKNOWN).isEqualTo( + ServerProtoEnums.ERROR_SOURCE_UNKNOWN); + assertWithMessage(message).that(CriticalEventProto.DATA_APP).isEqualTo( + ServerProtoEnums.DATA_APP); + assertWithMessage(message).that(CriticalEventProto.SYSTEM_APP).isEqualTo( + ServerProtoEnums.SYSTEM_APP); + assertWithMessage(message).that(CriticalEventProto.SYSTEM_SERVER).isEqualTo( + ServerProtoEnums.SYSTEM_SERVER); + } + + private CriticalEventLogProto getLogOutput() { + return getLogOutput(mCriticalEventLog); + } + + private CriticalEventLogProto getLogOutput(CriticalEventLog log) { + return getLogOutput(log, ServerProtoEnums.SYSTEM_SERVER, "AID_SYSTEM", SYSTEM_SERVER_UID); + } + + private CriticalEventLogProto getLogOutput(int traceProcessClassEnum, + String traceProcessName, int traceProcessUid) { + return getLogOutput(mCriticalEventLog, traceProcessClassEnum, traceProcessName, + traceProcessUid); + } + + private CriticalEventLogProto getLogOutput(CriticalEventLog log, int traceProcessClassEnum, + String traceProcessName, int traceProcessUid) { + return log.getOutputLogProto(traceProcessClassEnum, traceProcessName, traceProcessUid); + } + private CriticalEventLogStorageProto getEventsWritten() throws IOException { return CriticalEventLogStorageProto.parseFrom( Files.readAllBytes(mTestFile.toPath())); @@ -389,6 +533,20 @@ public class CriticalEventLogTest { } } + private static CriticalEventProto anr(long timestampMs, String subject, int processClass, + String processName, + int uid, int pid) { + CriticalEventProto event = new CriticalEventProto(); + event.timestampMs = timestampMs; + event.setAnr(new AppNotResponding()); + event.getAnr().subject = subject; + event.getAnr().processClass = processClass; + event.getAnr().process = processName; + event.getAnr().uid = uid; + event.getAnr().pid = pid; + return event; + } + private CriticalEventProto watchdog(long timestampMs, String subject) { return watchdog(timestampMs, subject, "A UUID"); } @@ -414,15 +572,32 @@ public class CriticalEventLogTest { assertThat(expected).isNotNull(); assertThat(actual).isNotNull(); - String message = - "Expected:\n" + Arrays.toString(expected) + "\nGot:\n" + Arrays.toString(actual); - assertWithMessage(message).that(expected.length).isEqualTo(actual.length); + String baseMsg = String.format("Expected:\n%s\nGot:\n%s", Arrays.toString(expected), + Arrays.toString(actual)); + String lengthMsg = String.format("%s\nGot different length arrays.\bExpected %d, got %d", + baseMsg, expected.length, actual.length); + assertWithMessage(lengthMsg).that(expected.length).isEqualTo(actual.length); for (int i = 0; i < expected.length; i++) { - assertWithMessage(message).that( + String pairMsg = String.format("%s\nMismatched pair.\nExpected:\n%s\nGot:\n%s", + baseMsg, expected[i], actual[i]); + assertWithMessage(pairMsg).that( MessageNano.messageNanoEquals(expected[i], actual[i])).isTrue(); } } + private static void assertProtoEquals(MessageNano actual, MessageNano expected) { + String message = String.format("Expected:\n%s\nGot:\n%s", expected, actual); + assertWithMessage(message).that( + MessageNano.messageNanoEquals(expected, actual)).isTrue(); + } + + private static void assertProtoNotEqual(MessageNano first, MessageNano second) { + String message = String.format("Expected protos to be different, but were equal:\n%s", + first); + assertWithMessage(message).that( + MessageNano.messageNanoEquals(first, second)).isFalse(); + } + private TestableCriticalEventLog setLogInstance() { return setLogInstance(new LogLoader()); }