1595086 - Intermittent org.mozilla.geckoview.test.SessionLifecycleTest#asyncScriptsSuspendedWhileInactive | status -2

Status: RESOLVED FIXED

(GeckoView :: General, defect, P5)

Description

[Treeherder Bug Filer]

Filed by: malexandru [at] mozilla.com
Parsed log: https://treeherder.mozilla.org/logviewer.html#?job_id=275320608&repo=autoland
Full log: https://queue.taskcluster.net/v1/task/JiOQozWZRgCmWHzcbVQS6A/runs/0/artifacts/public/logs/live_backing.log

---

[task 2019-11-08T14:04:49.571Z] 14:04:49 INFO - TEST-START | org.mozilla.geckoview.test.SessionLifecycleTest.asyncScriptsSuspendedWhileInactive
[task 2019-11-08T14:04:53.777Z] 14:04:53 INFO - org.mozilla.geckoview.test | INSTRUMENTATION_STATUS: numtests=548
[task 2019-11-08T14:04:53.777Z] 14:04:53 INFO - org.mozilla.geckoview.test | INSTRUMENTATION_STATUS: stream=
[task 2019-11-08T14:04:53.778Z] 14:04:53 INFO - org.mozilla.geckoview.test | Error in asyncScriptsSuspendedWhileInactive(org.mozilla.geckoview.test.SessionLifecycleTest):
[task 2019-11-08T14:04:53.781Z] 14:04:53 INFO - org.mozilla.geckoview.test | java.lang.AssertionError: requestAnimationFrame has not run yet
[task 2019-11-08T14:04:53.781Z] 14:04:53 INFO - org.mozilla.geckoview.test | Expected: <true>
[task 2019-11-08T14:04:53.781Z] 14:04:53 INFO - org.mozilla.geckoview.test | but: was <false>
[task 2019-11-08T14:04:53.781Z] 14:04:53 INFO - org.mozilla.geckoview.test | at org.hamcrest.MatcherAssert.assertThat(MatcherAssert.java:20)
[task 2019-11-08T14:04:53.781Z] 14:04:53 INFO - org.mozilla.geckoview.test | at org.junit.Assert.assertThat(Assert.java:956)
[task 2019-11-08T14:04:53.781Z] 14:04:53 INFO - org.mozilla.geckoview.test | at org.junit.rules.ErrorCollector$1.call(ErrorCollector.java:65)
[task 2019-11-08T14:04:53.781Z] 14:04:53 INFO - org.mozilla.geckoview.test | at org.junit.rules.ErrorCollector.checkSucceeds(ErrorCollector.java:78)
[task 2019-11-08T14:04:53.781Z] 14:04:53 INFO - org.mozilla.geckoview.test | at org.junit.rules.ErrorCollector.checkThat(ErrorCollector.java:63)
[task 2019-11-08T14:04:53.781Z] 14:04:53 INFO - org.mozilla.geckoview.test | at org.mozilla.geckoview.test.rule.GeckoSessionTestRule.checkThat(GeckoSessionTestRule.java:796)
[task 2019-11-08T14:04:53.781Z] 14:04:53 INFO - org.mozilla.geckoview.test | at org.mozilla.geckoview.test.BaseSessionTest.assertThat(BaseSessionTest.kt:75)
[task 2019-11-08T14:04:53.781Z] 14:04:53 INFO - org.mozilla.geckoview.test | at org.mozilla.geckoview.test.SessionLifecycleTest.asyncScriptsSuspendedWhileInactive(SessionLifecycleTest.kt:481)
[task 2019-11-08T14:04:53.781Z] 14:04:53 INFO - org.mozilla.geckoview.test | at java.lang.reflect.Method.invoke(Native Method)
[task 2019-11-08T14:04:53.781Z] 14:04:53 INFO - org.mozilla.geckoview.test | at org.junit.runners.model.FrameworkMethod$1.runReflectiveCall(FrameworkMethod.java:50)
[task 2019-11-08T14:04:53.781Z] 14:04:53 INFO - org.mozilla.geckoview.test | at org.junit.internal.runners.model.ReflectiveCallable.run(ReflectiveCallable.java:12)
[task 2019-11-08T14:04:53.781Z] 14:04:53 INFO - org.mozilla.geckoview.test | at org.junit.runners.model.FrameworkMethod.invokeExplosively(FrameworkMethod.java:47)
[task 2019-11-08T14:04:53.781Z] 14:04:53 INFO - org.mozilla.geckoview.test | at org.junit.internal.runners.statements.InvokeMethod.evaluate(InvokeMethod.java:17)
[task 2019-11-08T14:04:53.781Z] 14:04:53 INFO - org.mozilla.geckoview.test | at org.mozilla.geckoview.test.rule.GeckoSessionTestRule$2.lambda$evaluate$0$GeckoSessionTestRule$2(GeckoSessionTestRule.java:1257)
[task 2019-11-08T14:04:53.781Z] 14:04:53 INFO - org.mozilla.geckoview.test | at org.mozilla.geckoview.test.rule.-$$Lambda$GeckoSessionTestRule$2$mzZNnl5Bu5F2_4xGxj0DHU4J33I.run(lambda)
[task 2019-11-08T14:04:53.781Z] 14:04:53 INFO - org.mozilla.geckoview.test | at android.app.Instrumentation$SyncRunnable.run(Instrumentation.java:1950)
[task 2019-11-08T14:04:53.781Z] 14:04:53 INFO - org.mozilla.geckoview.test | at android.os.Handler.handleCallback(Handler.java:751)
[task 2019-11-08T14:04:53.781Z] 14:04:53 INFO - org.mozilla.geckoview.test | at android.os.Handler.dispatchMessage(Handler.java:95)
[task 2019-11-08T14:04:53.781Z] 14:04:53 INFO - org.mozilla.geckoview.test | at android.os.Looper.loop(Looper.java:154)
[task 2019-11-08T14:04:53.781Z] 14:04:53 INFO - org.mozilla.geckoview.test | at android.app.ActivityThread.main(ActivityThread.java:6077)
[task 2019-11-08T14:04:53.781Z] 14:04:53 INFO - org.mozilla.geckoview.test | at java.lang.reflect.Method.invoke(Native Method)
[task 2019-11-08T14:04:53.781Z] 14:04:53 INFO - org.mozilla.geckoview.test | at com.android.internal.os.ZygoteInit$MethodAndArgsCaller.run(ZygoteInit.java:866)
[task 2019-11-08T14:04:53.781Z] 14:04:53 INFO - org.mozilla.geckoview.test | at com.android.internal.os.ZygoteInit.main(ZygoteInit.java:756)
[task 2019-11-08T14:04:53.781Z] 14:04:53 INFO - org.mozilla.geckoview.test |
[task 2019-11-08T14:04:53.781Z] 14:04:53 INFO - org.mozilla.geckoview.test | INSTRUMENTATION_STATUS: id=AndroidJUnitRunner
[task 2019-11-08T14:04:53.781Z] 14:04:53 INFO - org.mozilla.geckoview.test | INSTRUMENTATION_STATUS: test=asyncScriptsSuspendedWhileInactive
[task 2019-11-08T14:04:53.781Z] 14:04:53 INFO - org.mozilla.geckoview.test | INSTRUMENTATION_STATUS: class=org.mozilla.geckoview.test.SessionLifecycleTest
[task 2019-11-08T14:04:53.781Z] 14:04:53 INFO - org.mozilla.geckoview.test | INSTRUMENTATION_STATUS: stack=java.lang.AssertionError: requestAnimationFrame has not run yet
[task 2019-11-08T14:04:53.781Z] 14:04:53 INFO - org.mozilla.geckoview.test | Expected: <true>
[task 2019-11-08T14:04:53.781Z] 14:04:53 INFO - org.mozilla.geckoview.test | but: was <false>
[task 2019-11-08T14:04:53.781Z] 14:04:53 INFO - org.mozilla.geckoview.test | at org.hamcrest.MatcherAssert.assertThat(MatcherAssert.java:20)
[task 2019-11-08T14:04:53.781Z] 14:04:53 INFO - org.mozilla.geckoview.test | at org.junit.Assert.assertThat(Assert.java:956)
[task 2019-11-08T14:04:53.781Z] 14:04:53 INFO - org.mozilla.geckoview.test | at org.junit.rules.ErrorCollector$1.call(ErrorCollector.java:65)
[task 2019-11-08T14:04:53.782Z] 14:04:53 INFO - org.mozilla.geckoview.test | at org.junit.rules.ErrorCollector.checkSucceeds(ErrorCollector.java:78)
[task 2019-11-08T14:04:53.782Z] 14:04:53 INFO - org.mozilla.geckoview.test | at org.junit.rules.ErrorCollector.checkThat(ErrorCollector.java:63)
[task 2019-11-08T14:04:53.782Z] 14:04:53 INFO - org.mozilla.geckoview.test | at org.mozilla.geckoview.test.rule.GeckoSessionTestRule.checkThat(GeckoSessionTestRule.java:796)
[task 2019-11-08T14:04:53.782Z] 14:04:53 INFO - org.mozilla.geckoview.test | at org.mozilla.geckoview.test.BaseSessionTest.assertThat(BaseSessionTest.kt:75)
[task 2019-11-08T14:04:53.782Z] 14:04:53 INFO - org.mozilla.geckoview.test | at org.mozilla.geckoview.test.SessionLifecycleTest.asyncScriptsSuspendedWhileInactive(SessionLifecycleTest.kt:481)
[task 2019-11-08T14:04:53.782Z] 14:04:53 INFO - org.mozilla.geckoview.test | at java.lang.reflect.Method.invoke(Native Method)
[task 2019-11-08T14:04:53.782Z] 14:04:53 INFO - org.mozilla.geckoview.test | at org.junit.runners.model.FrameworkMethod$1.runReflectiveCall(FrameworkMethod.java:50)
[task 2019-11-08T14:04:53.782Z] 14:04:53 INFO - org.mozilla.geckoview.test | at org.junit.internal.runners.model.ReflectiveCallable.run(ReflectiveCallable.java:12)
[task 2019-11-08T14:04:53.783Z] 14:04:53 INFO - org.mozilla.geckoview.test | at org.junit.runners.model.FrameworkMethod.invokeExplosively(FrameworkMethod.java:47)
[task 2019-11-08T14:04:53.783Z] 14:04:53 INFO - org.mozilla.geckoview.test | at org.junit.internal.runners.statements.InvokeMethod.evaluate(InvokeMethod.java:17)
[task 2019-11-08T14:04:53.783Z] 14:04:53 INFO - org.mozilla.geckoview.test | at org.mozilla.geckoview.test.rule.GeckoSessionTestRule$2.lambda$evaluate$0$GeckoSessionTestRule$2(GeckoSessionTestRule.java:1257)
[task 2019-11-08T14:04:53.783Z] 14:04:53 INFO - org.mozilla.geckoview.test | at org.mozilla.geckoview.test.rule.-$$Lambda$GeckoSessionTestRule$2$mzZNnl5Bu5F2_4xGxj0DHU4J33I.run(lambda)
[task 2019-11-08T14:04:53.783Z] 14:04:53 INFO - org.mozilla.geckoview.test | at android.app.Instrumentation$SyncRunnable.run(Instrumentation.java:1950)
[task 2019-11-08T14:04:53.783Z] 14:04:53 INFO - org.mozilla.geckoview.test | at android.os.Handler.handleCallback(Handler.java:751)
[task 2019-11-08T14:04:53.783Z] 14:04:53 INFO - org.mozilla.geckoview.test | at android.os.Handler.dispatchMessage(Handler.java:95)
[task 2019-11-08T14:04:53.784Z] 14:04:53 INFO - org.mozilla.geckoview.test | at android.os.Looper.loop(Looper.java:154)
[task 2019-11-08T14:04:53.784Z] 14:04:53 INFO - org.mozilla.geckoview.test | at android.app.ActivityThread.main(ActivityThread.java:6077)
[task 2019-11-08T14:04:53.784Z] 14:04:53 INFO - org.mozilla.geckoview.test | at java.lang.reflect.Method.invoke(Native Method)
[task 2019-11-08T14:04:53.784Z] 14:04:53 INFO - org.mozilla.geckoview.test | at com.android.internal.os.ZygoteInit$MethodAndArgsCaller.run(ZygoteInit.java:866)
[task 2019-11-08T14:04:53.784Z] 14:04:53 INFO - org.mozilla.geckoview.test | at com.android.internal.os.ZygoteInit.main(ZygoteInit.java:756)
[task 2019-11-08T14:04:53.784Z] 14:04:53 INFO - org.mozilla.geckoview.test |
[task 2019-11-08T14:04:53.784Z] 14:04:53 INFO - org.mozilla.geckoview.test | INSTRUMENTATION_STATUS: current=421
[task 2019-11-08T14:04:53.784Z] 14:04:53 INFO - org.mozilla.geckoview.test | INSTRUMENTATION_STATUS_CODE: -2
[task 2019-11-08T14:04:53.784Z] 14:04:53 WARNING - TEST-UNEXPECTED-FAIL | org.mozilla.geckoview.test.SessionLifecycleTest.asyncScriptsSuspendedWhileInactive | status -2
[task 2019-11-08T14:04:53.785Z] 14:04:53 INFO - TEST-INFO took 4211ms
[task 2019-11-08T14:04:53.785Z] 14:04:53 INFO - org.mozilla.geckoview.test | INSTRUMENTATION_STATUS: numtests=548
[task 2019-11-08T14:04:53.785Z] 14:04:53 INFO - org.mozilla.geckoview.test | INSTRUMENTATION_STATUS: stream=
[task 2019-11-08T14:04:53.785Z] 14:04:53 INFO - org.mozilla.geckoview.test | INSTRUMENTATION_STATUS: id=AndroidJUnitRunner
[task 2019-11-08T14:04:53.785Z] 14:04:53 INFO - org.mozilla.geckoview.test | INSTRUMENTATION_STATUS: test=readFromParcel_closedSessionAfterParceling
[task 2019-11-08T14:04:53.785Z] 14:04:53 INFO - org.mozilla.geckoview.test | INSTRUMENTATION_STATUS: class=org.mozilla.geckoview.test.SessionLifecycleTest
[task 2019-11-08T14:04:53.785Z] 14:04:53 INFO - org.mozilla.geckoview.test | INSTRUMENTATION_STATUS: current=422
[task 2019-11-08T14:04:53.785Z] 14:04:53 INFO - org.mozilla.geckoview.test | INSTRUMENTATION_STATUS_CODE: 1
[task 2019-11-08T14:04:53.785Z] 14:04:53 INFO - TEST-START | org.mozilla.geckoview.test.SessionLifecycleTest.readFromParcel_closedSessionAfterParceling

Comment 1

[Alexandru Michis [:malexandru]]

Thomas,
This looks to be related to the test you introduced in Bug 1578942, could you please take a look?

Comment 2

[Intermittent Failures Robot]

4 failures in 4850 pushes (0.001 failures/push) were associated with this bug in the last 7 days.

Repository breakdown:

• autoland: 4

Platform breakdown:

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

For more details, see:
https://treeherder.mozilla.org/intermittent-failures.html#/bugdetails?bug=1595086&startday=2019-11-04&endday=2019-11-10&tree=all

Comment 3

[Thomas Wisniewski [:twisniewski]]

I've tried a bunch of things here, but the root cause of the failure is elusive. Basically, it seems that suspendTimeouts does not always stop the test's subsequent requestAnimationFrame calls, though they are stopped during most test runs (and when manually testing), so something is simply causing the suspendTimeouts call to not work early enough for the test's rAF call.

There may be something like GC getting in the way, as the only difference I see between failing and successful test runs is a block of window-teardown code from another test that was run in parallel (ADB log ; try-run):

11-15 06:11:05.424  2843  2843 D SessionLifecycleTest: TOMW: SessionLifecycleTest.kt calling setActive(false)
11-15 06:11:05.424  2843  2843 D SessionLifecycleTest: TOMW: SessionLifecycleTest.kt continuing
11-15 06:11:05.427  2843  2868 D GeckoViewModule: dispatch GeckoView:SetActive, data={"active":false}
11-15 06:11:05.428  2843  2868 D GeckoViewContent: onEvent: event=GeckoView:SetActive, data={"active":false}
11-15 06:11:05.429  2843  2868 D GeckoViewModule: dispatch GeckoView:FlushSessionState, data=null
11-15 06:11:05.429  2843  2868 D GeckoViewProgress: onEvent: event=GeckoView:FlushSessionState, data=null
11-15 06:11:05.430  2843  2868 D GeckoViewConsole: onEvent GeckoView:WebExtension:PortMessageFromApp {"portId":137438955119,"message":{"id":"acb843f0-d595-4378-9127-59f59192f9fc","eval":"requestAnimationFrame(() => {\n                 requestAnimationFrame(() => {\n                   console.log(\"TOMW: requestAnimationFrame JS callback reached\");\n                   document.documentElement.style.backgroundColor = 'green';\n                 });\n               });\n               setTimeout(() => {\n                 setTimeout(() => {\n                   console.log(\"TOMW: setTimeout JS callback reached\");\n                   document.documentElement.style.backgroundColor = 'green';\n                 }, 1);\n               }, 1);"}}
11-15 06:11:05.439  2910  2925 D GeckoViewContent[C]: receiveMessage: GeckoView:SetActive
11-15 06:11:05.440  2910  2925 D GeckoViewContent[C]: TOMW: GeckoViewContentChild received GeckoView:SetActive(false), calling suspendTimeouts
11-15 06:11:05.440  2910  2925 I Gecko   : TOMW: nsGlobalWindowInner::Suspend() called
11-15 06:11:05.440  2910  2925 I Gecko   : TOMW: nsGlobalWindowInner::Suspend (called on children)
11-15 06:11:05.440  2910  2925 I Gecko   : TOMW: nsGlobalWindowInner::Suspend (workers suspended)
11-15 06:11:05.440  2910  2925 I Gecko   : TOMW: nsGlobalWindowInner::Suspend (timeouts suspended)
11-15 06:11:05.440  2910  2925 I Gecko   : TOMW: nsGlobalWindowInner::Suspend (done)
11-15 06:11:05.440  2910  2925 D GeckoViewContent[C]: TOMW: GeckoViewContentChild sending GeckoView:Suspended request
11-15 06:11:05.441  2910  2925 D GeckoViewSessionStateAggregator[C]: receiveMessage: GeckoView:FlushSessionState
11-15 06:11:05.514  2843  2843 D GeckoSession: handleMessage GeckoView:StateUpdated uri=null
11-15 06:11:05.514  2843  2843 W GeckoSession: No history entries found.
11-15 06:11:05.514  2843  2843 D SessionLifecycleTest: TOMW: SessionLifecycleTest.kt has sent requestAnimationFrame
11-15 06:11:05.515  2843  2868 D GeckoViewConsole: onEvent GeckoView:WebExtension:PortMessageFromApp {"portId":137438955119,"message":{"id":"48384c28-3508-4722-a13a-4946a5950e7e","eval":"new Promise(resolve => { resolve() })"}}
11-15 06:11:05.516  2843  2868 D GeckoViewConsole: onEvent GeckoView:WebExtension:PortMessageFromApp {"portId":137438955119,"message":{"id":"48384c28-3508-4722-a13a-4946a5950e7e","eval":"new Promise(resolve => 11-15 06:11:06.921  2910  2925 I Gecko   : --DOCSHELL 0x7082b124f800 == 9 [pid = 2910] [id = {927dc021-90e0-4237-86ed-47528323c1c1}] [url = about:blank]
11-15 06:11:06.921  2910  2925 I Gecko   : --DOCSHELL 0x7082b2287800 == 8 [pid = 2910] [id = {972570c4-0d40-4a03-a234-9fee27ed4176}] [url = http://localhost:4245/assets/www/inputs.html]
    ***
*** snip big block of window-cleanup logging ***
    ***
11-15 06:11:06.925  2910  2925 I Gecko   : --DOMWINDOW == 37 (0x7082b1b6bc00) [pid = 2910] [serial = 1434] [outer = 0x0] [url = http://localhost:4245/assets/www/selectionAction_frame.html]
    ***
*** snip more of the same ***
    ***
11-15 06:11:12.098  2910  2925 I Gecko   : --DOMWINDOW == 5 (0x7082b1be1d40) [pid = 2910] [serial = 1456] [outer = 0x0] [url = about:blank]
11-15 06:11:13.552  2843  2868 I Gecko   : AndroidBridge::GetMimeTypeFromExtensions
11-15 06:11:13.555  2843  2868 D GeckoViewConsole: onEvent GeckoView:WebExtension:PortMessageFromApp {"portId":137438955119,"message":{"id":"d08a4b46-95af-4285-88bb-87c5667f3a26","eval":"document.documentElement.style.backgroundColor !== 'green'"}}
11-15 06:11:13.568  2843  2843 D SessionLifecycleTest: TOMW: SessionLifecycleTest.kt calling setActive(true) and waiting for requestAnimationFrame
11-15 06:11:13.569  2843  2868 D GeckoViewModule: dispatch GeckoView:SetActive, data={"active":true}
11-15 06:11:13.569  2843  2868 D GeckoViewContent: onEvent: event=GeckoView:SetActive, data={"active":true}
11-15 06:11:13.570  2843  2868 D GeckoViewConsole: onEvent GeckoView:WebExtension:PortMessageFromApp {"portId":137438955119,"message":{"id":"01fd81e4-58e5-4a32-a3f4-3c149e89b7b5","eval":"new Promise(resolve => requestAnimationFrame(() => {\n              console.log(\"TOMW: final JS rAF promise resolved in test\");\n              resolve();\n             }))"}}
11-15 06:11:13.571  2843  2868 D GeckoScreenOrientation: unlocking
11-15 06:11:13.573  2910  2925 D GeckoViewContent[C]: receiveMessage: GeckoView:SetActive
11-15 06:11:13.574  2843  2892 D EGL_emulation: eglMakeCurrent: 0x7082d37b3d60: ver 2 0 (tinfo 0x7082ddee2080)
11-15 06:11:13.575  2910  2925 D GeckoViewContent[C]: TOMW: GeckoViewContentChild received GeckoView:SetActive(true), calling resumeTimeouts
11-15 06:11:13.575  2910  2925 I Gecko   : TOMW: nsGlobalWindowInner::Resume() called
11-15 06:11:13.576  2910  2925 I Gecko   : TOMW: nsGlobalWindowInner::Resume() done
11-15 06:11:13.582  2910  2925 I Web Content: TOMW: setTimeout JS callback reached
11-15 06:11:13.608  2910  2925 I Web Content: TOMW: final JS rAF promise resolved in test
11-15 06:11:13.677  2843  2858 I TestRunner: ----- begin exception -----
11-15 06:11:13.677  2843  2858 I TestRunner: java.lang.AssertionError: requestAnimationFrame has not run yet

Either way, waiting for the suspendTimeouts call to complete isn't enough, nor is nesting requestAnimationFrame calls. And according to the log, 2 seconds are passing between the suspendTimeouts call completing and the rAF callback being run, so it would not be enough to just wait a set amount of time before trying an rAF.

It seems we would need to figure out the precise time when the timeouts are really suspended and have a signal sent to the test at that point, or perhaps we could get away with pausing global GC during this portion of the test (or whatever causes that window teardown code to run). Beyond that, I'm not sure what can be done to make this test more robust, and I'm not convinced that it's worth the effort right now if it's just for the sake of this test.

Comment 4

[Intermittent Failures Robot]

24 failures in 4207 pushes (0.006 failures/push) were associated with this bug in the last 7 days.

Repository breakdown:

• autoland: 19
• try: 3
• mozilla-central: 2

Platform breakdown:

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

For more details, see:
https://treeherder.mozilla.org/intermittent-failures.html#/bugdetails?bug=1595086&startday=2019-11-11&endday=2019-11-17&tree=all

Comment 5

[Intermittent Failures Robot]

21 failures in 5444 pushes (0.004 failures/push) were associated with this bug in the last 7 days.

Repository breakdown:

• autoland: 16
• mozilla-central: 3
• try: 2

Platform breakdown:

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

For more details, see:
https://treeherder.mozilla.org/intermittent-failures.html#/bugdetails?bug=1595086&startday=2019-11-18&endday=2019-11-24&tree=all

Comment 6

[Andreea Pavel [:apavel]]

There are 25 total failures in the last 7 days on android-em-7-0-x86_64 opt and debug.

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

[task 2019-11-27T03:53:40.730Z] 03:53:40 INFO - org.mozilla.geckoview.test | INSTRUMENTATION_STATUS: numtests=582
[task 2019-11-27T03:53:40.734Z] 03:53:40 INFO - org.mozilla.geckoview.test | INSTRUMENTATION_STATUS: stream=
[task 2019-11-27T03:53:40.735Z] 03:53:40 INFO - org.mozilla.geckoview.test | Error in asyncScriptsSuspendedWhileInactive(org.mozilla.geckoview.test.SessionLifecycleTest):
[task 2019-11-27T03:53:40.735Z] 03:53:40 INFO - org.mozilla.geckoview.test | java.lang.AssertionError: requestAnimationFrame has not run yet
[task 2019-11-27T03:53:40.735Z] 03:53:40 INFO - org.mozilla.geckoview.test | Expected: <true>
[task 2019-11-27T03:53:40.735Z] 03:53:40 INFO - org.mozilla.geckoview.test | but: was <false>
[task 2019-11-27T03:53:40.735Z] 03:53:40 INFO - org.mozilla.geckoview.test | at org.hamcrest.MatcherAssert.assertThat(MatcherAssert.java:20)
[task 2019-11-27T03:53:40.735Z] 03:53:40 INFO - org.mozilla.geckoview.test | at org.junit.Assert.assertThat(Assert.java:956)
[task 2019-11-27T03:53:40.735Z] 03:53:40 INFO - org.mozilla.geckoview.test | at org.junit.rules.ErrorCollector$1.call(ErrorCollector.java:65)
[task 2019-11-27T03:53:40.735Z] 03:53:40 INFO - org.mozilla.geckoview.test | at org.junit.rules.ErrorCollector.checkSucceeds(ErrorCollector.java:78)
[task 2019-11-27T03:53:40.735Z] 03:53:40 INFO - org.mozilla.geckoview.test | at org.junit.rules.ErrorCollector.checkThat(ErrorCollector.java:63)
[task 2019-11-27T03:53:40.735Z] 03:53:40 INFO - org.mozilla.geckoview.test | at org.mozilla.geckoview.test.rule.GeckoSessionTestRule.checkThat(GeckoSessionTestRule.java:797)
[task 2019-11-27T03:53:40.735Z] 03:53:40 INFO - org.mozilla.geckoview.test | at org.mozilla.geckoview.test.BaseSessionTest.assertThat(BaseSessionTest.kt:77)
[task 2019-11-27T03:53:40.735Z] 03:53:40 INFO - org.mozilla.geckoview.test | at org.mozilla.geckoview.test.SessionLifecycleTest.asyncScriptsSuspendedWhileInactive(SessionLifecycleTest.kt:481)
[task 2019-11-27T03:53:40.735Z] 03:53:40 INFO - org.mozilla.geckoview.test | at java.lang.reflect.Method.invoke(Native Method)
[task 2019-11-27T03:53:40.735Z] 03:53:40 INFO - org.mozilla.geckoview.test | at org.junit.runners.model.FrameworkMethod$1.runReflectiveCall(FrameworkMethod.java:50)
[task 2019-11-27T03:53:40.735Z] 03:53:40 INFO - org.mozilla.geckoview.test | at org.junit.internal.runners.model.ReflectiveCallable.run(ReflectiveCallable.java:12)
[task 2019-11-27T03:53:40.735Z] 03:53:40 INFO - org.mozilla.geckoview.test | at org.junit.runners.model.FrameworkMethod.invokeExplosively(FrameworkMethod.java:47)
[task 2019-11-27T03:53:40.735Z] 03:53:40 INFO - org.mozilla.geckoview.test | at org.junit.internal.runners.statements.InvokeMethod.evaluate(InvokeMethod.java:17)
[task 2019-11-27T03:53:40.735Z] 03:53:40 INFO - org.mozilla.geckoview.test | at org.mozilla.geckoview.test.rule.GeckoSessionTestRule$2.lambda$evaluate$0$GeckoSessionTestRule$2(GeckoSessionTestRule.java:1266)
[task 2019-11-27T03:53:40.735Z] 03:53:40 INFO - org.mozilla.geckoview.test | at org.mozilla.geckoview.test.rule.-$$Lambda$GeckoSessionTestRule$2$mzZNnl5Bu5F2_4xGxj0DHU4J33I.run(lambda)
[task 2019-11-27T03:53:40.735Z] 03:53:40 INFO - org.mozilla.geckoview.test | at android.app.Instrumentation$SyncRunnable.run(Instrumentation.java:1950)
[task 2019-11-27T03:53:40.735Z] 03:53:40 INFO - org.mozilla.geckoview.test | at android.os.Handler.handleCallback(Handler.java:751)
[task 2019-11-27T03:53:40.735Z] 03:53:40 INFO - org.mozilla.geckoview.test | at android.os.Handler.dispatchMessage(Handler.java:95)
[task 2019-11-27T03:53:40.735Z] 03:53:40 INFO - org.mozilla.geckoview.test | at android.os.Looper.loop(Looper.java:154)
[task 2019-11-27T03:53:40.735Z] 03:53:40 INFO - org.mozilla.geckoview.test | at android.app.ActivityThread.main(ActivityThread.java:6077)
[task 2019-11-27T03:53:40.735Z] 03:53:40 INFO - org.mozilla.geckoview.test | at java.lang.reflect.Method.invoke(Native Method)
[task 2019-11-27T03:53:40.735Z] 03:53:40 INFO - org.mozilla.geckoview.test | at com.android.internal.os.ZygoteInit$MethodAndArgsCaller.run(ZygoteInit.java:866)
[task 2019-11-27T03:53:40.735Z] 03:53:40 INFO - org.mozilla.geckoview.test | at com.android.internal.os.ZygoteInit.main(ZygoteInit.java:756)
[task 2019-11-27T03:53:40.735Z] 03:53:40 INFO - org.mozilla.geckoview.test |
[task 2019-11-27T03:53:40.735Z] 03:53:40 INFO - org.mozilla.geckoview.test | INSTRUMENTATION_STATUS: id=AndroidJUnitRunner
[task 2019-11-27T03:53:40.735Z] 03:53:40 INFO - org.mozilla.geckoview.test | INSTRUMENTATION_STATUS: test=asyncScriptsSuspendedWhileInactive
[task 2019-11-27T03:53:40.735Z] 03:53:40 INFO - org.mozilla.geckoview.test | INSTRUMENTATION_STATUS: class=org.mozilla.geckoview.test.SessionLifecycleTest
[task 2019-11-27T03:53:40.735Z] 03:53:40 INFO - org.mozilla.geckoview.test | INSTRUMENTATION_STATUS: stack=java.lang.AssertionError: requestAnimationFrame has not run yet
[task 2019-11-27T03:53:40.735Z] 03:53:40 INFO - org.mozilla.geckoview.test | Expected: <true>
[task 2019-11-27T03:53:40.735Z] 03:53:40 INFO - org.mozilla.geckoview.test | but: was <false>
[task 2019-11-27T03:53:40.735Z] 03:53:40 INFO - org.mozilla.geckoview.test | at org.hamcrest.MatcherAssert.assertThat(MatcherAssert.java:20)
[task 2019-11-27T03:53:40.735Z] 03:53:40 INFO - org.mozilla.geckoview.test | at org.junit.Assert.assertThat(Assert.java:956)
[task 2019-11-27T03:53:40.735Z] 03:53:40 INFO - org.mozilla.geckoview.test | at org.junit.rules.ErrorCollector$1.call(ErrorCollector.java:65)
[task 2019-11-27T03:53:40.735Z] 03:53:40 INFO - org.mozilla.geckoview.test | at org.junit.rules.ErrorCollector.checkSucceeds(ErrorCollector.java:78)
[task 2019-11-27T03:53:40.735Z] 03:53:40 INFO - org.mozilla.geckoview.test | at org.junit.rules.ErrorCollector.checkThat(ErrorCollector.java:63)
[task 2019-11-27T03:53:40.735Z] 03:53:40 INFO - org.mozilla.geckoview.test | at org.mozilla.geckoview.test.rule.GeckoSessionTestRule.checkThat(GeckoSessionTestRule.java:797)
[task 2019-11-27T03:53:40.735Z] 03:53:40 INFO - org.mozilla.geckoview.test | at org.mozilla.geckoview.test.BaseSessionTest.assertThat(BaseSessionTest.kt:77)
[task 2019-11-27T03:53:40.735Z] 03:53:40 INFO - org.mozilla.geckoview.test | at org.mozilla.geckoview.test.SessionLifecycleTest.asyncScriptsSuspendedWhileInactive(SessionLifecycleTest.kt:481)
[task 2019-11-27T03:53:40.736Z] 03:53:40 INFO - org.mozilla.geckoview.test | at java.lang.reflect.Method.invoke(Native Method)
[task 2019-11-27T03:53:40.736Z] 03:53:40 INFO - org.mozilla.geckoview.test | at org.junit.runners.model.FrameworkMethod$1.runReflectiveCall(FrameworkMethod.java:50)
[task 2019-11-27T03:53:40.736Z] 03:53:40 INFO - org.mozilla.geckoview.test | at org.junit.internal.runners.model.ReflectiveCallable.run(ReflectiveCallable.java:12)
[task 2019-11-27T03:53:40.736Z] 03:53:40 INFO - org.mozilla.geckoview.test | at org.junit.runners.model.FrameworkMethod.invokeExplosively(FrameworkMethod.java:47)
[task 2019-11-27T03:53:40.736Z] 03:53:40 INFO - org.mozilla.geckoview.test | at org.junit.internal.runners.statements.InvokeMethod.evaluate(InvokeMethod.java:17)
[task 2019-11-27T03:53:40.736Z] 03:53:40 INFO - org.mozilla.geckoview.test | at org.mozilla.geckoview.test.rule.GeckoSessionTestRule$2.lambda$evaluate$0$GeckoSessionTestRule$2(GeckoSessionTestRule.java:1266)
[task 2019-11-27T03:53:40.736Z] 03:53:40 INFO - org.mozilla.geckoview.test | at org.mozilla.geckoview.test.rule.-$$Lambda$GeckoSessionTestRule$2$mzZNnl5Bu5F2_4xGxj0DHU4J33I.run(lambda)
[task 2019-11-27T03:53:40.737Z] 03:53:40 INFO - org.mozilla.geckoview.test | at android.app.Instrumentation$SyncRunnable.run(Instrumentation.java:1950)
[task 2019-11-27T03:53:40.737Z] 03:53:40 INFO - org.mozilla.geckoview.test | at android.os.Handler.handleCallback(Handler.java:751)
[task 2019-11-27T03:53:40.737Z] 03:53:40 INFO - org.mozilla.geckoview.test | at android.os.Handler.dispatchMessage(Handler.java:95)
[task 2019-11-27T03:53:40.737Z] 03:53:40 INFO - org.mozilla.geckoview.test | at android.os.Looper.loop(Looper.java:154)
[task 2019-11-27T03:53:40.737Z] 03:53:40 INFO - org.mozilla.geckoview.test | at android.app.ActivityThread.main(ActivityThread.java:6077)
[task 2019-11-27T03:53:40.737Z] 03:53:40 INFO - org.mozilla.geckoview.test | at java.lang.reflect.Method.invoke(Native Method)
[task 2019-11-27T03:53:40.738Z] 03:53:40 INFO - org.mozilla.geckoview.test | at com.android.internal.os.ZygoteInit$MethodAndArgsCaller.run(ZygoteInit.java:866)
[task 2019-11-27T03:53:40.738Z] 03:53:40 INFO - org.mozilla.geckoview.test | at com.android.internal.os.ZygoteInit.main(ZygoteInit.java:756)
[task 2019-11-27T03:53:40.738Z] 03:53:40 INFO - org.mozilla.geckoview.test |
[task 2019-11-27T03:53:40.738Z] 03:53:40 INFO - org.mozilla.geckoview.test | INSTRUMENTATION_STATUS: current=453
[task 2019-11-27T03:53:40.738Z] 03:53:40 INFO - org.mozilla.geckoview.test | INSTRUMENTATION_STATUS_CODE: -2
[task 2019-11-27T03:53:40.738Z] 03:53:40 WARNING - TEST-UNEXPECTED-FAIL | org.mozilla.geckoview.test.SessionLifecycleTest.asyncScriptsSuspendedWhileInactive | status -2
[task 2019-11-27T03:53:40.738Z] 03:53:40 INFO - TEST-INFO took 2708ms
[task 2019-11-27T03:53:40.738Z] 03:53:40 INFO - org.mozilla.geckoview.test | INSTRUMENTATION_STATUS: numtests=582
[task 2019-11-27T03:53:40.738Z] 03:53:40 INFO - org.mozilla.geckoview.test | INSTRUMENTATION_STATUS: stream=
[task 2019-11-27T03:53:40.738Z] 03:53:40 INFO - org.mozilla.geckoview.test | INSTRUMENTATION_STATUS: id=AndroidJUnitRunner
[task 2019-11-27T03:53:40.738Z] 03:53:40 INFO - org.mozilla.geckoview.test | INSTRUMENTATION_STATUS: test=readFromParcel_closedSessionAfterParceling
[task 2019-11-27T03:53:40.738Z] 03:53:40 INFO - org.mozilla.geckoview.test | INSTRUMENTATION_STATUS: class=org.mozilla.geckoview.test.SessionLifecycleTest
[task 2019-11-27T03:53:40.738Z] 03:53:40 INFO - org.mozilla.geckoview.test | INSTRUMENTATION_STATUS: current=454
[task 2019-11-27T03:53:40.738Z] 03:53:40 INFO - org.mozilla.geckoview.test | INSTRUMENTATION_STATUS_CODE: 1

Chris can you take a look?

Comment 7

[Thomas Wisniewski [:twisniewski]]

Just fyi, I'm still actively investigating this one (I've been discussing it with snorp), and was hoping to have an update today.

Comment 8

[Andreea Pavel [:apavel]]

(In reply to Thomas Wisniewski [:twisniewski] (PTO Nov.18-22) from comment #7)

Just fyi, I'm still actively investigating this one (I've been discussing it with snorp), and was hoping to have an update today.

Oh, great. Thank you for updating here.

Comment 9

[Thomas Wisniewski [:twisniewski]]

The problem here is that requestAnimationFrame isn't actually stopped by the patch in bug 1578942, but the test assumes it is (as that was the intent of the bug). If I freeze the refresh driver as well as calling suspendTimeouts, then the patch seems to work fine based on quite a few repeats of the failing job: https://treeherder.mozilla.org/#/jobs?repo=try&revision=01cd169c0ba465930cf60794f6578e2853012ce1&selectedJob=278848668

Note that I actually freeze the presShell in this patch, since that seems like a better option to me (it freezes the driver as well). Also note that the other failures in that try-run are appearing for me regardless of whether the patch is applied: https://treeherder.mozilla.org/#/jobs?repo=try&revision=09ba05cc61aea800af70023ddf9a92b045fa5536

A complete try-run also seems fine: https://treeherder.mozilla.org/#/jobs?repo=try&revision=74ecfd21bd04c22fae33a28a3eb0e1c4a0b1641d

Based on this, I'll request review of the patch.

Comment 10

[Thomas Wisniewski [:twisniewski]]

Attachment: Bug 1595086 - also freeze the presshell when setActive(false) is called to stop requestAnimationFrames; r?snorp

also freeze the presshell when setActive(false) is called to stop requestAnimationFrames

Comment 11

[Intermittent Failures Robot]

23 failures in 4331 pushes (0.005 failures/push) were associated with this bug in the last 7 days.

Repository breakdown:

• try: 2
• autoland: 18
• mozilla-central: 3

Platform breakdown:

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

For more details, see:
https://treeherder.mozilla.org/intermittent-failures.html#/bugdetails?bug=1595086&startday=2019-11-25&endday=2019-12-01&tree=all

Comment 12

[Pulsebot]

Pushed by [e-mail]:
https://hg.mozilla.org/integration/autoland/rev/6ce1fcebc7cd
also freeze the presshell when setActive(false) is called to stop requestAnimationFrames; r=smaug

Comment 13

[Narcis Beleuzu [:NarcisB]]

https://hg.mozilla.org/mozilla-central/rev/6ce1fcebc7cd

Comment 14

[Ryan VanderMeulen [:RyanVM]]

Please nominate this for Beta approval when you get a chance.

Comment 15

[Thomas Wisniewski [:twisniewski]]

Comment on attachment 9112661 [details]
Bug 1595086 - also freeze the presshell when setActive(false) is called to stop requestAnimationFrames; r?snorp

Beta/Release Uplift Approval Request

• User impact if declined: Backgrounded GeckoView browsers will likely use more resources than necessary on complex sites. This patch also fixes an intermittent test failure.
• Is this code covered by automated tests?: Yes
• Has the fix been verified in Nightly?: Yes
• Needs manual test from QE?: No
• If yes, steps to reproduce:
• List of other uplifts needed: None
• Risk to taking this patch: Low
• Why is the change risky/not risky? (and alternatives if risky): This patch only pauses web content painting on GeckoView when tabs are backgrounded, which may impact web scripts, but a similar change to script timeouts has already landed without reported issues, so the risk here is low.
• String changes made/needed:

Comment 16

[Intermittent Failures Robot]

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

Repository breakdown:

• autoland: 16
• mozilla-beta: 1

Platform breakdown:

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

For more details, see:
https://treeherder.mozilla.org/intermittent-failures.html#/bugdetails?bug=1595086&startday=2019-12-02&endday=2019-12-08&tree=all

Comment 17

[Julien Cristau [:jcristau] (back August 18)]

Comment on attachment 9112661 [details]
Bug 1595086 - also freeze the presshell when setActive(false) is called to stop requestAnimationFrames; r?snorp

gv fix for beta72

Comment 18

[Ryan VanderMeulen [:RyanVM]]

https://hg.mozilla.org/releases/mozilla-beta/rev/bb96b4399dea

Comment 19

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

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