diff --git a/android-core/src/androidTest/kotlin/com.mparticle/internal/BaseHandlerDisableTest.kt b/android-core/src/androidTest/kotlin/com.mparticle/internal/BaseHandlerDisableTest.kt new file mode 100644 index 000000000..b2e4c8644 --- /dev/null +++ b/android-core/src/androidTest/kotlin/com.mparticle/internal/BaseHandlerDisableTest.kt @@ -0,0 +1,132 @@ +package com.mparticle.internal + +import android.os.HandlerThread +import android.os.Message +import androidx.test.ext.junit.runners.AndroidJUnit4 +import org.junit.Assert.assertTrue +import org.junit.Test +import org.junit.runner.RunWith +import java.util.concurrent.CountDownLatch +import java.util.concurrent.TimeUnit + +/** + * Regression tests for [BaseHandler.disable]. + * + * `disable()` used to wait for an in-flight message with an unbounded, non-yielding spin: + * + * ``` + * while (handling) { + * } + * ``` + * + * A loop like that never lets the runtime suspend the thread, so it can starve the garbage + * collector: if the handler thread is itself blocked on an allocation that needs a collection the + * spinning thread is preventing, neither side can progress. That is not theoretical -- it was + * observed with the test thread in state R at 100% CPU holding the mutator lock at this line, while + * the upload handler sat inside `handleMessage()` in an allocating call, so `handling` never + * cleared. + * + * It matters well beyond the SDK's own shutdown path: `MParticle.reset()` calls it, and + * `BaseAbstractTest.beforeImpl()` calls `MParticle.reset()` in the `@Before` of every instrumented + * test. One wedge there stalls the entire `connectedAndroidTest` run, which is why CI saw + * instrumented jobs burn their whole `timeout-minutes` budget and get reported as "cancelled" with + * no test report and no stack trace. + */ +@RunWith(AndroidJUnit4::class) +class BaseHandlerDisableTest { + + /** + * Generous relative to the 5s drain timeout, so this asserts "bounded" rather than asserting an + * exact duration that would be sensitive to emulator scheduling. + */ + private val disableMustReturnWithinMs = 30_000L + + /** + * `disable()` is called on a separate thread rather than on the test thread on purpose. Against + * the unfixed implementation it never returns, and calling it here would hang the test thread + * itself -- reproducing the very failure this test exists to catch, rather than reporting it. + * On a worker thread the failure is a clean, readable assertion instead. + * + * The worker is a daemon so it cannot hold the process open. In the failing case it does keep + * spinning for the remainder of the run, but that only happens when the bug is already present. + */ + @Test + fun disableReturnsEvenWhileAMessageIsStillBeingHandled() { + val thread = HandlerThread("mp-basehandler-disable-test").apply { start() } + val messageIsBeingHandled = CountDownLatch(1) + val releaseHandlerThread = CountDownLatch(1) + try { + val handler = object : BaseHandler(thread.looper) { + override fun handleMessageImpl(msg: Message?) { + messageIsBeingHandled.countDown() + // Stay inside handleMessage() for the whole of the disable() call below, so + // that `handling` is true the entire time it is observed. This is the condition + // the old spin loop could not escape. + releaseHandlerThread.await(disableMustReturnWithinMs * 2, TimeUnit.MILLISECONDS) + } + } + + handler.sendMessage(handler.obtainMessage(1)) + assertTrue( + "Handler never picked up the message, so the scenario under test was never set up", + messageIsBeingHandled.await(10, TimeUnit.SECONDS), + ) + + val disableReturned = CountDownLatch(1) + Thread { + handler.disable(true) + disableReturned.countDown() + }.apply { + name = "mp-basehandler-disable-caller" + isDaemon = true + }.start() + + assertTrue( + "disable() did not return within ${disableMustReturnWithinMs}ms with a message in " + + "flight; it is spinning instead of giving up waiting", + disableReturned.await(disableMustReturnWithinMs, TimeUnit.MILLISECONDS), + ) + } finally { + releaseHandlerThread.countDown() + thread.quitSafely() + } + } + + /** + * Bounding the wait must not turn into not waiting at all: a message that finishes well within + * the drain timeout should still have completed by the time `disable()` returns. + * + * Safe to run on the test thread -- the in-flight message finishes in 500ms, so this cannot hang + * even against the unfixed implementation. + */ + @Test + fun disableStillWaitsForAnInFlightMessageToFinish() { + val thread = HandlerThread("mp-basehandler-disable-drain-test").apply { start() } + val messageIsBeingHandled = CountDownLatch(1) + val finishedHandling = CountDownLatch(1) + try { + val handler = object : BaseHandler(thread.looper) { + override fun handleMessageImpl(msg: Message?) { + messageIsBeingHandled.countDown() + Thread.sleep(500) + finishedHandling.countDown() + } + } + + handler.sendMessage(handler.obtainMessage(1)) + assertTrue( + "Handler never picked up the message, so the scenario under test was never set up", + messageIsBeingHandled.await(10, TimeUnit.SECONDS), + ) + + handler.disable(true) + + assertTrue( + "disable() returned before the in-flight message finished", + finishedHandling.count == 0L, + ) + } finally { + thread.quitSafely() + } + } +} diff --git a/android-core/src/main/java/com/mparticle/internal/BaseHandler.java b/android-core/src/main/java/com/mparticle/internal/BaseHandler.java index 92d68b689..797fdcbc4 100644 --- a/android-core/src/main/java/com/mparticle/internal/BaseHandler.java +++ b/android-core/src/main/java/com/mparticle/internal/BaseHandler.java @@ -3,6 +3,7 @@ import android.os.Handler; import android.os.Looper; import android.os.Message; +import android.os.SystemClock; import com.mparticle.internal.listeners.InternalListenerManager; @@ -11,6 +12,14 @@ import java.util.concurrent.CountDownLatch; public class BaseHandler extends Handler { + /** + * Longest that {@link #disable(boolean)} will wait for an in-flight message to finish before + * giving up and returning. The handler is already flagged disabled and its queue already + * cleared by that point, so returning early only means one in-flight message may still be + * completing on the handler thread. + */ + private static final long DISABLE_DRAIN_TIMEOUT_MS = 5000; + private volatile boolean disabled; private volatile boolean handling; @@ -24,7 +33,18 @@ public BaseHandler(Looper looper) { public void disable(boolean disable) { this.disabled = disable; removeCallbacksAndMessages(null); - while (handling) { + // Wait for any in-flight handleMessage() to finish, but never spin without yielding: a + // tight `while (handling) {}` loop contains no suspend point, so it can starve the + // garbage collector indefinitely. If the handler thread is itself blocked waiting on a + // GC that this thread is preventing, neither side can progress. Thread.yield() gives the + // runtime a suspend point, and the deadline bounds the wait either way. + long deadline = SystemClock.uptimeMillis() + DISABLE_DRAIN_TIMEOUT_MS; + while (handling && SystemClock.uptimeMillis() < deadline) { + Thread.yield(); + } + if (handling) { + Logger.error("Handler: " + getClass().getName() + " still had a message in flight after " + + DISABLE_DRAIN_TIMEOUT_MS + "ms; giving up waiting for it to drain."); } }