[3.7.0] Espresso IdlingResources + Looper timeouts

[AlexanderGH]

In 3.7.0 (this didn't happen in 3.6.x) we started getting idling resource timeouts for the loopers registered with registerLooperAsIdlingResource. It's unclear why they are suddenly timing out since calling dump() shows no queues messages/tasks.

However, things are hard to debug because androidx.test.espresso.base.Interrogator replaces the default queue handling with its own less realistic loopAndInterrogate impl. As a result, we can't use things like Looper.setMessageLogging as that config is ignored by the internal Handler of Interrogator. I also question whether loopAndInterrogate is correct, since when i don't call registerLooperAsIdlingResource the output of dump is different (and the message logging works), while ideally it should be the same.

Likely not useful, but here's an example stack-trace:

01-10 21:37:12.126 12249 12279 E TestRunner: androidx.test.espresso.IdlingResourceTimeoutException: Wait for [LooperIdlingResource-88-epoxy, LooperIdlingResource-87-FooWorkerThread] to become idle timed out
01-10 21:37:12.126 12249 12279 E TestRunner: 	at dalvik.system.VMStack.getThreadStackTrace(Native Method)
01-10 21:37:12.126 12249 12279 E TestRunner: 	at java.lang.Thread.getStackTrace(Thread.java:1960)
01-10 21:37:12.126 12249 12279 E TestRunner: 	at androidx.test.espresso.base.EspressoExceptionHandler.handleSafely(EspressoExceptionHandler.java:34)
01-10 21:37:12.126 12249 12279 E TestRunner: 	at androidx.test.espresso.base.EspressoExceptionHandler.handleSafely(EspressoExceptionHandler.java:26)
01-10 21:37:12.126 12249 12279 E TestRunner: 	at androidx.test.espresso.base.DefaultFailureHandler$TypedFailureHandler.handle(DefaultFailureHandler.java:158)
01-10 21:37:12.126 12249 12279 E TestRunner: 	at androidx.test.espresso.base.DefaultFailureHandler.handle(DefaultFailureHandler.java:120)
01-10 21:37:12.126 12249 12279 E TestRunner: 	at androidx.test.espresso.ViewInteraction.waitForAndHandleInteractionResults(ViewInteraction.java:385)
01-10 21:37:12.126 12249 12279 E TestRunner: 	at androidx.test.espresso.ViewInteraction.desugaredPerform(ViewInteraction.java:212)
01-10 21:37:12.126 12249 12279 E TestRunner: 	at androidx.test.espresso.ViewInteraction.perform(ViewInteraction.java:140)
01-10 21:37:12.126 12249 12279 E TestRunner: 	at androidx.test.espresso.Espresso.closeSoftKeyboard(Espresso.java:206)

I suspect it's a regression in 3.7.0, but if not, it would be nice to include more debugging info in the error about what task(s) are beleived to make the handler/looper not idle and also unclear dump() and setMessageLogging.

[brettchabot]

There was changes in Interrogator in 3.7.0 so it is possible there is a regression here.

But without more details its difficult to make this report actionable.

I'd suggest to turn on the "Interrogator" Logcat debugging to gain more insight.

Is it possible to provide a reproducible sample ?

[AlexanderGH]

Managed to get a minimal repro after going through every method call made onto the relevant handler/loopers. Looks like it's due to quit().

    @Test
    fun foo() {
        val handler1thread = HandlerThread("asd1").also {
            it.start()
        }
        val handler1 = Handler.createAsync(handler1thread.looper)
        IdlingRegistry.getInstance().registerLooperAsIdlingResource(handler1thread.looper)
        handler1thread.quit()
        Espresso.onIdle()
    }

[AlexanderGH]

Unfortunately, while that minimal repro has the same failure mode, I confirmed we still fail even without our code quitting the loopers. Attached are the interrogator logs (sadly, they don't seem too useful to me, but maybe you'll spot something I didn't). If you need any other log tags or need to me to enable any debug features, let me now.

test.txt

[AlexanderGH]

Any other logs or info I could grab that might be useful?

[brettchabot]

Sorry for lack of response. Yeah having just the Interrogator logs in isolation isn't that useful. Is it possible to add logging to the sections when you expect 'Espresso.onIdle' to return immediately and it doesn't.

Which Android SDK version are your tests running on?

I'm able to repro the 'quit' scenario and will look into it. I think it might be tricky to handle this without race conditions with the new concurrent queue. The previous Interrogator implementation did not have explicit handling for 'quit' either, but I think it worked because it would synchronize on the entire queue, and rely on quit emptying the message queue.

[AlexanderGH]

So far I've confirmed SDK/API level 31-36 have the issue. I can check older releases too if needed but i suspect it happens for all versions.

Attached some new logs with:

02-18 11:37:51.874  9068  9120 E Interrogator: [TEST METHOD ENDED]
02-18 11:37:53.176  9068  9120 E Interrogator: [TEST RULE EVALUATE END]
02-18 11:37:53.177  9068  9120 E Interrogator: [WAIT FOR onIdle()]

which are right before we call the onIdle(). I suspect we'd need more/extra logging in the interrogator/androidx to maybe log what specifically is causing it to not go idle.

log_output.txt