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
This commit is contained in:
Ben Miles
2021-08-20 15:48:18 +01:00
parent 508008be17
commit fdbfa3b5d9
9 changed files with 917 additions and 17 deletions

View File

@@ -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;
}
}

View File

@@ -192,7 +192,7 @@ public final class SystemServerInitThreadPool implements Dumpable {
final ArrayList<Integer> pids = new ArrayList<>();
pids.add(Process.myPid());
ActivityManagerService.dumpStackTraces(pids, null, null,
Watchdog.getInterestingNativePids(), null, null);
Watchdog.getInterestingNativePids(), null, null, null);
}
@Override

View File

@@ -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.

View File

@@ -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<Boolean> lastPids,
ArrayList<Integer> 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<Integer> firstPids,
ProcessCpuTracker processCpuTracker, SparseArray<Boolean> lastPids,
ArrayList<Integer> 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<Integer> firstPids,
ProcessCpuTracker processCpuTracker, SparseArray<Boolean> lastPids,
ArrayList<Integer> nativePids, StringWriter logExceptionCreatingFile,
long[] firstPidOffsets, String subject) {
long[] firstPidOffsets, String subject, String criticalEventSection) {
ArrayList<Integer> 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);
}
}

View File

@@ -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<CriticalEventProto> 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<T> {
private final int mCapacity;
private final RingBuffer<T> mBuffer;
ThreadSafeRingBuffer(Class<T> 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<CriticalEventProto> buffer);
}
/** Loads log events from disk into a ring buffer. */
static class LogLoader implements ILogLoader {
@Override
public void load(File logFile,
ThreadSafeRingBuffer<CriticalEventProto> 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();
}
}
}
}

View File

@@ -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();

View File

@@ -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"));
}

View File

@@ -53,6 +53,7 @@ android_test {
"testng",
"ub-uiautomator",
"platformprotosnano",
"framework-protos",
"hamcrest-library",
"servicestests-utils",
"service-appsearch",

View File

@@ -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<CriticalEventProto> buffer) {
// Do nothing.
}
}
}