Closed Bug 1596314 Opened 6 years ago Closed 2 years ago

Intermittent org.mozilla.geckoview.test.WebExecutorTest#readTimeout | java.lang.AssertionError: Expected exception: java.io.IOException | status -2

Categories

(GeckoView :: General, defect, P5)

Unspecified
All
defect

Tracking

(Not tracked)

RESOLVED FIXED

People

(Reporter: intermittent-bug-filer, Assigned: apavel)

References

Details

(Keywords: intermittent-failure, Whiteboard: [retriggered])

Attachments

(1 file)

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


[task 2019-11-13T23:47:35.967Z] 23:47:35 INFO - TEST-START | org.mozilla.geckoview.test.WebExecutorTest.readTimeout
[task 2019-11-13T23:47:36.065Z] 23:47:36 INFO - org.mozilla.geckoview.test | INSTRUMENTATION_STATUS: numtests=576
[task 2019-11-13T23:47:36.065Z] 23:47:36 INFO - org.mozilla.geckoview.test | INSTRUMENTATION_STATUS: stream=
[task 2019-11-13T23:47:36.065Z] 23:47:36 INFO - org.mozilla.geckoview.test | Error in readTimeout(org.mozilla.geckoview.test.WebExecutorTest):
[task 2019-11-13T23:47:36.069Z] 23:47:36 INFO - org.mozilla.geckoview.test | java.lang.AssertionError: Expected exception: java.io.IOException
[task 2019-11-13T23:47:36.069Z] 23:47:36 INFO - org.mozilla.geckoview.test | at org.junit.internal.runners.statements.ExpectException.evaluate(ExpectException.java:32)
[task 2019-11-13T23:47:36.069Z] 23:47:36 INFO - org.mozilla.geckoview.test | at android.support.test.internal.runner.junit4.statement.RunBefores.evaluate(RunBefores.java:80)
[task 2019-11-13T23:47:36.069Z] 23:47:36 INFO - org.mozilla.geckoview.test | at android.support.test.internal.runner.junit4.statement.RunAfters.evaluate(RunAfters.java:61)
[task 2019-11-13T23:47:36.069Z] 23:47:36 INFO - org.mozilla.geckoview.test | at org.junit.rules.ExpectedException$ExpectedExceptionStatement.evaluate(ExpectedException.java:239)
[task 2019-11-13T23:47:36.069Z] 23:47:36 INFO - org.mozilla.geckoview.test | at org.junit.rules.RunRules.evaluate(RunRules.java:20)
[task 2019-11-13T23:47:36.069Z] 23:47:36 INFO - org.mozilla.geckoview.test | at org.junit.runners.ParentRunner.runLeaf(ParentRunner.java:325)
[task 2019-11-13T23:47:36.069Z] 23:47:36 INFO - org.mozilla.geckoview.test | at org.junit.runners.BlockJUnit4ClassRunner.runChild(BlockJUnit4ClassRunner.java:78)
[task 2019-11-13T23:47:36.069Z] 23:47:36 INFO - org.mozilla.geckoview.test | at org.junit.runners.BlockJUnit4ClassRunner.runChild(BlockJUnit4ClassRunner.java:57)
[task 2019-11-13T23:47:36.069Z] 23:47:36 INFO - org.mozilla.geckoview.test | at org.junit.runners.ParentRunner$3.run(ParentRunner.java:290)
[task 2019-11-13T23:47:36.069Z] 23:47:36 INFO - org.mozilla.geckoview.test | at org.junit.runners.ParentRunner$1.schedule(ParentRunner.java:71)
[task 2019-11-13T23:47:36.072Z] 23:47:36 INFO - org.mozilla.geckoview.test | at org.junit.runners.ParentRunner.runChildren(ParentRunner.java:288)
[task 2019-11-13T23:47:36.072Z] 23:47:36 INFO - org.mozilla.geckoview.test | at org.junit.runners.ParentRunner.access$000(ParentRunner.java:58)
[task 2019-11-13T23:47:36.072Z] 23:47:36 INFO - org.mozilla.geckoview.test | at org.junit.runners.ParentRunner$2.evaluate(ParentRunner.java:268)
[task 2019-11-13T23:47:36.072Z] 23:47:36 INFO - org.mozilla.geckoview.test | at org.junit.runners.ParentRunner.run(ParentRunner.java:363)
[task 2019-11-13T23:47:36.072Z] 23:47:36 INFO - org.mozilla.geckoview.test | at android.support.test.runner.AndroidJUnit4.run(AndroidJUnit4.java:101)
[task 2019-11-13T23:47:36.072Z] 23:47:36 INFO - org.mozilla.geckoview.test | at org.junit.runners.Suite.runChild(Suite.java:128)
[task 2019-11-13T23:47:36.072Z] 23:47:36 INFO - org.mozilla.geckoview.test | at org.junit.runners.Suite.runChild(Suite.java:27)
[task 2019-11-13T23:47:36.072Z] 23:47:36 INFO - org.mozilla.geckoview.test | at org.junit.runners.ParentRunner$3.run(ParentRunner.java:290)
[task 2019-11-13T23:47:36.072Z] 23:47:36 INFO - org.mozilla.geckoview.test | at org.junit.runners.ParentRunner$1.schedule(ParentRunner.java:71)
[task 2019-11-13T23:47:36.072Z] 23:47:36 INFO - org.mozilla.geckoview.test | at org.junit.runners.ParentRunner.runChildren(ParentRunner.java:288)
[task 2019-11-13T23:47:36.072Z] 23:47:36 INFO - org.mozilla.geckoview.test | at org.junit.runners.ParentRunner.access$000(ParentRunner.java:58)
[task 2019-11-13T23:47:36.072Z] 23:47:36 INFO - org.mozilla.geckoview.test | at org.junit.runners.ParentRunner$2.evaluate(ParentRunner.java:268)
[task 2019-11-13T23:47:36.072Z] 23:47:36 INFO - org.mozilla.geckoview.test | at org.junit.runners.ParentRunner.run(ParentRunner.java:363)
[task 2019-11-13T23:47:36.072Z] 23:47:36 INFO - org.mozilla.geckoview.test | at org.junit.runner.JUnitCore.run(JUnitCore.java:137)
[task 2019-11-13T23:47:36.072Z] 23:47:36 INFO - org.mozilla.geckoview.test | at org.junit.runner.JUnitCore.run(JUnitCore.java:115)
[task 2019-11-13T23:47:36.072Z] 23:47:36 INFO - org.mozilla.geckoview.test | at android.support.test.internal.runner.TestExecutor.execute(TestExecutor.java:56)
[task 2019-11-13T23:47:36.072Z] 23:47:36 INFO - org.mozilla.geckoview.test | at android.support.test.runner.AndroidJUnitRunner.onStart(AndroidJUnitRunner.java:384)
[task 2019-11-13T23:47:36.073Z] 23:47:36 INFO - org.mozilla.geckoview.test | at android.app.Instrumentation$InstrumentationThread.run(Instrumentation.java:1932)
[task 2019-11-13T23:47:36.073Z] 23:47:36 INFO - org.mozilla.geckoview.test |
[task 2019-11-13T23:47:36.073Z] 23:47:36 INFO - org.mozilla.geckoview.test | INSTRUMENTATION_STATUS: id=AndroidJUnitRunner
[task 2019-11-13T23:47:36.073Z] 23:47:36 INFO - org.mozilla.geckoview.test | INSTRUMENTATION_STATUS: test=readTimeout
[task 2019-11-13T23:47:36.073Z] 23:47:36 INFO - org.mozilla.geckoview.test | INSTRUMENTATION_STATUS: class=org.mozilla.geckoview.test.WebExecutorTest
[task 2019-11-13T23:47:36.073Z] 23:47:36 INFO - org.mozilla.geckoview.test | INSTRUMENTATION_STATUS: stack=java.lang.AssertionError: Expected exception: java.io.IOException
[task 2019-11-13T23:47:36.073Z] 23:47:36 INFO - org.mozilla.geckoview.test | at org.junit.internal.runners.statements.ExpectException.evaluate(ExpectException.java:32)
[task 2019-11-13T23:47:36.073Z] 23:47:36 INFO - org.mozilla.geckoview.test | at android.support.test.internal.runner.junit4.statement.RunBefores.evaluate(RunBefores.java:80)
[task 2019-11-13T23:47:36.073Z] 23:47:36 INFO - org.mozilla.geckoview.test | at android.support.test.internal.runner.junit4.statement.RunAfters.evaluate(RunAfters.java:61)
[task 2019-11-13T23:47:36.073Z] 23:47:36 INFO - org.mozilla.geckoview.test | at org.junit.rules.ExpectedException$ExpectedExceptionStatement.evaluate(ExpectedException.java:239)
[task 2019-11-13T23:47:36.073Z] 23:47:36 INFO - org.mozilla.geckoview.test | at org.junit.rules.RunRules.evaluate(RunRules.java:20)
[task 2019-11-13T23:47:36.073Z] 23:47:36 INFO - org.mozilla.geckoview.test | at org.junit.runners.ParentRunner.runLeaf(ParentRunner.java:325)
[task 2019-11-13T23:47:36.073Z] 23:47:36 INFO - org.mozilla.geckoview.test | at org.junit.runners.BlockJUnit4ClassRunner.runChild(BlockJUnit4ClassRunner.java:78)
[task 2019-11-13T23:47:36.073Z] 23:47:36 INFO - org.mozilla.geckoview.test | at org.junit.runners.BlockJUnit4ClassRunner.runChild(BlockJUnit4ClassRunner.java:57)
[task 2019-11-13T23:47:36.073Z] 23:47:36 INFO - org.mozilla.geckoview.test | at org.junit.runners.ParentRunner$3.run(ParentRunner.java:290)
[task 2019-11-13T23:47:36.073Z] 23:47:36 INFO - org.mozilla.geckoview.test | at org.junit.runners.ParentRunner$1.schedule(ParentRunner.java:71)
[task 2019-11-13T23:47:36.073Z] 23:47:36 INFO - org.mozilla.geckoview.test | at org.junit.runners.ParentRunner.runChildren(ParentRunner.java:288)
[task 2019-11-13T23:47:36.073Z] 23:47:36 INFO - org.mozilla.geckoview.test | at org.junit.runners.ParentRunner.access$000(ParentRunner.java:58)
[task 2019-11-13T23:47:36.073Z] 23:47:36 INFO - org.mozilla.geckoview.test | at org.junit.runners.ParentRunner$2.evaluate(ParentRunner.java:268)
[task 2019-11-13T23:47:36.073Z] 23:47:36 INFO - org.mozilla.geckoview.test | at org.junit.runners.ParentRunner.run(ParentRunner.java:363)
[task 2019-11-13T23:47:36.073Z] 23:47:36 INFO - org.mozilla.geckoview.test | at android.support.test.runner.AndroidJUnit4.run(AndroidJUnit4.java:101)
[task 2019-11-13T23:47:36.073Z] 23:47:36 INFO - org.mozilla.geckoview.test | at org.junit.runners.Suite.runChild(Suite.java:128)
[task 2019-11-13T23:47:36.073Z] 23:47:36 INFO - org.mozilla.geckoview.test | at org.junit.runners.Suite.runChild(Suite.java:27)
[task 2019-11-13T23:47:36.073Z] 23:47:36 INFO - org.mozilla.geckoview.test | at org.junit.runners.ParentRunner$3.run(ParentRunner.java:290)
[task 2019-11-13T23:47:36.073Z] 23:47:36 INFO - org.mozilla.geckoview.test | at org.junit.runners.ParentRunner$1.schedule(ParentRunner.java:71)
[task 2019-11-13T23:47:36.073Z] 23:47:36 INFO - org.mozilla.geckoview.test | at org.junit.runners.ParentRunner.runChildren(ParentRunner.java:288)
[task 2019-11-13T23:47:36.073Z] 23:47:36 INFO - org.mozilla.geckoview.test | at org.junit.runners.ParentRunner.access$000(ParentRunner.java:58)
[task 2019-11-13T23:47:36.073Z] 23:47:36 INFO - org.mozilla.geckoview.test | at org.junit.runners.ParentRunner$2.evaluate(ParentRunner.java:268)
[task 2019-11-13T23:47:36.073Z] 23:47:36 INFO - org.mozilla.geckoview.test | at org.junit.runners.ParentRunner.run(ParentRunner.java:363)
[task 2019-11-13T23:47:36.073Z] 23:47:36 INFO - org.mozilla.geckoview.test | at org.junit.runner.JUnitCore.run(JUnitCore.java:137)
[task 2019-11-13T23:47:36.073Z] 23:47:36 INFO - org.mozilla.geckoview.test | at org.junit.runner.JUnitCore.run(JUnitCore.java:115)
[task 2019-11-13T23:47:36.073Z] 23:47:36 INFO - org.mozilla.geckoview.test | at android.support.test.internal.runner.TestExecutor.execute(TestExecutor.java:56)
[task 2019-11-13T23:47:36.073Z] 23:47:36 INFO - org.mozilla.geckoview.test | at android.support.test.runner.AndroidJUnitRunner.onStart(AndroidJUnitRunner.java:384)
[task 2019-11-13T23:47:36.073Z] 23:47:36 INFO - org.mozilla.geckoview.test | at android.app.Instrumentation$InstrumentationThread.run(Instrumentation.java:1932)
[task 2019-11-13T23:47:36.073Z] 23:47:36 INFO - org.mozilla.geckoview.test |
[task 2019-11-13T23:47:36.073Z] 23:47:36 INFO - org.mozilla.geckoview.test | INSTRUMENTATION_STATUS: current=501
[task 2019-11-13T23:47:36.073Z] 23:47:36 INFO - org.mozilla.geckoview.test | INSTRUMENTATION_STATUS_CODE: -2
[task 2019-11-13T23:47:36.073Z] 23:47:36 WARNING - TEST-UNEXPECTED-FAIL | org.mozilla.geckoview.test.WebExecutorTest.readTimeout | status -2
[task 2019-11-13T23:47:36.073Z] 23:47:36 INFO - TEST-INFO took 105ms

Could bug 1595995 be the culprit?

I don't see how. It's a no-op for builds that didn't fail before.

Flags: needinfo?(mh+mozilla)

In the last 7 days, there have been 37 failures on android-em-7-0-x86_64 platform, debug and opt build type.

An example of a recent log file:
https://treeherder.mozilla.org/logviewer.html#/jobs?job_id=277898204&repo=autoland&lineNumber=10512

And the relevant part of the log:
[task 2019-11-24T14:08:13.711Z] 14:08:13 INFO - TEST-START | org.mozilla.geckoview.test.WebExecutorTest.readTimeout

task 2019-11-24T14:08:13.818Z] 14:08:13 INFO - org.mozilla.geckoview.test |
[task 2019-11-24T14:08:13.818Z] 14:08:13 INFO - org.mozilla.geckoview.test | INSTRUMENTATION_STATUS: current=507
[task 2019-11-24T14:08:13.818Z] 14:08:13 INFO - org.mozilla.geckoview.test | INSTRUMENTATION_STATUS_CODE: -2
[task 2019-11-24T14:08:13.818Z] 14:08:13 WARNING - TEST-UNEXPECTED-FAIL | org.mozilla.geckoview.test.WebExecutorTest.readTimeout | status -2
[task 2019-11-24T14:08:13.818Z] 14:08:13 INFO - TEST-INFO took 103ms
[task 2019-11-24T14:08:13.818Z] 14:08:13 INFO - org.mozilla.geckoview.test | INSTRUMENTATION_STATUS: numtests=582
[task 2019-11-24T14:08:13.818Z] 14:08:13 INFO - org.mozilla.geckoview.test | INSTRUMENTATION_STATUS: stream=
[task 2019-11-24T14:08:13.819Z] 14:08:13 INFO - org.mozilla.geckoview.test | INSTRUMENTATION_STATUS: id=AndroidJUnitRunner
[task 2019-11-24T14:08:13.819Z] 14:08:13 INFO - org.mozilla.geckoview.test | INSTRUMENTATION_STATUS: test=testFetchUnknownHost
[task 2019-11-24T14:08:13.819Z] 14:08:13 INFO - org.mozilla.geckoview.test | INSTRUMENTATION_STATUS: class=org.mozilla.geckoview.test.WebExecutorTest
[task 2019-11-24T14:08:13.819Z] 14:08:13 INFO - org.mozilla.geckoview.test | INSTRUMENTATION_STATUS: current=508
[task 2019-11-24T14:08:13.819Z] 14:08:13 INFO - org.mozilla.geckoview.test | INSTRUMENTATION_STATUS_CODE: 1

Emily, as you are the triage owner of this component, could you please take a look at this?
Thank you!

Flags: needinfo?(etoop)
Whiteboard: [stockwell needswork:owner]
Flags: needinfo?(ckerschb)
Whiteboard: [stockwell needswork:owner] → [stockwell needswork:owner][retriggered]

Joel should we disable here or wait some more for a reply?

Flags: needinfo?(etoop) → needinfo?(jmaher)

as the root cause landed 2 weeks ago, it isn't reasonable to backout. I see in the original bug the author has a needinfo pending as well. Given the high frequency, I would vote for disabling.

Flags: needinfo?(jmaher)
Assignee: nobody → apavel

I am going to ping :ckerschb@christophkerschbaumer.com and ask him to look at it. This was a GeckoView test broken by non-GeckoView work so I have been hoping the original author would deal with it.

I've just spoken to Christoph and he expects the intermittent to be resolved by bug 1593832 which is predicted to land today. Please can you hold off on the test disabling until we know if this fix resolves the failure.

Flags: needinfo?(ckerschb) → needinfo?(apavel)

(In reply to Emily Toop (:fluffyemily) from comment #14)

I've just spoken to Christoph and he expects the intermittent to be resolved by bug 1593832 which is predicted to land today. Please can you hold off on the test disabling until we know if this fix resolves the failure.

Yes, will do. Thanks for helping out!

Flags: needinfo?(apavel)
Whiteboard: [stockwell needswork:owner][retriggered] → [stockwell needswork:owner][retriggered][comment 14]

(In reply to Andreea Pavel [:apavel] from comment #7)

Hi Christoph, I retriggered this failure and showed up when bug 1595762 landed. Can you take a look?

Retrigger range: https://treeherder.mozilla.org/#/jobs?repo=autoland&searchStr=android%2C7.0%2Cx86-64%2Copt%2Ctest-android-em-7.0-x86_64%2Fopt-geckoview-junit-e10s%2C%28gv-junit%29&tochange=60db8c551c38d0619df981ac11e5616b8d8e3002&fromchange=291ef4ef1773d3a6cf138975185cdef75010e76b&selectedJob=277922693

Hopefully Christoph's fix will work, but if it doesn't, note that while the first failures showed up on bug 1595762, this test was added by the immediately previous push, bug 1595145: the test may have always been intermittent.

:snorp Can you take a look at this please, as bug 1595145 is one of yours.

Flags: needinfo?(snorp)

There are 59 total failures in the last 7 days and this seems to be spiking starting with the 30th of November.
James did you get the chance to take a look?

Not related to WebExtension

Component: Extensions → General
Keywords: leave-open
Whiteboard: [stockwell needswork:owner][retriggered][comment 14] → [stockwell disabled][retriggered]
Pushed by apavel@mozilla.com: https://hg.mozilla.org/integration/autoland/rev/fa7cc0b71f1f disable WebExecutorTest.readTimeout for frequent failures r=gbrown,geckoview-reviewers,snorp

I'll re-enable this with some other changes in a new bug.

Flags: needinfo?(snorp)
Keywords: leave-open
Whiteboard: [stockwell disabled][retriggered] → [retriggered]
Summary: Intermittent org.mozilla.geckoview.test.WebExecutorTest.readTimeout | status -2 → Intermittent org.mozilla.geckoview.test.WebExecutorTest.readTimeout | java.lang.AssertionError: Expected exception: java.io.IOException
Summary: Intermittent org.mozilla.geckoview.test.WebExecutorTest.readTimeout | java.lang.AssertionError: Expected exception: java.io.IOException → Intermittent org.mozilla.geckoview.test.WebExecutorTest.readTimeout | java.lang.AssertionError: Expected exception: java.io.IOException | status -2
Assignee: apavel → nobody

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

Summary: Intermittent org.mozilla.geckoview.test.WebExecutorTest.readTimeout | java.lang.AssertionError: Expected exception: java.io.IOException | status -2 → Intermittent org.mozilla.geckoview.test.WebExecutorTest#readTimeout | java.lang.AssertionError: Expected exception: java.io.IOException | status -2
Severity: normal → S3
Status: NEW → RESOLVED
Closed: 2 years ago
Resolution: --- → FIXED
Assignee: nobody → apavel
You need to log in before you can comment on or make changes to this bug.

Attachment

General

Created:
Updated:
Size: