Intermittent geckoview exceptions on Android with errors such as TEST-UNEXPECTED-FAIL | org.mozilla.geckoview.test.AccessibilityTest.testMoveByCharacter | status -2

REOPENED
Unassigned

Status

defect
P3
normal
REOPENED
9 months ago
2 days ago

People

(Reporter: nataliaCs, Unassigned)

Tracking

(Blocks 1 bug, {intermittent-failure})

unspecified
Unspecified
Android
Dependency tree / graph

Firefox Tracking Flags

(firefox63 affected, firefox66 wontfix, firefox67 fix-optional, firefox68 affected)

Details

(Reporter)

Description

9 months ago
Push with failures: https://treeherder.mozilla.org/#/jobs?repo=mozilla-central&revision=17116905bc072c37d74226ccc46c93f0bd45d516&group_state=expanded&selectedJob=192794708

Task logs: https://tools.taskcluster.net/groups/BpbR0zhTRc-gm_u7KHaMnw/tasks/X2WktrI2TOOYGLxo4b7BuQ/runs/6/logs/public%2Flogs%2Flive.log#L2449

Task details: https://tools.taskcluster.net/groups/BpbR0zhTRc-gm_u7KHaMnw/tasks/X2WktrI2TOOYGLxo4b7BuQ/details

Live log: https://taskcluster-artifacts.net/X2WktrI2TOOYGLxo4b7BuQ/6/public/logs/live_backing.log

[task 2018-08-08T15:01:32.633Z] 15:01:32     INFO -  TEST-START | org.mozilla.geckoview.test.AccessibilityTest.testMoveByCharacter
[task 2018-08-08T15:05:08.003Z] 15:05:08     INFO -  org.mozilla.geckoview.test | INSTRUMENTATION_STATUS: id=AndroidJUnitRunner
[task 2018-08-08T15:05:08.110Z] 15:05:08     INFO -  org.mozilla.geckoview.test |
[task 2018-08-08T15:05:08.110Z] 15:05:08     INFO -  org.mozilla.geckoview.test | INSTRUMENTATION_STATUS: current=3
[task 2018-08-08T15:05:08.110Z] 15:05:08     INFO -  org.mozilla.geckoview.test | INSTRUMENTATION_STATUS: class=org.mozilla.geckoview.test.AccessibilityTest
[task 2018-08-08T15:05:08.110Z] 15:05:08     INFO -  org.mozilla.geckoview.test | INSTRUMENTATION_STATUS: stream=
[task 2018-08-08T15:05:08.110Z] 15:05:08     INFO -  org.mozilla.geckoview.test | Error in testMoveByCharacter(org.mozilla.geckoview.test.AccessibilityTest):
[task 2018-08-08T15:05:08.110Z] 15:05:08     INFO -  org.mozilla.geckoview.test | org.mozilla.geckoview.test.util.UiThreadUtils$TimeoutException: Timed out after 120000ms
[task 2018-08-08T15:05:08.111Z] 15:05:08     INFO -  org.mozilla.geckoview.test | 	at org.mozilla.geckoview.test.util.UiThreadUtils$TimeoutRunnable.run(UiThreadUtils.java:48)
[task 2018-08-08T15:05:08.111Z] 15:05:08     INFO -  org.mozilla.geckoview.test | 	at android.os.Handler.handleCallback(Handler.java:730)
[task 2018-08-08T15:05:08.111Z] 15:05:08     INFO -  org.mozilla.geckoview.test | 	at android.os.Handler.dispatchMessage(Handler.java:92)
[task 2018-08-08T15:05:08.111Z] 15:05:08     INFO -  org.mozilla.geckoview.test | 	at org.mozilla.geckoview.test.util.UiThreadUtils.loopUntilIdle(UiThreadUtils.java:100)
[task 2018-08-08T15:05:08.111Z] 15:05:08     INFO -  org.mozilla.geckoview.test | 	at org.mozilla.geckoview.test.rule.GeckoSessionTestRule.waitUntilCalled(GeckoSessionTestRule.java:1735)
[task 2018-08-08T15:05:08.111Z] 15:05:08     INFO -  org.mozilla.geckoview.test | 	at org.mozilla.geckoview.test.rule.GeckoSessionTestRule.waitUntilCalled(GeckoSessionTestRule.java:1683)
[task 2018-08-08T15:05:08.111Z] 15:05:08     INFO -  org.mozilla.geckoview.test | 	at org.mozilla.geckoview.test.rule.GeckoSessionTestRule.waitUntilCalled(GeckoSessionTestRule.java:1636)
[task 2018-08-08T15:05:08.111Z] 15:05:08     INFO -  org.mozilla.geckoview.test | 	at org.mozilla.geckoview.test.AccessibilityTest.waitForInitialFocus(AccessibilityTest.kt:110)
[task 2018-08-08T15:05:08.112Z] 15:05:08     INFO -  org.mozilla.geckoview.test | 	at org.mozilla.geckoview.test.AccessibilityTest.testMoveByCharacter(AccessibilityTest.kt:294)
[task 2018-08-08T15:05:08.112Z] 15:05:08     INFO -  org.mozilla.geckoview.test | 	at java.lang.reflect.Method.invokeNative(Native Method)
[task 2018-08-08T15:05:08.113Z] 15:05:08     INFO -  org.mozilla.geckoview.test | 	at java.lang.reflect.Method.invoke(Method.java:525)
[task 2018-08-08T15:05:08.113Z] 15:05:08     INFO -  org.mozilla.geckoview.test | 	at org.junit.runners.model.FrameworkMethod$1.runReflectiveCall(FrameworkMethod.java:50)
[task 2018-08-08T15:05:08.113Z] 15:05:08     INFO -  org.mozilla.geckoview.test | 	at org.junit.internal.runners.model.ReflectiveCallable.run(ReflectiveCallable.java:12)
[task 2018-08-08T15:05:08.115Z] 15:05:08     INFO -  org.mozilla.geckoview.test | 	at org.junit.runners.model.FrameworkMethod.invokeExplosively(FrameworkMethod.java:47)
[task 2018-08-08T15:05:08.116Z] 15:05:08     INFO -  org.mozilla.geckoview.test | 	at org.junit.internal.runners.statements.InvokeMethod.evaluate(InvokeMethod.java:17)
[task 2018-08-08T15:05:08.117Z] 15:05:08     INFO -  org.mozilla.geckoview.test | 	at org.junit.internal.runners.statements.RunBefores.evaluate(RunBefores.java:26)
[task 2018-08-08T15:05:08.117Z] 15:05:08     INFO -  org.mozilla.geckoview.test | 	at org.junit.internal.runners.statements.RunAfters.evaluate(RunAfters.java:27)
[task 2018-08-08T15:05:08.118Z] 15:05:08     INFO -  org.mozilla.geckoview.test | 	at org.mozilla.geckoview.test.rule.GeckoSessionTestRule$4.evaluate(GeckoSessionTestRule.java:1486)
[task 2018-08-08T15:05:08.118Z] 15:05:08     INFO -  org.mozilla.geckoview.test | 	at android.support.test.internal.statement.UiThreadStatement$1.run(UiThreadStatement.java:44)
[task 2018-08-08T15:05:08.118Z] 15:05:08     INFO -  org.mozilla.geckoview.test | 	at android.app.Instrumentation$SyncRunnable.run(Instrumentation.java:1719)
[task 2018-08-08T15:05:08.119Z] 15:05:08     INFO -  org.mozilla.geckoview.test | 	at android.os.Handler.handleCallback(Handler.java:730)
[task 2018-08-08T15:05:08.119Z] 15:05:08     INFO -  org.mozilla.geckoview.test | 	at android.os.Handler.dispatchMessage(Handler.java:92)
[task 2018-08-08T15:05:08.120Z] 15:05:08     INFO -  org.mozilla.geckoview.test | 	at android.os.Looper.loop(Looper.java:137)
[task 2018-08-08T15:05:08.120Z] 15:05:08     INFO -  org.mozilla.geckoview.test | 	at android.app.ActivityThread.main(ActivityThread.java:5103)
[task 2018-08-08T15:05:08.121Z] 15:05:08     INFO -  org.mozilla.geckoview.test | 	at java.lang.reflect.Method.invokeNative(Native Method)
[task 2018-08-08T15:05:08.121Z] 15:05:08     INFO -  org.mozilla.geckoview.test | 	at java.lang.reflect.Method.invoke(Method.java:525)
[task 2018-08-08T15:05:08.121Z] 15:05:08     INFO -  org.mozilla.geckoview.test | 	at com.android.internal.os.ZygoteInit$MethodAndArgsCaller.run(ZygoteInit.java:737)
[task 2018-08-08T15:05:08.122Z] 15:05:08     INFO -  org.mozilla.geckoview.test | 	at com.android.internal.os.ZygoteInit.main(ZygoteInit.java:553)
[task 2018-08-08T15:05:08.122Z] 15:05:08     INFO -  org.mozilla.geckoview.test | 	at dalvik.system.NativeStart.main(Native Method)
[task 2018-08-08T15:05:08.123Z] 15:05:08     INFO -  org.mozilla.geckoview.test |
[task 2018-08-08T15:05:08.123Z] 15:05:08     INFO -  org.mozilla.geckoview.test | INSTRUMENTATION_STATUS: numtests=79
[task 2018-08-08T15:05:08.123Z] 15:05:08     INFO -  org.mozilla.geckoview.test | INSTRUMENTATION_STATUS: stack=org.mozilla.geckoview.test.util.UiThreadUtils$TimeoutException: Timed out after 120000ms
[task 2018-08-08T15:05:08.123Z] 15:05:08     INFO -  org.mozilla.geckoview.test | 	at org.mozilla.geckoview.test.util.UiThreadUtils$TimeoutRunnable.run(UiThreadUtils.java:48)
[task 2018-08-08T15:05:08.124Z] 15:05:08     INFO -  org.mozilla.geckoview.test | 	at android.os.Handler.handleCallback(Handler.java:730)
[task 2018-08-08T15:05:08.124Z] 15:05:08     INFO -  org.mozilla.geckoview.test | 	at android.os.Handler.dispatchMessage(Handler.java:92)
[task 2018-08-08T15:05:08.125Z] 15:05:08     INFO -  org.mozilla.geckoview.test | 	at org.mozilla.geckoview.test.util.UiThreadUtils.loopUntilIdle(UiThreadUtils.java:100)
[task 2018-08-08T15:05:08.125Z] 15:05:08     INFO -  org.mozilla.geckoview.test | 	at org.mozilla.geckoview.test.rule.GeckoSessionTestRule.waitUntilCalled(GeckoSessionTestRule.java:1735)
[task 2018-08-08T15:05:08.126Z] 15:05:08     INFO -  org.mozilla.geckoview.test | 	at org.mozilla.geckoview.test.rule.GeckoSessionTestRule.waitUntilCalled(GeckoSessionTestRule.java:1683)
[task 2018-08-08T15:05:08.126Z] 15:05:08     INFO -  org.mozilla.geckoview.test | 	at org.mozilla.geckoview.test.rule.GeckoSessionTestRule.waitUntilCalled(GeckoSessionTestRule.java:1636)
[task 2018-08-08T15:05:08.127Z] 15:05:08     INFO -  org.mozilla.geckoview.test | 	at org.mozilla.geckoview.test.AccessibilityTest.waitForInitialFocus(AccessibilityTest.kt:110)
[task 2018-08-08T15:05:08.127Z] 15:05:08     INFO -  org.mozilla.geckoview.test | 	at org.mozilla.geckoview.test.AccessibilityTest.testMoveByCharacter(AccessibilityTest.kt:294)
[task 2018-08-08T15:05:08.127Z] 15:05:08     INFO -  org.mozilla.geckoview.test | 	at java.lang.reflect.Method.invokeNative(Native Method)
[task 2018-08-08T15:05:08.128Z] 15:05:08     INFO -  org.mozilla.geckoview.test | 	at java.lang.reflect.Method.invoke(Method.java:525)
[task 2018-08-08T15:05:08.128Z] 15:05:08     INFO -  org.mozilla.geckoview.test | 	at org.junit.runners.model.FrameworkMethod$1.runReflectiveCall(FrameworkMethod.java:50)
[task 2018-08-08T15:05:08.129Z] 15:05:08     INFO -  org.mozilla.geckoview.test | 	at org.junit.internal.runners.model.ReflectiveCallable.run(ReflectiveCallable.java:12)
[task 2018-08-08T15:05:08.129Z] 15:05:08     INFO -  org.mozilla.geckoview.test | 	at org.junit.runners.model.FrameworkMethod.invokeExplosively(FrameworkMethod.java:47)
[task 2018-08-08T15:05:08.130Z] 15:05:08     INFO -  org.mozilla.geckoview.test | 	at org.junit.internal.runners.statements.InvokeMethod.evaluate(InvokeMethod.java:17)
[task 2018-08-08T15:05:08.131Z] 15:05:08     INFO -  org.mozilla.geckoview.test | 	at org.junit.internal.runners.statements.RunBefores.evaluate(RunBefores.java:26)
[task 2018-08-08T15:05:08.132Z] 15:05:08     INFO -  org.mozilla.geckoview.test | 	at org.junit.internal.runners.statements.RunAfters.evaluate(RunAfters.java:27)
[task 2018-08-08T15:05:08.132Z] 15:05:08     INFO -  org.mozilla.geckoview.test | 	at org.mozilla.geckoview.test.rule.GeckoSessionTestRule$4.evaluate(GeckoSessionTestRule.java:1486)
[task 2018-08-08T15:05:08.133Z] 15:05:08     INFO -  org.mozilla.geckoview.test | 	at android.support.test.internal.statement.UiThreadStatement$1.run(UiThreadStatement.java:44)
[task 2018-08-08T15:05:08.134Z] 15:05:08     INFO -  org.mozilla.geckoview.test | 	at android.app.Instrumentation$SyncRunnable.run(Instrumentation.java:1719)
[task 2018-08-08T15:05:08.135Z] 15:05:08     INFO -  org.mozilla.geckoview.test | 	at android.os.Handler.handleCallback(Handler.java:730)
[task 2018-08-08T15:05:08.136Z] 15:05:08     INFO -  org.mozilla.geckoview.test | 	at android.os.Handler.dispatchMessage(Handler.java:92)
[task 2018-08-08T15:05:08.137Z] 15:05:08     INFO -  org.mozilla.geckoview.test | 	at android.os.Looper.loop(Looper.java:137)
[task 2018-08-08T15:05:08.138Z] 15:05:08     INFO -  org.mozilla.geckoview.test | 	at android.app.ActivityThread.main(ActivityThread.java:5103)
[task 2018-08-08T15:05:08.139Z] 15:05:08     INFO -  org.mozilla.geckoview.test | 	at java.lang.reflect.Method.invokeNative(Native Method)
[task 2018-08-08T15:05:08.140Z] 15:05:08     INFO -  org.mozilla.geckoview.test | 	at java.lang.reflect.Method.invoke(Method.java:525)
[task 2018-08-08T15:05:08.141Z] 15:05:08     INFO -  org.mozilla.geckoview.test | 	at com.android.internal.os.ZygoteInit$MethodAndArgsCaller.run(ZygoteInit.java:737)
[task 2018-08-08T15:05:08.142Z] 15:05:08     INFO -  org.mozilla.geckoview.test | 	at com.android.internal.os.ZygoteInit.main(ZygoteInit.java:553)
[task 2018-08-08T15:05:08.143Z] 15:05:08     INFO -  org.mozilla.geckoview.test | 	at dalvik.system.NativeStart.main(Native Method)
[task 2018-08-08T15:05:08.144Z] 15:05:08     INFO -  org.mozilla.geckoview.test |
[task 2018-08-08T15:05:08.144Z] 15:05:08     INFO -  org.mozilla.geckoview.test | INSTRUMENTATION_STATUS: test=testMoveByCharacter
[task 2018-08-08T15:05:08.145Z] 15:05:08     INFO -  org.mozilla.geckoview.test | INSTRUMENTATION_STATUS_CODE: -2
[task 2018-08-08T15:05:08.145Z] 15:05:08  WARNING -  TEST-UNEXPECTED-FAIL | org.mozilla.geckoview.test.AccessibilityTest.testMoveByCharacter | status -2


@snorp, is there any chance you could take a look at these failures?
Could https://hg.mozilla.org/mozilla-central/rev/09871ad4c346 have triggered this?
(Reporter)

Updated

9 months ago
Flags: needinfo?(snorp)
Natalia do you know how often this intermittent fails?
Flags: needinfo?(ncsoregi)
P3 until we know how big a problem this is. Here is the full pushlog from comment 2. Could this be related to screen metrics bug 1475875?

https://hg.mozilla.org/mozilla-central/pushloghtml?changeset=17116905bc072c37d74226ccc46c93f0bd45d516
It looks like Gecko may be hung here. Geoff, can we make the harness send a SIGBART in cases like this?
Flags: needinfo?(snorp) → needinfo?(gbrown)
So far all such failures are on ccov -- recently added.
Blocks: 1473313
All failures were on one revision. So far 4 more recent revisions are all okay: Maybe nothing to worry about?
I should be able to abort on a particular logged string. Maybe "org.mozilla.geckoview.test.util.UiThreadUtils$TimeoutException"?
Assignee: nobody → gbrown
Flags: needinfo?(gbrown)
Comment hidden (Intermittent Failures Robot)
Priority: -- → P3
Flags: needinfo?(gbrown)
One of the more annoying aspects of this bugs is that the task retries, only to hit the same issue.

The task retry is caused by:

[task 2018-08-15T03:28:26.718Z] 03:28:26     INFO -  Traceback (most recent call last):
[task 2018-08-15T03:28:26.719Z] 03:28:26     INFO -    File "/builds/worker/workspace/build/tests/mochitest/runjunit.py", line 431, in run_test_harness
[task 2018-08-15T03:28:26.719Z] 03:28:26     INFO -      result = runner.run_tests(options.test_filters)
[task 2018-08-15T03:28:26.719Z] 03:28:26     INFO -    File "/builds/worker/workspace/build/tests/mochitest/runjunit.py", line 275, in run_tests
[task 2018-08-15T03:28:26.720Z] 03:28:26     INFO -      self.device.pull(self.remote_coverage_output_path, self.options.coverage_output_path)
[task 2018-08-15T03:28:26.720Z] 03:28:26     INFO -    File "/builds/worker/workspace/build/venv/lib/python2.7/site-packages/mozdevice/adb.py", line 1874, in pull
[task 2018-08-15T03:28:26.720Z] 03:28:26     INFO -      self.command_output(["pull", remote, local], timeout=timeout)
[task 2018-08-15T03:28:26.721Z] 03:28:26     INFO -    File "/builds/worker/workspace/build/venv/lib/python2.7/site-packages/mozdevice/adb.py", line 899, in command_output
[task 2018-08-15T03:28:26.723Z] 03:28:26     INFO -      timeout=timeout)
[task 2018-08-15T03:28:26.723Z] 03:28:26     INFO -    File "/builds/worker/workspace/build/venv/lib/python2.7/site-packages/mozdevice/adb.py", line 297, in command_output
[task 2018-08-15T03:28:26.723Z] 03:28:26 CRITICAL -      raise ADBProcessError(adb_process)
[task 2018-08-15T03:28:26.723Z] 03:28:26 CRITICAL -  ADBProcessError: args: adb -s emulator-5554 wait-for-device pull /sdcard/tests/junit-coverage.ec /tmp/tmp9gypwX/junit-coverage.ec, exitcode: 1, stdout: adb: error: remote object '/sdcard/tests/junit-coverage.ec' does not exist

We could catch that exception, or check for existence of the file before attempting a pull.
Depends on: 1483586
(In reply to Geoff Brown [:gbrown] from comment #10)
> We could catch that exception, or check for existence of the file before
> attempting a pull.

Filing bug 1483586 for that fix.

I've been looking over the build logs, test logs and logcats for failing and succeeding tasks. I have found nothing obvious. I'll try to reproduce this on the try server.
Thanks :tvijiala. Feel free to take this bug, especially if you are able to reproduce / think of a way to prevent the failure. 

For my part, I'll consider follow-up on comment 7, but first I'd like to see this fail again after bug 1483586 is resolved.
Comment hidden (Intermittent Failures Robot)
Comment hidden (Intermittent Failures Robot)
See Also: → 1485950
Duplicate of this bug: 1487510
Comment hidden (Intermittent Failures Robot)
We are no longer retrying (great!). We are no longer seeing the same exception (comment 4, comment 7), so I won't follow-up on those ideas.

However, infrequent failures continue, generally on ccov builds. When this failure is seen, retries of the test suite on the same build are perma-fail:

https://treeherder.mozilla.org/#/jobs?repo=mozilla-central&revision=09de350001f07965f787c19f298fd0cd6cd839fa&filter-searchStr=geckoview-junit

Recent failure:

https://treeherder.mozilla.org/logviewer.html#?job_id=196609986&repo=mozilla-central&lineNumber=1512-1579

[task 2018-08-30T10:21:28.615Z] 10:21:28     INFO -  org.mozilla.geckoview.test | INSTRUMENTATION_STATUS: class=org.mozilla.geckoview.test.ContentDelegateTest
[task 2018-08-30T10:21:28.616Z] 10:21:28     INFO -  org.mozilla.geckoview.test | INSTRUMENTATION_STATUS: stream=
[task 2018-08-30T10:21:28.618Z] 10:21:28     INFO -  org.mozilla.geckoview.test | Error in saveAndRestoreState(org.mozilla.geckoview.test.ContentDelegateTest):
[task 2018-08-30T10:21:28.619Z] 10:21:28     INFO -  org.mozilla.geckoview.test | java.lang.RuntimeException: java.lang.Exception: shistoryInternal.GetTransactionAtIndex is not a function
[task 2018-08-30T10:21:28.620Z] 10:21:28     INFO -  org.mozilla.geckoview.test | 	at org.mozilla.geckoview.test.rule.GeckoSessionTestRule.unwrapRuntimeException(GeckoSessionTestRule.java:1094)
[task 2018-08-30T10:21:28.622Z] 10:21:28     INFO -  org.mozilla.geckoview.test | 	at org.mozilla.geckoview.test.rule.GeckoSessionTestRule.waitForResult(GeckoSessionTestRule.java:2342)
[task 2018-08-30T10:21:28.622Z] 10:21:28     INFO -  org.mozilla.geckoview.test | 	at org.mozilla.geckoview.test.ContentDelegateTest.saveAndRestoreState(ContentDelegateTest.kt:146)
[task 2018-08-30T10:21:28.623Z] 10:21:28     INFO -  org.mozilla.geckoview.test | 	at java.lang.reflect.Method.invokeNative(Native Method)
[task 2018-08-30T10:21:28.623Z] 10:21:28     INFO -  org.mozilla.geckoview.test | 	at java.lang.reflect.Method.invoke(Method.java:525)
[task 2018-08-30T10:21:28.623Z] 10:21:28     INFO -  org.mozilla.geckoview.test | 	at org.junit.runners.model.FrameworkMethod$1.runReflectiveCall(FrameworkMethod.java:50)
[task 2018-08-30T10:21:28.623Z] 10:21:28     INFO -  org.mozilla.geckoview.test | 	at org.junit.internal.runners.model.ReflectiveCallable.run(ReflectiveCallable.java:12)
[task 2018-08-30T10:21:28.623Z] 10:21:28     INFO -  org.mozilla.geckoview.test | 	at org.junit.runners.model.FrameworkMethod.invokeExplosively(FrameworkMethod.java:47)
[task 2018-08-30T10:21:28.624Z] 10:21:28     INFO -  org.mozilla.geckoview.test | 	at org.junit.internal.runners.statements.InvokeMethod.evaluate(InvokeMethod.java:17)
[task 2018-08-30T10:21:28.624Z] 10:21:28     INFO -  org.mozilla.geckoview.test | 	at org.mozilla.geckoview.test.rule.GeckoSessionTestRule$4$1.run(GeckoSessionTestRule.java:1486)
[task 2018-08-30T10:21:28.624Z] 10:21:28     INFO -  org.mozilla.geckoview.test | 	at android.app.Instrumentation$SyncRunnable.run(Instrumentation.java:1719)
[task 2018-08-30T10:21:28.624Z] 10:21:28     INFO -  org.mozilla.geckoview.test | 	at android.os.Handler.handleCallback(Handler.java:730)
[task 2018-08-30T10:21:28.625Z] 10:21:28     INFO -  org.mozilla.geckoview.test | 	at android.os.Handler.dispatchMessage(Handler.java:92)
[task 2018-08-30T10:21:28.625Z] 10:21:28     INFO -  org.mozilla.geckoview.test | 	at android.os.Looper.loop(Looper.java:137)
[task 2018-08-30T10:21:28.626Z] 10:21:28     INFO -  org.mozilla.geckoview.test | 	at android.app.ActivityThread.main(ActivityThread.java:5103)
[task 2018-08-30T10:21:28.626Z] 10:21:28     INFO -  org.mozilla.geckoview.test | 	at java.lang.reflect.Method.invokeNative(Native Method)
[task 2018-08-30T10:21:28.626Z] 10:21:28     INFO -  org.mozilla.geckoview.test | 	at java.lang.reflect.Method.invoke(Method.java:525)
[task 2018-08-30T10:21:28.627Z] 10:21:28     INFO -  org.mozilla.geckoview.test | 	at com.android.internal.os.ZygoteInit$MethodAndArgsCaller.run(ZygoteInit.java:737)
[task 2018-08-30T10:21:28.627Z] 10:21:28     INFO -  org.mozilla.geckoview.test | 	at com.android.internal.os.ZygoteInit.main(ZygoteInit.java:553)
[task 2018-08-30T10:21:28.627Z] 10:21:28     INFO -  org.mozilla.geckoview.test | 	at dalvik.system.NativeStart.main(Native Method)
[task 2018-08-30T10:21:28.628Z] 10:21:28     INFO -  org.mozilla.geckoview.test | Caused by: java.lang.Exception: shistoryInternal.GetTransactionAtIndex is not a function
[task 2018-08-30T10:21:28.628Z] 10:21:28     INFO -  org.mozilla.geckoview.test | 	at org.mozilla.geckoview.GeckoSession$CallbackResult.sendError(GeckoSession.java:108)
[task 2018-08-30T10:21:28.628Z] 10:21:28     INFO -  org.mozilla.geckoview.test | 	at org.mozilla.gecko.EventDispatcher$JavaCallbackDelegate$1.run(EventDispatcher.java:437)
[task 2018-08-30T10:21:28.628Z] 10:21:28     INFO -  org.mozilla.geckoview.test | 	at android.os.Handler.handleCallback(Handler.java:730)
[task 2018-08-30T10:21:28.629Z] 10:21:28     INFO -  org.mozilla.geckoview.test | 	at android.os.Handler.dispatchMessage(Handler.java:92)
[task 2018-08-30T10:21:28.629Z] 10:21:28     INFO -  org.mozilla.geckoview.test | 	at org.mozilla.geckoview.test.util.UiThreadUtils.loopUntilIdle(UiThreadUtils.java:100)
[task 2018-08-30T10:21:28.629Z] 10:21:28     INFO -  org.mozilla.geckoview.test | 	at org.mozilla.geckoview.test.rule.GeckoSessionTestRule.waitForResult(GeckoSessionTestRule.java:2335)
[task 2018-08-30T10:21:28.629Z] 10:21:28     INFO -  org.mozilla.geckoview.test | 	... 18 more
[task 2018-08-30T10:21:28.629Z] 10:21:28     INFO -  org.mozilla.geckoview.test |
[task 2018-08-30T10:21:28.630Z] 10:21:28     INFO -  org.mozilla.geckoview.test | INSTRUMENTATION_STATUS: numtests=89
[task 2018-08-30T10:21:28.630Z] 10:21:28     INFO -  org.mozilla.geckoview.test | INSTRUMENTATION_STATUS: stack=java.lang.RuntimeException: java.lang.Exception: shistoryInternal.GetTransactionAtIndex is not a function
[task 2018-08-30T10:21:28.630Z] 10:21:28     INFO -  org.mozilla.geckoview.test | 	at org.mozilla.geckoview.test.rule.GeckoSessionTestRule.unwrapRuntimeException(GeckoSessionTestRule.java:1094)
[task 2018-08-30T10:21:28.630Z] 10:21:28     INFO -  org.mozilla.geckoview.test | 	at org.mozilla.geckoview.test.rule.GeckoSessionTestRule.waitForResult(GeckoSessionTestRule.java:2342)
[task 2018-08-30T10:21:28.630Z] 10:21:28     INFO -  org.mozilla.geckoview.test | 	at org.mozilla.geckoview.test.ContentDelegateTest.saveAndRestoreState(ContentDelegateTest.kt:146)
[task 2018-08-30T10:21:28.631Z] 10:21:28     INFO -  org.mozilla.geckoview.test | 	at java.lang.reflect.Method.invokeNative(Native Method)
[task 2018-08-30T10:21:28.631Z] 10:21:28     INFO -  org.mozilla.geckoview.test | 	at java.lang.reflect.Method.invoke(Method.java:525)
[task 2018-08-30T10:21:28.632Z] 10:21:28     INFO -  org.mozilla.geckoview.test | 	at org.junit.runners.model.FrameworkMethod$1.runReflectiveCall(FrameworkMethod.java:50)
[task 2018-08-30T10:21:28.633Z] 10:21:28     INFO -  org.mozilla.geckoview.test | 	at org.junit.internal.runners.model.ReflectiveCallable.run(ReflectiveCallable.java:12)
[task 2018-08-30T10:21:28.633Z] 10:21:28     INFO -  org.mozilla.geckoview.test | 	at org.junit.runners.model.FrameworkMethod.invokeExplosively(FrameworkMethod.java:47)
[task 2018-08-30T10:21:28.634Z] 10:21:28     INFO -  org.mozilla.geckoview.test | 	at org.junit.internal.runners.statements.InvokeMethod.evaluate(InvokeMethod.java:17)
[task 2018-08-30T10:21:28.634Z] 10:21:28     INFO -  org.mozilla.geckoview.test | 	at org.mozilla.geckoview.test.rule.GeckoSessionTestRule$4$1.run(GeckoSessionTestRule.java:1486)
[task 2018-08-30T10:21:28.635Z] 10:21:28     INFO -  org.mozilla.geckoview.test | 	at android.app.Instrumentation$SyncRunnable.run(Instrumentation.java:1719)
[task 2018-08-30T10:21:28.635Z] 10:21:28     INFO -  org.mozilla.geckoview.test | 	at android.os.Handler.handleCallback(Handler.java:730)
[task 2018-08-30T10:21:28.636Z] 10:21:28     INFO -  org.mozilla.geckoview.test | 	at android.os.Handler.dispatchMessage(Handler.java:92)
[task 2018-08-30T10:21:28.636Z] 10:21:28     INFO -  org.mozilla.geckoview.test | 	at android.os.Looper.loop(Looper.java:137)
[task 2018-08-30T10:21:28.637Z] 10:21:28     INFO -  org.mozilla.geckoview.test | 	at android.app.ActivityThread.main(ActivityThread.java:5103)
[task 2018-08-30T10:21:28.637Z] 10:21:28     INFO -  org.mozilla.geckoview.test | 	at java.lang.reflect.Method.invokeNative(Native Method)
[task 2018-08-30T10:21:28.638Z] 10:21:28     INFO -  org.mozilla.geckoview.test | 	at java.lang.reflect.Method.invoke(Method.java:525)
[task 2018-08-30T10:21:28.638Z] 10:21:28     INFO -  org.mozilla.geckoview.test | 	at com.android.internal.os.ZygoteInit$MethodAndArgsCaller.run(ZygoteInit.java:737)
[task 2018-08-30T10:21:28.638Z] 10:21:28     INFO -  org.mozilla.geckoview.test | 	at com.android.internal.os.ZygoteInit.main(ZygoteInit.java:553)
[task 2018-08-30T10:21:28.639Z] 10:21:28     INFO -  org.mozilla.geckoview.test | 	at dalvik.system.NativeStart.main(Native Method)
[task 2018-08-30T10:21:28.640Z] 10:21:28     INFO -  org.mozilla.geckoview.test | Caused by: java.lang.Exception: shistoryInternal.GetTransactionAtIndex is not a function
[task 2018-08-30T10:21:28.640Z] 10:21:28     INFO -  org.mozilla.geckoview.test | 	at org.mozilla.geckoview.GeckoSession$CallbackResult.sendError(GeckoSession.java:108)
[task 2018-08-30T10:21:28.640Z] 10:21:28     INFO -  org.mozilla.geckoview.test | 	at org.mozilla.gecko.EventDispatcher$JavaCallbackDelegate$1.run(EventDispatcher.java:437)
[task 2018-08-30T10:21:28.641Z] 10:21:28     INFO -  org.mozilla.geckoview.test | 	at android.os.Handler.handleCallback(Handler.java:730)
[task 2018-08-30T10:21:28.641Z] 10:21:28     INFO -  org.mozilla.geckoview.test | 	at android.os.Handler.dispatchMessage(Handler.java:92)
[task 2018-08-30T10:21:28.642Z] 10:21:28     INFO -  org.mozilla.geckoview.test | 	at org.mozilla.geckoview.test.util.UiThreadUtils.loopUntilIdle(UiThreadUtils.java:100)
[task 2018-08-30T10:21:28.643Z] 10:21:28     INFO -  org.mozilla.geckoview.test | 	at org.mozilla.geckoview.test.rule.GeckoSessionTestRule.waitForResult(GeckoSessionTestRule.java:2335)
[task 2018-08-30T10:21:28.643Z] 10:21:28     INFO -  org.mozilla.geckoview.test | 	... 18 more
[task 2018-08-30T10:21:28.644Z] 10:21:28     INFO -  org.mozilla.geckoview.test |
[task 2018-08-30T10:21:28.644Z] 10:21:28     INFO -  org.mozilla.geckoview.test | INSTRUMENTATION_STATUS: test=saveAndRestoreState
[task 2018-08-30T10:21:28.644Z] 10:21:28     INFO -  org.mozilla.geckoview.test | INSTRUMENTATION_STATUS_CODE: -2
[task 2018-08-30T10:21:28.644Z] 10:21:28  WARNING -  TEST-UNEXPECTED-FAIL | org.mozilla.geckoview.test.ContentDelegateTest.saveAndRestoreState | status -2
[task 2018-08-30T10:21:28.645Z] 10:21:28     INFO -  TEST-INFO took 7228ms


https://taskcluster-artifacts.net/FcmvynKUQCWqSz-L6bWo3A/0/public/test_info//logcat-emulator-5554.log

08-30 03:21:26.247   738   755 D GeckoViewProgress: onStateChange: isTopLevel=true, flags=0xc0010, status=NS_OK loadType=1
08-30 03:21:26.257   738   755 D GeckoViewProgress: onStateChange: uri=jar:file:///data/app/org.mozilla.geckoview.test-1.apk!/assets/www/saveState.html isSuccess=true isStart=false isStop=true
08-30 03:21:26.977   738   755 D GeckoViewModule: dispatch GeckoView:SaveState, data=null
08-30 03:21:27.007   783   796 D GeckoViewScroll[C]: handleEvent: scroll
08-30 03:21:27.427   738   755 D GeckoViewContent: onEvent: event=GeckoView:SaveState, data=null
08-30 03:21:27.578   783   796 D GeckoViewContent[C]: receiveMessage: GeckoView:SaveState
08-30 03:21:27.727   738   755 D GeckoViewContent: receiveMessage: GeckoView:SaveStateFinish
08-30 03:21:28.147   738   751 I TestRunner: failed: saveAndRestoreState(org.mozilla.geckoview.test.ContentDelegateTest)
08-30 03:21:28.147   738   751 I TestRunner: ----- begin exception -----
08-30 03:21:28.187   738   751 I TestRunner: java.lang.RuntimeException: java.lang.Exception: shistoryInternal.GetTransactionAtIndex is not a function
08-30 03:21:28.187   738   751 I TestRunner: 	at org.mozilla.geckoview.test.rule.GeckoSessionTestRule.unwrapRuntimeException(GeckoSessionTestRule.java:1094)
08-30 03:21:28.187   738   751 I TestRunner: 	at org.mozilla.geckoview.test.rule.GeckoSessionTestRule.waitForResult(GeckoSessionTestRule.java:2342)
08-30 03:21:28.187   738   751 I TestRunner: 	at org.mozilla.geckoview.test.ContentDelegateTest.saveAndRestoreState(ContentDelegateTest.kt:146)
08-30 03:21:28.187   738   751 I TestRunner: 	at java.lang.reflect.Method.invokeNative(Native Method)
08-30 03:21:28.187   738   751 I TestRunner: 	at java.lang.reflect.Method.invoke(Method.java:525)
08-30 03:21:28.187   738   751 I TestRunner: 	at org.junit.runners.model.FrameworkMethod$1.runReflectiveCall(FrameworkMethod.java:50)
08-30 03:21:28.187   738   751 I TestRunner: 	at org.junit.internal.runners.model.ReflectiveCallable.run(ReflectiveCallable.java:12)
08-30 03:21:28.187   738   751 I TestRunner: 	at org.junit.runners.model.FrameworkMethod.invokeExplosively(FrameworkMethod.java:47)
08-30 03:21:28.187   738   751 I TestRunner: 	at org.junit.internal.runners.statements.InvokeMethod.evaluate(InvokeMethod.java:17)
08-30 03:21:28.187   738   751 I TestRunner: 	at org.mozilla.geckoview.test.rule.GeckoSessionTestRule$4$1.run(GeckoSessionTestRule.java:1486)
08-30 03:21:28.187   738   751 I TestRunner: 	at android.app.Instrumentation$SyncRunnable.run(Instrumentation.java:1719)
08-30 03:21:28.187   738   751 I TestRunner: 	at android.os.Handler.handleCallback(Handler.java:730)
08-30 03:21:28.187   738   751 I TestRunner: 	at android.os.Handler.dispatchMessage(Handler.java:92)
08-30 03:21:28.187   738   751 I TestRunner: 	at android.os.Looper.loop(Looper.java:137)
08-30 03:21:28.187   738   751 I TestRunner: 	at android.app.ActivityThread.main(ActivityThread.java:5103)
08-30 03:21:28.187   738   751 I TestRunner: 	at java.lang.reflect.Method.invokeNative(Native Method)
08-30 03:21:28.187   738   751 I TestRunner: 	at java.lang.reflect.Method.invoke(Method.java:525)
08-30 03:21:28.187   738   751 I TestRunner: 	at com.android.internal.os.ZygoteInit$MethodAndArgsCaller.run(ZygoteInit.java:737)
08-30 03:21:28.187   738   751 I TestRunner: 	at com.android.internal.os.ZygoteInit.main(ZygoteInit.java:553)
08-30 03:21:28.187   738   751 I TestRunner: 	at dalvik.system.NativeStart.main(Native Method)
08-30 03:21:28.187   738   751 I TestRunner: Caused by: java.lang.Exception: shistoryInternal.GetTransactionAtIndex is not a function
08-30 03:21:28.187   738   751 I TestRunner: 	at org.mozilla.geckoview.GeckoSession$CallbackResult.sendError(GeckoSession.java:108)
08-30 03:21:28.187   738   751 I TestRunner: 	at org.mozilla.gecko.EventDispatcher$JavaCallbackDelegate$1.run(EventDispatcher.java:437)
08-30 03:21:28.187   738   751 I TestRunner: 	at android.os.Handler.handleCallback(Handler.java:730)
08-30 03:21:28.187   738   751 I TestRunner: 	at android.os.Handler.dispatchMessage(Handler.java:92)
08-30 03:21:28.187   738   751 I TestRunner: 	at org.mozilla.geckoview.test.util.UiThreadUtils.loopUntilIdle(UiThreadUtils.java:100)
08-30 03:21:28.187   738   751 I TestRunner: 	at org.mozilla.geckoview.test.rule.GeckoSessionTestRule.waitForResult(GeckoSessionTestRule.java:2335)
08-30 03:21:28.187   738   751 I TestRunner: 	... 18 more
08-30 03:21:28.187   738   751 I TestRunner: ----- end exception -----
08-30 03:21:28.207   738   751 I TestRunner: finished: saveAndRestoreState(org.mozilla.geckoview.test.ContentDelegateTest)


:jchen -- Can you have a look?
Assignee: gbrown → nobody
Flags: needinfo?(nchen)
> java.lang.RuntimeException: java.lang.Exception: shistoryInternal.GetTransactionAtIndex is not a function

"shistoryInternal.GetTransactionAtIndex" was recently removed by bug 1487296. I wonder if we are running into stale caches or (more likely) stale artifact builds.
Flags: needinfo?(nchen)
Comment hidden (Intermittent Failures Robot)
Comment hidden (Intermittent Failures Robot)
Comment hidden (Intermittent Failures Robot)

Updated

4 months ago
Product: Firefox for Android → GeckoView
OS: Unspecified → Android

No failures since 2018.

Assignee: nobody → gbrown
Status: NEW → RESOLVED
Last Resolved: 2 months ago
Resolution: --- → WORKSFORME

This reoccurred here: https://treeherder.mozilla.org/logviewer.html#/jobs?job_id=235111215&repo=autoland&lineNumber=1530

[task 2019-03-21T02:53:16.597Z] 02:53:16 INFO - org.mozilla.geckoview.test | INSTRUMENTATION_STATUS: numtests=68
[task 2019-03-21T02:53:16.597Z] 02:53:16 INFO - org.mozilla.geckoview.test | INSTRUMENTATION_STATUS: stack=org.mozilla.geckoview.test.util.UiThreadUtils$TimeoutException: Timed out after 120000ms
[task 2019-03-21T02:53:16.597Z] 02:53:16 INFO - org.mozilla.geckoview.test | at org.mozilla.geckoview.test.util.UiThreadUtils$TimeoutRunnable.run(UiThreadUtils.java:56)
[task 2019-03-21T02:53:16.597Z] 02:53:16 INFO - org.mozilla.geckoview.test | at android.os.Handler.handleCallback(Handler.java:730)
[task 2019-03-21T02:53:16.597Z] 02:53:16 INFO - org.mozilla.geckoview.test | at android.os.Handler.dispatchMessage(Handler.java:92)
[task 2019-03-21T02:53:16.597Z] 02:53:16 INFO - org.mozilla.geckoview.test | at org.mozilla.geckoview.test.util.UiThreadUtils.loopUntilIdle(UiThreadUtils.java:154)
[task 2019-03-21T02:53:16.597Z] 02:53:16 INFO - org.mozilla.geckoview.test | at org.mozilla.geckoview.test.rule.GeckoSessionTestRule.waitUntilCalled(GeckoSessionTestRule.java:1681)
[task 2019-03-21T02:53:16.597Z] 02:53:16 INFO - org.mozilla.geckoview.test | at org.mozilla.geckoview.test.rule.GeckoSessionTestRule.waitUntilCalled(GeckoSessionTestRule.java:1627)
[task 2019-03-21T02:53:16.597Z] 02:53:16 INFO - org.mozilla.geckoview.test | at org.mozilla.geckoview.test.rule.GeckoSessionTestRule.waitUntilCalled(GeckoSessionTestRule.java:1580)
[task 2019-03-21T02:53:16.597Z] 02:53:16 INFO - org.mozilla.geckoview.test | at org.mozilla.geckoview.test.AccessibilityTest.testMoveByCharacter(AccessibilityTest.kt:374)
[task 2019-03-21T02:53:16.597Z] 02:53:16 INFO - org.mozilla.geckoview.test | at java.lang.reflect.Method.invokeNative(Native Method)
[task 2019-03-21T02:53:16.597Z] 02:53:16 INFO - org.mozilla.geckoview.test | at java.lang.reflect.Method.invoke(Method.java:525)
[task 2019-03-21T02:53:16.597Z] 02:53:16 INFO - org.mozilla.geckoview.test | at org.junit.runners.model.FrameworkMethod$1.runReflectiveCall(FrameworkMethod.java:50)
[task 2019-03-21T02:53:16.597Z] 02:53:16 INFO - org.mozilla.geckoview.test | at org.junit.internal.runners.model.ReflectiveCallable.run(ReflectiveCallable.java:12)
[task 2019-03-21T02:53:16.598Z] 02:53:16 INFO - org.mozilla.geckoview.test | at org.junit.runners.model.FrameworkMethod.invokeExplosively(FrameworkMethod.java:47)
[task 2019-03-21T02:53:16.598Z] 02:53:16 INFO - org.mozilla.geckoview.test | at org.junit.internal.runners.statements.InvokeMethod.evaluate(InvokeMethod.java:17)
[task 2019-03-21T02:53:16.598Z] 02:53:16 INFO - org.mozilla.geckoview.test | at android.support.test.internal.runner.junit4.statement.RunBefores.evaluate(RunBefores.java:80)
[task 2019-03-21T02:53:16.598Z] 02:53:16 INFO - org.mozilla.geckoview.test | at android.support.test.internal.runner.junit4.statement.RunAfters.evaluate(RunAfters.java:61)
[task 2019-03-21T02:53:16.598Z] 02:53:16 INFO - org.mozilla.geckoview.test | at org.mozilla.geckoview.test.rule.GeckoSessionTestRule$3$1.run(GeckoSessionTestRule.java:1422)
[task 2019-03-21T02:53:16.598Z] 02:53:16 INFO - org.mozilla.geckoview.test | at android.app.Instrumentation$SyncRunnable.run(Instrumentation.java:1719)
[task 2019-03-21T02:53:16.598Z] 02:53:16 INFO - org.mozilla.geckoview.test | at android.os.Handler.handleCallback(Handler.java:730)
[task 2019-03-21T02:53:16.598Z] 02:53:16 INFO - org.mozilla.geckoview.test | at android.os.Handler.dispatchMessage(Handler.java:92)
[task 2019-03-21T02:53:16.598Z] 02:53:16 INFO - org.mozilla.geckoview.test | at android.os.Looper.loop(Looper.java:137)
[task 2019-03-21T02:53:16.598Z] 02:53:16 INFO - org.mozilla.geckoview.test | at android.app.ActivityThread.main(ActivityThread.java:5103)
[task 2019-03-21T02:53:16.598Z] 02:53:16 INFO - org.mozilla.geckoview.test | at java.lang.reflect.Method.invokeNative(Native Method)
[task 2019-03-21T02:53:16.598Z] 02:53:16 INFO - org.mozilla.geckoview.test | at java.lang.reflect.Method.invoke(Method.java:525)
[task 2019-03-21T02:53:16.598Z] 02:53:16 INFO - org.mozilla.geckoview.test | at com.android.internal.os.ZygoteInit$MethodAndArgsCaller.run(ZygoteInit.java:737)
[task 2019-03-21T02:53:16.598Z] 02:53:16 INFO - org.mozilla.geckoview.test | at com.android.internal.os.ZygoteInit.main(ZygoteInit.java:553)
[task 2019-03-21T02:53:16.598Z] 02:53:16 INFO - org.mozilla.geckoview.test | at dalvik.system.NativeStart.main(Native Method)
[task 2019-03-21T02:53:16.599Z] 02:53:16 INFO - org.mozilla.geckoview.test |
[task 2019-03-21T02:53:16.599Z] 02:53:16 INFO - org.mozilla.geckoview.test | INSTRUMENTATION_STATUS: test=testMoveByCharacter
[task 2019-03-21T02:53:16.599Z] 02:53:16 INFO - org.mozilla.geckoview.test | INSTRUMENTATION_STATUS_CODE: -2
[task 2019-03-21T02:53:16.599Z] 02:53:16 WARNING - TEST-UNEXPECTED-FAIL | org.mozilla.geckoview.test.AccessibilityTest.testMoveByCharacter | status -2
[task 2019-03-21T02:53:16.599Z] 02:53:16 INFO - TEST-INFO took 187129ms

Status: RESOLVED → REOPENED
Resolution: WORKSFORME → ---
Assignee: gbrown → nobody
Priority: P3 → --
Comment hidden (Intermittent Failures Robot)
Comment hidden (Intermittent Failures Robot)
Comment hidden (Intermittent Failures Robot)
Comment hidden (Intermittent Failures Robot)
You need to log in before you can comment on or make changes to this bug.