From fdbfa3b5d9a1ecb62637dfe6f13fd517f01be123 Mon Sep 17 00:00:00 2001 From: Ben Miles Date: Fri, 20 Aug 2021 15:48:18 +0100 Subject: [PATCH] Add critical event log The critical event log is a small (20 items) log of recent "critical events" such as watchdogs and half-watchdogs. Events from the log that occurred in the last 5 minutes are dumped to ANR files and ANR dropbox entries in textproto format. This change adds the log itself & support for logging watchdogs and half-watchdogs. Other event types such as system server crashes will be added in follow-up CLs. Bug: 200263868 Test: atest CriticalEventLogTest Change-Id: I431e15c5d5c16a358cd0eea30682078d04257499 --- proto/src/critical_event_log.proto | 78 +++ .../server/SystemServerInitThreadPool.java | 2 +- .../java/com/android/server/Watchdog.java | 20 +- .../server/am/ActivityManagerService.java | 23 +- .../android/server/am/CriticalEventLog.java | 328 ++++++++++++ .../server/am/ProcessErrorStateRecord.java | 3 +- .../com/android/server/wm/AnrController.java | 4 +- services/tests/servicestests/Android.bp | 1 + .../server/am/CriticalEventLogTest.java | 475 ++++++++++++++++++ 9 files changed, 917 insertions(+), 17 deletions(-) create mode 100644 proto/src/critical_event_log.proto create mode 100644 services/core/java/com/android/server/am/CriticalEventLog.java create mode 100644 services/tests/servicestests/src/com/android/server/am/CriticalEventLogTest.java diff --git a/proto/src/critical_event_log.proto b/proto/src/critical_event_log.proto new file mode 100644 index 0000000000000..cb05a714ac5f4 --- /dev/null +++ b/proto/src/critical_event_log.proto @@ -0,0 +1,78 @@ +/* + * Copyright (C) 2021 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. + */ + +syntax = "proto2"; +package com.android.server.am; + +option java_multiple_files = true; + +// Output proto containing recent critical events for inclusion in logs such as ANR files. +// Do not change the field names since this data is dumped to ANR files in textproto format. +message CriticalEventLogProto { + // Timestamp when the log snapshot was generated. + // Required. + optional int64 timestamp_ms = 1; + + // Max age of events that are included in this proto. + // Required. + optional int32 window_ms = 2; + + // Max number of events in the log. + // Note: if the number of events is equal to the capacity then it is likely the actual time range + // covered by the log is shorter than window_ms. + // Required. + optional int32 capacity = 3; + + // Recent critical events. + repeated CriticalEventProto events = 4; +} + +// On-disk storage of events. +message CriticalEventLogStorageProto { + repeated CriticalEventProto events = 1; +} + +// A "critical" event such as an ANR or watchdog. +// Do not change the field names since this data is dumped to ANR files in textproto format. +message CriticalEventProto { + // Timestamp of the event. + // Required. + optional int64 timestamp_ms = 1; + + // Required. + oneof event { + Watchdog watchdog = 2; + HalfWatchdog half_watchdog = 3; + } + + message Watchdog { + // The watchdog subject. + // Required. + optional string subject = 1; + + // Unique identifier of the watchdog. + // Can be used to join with other data for this watchdog such as stack dumps & perfetto traces. + // Generated in {@link com.android.server.Watchdog#run}. + // Required. + optional string uuid = 2; + } + + message HalfWatchdog { + // The half-watchdog subject. + // Required. + optional string subject = 1; + } +} \ No newline at end of file diff --git a/services/core/java/com/android/server/SystemServerInitThreadPool.java b/services/core/java/com/android/server/SystemServerInitThreadPool.java index 364e73381bb9a..53b660533ce2b 100644 --- a/services/core/java/com/android/server/SystemServerInitThreadPool.java +++ b/services/core/java/com/android/server/SystemServerInitThreadPool.java @@ -192,7 +192,7 @@ public final class SystemServerInitThreadPool implements Dumpable { final ArrayList pids = new ArrayList<>(); pids.add(Process.myPid()); ActivityManagerService.dumpStackTraces(pids, null, null, - Watchdog.getInterestingNativePids(), null, null); + Watchdog.getInterestingNativePids(), null, null, null); } @Override diff --git a/services/core/java/com/android/server/Watchdog.java b/services/core/java/com/android/server/Watchdog.java index fcd049f1c4944..46efa3cd876ee 100644 --- a/services/core/java/com/android/server/Watchdog.java +++ b/services/core/java/com/android/server/Watchdog.java @@ -45,6 +45,7 @@ import com.android.internal.os.ProcessCpuTracker; import com.android.internal.os.ZygoteConnectionConstants; import com.android.internal.util.FrameworkStatsLog; import com.android.server.am.ActivityManagerService; +import com.android.server.am.CriticalEventLog; import com.android.server.am.TraceErrorLogger; import com.android.server.wm.SurfaceAnimationThread; @@ -661,10 +662,15 @@ public class Watchdog { } // END synchronized (mLock) 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(); + CriticalEventLog.getInstance().logHalfWatchdog(subject); + // We've waited half the deadlock-detection interval. Pull a stack // trace and wait another half. ActivityManagerService.dumpStackTraces(pids, null, null, - getInterestingNativePids(), null, subject); + getInterestingNativePids(), null, subject, criticalEvents); continue; } @@ -673,12 +679,9 @@ public class Watchdog { // Then kill this process so that the system will restart. EventLog.writeEvent(EventLogTags.WATCHDOG, subject); - final UUID errorId; + final UUID errorId = mTraceErrorLogger.generateErrorId(); if (mTraceErrorLogger.isAddErrorIdEnabled()) { - errorId = mTraceErrorLogger.generateErrorId(); mTraceErrorLogger.addErrorIdToTrace("system_server", errorId); - } else { - errorId = null; } // Log the atom as early as possible since it is used as a mechanism to trigger @@ -686,6 +689,11 @@ public class Watchdog { // point in time when the Watchdog happens as possible. FrameworkStatsLog.write(FrameworkStatsLog.SYSTEM_SERVER_WATCHDOG_OCCURRED, subject); + // Get critical event log before logging the watchdog so that it doesn't occur in the + // log. + String criticalEvents = CriticalEventLog.getInstance().logLinesForAnrFile(); + CriticalEventLog.getInstance().logWatchdog(subject, errorId); + long anrTime = SystemClock.uptimeMillis(); StringBuilder report = new StringBuilder(); report.append(MemoryPressureUtil.currentPsiState()); @@ -693,7 +701,7 @@ public class Watchdog { StringWriter tracesFileException = new StringWriter(); final File stack = ActivityManagerService.dumpStackTraces( pids, processCpuTracker, new SparseArray<>(), getInterestingNativePids(), - tracesFileException, subject); + tracesFileException, subject, criticalEvents); // Give some extra time to make sure the stack traces get written. // The system's been hanging for a minute, another second or two won't hurt much. diff --git a/services/core/java/com/android/server/am/ActivityManagerService.java b/services/core/java/com/android/server/am/ActivityManagerService.java index da6eeb6c79024..5eb12ccec0ce1 100644 --- a/services/core/java/com/android/server/am/ActivityManagerService.java +++ b/services/core/java/com/android/server/am/ActivityManagerService.java @@ -2394,6 +2394,7 @@ public class ActivityManagerService extends IActivityManager.Stub private void start() { removeAllProcessGroups(); + CriticalEventLog.init(); mBatteryStatsService.publish(); mAppOpsService.publish(); Slog.d("AppOps", "AppOpsService published"); @@ -3199,7 +3200,7 @@ public class ActivityManagerService extends IActivityManager.Stub ProcessCpuTracker processCpuTracker, SparseArray lastPids, ArrayList nativePids, StringWriter logExceptionCreatingFile) { return dumpStackTraces(firstPids, processCpuTracker, lastPids, nativePids, - logExceptionCreatingFile, null, null); + logExceptionCreatingFile, null, null, null); } /** @@ -3209,13 +3210,14 @@ public class ActivityManagerService extends IActivityManager.Stub * @param nativePids optional list of native pids to dump stack crawls * @param logExceptionCreatingFile optional writer to which we log errors creating the file * @param subject optional line related to the error + * @param criticalEventSection optional lines containing recent critical events. */ public static File dumpStackTraces(ArrayList firstPids, ProcessCpuTracker processCpuTracker, SparseArray lastPids, ArrayList nativePids, StringWriter logExceptionCreatingFile, - String subject) { + String subject, String criticalEventSection) { return dumpStackTraces(firstPids, processCpuTracker, lastPids, nativePids, - logExceptionCreatingFile, null, subject); + logExceptionCreatingFile, null, subject, criticalEventSection); } /** @@ -3225,7 +3227,7 @@ public class ActivityManagerService extends IActivityManager.Stub /* package */ static File dumpStackTraces(ArrayList firstPids, ProcessCpuTracker processCpuTracker, SparseArray lastPids, ArrayList nativePids, StringWriter logExceptionCreatingFile, - long[] firstPidOffsets, String subject) { + long[] firstPidOffsets, String subject, String criticalEventSection) { ArrayList extraPids = null; Slog.i(TAG, "dumpStackTraces pids=" + lastPids + " nativepids=" + nativePids); @@ -3277,12 +3279,17 @@ public class ActivityManagerService extends IActivityManager.Stub return null; } - if (subject != null) { + if (subject != null || criticalEventSection != null) { try (FileOutputStream fos = new FileOutputStream(tracesFile, true)) { - String header = "Subject: " + subject + "\n"; - fos.write(header.getBytes(StandardCharsets.UTF_8)); + if (subject != null) { + String header = "Subject: " + subject + "\n\n"; + fos.write(header.getBytes(StandardCharsets.UTF_8)); + } + if (criticalEventSection != null) { + fos.write(criticalEventSection.getBytes(StandardCharsets.UTF_8)); + } } catch (IOException e) { - Slog.w(TAG, "Exception writing subject to ANR dump file:", e); + Slog.w(TAG, "Exception writing to ANR dump file:", e); } } diff --git a/services/core/java/com/android/server/am/CriticalEventLog.java b/services/core/java/com/android/server/am/CriticalEventLog.java new file mode 100644 index 0000000000000..6b695598b83f3 --- /dev/null +++ b/services/core/java/com/android/server/am/CriticalEventLog.java @@ -0,0 +1,328 @@ +/* + * Copyright (C) 2021 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.server.am; + +import android.os.Handler; +import android.os.HandlerThread; +import android.util.Slog; + +import com.android.framework.protobuf.nano.MessageNanoPrinter; +import com.android.internal.annotations.VisibleForTesting; +import com.android.internal.util.RingBuffer; +import com.android.server.am.nano.CriticalEventLogProto; +import com.android.server.am.nano.CriticalEventLogStorageProto; +import com.android.server.am.nano.CriticalEventProto; +import com.android.server.am.nano.CriticalEventProto.HalfWatchdog; +import com.android.server.am.nano.CriticalEventProto.Watchdog; + +import java.io.File; +import java.io.FileOutputStream; +import java.io.IOException; +import java.nio.file.Files; +import java.nio.file.Paths; +import java.time.Duration; +import java.util.Arrays; +import java.util.UUID; + +/** + * Log of recent critical events such as Watchdogs. + * + * For use in ANR reports to show recent events that may help to debug the ANR. In particular, + * the presence of recent critical events signal that the device was already in a had state. + * + * This class needs to be thread safe since it's used as a singleton. + */ +public class CriticalEventLog { + private static final String TAG = CriticalEventLog.class.getSimpleName(); + + private static CriticalEventLog sInstance; + + /** Name of the file the log is saved to. */ + @VisibleForTesting + static final String FILENAME = "critical_event_log.pb"; + + /** Timestamp when the log was last saved (or attempted to be saved) to disk. */ + private long mLastSaveAttemptMs = 0; + + /** File the log is saved to. */ + private final File mLogFile; + + /** Ring buffer containing the log events. */ + private final ThreadSafeRingBuffer mEvents; + + /** Max age of events to include in the output log proto. */ + private final int mWindowMs; + + /** Minimum time between consecutive saves of the log to disk. */ + private final long mMinTimeBetweenSavesMs; + + /** Whether to load and save the log synchronously with no delay. Only set to true in tests. */ + private final boolean mLoadAndSaveImmediately; + + private final Handler mHandler; + + private final Runnable mSaveRunnable = this::saveLogToFileNow; + + @VisibleForTesting + CriticalEventLog(String logDir, int capacity, int windowMs, long minTimeBetweenSavesMs, + boolean loadAndSaveImmediately, ILogLoader logLoader) { + mLogFile = Paths.get(logDir, FILENAME).toFile(); + mWindowMs = windowMs; + mMinTimeBetweenSavesMs = minTimeBetweenSavesMs; + mLoadAndSaveImmediately = loadAndSaveImmediately; + + mEvents = new ThreadSafeRingBuffer<>(CriticalEventProto.class, capacity); + + HandlerThread thread = new HandlerThread("CriticalEventLogIO"); + thread.start(); + mHandler = new Handler(thread.getLooper()); + + final Runnable loadEvents = () -> logLoader.load(mLogFile, mEvents); + if (!mLoadAndSaveImmediately) { + mHandler.post(loadEvents); + } else { + loadEvents.run(); + } + } + + /** Returns a new instance with production settings. */ + private CriticalEventLog() { + this( + /* logDir= */"/data/misc/critical-events", + /* capacity= */ 20, + /* windowMs= */ (int) Duration.ofMinutes(5).toMillis(), + /* minTimeBetweenSavesMs= */ Duration.ofSeconds(2).toMillis(), + /* loadAndSaveImmediately= */ false, + new LogLoader()); + } + + /** Returns the singleton instance. */ + public static CriticalEventLog getInstance() { + if (sInstance == null) { + sInstance = new CriticalEventLog(); + } + return sInstance; + } + + /** + * Ensures the singleton instance has been instantiated. + * + * Use this to eagerly instantiate the log (which loads the previous events from disk). + * Otherwise this will occur lazily when the first event is logged, by which time the device may + * be under load. + */ + public static void init() { + getInstance(); + } + + @VisibleForTesting + protected long getWallTimeMillis() { + return System.currentTimeMillis(); + } + + /** Logs a watchdog. */ + public void logWatchdog(String subject, UUID uuid) { + Watchdog watchdog = new Watchdog(); + watchdog.subject = subject; + watchdog.uuid = uuid.toString(); + CriticalEventProto event = new CriticalEventProto(); + event.setWatchdog(watchdog); + log(event); + } + + /** Logs a half-watchdog. */ + public void logHalfWatchdog(String subject) { + HalfWatchdog halfWatchdog = new HalfWatchdog(); + halfWatchdog.subject = subject; + CriticalEventProto event = new CriticalEventProto(); + event.setHalfWatchdog(halfWatchdog); + log(event); + } + + private void log(CriticalEventProto event) { + event.timestampMs = getWallTimeMillis(); + mEvents.append(event); + saveLogToFile(); + } + + /** + * Returns recent critical events in text format to include in logs such as ANR files. + * + * Includes all events in the ring buffer with age less than or equal to {@code mWindowMs}. + */ + public String logLinesForAnrFile() { + return new StringBuilder() + .append("--- CriticalEventLog ---\n") + .append(MessageNanoPrinter.print(getRecentEvents())) + .append('\n').toString(); + } + + /** + * Returns a proto containing recent critical events. + * + * Includes all events in the ring buffer with age less than or equal to {@code mWindowMs}. + */ + @VisibleForTesting + protected CriticalEventLogProto getRecentEvents() { + CriticalEventLogProto log = new CriticalEventLogProto(); + log.timestampMs = getWallTimeMillis(); + log.windowMs = mWindowMs; + log.capacity = mEvents.capacity(); + log.events = recentEventsWithMinTimestamp(log.timestampMs - mWindowMs); + + return log; + } + + /** + * Returns the most recent logged events, starting with the first event that has a timestamp + * greater than or equal to {@code minTimestampMs}. + * + * If no events have a timestamp greater than or equal to {@code minTimestampMs}, returns an + * empty array. + */ + private CriticalEventProto[] recentEventsWithMinTimestamp(long minTimestampMs) { + // allEvents are in insertion order, i.e. in order of when the relevant log___() function + // was called. + // This means that if the system clock changed (e.g. a NITZ update) allEvents may not be + // strictly ordered by timestamp. In this case we are permissive and start with the + // first event that has a timestamp in the desired range. + CriticalEventProto[] allEvents = mEvents.toArray(); + for (int i = 0; i < allEvents.length; i++) { + if (allEvents[i].timestampMs >= minTimestampMs) { + return Arrays.copyOfRange(allEvents, i, allEvents.length); + } + } + return new CriticalEventProto[]{}; + } + + private void saveLogToFile() { + if (mLoadAndSaveImmediately) { + saveLogToFileNow(); + return; + } + if (mHandler.hasCallbacks(mSaveRunnable)) { + // An earlier save is already scheduled so don't need to schedule an additional one. + return; + } + + if (!mHandler.postDelayed(mSaveRunnable, saveDelayMs())) { + Slog.w(TAG, "Error scheduling save"); + } + } + + /** + * Returns the delay in milliseconds when scheduling a save on the handler thread. + * + * Returns a value in the range [0, {@code minTimeBetweenSavesMs}] such that the time between + * consecutive saves does not exceed {@code minTimeBetweenSavesMs}. + * + * This means that if the last save occurred a long time ago, or if no previous saves + * have occurred then the returned delay will be zero. + */ + @VisibleForTesting + protected long saveDelayMs() { + final long nowMs = getWallTimeMillis(); + return Math.max(0, + mLastSaveAttemptMs + mMinTimeBetweenSavesMs - nowMs); + } + + @VisibleForTesting + protected void saveLogToFileNow() { + mLastSaveAttemptMs = getWallTimeMillis(); + + File logDir = mLogFile.getParentFile(); + if (!logDir.exists()) { + if (!logDir.mkdir()) { + Slog.e(TAG, "Error creating log directory: " + logDir.getPath()); + return; + } + } + + if (!mLogFile.exists()) { + try { + mLogFile.createNewFile(); + } catch (IOException e) { + Slog.e(TAG, "Error creating log file", e); + return; + } + } + + CriticalEventLogStorageProto logProto = new CriticalEventLogStorageProto(); + logProto.events = mEvents.toArray(); + + final byte[] bytes = CriticalEventLogStorageProto.toByteArray(logProto); + try (FileOutputStream stream = new FileOutputStream(mLogFile, false)) { + stream.write(bytes); + } catch (IOException e) { + Slog.e(TAG, "Error saving log to disk.", e); + } + } + + @VisibleForTesting + protected static class ThreadSafeRingBuffer { + private final int mCapacity; + private final RingBuffer mBuffer; + + ThreadSafeRingBuffer(Class clazz, int capacity) { + this.mCapacity = capacity; + this.mBuffer = new RingBuffer<>(clazz, capacity); + } + + synchronized void append(T t) { + mBuffer.append(t); + } + + synchronized T[] toArray() { + return mBuffer.toArray(); + } + + int capacity() { + return mCapacity; + } + } + + /** Loads log events from disk into a ring buffer. */ + protected interface ILogLoader { + void load(File logFile, ThreadSafeRingBuffer buffer); + } + + /** Loads log events from disk into a ring buffer. */ + static class LogLoader implements ILogLoader { + @Override + public void load(File logFile, + ThreadSafeRingBuffer buffer) { + for (CriticalEventProto event : loadLogFromFile(logFile).events) { + buffer.append(event); + } + } + + private static CriticalEventLogStorageProto loadLogFromFile(File logFile) { + if (!logFile.exists()) { + Slog.i(TAG, "No log found, returning empty log proto."); + return new CriticalEventLogStorageProto(); + } + + try { + return CriticalEventLogStorageProto.parseFrom( + Files.readAllBytes(logFile.toPath())); + } catch (IOException e) { + Slog.e(TAG, "Error reading log from disk.", e); + return new CriticalEventLogStorageProto(); + } + } + } +} diff --git a/services/core/java/com/android/server/am/ProcessErrorStateRecord.java b/services/core/java/com/android/server/am/ProcessErrorStateRecord.java index a32fe02644d34..5fac8791b79ff 100644 --- a/services/core/java/com/android/server/am/ProcessErrorStateRecord.java +++ b/services/core/java/com/android/server/am/ProcessErrorStateRecord.java @@ -400,9 +400,10 @@ 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); + nativePids, tracesFileException, offsets, annotation, criticalEventLog); if (isMonitorCpuUsage()) { mService.updateCpuStatsNow(); diff --git a/services/core/java/com/android/server/wm/AnrController.java b/services/core/java/com/android/server/wm/AnrController.java index 892db9c33dbde..bf66107217301 100644 --- a/services/core/java/com/android/server/wm/AnrController.java +++ b/services/core/java/com/android/server/wm/AnrController.java @@ -31,6 +31,7 @@ import android.util.SparseArray; import android.view.InputApplicationHandle; import com.android.server.am.ActivityManagerService; +import com.android.server.am.CriticalEventLog; import com.android.server.wm.EmbeddedWindowController.EmbeddedWindow; import java.io.File; @@ -222,9 +223,10 @@ class AnrController { } } + String criticalEvents = CriticalEventLog.getInstance().logLinesForAnrFile(); final File tracesFile = ActivityManagerService.dumpStackTraces(firstPids, null /* processCpuTracker */, null /* lastPids */, nativePids, - null /* logExceptionCreatingFile */); + null /* logExceptionCreatingFile */, "Pre-dump", criticalEvents); if (tracesFile != null) { tracesFile.renameTo(new File(tracesFile.getParent(), tracesFile.getName() + "_pre")); } diff --git a/services/tests/servicestests/Android.bp b/services/tests/servicestests/Android.bp index ef9248af13abc..8848098825895 100644 --- a/services/tests/servicestests/Android.bp +++ b/services/tests/servicestests/Android.bp @@ -53,6 +53,7 @@ android_test { "testng", "ub-uiautomator", "platformprotosnano", + "framework-protos", "hamcrest-library", "servicestests-utils", "service-appsearch", diff --git a/services/tests/servicestests/src/com/android/server/am/CriticalEventLogTest.java b/services/tests/servicestests/src/com/android/server/am/CriticalEventLogTest.java new file mode 100644 index 0000000000000..903d7f2d86dbe --- /dev/null +++ b/services/tests/servicestests/src/com/android/server/am/CriticalEventLogTest.java @@ -0,0 +1,475 @@ +/* + * Copyright (C) 2021 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.server.am; + +import static com.google.common.truth.Truth.assertThat; +import static com.google.common.truth.Truth.assertWithMessage; + +import com.android.framework.protobuf.nano.MessageNano; +import com.android.server.am.CriticalEventLog.ILogLoader; +import com.android.server.am.CriticalEventLog.LogLoader; +import com.android.server.am.nano.CriticalEventLogProto; +import com.android.server.am.nano.CriticalEventLogStorageProto; +import com.android.server.am.nano.CriticalEventProto; +import com.android.server.am.nano.CriticalEventProto.HalfWatchdog; +import com.android.server.am.nano.CriticalEventProto.Watchdog; + +import org.junit.Before; +import org.junit.Rule; +import org.junit.Test; +import org.junit.rules.TemporaryFolder; + +import java.io.File; +import java.io.FileOutputStream; +import java.io.IOException; +import java.nio.charset.StandardCharsets; +import java.nio.file.Files; +import java.time.Duration; +import java.util.Arrays; +import java.util.UUID; + +/** + * Test class for {@link CriticalEventLog}. + * + * Build/Install/Run: + * atest FrameworksServicesTests:CriticalEventLogTest + */ +public class CriticalEventLogTest { + /** Epoch time when the critical event log is instantiated. */ + private static final long START_TIME_MS = 1577880000000L; // 2020-01-01 12:00:00.000 UTC + + /** Max number of events to include in the log. */ + private static final int BUFFER_CAPACITY = 5; + + /** Max age of events to include in the output log proto. */ + private static final Duration LOG_WINDOW = Duration.ofMinutes(5); + + /** How long to wait between consecutive saves of the log to disk. */ + private static final Duration MIN_TIME_BETWEEN_SAVES = Duration.ofSeconds(2); + + private static final String UUID_STRING = "123e4567-e89b-12d3-a456-556642440000"; + + @Rule + public TemporaryFolder mFolder = new TemporaryFolder(); + + private TestableCriticalEventLog mCriticalEventLog; + private File mTestFile; + + @Before + public void setup() throws IOException { + mTestFile = mFolder.newFile(CriticalEventLog.FILENAME); + setLogInstance(); + } + + @Test + public void loadEvents_validContents() throws Exception { + createTestFileWithEvents(2); + setLogInstance(); // Log instance reads the proto file at initialization. + + CriticalEventLogProto logProto = mCriticalEventLog.getRecentEvents(); + + assertThat(logProto.timestampMs).isEqualTo(START_TIME_MS); + assertProtoArrayEquals( + logProto.events, + new CriticalEventProto[]{ + watchdog(START_TIME_MS - 2000, "Old watchdog 1"), + watchdog(START_TIME_MS - 1000, "Old watchdog 2"), + }); + } + + @Test + public void loadEvents_fileDoesntExist() { + mTestFile.delete(); + setLogInstance(); + + CriticalEventLogProto logProto = mCriticalEventLog.getRecentEvents(); + + assertThat(logProto.timestampMs).isEqualTo(START_TIME_MS); + assertThat(logProto.events).isEmpty(); + } + + @Test + public void loadEvents_directoryDoesntExist() { + mFolder.delete(); + setLogInstance(); + + CriticalEventLogProto logProto = mCriticalEventLog.getRecentEvents(); + + assertThat(logProto.timestampMs).isEqualTo(START_TIME_MS); + assertThat(logProto.events).isEmpty(); + } + + @Test + public void loadEvents_unreadable() throws Exception { + createTestFileWithEvents(1); + mTestFile.setReadable(false); + setLogInstance(); + + CriticalEventLogProto logProto = mCriticalEventLog.getRecentEvents(); + + assertThat(logProto.timestampMs).isEqualTo(START_TIME_MS); + assertThat(logProto.events).isEmpty(); + } + + @Test + public void loadEvents_malformedFile() throws Exception { + try (FileOutputStream stream = new FileOutputStream(mTestFile)) { + stream.write("This is not a proto file.".getBytes(StandardCharsets.UTF_8)); + } + setLogInstance(); + + CriticalEventLogProto logProto = mCriticalEventLog.getRecentEvents(); + + assertThat(logProto.timestampMs).isEqualTo(START_TIME_MS); + assertThat(logProto.events).isEmpty(); + } + + @Test + public void loadEvents_emptyProto() throws Exception { + createTestFileWithEvents(0); + setLogInstance(); + + CriticalEventLogProto logProto = mCriticalEventLog.getRecentEvents(); + + assertThat(logProto.timestampMs).isEqualTo(START_TIME_MS); + assertThat(logProto.events).isEmpty(); + } + + @Test + public void loadEvents_numEventsExceedsBufferCapacity() throws Exception { + createTestFileWithEvents(10); // Ring buffer capacity is 5 + setLogInstance(); + + CriticalEventLogProto logProto = mCriticalEventLog.getRecentEvents(); + + assertThat(logProto.timestampMs).isEqualTo(START_TIME_MS); + // Log contains the last 5 events only. + assertProtoArrayEquals( + logProto.events, + new CriticalEventProto[]{ + watchdog(START_TIME_MS - 5000, "Old watchdog 6"), + watchdog(START_TIME_MS - 4000, "Old watchdog 7"), + watchdog(START_TIME_MS - 3000, "Old watchdog 8"), + watchdog(START_TIME_MS - 2000, "Old watchdog 9"), + watchdog(START_TIME_MS - 1000, "Old watchdog 10"), + }); + } + + @Test + public void logLinesForAnrFile() { + mCriticalEventLog.incTimeSeconds(1); + mCriticalEventLog.logWatchdog("Watchdog subject", + UUID.fromString("123e4567-e89b-12d3-a456-556642440000")); + mCriticalEventLog.incTimeSeconds(1); + mCriticalEventLog.logHalfWatchdog("Half watchdog subject"); + mCriticalEventLog.incTimeSeconds(1); + + assertThat(mCriticalEventLog.logLinesForAnrFile()).isEqualTo( + "--- CriticalEventLog ---\n" + + "capacity: 5\n" + + "events <\n" + + " timestamp_ms: 1577880001000\n" + + " watchdog <\n" + + " subject: \"Watchdog subject\"\n" + + " uuid: \"123e4567-e89b-12d3-a456-556642440000\"\n" + + " >\n" + + ">\n" + + "events <\n" + + " timestamp_ms: 1577880002000\n" + + " half_watchdog <\n" + + " subject: \"Half watchdog subject\"\n" + + " >\n" + + ">\n" + + "timestamp_ms: 1577880003000\n" + + "window_ms: 300000\n\n"); + } + + @Test + public void logWatchdog() { + mCriticalEventLog.incTimeSeconds(1); + mCriticalEventLog.logWatchdog("Subject 1", + UUID.fromString("123e4567-e89b-12d3-a456-556642440000")); + mCriticalEventLog.incTimeSeconds(1); + + CriticalEventLogProto logProto = mCriticalEventLog.getRecentEvents(); + + assertThat(logProto.timestampMs).isEqualTo(START_TIME_MS + 2000); + assertProtoArrayEquals(logProto.events, new CriticalEventProto[]{ + watchdog(START_TIME_MS + 1000, "Subject 1", "123e4567-e89b-12d3-a456-556642440000") + }); + } + + @Test + public void logHalfWatchdog() { + setLogInstance(); + mCriticalEventLog.incTimeSeconds(1); + mCriticalEventLog.logHalfWatchdog("Subject 1"); + mCriticalEventLog.incTimeSeconds(1); + + CriticalEventLogProto logProto = mCriticalEventLog.getRecentEvents(); + + assertThat(logProto.timestampMs).isEqualTo(START_TIME_MS + 2000); + assertProtoArrayEquals(logProto.events, new CriticalEventProto[]{ + halfWatchdog(START_TIME_MS + 1000, "Subject 1") + }); + } + + @Test + public void getOutputLogProto_numberOfEventsExceedsCapacity() { + // Log 10 events in 10 sec (capacity = 5) + for (int i = 0; i < 10; i++) { + mCriticalEventLog.logWatchdog("Subject " + i, + UUID.fromString(UUID_STRING)); + mCriticalEventLog.incTimeSeconds(1); + } + + CriticalEventLogProto logProto = mCriticalEventLog.getRecentEvents(); + + assertThat(logProto.timestampMs).isEqualTo(START_TIME_MS + 10000); + assertThat(logProto.windowMs).isEqualTo(300_000); // 5 minutes + assertThat(logProto.capacity).isEqualTo(5); + + // Only last 5 events are included in log output. + assertProtoArrayEquals(logProto.events, new CriticalEventProto[]{ + watchdog(START_TIME_MS + 5000, "Subject 5", UUID_STRING), + watchdog(START_TIME_MS + 6000, "Subject 6", UUID_STRING), + watchdog(START_TIME_MS + 7000, "Subject 7", UUID_STRING), + watchdog(START_TIME_MS + 8000, "Subject 8", UUID_STRING), + watchdog(START_TIME_MS + 9000, "Subject 9", UUID_STRING), + }); + } + + @Test + public void getOutputLogProto_logContainsOldEvents() { + long logTimestamp = START_TIME_MS + Duration.ofDays(1).toMillis(); + + // Old events (older than 5 mins) + mCriticalEventLog.setCurrentTimeMillis(logTimestamp - Duration.ofSeconds(302).toMillis()); + mCriticalEventLog.logHalfWatchdog("Old event 1"); // 5m2s old + mCriticalEventLog.incTimeSeconds(1); + mCriticalEventLog.logHalfWatchdog("Old event 2"); // 5m1s old + mCriticalEventLog.incTimeSeconds(1); + + // New events (5 mins old or less) + mCriticalEventLog.logHalfWatchdog("New event 1"); // 5m0s old + mCriticalEventLog.incTimeSeconds(1); + mCriticalEventLog.logHalfWatchdog("New event 2"); // 5m59s old + + mCriticalEventLog.setCurrentTimeMillis(logTimestamp); + CriticalEventLogProto logProto = mCriticalEventLog.getRecentEvents(); + + assertThat(logProto.timestampMs).isEqualTo(logTimestamp); + assertThat(logProto.windowMs).isEqualTo(300_000); // 5 minutes + assertThat(logProto.capacity).isEqualTo(5); + + // Only events with age <= 5 min are included + assertProtoArrayEquals(logProto.events, new CriticalEventProto[]{ + halfWatchdog(logTimestamp - Duration.ofSeconds(300).toMillis(), "New event 1"), + halfWatchdog(logTimestamp - Duration.ofSeconds(299).toMillis(), "New event 2"), + }); + } + + @Test + public void getOutputLogProto_logHasNotBeenLoadedFromDiskYet() throws Exception { + createTestFileWithEvents(5); + setLogInstance(new NoOpLogLoader()); + + CriticalEventLogProto logProto = mCriticalEventLog.getRecentEvents(); + + // Output log is empty. + assertThat(logProto.timestampMs).isEqualTo(START_TIME_MS); + assertThat(logProto.events).isEmpty(); + } + + @Test + public void saveEventsToDiskNow() throws Exception { + mCriticalEventLog.incTimeSeconds(1); + mCriticalEventLog.logWatchdog("Watchdog subject", UUID.fromString(UUID_STRING)); + + mCriticalEventLog.incTimeSeconds(1); + mCriticalEventLog.logHalfWatchdog("Half watchdog subject"); + + // Don't need to call saveEventsToDiskNow since it's called after every event + // when mSaveImmediately = true. + + CriticalEventLogStorageProto expected = new CriticalEventLogStorageProto(); + expected.events = new CriticalEventProto[]{ + watchdog(START_TIME_MS + 1000, "Watchdog subject", UUID_STRING), + halfWatchdog(START_TIME_MS + 2000, "Half watchdog subject") + }; + + assertThat(MessageNano.messageNanoEquals(getEventsWritten(), expected)).isTrue(); + } + + @Test + public void saveDelayMs() { + // First save has no delay + assertThat(mCriticalEventLog.saveDelayMs()).isEqualTo(0L); + + // Save log, then next save delay is in 2s + mCriticalEventLog.saveLogToFileNow(); + assertThat(mCriticalEventLog.saveDelayMs()).isEqualTo(2000L); + mCriticalEventLog.incTimeSeconds(1); + assertThat(mCriticalEventLog.saveDelayMs()).isEqualTo(1000L); + + // Save again, save delay is 2s again. + mCriticalEventLog.saveLogToFileNow(); + assertThat(mCriticalEventLog.saveDelayMs()).isEqualTo(2000L); + } + + @Test + public void simulateReboot_saveAndLoadCycle() { + TestableCriticalEventLog log1 = setLogInstance(); + + // Log 8 events + for (int i = 0; i < 8; i++) { + log1.logHalfWatchdog("Old subject " + i); + log1.incTimeSeconds(1); + } + + // Simulate reboot by making new log instance. + TestableCriticalEventLog log2 = setLogInstance(); + assertThat(log1).isNotSameInstanceAs(log2); + + // Log one more event + log2.setCurrentTimeMillis(START_TIME_MS + 20_000); + log2.logHalfWatchdog("New subject"); + log2.incTimeSeconds(1); + + CriticalEventLogProto logProto = log2.getRecentEvents(); + + // Log contains 4 + 1 events. + assertThat(logProto.timestampMs).isEqualTo(START_TIME_MS + 21_000); + assertProtoArrayEquals(logProto.events, new CriticalEventProto[]{ + halfWatchdog(START_TIME_MS + 4000, "Old subject 4"), + halfWatchdog(START_TIME_MS + 5000, "Old subject 5"), + halfWatchdog(START_TIME_MS + 6000, "Old subject 6"), + halfWatchdog(START_TIME_MS + 7000, "Old subject 7"), + halfWatchdog(START_TIME_MS + 20_000, "New subject") + }); + } + + private CriticalEventLogStorageProto getEventsWritten() throws IOException { + return CriticalEventLogStorageProto.parseFrom( + Files.readAllBytes(mTestFile.toPath())); + } + + /** + * Creates a log file containing some watchdog events. + * + * They occur at a rate of one per second, with the last at 1 sec before START_TIME_MS. + */ + private void createTestFileWithEvents(int numEvents) throws Exception { + CriticalEventLogStorageProto log = new CriticalEventLogStorageProto(); + log.events = new CriticalEventProto[numEvents]; + long startTimeMs = START_TIME_MS - (numEvents * 1000L); + + for (int i = 0; i < numEvents; i++) { + long timestampMs = startTimeMs + (i * 1000L); + String subject = String.format("Old watchdog %d", i + 1); + log.events[i] = watchdog(timestampMs, subject); + } + + try (FileOutputStream stream = new FileOutputStream(mTestFile)) { + stream.write(CriticalEventLogStorageProto.toByteArray(log)); + } + } + + private CriticalEventProto watchdog(long timestampMs, String subject) { + return watchdog(timestampMs, subject, "A UUID"); + } + + private CriticalEventProto watchdog(long timestampMs, String subject, String uuid) { + CriticalEventProto event = new CriticalEventProto(); + event.timestampMs = timestampMs; + event.setWatchdog(new Watchdog()); + event.getWatchdog().subject = subject; + event.getWatchdog().uuid = uuid; + return event; + } + + private CriticalEventProto halfWatchdog(long timestampMs, String subject) { + CriticalEventProto event = new CriticalEventProto(); + event.timestampMs = timestampMs; + event.setHalfWatchdog(new HalfWatchdog()); + event.getHalfWatchdog().subject = subject; + return event; + } + + private static void assertProtoArrayEquals(MessageNano[] actual, MessageNano[] expected) { + 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); + for (int i = 0; i < expected.length; i++) { + assertWithMessage(message).that( + MessageNano.messageNanoEquals(expected[i], actual[i])).isTrue(); + } + } + + private TestableCriticalEventLog setLogInstance() { + return setLogInstance(new LogLoader()); + } + + private TestableCriticalEventLog setLogInstance(ILogLoader logLoader) { + mCriticalEventLog = new TestableCriticalEventLog(mFolder.getRoot().getAbsolutePath(), + logLoader); + return mCriticalEventLog; + } + + private static class TestableCriticalEventLog extends CriticalEventLog { + private long mNowMillis = START_TIME_MS; + + TestableCriticalEventLog(String logDir, ILogLoader logLoader) { + super(logDir, + BUFFER_CAPACITY, + (int) LOG_WINDOW.toMillis(), + MIN_TIME_BETWEEN_SAVES.toMillis(), + /* loadAndSaveImmediately= */ true, + logLoader); + } + + @Override + protected long getWallTimeMillis() { + return mNowMillis; + } + + void incTimeSeconds(int seconds) { + mNowMillis += (seconds * 1000L); + } + + void setCurrentTimeMillis(long millis) { + mNowMillis = millis; + } + } + + /** + * A log loader that does nothing. + * + * Used to check behaviour when log loading is slow since the loading happens + * asynchronously. + */ + private static class NoOpLogLoader implements ILogLoader { + @Override + public void load(File logFile, + CriticalEventLog.ThreadSafeRingBuffer buffer) { + // Do nothing. + } + } +}