Closed Bug 1607766 Opened 6 years ago Closed 5 days ago

Intermittent org.mozilla.geckoview.test.ExtensionActionTest <test name> | single tracking bug

Categories

(GeckoView :: Extensions, defect, P5)

Unspecified
All
defect

Tracking

(firefox158 fixed)

RESOLVED FIXED
158 Branch
Tracking Status
firefox158 --- fixed

People

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

References

(Blocks 1 open bug)

Details

(Keywords: intermittent-failure, intermittent-testcase, Whiteboard: [fxdroid])

Attachments

(2 files)

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


[task 2020-01-08T11:22:48.852Z] 11:22:48     INFO -  TEST-START | org.mozilla.geckoview.test.ExtensionActionTest.setBadgeText[#browserAction]
[task 2020-01-08T11:23:19.002Z] 11:23:19     INFO -  org.mozilla.geckoview.test | INSTRUMENTATION_STATUS: numtests=622
[task 2020-01-08T11:23:19.002Z] 11:23:19     INFO -  org.mozilla.geckoview.test | INSTRUMENTATION_STATUS: stream=
[task 2020-01-08T11:23:19.010Z] 11:23:19     INFO -  org.mozilla.geckoview.test | Error in setBadgeText[#browserAction](org.mozilla.geckoview.test.ExtensionActionTest):
[task 2020-01-08T11:23:19.010Z] 11:23:19     INFO -  org.mozilla.geckoview.test | org.mozilla.geckoview.test.util.UiThreadUtils$TimeoutException: Timed out after 30000ms
[task 2020-01-08T11:23:19.010Z] 11:23:19     INFO -  org.mozilla.geckoview.test | 	at org.mozilla.geckoview.test.util.UiThreadUtils$TimeoutRunnable.run(UiThreadUtils.java:58)
[task 2020-01-08T11:23:19.010Z] 11:23:19     INFO -  org.mozilla.geckoview.test | 	at android.os.Handler.handleCallback(Handler.java:751)
[task 2020-01-08T11:23:19.010Z] 11:23:19     INFO -  org.mozilla.geckoview.test | 	at android.os.Handler.dispatchMessage(Handler.java:95)
[task 2020-01-08T11:23:19.010Z] 11:23:19     INFO -  org.mozilla.geckoview.test | 	at org.mozilla.geckoview.test.util.UiThreadUtils.waitForCondition(UiThreadUtils.java:161)
[task 2020-01-08T11:23:19.010Z] 11:23:19     INFO -  org.mozilla.geckoview.test | 	at org.mozilla.geckoview.test.util.UiThreadUtils.waitForResult(UiThreadUtils.java:86)
[task 2020-01-08T11:23:19.010Z] 11:23:19     INFO -  org.mozilla.geckoview.test | 	at org.mozilla.geckoview.test.rule.GeckoSessionTestRule.waitForResult(GeckoSessionTestRule.java:2259)
[task 2020-01-08T11:23:19.010Z] 11:23:19     INFO -  org.mozilla.geckoview.test | 	at org.mozilla.geckoview.test.ExtensionActionTest.testActionApi(ExtensionActionTest.kt:183)
[task 2020-01-08T11:23:19.010Z] 11:23:19     INFO -  org.mozilla.geckoview.test | 	at org.mozilla.geckoview.test.ExtensionActionTest.setBadgeText(ExtensionActionTest.kt:253)
[task 2020-01-08T11:23:19.010Z] 11:23:19     INFO -  org.mozilla.geckoview.test | 	at java.lang.reflect.Method.invoke(Native Method)
[task 2020-01-08T11:23:19.010Z] 11:23:19     INFO -  org.mozilla.geckoview.test | 	at org.junit.runners.model.FrameworkMethod$1.runReflectiveCall(FrameworkMethod.java:50)
[task 2020-01-08T11:23:19.010Z] 11:23:19     INFO -  org.mozilla.geckoview.test | 	at org.junit.internal.runners.model.ReflectiveCallable.run(ReflectiveCallable.java:12)
[task 2020-01-08T11:23:19.010Z] 11:23:19     INFO -  org.mozilla.geckoview.test | 	at org.junit.runners.model.FrameworkMethod.invokeExplosively(FrameworkMethod.java:47)
[task 2020-01-08T11:23:19.010Z] 11:23:19     INFO -  org.mozilla.geckoview.test | 	at org.junit.internal.runners.statements.InvokeMethod.evaluate(InvokeMethod.java:17)
[task 2020-01-08T11:23:19.010Z] 11:23:19     INFO -  org.mozilla.geckoview.test | 	at org.junit.internal.runners.statements.RunBefores.evaluate(RunBefores.java:26)
[task 2020-01-08T11:23:19.010Z] 11:23:19     INFO -  org.mozilla.geckoview.test | 	at org.junit.internal.runners.statements.RunAfters.evaluate(RunAfters.java:27)
[task 2020-01-08T11:23:19.010Z] 11:23:19     INFO -  org.mozilla.geckoview.test | 	at org.mozilla.geckoview.test.rule.GeckoSessionTestRule$2.lambda$evaluate$0$GeckoSessionTestRule$2(GeckoSessionTestRule.java:1298)
[task 2020-01-08T11:23:19.010Z] 11:23:19     INFO -  org.mozilla.geckoview.test | 	at org.mozilla.geckoview.test.rule.-$$Lambda$GeckoSessionTestRule$2$sIbRNaZJgAu-QrUVWSGD8JbPSWM.run(lambda)
[task 2020-01-08T11:23:19.010Z] 11:23:19     INFO -  org.mozilla.geckoview.test | 	at android.app.Instrumentation$SyncRunnable.run(Instrumentation.java:1950)
[task 2020-01-08T11:23:19.010Z] 11:23:19     INFO -  org.mozilla.geckoview.test | 	at android.os.Handler.handleCallback(Handler.java:751)
[task 2020-01-08T11:23:19.010Z] 11:23:19     INFO -  org.mozilla.geckoview.test | 	at android.os.Handler.dispatchMessage(Handler.java:95)
[task 2020-01-08T11:23:19.010Z] 11:23:19     INFO -  org.mozilla.geckoview.test | 	at android.os.Looper.loop(Looper.java:154)
[task 2020-01-08T11:23:19.010Z] 11:23:19     INFO -  org.mozilla.geckoview.test | 	at android.app.ActivityThread.main(ActivityThread.java:6077)
[task 2020-01-08T11:23:19.010Z] 11:23:19     INFO -  org.mozilla.geckoview.test | 	at java.lang.reflect.Method.invoke(Native Method)
[task 2020-01-08T11:23:19.010Z] 11:23:19     INFO -  org.mozilla.geckoview.test | 	at com.android.internal.os.ZygoteInit$MethodAndArgsCaller.run(ZygoteInit.java:866)
[task 2020-01-08T11:23:19.010Z] 11:23:19     INFO -  org.mozilla.geckoview.test | 	at com.android.internal.os.ZygoteInit.main(ZygoteInit.java:756)
[task 2020-01-08T11:23:19.010Z] 11:23:19     INFO -  org.mozilla.geckoview.test |
[task 2020-01-08T11:23:19.010Z] 11:23:19     INFO -  org.mozilla.geckoview.test | INSTRUMENTATION_STATUS: id=AndroidJUnitRunner
[task 2020-01-08T11:23:19.010Z] 11:23:19     INFO -  org.mozilla.geckoview.test | INSTRUMENTATION_STATUS: test=setBadgeText[#browserAction]
[task 2020-01-08T11:23:19.010Z] 11:23:19     INFO -  org.mozilla.geckoview.test | INSTRUMENTATION_STATUS: class=org.mozilla.geckoview.test.ExtensionActionTest
[task 2020-01-08T11:23:19.010Z] 11:23:19     INFO -  org.mozilla.geckoview.test | INSTRUMENTATION_STATUS: stack=org.mozilla.geckoview.test.util.UiThreadUtils$TimeoutException: Timed out after 30000ms
[task 2020-01-08T11:23:19.010Z] 11:23:19     INFO -  org.mozilla.geckoview.test | 	at org.mozilla.geckoview.test.util.UiThreadUtils$TimeoutRunnable.run(UiThreadUtils.java:58)
[task 2020-01-08T11:23:19.010Z] 11:23:19     INFO -  org.mozilla.geckoview.test | 	at android.os.Handler.handleCallback(Handler.java:751)
[task 2020-01-08T11:23:19.010Z] 11:23:19     INFO -  org.mozilla.geckoview.test | 	at android.os.Handler.dispatchMessage(Handler.java:95)
[task 2020-01-08T11:23:19.010Z] 11:23:19     INFO -  org.mozilla.geckoview.test | 	at org.mozilla.geckoview.test.util.UiThreadUtils.waitForCondition(UiThreadUtils.java:161)
[task 2020-01-08T11:23:19.010Z] 11:23:19     INFO -  org.mozilla.geckoview.test | 	at org.mozilla.geckoview.test.util.UiThreadUtils.waitForResult(UiThreadUtils.java:86)
[task 2020-01-08T11:23:19.010Z] 11:23:19     INFO -  org.mozilla.geckoview.test | 	at org.mozilla.geckoview.test.rule.GeckoSessionTestRule.waitForResult(GeckoSessionTestRule.java:2259)
[task 2020-01-08T11:23:19.010Z] 11:23:19     INFO -  org.mozilla.geckoview.test | 	at org.mozilla.geckoview.test.ExtensionActionTest.testActionApi(ExtensionActionTest.kt:183)
[task 2020-01-08T11:23:19.010Z] 11:23:19     INFO -  org.mozilla.geckoview.test | 	at org.mozilla.geckoview.test.ExtensionActionTest.setBadgeText(ExtensionActionTest.kt:253)
[task 2020-01-08T11:23:19.010Z] 11:23:19     INFO -  org.mozilla.geckoview.test | 	at java.lang.reflect.Method.invoke(Native Method)
[task 2020-01-08T11:23:19.010Z] 11:23:19     INFO -  org.mozilla.geckoview.test | 	at org.junit.runners.model.FrameworkMethod$1.runReflectiveCall(FrameworkMethod.java:50)
[task 2020-01-08T11:23:19.010Z] 11:23:19     INFO -  org.mozilla.geckoview.test | 	at org.junit.internal.runners.model.ReflectiveCallable.run(ReflectiveCallable.java:12)
[task 2020-01-08T11:23:19.011Z] 11:23:19     INFO -  org.mozilla.geckoview.test | 	at org.junit.runners.model.FrameworkMethod.invokeExplosively(FrameworkMethod.java:47)
[task 2020-01-08T11:23:19.011Z] 11:23:19     INFO -  org.mozilla.geckoview.test | 	at org.junit.internal.runners.statements.InvokeMethod.evaluate(InvokeMethod.java:17)
[task 2020-01-08T11:23:19.011Z] 11:23:19     INFO -  org.mozilla.geckoview.test | 	at org.junit.internal.runners.statements.RunBefores.evaluate(RunBefores.java:26)
[task 2020-01-08T11:23:19.011Z] 11:23:19     INFO -  org.mozilla.geckoview.test | 	at org.junit.internal.runners.statements.RunAfters.evaluate(RunAfters.java:27)
[task 2020-01-08T11:23:19.011Z] 11:23:19     INFO -  org.mozilla.geckoview.test | 	at org.mozilla.geckoview.test.rule.GeckoSessionTestRule$2.lambda$evaluate$0$GeckoSessionTestRule$2(GeckoSessionTestRule.java:1298)
[task 2020-01-08T11:23:19.011Z] 11:23:19     INFO -  org.mozilla.geckoview.test | 	at org.mozilla.geckoview.test.rule.-$$Lambda$GeckoSessionTestRule$2$sIbRNaZJgAu-QrUVWSGD8JbPSWM.run(lambda)
[task 2020-01-08T11:23:19.011Z] 11:23:19     INFO -  org.mozilla.geckoview.test | 	at android.app.Instrumentation$SyncRunnable.run(Instrumentation.java:1950)
[task 2020-01-08T11:23:19.011Z] 11:23:19     INFO -  org.mozilla.geckoview.test | 	at android.os.Handler.handleCallback(Handler.java:751)
[task 2020-01-08T11:23:19.011Z] 11:23:19     INFO -  org.mozilla.geckoview.test | 	at android.os.Handler.dispatchMessage(Handler.java:95)
[task 2020-01-08T11:23:19.011Z] 11:23:19     INFO -  org.mozilla.geckoview.test | 	at android.os.Looper.loop(Looper.java:154)
[task 2020-01-08T11:23:19.011Z] 11:23:19     INFO -  org.mozilla.geckoview.test | 	at android.app.ActivityThread.main(ActivityThread.java:6077)
[task 2020-01-08T11:23:19.011Z] 11:23:19     INFO -  org.mozilla.geckoview.test | 	at java.lang.reflect.Method.invoke(Native Method)
[task 2020-01-08T11:23:19.011Z] 11:23:19     INFO -  org.mozilla.geckoview.test | 	at com.android.internal.os.ZygoteInit$MethodAndArgsCaller.run(ZygoteInit.java:866)
[task 2020-01-08T11:23:19.011Z] 11:23:19     INFO -  org.mozilla.geckoview.test | 	at com.android.internal.os.ZygoteInit.main(ZygoteInit.java:756)
[task 2020-01-08T11:23:19.011Z] 11:23:19     INFO -  org.mozilla.geckoview.test |
[task 2020-01-08T11:23:19.011Z] 11:23:19     INFO -  org.mozilla.geckoview.test | INSTRUMENTATION_STATUS: current=55
[task 2020-01-08T11:23:19.011Z] 11:23:19     INFO -  org.mozilla.geckoview.test | INSTRUMENTATION_STATUS_CODE: -2
[task 2020-01-08T11:23:19.011Z] 11:23:19  WARNING -  TEST-UNEXPECTED-FAIL | org.mozilla.geckoview.test.ExtensionActionTest.setBadgeText[#browserAction] | org.mozilla.geckoview.test.util.UiThreadUtils$TimeoutException: Timed out after 30000ms
[task 2020-01-08T11:23:19.011Z] 11:23:19     INFO -  TEST-INFO took 30151ms
[task 2020-01-08T11:23:19.012Z] 11:23:19     INFO -  org.mozilla.geckoview.test | INSTRUMENTATION_STATUS: numtests=622
[task 2020-01-08T11:23:19.012Z] 11:23:19     INFO -  org.mozilla.geckoview.test | INSTRUMENTATION_STATUS: stream=
[task 2020-01-08T11:23:19.012Z] 11:23:19     INFO -  org.mozilla.geckoview.test | INSTRUMENTATION_STATUS: id=AndroidJUnitRunner
[task 2020-01-08T11:23:19.012Z] 11:23:19     INFO -  org.mozilla.geckoview.test | INSTRUMENTATION_STATUS: test=setIconError[#browserAction]
[task 2020-01-08T11:23:19.012Z] 11:23:19     INFO -  org.mozilla.geckoview.test | INSTRUMENTATION_STATUS: class=org.mozilla.geckoview.test.ExtensionActionTest
[task 2020-01-08T11:23:19.012Z] 11:23:19     INFO -  org.mozilla.geckoview.test | INSTRUMENTATION_STATUS: current=56
[task 2020-01-08T11:23:19.012Z] 11:23:19     INFO -  org.mozilla.geckoview.test | INSTRUMENTATION_STATUS_CODE: 1
Summary: Intermittent org.mozilla.geckoview.test.ExtensionActionTest.setBadgeText[#browserAction] | org.mozilla.geckoview.test.util.UiThreadUtils$TimeoutException: Timed out after 30000ms → Intermittent org.mozilla.geckoview.test.ExtensionActionTest<test name> | org.mozilla.geckoview.test.util.UiThreadUtils$TimeoutException: Timed out after 30000ms

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

Summary: Intermittent org.mozilla.geckoview.test.ExtensionActionTest<test name> | org.mozilla.geckoview.test.util.UiThreadUtils$TimeoutException: Timed out after 30000ms → Intermittent org.mozilla.geckoview.test.ExtensionActionTest<test name> | org.mozilla.geckoview.test.util#UiThreadUtils$TimeoutException: Timed out after 30000ms
Status: NEW → RESOLVED
Closed: 4 years ago
Resolution: --- → INCOMPLETE
Status: RESOLVED → REOPENED
Resolution: INCOMPLETE → ---
Status: REOPENED → RESOLVED
Closed: 4 years ago → 4 years ago
Resolution: --- → INCOMPLETE
Status: RESOLVED → REOPENED
Resolution: INCOMPLETE → ---
Status: REOPENED → RESOLVED
Closed: 4 years ago → 4 years ago
Resolution: --- → INCOMPLETE
Status: RESOLVED → REOPENED
Resolution: INCOMPLETE → ---
Status: REOPENED → RESOLVED
Closed: 4 years ago → 4 years ago
Resolution: --- → INCOMPLETE
Status: RESOLVED → REOPENED
Resolution: INCOMPLETE → ---
Status: REOPENED → RESOLVED
Closed: 4 years ago → 3 years ago
Resolution: --- → INCOMPLETE
Status: RESOLVED → REOPENED
Resolution: INCOMPLETE → ---
Severity: normal → S4
Status: REOPENED → RESOLVED
Closed: 3 years ago → 3 years ago
Resolution: --- → INCOMPLETE
Status: RESOLVED → REOPENED
Resolution: INCOMPLETE → ---
Status: REOPENED → RESOLVED
Closed: 3 years ago → 3 years ago
Resolution: --- → INCOMPLETE
Status: RESOLVED → REOPENED
Resolution: INCOMPLETE → ---
Summary: Intermittent org.mozilla.geckoview.test.ExtensionActionTest<test name> | org.mozilla.geckoview.test.util#UiThreadUtils$TimeoutException: Timed out after 30000ms → Intermittent org.mozilla.geckoview.test.ExtensionActionTest <test name> | single tracking bug
Status: REOPENED → RESOLVED
Closed: 3 years ago → 3 years ago
Resolution: --- → INCOMPLETE
Status: RESOLVED → REOPENED
Resolution: INCOMPLETE → ---
Status: REOPENED → RESOLVED
Closed: 3 years ago → 2 years ago
Resolution: --- → INCOMPLETE
Status: RESOLVED → REOPENED
Resolution: INCOMPLETE → ---
Status: REOPENED → RESOLVED
Closed: 2 years ago → 2 years ago
Resolution: --- → INCOMPLETE
Status: RESOLVED → REOPENED
Resolution: INCOMPLETE → ---
Status: REOPENED → RESOLVED
Closed: 2 years ago → 2 years ago
Resolution: --- → INCOMPLETE
Status: RESOLVED → REOPENED
Resolution: INCOMPLETE → ---
Status: REOPENED → RESOLVED
Closed: 2 years ago → 1 year ago
Resolution: --- → INCOMPLETE
Status: RESOLVED → REOPENED
Resolution: INCOMPLETE → ---

testActionApi and testBackgroundActionApi post the message that makes the extension change its action, then
register the ActionDelegate that waits for the resulting update. The update comes back through a content
script and the background script within a few milliseconds; when the UI thread is preempted for longer than
that, the session dispatcher has no listener yet and discards the update ("No listener for
GeckoView:BrowserAction:Update" in logcat), so the wait times out after 30 seconds. Register the delegate
first.

For the background variant this also orders the attach-triggered default update ahead of the real one, which
the counter check in the delegate already assumes.

GeckoSessionTestRule now says so in the addExternalDelegateDuringNextWait docs.

Assignee: nobody → ryanvm

WebExtension has no equals(), and the controller's extension store hands delegates whichever instance it holds
for an id. That instance is replaced on every list, enable, disable and update, and an action or tab event
that reaches the store between an uninstall and the next install's registration makes it fetch and cache a
fresh copy that can land after the installed one. testPopupsCanCloseThemselves and testPopupMessaging then saw
a different instance for the same extension in onTogglePopup and failed; the tabs.create and tabs.remove
delegate assertions in WebExtensionTest rely on the same identity. Compare ids instead.

Whiteboard: [fxdroid]
Pushed by rvandermeulen@mozilla.com: https://github.com/mozilla-firefox/firefox/commit/36df756d3a89 https://hg.mozilla.org/integration/autoland/rev/1d364a9c8ae2 Register the action delegate before posting the port message in ExtensionActionTest. r=geckoview-reviewers,ohall https://github.com/mozilla-firefox/firefox/commit/c94f03f23a13 https://hg.mozilla.org/integration/autoland/rev/76c69c35bcab Compare WebExtension ids rather than instances in extension delegate assertions. r=geckoview-reviewers,ohall
Status: REOPENED → RESOLVED
Closed: 1 year ago → 5 days ago
Resolution: --- → FIXED
Target Milestone: --- → 158 Branch
You need to log in before you can comment on or make changes to this bug.

Attachment

General

Created:
Updated:
Size: