ref(android): Measure ANR thresholds on the uptime clock (JAVA-579)

The watchdog took its readings from an ICurrentDateProvider lambda over
SystemClock.uptimeMillis(). The type said nothing about which clock it
carried, so nothing stopped a caller from handing it an elapsed-real-time
provider — and that substitution is not benign here: elapsed real time
counts deep sleep, so a device suspended between posting the ticker and
checking it would report the suspended interval as a blocked main thread
and fabricate an ANR.

UptimeClock names the guarantee the detection depends on, and Deadline
replaces the hand-rolled "now minus last tick" arithmetic with the
question actually being asked: has the main thread missed its window.

System.nanoTime() is CLOCK_MONOTONIC on Android, the same clock behind
SystemClock.uptimeMillis(), so the thresholds are unchanged.

Author: runningcode

sentry-android-core/src/main/java/io/sentry/android/core/ANRWatchDog.java

@@ -30,11 +30,13 @@
 import android.app.ActivityManager;
 import android.content.Context;
 import android.os.Debug;
-import android.os.SystemClock;
 import io.sentry.ILogger;
 import io.sentry.SentryLevel;
-import io.sentry.transport.ICurrentDateProvider;
+import io.sentry.time.Deadline;
+import io.sentry.time.JavaUptimeClock;
+import io.sentry.time.UptimeClock;
 import java.util.List;
+import java.util.concurrent.TimeUnit;
 import java.util.concurrent.atomic.AtomicBoolean;
 import org.jetbrains.annotations.NotNull;
 import org.jetbrains.annotations.TestOnly;
@@ -46,15 +48,17 @@ final class ANRWatchDog extends Thread {
   private final boolean reportInDebug;
   private final ANRListener anrListener;
   private final MainLooperHandler uiHandler;
-  private final ICurrentDateProvider timeProvider;
+  private final UptimeClock clock;
 
   /** the interval in which we check if there's an ANR, in ms */
   private long pollingIntervalMs;
 
   private final long timeoutIntervalMillis;
   private final @NotNull ILogger logger;
 
-  private volatile long lastKnownActiveUiTimestampMs = 0;
+  /** How long the main thread has left to run the ticker before we call it an ANR. */
+  private volatile @NotNull Deadline uiResponsiveUntil;
+
   private final AtomicBoolean reported = new AtomicBoolean(false);
 
   private final @NotNull Context context;
@@ -68,10 +72,8 @@ final class ANRWatchDog extends Thread {
       @NotNull ANRListener listener,
       @NotNull ILogger logger,
       final @NotNull Context context) {
-    // avoid method refs on Android due to some issues with older AGP setups
-    // noinspection Convert2MethodRef
     this(
-        () -> SystemClock.uptimeMillis(),
+        JavaUptimeClock.getInstance(),
         timeoutIntervalMillis,
         500,
         reportInDebug,
@@ -83,7 +85,7 @@ final class ANRWatchDog extends Thread {
 
   @TestOnly
   ANRWatchDog(
-      @NotNull final ICurrentDateProvider timeProvider,
+      @NotNull final UptimeClock clock,
       long timeoutIntervalMillis,
       long pollingIntervalMillis,
       boolean reportInDebug,
@@ -94,17 +96,18 @@ final class ANRWatchDog extends Thread {
 
     super("|ANR-WatchDog|");
 
-    this.timeProvider = timeProvider;
+    this.clock = clock;
     this.timeoutIntervalMillis = timeoutIntervalMillis;
     this.pollingIntervalMs = pollingIntervalMillis;
     this.reportInDebug = reportInDebug;
     this.anrListener = listener;
     this.logger = logger;
     this.uiHandler = uiHandler;
     this.context = context;
+    this.uiResponsiveUntil = Deadline.after(clock, timeoutIntervalMillis, TimeUnit.MILLISECONDS);
     this.ticker =
         () -> {
-          lastKnownActiveUiTimestampMs = timeProvider.getCurrentTimeMillis();
+          uiResponsiveUntil = Deadline.after(clock, timeoutIntervalMillis, TimeUnit.MILLISECONDS);
           reported.set(false);
         };
 
@@ -140,11 +143,8 @@ public void run() {
         return;
       }
 
-      final long unresponsiveDurationMs =
-          timeProvider.getCurrentTimeMillis() - lastKnownActiveUiTimestampMs;
-
       // If the main thread has not handled ticker, it is blocked. ANR.
-      if (unresponsiveDurationMs > timeoutIntervalMillis) {
+      if (uiResponsiveUntil.hasPassed()) {
         if (!reportInDebug && (Debug.isDebuggerConnected() || Debug.waitingForDebugger())) {
           logger.log(
               SentryLevel.DEBUG,

sentry-android-core/src/test/java/io/sentry/android/core/ANRWatchDogTest.kt

@@ -4,10 +4,11 @@ import android.app.ActivityManager
 import android.app.ActivityManager.ProcessErrorStateInfo.NOT_RESPONDING
 import android.app.ActivityManager.ProcessErrorStateInfo.NO_ERROR
 import android.content.Context
-import io.sentry.transport.ICurrentDateProvider
+import io.sentry.time.TestTicker
 import java.util.concurrent.CountDownLatch
 import java.util.concurrent.Executors
 import java.util.concurrent.TimeUnit
+import java.util.concurrent.TimeUnit.MILLISECONDS
 import kotlin.test.Test
 import kotlin.test.assertEquals
 import kotlin.test.assertNotNull
@@ -20,12 +21,12 @@ import org.mockito.kotlin.mock
 import org.mockito.kotlin.whenever
 
 class ANRWatchDogTest {
-  private var currentTimeMs = 0L
-  private val timeProvider = ICurrentDateProvider { currentTimeMs }
+  private lateinit var clock: TestTicker
 
   @Before
   fun `setup`() {
-    currentTimeMs = 12341234
+    // an arbitrary, non-zero origin: no caller may assume a tick counts from zero
+    clock = TestTicker(MILLISECONDS.toNanos(12341234))
   }
 
   @Test
@@ -42,8 +43,7 @@ class ANRWatchDogTest {
     whenever(handler.thread).thenReturn(thread)
     val interval = 10L
 
-    val sut =
-      ANRWatchDog(timeProvider, interval, 1L, true, { a -> anr = a }, mock(), handler, mock())
+    val sut = ANRWatchDog(clock, interval, 1L, true, { a -> anr = a }, mock(), handler, mock())
     val es = Executors.newSingleThreadExecutor()
     try {
       es.submit { sut.run() }
@@ -53,7 +53,7 @@ class ANRWatchDogTest {
       ) // Wait until worker posts the job for the "UI thread"
       var waitCount = 0
       do {
-        currentTimeMs += 100L
+        clock.advance(100, MILLISECONDS)
         Thread.sleep(100) // Let worker realize this is ANR
       } while (anr == null && waitCount++ < 100)
 
@@ -79,15 +79,14 @@ class ANRWatchDogTest {
     whenever(handler.thread).thenReturn(thread)
     val interval = 10L
 
-    val sut =
-      ANRWatchDog(timeProvider, interval, 1L, true, { a -> anr = a }, mock(), handler, mock())
+    val sut = ANRWatchDog(clock, interval, 1L, true, { a -> anr = a }, mock(), handler, mock())
     val es = Executors.newSingleThreadExecutor()
     try {
       es.submit { sut.run() }
 
       var waitCount = 0
       do {
-        currentTimeMs += 100L
+        clock.advance(100, MILLISECONDS)
         Thread.sleep(100) // Let worker realize his runner always runs
       } while (!invoked && waitCount++ < 100)
 
@@ -121,8 +120,7 @@ class ANRWatchDogTest {
     val anrs = listOf(stateInfo)
     whenever(am.processesInErrorState).thenReturn(anrs)
 
-    val sut =
-      ANRWatchDog(timeProvider, interval, 1L, true, { a -> anr = a }, mock(), handler, context)
+    val sut = ANRWatchDog(clock, interval, 1L, true, { a -> anr = a }, mock(), handler, context)
     val es = Executors.newSingleThreadExecutor()
     try {
       es.submit { sut.run() }
@@ -132,7 +130,7 @@ class ANRWatchDogTest {
       ) // Wait until worker posts the job for the "UI thread"
       var waitCount = 0
       do {
-        currentTimeMs += 100L
+        clock.advance(100, MILLISECONDS)
         Thread.sleep(100) // Let worker realize this is ANR
       } while (anr == null && waitCount++ < 100)
 
@@ -167,8 +165,7 @@ class ANRWatchDogTest {
     val anrs = listOf(stateInfo)
     whenever(am.processesInErrorState).thenReturn(anrs)
 
-    val sut =
-      ANRWatchDog(timeProvider, interval, 1L, true, { a -> anr = a }, mock(), handler, context)
+    val sut = ANRWatchDog(clock, interval, 1L, true, { a -> anr = a }, mock(), handler, context)
     val es = Executors.newSingleThreadExecutor()
     try {
       es.submit { sut.run() }
@@ -178,7 +175,7 @@ class ANRWatchDogTest {
       ) // Wait until worker posts the job for the "UI thread"
       var waitCount = 0
       do {
-        currentTimeMs += 100L
+        clock.advance(100, MILLISECONDS)
         Thread.sleep(100L) // Let worker realize this is ANR
       } while (anr == null && waitCount++ < 100)
       assertNull(anr) // callback never ran
@@ -187,4 +184,31 @@ class ANRWatchDogTest {
       es.shutdown()
     }
   }
+
+  @Test
+  fun `a device suspend does not trip the ANR threshold`() {
+    // The uptime clock stands still while the device is suspended, so a suspend cannot be mistaken
+    // for a blocked main thread. On an elapsed-real-time clock the suspended interval would count
+    // against the main thread and fabricate an ANR.
+    var anr: ApplicationNotResponding? = null
+    val handler = mock<MainLooperHandler>()
+    val latch = CountDownLatch(1)
+    whenever(handler.post(any())).then { latch.countDown() }
+    whenever(handler.thread).thenReturn(mock<Thread>())
+
+    // context is a mock, so ActivityManager is absent and any passed deadline reports an ANR
+    val sut = ANRWatchDog(clock, 10L, 1L, true, { a -> anr = a }, mock(), handler, mock())
+    val es = Executors.newSingleThreadExecutor()
+    try {
+      es.submit { sut.run() }
+
+      assertTrue(latch.await(10L, TimeUnit.SECONDS)) // wait until the watchdog is polling
+      Thread.sleep(200) // hundreds of polls of wall time, none of it uptime
+
+      assertNull(anr)
+    } finally {
+      sut.interrupt()
+      es.shutdown()
+    }
+  }
 }