1615203 - Intermittent org.mozilla.geckoview.test.crash.ParentCrashTest#crashParent | java.lang.RuntimeException: java.util.concurrent.ExecutionException: org.mozilla.geckoview.test.util.UiThreadUtils$TimeoutException: Timed out after 60000ms

Status: RESOLVED WORKSFORME

(GeckoView :: General, defect, P2)

Description

[Treeherder Bug Filer]

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

---

[task 2020-02-13T07:33:15.106Z] 07:33:15 INFO - TEST-START | org.mozilla.geckoview.test.crash.ParentCrashTest.crashParent
[task 2020-02-13T07:34:15.038Z] 07:34:15 INFO - org.mozilla.geckoview.test | INSTRUMENTATION_STATUS: numtests=641
[task 2020-02-13T07:34:15.040Z] 07:34:15 INFO - org.mozilla.geckoview.test | INSTRUMENTATION_STATUS: stream=
[task 2020-02-13T07:34:15.040Z] 07:34:15 INFO - org.mozilla.geckoview.test | Error in crashParent(org.mozilla.geckoview.test.crash.ParentCrashTest):
[task 2020-02-13T07:34:15.040Z] 07:34:15 INFO - org.mozilla.geckoview.test | java.lang.RuntimeException: java.util.concurrent.ExecutionException: org.mozilla.geckoview.test.util.UiThreadUtils$TimeoutException: Timed out after 60000ms
[task 2020-02-13T07:34:15.040Z] 07:34:15 INFO - org.mozilla.geckoview.test | at org.mozilla.geckoview.test.util.RuntimeCreator.shutdownRuntime(RuntimeCreator.java:235)
[task 2020-02-13T07:34:15.040Z] 07:34:15 INFO - org.mozilla.geckoview.test | at org.mozilla.geckoview.test.crash.ParentCrashTest.setup(ParentCrashTest.kt:43)
[task 2020-02-13T07:34:15.040Z] 07:34:15 INFO - org.mozilla.geckoview.test | at java.lang.reflect.Method.invoke(Native Method)
[task 2020-02-13T07:34:15.040Z] 07:34:15 INFO - org.mozilla.geckoview.test | at org.junit.runners.model.FrameworkMethod$1.runReflectiveCall(FrameworkMethod.java:50)
[task 2020-02-13T07:34:15.040Z] 07:34:15 INFO - org.mozilla.geckoview.test | at org.junit.internal.runners.model.ReflectiveCallable.run(ReflectiveCallable.java:12)
[task 2020-02-13T07:34:15.040Z] 07:34:15 INFO - org.mozilla.geckoview.test | at org.junit.runners.model.FrameworkMethod.invokeExplosively(FrameworkMethod.java:47)
[task 2020-02-13T07:34:15.040Z] 07:34:15 INFO - org.mozilla.geckoview.test | at androidx.test.internal.runner.junit4.statement.RunBefores.evaluate(RunBefores.java:76)
[task 2020-02-13T07:34:15.040Z] 07:34:15 INFO - org.mozilla.geckoview.test | at androidx.test.rule.ServiceTestRule$ServiceStatement.evaluate(ServiceTestRule.java:335)
[task 2020-02-13T07:34:15.040Z] 07:34:15 INFO - org.mozilla.geckoview.test | at org.junit.rules.RunRules.evaluate(RunRules.java:20)
[task 2020-02-13T07:34:15.040Z] 07:34:15 INFO - org.mozilla.geckoview.test | at org.junit.runners.ParentRunner.runLeaf(ParentRunner.java:325)
[task 2020-02-13T07:34:15.040Z] 07:34:15 INFO - org.mozilla.geckoview.test | at org.junit.runners.BlockJUnit4ClassRunner.runChild(BlockJUnit4ClassRunner.java:78)
[task 2020-02-13T07:34:15.048Z] 07:34:15 INFO - org.mozilla.geckoview.test | at org.junit.runners.BlockJUnit4ClassRunner.runChild(BlockJUnit4ClassRunner.java:57)
[task 2020-02-13T07:34:15.048Z] 07:34:15 INFO - org.mozilla.geckoview.test | at org.junit.runners.ParentRunner$3.run(ParentRunner.java:290)
[task 2020-02-13T07:34:15.048Z] 07:34:15 INFO - org.mozilla.geckoview.test | at org.junit.runners.ParentRunner$1.schedule(ParentRunner.java:71)
[task 2020-02-13T07:34:15.048Z] 07:34:15 INFO - org.mozilla.geckoview.test | at org.junit.runners.ParentRunner.runChildren(ParentRunner.java:288)
[task 2020-02-13T07:34:15.048Z] 07:34:15 INFO - org.mozilla.geckoview.test | at org.junit.runners.ParentRunner.access$000(ParentRunner.java:58)
[task 2020-02-13T07:34:15.048Z] 07:34:15 INFO - org.mozilla.geckoview.test | at org.junit.runners.ParentRunner$2.evaluate(ParentRunner.java:268)
[task 2020-02-13T07:34:15.048Z] 07:34:15 INFO - org.mozilla.geckoview.test | at org.junit.runners.ParentRunner.run(ParentRunner.java:363)
[task 2020-02-13T07:34:15.048Z] 07:34:15 INFO - org.mozilla.geckoview.test | at androidx.test.ext.junit.runners.AndroidJUnit4.run(AndroidJUnit4.java:104)
[task 2020-02-13T07:34:15.048Z] 07:34:15 INFO - org.mozilla.geckoview.test | at org.junit.runners.Suite.runChild(Suite.java:128)
[task 2020-02-13T07:34:15.048Z] 07:34:15 INFO - org.mozilla.geckoview.test | at org.junit.runners.Suite.runChild(Suite.java:27)
[task 2020-02-13T07:34:15.048Z] 07:34:15 INFO - org.mozilla.geckoview.test | at org.junit.runners.ParentRunner$3.run(ParentRunner.java:290)
[task 2020-02-13T07:34:15.048Z] 07:34:15 INFO - org.mozilla.geckoview.test | at org.junit.runners.ParentRunner$1.schedule(ParentRunner.java:71)
[task 2020-02-13T07:34:15.048Z] 07:34:15 INFO - org.mozilla.geckoview.test | at org.junit.runners.ParentRunner.runChildren(ParentRunner.java:288)
[task 2020-02-13T07:34:15.048Z] 07:34:15 INFO - org.mozilla.geckoview.test | at org.junit.runners.ParentRunner.access$000(ParentRunner.java:58)
[task 2020-02-13T07:34:15.048Z] 07:34:15 INFO - org.mozilla.geckoview.test | at org.junit.runners.ParentRunner$2.evaluate(ParentRunner.java:268)
[task 2020-02-13T07:34:15.048Z] 07:34:15 INFO - org.mozilla.geckoview.test | at org.junit.runners.ParentRunner.run(ParentRunner.java:363)
[task 2020-02-13T07:34:15.048Z] 07:34:15 INFO - org.mozilla.geckoview.test | at org.junit.runner.JUnitCore.run(JUnitCore.java:137)
[task 2020-02-13T07:34:15.048Z] 07:34:15 INFO - org.mozilla.geckoview.test | at org.junit.runner.JUnitCore.run(JUnitCore.java:115)
[task 2020-02-13T07:34:15.048Z] 07:34:15 INFO - org.mozilla.geckoview.test | at androidx.test.internal.runner.TestExecutor.execute(TestExecutor.java:56)
[task 2020-02-13T07:34:15.049Z] 07:34:15 INFO - org.mozilla.geckoview.test | at androidx.test.runner.AndroidJUnitRunner.onStart(AndroidJUnitRunner.java:388)
[task 2020-02-13T07:34:15.049Z] 07:34:15 INFO - org.mozilla.geckoview.test | at android.app.Instrumentation$InstrumentationThread.run(Instrumentation.java:1932)
[task 2020-02-13T07:34:15.049Z] 07:34:15 INFO - org.mozilla.geckoview.test |
[task 2020-02-13T07:34:15.049Z] 07:34:15 INFO - org.mozilla.geckoview.test | INSTRUMENTATION_STATUS: id=AndroidJUnitRunner
[task 2020-02-13T07:34:15.049Z] 07:34:15 INFO - org.mozilla.geckoview.test | INSTRUMENTATION_STATUS: test=crashParent
[task 2020-02-13T07:34:15.049Z] 07:34:15 INFO - org.mozilla.geckoview.test | INSTRUMENTATION_STATUS: class=org.mozilla.geckoview.test.crash.ParentCrashTest
[task 2020-02-13T07:34:15.049Z] 07:34:15 INFO - org.mozilla.geckoview.test | INSTRUMENTATION_STATUS: stack=java.lang.RuntimeException: java.util.concurrent.ExecutionException: org.mozilla.geckoview.test.util.UiThreadUtils$TimeoutException: Timed out after 60000ms
[task 2020-02-13T07:34:15.049Z] 07:34:15 INFO - org.mozilla.geckoview.test | at org.mozilla.geckoview.test.util.RuntimeCreator.shutdownRuntime(RuntimeCreator.java:235)
[task 2020-02-13T07:34:15.049Z] 07:34:15 INFO - org.mozilla.geckoview.test | at org.mozilla.geckoview.test.crash.ParentCrashTest.setup(ParentCrashTest.kt:43)
[task 2020-02-13T07:34:15.049Z] 07:34:15 INFO - org.mozilla.geckoview.test | at java.lang.reflect.Method.invoke(Native Method)
[task 2020-02-13T07:34:15.049Z] 07:34:15 INFO - org.mozilla.geckoview.test | at org.junit.runners.model.FrameworkMethod$1.runReflectiveCall(FrameworkMethod.java:50)
[task 2020-02-13T07:34:15.049Z] 07:34:15 INFO - org.mozilla.geckoview.test | at org.junit.internal.runners.model.ReflectiveCallable.run(ReflectiveCallable.java:12)
[task 2020-02-13T07:34:15.049Z] 07:34:15 INFO - org.mozilla.geckoview.test | at org.junit.runners.model.FrameworkMethod.invokeExplosively(FrameworkMethod.java:47)
[task 2020-02-13T07:34:15.049Z] 07:34:15 INFO - org.mozilla.geckoview.test | at androidx.test.internal.runner.junit4.statement.RunBefores.evaluate(RunBefores.java:76)
[task 2020-02-13T07:34:15.049Z] 07:34:15 INFO - org.mozilla.geckoview.test | at androidx.test.rule.ServiceTestRule$ServiceStatement.evaluate(ServiceTestRule.java:335)
[task 2020-02-13T07:34:15.049Z] 07:34:15 INFO - org.mozilla.geckoview.test | at org.junit.rules.RunRules.evaluate(RunRules.java:20)
[task 2020-02-13T07:34:15.049Z] 07:34:15 INFO - org.mozilla.geckoview.test | at org.junit.runners.ParentRunner.runLeaf(ParentRunner.java:325)
[task 2020-02-13T07:34:15.049Z] 07:34:15 INFO - org.mozilla.geckoview.test | at org.junit.runners.BlockJUnit4ClassRunner.runChild(BlockJUnit4ClassRunner.java:78)
[task 2020-02-13T07:34:15.049Z] 07:34:15 INFO - org.mozilla.geckoview.test | at org.junit.runners.BlockJUnit4ClassRunner.runChild(BlockJUnit4ClassRunner.java:57)
[task 2020-02-13T07:34:15.049Z] 07:34:15 INFO - org.mozilla.geckoview.test | at org.junit.runners.ParentRunner$3.run(ParentRunner.java:290)
[task 2020-02-13T07:34:15.049Z] 07:34:15 INFO - org.mozilla.geckoview.test | at org.junit.runners.ParentRunner$1.schedule(ParentRunner.java:71)
[task 2020-02-13T07:34:15.049Z] 07:34:15 INFO - org.mozilla.geckoview.test | at org.junit.runners.ParentRunner.runChildren(ParentRunner.java:288)
[task 2020-02-13T07:34:15.049Z] 07:34:15 INFO - org.mozilla.geckoview.test | at org.junit.runners.ParentRunner.access$000(ParentRunner.java:58)
[task 2020-02-13T07:34:15.049Z] 07:34:15 INFO - org.mozilla.geckoview.test | at org.junit.runners.ParentRunner$2.evaluate(ParentRunner.java:268)
[task 2020-02-13T07:34:15.049Z] 07:34:15 INFO - org.mozilla.geckoview.test | at org.junit.runners.ParentRunner.run(ParentRunner.java:363)
[task 2020-02-13T07:34:15.049Z] 07:34:15 INFO - org.mozilla.geckoview.test | at androidx.test.ext.junit.runners.AndroidJUnit4.run(AndroidJUnit4.java:104)
[task 2020-02-13T07:34:15.049Z] 07:34:15 INFO - org.mozilla.geckoview.test | at org.junit.runners.Suite.runChild(Suite.java:128)
[task 2020-02-13T07:34:15.049Z] 07:34:15 INFO - org.mozilla.geckoview.test | at org.junit.runners.Suite.runChild(Suite.java:27)
[task 2020-02-13T07:34:15.049Z] 07:34:15 INFO - org.mozilla.geckoview.test | at org.junit.runners.ParentRunner$3.run(ParentRunner.java:290)
[task 2020-02-13T07:34:15.049Z] 07:34:15 INFO - org.mozilla.geckoview.test | at org.junit.runners.ParentRunner$1.schedule(ParentRunner.java:71)
[task 2020-02-13T07:34:15.049Z] 07:34:15 INFO - org.mozilla.geckoview.test | at org.junit.runners.ParentRunner.runChildren(ParentRunner.java:288)
[task 2020-02-13T07:34:15.049Z] 07:34:15 INFO - org.mozilla.geckoview.test | at org.junit.runners.ParentRunner.access$000(ParentRunner.java:58)
[task 2020-02-13T07:34:15.049Z] 07:34:15 INFO - org.mozilla.geckoview.test | at org.junit.runners.ParentRunner$2.evaluate(ParentRunner.java:268)
[task 2020-02-13T07:34:15.049Z] 07:34:15 INFO - org.mozilla.geckoview.test | at org.junit.runners.ParentRunner.run(ParentRunner.java:363)
[task 2020-02-13T07:34:15.049Z] 07:34:15 INFO - org.mozilla.geckoview.test | at org.junit.runner.JUnitCore.run(JUnitCore.java:137)
[task 2020-02-13T07:34:15.049Z] 07:34:15 INFO - org.mozilla.geckoview.test | at org.junit.runner.JUnitCore.run(JUnitCore.java:115)
[task 2020-02-13T07:34:15.049Z] 07:34:15 INFO - org.mozilla.geckoview.test | at androidx.test.internal.runner.TestExecutor.execute(TestExecutor.java:56)
[task 2020-02-13T07:34:15.050Z] 07:34:15 INFO - org.mozilla.geckoview.test | at androidx.test.runner.AndroidJUnitRunner.onStart(AndroidJUnitRunner.java:388)
[task 2020-02-13T07:34:15.050Z] 07:34:15 INFO - org.mozilla.geckoview.test | at android.app.Instrumentation$InstrumentationThread.run(Instrumentation.java:1932)
[task 2020-02-13T07:34:15.051Z] 07:34:15 INFO - org.mozilla.geckoview.test |
[task 2020-02-13T07:34:15.051Z] 07:34:15 INFO - org.mozilla.geckoview.test | INSTRUMENTATION_STATUS: current=641
[task 2020-02-13T07:34:15.051Z] 07:34:15 INFO - org.mozilla.geckoview.test | INSTRUMENTATION_STATUS_CODE: -2
[task 2020-02-13T07:34:15.051Z] 07:34:15 WARNING - TEST-UNEXPECTED-FAIL | org.mozilla.geckoview.test.crash.ParentCrashTest.crashParent | java.lang.RuntimeException: java.util.concurrent.ExecutionException: org.mozilla.geckoview.test.util.UiThreadUtils$TimeoutException: Timed out after 60000ms

Comment 1

[Intermittent Failures Robot]

1 failures in 4690 pushes (0.0 failures/push) were associated with this bug in the last 7 days.

Repository breakdown:

• autoland: 1

Platform breakdown:

• android-em-7-0-x86_64: 1

For more details, see:
https://treeherder.mozilla.org/intermittent-failures.html#/bugdetails?bug=1615203&startday=2020-02-10&endday=2020-02-16&tree=all

Comment 2

[Intermittent Failures Robot]

1 failures in 4045 pushes (0.0 failures/push) were associated with this bug in the last 7 days.

Repository breakdown:

• try: 1

Platform breakdown:

• android-em-7-0-x86_64: 1

For more details, see:
https://treeherder.mozilla.org/intermittent-failures.html#/bugdetails?bug=1615203&startday=2020-02-17&endday=2020-02-23&tree=all

Comment 3

[Intermittent Failures Robot]

2 failures in 5265 pushes (0.0 failures/push) were associated with this bug in the last 7 days.

Repository breakdown:

• autoland: 2

Platform breakdown:

• android-em-7-0-x86_64: 2

For more details, see:
https://treeherder.mozilla.org/intermittent-failures.html#/bugdetails?bug=1615203&startday=2020-07-06&endday=2020-07-12&tree=all

Comment 4

[Intermittent Failures Robot]

1 failures in 4257 pushes (0.0 failures/push) were associated with this bug in the last 7 days.

Repository breakdown:

• autoland: 1

Platform and build breakdown:

• android-em-7-0-x86_64-qr: 1
  • debug: 1

For more details, see:
https://treeherder.mozilla.org/intermittent-failures/bugdetails?bug=1615203&startday=2021-03-15&endday=2021-03-21&tree=all

Comment 5

[Nicolas B. Pierron [:nbp]]

Would it be possible to address this issue, as this is blocking work to get performance optimizations to Android.

The blocked work (Bug 1710884) already provided, on desktop, a 9% speed-up of content process startup as well as a resident memory usage reduction between 5% to 8%. (see Bug 1709135)

Comment 6

[[ex-Mozilla] Agi Sferro | :agi]

6c6f5da9-bf33-4082-a19d-7d99e8083d97 Mass rename intermittents due to Bug 1723034.

Comment 7

[Intermittent Failures Robot]

16 failures in 518 pushes (0.031 failures/push) were associated with this bug yesterday.

Repository breakdown:

• autoland: 16

Platform and build breakdown:

• android-em-7-0-x86_64-qr: 11
  • debug-isolated-process: 6
  • debug: 5
• android-em-7-0-x86_64-lite-qr: 5
  • debug: 5

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

Comment 8

[[ex-Mozilla] Agi Sferro | :agi]

Nicolas, could you explain how this intermittent is related to Bug 1710884? Also I don't think anybody watches [e-mail], please ni me or Emily Toop for GeckoView/Android bugs in the future :)

Comment 9

[Intermittent Failures Robot]

20 failures in 679 pushes (0.029 failures/push) were associated with this bug yesterday.

Repository breakdown:

• autoland: 10
• mozilla-central: 10

Platform and build breakdown:

• android-em-7-0-x86_64-qr: 15
  • debug: 9
  • debug-isolated-process: 6
• android-em-7-0-x86_64-lite-qr: 5
  • debug: 5

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

Comment 10

[Emily Toop (:fluffyemily)]

This has had lots of failures recently. Resetting priority for re-triage.

Comment 11

[Natalia Csoregi [:nataliaCs]]

Update:

There have been 36 failures within the last 7 days:

• 10 failures on android-em-7-0-x86_64-lite-qr debug
• 26 failures on Android 7.0 x86-64 WebRender debug/ debug-isolated-process

Recent failure log: https://treeherder.mozilla.org/logviewer?job_id=349347586&repo=mozilla-central&lineNumber=15636

[task 2021-08-24T04:13:30.756Z] 04:13:30     INFO -  TEST-START | org.mozilla.geckoview.test.crash.ParentCrashTest#crashParent
[task 2021-08-24T04:14:30.757Z] 04:14:30     INFO -  org.mozilla.geckoview.test | INSTRUMENTATION_STATUS: numtests=795
[task 2021-08-24T04:14:30.758Z] 04:14:30     INFO -  org.mozilla.geckoview.test | INSTRUMENTATION_STATUS: stream=
[task 2021-08-24T04:14:30.758Z] 04:14:30     INFO -  org.mozilla.geckoview.test | Error in crashParent(org.mozilla.geckoview.test.crash.ParentCrashTest):
[task 2021-08-24T04:14:30.758Z] 04:14:30     INFO -  org.mozilla.geckoview.test | java.lang.RuntimeException: java.util.concurrent.ExecutionException: org.mozilla.geckoview.test.util.UiThreadUtils$TimeoutException: Timed out after 60000ms
[task 2021-08-24T04:14:30.758Z] 04:14:30     INFO -  org.mozilla.geckoview.test | 	at org.mozilla.geckoview.test.util.RuntimeCreator.shutdownRuntime(RuntimeCreator.java:251)
[task 2021-08-24T04:14:30.759Z] 04:14:30     INFO -  org.mozilla.geckoview.test | 	at org.mozilla.geckoview.test.crash.ParentCrashTest.setup(ParentCrashTest.kt:41)
[task 2021-08-24T04:14:30.759Z] 04:14:30     INFO -  org.mozilla.geckoview.test | 	at java.lang.reflect.Method.invoke(Native Method)
[task 2021-08-24T04:14:30.759Z] 04:14:30     INFO -  org.mozilla.geckoview.test | 	at org.junit.runners.model.FrameworkMethod$1.runReflectiveCall(FrameworkMethod.java:50)
[task 2021-08-24T04:14:30.759Z] 04:14:30     INFO -  org.mozilla.geckoview.test | 	at org.junit.internal.runners.model.ReflectiveCallable.run(ReflectiveCallable.java:12)
[task 2021-08-24T04:14:30.760Z] 04:14:30     INFO -  org.mozilla.geckoview.test | 	at org.junit.runners.model.FrameworkMethod.invokeExplosively(FrameworkMethod.java:47)
[task 2021-08-24T04:14:30.760Z] 04:14:30     INFO -  org.mozilla.geckoview.test | 	at androidx.test.internal.runner.junit4.statement.RunBefores.evaluate(RunBefores.java:76)
[task 2021-08-24T04:14:30.760Z] 04:14:30     INFO -  org.mozilla.geckoview.test | 	at androidx.test.rule.ServiceTestRule$ServiceStatement.evaluate(ServiceTestRule.java:335)
[task 2021-08-24T04:14:30.761Z] 04:14:30     INFO -  org.mozilla.geckoview.test | 	at org.junit.rules.ExternalResource$1.evaluate(ExternalResource.java:48)
[task 2021-08-24T04:14:30.761Z] 04:14:30     INFO -  org.mozilla.geckoview.test | 	at org.junit.rules.RunRules.evaluate(RunRules.java:20)
[task 2021-08-24T04:14:30.761Z] 04:14:30     INFO -  org.mozilla.geckoview.test | 	at org.junit.runners.ParentRunner.runLeaf(ParentRunner.java:325)
[task 2021-08-24T04:14:30.761Z] 04:14:30     INFO -  org.mozilla.geckoview.test | 	at org.junit.runners.BlockJUnit4ClassRunner.runChild(BlockJUnit4ClassRunner.java:78)
[task 2021-08-24T04:14:30.761Z] 04:14:30     INFO -  org.mozilla.geckoview.test | 	at org.junit.runners.BlockJUnit4ClassRunner.runChild(BlockJUnit4ClassRunner.java:57)
[task 2021-08-24T04:14:30.762Z] 04:14:30     INFO -  org.mozilla.geckoview.test | 	at org.junit.runners.ParentRunner$3.run(ParentRunner.java:290)
[task 2021-08-24T04:14:30.762Z] 04:14:30     INFO -  org.mozilla.geckoview.test | 	at org.junit.runners.ParentRunner$1.schedule(ParentRunner.java:71)
[task 2021-08-24T04:14:30.762Z] 04:14:30     INFO -  org.mozilla.geckoview.test | 	at org.junit.runners.ParentRunner.runChildren(ParentRunner.java:288)
[task 2021-08-24T04:14:30.762Z] 04:14:30     INFO -  org.mozilla.geckoview.test | 	at org.junit.runners.ParentRunner.access$000(ParentRunner.java:58)
[task 2021-08-24T04:14:30.762Z] 04:14:30     INFO -  org.mozilla.geckoview.test | 	at org.junit.runners.ParentRunner$2.evaluate(ParentRunner.java:268)
[task 2021-08-24T04:14:30.763Z] 04:14:30     INFO -  org.mozilla.geckoview.test | 	at org.junit.runners.ParentRunner.run(ParentRunner.java:363)
[task 2021-08-24T04:14:30.763Z] 04:14:30     INFO -  org.mozilla.geckoview.test | 	at androidx.test.ext.junit.runners.AndroidJUnit4.run(AndroidJUnit4.java:104)
[task 2021-08-24T04:14:30.763Z] 04:14:30     INFO -  org.mozilla.geckoview.test | 	at org.junit.runners.Suite.runChild(Suite.java:128)
[task 2021-08-24T04:14:30.763Z] 04:14:30     INFO -  org.mozilla.geckoview.test | 	at org.junit.runners.Suite.runChild(Suite.java:27)
[task 2021-08-24T04:14:30.763Z] 04:14:30     INFO -  org.mozilla.geckoview.test | 	at org.junit.runners.ParentRunner$3.run(ParentRunner.java:290)
[task 2021-08-24T04:14:30.764Z] 04:14:30     INFO -  org.mozilla.geckoview.test | 	at org.junit.runners.ParentRunner$1.schedule(ParentRunner.java:71)
[task 2021-08-24T04:14:30.764Z] 04:14:30     INFO -  org.mozilla.geckoview.test | 	at org.junit.runners.ParentRunner.runChildren(ParentRunner.java:288)
[task 2021-08-24T04:14:30.764Z] 04:14:30     INFO -  org.mozilla.geckoview.test | 	at org.junit.runners.ParentRunner.access$000(ParentRunner.java:58)
[task 2021-08-24T04:14:30.764Z] 04:14:30     INFO -  org.mozilla.geckoview.test | 	at org.junit.runners.ParentRunner$2.evaluate(ParentRunner.java:268)
[task 2021-08-24T04:14:30.764Z] 04:14:30     INFO -  org.mozilla.geckoview.test | 	at org.junit.runners.ParentRunner.run(ParentRunner.java:363)
[task 2021-08-24T04:14:30.765Z] 04:14:30     INFO -  org.mozilla.geckoview.test | 	at org.junit.runner.JUnitCore.run(JUnitCore.java:137)
[task 2021-08-24T04:14:30.765Z] 04:14:30     INFO -  org.mozilla.geckoview.test | 	at org.junit.runner.JUnitCore.run(JUnitCore.java:115)
[task 2021-08-24T04:14:30.765Z] 04:14:30     INFO -  org.mozilla.geckoview.test | 	at androidx.test.internal.runner.TestExecutor.execute(TestExecutor.java:56)
[task 2021-08-24T04:14:30.765Z] 04:14:30     INFO -  org.mozilla.geckoview.test | 	at androidx.test.runner.AndroidJUnitRunner.onStart(AndroidJUnitRunner.java:388)
[task 2021-08-24T04:14:30.765Z] 04:14:30     INFO -  org.mozilla.geckoview.test | 	at android.app.Instrumentation$InstrumentationThread.run(Instrumentation.java:1932)
[task 2021-08-24T04:14:30.766Z] 04:14:30     INFO -  org.mozilla.geckoview.test |
[task 2021-08-24T04:14:30.766Z] 04:14:30     INFO -  org.mozilla.geckoview.test | INSTRUMENTATION_STATUS: id=AndroidJUnitRunner
[task 2021-08-24T04:14:30.766Z] 04:14:30     INFO -  org.mozilla.geckoview.test | INSTRUMENTATION_STATUS: test=crashParent
[task 2021-08-24T04:14:30.766Z] 04:14:30     INFO -  org.mozilla.geckoview.test | INSTRUMENTATION_STATUS: class=org.mozilla.geckoview.test.crash.ParentCrashTest
[task 2021-08-24T04:14:30.766Z] 04:14:30     INFO -  org.mozilla.geckoview.test | INSTRUMENTATION_STATUS: stack=java.lang.RuntimeException: java.util.concurrent.ExecutionException: org.mozilla.geckoview.test.util.UiThreadUtils$TimeoutException: Timed out after 60000ms
[task 2021-08-24T04:14:30.766Z] 04:14:30     INFO -  org.mozilla.geckoview.test | 	at org.mozilla.geckoview.test.util.RuntimeCreator.shutdownRuntime(RuntimeCreator.java:251)
[task 2021-08-24T04:14:30.767Z] 04:14:30     INFO -  org.mozilla.geckoview.test | 	at org.mozilla.geckoview.test.crash.ParentCrashTest.setup(ParentCrashTest.kt:41)
[task 2021-08-24T04:14:30.767Z] 04:14:30     INFO -  org.mozilla.geckoview.test | 	at java.lang.reflect.Method.invoke(Native Method)
[task 2021-08-24T04:14:30.767Z] 04:14:30     INFO -  org.mozilla.geckoview.test | 	at org.junit.runners.model.FrameworkMethod$1.runReflectiveCall(FrameworkMethod.java:50)
[task 2021-08-24T04:14:30.767Z] 04:14:30     INFO -  org.mozilla.geckoview.test | 	at org.junit.internal.runners.model.ReflectiveCallable.run(ReflectiveCallable.java:12)
[task 2021-08-24T04:14:30.767Z] 04:14:30     INFO -  org.mozilla.geckoview.test | 	at org.junit.runners.model.FrameworkMethod.invokeExplosively(FrameworkMethod.java:47)
[task 2021-08-24T04:14:30.767Z] 04:14:30     INFO -  org.mozilla.geckoview.test | 	at androidx.test.internal.runner.junit4.statement.RunBefores.evaluate(RunBefores.java:76)
[task 2021-08-24T04:14:30.768Z] 04:14:30     INFO -  org.mozilla.geckoview.test | 	at androidx.test.rule.ServiceTestRule$ServiceStatement.evaluate(ServiceTestRule.java:335)
[task 2021-08-24T04:14:30.768Z] 04:14:30     INFO -  org.mozilla.geckoview.test | 	at org.junit.rules.ExternalResource$1.evaluate(ExternalResource.java:48)
[task 2021-08-24T04:14:30.768Z] 04:14:30     INFO -  org.mozilla.geckoview.test | 	at org.junit.rules.RunRules.evaluate(RunRules.java:20)
[task 2021-08-24T04:14:30.768Z] 04:14:30     INFO -  org.mozilla.geckoview.test | 	at org.junit.runners.ParentRunner.runLeaf(ParentRunner.java:325)
[task 2021-08-24T04:14:30.768Z] 04:14:30     INFO -  org.mozilla.geckoview.test | 	at org.junit.runners.BlockJUnit4ClassRunner.runChild(BlockJUnit4ClassRunner.java:78)
[task 2021-08-24T04:14:30.768Z] 04:14:30     INFO -  org.mozilla.geckoview.test | 	at org.junit.runners.BlockJUnit4ClassRunner.runChild(BlockJUnit4ClassRunner.java:57)
[task 2021-08-24T04:14:30.769Z] 04:14:30     INFO -  org.mozilla.geckoview.test | 	at org.junit.runners.ParentRunner$3.run(ParentRunner.java:290)
[task 2021-08-24T04:14:30.769Z] 04:14:30     INFO -  org.mozilla.geckoview.test | 	at org.junit.runners.ParentRunner$1.schedule(ParentRunner.java:71)
[task 2021-08-24T04:14:30.769Z] 04:14:30     INFO -  org.mozilla.geckoview.test | 	at org.junit.runners.ParentRunner.runChildren(ParentRunner.java:288)
[task 2021-08-24T04:14:30.769Z] 04:14:30     INFO -  org.mozilla.geckoview.test | 	at org.junit.runners.ParentRunner.access$000(ParentRunner.java:58)
[task 2021-08-24T04:14:30.769Z] 04:14:30     INFO -  org.mozilla.geckoview.test | 	at org.junit.runners.ParentRunner$2.evaluate(ParentRunner.java:268)
[task 2021-08-24T04:14:30.769Z] 04:14:30     INFO -  org.mozilla.geckoview.test | 	at org.junit.runners.ParentRunner.run(ParentRunner.java:363)
[task 2021-08-24T04:14:30.769Z] 04:14:30     INFO -  org.mozilla.geckoview.test | 	at androidx.test.ext.junit.runners.AndroidJUnit4.run(AndroidJUnit4.java:104)
[task 2021-08-24T04:14:30.770Z] 04:14:30     INFO -  org.mozilla.geckoview.test | 	at org.junit.runners.Suite.runChild(Suite.java:128)
[task 2021-08-24T04:14:30.770Z] 04:14:30     INFO -  org.mozilla.geckoview.test | 	at org.junit.runners.Suite.runChild(Suite.java:27)
[task 2021-08-24T04:14:30.770Z] 04:14:30     INFO -  org.mozilla.geckoview.test | 	at org.junit.runners.ParentRunner$3.run(ParentRunner.java:290)
[task 2021-08-24T04:14:30.770Z] 04:14:30     INFO -  org.mozilla.geckoview.test | 	at org.junit.runners.ParentRunner$1.schedule(ParentRunner.java:71)
[task 2021-08-24T04:14:30.770Z] 04:14:30     INFO -  org.mozilla.geckoview.test | 	at org.junit.runners.ParentRunner.runChildren(ParentRunner.java:288)
[task 2021-08-24T04:14:30.770Z] 04:14:30     INFO -  org.mozilla.geckoview.test | 	at org.junit.runners.ParentRunner.access$000(ParentRunner.java:58)
[task 2021-08-24T04:14:30.770Z] 04:14:30     INFO -  org.mozilla.geckoview.test | 	at org.junit.runners.ParentRunner$2.evaluate(ParentRunner.java:268)
[task 2021-08-24T04:14:30.771Z] 04:14:30     INFO -  org.mozilla.geckoview.test | 	at org.junit.runners.ParentRunner.run(ParentRunner.java:363)
[task 2021-08-24T04:14:30.771Z] 04:14:30     INFO -  org.mozilla.geckoview.test | 	at org.junit.runner.JUnitCore.run(JUnitCore.java:137)
[task 2021-08-24T04:14:30.771Z] 04:14:30     INFO -  org.mozilla.geckoview.test | 	at org.junit.runner.JUnitCore.run(JUnitCore.java:115)
[task 2021-08-24T04:14:30.771Z] 04:14:30     INFO -  org.mozilla.geckoview.test | 	at androidx.test.internal.runner.TestExecutor.execute(TestExecutor.java:56)
[task 2021-08-24T04:14:30.771Z] 04:14:30     INFO -  org.mozilla.geckoview.test | 	at androidx.test.runner.AndroidJUnitRunner.onStart(AndroidJUnitRunner.java:388)
[task 2021-08-24T04:14:30.771Z] 04:14:30     INFO -  org.mozilla.geckoview.test | 	at android.app.Instrumentation$InstrumentationThread.run(Instrumentation.java:1932)
[task 2021-08-24T04:14:30.771Z] 04:14:30     INFO -  org.mozilla.geckoview.test |
[task 2021-08-24T04:14:30.772Z] 04:14:30     INFO -  org.mozilla.geckoview.test | INSTRUMENTATION_STATUS: current=795
[task 2021-08-24T04:14:30.772Z] 04:14:30     INFO -  org.mozilla.geckoview.test | INSTRUMENTATION_STATUS_CODE: -2
[task 2021-08-24T04:14:30.772Z] 04:14:30     INFO -  Printing logcat for test:
[task 2021-08-24T04:14:30.829Z] 04:14:30     INFO -  None
[task 2021-08-24T04:14:30.830Z] 04:14:30  WARNING -  TEST-UNEXPECTED-FAIL | org.mozilla.geckoview.test.crash.ParentCrashTest#crashParent | java.lang.RuntimeException: java.util.concurrent.ExecutionException: org.mozilla.geckoview.test.util.UiThreadUtils$TimeoutException: Timed out after 60000ms
[task 2021-08-24T04:14:30.830Z] 04:14:30     INFO -  TEST-INFO took 60075ms

Comment 12

[Intermittent Failures Robot]

36 failures in 2580 pushes (0.014 failures/push) were associated with this bug in the last 7 days.

This is the #40 most frequent failure this week.

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

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

Repository breakdown:

• autoland: 26
• mozilla-central: 10

Platform and build breakdown:

• android-em-7-0-x86_64-qr: 26
  • debug-isolated-process: 12
  • debug: 14
• android-em-7-0-x86_64-lite-qr: 10
  • debug: 10

For more details, see:
https://treeherder.mozilla.org/intermittent-failures/bugdetails?bug=1615203&startday=2021-08-23&endday=2021-08-29&tree=all

Comment 13

[Nicolas B. Pierron [:nbp]]

(In reply to Agi Sferro | :agi | ni? for questions | ⏰ PST | he/him from comment #8)

Nicolas, could you explain how this intermittent is related to Bug 1710884? Also I don't think anybody watches [e-mail], please ni me or Emily Toop for GeckoView/Android bugs in the future :)

Bug 1710884 adds a new File Descriptor, for shared memory, which is passed from the parent process to each child processes.

When using the patch present in Bug 1710884, I was able to constantly reproduce these timeouts, which are similar to the the one reported here.
To be precise, I have no idea whether the timeout I experienced with attachment 9221638 [details] were the same or not. I only noticed that we were taking a lot of time, even before this patch, and that my patch probably made the time trip over the nearby timeout limit.

I honestly do not know whether the approach taken in attachment 9221638 [details] is the correct way to share memory across processes on Android, and I blindly followed what was done for other shared memory pages.

Comment 14

[[ex-Mozilla] Agi Sferro | :agi]

I see, do you see the same timeouts if you rebase to master? we aren't seeing this intermittent anymore from what I can tell.

If you do see them, can you link a try run?

Comment 15

[Nicolas B. Pierron [:nbp]]

(In reply to Agi Sferro | :agi | ni? for questions | ⏰ PST | he/him from comment #14)

I see, do you see the same timeouts if you rebase to master? we aren't seeing this intermittent anymore from what I can tell.

If you do see them, can you link a try run?

I send it to try once more, I did not noticed any more timeout being reported. On the other hand the test case org.mozilla.geckoview.test.crash.ParentCrashTest#crashParent does not seems to be executed anymore in most configuration where it used to timeout.

The test suites gv-junit and gv-junit-e10s-single are no longer running the test case, and gv-junit-fis reports failure to instrument:

[task 2021-09-06T17:41:24.930Z] 17:41:24     INFO -  TEST-START | org.mozilla.geckoview.test.crash.ParentCrashTest#crashParent
[task 2021-09-06T17:41:24.975Z] 17:41:24     INFO -  org.mozilla.geckoview.test | INSTRUMENTATION_STATUS: numtests=796
[task 2021-09-06T17:41:24.975Z] 17:41:24     INFO -  org.mozilla.geckoview.test | INSTRUMENTATION_STATUS: stream=
[task 2021-09-06T17:41:24.976Z] 17:41:24     INFO -  org.mozilla.geckoview.test | org.mozilla.geckoview.test.crash.ParentCrashTest:
[task 2021-09-06T17:41:24.976Z] 17:41:24     INFO -  org.mozilla.geckoview.test | INSTRUMENTATION_STATUS: id=AndroidJUnitRunner
[task 2021-09-06T17:41:24.976Z] 17:41:24     INFO -  org.mozilla.geckoview.test | INSTRUMENTATION_STATUS: test=crashParent
[task 2021-09-06T17:41:24.976Z] 17:41:24     INFO -  org.mozilla.geckoview.test | INSTRUMENTATION_STATUS: class=org.mozilla.geckoview.test.crash.ParentCrashTest
[task 2021-09-06T17:41:24.976Z] 17:41:24     INFO -  org.mozilla.geckoview.test | INSTRUMENTATION_STATUS: stack=org.junit.AssumptionViolatedException: got: <true>, expected: <false>
[task 2021-09-06T17:41:24.976Z] 17:41:24     INFO -  org.mozilla.geckoview.test | 	at org.junit.Assume.assumeThat(Assume.java:95)
[task 2021-09-06T17:41:24.977Z] 17:41:24     INFO -  org.mozilla.geckoview.test | 	at org.mozilla.geckoview.test.crash.ParentCrashTest.crashParent(ParentCrashTest.kt:54)
[task 2021-09-06T17:41:24.977Z] 17:41:24     INFO -  org.mozilla.geckoview.test | 	at java.lang.reflect.Method.invoke(Native Method)
[task 2021-09-06T17:41:24.977Z] 17:41:24     INFO -  org.mozilla.geckoview.test | 	at org.junit.runners.model.FrameworkMethod$1.runReflectiveCall(FrameworkMethod.java:50)
[task 2021-09-06T17:41:24.977Z] 17:41:24     INFO -  org.mozilla.geckoview.test | 	at org.junit.internal.runners.model.ReflectiveCallable.run(ReflectiveCallable.java:12)
[task 2021-09-06T17:41:24.977Z] 17:41:24     INFO -  org.mozilla.geckoview.test | 	at org.junit.runners.model.FrameworkMethod.invokeExplosively(FrameworkMethod.java:47)
[task 2021-09-06T17:41:24.978Z] 17:41:24     INFO -  org.mozilla.geckoview.test | 	at org.junit.internal.runners.statements.InvokeMethod.evaluate(InvokeMethod.java:17)
[task 2021-09-06T17:41:24.978Z] 17:41:24     INFO -  org.mozilla.geckoview.test | 	at androidx.test.internal.runner.junit4.statement.UiThreadStatement$1.run(UiThreadStatement.java:55)
[task 2021-09-06T17:41:24.978Z] 17:41:24     INFO -  org.mozilla.geckoview.test | 	at java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:428)
[task 2021-09-06T17:41:24.979Z] 17:41:24     INFO -  org.mozilla.geckoview.test | 	at java.util.concurrent.FutureTask.run(FutureTask.java:237)
[task 2021-09-06T17:41:24.979Z] 17:41:24     INFO -  org.mozilla.geckoview.test | 	at android.app.Instrumentation$SyncRunnable.run(Instrumentation.java:1950)
[task 2021-09-06T17:41:24.979Z] 17:41:24     INFO -  org.mozilla.geckoview.test | 	at android.os.Handler.handleCallback(Handler.java:751)
[task 2021-09-06T17:41:24.979Z] 17:41:24     INFO -  org.mozilla.geckoview.test | 	at android.os.Handler.dispatchMessage(Handler.java:95)
[task 2021-09-06T17:41:24.979Z] 17:41:24     INFO -  org.mozilla.geckoview.test | 	at android.os.Looper.loop(Looper.java:154)
[task 2021-09-06T17:41:24.979Z] 17:41:24     INFO -  org.mozilla.geckoview.test | 	at android.app.ActivityThread.main(ActivityThread.java:6077)
[task 2021-09-06T17:41:24.979Z] 17:41:24     INFO -  org.mozilla.geckoview.test | 	at java.lang.reflect.Method.invoke(Native Method)
[task 2021-09-06T17:41:24.979Z] 17:41:24     INFO -  org.mozilla.geckoview.test | 	at com.android.internal.os.ZygoteInit$MethodAndArgsCaller.run(ZygoteInit.java:866)
[task 2021-09-06T17:41:24.980Z] 17:41:24     INFO -  org.mozilla.geckoview.test | 	at com.android.internal.os.ZygoteInit.main(ZygoteInit.java:756)
[task 2021-09-06T17:41:24.980Z] 17:41:24     INFO -  org.mozilla.geckoview.test |
[task 2021-09-06T17:41:24.980Z] 17:41:24     INFO -  org.mozilla.geckoview.test | INSTRUMENTATION_STATUS: current=796
[task 2021-09-06T17:41:24.980Z] 17:41:24     INFO -  org.mozilla.geckoview.test | INSTRUMENTATION_STATUS_CODE: -4
[task 2021-09-06T17:41:24.980Z] 17:41:24     INFO -  TEST-FAIL | org.mozilla.geckoview.test.crash.ParentCrashTest#crashParent | took 47ms

Which are not reported as test suite failures.
https://treeherder.mozilla.org/jobs?repo=try&revision=40c5c5f617af8b9d4bb5ca2269cf42dffb907932

Comment 16

[Nicolas B. Pierron [:nbp]]

(In reply to Nicolas B. Pierron [:nbp] from comment #15)

(In reply to Agi Sferro | :agi | ni? for questions | ⏰ PST | he/him from comment #14)

I see, do you see the same timeouts if you rebase to master? we aren't seeing this intermittent anymore from what I can tell.

If you do see them, can you link a try run?

https://treeherder.mozilla.org/jobs?repo=try&revision=40c5c5f617af8b9d4bb5ca2269cf42dffb907932

Apparently this bug got reproduced on this try push with the gv-junit test suite on android-em-7-0-x86_64-lite-qr opt

Comment 17

[[ex-Mozilla] Agi Sferro | :agi]

(In reply to Nicolas B. Pierron [:nbp] from comment #15)

(In reply to Agi Sferro | :agi | ni? for questions | ⏰ PST | he/him from comment #14)

I see, do you see the same timeouts if you rebase to master? we aren't seeing this intermittent anymore from what I can tell.

If you do see them, can you link a try run?

I send it to try once more, I did not noticed any more timeout being reported. On the other hand the test case org.mozilla.geckoview.test.crash.ParentCrashTest#crashParent does not seems to be executed anymore in most configuration where it used to timeout.

Oh man! What you were seeing is Bug 1729561, which I found while looking at this. The stack=org.junit.AssumptionViolatedException: got: <true>, expected: <false> is expected, it's the way we "skip" tests on Android.

(In reply to Nicolas B. Pierron [:nbp] from comment #16)

(In reply to Agi Sferro | :agi | ni? for questions | ⏰ PST | he/him from comment #14)

I see, do you see the same timeouts if you rebase to master? we aren't seeing this intermittent anymore from what I can tell.

If you do see them, can you link a try run?

https://treeherder.mozilla.org/jobs?repo=try&revision=40c5c5f617af8b9d4bb5ca2269cf42dffb907932

Apparently this bug got reproduced on this try push with the gv-junit test suite on android-em-7-0-x86_64-lite-qr opt

OK good. I'll see if I can guess what's the problem there.

Comment 18

[lukas.bernhard]

Attachment: Logs from failing test on local device

I attached logging output when running the test on a local device. It seems the parent is crashing as expected, however there is still a timeout when retrieving the result.
If you have any idea how to debug further, please let me know.

Comment 19

[[ex-Mozilla] Agi Sferro | :agi]

mcomella brought up that this is blocking a perf fix (Bug 1618391) we should probably reprioritize.

Comment 20

[Chris Peterson [:cpeterson]]

Resolving as WFM because there have been no test failures in the last three months.

Comment 21

[Nicolas B. Pierron [:nbp]]

(In reply to Chris Peterson [:cpeterson] from comment #20)

Resolving as WFM because there have been no test failures in the last three months.

Just to make sure I understand better …
Can we land Bug 1710884 without being blocked by this issue?

Comment 22

[Chris Peterson [:cpeterson]]

(In reply to Nicolas B. Pierron [:nbp] from comment #21)

(In reply to Chris Peterson [:cpeterson] from comment #20)

Resolving as WFM because there have been no test failures in the last three months.

Just to make sure I understand better …
Can we land Bug 1710884 without being blocked by this issue?

I don't know the full details of this two-year-old bug, but if the current tests are passing with bug 1710884's IPC glue code, then you can try landing it.