1 /* 2 * Copyright (C) 2021 The Android Open Source Project 3 * 4 * Licensed under the Apache License, Version 2.0 (the "License"); 5 * you may not use this file except in compliance with the License. 6 * You may obtain a copy of the License at 7 * 8 * http://www.apache.org/licenses/LICENSE-2.0 9 * 10 * Unless required by applicable law or agreed to in writing, software 11 * distributed under the License is distributed on an "AS IS" BASIS, 12 * WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied. 13 * See the License for the specific language governing permissions and 14 * limitations under the License. 15 */ 16 17 package com.android.server.criticalevents; 18 19 import static com.google.common.truth.Truth.assertThat; 20 import static com.google.common.truth.Truth.assertWithMessage; 21 22 import android.server.ServerProtoEnums; 23 24 import com.android.framework.protobuf.nano.MessageNano; 25 import com.android.server.criticalevents.CriticalEventLog.ILogLoader; 26 import com.android.server.criticalevents.CriticalEventLog.LogLoader; 27 import com.android.server.criticalevents.nano.CriticalEventLogProto; 28 import com.android.server.criticalevents.nano.CriticalEventLogStorageProto; 29 import com.android.server.criticalevents.nano.CriticalEventProto; 30 import com.android.server.criticalevents.nano.CriticalEventProto.AppNotResponding; 31 import com.android.server.criticalevents.nano.CriticalEventProto.HalfWatchdog; 32 import com.android.server.criticalevents.nano.CriticalEventProto.JavaCrash; 33 import com.android.server.criticalevents.nano.CriticalEventProto.NativeCrash; 34 import com.android.server.criticalevents.nano.CriticalEventProto.Watchdog; 35 36 import org.junit.Before; 37 import org.junit.Rule; 38 import org.junit.Test; 39 import org.junit.rules.TemporaryFolder; 40 41 import java.io.File; 42 import java.io.FileOutputStream; 43 import java.io.IOException; 44 import java.nio.charset.StandardCharsets; 45 import java.nio.file.Files; 46 import java.time.Duration; 47 import java.util.Arrays; 48 import java.util.UUID; 49 50 /** 51 * Test class for {@link CriticalEventLog}. 52 * 53 * Build/Install/Run: 54 * atest FrameworksServicesTests:CriticalEventLogTest 55 */ 56 public class CriticalEventLogTest { 57 /** Epoch time when the critical event log is instantiated. */ 58 private static final long START_TIME_MS = 1577880000000L; // 2020-01-01 12:00:00.000 UTC 59 60 /** Max number of events to include in the log. */ 61 private static final int BUFFER_CAPACITY = 5; 62 63 /** Max age of events to include in the output log proto. */ 64 private static final Duration LOG_WINDOW = Duration.ofMinutes(5); 65 66 /** How long to wait between consecutive saves of the log to disk. */ 67 private static final Duration MIN_TIME_BETWEEN_SAVES = Duration.ofSeconds(2); 68 69 private static final String UUID_STRING = "123e4567-e89b-12d3-a456-556642440000"; 70 71 private static final int SYSTEM_SERVER_UID = 1000; 72 private static final int SYSTEM_APP_UID = 1001; 73 74 private static final int DATA_APP_UID = 10_001; 75 private static final int DATA_APP_UID_2 = 10_002; 76 private static final int DATA_APP_UID_3 = 10_003; 77 78 @Rule 79 public TemporaryFolder mFolder = new TemporaryFolder(); 80 81 private TestableCriticalEventLog mCriticalEventLog; 82 private File mTestFile; 83 84 @Before setup()85 public void setup() throws IOException { 86 mTestFile = mFolder.newFile(CriticalEventLog.FILENAME); 87 setLogInstance(); 88 } 89 90 @Test loadEvents_validContents()91 public void loadEvents_validContents() throws Exception { 92 createTestFileWithEvents(2); 93 setLogInstance(); // Log instance reads the proto file at initialization. 94 95 CriticalEventLogProto logProto = getLogOutput(); 96 97 assertThat(logProto.timestampMs).isEqualTo(START_TIME_MS); 98 assertProtoArrayEquals( 99 logProto.events, 100 new CriticalEventProto[]{ 101 watchdog(START_TIME_MS - 2000, "Old watchdog 1"), 102 watchdog(START_TIME_MS - 1000, "Old watchdog 2"), 103 }); 104 } 105 106 @Test loadEvents_fileDoesntExist()107 public void loadEvents_fileDoesntExist() { 108 mTestFile.delete(); 109 setLogInstance(); 110 111 CriticalEventLogProto logProto = getLogOutput(); 112 113 assertThat(logProto.timestampMs).isEqualTo(START_TIME_MS); 114 assertThat(logProto.events).isEmpty(); 115 } 116 117 @Test loadEvents_directoryDoesntExist()118 public void loadEvents_directoryDoesntExist() { 119 mFolder.delete(); 120 setLogInstance(); 121 122 CriticalEventLogProto logProto = getLogOutput(); 123 124 assertThat(logProto.timestampMs).isEqualTo(START_TIME_MS); 125 assertThat(logProto.events).isEmpty(); 126 } 127 128 @Test loadEvents_unreadable()129 public void loadEvents_unreadable() throws Exception { 130 createTestFileWithEvents(1); 131 mTestFile.setReadable(false); 132 setLogInstance(); 133 134 CriticalEventLogProto logProto = getLogOutput(); 135 136 assertThat(logProto.timestampMs).isEqualTo(START_TIME_MS); 137 assertThat(logProto.events).isEmpty(); 138 } 139 140 @Test loadEvents_malformedFile()141 public void loadEvents_malformedFile() throws Exception { 142 try (FileOutputStream stream = new FileOutputStream(mTestFile)) { 143 stream.write("This is not a proto file.".getBytes(StandardCharsets.UTF_8)); 144 } 145 setLogInstance(); 146 147 CriticalEventLogProto logProto = getLogOutput(); 148 149 assertThat(logProto.timestampMs).isEqualTo(START_TIME_MS); 150 assertThat(logProto.events).isEmpty(); 151 } 152 153 @Test loadEvents_emptyProto()154 public void loadEvents_emptyProto() throws Exception { 155 createTestFileWithEvents(0); 156 setLogInstance(); 157 158 CriticalEventLogProto logProto = getLogOutput(); 159 160 assertThat(logProto.timestampMs).isEqualTo(START_TIME_MS); 161 assertThat(logProto.events).isEmpty(); 162 } 163 164 @Test loadEvents_numEventsExceedsBufferCapacity()165 public void loadEvents_numEventsExceedsBufferCapacity() throws Exception { 166 createTestFileWithEvents(10); // Ring buffer capacity is 5 167 setLogInstance(); 168 169 CriticalEventLogProto logProto = getLogOutput(); 170 171 assertThat(logProto.timestampMs).isEqualTo(START_TIME_MS); 172 // Log contains the last 5 events only. 173 assertProtoArrayEquals( 174 logProto.events, 175 new CriticalEventProto[]{ 176 watchdog(START_TIME_MS - 5000, "Old watchdog 6"), 177 watchdog(START_TIME_MS - 4000, "Old watchdog 7"), 178 watchdog(START_TIME_MS - 3000, "Old watchdog 8"), 179 watchdog(START_TIME_MS - 2000, "Old watchdog 9"), 180 watchdog(START_TIME_MS - 1000, "Old watchdog 10"), 181 }); 182 } 183 184 @Test logLinesForTraceFile()185 public void logLinesForTraceFile() { 186 mCriticalEventLog.incTimeSeconds(1); 187 mCriticalEventLog.logWatchdog("Watchdog subject", 188 UUID.fromString("123e4567-e89b-12d3-a456-556642440000")); 189 mCriticalEventLog.incTimeSeconds(1); 190 mCriticalEventLog.logHalfWatchdog("Half watchdog subject"); 191 mCriticalEventLog.incTimeSeconds(1); 192 193 assertThat(mCriticalEventLog.logLinesForSystemServerTraceFile()).isEqualTo( 194 "--- CriticalEventLog ---\n" 195 + "capacity: 5\n" 196 + "events <\n" 197 + " timestamp_ms: 1577880001000\n" 198 + " watchdog <\n" 199 + " subject: \"Watchdog subject\"\n" 200 + " uuid: \"123e4567-e89b-12d3-a456-556642440000\"\n" 201 + " >\n" 202 + ">\n" 203 + "events <\n" 204 + " timestamp_ms: 1577880002000\n" 205 + " half_watchdog <\n" 206 + " subject: \"Half watchdog subject\"\n" 207 + " >\n" 208 + ">\n" 209 + "timestamp_ms: 1577880003000\n" 210 + "window_ms: 300000\n\n"); 211 } 212 213 @Test logWatchdog()214 public void logWatchdog() { 215 mCriticalEventLog.incTimeSeconds(1); 216 mCriticalEventLog.logWatchdog("Subject 1", 217 UUID.fromString("123e4567-e89b-12d3-a456-556642440000")); 218 mCriticalEventLog.incTimeSeconds(1); 219 220 CriticalEventLogProto logProto = getLogOutput(); 221 222 assertThat(logProto.timestampMs).isEqualTo(START_TIME_MS + 2000); 223 assertProtoArrayEquals(logProto.events, new CriticalEventProto[]{ 224 watchdog(START_TIME_MS + 1000, "Subject 1", "123e4567-e89b-12d3-a456-556642440000") 225 }); 226 } 227 228 @Test logHalfWatchdog()229 public void logHalfWatchdog() { 230 setLogInstance(); 231 mCriticalEventLog.incTimeSeconds(1); 232 mCriticalEventLog.logHalfWatchdog("Subject 1"); 233 mCriticalEventLog.incTimeSeconds(1); 234 235 CriticalEventLogProto logProto = getLogOutput(); 236 237 assertThat(logProto.timestampMs).isEqualTo(START_TIME_MS + 2000); 238 assertProtoArrayEquals(logProto.events, new CriticalEventProto[]{ 239 halfWatchdog(START_TIME_MS + 1000, "Subject 1") 240 }); 241 } 242 243 @Test logAnr()244 public void logAnr() { 245 mCriticalEventLog.incTimeSeconds(1); 246 mCriticalEventLog.logAnr("Subject 1", ServerProtoEnums.SYSTEM_SERVER, "AID_SYSTEM", 247 SYSTEM_SERVER_UID, 0); 248 mCriticalEventLog.incTimeSeconds(1); 249 250 CriticalEventLogProto logProto = getLogOutput(); 251 252 assertThat(logProto.timestampMs).isEqualTo(START_TIME_MS + 2000); 253 assertProtoArrayEquals(logProto.events, new CriticalEventProto[]{ 254 anr(START_TIME_MS + 1000, "Subject 1", ServerProtoEnums.SYSTEM_SERVER, 255 "AID_SYSTEM", SYSTEM_SERVER_UID, 0) 256 }); 257 } 258 259 @Test logJavaCrash()260 public void logJavaCrash() { 261 mCriticalEventLog.incTimeSeconds(1); 262 mCriticalEventLog.logJavaCrash("com.android.MyClass", ServerProtoEnums.SYSTEM_APP, 263 "AID_RADIO", SYSTEM_APP_UID, 1); 264 mCriticalEventLog.incTimeSeconds(1); 265 266 CriticalEventLogProto logProto = getLogOutput(); 267 268 assertThat(logProto.timestampMs).isEqualTo(START_TIME_MS + 2000); 269 assertProtoArrayEquals(logProto.events, new CriticalEventProto[]{ 270 javaCrash(START_TIME_MS + 1000, "com.android.MyClass", ServerProtoEnums.SYSTEM_APP, 271 "AID_RADIO", SYSTEM_APP_UID, 1) 272 }); 273 } 274 275 @Test logNativeCrash()276 public void logNativeCrash() { 277 mCriticalEventLog.incTimeSeconds(1); 278 mCriticalEventLog.logNativeCrash(ServerProtoEnums.SYSTEM_APP, "AID_RADIO", SYSTEM_APP_UID, 279 1); 280 mCriticalEventLog.incTimeSeconds(1); 281 282 CriticalEventLogProto logProto = getLogOutput(); 283 284 assertThat(logProto.timestampMs).isEqualTo(START_TIME_MS + 2000); 285 assertProtoArrayEquals(logProto.events, new CriticalEventProto[]{ 286 nativeCrash(START_TIME_MS + 1000, ServerProtoEnums.SYSTEM_APP, "AID_RADIO", 287 SYSTEM_APP_UID, 1) 288 }); 289 } 290 291 @Test privacyRedaction_anr()292 public void privacyRedaction_anr() { 293 CriticalEventProto systemServerAnr = anr(START_TIME_MS + 1000, "Subject 1", 294 CriticalEventProto.SYSTEM_SERVER, "AID_SYSTEM", SYSTEM_SERVER_UID, 0); 295 CriticalEventProto systemAppAnr = anr(START_TIME_MS + 2000, "Subject 2", 296 CriticalEventProto.SYSTEM_APP, 297 "AID_RADIO", SYSTEM_APP_UID, 1); 298 CriticalEventProto fooAppAnr = anr(START_TIME_MS + 3000, "Subject 3", 299 CriticalEventProto.DATA_APP, "com.foo", DATA_APP_UID, 2); 300 CriticalEventProto fooAppAnrUid2 = anr(START_TIME_MS + 4000, "Subject 4", 301 CriticalEventProto.DATA_APP, "com.foo", DATA_APP_UID_2, 3); 302 CriticalEventProto fooAppAnrUid2Redacted = anr(START_TIME_MS + 4000, "", 303 CriticalEventProto.DATA_APP, "", DATA_APP_UID_2, 3); 304 CriticalEventProto barAppAnr = anr(START_TIME_MS + 5000, "Subject 5", 305 CriticalEventProto.DATA_APP, "com.bar", DATA_APP_UID_3, 4); 306 CriticalEventProto barAppAnrRedacted = anr(START_TIME_MS + 5000, "", 307 CriticalEventProto.DATA_APP, "", DATA_APP_UID_3, 4); 308 309 addToLog(systemServerAnr, systemAppAnr, fooAppAnr, fooAppAnrUid2, barAppAnr); 310 311 assertProtoArrayEquals( 312 getLogOutput(ServerProtoEnums.DATA_APP, "com.foo", DATA_APP_UID).events, 313 new CriticalEventProto[]{ 314 systemServerAnr, 315 systemAppAnr, 316 fooAppAnr, 317 // Redacted since the trace file and ANR are for different uids. 318 fooAppAnrUid2Redacted, 319 // Redacted since the trace file and ANR are for different data apps. 320 barAppAnrRedacted 321 }); 322 323 assertProtoArrayEquals( 324 getLogOutput(ServerProtoEnums.SYSTEM_SERVER, "AID_SYSTEM", 325 SYSTEM_SERVER_UID).events, 326 new CriticalEventProto[]{ 327 systemServerAnr, 328 systemAppAnr, 329 fooAppAnr, 330 fooAppAnrUid2, 331 barAppAnr 332 }); 333 334 assertProtoArrayEquals( 335 getLogOutput(ServerProtoEnums.SYSTEM_APP, "AID_RADIO", 336 SYSTEM_APP_UID).events, 337 new CriticalEventProto[]{ 338 systemServerAnr, 339 systemAppAnr, 340 fooAppAnr, 341 fooAppAnrUid2, 342 barAppAnr 343 }); 344 } 345 346 @Test privacyRedaction_javaCrash()347 public void privacyRedaction_javaCrash() { 348 CriticalEventProto systemServerCrash = javaCrash(START_TIME_MS + 1000, "Exception class 1", 349 CriticalEventProto.SYSTEM_SERVER, "AID_SYSTEM", 350 SYSTEM_SERVER_UID, 0); 351 CriticalEventProto systemAppCrash = javaCrash(START_TIME_MS + 2000, "Exception class 2", 352 CriticalEventProto.SYSTEM_APP, "AID_RADIO", SYSTEM_APP_UID, 1); 353 CriticalEventProto fooAppCrash = javaCrash(START_TIME_MS + 3000, "Exception class 3", 354 CriticalEventProto.DATA_APP, "com.foo", DATA_APP_UID, 2); 355 CriticalEventProto fooAppCrashUid2 = javaCrash(START_TIME_MS + 4000, "Exception class 4", 356 CriticalEventProto.DATA_APP, "com.foo", DATA_APP_UID_2, 3); 357 CriticalEventProto fooAppCrashUid2Redacted = javaCrash(START_TIME_MS + 4000, "", 358 CriticalEventProto.DATA_APP, "", DATA_APP_UID_2, 3); 359 CriticalEventProto barAppCrash = javaCrash(START_TIME_MS + 5000, "Exception class 5", 360 CriticalEventProto.DATA_APP, "com.bar", DATA_APP_UID_3, 4); 361 CriticalEventProto barAppCrashRedacted = javaCrash(START_TIME_MS + 5000, "", 362 CriticalEventProto.DATA_APP, "", DATA_APP_UID_3, 4); 363 364 addToLog(systemServerCrash, systemAppCrash, fooAppCrash, fooAppCrashUid2, barAppCrash); 365 366 assertProtoArrayEquals( 367 getLogOutput(ServerProtoEnums.DATA_APP, "com.foo", DATA_APP_UID).events, 368 new CriticalEventProto[]{ 369 systemServerCrash, 370 systemAppCrash, 371 fooAppCrash, 372 // Redacted since the trace file and crash are for different uids. 373 fooAppCrashUid2Redacted, 374 // Redacted since the trace file and crash are for different data apps. 375 barAppCrashRedacted 376 }); 377 378 assertProtoArrayEquals( 379 getLogOutput(ServerProtoEnums.SYSTEM_SERVER, "AID_SYSTEM", 380 SYSTEM_SERVER_UID).events, 381 new CriticalEventProto[]{ 382 systemServerCrash, 383 systemAppCrash, 384 fooAppCrash, 385 fooAppCrashUid2, 386 barAppCrash 387 }); 388 389 assertProtoArrayEquals( 390 getLogOutput(ServerProtoEnums.SYSTEM_APP, "AID_RADIO", 391 SYSTEM_APP_UID).events, 392 new CriticalEventProto[]{ 393 systemServerCrash, 394 systemAppCrash, 395 fooAppCrash, 396 fooAppCrashUid2, 397 barAppCrash 398 }); 399 } 400 401 @Test privacyRedaction_nativeCrash()402 public void privacyRedaction_nativeCrash() { 403 CriticalEventProto systemServerCrash = nativeCrash(START_TIME_MS + 1000, 404 CriticalEventProto.SYSTEM_SERVER, "AID_SYSTEM", 405 SYSTEM_SERVER_UID, 0); 406 CriticalEventProto systemAppCrash = nativeCrash(START_TIME_MS + 2000, 407 CriticalEventProto.SYSTEM_APP, "AID_RADIO", SYSTEM_APP_UID, 1); 408 CriticalEventProto fooAppCrash = nativeCrash(START_TIME_MS + 3000, 409 CriticalEventProto.DATA_APP, "com.foo", DATA_APP_UID, 2); 410 CriticalEventProto fooAppCrashUid2 = nativeCrash(START_TIME_MS + 4000, 411 CriticalEventProto.DATA_APP, "com.foo", DATA_APP_UID_2, 3); 412 CriticalEventProto fooAppCrashUid2Redacted = nativeCrash(START_TIME_MS + 4000, 413 CriticalEventProto.DATA_APP, "", DATA_APP_UID_2, 3); 414 CriticalEventProto barAppCrash = nativeCrash(START_TIME_MS + 5000, 415 CriticalEventProto.DATA_APP, "com.bar", DATA_APP_UID_3, 4); 416 CriticalEventProto barAppCrashRedacted = nativeCrash(START_TIME_MS + 5000, 417 CriticalEventProto.DATA_APP, "", DATA_APP_UID_3, 4); 418 419 addToLog(systemServerCrash, systemAppCrash, fooAppCrash, fooAppCrashUid2, barAppCrash); 420 421 assertProtoArrayEquals( 422 getLogOutput(ServerProtoEnums.DATA_APP, "com.foo", DATA_APP_UID).events, 423 new CriticalEventProto[]{ 424 systemServerCrash, 425 systemAppCrash, 426 fooAppCrash, 427 // Redacted since the trace file and crash are for different uids. 428 fooAppCrashUid2Redacted, 429 // Redacted since the trace file and crash are for different data apps. 430 barAppCrashRedacted 431 }); 432 433 assertProtoArrayEquals( 434 getLogOutput(ServerProtoEnums.SYSTEM_SERVER, "AID_SYSTEM", 435 SYSTEM_SERVER_UID).events, 436 new CriticalEventProto[]{ 437 systemServerCrash, 438 systemAppCrash, 439 fooAppCrash, 440 fooAppCrashUid2, 441 barAppCrash 442 }); 443 444 assertProtoArrayEquals( 445 getLogOutput(ServerProtoEnums.SYSTEM_APP, "AID_RADIO", 446 SYSTEM_APP_UID).events, 447 new CriticalEventProto[]{ 448 systemServerCrash, 449 systemAppCrash, 450 fooAppCrash, 451 fooAppCrashUid2, 452 barAppCrash 453 }); 454 } 455 456 @Test privacyRedaction_doesNotMutateLogState()457 public void privacyRedaction_doesNotMutateLogState() { 458 mCriticalEventLog.logAnr("ANR Subject", ServerProtoEnums.DATA_APP, "com.foo", 459 10_001, DATA_APP_UID); 460 mCriticalEventLog.logJavaCrash("com.foo.MyClass", ServerProtoEnums.DATA_APP, "com.foo", 461 10_001, DATA_APP_UID); 462 mCriticalEventLog.logNativeCrash(ServerProtoEnums.DATA_APP, "com.foo", 10_001, 463 DATA_APP_UID); 464 465 CriticalEventLogProto unredactedLogBefore = getLogOutput(ServerProtoEnums.SYSTEM_SERVER, 466 "AID_SYSTEM", SYSTEM_SERVER_UID); 467 CriticalEventLogProto redactedLog = getLogOutput(ServerProtoEnums.DATA_APP, "com.bar", 468 DATA_APP_UID); 469 CriticalEventLogProto unredactedLogAfter = getLogOutput(ServerProtoEnums.SYSTEM_SERVER, 470 "AID_SYSTEM", SYSTEM_SERVER_UID); 471 472 assertProtoNotEqual(unredactedLogBefore, redactedLog); // verify some redaction took place. 473 assertProtoEquals(unredactedLogBefore, unredactedLogAfter); 474 } 475 476 @Test getOutputLogProto_numberOfEventsExceedsCapacity()477 public void getOutputLogProto_numberOfEventsExceedsCapacity() { 478 // Log 10 events in 10 sec (capacity = 5) 479 for (int i = 0; i < 10; i++) { 480 mCriticalEventLog.logWatchdog("Subject " + i, 481 UUID.fromString(UUID_STRING)); 482 mCriticalEventLog.incTimeSeconds(1); 483 } 484 485 CriticalEventLogProto logProto = getLogOutput(); 486 487 assertThat(logProto.timestampMs).isEqualTo(START_TIME_MS + 10000); 488 assertThat(logProto.windowMs).isEqualTo(300_000); // 5 minutes 489 assertThat(logProto.capacity).isEqualTo(5); 490 491 // Only last 5 events are included in log output. 492 assertProtoArrayEquals(logProto.events, new CriticalEventProto[]{ 493 watchdog(START_TIME_MS + 5000, "Subject 5", UUID_STRING), 494 watchdog(START_TIME_MS + 6000, "Subject 6", UUID_STRING), 495 watchdog(START_TIME_MS + 7000, "Subject 7", UUID_STRING), 496 watchdog(START_TIME_MS + 8000, "Subject 8", UUID_STRING), 497 watchdog(START_TIME_MS + 9000, "Subject 9", UUID_STRING), 498 }); 499 } 500 501 @Test getOutputLogProto_logContainsOldEvents()502 public void getOutputLogProto_logContainsOldEvents() { 503 long logTimestamp = START_TIME_MS + Duration.ofDays(1).toMillis(); 504 505 // Old events (older than 5 mins) 506 mCriticalEventLog.setCurrentTimeMillis(logTimestamp - Duration.ofSeconds(302).toMillis()); 507 mCriticalEventLog.logHalfWatchdog("Old event 1"); // 5m2s old 508 mCriticalEventLog.incTimeSeconds(1); 509 mCriticalEventLog.logHalfWatchdog("Old event 2"); // 5m1s old 510 mCriticalEventLog.incTimeSeconds(1); 511 512 // New events (5 mins old or less) 513 mCriticalEventLog.logHalfWatchdog("New event 1"); // 5m0s old 514 mCriticalEventLog.incTimeSeconds(1); 515 mCriticalEventLog.logHalfWatchdog("New event 2"); // 5m59s old 516 517 mCriticalEventLog.setCurrentTimeMillis(logTimestamp); 518 CriticalEventLogProto logProto = getLogOutput(); 519 520 assertThat(logProto.timestampMs).isEqualTo(logTimestamp); 521 assertThat(logProto.windowMs).isEqualTo(300_000); // 5 minutes 522 assertThat(logProto.capacity).isEqualTo(5); 523 524 // Only events with age <= 5 min are included 525 assertProtoArrayEquals(logProto.events, new CriticalEventProto[]{ 526 halfWatchdog(logTimestamp - Duration.ofSeconds(300).toMillis(), "New event 1"), 527 halfWatchdog(logTimestamp - Duration.ofSeconds(299).toMillis(), "New event 2"), 528 }); 529 } 530 531 @Test getOutputLogProto_logHasNotBeenLoadedFromDiskYet()532 public void getOutputLogProto_logHasNotBeenLoadedFromDiskYet() throws Exception { 533 createTestFileWithEvents(5); 534 setLogInstance(new NoOpLogLoader()); 535 536 CriticalEventLogProto logProto = getLogOutput(); 537 538 // Output log is empty. 539 assertThat(logProto.timestampMs).isEqualTo(START_TIME_MS); 540 assertThat(logProto.events).isEmpty(); 541 } 542 543 @Test saveEventsToDiskNow()544 public void saveEventsToDiskNow() throws Exception { 545 mCriticalEventLog.incTimeSeconds(1); 546 mCriticalEventLog.logWatchdog("Watchdog subject", UUID.fromString(UUID_STRING)); 547 548 mCriticalEventLog.incTimeSeconds(1); 549 mCriticalEventLog.logHalfWatchdog("Half watchdog subject"); 550 551 // Don't need to call saveEventsToDiskNow since it's called after every event 552 // when mSaveImmediately = true. 553 554 CriticalEventLogStorageProto expected = new CriticalEventLogStorageProto(); 555 expected.events = new CriticalEventProto[]{ 556 watchdog(START_TIME_MS + 1000, "Watchdog subject", UUID_STRING), 557 halfWatchdog(START_TIME_MS + 2000, "Half watchdog subject") 558 }; 559 560 assertThat(MessageNano.messageNanoEquals(getEventsWritten(), expected)).isTrue(); 561 } 562 563 @Test saveDelayMs()564 public void saveDelayMs() { 565 // First save has no delay 566 assertThat(mCriticalEventLog.saveDelayMs()).isEqualTo(0L); 567 568 // Save log, then next save delay is in 2s 569 mCriticalEventLog.saveLogToFileNow(); 570 assertThat(mCriticalEventLog.saveDelayMs()).isEqualTo(2000L); 571 mCriticalEventLog.incTimeSeconds(1); 572 assertThat(mCriticalEventLog.saveDelayMs()).isEqualTo(1000L); 573 574 // Save again, save delay is 2s again. 575 mCriticalEventLog.saveLogToFileNow(); 576 assertThat(mCriticalEventLog.saveDelayMs()).isEqualTo(2000L); 577 } 578 579 @Test simulateReboot_saveAndLoadCycle()580 public void simulateReboot_saveAndLoadCycle() { 581 TestableCriticalEventLog log1 = setLogInstance(); 582 583 // Log 8 events 584 for (int i = 0; i < 8; i++) { 585 log1.logHalfWatchdog("Old subject " + i); 586 log1.incTimeSeconds(1); 587 } 588 589 // Simulate reboot by making new log instance. 590 TestableCriticalEventLog log2 = setLogInstance(); 591 assertThat(log1).isNotSameInstanceAs(log2); 592 593 // Log one more event 594 log2.setCurrentTimeMillis(START_TIME_MS + 20_000); 595 log2.logHalfWatchdog("New subject"); 596 log2.incTimeSeconds(1); 597 598 CriticalEventLogProto logProto = getLogOutput(log2); 599 600 // Log contains 4 + 1 events. 601 assertThat(logProto.timestampMs).isEqualTo(START_TIME_MS + 21_000); 602 assertProtoArrayEquals(logProto.events, new CriticalEventProto[]{ 603 halfWatchdog(START_TIME_MS + 4000, "Old subject 4"), 604 halfWatchdog(START_TIME_MS + 5000, "Old subject 5"), 605 halfWatchdog(START_TIME_MS + 6000, "Old subject 6"), 606 halfWatchdog(START_TIME_MS + 7000, "Old subject 7"), 607 halfWatchdog(START_TIME_MS + 20_000, "New subject") 608 }); 609 } 610 611 @Test processClassEnumParity()612 public void processClassEnumParity() { 613 String message = "CriticalEventProto.ProcessClass and ServerProtoEnum are out of sync."; 614 assertWithMessage(message).that(CriticalEventProto.PROCESS_CLASS_UNKNOWN).isEqualTo( 615 ServerProtoEnums.ERROR_SOURCE_UNKNOWN); 616 assertWithMessage(message).that(CriticalEventProto.DATA_APP).isEqualTo( 617 ServerProtoEnums.DATA_APP); 618 assertWithMessage(message).that(CriticalEventProto.SYSTEM_APP).isEqualTo( 619 ServerProtoEnums.SYSTEM_APP); 620 assertWithMessage(message).that(CriticalEventProto.SYSTEM_SERVER).isEqualTo( 621 ServerProtoEnums.SYSTEM_SERVER); 622 } 623 addToLog(CriticalEventProto... events)624 private void addToLog(CriticalEventProto... events) { 625 for (CriticalEventProto event : events) { 626 mCriticalEventLog.appendAndSave(event); 627 } 628 } 629 getLogOutput()630 private CriticalEventLogProto getLogOutput() { 631 return getLogOutput(mCriticalEventLog); 632 } 633 getLogOutput(CriticalEventLog log)634 private CriticalEventLogProto getLogOutput(CriticalEventLog log) { 635 return getLogOutput(log, ServerProtoEnums.SYSTEM_SERVER, "AID_SYSTEM", SYSTEM_SERVER_UID); 636 } 637 getLogOutput(int traceProcessClassEnum, String traceProcessName, int traceProcessUid)638 private CriticalEventLogProto getLogOutput(int traceProcessClassEnum, 639 String traceProcessName, int traceProcessUid) { 640 return getLogOutput(mCriticalEventLog, traceProcessClassEnum, traceProcessName, 641 traceProcessUid); 642 } 643 getLogOutput(CriticalEventLog log, int traceProcessClassEnum, String traceProcessName, int traceProcessUid)644 private CriticalEventLogProto getLogOutput(CriticalEventLog log, int traceProcessClassEnum, 645 String traceProcessName, int traceProcessUid) { 646 return log.getOutputLogProto(traceProcessClassEnum, traceProcessName, traceProcessUid); 647 } 648 getEventsWritten()649 private CriticalEventLogStorageProto getEventsWritten() throws IOException { 650 return CriticalEventLogStorageProto.parseFrom( 651 Files.readAllBytes(mTestFile.toPath())); 652 } 653 654 /** 655 * Creates a log file containing some watchdog events. 656 * 657 * They occur at a rate of one per second, with the last at 1 sec before START_TIME_MS. 658 */ createTestFileWithEvents(int numEvents)659 private void createTestFileWithEvents(int numEvents) throws Exception { 660 CriticalEventLogStorageProto log = new CriticalEventLogStorageProto(); 661 log.events = new CriticalEventProto[numEvents]; 662 long startTimeMs = START_TIME_MS - (numEvents * 1000L); 663 664 for (int i = 0; i < numEvents; i++) { 665 long timestampMs = startTimeMs + (i * 1000L); 666 String subject = String.format("Old watchdog %d", i + 1); 667 log.events[i] = watchdog(timestampMs, subject); 668 } 669 670 try (FileOutputStream stream = new FileOutputStream(mTestFile)) { 671 stream.write(CriticalEventLogStorageProto.toByteArray(log)); 672 } 673 } 674 watchdog(long timestampMs, String subject)675 private static CriticalEventProto watchdog(long timestampMs, String subject) { 676 return watchdog(timestampMs, subject, "A UUID"); 677 } 678 watchdog(long timestampMs, String subject, String uuid)679 private static CriticalEventProto watchdog(long timestampMs, String subject, String uuid) { 680 CriticalEventProto event = new CriticalEventProto(); 681 event.timestampMs = timestampMs; 682 event.setWatchdog(new Watchdog()); 683 event.getWatchdog().subject = subject; 684 event.getWatchdog().uuid = uuid; 685 return event; 686 } 687 halfWatchdog(long timestampMs, String subject)688 private static CriticalEventProto halfWatchdog(long timestampMs, String subject) { 689 CriticalEventProto event = new CriticalEventProto(); 690 event.timestampMs = timestampMs; 691 event.setHalfWatchdog(new HalfWatchdog()); 692 event.getHalfWatchdog().subject = subject; 693 return event; 694 } 695 anr(long timestampMs, String subject, int processClass, String processName, int uid, int pid)696 private static CriticalEventProto anr(long timestampMs, String subject, int processClass, 697 String processName, int uid, int pid) { 698 CriticalEventProto event = new CriticalEventProto(); 699 event.timestampMs = timestampMs; 700 event.setAnr(new AppNotResponding()); 701 event.getAnr().subject = subject; 702 event.getAnr().processClass = processClass; 703 event.getAnr().process = processName; 704 event.getAnr().uid = uid; 705 event.getAnr().pid = pid; 706 return event; 707 } 708 javaCrash(long timestampMs, String exceptionClass, int processClass, String processName, int uid, int pid)709 private static CriticalEventProto javaCrash(long timestampMs, String exceptionClass, 710 int processClass, String processName, int uid, int pid) { 711 CriticalEventProto event = new CriticalEventProto(); 712 event.timestampMs = timestampMs; 713 event.setJavaCrash(new JavaCrash()); 714 event.getJavaCrash().exceptionClass = exceptionClass; 715 event.getJavaCrash().processClass = processClass; 716 event.getJavaCrash().process = processName; 717 event.getJavaCrash().uid = uid; 718 event.getJavaCrash().pid = pid; 719 return event; 720 } 721 nativeCrash(long timestampMs, int processClass, String processName, int uid, int pid)722 private static CriticalEventProto nativeCrash(long timestampMs, int processClass, 723 String processName, int uid, int pid) { 724 CriticalEventProto event = new CriticalEventProto(); 725 event.timestampMs = timestampMs; 726 event.setNativeCrash(new NativeCrash()); 727 event.getNativeCrash().processClass = processClass; 728 event.getNativeCrash().process = processName; 729 event.getNativeCrash().uid = uid; 730 event.getNativeCrash().pid = pid; 731 return event; 732 } 733 assertProtoArrayEquals(MessageNano[] actual, MessageNano[] expected)734 private static void assertProtoArrayEquals(MessageNano[] actual, MessageNano[] expected) { 735 assertThat(expected).isNotNull(); 736 assertThat(actual).isNotNull(); 737 738 String baseMsg = String.format("Expected:\n%s\nGot:\n%s", Arrays.toString(expected), 739 Arrays.toString(actual)); 740 String lengthMsg = String.format("%s\nGot different length arrays.\bExpected %d, got %d", 741 baseMsg, expected.length, actual.length); 742 assertWithMessage(lengthMsg).that(expected.length).isEqualTo(actual.length); 743 for (int i = 0; i < expected.length; i++) { 744 String pairMsg = String.format("%s\nMismatched pair.\nExpected:\n%s\nGot:\n%s", 745 baseMsg, expected[i], actual[i]); 746 assertWithMessage(pairMsg).that( 747 MessageNano.messageNanoEquals(expected[i], actual[i])).isTrue(); 748 } 749 } 750 assertProtoEquals(MessageNano actual, MessageNano expected)751 private static void assertProtoEquals(MessageNano actual, MessageNano expected) { 752 String message = String.format("Expected:\n%s\nGot:\n%s", expected, actual); 753 assertWithMessage(message).that( 754 MessageNano.messageNanoEquals(expected, actual)).isTrue(); 755 } 756 assertProtoNotEqual(MessageNano first, MessageNano second)757 private static void assertProtoNotEqual(MessageNano first, MessageNano second) { 758 String message = String.format("Expected protos to be different, but were equal:\n%s", 759 first); 760 assertWithMessage(message).that( 761 MessageNano.messageNanoEquals(first, second)).isFalse(); 762 } 763 setLogInstance()764 private TestableCriticalEventLog setLogInstance() { 765 return setLogInstance(new LogLoader()); 766 } 767 setLogInstance(ILogLoader logLoader)768 private TestableCriticalEventLog setLogInstance(ILogLoader logLoader) { 769 mCriticalEventLog = new TestableCriticalEventLog(mFolder.getRoot().getAbsolutePath(), 770 logLoader); 771 return mCriticalEventLog; 772 } 773 774 private static class TestableCriticalEventLog extends CriticalEventLog { 775 private long mNowMillis = START_TIME_MS; 776 TestableCriticalEventLog(String logDir, ILogLoader logLoader)777 TestableCriticalEventLog(String logDir, ILogLoader logLoader) { 778 super(logDir, 779 BUFFER_CAPACITY, 780 (int) LOG_WINDOW.toMillis(), 781 MIN_TIME_BETWEEN_SAVES.toMillis(), 782 /* loadAndSaveImmediately= */ true, 783 logLoader); 784 } 785 786 @Override getWallTimeMillis()787 protected long getWallTimeMillis() { 788 return mNowMillis; 789 } 790 incTimeSeconds(int seconds)791 void incTimeSeconds(int seconds) { 792 mNowMillis += (seconds * 1000L); 793 } 794 setCurrentTimeMillis(long millis)795 void setCurrentTimeMillis(long millis) { 796 mNowMillis = millis; 797 } 798 } 799 800 /** 801 * A log loader that does nothing. 802 * 803 * Used to check behaviour when log loading is slow since the loading happens 804 * asynchronously. 805 */ 806 private static class NoOpLogLoader implements ILogLoader { 807 @Override load(File logFile, CriticalEventLog.ThreadSafeRingBuffer<CriticalEventProto> buffer)808 public void load(File logFile, 809 CriticalEventLog.ThreadSafeRingBuffer<CriticalEventProto> buffer) { 810 // Do nothing. 811 } 812 } 813 } 814