Closed Bug 1636720 Opened 1 year ago Closed 11 months ago

Intermittent gv-junit-e10s-multi runjunit.py | The previous test failed because of an error in the test harness | org.mozilla.geckoview.test.rule.TestHarnessException: org.mozilla.geckoview.test.util.UiThreadUtils$TimeoutException: Timed out after 30000ms

Categories

(GeckoView :: General, defect, P2)

Unspecified
All
defect

Tracking

(Not tracked)

RESOLVED FIXED

People

(Reporter: aklotz, Assigned: aklotz)

References

Details

(Keywords: intermittent-failure, Whiteboard: [geckoview:m78][geckoview:m79][geckoview:m80][Comment 14][stockwell disable-recommended])

+++ This bug was initially created as a clone of Bug #1607878 +++

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


[task 2020-01-08T18:55:53.345Z] 18:55:53 INFO - TEST-START | org.mozilla.geckoview.test.ExtensionActionTest.setBadgeBackgroundColor[#pageAction]
[task 2020-01-08T18:56:23.392Z] 18:56:23 INFO - org.mozilla.geckoview.test | INSTRUMENTATION_STATUS: numtests=622
[task 2020-01-08T18:56:23.392Z] 18:56:23 INFO - org.mozilla.geckoview.test | INSTRUMENTATION_STATUS: stream=
[task 2020-01-08T18:56:23.392Z] 18:56:23 INFO - org.mozilla.geckoview.test | Error in setBadgeBackgroundColor#pageAction:
[task 2020-01-08T18:56:23.393Z] 18:56:23 INFO - org.mozilla.geckoview.test | org.mozilla.geckoview.test.rule.TestHarnessException: org.mozilla.geckoview.test.util.UiThreadUtils$TimeoutException: Timed out after 30000ms
[task 2020-01-08T18:56:23.396Z] 18:56:23 INFO - org.mozilla.geckoview.test | at org.mozilla.geckoview.test.rule.GeckoSessionTestRule$2.initTest(GeckoSessionTestRule.java:1285)
[task 2020-01-08T18:56:23.396Z] 18:56:23 INFO - org.mozilla.geckoview.test | at org.mozilla.geckoview.test.rule.GeckoSessionTestRule$2.lambda$evaluate$0$GeckoSessionTestRule$2(GeckoSessionTestRule.java:1297)
[task 2020-01-08T18:56:23.396Z] 18:56:23 INFO - org.mozilla.geckoview.test | at org.mozilla.geckoview.test.rule.-$$Lambda$GeckoSessionTestRule$2$sIbRNaZJgAu-QrUVWSGD8JbPSWM.run(lambda)
[task 2020-01-08T18:56:23.396Z] 18:56:23 INFO - org.mozilla.geckoview.test | at android.app.Instrumentation$SyncRunnable.run(Instrumentation.java:1950)
[task 2020-01-08T18:56:23.396Z] 18:56:23 INFO - org.mozilla.geckoview.test | at android.os.Handler.handleCallback(Handler.java:751)
[task 2020-01-08T18:56:23.396Z] 18:56:23 INFO - org.mozilla.geckoview.test | at android.os.Handler.dispatchMessage(Handler.java:95)
[task 2020-01-08T18:56:23.396Z] 18:56:23 INFO - org.mozilla.geckoview.test | at android.os.Looper.loop(Looper.java:154)
[task 2020-01-08T18:56:23.396Z] 18:56:23 INFO - org.mozilla.geckoview.test | at android.app.ActivityThread.main(ActivityThread.java:6077)
[task 2020-01-08T18:56:23.396Z] 18:56:23 INFO - org.mozilla.geckoview.test | at java.lang.reflect.Method.invoke(Native Method)
[task 2020-01-08T18:56:23.396Z] 18:56:23 INFO - org.mozilla.geckoview.test | at com.android.internal.os.ZygoteInit$MethodAndArgsCaller.run(ZygoteInit.java:866)
[task 2020-01-08T18:56:23.396Z] 18:56:23 INFO - org.mozilla.geckoview.test | at com.android.internal.os.ZygoteInit.main(ZygoteInit.java:756)
[task 2020-01-08T18:56:23.396Z] 18:56:23 INFO - org.mozilla.geckoview.test | Caused by: org.mozilla.geckoview.test.util.UiThreadUtils$TimeoutException: Timed out after 30000ms
[task 2020-01-08T18:56:23.396Z] 18:56:23 INFO - org.mozilla.geckoview.test | at org.mozilla.geckoview.test.util.UiThreadUtils$TimeoutRunnable.run(UiThreadUtils.java:58)
[task 2020-01-08T18:56:23.396Z] 18:56:23 INFO - org.mozilla.geckoview.test | at android.os.Handler.handleCallback(Handler.java:751)
[task 2020-01-08T18:56:23.396Z] 18:56:23 INFO - org.mozilla.geckoview.test | at android.os.Handler.dispatchMessage(Handler.java:95)
[task 2020-01-08T18:56:23.396Z] 18:56:23 INFO - org.mozilla.geckoview.test | at org.mozilla.geckoview.test.util.UiThreadUtils.waitForCondition(UiThreadUtils.java:161)
[task 2020-01-08T18:56:23.396Z] 18:56:23 INFO - org.mozilla.geckoview.test | at org.mozilla.geckoview.test.rule.GeckoSessionTestRule.openSession(GeckoSessionTestRule.java:1142)
[task 2020-01-08T18:56:23.396Z] 18:56:23 INFO - org.mozilla.geckoview.test | at org.mozilla.geckoview.test.rule.GeckoSessionTestRule.prepareStatement(GeckoSessionTestRule.java:1092)
[task 2020-01-08T18:56:23.396Z] 18:56:23 INFO - org.mozilla.geckoview.test | at org.mozilla.geckoview.test.rule.GeckoSessionTestRule$2.initTest(GeckoSessionTestRule.java:1281)
[task 2020-01-08T18:56:23.396Z] 18:56:23 INFO - org.mozilla.geckoview.test | ... 10 more
[task 2020-01-08T18:56:23.396Z] 18:56:23 INFO - org.mozilla.geckoview.test |
[task 2020-01-08T18:56:23.396Z] 18:56:23 INFO - org.mozilla.geckoview.test | INSTRUMENTATION_STATUS: id=AndroidJUnitRunner
[task 2020-01-08T18:56:23.396Z] 18:56:23 INFO - org.mozilla.geckoview.test | INSTRUMENTATION_STATUS: test=setBadgeBackgroundColor[#pageAction]
[task 2020-01-08T18:56:23.396Z] 18:56:23 INFO - org.mozilla.geckoview.test | INSTRUMENTATION_STATUS: class=org.mozilla.geckoview.test.ExtensionActionTest
[task 2020-01-08T18:56:23.396Z] 18:56:23 INFO - org.mozilla.geckoview.test | INSTRUMENTATION_STATUS: stack=org.mozilla.geckoview.test.rule.TestHarnessException: org.mozilla.geckoview.test.util.UiThreadUtils$TimeoutException: Timed out after 30000ms
[task 2020-01-08T18:56:23.396Z] 18:56:23 INFO - SUITE-END | took 73s
[task 2020-01-08T18:56:23.396Z] 18:56:23 WARNING - TEST-UNEXPECTED-FAIL | runjunit.py | The previous test failed because of an error in the test harness | org.mozilla.geckoview.test.rule.TestHarnessException: org.mozilla.geckoview.test.util.UiThreadUtils$TimeoutException: Timed out after 30000ms
[task 2020-01-08T18:56:23.396Z] 18:56:23 INFO - Stopping web server
[task 2020-01-08T18:56:23.397Z] 18:56:23 INFO - Stopping web socket server
[task 2020-01-08T18:56:23.417Z] 18:56:23 INFO - Stopping ssltunnel
[task 2020-01-08T18:56:26.139Z] 18:56:26 ERROR - Return code: 255
[task 2020-01-08T18:56:26.139Z] 18:56:26 ERROR - No tests run or test summary not found
[task 2020-01-08T18:56:26.140Z] 18:56:26 INFO - TinderboxPrint: geckoview-junit<br/><em class="testfail">T-FAIL</em>
[task 2020-01-08T18:56:26.140Z] 18:56:26 INFO - ##### geckoview-junit log ends
[task 2020-01-08T18:56:26.140Z] 18:56:26 WARNING - # TBPL WARNING #
[task 2020-01-08T18:56:26.140Z] 18:56:26 WARNING - setting return code to 1
[task 2020-01-08T18:56:26.140Z] 18:56:26 WARNING - The geckoview-junit suite: geckoview-junit ran with return status: WARNING
[task 2020-01-08T18:56:26.140Z] 18:56:26 INFO - Running post-action listener: _package_coverage_data
[task 2020-01-08T18:56:26.140Z] 18:56:26 INFO - Running post-action listener: _resource_record_post_action
[task 2020-01-08T18:56:26.140Z] 18:56:26 INFO - Running post-action listener: process_java_coverage_data
[task 2020-01-08T18:56:26.140Z] 18:56:26 INFO - Running post-action listener: stop_device

I took a look at some logs yesterday. We clean up the session(s) from a previous test, and then, while starting up a new mainSession for the next test, occasionally the content process hangs during startup.

The last thing I saw in the logcat was GeckoThread: zerdatime 399702 - runGecko. At some point from there everything just hung.

Priority: P5 → P2
See Also: → 1607878

This bug failed 91 times in the last 7 days. Occurs on android-em-7-0-x86_64 on OPT build types.

Recent log:
https://treeherder.mozilla.org/logviewer.html#/jobs?job_id=302621207&repo=autoland&lineNumber=11270

Aaron: Any updates on this bug?

Flags: needinfo?(aklotz)

Let's see how this looks after bug 1625326 merges.

Depends on: 1625326
Flags: needinfo?(aklotz)
Whiteboard: [geckoview:m78][stockwell disable-recommended] → [geckoview:m78][geckoview:m79][stockwell disable-recommended]
Priority: P2 → P1

The failure rate has decreased, but there are still occurrences. For the last 7 days there are 24 total failures.

Whiteboard: [geckoview:m78][geckoview:m79][stockwell disable-recommended] → [geckoview:m78][geckoview:m79][stockwell needswork:owner]
Assignee: nobody → aklotz
Status: NEW → ASSIGNED

Aaron, this has reached the disable recommended queue, are there any updates?
Should we disable until there is a fix?

There are 30 total failures in the last 7 days on android-em-7-0-x86_64 opt

Recent failure log: https://treeherder.mozilla.org/logviewer.html#/jobs?job_id=305277187&repo=autoland&lineNumber=11436

[task 2020-06-05T23:04:32.130Z] 23:04:32 INFO - TEST-START | org.mozilla.geckoview.test.StorageControllerTest.clearDataFlags
[task 2020-06-05T23:05:02.086Z] 23:05:02 INFO - org.mozilla.geckoview.test | INSTRUMENTATION_STATUS: numtests=736
[task 2020-06-05T23:05:02.086Z] 23:05:02 INFO - org.mozilla.geckoview.test | INSTRUMENTATION_STATUS: stream=
[task 2020-06-05T23:05:02.086Z] 23:05:02 INFO - org.mozilla.geckoview.test | Error in clearDataFlags(org.mozilla.geckoview.test.StorageControllerTest):
[task 2020-06-05T23:05:02.086Z] 23:05:02 INFO - org.mozilla.geckoview.test | org.mozilla.geckoview.test.rule.TestHarnessException: org.mozilla.geckoview.test.util.UiThreadUtils$TimeoutException: Timed out after 30000ms
[task 2020-06-05T23:05:02.087Z] 23:05:02 INFO - org.mozilla.geckoview.test | at org.mozilla.geckoview.test.rule.GeckoSessionTestRule$2.initTest(GeckoSessionTestRule.java:1280)
[task 2020-06-05T23:05:02.087Z] 23:05:02 INFO - org.mozilla.geckoview.test | at org.mozilla.geckoview.test.rule.GeckoSessionTestRule$2.lambda$evaluate$0$GeckoSessionTestRule$2(GeckoSessionTestRule.java:1292)
[task 2020-06-05T23:05:02.087Z] 23:05:02 INFO - org.mozilla.geckoview.test | at org.mozilla.geckoview.test.rule.-$$Lambda$GeckoSessionTestRule$2$sIbRNaZJgAu-QrUVWSGD8JbPSWM.run(lambda)
[task 2020-06-05T23:05:02.087Z] 23:05:02 INFO - org.mozilla.geckoview.test | at android.app.Instrumentation$SyncRunnable.run(Instrumentation.java:1950)
[task 2020-06-05T23:05:02.087Z] 23:05:02 INFO - org.mozilla.geckoview.test | at android.os.Handler.handleCallback(Handler.java:751)
[task 2020-06-05T23:05:02.088Z] 23:05:02 INFO - org.mozilla.geckoview.test | at android.os.Handler.dispatchMessage(Handler.java:95)
[task 2020-06-05T23:05:02.088Z] 23:05:02 INFO - org.mozilla.geckoview.test | at android.os.Looper.loop(Looper.java:154)
[task 2020-06-05T23:05:02.088Z] 23:05:02 INFO - org.mozilla.geckoview.test | at android.app.ActivityThread.main(ActivityThread.java:6077)
[task 2020-06-05T23:05:02.088Z] 23:05:02 INFO - org.mozilla.geckoview.test | at java.lang.reflect.Method.invoke(Native Method)
[task 2020-06-05T23:05:02.088Z] 23:05:02 INFO - org.mozilla.geckoview.test | at com.android.internal.os.ZygoteInit$MethodAndArgsCaller.run(ZygoteInit.java:866)
[task 2020-06-05T23:05:02.088Z] 23:05:02 INFO - org.mozilla.geckoview.test | at com.android.internal.os.ZygoteInit.main(ZygoteInit.java:756)
[task 2020-06-05T23:05:02.089Z] 23:05:02 INFO - org.mozilla.geckoview.test | Caused by: org.mozilla.geckoview.test.util.UiThreadUtils$TimeoutException: Timed out after 30000ms
[task 2020-06-05T23:05:02.089Z] 23:05:02 INFO - org.mozilla.geckoview.test | at org.mozilla.geckoview.test.util.UiThreadUtils$TimeoutRunnable.run(UiThreadUtils.java:52)
[task 2020-06-05T23:05:02.089Z] 23:05:02 INFO - org.mozilla.geckoview.test | at android.os.Handler.handleCallback(Handler.java:751)
[task 2020-06-05T23:05:02.089Z] 23:05:02 INFO - org.mozilla.geckoview.test | at android.os.Handler.dispatchMessage(Handler.java:95)
[task 2020-06-05T23:05:02.090Z] 23:05:02 INFO - org.mozilla.geckoview.test | at org.mozilla.geckoview.test.util.UiThreadUtils.waitForCondition(UiThreadUtils.java:155)
[task 2020-06-05T23:05:02.090Z] 23:05:02 INFO - org.mozilla.geckoview.test | at org.mozilla.geckoview.test.rule.GeckoSessionTestRule.openSession(GeckoSessionTestRule.java:1145)
[task 2020-06-05T23:05:02.090Z] 23:05:02 INFO - org.mozilla.geckoview.test | at org.mozilla.geckoview.test.rule.GeckoSessionTestRule.prepareStatement(GeckoSessionTestRule.java:1090)
[task 2020-06-05T23:05:02.090Z] 23:05:02 INFO - org.mozilla.geckoview.test | at org.mozilla.geckoview.test.rule.GeckoSessionTestRule$2.initTest(GeckoSessionTestRule.java:1276)
[task 2020-06-05T23:05:02.090Z] 23:05:02 INFO - org.mozilla.geckoview.test | ... 10 more
[task 2020-06-05T23:05:02.090Z] 23:05:02 INFO - org.mozilla.geckoview.test |
[task 2020-06-05T23:05:02.090Z] 23:05:02 INFO - org.mozilla.geckoview.test | INSTRUMENTATION_STATUS: id=AndroidJUnitRunner
[task 2020-06-05T23:05:02.091Z] 23:05:02 INFO - org.mozilla.geckoview.test | INSTRUMENTATION_STATUS: test=clearDataFlags
[task 2020-06-05T23:05:02.091Z] 23:05:02 INFO - org.mozilla.geckoview.test | INSTRUMENTATION_STATUS: class=org.mozilla.geckoview.test.StorageControllerTest
[task 2020-06-05T23:05:02.091Z] 23:05:02 INFO - org.mozilla.geckoview.test | INSTRUMENTATION_STATUS: stack=org.mozilla.geckoview.test.rule.TestHarnessException: org.mozilla.geckoview.test.util.UiThreadUtils$TimeoutException: Timed out after 30000ms
[task 2020-06-05T23:05:02.091Z] 23:05:02 INFO - SUITE-END | took 630s
[task 2020-06-05T23:05:02.091Z] 23:05:02 WARNING - TEST-UNEXPECTED-FAIL | runjunit.py | The previous test failed because of an error in the test harness | org.mozilla.geckoview.test.rule.TestHarnessException: org.mozilla.geckoview.test.util.UiThreadUtils$TimeoutException: Timed out after 30000ms
[task 2020-06-05T23:05:02.092Z] 23:05:02 INFO - Stopping web server
[task 2020-06-05T23:05:02.104Z] 23:05:02 INFO - Stopping web socket server
[task 2020-06-05T23:05:02.125Z] 23:05:02 INFO - Stopping ssltunnel
[task 2020-06-05T23:05:03.113Z] 23:05:03 ERROR - Return code: 255
[task 2020-06-05T23:05:03.113Z] 23:05:03 ERROR - No tests run or test summary not found
[task 2020-06-05T23:05:03.113Z] 23:05:03 INFO - TinderboxPrint: geckoview-junit<br/><em class="testfail">T-FAIL</em>
[task 2020-06-05T23:05:03.113Z] 23:05:03 INFO - ##### geckoview-junit log ends
[task 2020-06-05T23:05:03.114Z] 23:05:03 WARNING - # TBPL WARNING #
[task 2020-06-05T23:05:03.114Z] 23:05:03 WARNING - setting return code to 1

Whiteboard: [geckoview:m78][geckoview:m79][stockwell disable-recommended] → [geckoview:m78][geckoview:m79][stockwell needswork:owner]
Depends on: 1647470
Priority: P1 → P2

In the last 7 days there 62 total failures on android-em-7-0-x86_64-shippable and android-em-7-0-x86_64 platforms, opt build type.

Recent failure log: https://treeherder.mozilla.org/logviewer.html#/jobs?job_id=307738036&repo=mozilla-central&lineNumber=11423

Whiteboard: [geckoview:m78][geckoview:m79][Comment 14][stockwell disable-recommended] → [geckoview:m78][geckoview:m79][Comment 14][stockwell needswork:owner]

No failures since bug 1647470 landed. Resolving.

Status: ASSIGNED → RESOLVED
Closed: 11 months ago
Resolution: --- → FIXED
Whiteboard: [geckoview:m78][geckoview:m79][Comment 14][stockwell disable-recommended] → [geckoview:m78][geckoview:m79][geckoview:m80][Comment 14][stockwell disable-recommended]
You need to log in before you can comment on or make changes to this bug.