1743920 - Permafailing org.mozilla.geckoview.test.TextInputDelegateTest#<test> | org.mozilla.geckoview.test.util.UiThreadUtils$TimeoutException: Timed out after 30000ms

Status: RESOLVED FIXED

(GeckoView :: General, defect, P5)

Description

[Treeherder Bug Filer]

Filed by: ncsoregi [at] mozilla.com
Parsed log: https://treeherder.mozilla.org/logviewer?job_id=359856329&repo=autoland
Full log: https://firefox-ci-tc.services.mozilla.com/api/queue/v1/task/Hc9HbtvwQZW3DVw5E45jLQ/runs/0/artifacts/public/logs/live_backing.log

---

[task 2021-12-01T17:12:26.635Z] 17:12:26     INFO -  12-01 17:12:26.226 E/GeckoSessionTestRule( 3466): Error
[task 2021-12-01T17:12:26.635Z] 17:12:26     INFO -  12-01 17:12:26.226 E/GeckoSessionTestRule( 3466): org.mozilla.geckoview.test.util.UiThreadUtils$TimeoutException: Timed out after 30000ms
[task 2021-12-01T17:12:26.635Z] 17:12:26     INFO -  12-01 17:12:26.226 E/GeckoSessionTestRule( 3466): 	at org.mozilla.geckoview.test.util.UiThreadUtils$TimeoutRunnable.run(UiThreadUtils.java:49)
[task 2021-12-01T17:12:26.636Z] 17:12:26     INFO -  12-01 17:12:26.226 E/GeckoSessionTestRule( 3466): 	at android.os.Handler.handleCallback(Handler.java:751)
[task 2021-12-01T17:12:26.636Z] 17:12:26     INFO -  12-01 17:12:26.226 E/GeckoSessionTestRule( 3466): 	at android.os.Handler.dispatchMessage(Handler.java:95)
[task 2021-12-01T17:12:26.636Z] 17:12:26     INFO -  12-01 17:12:26.226 E/GeckoSessionTestRule( 3466): 	at org.mozilla.geckoview.test.util.UiThreadUtils.waitForCondition(UiThreadUtils.java:158)
[task 2021-12-01T17:12:26.636Z] 17:12:26     INFO -  12-01 17:12:26.226 E/GeckoSessionTestRule( 3466): 	at org.mozilla.geckoview.test.rule.GeckoSessionTestRule.waitForMessage(GeckoSessionTestRule.java:2174)
[task 2021-12-01T17:12:26.636Z] 17:12:26     INFO -  12-01 17:12:26.226 E/GeckoSessionTestRule( 3466): 	at org.mozilla.geckoview.test.rule.GeckoSessionTestRule.evaluateJS(GeckoSessionTestRule.java:2134)
[task 2021-12-01T17:12:26.636Z] 17:12:26     INFO -  12-01 17:12:26.226 E/GeckoSessionTestRule( 3466): 	at org.mozilla.geckoview.test.rule.GeckoSessionTestRule.waitForJS(GeckoSessionTestRule.java:2300)
[task 2021-12-01T17:12:26.636Z] 17:12:26     INFO -  12-01 17:12:26.226 E/GeckoSessionTestRule( 3466): 	at org.mozilla.geckoview.test.BaseSessionTest.waitForJS(BaseSessionTest.kt:210)
[task 2021-12-01T17:12:26.637Z] 17:12:26     INFO -  12-01 17:12:26.226 E/GeckoSessionTestRule( 3466): 	at org.mozilla.geckoview.test.TextInputDelegateTest.processChildEvents(TextInputDelegateTest.kt:110)
[task 2021-12-01T17:12:26.637Z] 17:12:26     INFO -  12-01 17:12:26.226 E/GeckoSessionTestRule( 3466): 	at org.mozilla.geckoview.test.TextInputDelegateTest.assertText(TextInputDelegateTest.kt:346)
[task 2021-12-01T17:12:26.637Z] 17:12:26     INFO -  12-01 17:12:26.226 E/GeckoSessionTestRule( 3466): 	at org.mozilla.geckoview.test.TextInputDelegateTest.inputConnection_largeText(TextInputDelegateTest.kt:669)
[task 2021-12-01T17:12:26.637Z] 17:12:26     INFO -  12-01 17:12:26.226 E/GeckoSessionTestRule( 3466): 	at java.lang.reflect.Method.invoke(Native Method)
[task 2021-12-01T17:12:26.637Z] 17:12:26     INFO -  12-01 17:12:26.226 E/GeckoSessionTestRule( 3466): 	at org.junit.runners.model.FrameworkMethod$1.runReflectiveCall(FrameworkMethod.java:50)
[task 2021-12-01T17:12:26.637Z] 17:12:26     INFO -  12-01 17:12:26.226 E/GeckoSessionTestRule( 3466): 	at org.junit.internal.runners.model.ReflectiveCallable.run(ReflectiveCallable.java:12)
[task 2021-12-01T17:12:26.637Z] 17:12:26     INFO -  12-01 17:12:26.226 E/GeckoSessionTestRule( 3466): 	at org.junit.runners.model.FrameworkMethod.invokeExplosively(FrameworkMethod.java:47)
[task 2021-12-01T17:12:26.637Z] 17:12:26     INFO -  12-01 17:12:26.226 E/GeckoSessionTestRule( 3466): 	at org.junit.internal.runners.statements.InvokeMethod.evaluate(InvokeMethod.java:17)
[task 2021-12-01T17:12:26.637Z] 17:12:26     INFO -  12-01 17:12:26.226 E/GeckoSessionTestRule( 3466): 	at org.mozilla.geckoview.test.rule.GeckoSessionTestRule$2.lambda$evaluate$0$GeckoSessionTestRule$2(GeckoSessionTestRule.java:1442)
[task 2021-12-01T17:12:26.638Z] 17:12:26     INFO -  12-01 17:12:26.226 E/GeckoSessionTestRule( 3466): 	at org.mozilla.geckoview.test.rule.-$$Lambda$GeckoSessionTestRule$2$TNUWVrkQlCzXHIjIbcLih1Q8TRE.run(lambda)
[task 2021-12-01T17:12:26.638Z] 17:12:26     INFO -  12-01 17:12:26.226 E/GeckoSessionTestRule( 3466): 	at android.app.Instrumentation$SyncRunnable.run(Instrumentation.java:1950)
[task 2021-12-01T17:12:26.638Z] 17:12:26     INFO -  12-01 17:12:26.226 E/GeckoSessionTestRule( 3466): 	at android.os.Handler.handleCallback(Handler.java:751)
[task 2021-12-01T17:12:26.638Z] 17:12:26     INFO -  12-01 17:12:26.226 E/GeckoSessionTestRule( 3466): 	at android.os.Handler.dispatchMessage(Handler.java:95)
[task 2021-12-01T17:12:26.638Z] 17:12:26     INFO -  12-01 17:12:26.226 E/GeckoSessionTestRule( 3466): 	at android.os.Looper.loop(Looper.java:154)
[task 2021-12-01T17:12:26.638Z] 17:12:26     INFO -  12-01 17:12:26.226 E/GeckoSessionTestRule( 3466): 	at android.app.ActivityThread.main(ActivityThread.java:6077)
[task 2021-12-01T17:12:26.638Z] 17:12:26     INFO -  12-01 17:12:26.226 E/GeckoSessionTestRule( 3466): 	at java.lang.reflect.Method.invoke(Native Method)
[task 2021-12-01T17:12:26.638Z] 17:12:26     INFO -  12-01 17:12:26.226 E/GeckoSessionTestRule( 3466): 	at com.android.internal.os.ZygoteInit$MethodAndArgsCaller.run(ZygoteInit.java:866)
[task 2021-12-01T17:12:26.638Z] 17:12:26     INFO -  12-01 17:12:26.226 E/GeckoSessionTestRule( 3466): 	at com.android.internal.os.ZygoteInit.main(ZygoteInit.java:756)
[task 2021-12-01T17:12:26.638Z] 17:12:26     INFO -  12-01 17:12:26.231 D/GeckoViewConsole( 3466): onEvent GeckoView:WebExtension:PortMessageFromApp {"message":{"id":"2ac07c99-9109-48fd-be00-f9430a4dfe28","args":{"oldPrefs":{"dom.select_events.textcontrols.enabled":null}},"type":"RestorePrefs"}}
[task 2021-12-01T17:12:26.639Z] 17:12:26     INFO -  12-01 17:12:26.243 D/EGL_emulation( 3466): eglMakeCurrent: 0x7ec8e05539a0: ver 3 0 (tinfo 0x7ec8e0551f80)
[task 2021-12-01T17:12:26.639Z] 17:12:26     INFO -  12-01 17:12:26.246 D/GeckoViewContent( 3466): handleEvent: DOMWindowClose
[task 2021-12-01T17:12:26.639Z] 17:12:26     INFO -  12-01 17:12:26.248 D/GeckoViewConsole( 3466): onEvent GeckoView:WebExtension:List null
[task 2021-12-01T17:12:26.639Z] 17:12:26     INFO -  12-01 17:12:26.252 I/Gecko   ( 3466): nsWindow[0x7ec882ce3800]::Show 0
[task 2021-12-01T17:12:26.639Z] 17:12:26     INFO -  12-01 17:12:26.252 E/GeckoSessionTestRule( 3466): test_end c5ee677f-bc83-49bd-9e28-2d35f3d0f059 inputConnection_largeText[#textarea](org.mozilla.geckoview.test.TextInputDelegateTest)
[task 2021-12-01T17:12:26.639Z] 17:12:26  WARNING -  TEST-UNEXPECTED-FAIL | org.mozilla.geckoview.test.TextInputDelegateTest#inputConnection_largeText[#textarea] | org.mozilla.geckoview.test.util.UiThreadUtils$TimeoutException: Timed out after 30000ms
[task 2021-12-01T17:12:26.639Z] 17:12:26     INFO -  TEST-INFO took 32604ms

Comment 1

[Natalia Csoregi [:nataliaCs]]

It has started permafailing: https://treeherder.mozilla.org/jobs?repo=autoland&resultStatus=success%2Ctestfailed%2Cbusted%2Cexception%2Crunnable&searchStr=android%2C7.0%2Cx86-64%2Clite%2Cwebrender%2Cdebug%2Ctest-android-em-7.0-x86_64-lite-qr%2Fdebug-geckoview-junit-e10s-single-e10s%2Cgv-junit-e10s-single&tochange=e86bd6c22ef7deb3ed8606825a4651b159e29a50&fromchange=80cc015458a7a856a31110a46ee9e866f428090a&selectedTaskRun=Hc9HbtvwQZW3DVw5E45jLQ.0

:m_kato, could you take a look at this please?

Comment 2

[Makoto Kato [:m_kato]]

(In reply to Natalia Csoregi [:nataliaCs] from comment #1)

It has started permafailing: https://treeherder.mozilla.org/jobs?repo=autoland&resultStatus=success%2Ctestfailed%2Cbusted%2Cexception%2Crunnable&searchStr=android%2C7.0%2Cx86-64%2Clite%2Cwebrender%2Cdebug%2Ctest-android-em-7.0-x86_64-lite-qr%2Fdebug-geckoview-junit-e10s-single-e10s%2Cgv-junit-e10s-single&tochange=e86bd6c22ef7deb3ed8606825a4651b159e29a50&fromchange=80cc015458a7a856a31110a46ee9e866f428090a&selectedTaskRun=Hc9HbtvwQZW3DVw5E45jLQ.0

:m_kato, could you take a look at this please?

This timeout seems to be that new Promise(r => requestAnimationFrame(r)) isn't resolved. I guess that this might be infra issue or another bug. Could you reproduce this repeatedly?

Comment 3

[Noemi Erli[:noemi_erli]]

Yes, this is still happening and it's still a perma : https://treeherder.mozilla.org/jobs?repo=autoland&resultStatus=pending%2Crunning%2Csuccess%2Ctestfailed%2Cbusted%2Cexception%2Crunnable&searchStr=gv-junit&fromchange=a94d331487a16ec105425c34badeb25545d0adbe&tochange=90369a230cb466c36dea3c186b3b92716c9bc826

https://treeherder.mozilla.org/jobs?repo=autoland&resultStatus=pending%2Crunning%2Csuccess%2Ctestfailed%2Cbusted%2Cexception%2Crunnable&searchStr=android%2C7.0%2Cx86-64%2Clite%2Cwebrender%2Cdebug%2Ctest-android-em-7.0-x86_64-lite-qr%2Fdebug-geckoview-junit-e10s-single-e10s%2Cgv-junit-e10s-single&fromchange=d383983b68e25544e2578348073e1f4e907b6969&tochange=815bbe6ee2b0b736cbbbcf74fb15099e5e9977b9

Comment 4

[Sebastian Hengst [:aryx] (needinfo me if it's about an intermittent or backout)]

Could the failing tests be temporarily disabled?

Comment 5

[Makoto Kato [:m_kato]]

(In reply to Sebastian Hengst [:aryx] (needinfo on intermittent or backout) from comment #4)

Could the failing tests be temporarily disabled?

Maybe all geckoview-junit tests will be failure since client JavaScript doesn't run well. I want to know regression range for this failures.

Comment 6

[Makoto Kato [:m_kato]]

agi, do you change anything test infra for geckoview-junit?

Comment 7

[Makoto Kato [:m_kato]]

WebPush tests of GEckoView-junit (Not TextInputDelegateTest ) is also failure such as https://treeherder.mozilla.org/logviewer?job_id=359931595&repo=autoland&lineNumber=13368. This failure is timeout since client JS doesn't resolve Promise.

Comment 8

[Intermittent Failures Robot]

96 failures in 654 pushes (0.147 failures/push) were associated with this bug yesterday.

Repository breakdown:

• autoland: 88
• mozilla-central: 8

Platform and build breakdown:

• android-em-7-0-x86_64-qr: 56
  • debug-isolated-process: 30
  • debug: 26
• android-em-7-0-x86_64-lite-qr: 40
  • debug: 40

For more details, see:
https://treeherder.mozilla.org/intermittent-failures/bugdetails?bug=1743920&startday=2021-12-02&endday=2021-12-02&tree=all

Comment 9

[Andreea Pavel [:apavel]]

No failures in the last 2 days.

Comment 10

[Intermittent Failures Robot]

99 failures in 3170 pushes (0.031 failures/push) were associated with this bug in the last 7 days.

This is the #5 most frequent failure this week.

** This failure happened more than 75 times this week! Resolving this bug is a very high priority. **

** Try to resolve this bug as soon as possible. If unresolved for 1 week, the affected test(s) may be disabled. **

Repository breakdown:

• autoland: 91
• mozilla-central: 8

Platform and build breakdown:

• android-em-7-0-x86_64-lite-qr: 41
  • debug: 41
• android-em-7-0-x86_64-qr: 58
  • debug: 28
  • debug-isolated-process: 30

For more details, see:
https://treeherder.mozilla.org/intermittent-failures/bugdetails?bug=1743920&startday=2021-11-29&endday=2021-12-05&tree=all

Comment 11

[Mathew Hodson]

The push in bug 1743637 that caused these failures was backed out by https://hg.mozilla.org/mozilla-central/rev/8290bc0f4cebe33a586feabe5d9040dedcd6a94d

If the failures have stopped, can this bug be closed?

Comment 12

[Makoto Kato [:m_kato]]

(In reply to Mathew Hodson from comment #11)

The push in bug 1743637 that caused these failures was backed out by https://hg.mozilla.org/mozilla-central/rev/8290bc0f4cebe33a586feabe5d9040dedcd6a94d

If the failures have stopped, can this bug be closed?

I guess that previous fix (https://hg.mozilla.org/integration/autoland/rev/e86bd6c22ef7) causes that it hits the cast assertion. The latest fix of bug 1743637 resolves it, so this won't occur after bug 1743637 is closed.

Comment 13

[Mathew Hodson]

Fixed by the back out.