1464351 - Intermittent org.mozilla.geckoview.test.GeckoSessionTestRuleTest#forCallbacksDuringWait_limitedToLastSessionWait | status -2

Status: RESOLVED FIXED

(GeckoView :: General, defect, P2)

Description

[Treeherder Bug Filer]

Filed by: ncsoregi [at] mozilla.com

https://treeherder.mozilla.org/logviewer.html#?job_id=180186230&repo=autoland

https://queue.taskcluster.net/v1/task/J3owZT5lTuCLq3vHhQqgfQ/runs/0/artifacts/public/logs/live_backing.log

[task 2018-05-25T07:08:14.212Z] 07:08:14     INFO -  TEST-START | org.mozilla.geckoview.test.GeckoSessionTestRuleTest.forCallbacksDuringWait_limitedToLastSessionWait
[task 2018-05-25T07:08:30.849Z] 07:08:30     INFO -  org.mozilla.geckoview.test | INSTRUMENTATION_STATUS: id=AndroidJUnitRunner
[task 2018-05-25T07:08:30.850Z] 07:08:30     INFO -  org.mozilla.geckoview.test | INSTRUMENTATION_STATUS: current=8
[task 2018-05-25T07:08:30.850Z] 07:08:30     INFO -  org.mozilla.geckoview.test | INSTRUMENTATION_STATUS: class=org.mozilla.geckoview.test.GeckoSessionTestRuleTest
[task 2018-05-25T07:08:30.850Z] 07:08:30     INFO -  org.mozilla.geckoview.test | INSTRUMENTATION_STATUS: stream=
[task 2018-05-25T07:08:30.850Z] 07:08:30     INFO -  org.mozilla.geckoview.test | Error in forCallbacksDuringWait_limitedToLastSessionWait(org.mozilla.geckoview.test.GeckoSessionTestRuleTest):
[task 2018-05-25T07:08:30.850Z] 07:08:30     INFO -  org.mozilla.geckoview.test | java.lang.AssertionError: onPageStop call count should be within limit
[task 2018-05-25T07:08:30.850Z] 07:08:30     INFO -  org.mozilla.geckoview.test | Expected: a value less than or equal to <0>
[task 2018-05-25T07:08:30.851Z] 07:08:30     INFO -  org.mozilla.geckoview.test |      but: <1> was greater than <0>
[task 2018-05-25T07:08:30.851Z] 07:08:30     INFO -  org.mozilla.geckoview.test | 	at org.hamcrest.MatcherAssert.assertThat(MatcherAssert.java:20)
[task 2018-05-25T07:08:30.851Z] 07:08:30     INFO -  org.mozilla.geckoview.test | 	at org.junit.Assert.assertThat(Assert.java:956)
[task 2018-05-25T07:08:30.852Z] 07:08:30     INFO -  org.mozilla.geckoview.test | 	at org.mozilla.geckoview.test.rule.GeckoSessionTestRule.checkThat(GeckoSessionTestRule.java:844)
[task 2018-05-25T07:08:30.852Z] 07:08:30     INFO -  org.mozilla.geckoview.test | 	at org.mozilla.geckoview.test.rule.GeckoSessionTestRule.assertAllowMoreCalls(GeckoSessionTestRule.java:851)
[task 2018-05-25T07:08:30.852Z] 07:08:30     INFO -  org.mozilla.geckoview.test | 	at org.mozilla.geckoview.test.rule.GeckoSessionTestRule.forCallbacksDuringWait(GeckoSessionTestRule.java:1651)
[task 2018-05-25T07:08:30.852Z] 07:08:30     INFO -  org.mozilla.geckoview.test | 	at org.mozilla.geckoview.test.BaseSessionTest.forCallbacksDuringWait(BaseSessionTest.kt:100)
[task 2018-05-25T07:08:30.852Z] 07:08:30     INFO -  org.mozilla.geckoview.test | 	at org.mozilla.geckoview.test.GeckoSessionTestRuleTest.forCallbacksDuringWait_limitedToLastSessionWait(GeckoSessionTestRuleTest.kt:1054)
[task 2018-05-25T07:08:30.852Z] 07:08:30     INFO -  org.mozilla.geckoview.test | 	at java.lang.reflect.Method.invokeNative(Native Method)
[task 2018-05-25T07:08:30.853Z] 07:08:30     INFO -  org.mozilla.geckoview.test | 	at java.lang.reflect.Method.invoke(Method.java:525)
[task 2018-05-25T07:08:30.853Z] 07:08:30     INFO -  org.mozilla.geckoview.test | 	at org.junit.runners.model.FrameworkMethod$1.runReflectiveCall(FrameworkMethod.java:50)
[task 2018-05-25T07:08:30.853Z] 07:08:30     INFO -  org.mozilla.geckoview.test | 	at org.junit.internal.runners.model.ReflectiveCallable.run(ReflectiveCallable.java:12)
[task 2018-05-25T07:08:30.853Z] 07:08:30     INFO -  org.mozilla.geckoview.test | 	at org.junit.runners.model.FrameworkMethod.invokeExplosively(FrameworkMethod.java:47)
[task 2018-05-25T07:08:30.853Z] 07:08:30     INFO -  org.mozilla.geckoview.test | 	at org.junit.internal.runners.statements.InvokeMethod.evaluate(InvokeMethod.java:17)
[task 2018-05-25T07:08:30.853Z] 07:08:30     INFO -  org.mozilla.geckoview.test | 	at org.mozilla.geckoview.test.rule.GeckoSessionTestRule$4.evaluate(GeckoSessionTestRule.java:1246)
[task 2018-05-25T07:08:30.854Z] 07:08:30     INFO -  org.mozilla.geckoview.test | 	at android.support.test.internal.statement.UiThreadStatement$1.run(UiThreadStatement.java:44)
[task 2018-05-25T07:08:30.854Z] 07:08:30     INFO -  org.mozilla.geckoview.test | 	at android.app.Instrumentation$SyncRunnable.run(Instrumentation.java:1719)
[task 2018-05-25T07:08:30.854Z] 07:08:30     INFO -  org.mozilla.geckoview.test | 	at android.os.Handler.handleCallback(Handler.java:730)
[task 2018-05-25T07:08:30.854Z] 07:08:30     INFO -  org.mozilla.geckoview.test | 	at android.os.Handler.dispatchMessage(Handler.java:92)
[task 2018-05-25T07:08:30.854Z] 07:08:30     INFO -  org.mozilla.geckoview.test | 	at android.os.Looper.loop(Looper.java:137)
[task 2018-05-25T07:08:30.854Z] 07:08:30     INFO -  org.mozilla.geckoview.test | 	at android.app.ActivityThread.main(ActivityThread.java:5103)
[task 2018-05-25T07:08:30.854Z] 07:08:30     INFO -  org.mozilla.geckoview.test | 	at java.lang.reflect.Method.invokeNative(Native Method)
[task 2018-05-25T07:08:30.855Z] 07:08:30     INFO -  org.mozilla.geckoview.test | 	at java.lang.reflect.Method.invoke(Method.java:525)
[task 2018-05-25T07:08:30.855Z] 07:08:30     INFO -  org.mozilla.geckoview.test | 	at com.android.internal.os.ZygoteInit$MethodAndArgsCaller.run(ZygoteInit.java:737)
[task 2018-05-25T07:08:30.855Z] 07:08:30     INFO -  org.mozilla.geckoview.test | 	at com.android.internal.os.ZygoteInit.main(ZygoteInit.java:553)
[task 2018-05-25T07:08:30.855Z] 07:08:30     INFO -  org.mozilla.geckoview.test | 	at dalvik.system.NativeStart.main(Native Method)
[task 2018-05-25T07:08:30.855Z] 07:08:30     INFO -  org.mozilla.geckoview.test |
[task 2018-05-25T07:08:30.855Z] 07:08:30     INFO -  org.mozilla.geckoview.test | INSTRUMENTATION_STATUS: numtests=60
[task 2018-05-25T07:08:30.855Z] 07:08:30     INFO -  org.mozilla.geckoview.test | INSTRUMENTATION_STATUS: stack=java.lang.AssertionError: onPageStop call count should be within limit
[task 2018-05-25T07:08:30.856Z] 07:08:30     INFO -  org.mozilla.geckoview.test | Expected: a value less than or equal to <0>
[task 2018-05-25T07:08:30.856Z] 07:08:30     INFO -  org.mozilla.geckoview.test |      but: <1> was greater than <0>
[task 2018-05-25T07:08:30.857Z] 07:08:30     INFO -  org.mozilla.geckoview.test | 	at org.hamcrest.MatcherAssert.assertThat(MatcherAssert.java:20)
[task 2018-05-25T07:08:30.857Z] 07:08:30     INFO -  org.mozilla.geckoview.test | 	at org.junit.Assert.assertThat(Assert.java:956)
[task 2018-05-25T07:08:30.858Z] 07:08:30     INFO -  org.mozilla.geckoview.test | 	at org.mozilla.geckoview.test.rule.GeckoSessionTestRule.checkThat(GeckoSessionTestRule.java:844)
[task 2018-05-25T07:08:30.858Z] 07:08:30     INFO -  org.mozilla.geckoview.test | 	at org.mozilla.geckoview.test.rule.GeckoSessionTestRule.assertAllowMoreCalls(GeckoSessionTestRule.java:851)
[task 2018-05-25T07:08:30.859Z] 07:08:30     INFO -  org.mozilla.geckoview.test | 	at org.mozilla.geckoview.test.rule.GeckoSessionTestRule.forCallbacksDuringWait(GeckoSessionTestRule.java:1651)
[task 2018-05-25T07:08:30.859Z] 07:08:30     INFO -  org.mozilla.geckoview.test | 	at org.mozilla.geckoview.test.BaseSessionTest.forCallbacksDuringWait(BaseSessionTest.kt:100)
[task 2018-05-25T07:08:30.860Z] 07:08:30     INFO -  org.mozilla.geckoview.test | 	at org.mozilla.geckoview.test.GeckoSessionTestRuleTest.forCallbacksDuringWait_limitedToLastSessionWait(GeckoSessionTestRuleTest.kt:1054)
[task 2018-05-25T07:08:30.861Z] 07:08:30     INFO -  org.mozilla.geckoview.test | 	at java.lang.reflect.Method.invokeNative(Native Method)
[task 2018-05-25T07:08:30.861Z] 07:08:30     INFO -  org.mozilla.geckoview.test | 	at java.lang.reflect.Method.invoke(Method.java:525)
[task 2018-05-25T07:08:30.862Z] 07:08:30     INFO -  org.mozilla.geckoview.test | 	at org.junit.runners.model.FrameworkMethod$1.runReflectiveCall(FrameworkMethod.java:50)
[task 2018-05-25T07:08:30.863Z] 07:08:30     INFO -  org.mozilla.geckoview.test | 	at org.junit.internal.runners.model.ReflectiveCallable.run(ReflectiveCallable.java:12)
[task 2018-05-25T07:08:30.863Z] 07:08:30     INFO -  org.mozilla.geckoview.test | 	at org.junit.runners.model.FrameworkMethod.invokeExplosively(FrameworkMethod.java:47)
[task 2018-05-25T07:08:30.864Z] 07:08:30     INFO -  org.mozilla.geckoview.test | 	at org.junit.internal.runners.statements.InvokeMethod.evaluate(InvokeMethod.java:17)
[task 2018-05-25T07:08:30.864Z] 07:08:30     INFO -  org.mozilla.geckoview.test | 	at org.mozilla.geckoview.test.rule.GeckoSessionTestRule$4.evaluate(GeckoSessionTestRule.java:1246)
[task 2018-05-25T07:08:30.865Z] 07:08:30     INFO -  org.mozilla.geckoview.test | 	at android.support.test.internal.statement.UiThreadStatement$1.run(UiThreadStatement.java:44)
[task 2018-05-25T07:08:30.866Z] 07:08:30     INFO -  org.mozilla.geckoview.test | 	at android.app.Instrumentation$SyncRunnable.run(Instrumentation.java:1719)
[task 2018-05-25T07:08:30.866Z] 07:08:30     INFO -  org.mozilla.geckoview.test | 	at android.os.Handler.handleCallback(Handler.java:730)
[task 2018-05-25T07:08:30.866Z] 07:08:30     INFO -  org.mozilla.geckoview.test | 	at android.os.Handler.dispatchMessage(Handler.java:92)
[task 2018-05-25T07:08:30.867Z] 07:08:30     INFO -  org.mozilla.geckoview.test | 	at android.os.Looper.loop(Looper.java:137)
[task 2018-05-25T07:08:30.867Z] 07:08:30     INFO -  org.mozilla.geckoview.test | 	at android.app.ActivityThread.main(ActivityThread.java:5103)
[task 2018-05-25T07:08:30.868Z] 07:08:30     INFO -  org.mozilla.geckoview.test | 	at java.lang.reflect.Method.invokeNative(Native Method)
[task 2018-05-25T07:08:30.868Z] 07:08:30     INFO -  org.mozilla.geckoview.test | 	at java.lang.reflect.Method.invoke(Method.java:525)
[task 2018-05-25T07:08:30.869Z] 07:08:30     INFO -  org.mozilla.geckoview.test | 	at com.android.internal.os.ZygoteInit$MethodAndArgsCaller.run(ZygoteInit.java:737)
[task 2018-05-25T07:08:30.869Z] 07:08:30     INFO -  org.mozilla.geckoview.test | 	at com.android.internal.os.ZygoteInit.main(ZygoteInit.java:553)
[task 2018-05-25T07:08:30.870Z] 07:08:30     INFO -  org.mozilla.geckoview.test | 	at dalvik.system.NativeStart.main(Native Method)
[task 2018-05-25T07:08:30.870Z] 07:08:30     INFO -  org.mozilla.geckoview.test |
[task 2018-05-25T07:08:30.870Z] 07:08:30     INFO -  org.mozilla.geckoview.test | INSTRUMENTATION_STATUS: test=forCallbacksDuringWait_limitedToLastSessionWait
[task 2018-05-25T07:08:30.871Z] 07:08:30     INFO -  org.mozilla.geckoview.test | INSTRUMENTATION_STATUS_CODE: -2
[task 2018-05-25T07:08:30.871Z] 07:08:30  WARNING -  TEST-UNEXPECTED-FAIL | org.mozilla.geckoview.test.GeckoSessionTestRuleTest.forCallbacksDuringWait_limitedToLastSessionWait | status -2
[task 2018-05-25T07:08:30.872Z] 07:08:30     INFO -  TEST-INFO took 16642ms

Comment 1

[Intermittent Failures Robot]

8 failures in 632 pushes (0.013 failures/push) were associated with this bug in the last 7 days.    

Repository breakdown:
* autoland: 4
* mozilla-inbound: 2
* try: 1
* mozilla-central: 1

Platform breakdown:
* android-4-3-armv7-api16: 8

For more details, see:
https://treeherder.mozilla.org/intermittent-failures.html#/bugdetails?bug=1464351&startday=2018-05-21&endday=2018-05-27&tree=trunk

Comment 2

[Intermittent Failures Robot]

17 failures in 655 pushes (0.026 failures/push) were associated with this bug in the last 7 days.    

Repository breakdown:
* autoland: 8
* mozilla-inbound: 6
* try: 2
* mozilla-central: 1

Platform breakdown:
* android-4-3-armv7-api16: 17

For more details, see:
https://treeherder.mozilla.org/intermittent-failures.html#/bugdetails?bug=1464351&startday=2018-05-28&endday=2018-06-03&tree=trunk

Comment 3

[Chris Peterson [:cpeterson]]

Resetting priority from P5 to -- so GeckoView bug triage will see this bug.

Comment 4

[(inactive) Jim Chen [:jchen] [:darchons]]

Attachment: Bug 1464351 - Look for initial about:blank load for cached session;

We can get multiple initial loads for the cached session, so we must
specifically look for an about:blank load to wait on.

Review commit: https://reviewboard.mozilla.org/r/250148/diff/#index_header
See other reviews: https://reviewboard.mozilla.org/r/250148/

Comment 5

[Intermittent Failures Robot]

10 failures in 669 pushes (0.015 failures/push) were associated with this bug in the last 7 days.    

Repository breakdown:
* autoland: 6
* mozilla-inbound: 3
* mozilla-central: 1

Platform breakdown:
* android-4-3-armv7-api16: 10

For more details, see:
https://treeherder.mozilla.org/intermittent-failures.html#/bugdetails?bug=1464351&startday=2018-06-04&endday=2018-06-10&tree=trunk

Comment 6

[Intermittent Failures Robot]

10 failures in 408 pushes (0.025 failures/push) were associated with this bug in the last 7 days.    

Repository breakdown:
* autoland: 4
* mozilla-inbound: 3
* mozilla-central: 3

Platform breakdown:
* android-4-3-armv7-api16: 10

For more details, see:
https://treeherder.mozilla.org/intermittent-failures.html#/bugdetails?bug=1464351&startday=2018-06-11&endday=2018-06-17&tree=trunk

Comment 7

[(inactive) Jim Chen [:jchen] [:darchons]]

Comment on attachment 8984338 [details]
Bug 1464351 - Look for initial about:blank load for cached session;

https://reviewboard.mozilla.org/r/250148/#review257754

Comment 8

[Eugen Sawin [:esawin]]

Comment on attachment 8984338 [details]
Bug 1464351 - Look for initial about:blank load for cached session;

https://reviewboard.mozilla.org/r/250148/#review257930

Comment 9

[(inactive) Jim Chen [:jchen] [:darchons]]

Comment on attachment 8984338 [details]
Bug 1464351 - Look for initial about:blank load for cached session;

Review request updated; see interdiff: https://reviewboard.mozilla.org/r/250148/diff/1-2/

Comment 10

[Pulsebot]

Pushed by [e-mail]:
https://hg.mozilla.org/integration/autoland/rev/359b40c7c268
Look for initial about:blank load for cached session; r=esawin

Comment 11

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

https://hg.mozilla.org/mozilla-central/rev/359b40c7c268

Comment 12

[Intermittent Failures Robot]

8 failures in 521 pushes (0.015 failures/push) were associated with this bug in the last 7 days.    

Repository breakdown:
* autoland: 4
* try: 2
* mozilla-inbound: 2

Platform breakdown:
* android-4-3-armv7-api16: 8

For more details, see:
https://treeherder.mozilla.org/intermittent-failures.html#/bugdetails?bug=1464351&startday=2018-06-18&endday=2018-06-24&tree=trunk

Comment 14

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

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