1487361 - Perma tier2 failure java.lang.RuntimeException: java.lang.Exception: shistoryInternal.GetTransactionAtIndex is not a function / org.mozilla.geckoview.test.util.UiThreadUtils$TimeoutException: Timed out

Status: RESOLVED INCOMPLETE

(GeckoView :: General, defect, P5)

Description

[Treeherder Bug Filer]

Filed by: ebalazs [at] mozilla.com

https://treeherder.mozilla.org/logviewer.html#?job_id=196609993&repo=mozilla-central

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

There are two types of failures: 
Error in saveStateSync(org.mozilla.geckoview.test.ContentDelegateTest):
[task 2018-08-30T10:35:18.723Z] 10:35:18     INFO -  org.mozilla.geckoview.test | org.mozilla.geckoview.test.util.UiThreadUtils$TimeoutException: Timed out
[task 2018-08-30T10:35:18.724Z] 10:35:18     INFO -  org.mozilla.geckoview.test | 	at org.mozilla.geckoview.test.ContentDelegateTest.saveStateSync(ContentDelegateTest.kt:192)
[task 2018-08-30T10:35:18.727Z] 10:35:18     INFO -  org.mozilla.geckoview.test | 	at java.lang.reflect.Method.invokeNative(Native Method)
[task 2018-08-30T10:35:18.727Z] 10:35:18     INFO -  org.mozilla.geckoview.test | 	at java.lang.reflect.Method.invoke(Method.java:525)
[task 2018-08-30T10:35:18.727Z] 10:35:18     INFO -  org.mozilla.geckoview.test | 	at org.junit.runners.model.FrameworkMethod$1.runReflectiveCall(FrameworkMethod.java:50)
[task 2018-08-30T10:35:18.727Z] 10:35:18     INFO -  org.mozilla.geckoview.test | 	at org.junit.internal.runners.model.ReflectiveCallable.run(ReflectiveCallable.java:12)
[task 2018-08-30T10:35:18.727Z] 10:35:18     INFO -  org.mozilla.geckoview.test | 	at org.junit.runners.model.FrameworkMethod.invokeExplosively(FrameworkMethod.java:47)
[task 2018-08-30T10:35:18.727Z] 10:35:18     INFO -  org.mozilla.geckoview.test | 	at org.junit.internal.runners.statements.InvokeMethod.evaluate(InvokeMethod.java:17)
[task 2018-08-30T10:35:18.727Z] 10:35:18     INFO -  org.mozilla.geckoview.test | 	at org.mozilla.geckoview.test.rule.GeckoSessionTestRule$4$1.run(GeckoSessionTestRule.java:1486)
[task 2018-08-30T10:35:18.727Z] 10:35:18     INFO -  org.mozilla.geckoview.test | 	at android.app.Instrumentation$SyncRunnable.run(Instrumentation.java:1719)
[task 2018-08-30T10:35:18.727Z] 10:35:18     INFO -  org.mozilla.geckoview.test | 	at android.os.Handler.handleCallback(Handler.java:730)
[task 2018-08-30T10:35:18.728Z] 10:35:18     INFO -  org.mozilla.geckoview.test | 	at android.os.Handler.dispatchMessage(Handler.java:92)
[task 2018-08-30T10:35:18.728Z] 10:35:18     INFO -  org.mozilla.geckoview.test | 	at android.os.Looper.loop(Looper.java:137)
[task 2018-08-30T10:35:18.729Z] 10:35:18     INFO -  org.mozilla.geckoview.test | 	at android.app.ActivityThread.main(ActivityThread.java:5103)
[task 2018-08-30T10:35:18.729Z] 10:35:18     INFO -  org.mozilla.geckoview.test | 	at java.lang.reflect.Method.invokeNative(Native Method)
[task 2018-08-30T10:35:18.730Z] 10:35:18     INFO -  org.mozilla.geckoview.test | 	at java.lang.reflect.Method.invoke(Method.java:525)
[task 2018-08-30T10:35:18.730Z] 10:35:18     INFO -  org.mozilla.geckoview.test | 	at com.android.internal.os.ZygoteInit$MethodAndArgsCaller.run(ZygoteInit.java:737)
[task 2018-08-30T10:35:18.731Z] 10:35:18     INFO -  org.mozilla.geckoview.test | 	at com.android.internal.os.ZygoteInit.main(ZygoteInit.java:553)
[task 2018-08-30T10:35:18.731Z] 10:35:18     INFO -  org.mozilla.geckoview.test | 	at dalvik.system.NativeStart.main(Native Method)
[task 2018-08-30T10:35:18.732Z] 10:35:18     INFO -  org.mozilla.geckoview.test |
[task 2018-08-30T10:35:18.732Z] 10:35:18     INFO -  org.mozilla.geckoview.test | INSTRUMENTATION_STATUS: numtests=81
[task 2018-08-30T10:35:18.733Z] 10:35:18     INFO -  org.mozilla.geckoview.test | INSTRUMENTATION_STATUS: stack=org.mozilla.geckoview.test.util.UiThreadUtils$TimeoutException: Timed out
[task 2018-08-30T10:35:18.733Z] 10:35:18     INFO -  org.mozilla.geckoview.test | 	at org.mozilla.geckoview.test.ContentDelegateTest.saveStateSync(ContentDelegateTest.kt:192)
[task 2018-08-30T10:35:18.734Z] 10:35:18     INFO -  org.mozilla.geckoview.test | 	at java.lang.reflect.Method.invokeNative(Native Method)
[task 2018-08-30T10:35:18.734Z] 10:35:18     INFO -  org.mozilla.geckoview.test | 	at java.lang.reflect.Method.invoke(Method.java:525)
[task 2018-08-30T10:35:18.735Z] 10:35:18     INFO -  org.mozilla.geckoview.test | 	at org.junit.runners.model.FrameworkMethod$1.runReflectiveCall(FrameworkMethod.java:50)
[task 2018-08-30T10:35:18.735Z] 10:35:18     INFO -  org.mozilla.geckoview.test | 	at org.junit.internal.runners.model.ReflectiveCallable.run(ReflectiveCallable.java:12)
[task 2018-08-30T10:35:18.736Z] 10:35:18     INFO -  org.mozilla.geckoview.test | 	at org.junit.runners.model.FrameworkMethod.invokeExplosively(FrameworkMethod.java:47)
[task 2018-08-30T10:35:18.737Z] 10:35:18     INFO -  org.mozilla.geckoview.test | 	at org.junit.internal.runners.statements.InvokeMethod.evaluate(InvokeMethod.java:17)
[task 2018-08-30T10:35:18.737Z] 10:35:18     INFO -  org.mozilla.geckoview.test | 	at org.mozilla.geckoview.test.rule.GeckoSessionTestRule$4$1.run(GeckoSessionTestRule.java:1486)
[task 2018-08-30T10:35:18.738Z] 10:35:18     INFO -  org.mozilla.geckoview.test | 	at android.app.Instrumentation$SyncRunnable.run(Instrumentation.java:1719)
[task 2018-08-30T10:35:18.738Z] 10:35:18     INFO -  org.mozilla.geckoview.test | 	at android.os.Handler.handleCallback(Handler.java:730)
[task 2018-08-30T10:35:18.739Z] 10:35:18     INFO -  org.mozilla.geckoview.test | 	at android.os.Handler.dispatchMessage(Handler.java:92)
[task 2018-08-30T10:35:18.740Z] 10:35:18     INFO -  org.mozilla.geckoview.test | 	at android.os.Looper.loop(Looper.java:137)
[task 2018-08-30T10:35:18.740Z] 10:35:18     INFO -  org.mozilla.geckoview.test | 	at android.app.ActivityThread.main(ActivityThread.java:5103)
[task 2018-08-30T10:35:18.741Z] 10:35:18     INFO -  org.mozilla.geckoview.test | 	at java.lang.reflect.Method.invokeNative(Native Method)
[task 2018-08-30T10:35:18.741Z] 10:35:18     INFO -  org.mozilla.geckoview.test | 	at java.lang.reflect.Method.invoke(Method.java:525)
[task 2018-08-30T10:35:18.742Z] 10:35:18     INFO -  org.mozilla.geckoview.test | 	at com.android.internal.os.ZygoteInit$MethodAndArgsCaller.run(ZygoteInit.java:737)
[task 2018-08-30T10:35:18.742Z] 10:35:18     INFO -  org.mozilla.geckoview.test | 	at com.android.internal.os.ZygoteInit.main(ZygoteInit.java:553)
[task 2018-08-30T10:35:18.743Z] 10:35:18     INFO -  org.mozilla.geckoview.test | 	at dalvik.system.NativeStart.main(Native Method)
[task 2018-08-30T10:35:18.743Z] 10:35:18     INFO -  org.mozilla.geckoview.test |
[task 2018-08-30T10:35:18.743Z] 10:35:18     INFO -  org.mozilla.geckoview.test | INSTRUMENTATION_STATUS: test=saveStateSync
[task 2018-08-30T10:35:18.744Z] 10:35:18     INFO -  org.mozilla.geckoview.test | INSTRUMENTATION_STATUS_CODE: -2
[task 2018-08-30T10:35:18.744Z] 10:35:18  WARNING -  TEST-UNEXPECTED-FAIL | org.mozilla.geckoview.test.ContentDelegateTest.saveStateSync | status -2
and
Error in saveAndRestoreState(org.mozilla.geckoview.test.ContentDelegateTest):
[task 2018-08-30T10:56:58.482Z] 10:56:58     INFO -  org.mozilla.geckoview.test | java.lang.RuntimeException: java.lang.Exception: shistoryInternal.GetTransactionAtIndex is not a function
[task 2018-08-30T10:56:58.483Z] 10:56:58     INFO -  org.mozilla.geckoview.test | 	at org.mozilla.geckoview.test.rule.GeckoSessionTestRule.unwrapRuntimeException(GeckoSessionTestRule.java:1094)
[task 2018-08-30T10:56:58.484Z] 10:56:58     INFO -  org.mozilla.geckoview.test | 	at org.mozilla.geckoview.test.rule.GeckoSessionTestRule.waitForResult(GeckoSessionTestRule.java:2342)
[task 2018-08-30T10:56:58.485Z] 10:56:58     INFO -  org.mozilla.geckoview.test | 	at org.mozilla.geckoview.test.ContentDelegateTest.saveAndRestoreState(ContentDelegateTest.kt:146)
[task 2018-08-30T10:56:58.486Z] 10:56:58     INFO -  org.mozilla.geckoview.test | 	at java.lang.reflect.Method.invokeNative(Native Method)
[task 2018-08-30T10:56:58.486Z] 10:56:58     INFO -  org.mozilla.geckoview.test | 	at java.lang.reflect.Method.invoke(Method.java:525)
[task 2018-08-30T10:56:58.487Z] 10:56:58     INFO -  org.mozilla.geckoview.test | 	at org.junit.runners.model.FrameworkMethod$1.runReflectiveCall(FrameworkMethod.java:50)
[task 2018-08-30T10:56:58.488Z] 10:56:58     INFO -  org.mozilla.geckoview.test | 	at org.junit.internal.runners.model.ReflectiveCallable.run(ReflectiveCallable.java:12)
[task 2018-08-30T10:56:58.488Z] 10:56:58     INFO -  org.mozilla.geckoview.test | 	at org.junit.runners.model.FrameworkMethod.invokeExplosively(FrameworkMethod.java:47)
[task 2018-08-30T10:56:58.489Z] 10:56:58     INFO -  org.mozilla.geckoview.test | 	at org.junit.internal.runners.statements.InvokeMethod.evaluate(InvokeMethod.java:17)
[task 2018-08-30T10:56:58.490Z] 10:56:58     INFO -  org.mozilla.geckoview.test | 	at org.mozilla.geckoview.test.rule.GeckoSessionTestRule$4$1.run(GeckoSessionTestRule.java:1486)
[task 2018-08-30T10:56:58.490Z] 10:56:58     INFO -  org.mozilla.geckoview.test | 	at android.app.Instrumentation$SyncRunnable.run(Instrumentation.java:1719)
[task 2018-08-30T10:56:58.491Z] 10:56:58     INFO -  org.mozilla.geckoview.test | 	at android.os.Handler.handleCallback(Handler.java:730)
[task 2018-08-30T10:56:58.493Z] 10:56:58     INFO -  org.mozilla.geckoview.test | 	at android.os.Handler.dispatchMessage(Handler.java:92)
[task 2018-08-30T10:56:58.494Z] 10:56:58     INFO -  org.mozilla.geckoview.test | 	at android.os.Looper.loop(Looper.java:137)
[task 2018-08-30T10:56:58.494Z] 10:56:58     INFO -  org.mozilla.geckoview.test | 	at android.app.ActivityThread.main(ActivityThread.java:5103)
[task 2018-08-30T10:56:58.494Z] 10:56:58     INFO -  org.mozilla.geckoview.test | 	at java.lang.reflect.Method.invokeNative(Native Method)
[task 2018-08-30T10:56:58.494Z] 10:56:58     INFO -  org.mozilla.geckoview.test | 	at java.lang.reflect.Method.invoke(Method.java:525)
[task 2018-08-30T10:56:58.494Z] 10:56:58     INFO -  org.mozilla.geckoview.test | 	at com.android.internal.os.ZygoteInit$MethodAndArgsCaller.run(ZygoteInit.java:737)
[task 2018-08-30T10:56:58.494Z] 10:56:58     INFO -  org.mozilla.geckoview.test | 	at com.android.internal.os.ZygoteInit.main(ZygoteInit.java:553)
[task 2018-08-30T10:56:58.494Z] 10:56:58     INFO -  org.mozilla.geckoview.test | 	at dalvik.system.NativeStart.main(Native Method)
[task 2018-08-30T10:56:58.494Z] 10:56:58     INFO -  org.mozilla.geckoview.test | Caused by: java.lang.Exception: shistoryInternal.GetTransactionAtIndex is not a function
[task 2018-08-30T10:56:58.494Z] 10:56:58     INFO -  org.mozilla.geckoview.test | 	at org.mozilla.geckoview.GeckoSession$CallbackResult.sendError(GeckoSession.java:108)
[task 2018-08-30T10:56:58.494Z] 10:56:58     INFO -  org.mozilla.geckoview.test | 	at org.mozilla.gecko.EventDispatcher$JavaCallbackDelegate$1.run(EventDispatcher.java:437)
[task 2018-08-30T10:56:58.495Z] 10:56:58     INFO -  org.mozilla.geckoview.test | 	at android.os.Handler.handleCallback(Handler.java:730)
[task 2018-08-30T10:56:58.495Z] 10:56:58     INFO -  org.mozilla.geckoview.test | 	at android.os.Handler.dispatchMessage(Handler.java:92)
[task 2018-08-30T10:56:58.495Z] 10:56:58     INFO -  org.mozilla.geckoview.test | 	at org.mozilla.geckoview.test.util.UiThreadUtils.loopUntilIdle(UiThreadUtils.java:100)
[task 2018-08-30T10:56:58.495Z] 10:56:58     INFO -  org.mozilla.geckoview.test | 	at org.mozilla.geckoview.test.rule.GeckoSessionTestRule.waitForResult(GeckoSessionTestRule.java:2335)
[task 2018-08-30T10:56:58.496Z] 10:56:58     INFO -  org.mozilla.geckoview.test | 	... 18 more
[task 2018-08-30T10:56:58.496Z] 10:56:58     INFO -  org.mozilla.geckoview.test |
[task 2018-08-30T10:56:58.496Z] 10:56:58     INFO -  org.mozilla.geckoview.test | INSTRUMENTATION_STATUS: numtests=89
[task 2018-08-30T10:56:58.496Z] 10:56:58     INFO -  org.mozilla.geckoview.test | INSTRUMENTATION_STATUS: stack=java.lang.RuntimeException: java.lang.Exception: shistoryInternal.GetTransactionAtIndex is not a function
[task 2018-08-30T10:56:58.496Z] 10:56:58     INFO -  org.mozilla.geckoview.test | 	at org.mozilla.geckoview.test.rule.GeckoSessionTestRule.unwrapRuntimeException(GeckoSessionTestRule.java:1094)
[task 2018-08-30T10:56:58.497Z] 10:56:58     INFO -  org.mozilla.geckoview.test | 	at org.mozilla.geckoview.test.rule.GeckoSessionTestRule.waitForResult(GeckoSessionTestRule.java:2342)
[task 2018-08-30T10:56:58.497Z] 10:56:58     INFO -  org.mozilla.geckoview.test | 	at org.mozilla.geckoview.test.ContentDelegateTest.saveAndRestoreState(ContentDelegateTest.kt:146)
[task 2018-08-30T10:56:58.497Z] 10:56:58     INFO -  org.mozilla.geckoview.test | 	at java.lang.reflect.Method.invokeNative(Native Method)
[task 2018-08-30T10:56:58.497Z] 10:56:58     INFO -  org.mozilla.geckoview.test | 	at java.lang.reflect.Method.invoke(Method.java:525)
[task 2018-08-30T10:56:58.497Z] 10:56:58     INFO -  org.mozilla.geckoview.test | 	at org.junit.runners.model.FrameworkMethod$1.runReflectiveCall(FrameworkMethod.java:50)
[task 2018-08-30T10:56:58.497Z] 10:56:58     INFO -  org.mozilla.geckoview.test | 	at org.junit.internal.runners.model.ReflectiveCallable.run(ReflectiveCallable.java:12)
[task 2018-08-30T10:56:58.498Z] 10:56:58     INFO -  org.mozilla.geckoview.test | 	at org.junit.runners.model.FrameworkMethod.invokeExplosively(FrameworkMethod.java:47)
[task 2018-08-30T10:56:58.499Z] 10:56:58     INFO -  org.mozilla.geckoview.test | 	at org.junit.internal.runners.statements.InvokeMethod.evaluate(InvokeMethod.java:17)
[task 2018-08-30T10:56:58.499Z] 10:56:58     INFO -  org.mozilla.geckoview.test | 	at org.mozilla.geckoview.test.rule.GeckoSessionTestRule$4$1.run(GeckoSessionTestRule.java:1486)
[task 2018-08-30T10:56:58.500Z] 10:56:58     INFO -  org.mozilla.geckoview.test | 	at android.app.Instrumentation$SyncRunnable.run(Instrumentation.java:1719)
[task 2018-08-30T10:56:58.500Z] 10:56:58     INFO -  org.mozilla.geckoview.test | 	at android.os.Handler.handleCallback(Handler.java:730)
[task 2018-08-30T10:56:58.501Z] 10:56:58     INFO -  org.mozilla.geckoview.test | 	at android.os.Handler.dispatchMessage(Handler.java:92)
[task 2018-08-30T10:56:58.502Z] 10:56:58     INFO -  org.mozilla.geckoview.test | 	at android.os.Looper.loop(Looper.java:137)
[task 2018-08-30T10:56:58.502Z] 10:56:58     INFO -  org.mozilla.geckoview.test | 	at android.app.ActivityThread.main(ActivityThread.java:5103)
[task 2018-08-30T10:56:58.502Z] 10:56:58     INFO -  org.mozilla.geckoview.test | 	at java.lang.reflect.Method.invokeNative(Native Method)
[task 2018-08-30T10:56:58.503Z] 10:56:58     INFO -  org.mozilla.geckoview.test | 	at java.lang.reflect.Method.invoke(Method.java:525)
[task 2018-08-30T10:56:58.503Z] 10:56:58     INFO -  org.mozilla.geckoview.test | 	at com.android.internal.os.ZygoteInit$MethodAndArgsCaller.run(ZygoteInit.java:737)
[task 2018-08-30T10:56:58.503Z] 10:56:58     INFO -  org.mozilla.geckoview.test | 	at com.android.internal.os.ZygoteInit.main(ZygoteInit.java:553)
[task 2018-08-30T10:56:58.504Z] 10:56:58     INFO -  org.mozilla.geckoview.test | 	at dalvik.system.NativeStart.main(Native Method)
[task 2018-08-30T10:56:58.504Z] 10:56:58     INFO -  org.mozilla.geckoview.test | Caused by: java.lang.Exception: shistoryInternal.GetTransactionAtIndex is not a function
[task 2018-08-30T10:56:58.504Z] 10:56:58     INFO -  org.mozilla.geckoview.test | 	at org.mozilla.geckoview.GeckoSession$CallbackResult.sendError(GeckoSession.java:108)
[task 2018-08-30T10:56:58.505Z] 10:56:58     INFO -  org.mozilla.geckoview.test | 	at org.mozilla.gecko.EventDispatcher$JavaCallbackDelegate$1.run(EventDispatcher.java:437)
[task 2018-08-30T10:56:58.505Z] 10:56:58     INFO -  org.mozilla.geckoview.test | 	at android.os.Handler.handleCallback(Handler.java:730)
[task 2018-08-30T10:56:58.506Z] 10:56:58     INFO -  org.mozilla.geckoview.test | 	at android.os.Handler.dispatchMessage(Handler.java:92)
[task 2018-08-30T10:56:58.506Z] 10:56:58     INFO -  org.mozilla.geckoview.test | 	at org.mozilla.geckoview.test.util.UiThreadUtils.loopUntilIdle(UiThreadUtils.java:100)
[task 2018-08-30T10:56:58.506Z] 10:56:58     INFO -  org.mozilla.geckoview.test | 	at org.mozilla.geckoview.test.rule.GeckoSessionTestRule.waitForResult(GeckoSessionTestRule.java:2335)
[task 2018-08-30T10:56:58.507Z] 10:56:58     INFO -  org.mozilla.geckoview.test | 	... 18 more
[task 2018-08-30T10:56:58.507Z] 10:56:58     INFO -  org.mozilla.geckoview.test |
[task 2018-08-30T10:56:58.507Z] 10:56:58     INFO -  org.mozilla.geckoview.test | INSTRUMENTATION_STATUS: test=saveAndRestoreState
[task 2018-08-30T10:56:58.508Z] 10:56:58     INFO -  org.mozilla.geckoview.test | INSTRUMENTATION_STATUS_CODE: -2
[task 2018-08-30T10:56:58.509Z] 10:56:58  WARNING -  TEST-UNEXPECTED-FAIL | org.mozilla.geckoview.test.ContentDelegateTest.saveAndRestoreState | status -2

Comment 1

[Eliza Balazs [:ebalazs_]]

In the next push are green: https://treeherder.mozilla.org/#/jobs?repo=mozilla-central&filter-resultStatus=testfailed&filter-resultStatus=busted&filter-resultStatus=exception&filter-resultStatus=runnable&filter-resultStatus=success&filter-searchStr=android%204.3%20api16%2B%20ccov%20debug%20test-android-em-4.3-arm7-api-16-ccov%2Fdebug-geckoview-junit&selectedJob=196609993

Comment 2

[Intermittent Failures Robot]

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

Repository breakdown:
* mozilla-central: 7

Platform breakdown:
* android-em-4-3-armv7-api16-ccov: 7

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

Comment 3

[Intermittent Failures Robot]

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

Repository breakdown:
* mozilla-central: 12

Platform breakdown:
* android-em-4-3-armv7-api16-ccov: 12

For more details, see:
https://treeherder.mozilla.org/intermittent-failures.html#/bugdetails?bug=1487361&startday=2018-09-03&endday=2018-09-09&tree=all

Comment 4

[Intermittent Failures Robot]

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

Repository breakdown:
* mozilla-central: 1

Platform breakdown:
* android-em-4-3-armv7-api16-ccov: 1

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

Comment 5

[Firefox Bug Husbandry Bot]

https://wiki.mozilla.org/Bug_Triage#Intermittent_Test_Failure_Cleanup