Closed Bug 1553354 Opened 6 years ago Closed 6 years ago

Intermittent org.mozilla.geckoview.test.WebExtensionTest#contentPortMessaging | status -2

Categories

(GeckoView :: Extensions, defect, P5)

Product:
GeckoView
Component:
Extensions
Platform:
Unspecified
Android
Type:
defect

Tracking

(firefox-esr68 wontfix, firefox69 wontfix, firefox71 wontfix, firefox72 wontfix, firefox73 fixed)

Status:
RESOLVED FIXED
Milestone:
mozilla73
Tracking Flags:
Tracking Status
firefox-esr68 --- wontfix
firefox69 --- wontfix
firefox71 --- wontfix
firefox72 --- wontfix
firefox73 --- fixed

People

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

References

(Blocks 1 open bug)

Details

(Keywords: intermittent-failure, regression)

Attachments

(2 files)

Bug 1553354 - Add org.mozilla.gecko.MultiMap.
47 bytes, text/x-phabricator-request
Details | Review
Bug 1553354 - Store messages when either the port or the delegate cannot be found.
47 bytes, text/x-phabricator-request
Details | Review

Filed by: csabou [at] mozilla.com
Parsed log: https://treeherder.mozilla.org/logviewer.html#?job_id=247547533&repo=mozilla-beta
Full log: https://queue.taskcluster.net/v1/task/FcuZcK4DTC-6EJNxonDl3g/runs/0/artifacts/public/logs/live_backing.log

[task 2019-05-21T13:42:02.430Z] 13:42:02 INFO - TEST-START | org.mozilla.geckoview.test.WebExtensionTest.contentPortMessaging
[task 2019-05-21T13:44:04.702Z] 13:44:04 INFO - org.mozilla.geckoview.test | INSTRUMENTATION_STATUS: id=AndroidJUnitRunner
[task 2019-05-21T13:44:04.702Z] 13:44:04 INFO - org.mozilla.geckoview.test | INSTRUMENTATION_STATUS: current=151
[task 2019-05-21T13:44:04.702Z] 13:44:04 INFO - org.mozilla.geckoview.test | INSTRUMENTATION_STATUS: class=org.mozilla.geckoview.test.WebExtensionTest
[task 2019-05-21T13:44:04.702Z] 13:44:04 INFO - org.mozilla.geckoview.test | INSTRUMENTATION_STATUS: stream=
[task 2019-05-21T13:44:04.702Z] 13:44:04 INFO - org.mozilla.geckoview.test | Error in contentPortMessaging(org.mozilla.geckoview.test.WebExtensionTest):
[task 2019-05-21T13:44:04.702Z] 13:44:04 INFO - org.mozilla.geckoview.test | org.mozilla.geckoview.test.util.UiThreadUtils$TimeoutException: Timed out after 120000ms
[task 2019-05-21T13:44:04.703Z] 13:44:04 INFO - org.mozilla.geckoview.test | at org.mozilla.geckoview.test.util.UiThreadUtils$TimeoutRunnable.run(UiThreadUtils.java:56)
[task 2019-05-21T13:44:04.703Z] 13:44:04 INFO - org.mozilla.geckoview.test | at android.os.Handler.handleCallback(Handler.java:730)
[task 2019-05-21T13:44:04.703Z] 13:44:04 INFO - org.mozilla.geckoview.test | at android.os.Handler.dispatchMessage(Handler.java:92)
[task 2019-05-21T13:44:04.703Z] 13:44:04 INFO - org.mozilla.geckoview.test | at org.mozilla.geckoview.test.util.UiThreadUtils.loopUntilIdle(UiThreadUtils.java:154)
[task 2019-05-21T13:44:04.703Z] 13:44:04 INFO - org.mozilla.geckoview.test | at org.mozilla.geckoview.test.rule.GeckoSessionTestRule.waitForInitialLoad(GeckoSessionTestRule.java:1314)
[task 2019-05-21T13:44:04.704Z] 13:44:04 INFO - org.mozilla.geckoview.test | at org.mozilla.geckoview.test.rule.GeckoSessionTestRule.waitForOpenSession(GeckoSessionTestRule.java:1263)
[task 2019-05-21T13:44:04.704Z] 13:44:04 INFO - org.mozilla.geckoview.test | at org.mozilla.geckoview.test.rule.GeckoSessionTestRule.openSession(GeckoSessionTestRule.java:1259)
[task 2019-05-21T13:44:04.704Z] 13:44:04 INFO - org.mozilla.geckoview.test | at org.mozilla.geckoview.test.rule.GeckoSessionTestRule.prepareStatement(GeckoSessionTestRule.java:1241)
[task 2019-05-21T13:44:04.706Z] 13:44:04 INFO - org.mozilla.geckoview.test | at org.mozilla.geckoview.test.rule.GeckoSessionTestRule$3$1.run(GeckoSessionTestRule.java:1421)
[task 2019-05-21T13:44:04.706Z] 13:44:04 INFO - org.mozilla.geckoview.test | at android.app.Instrumentation$SyncRunnable.run(Instrumentation.java:1719)
[task 2019-05-21T13:44:04.706Z] 13:44:04 INFO - org.mozilla.geckoview.test | at android.os.Handler.handleCallback(Handler.java:730)
[task 2019-05-21T13:44:04.706Z] 13:44:04 INFO - org.mozilla.geckoview.test | at android.os.Handler.dispatchMessage(Handler.java:92)
[task 2019-05-21T13:44:04.706Z] 13:44:04 INFO - org.mozilla.geckoview.test | at android.os.Looper.loop(Looper.java:137)
[task 2019-05-21T13:44:04.706Z] 13:44:04 INFO - org.mozilla.geckoview.test | at android.app.ActivityThread.main(ActivityThread.java:5103)
[task 2019-05-21T13:44:04.706Z] 13:44:04 INFO - org.mozilla.geckoview.test | at java.lang.reflect.Method.invokeNative(Native Method)
[task 2019-05-21T13:44:04.707Z] 13:44:04 INFO - org.mozilla.geckoview.test | at java.lang.reflect.Method.invoke(Method.java:525)
[task 2019-05-21T13:44:04.707Z] 13:44:04 INFO - org.mozilla.geckoview.test | at com.android.internal.os.ZygoteInit$MethodAndArgsCaller.run(ZygoteInit.java:737)
[task 2019-05-21T13:44:04.707Z] 13:44:04 INFO - org.mozilla.geckoview.test | at com.android.internal.os.ZygoteInit.main(ZygoteInit.java:553)
[task 2019-05-21T13:44:04.707Z] 13:44:04 INFO - org.mozilla.geckoview.test | at dalvik.system.NativeStart.main(Native Method)
[task 2019-05-21T13:44:04.707Z] 13:44:04 INFO - org.mozilla.geckoview.test |
[task 2019-05-21T13:44:04.707Z] 13:44:04 INFO - org.mozilla.geckoview.test | INSTRUMENTATION_STATUS: numtests=155
[task 2019-05-21T13:44:04.707Z] 13:44:04 INFO - org.mozilla.geckoview.test | INSTRUMENTATION_STATUS: stack=org.mozilla.geckoview.test.util.UiThreadUtils$TimeoutException: Timed out after 120000ms
[task 2019-05-21T13:44:04.707Z] 13:44:04 INFO - org.mozilla.geckoview.test | at org.mozilla.geckoview.test.util.UiThreadUtils$TimeoutRunnable.run(UiThreadUtils.java:56)
[task 2019-05-21T13:44:04.707Z] 13:44:04 INFO - org.mozilla.geckoview.test | at android.os.Handler.handleCallback(Handler.java:730)
[task 2019-05-21T13:44:04.707Z] 13:44:04 INFO - org.mozilla.geckoview.test | at android.os.Handler.dispatchMessage(Handler.java:92)
[task 2019-05-21T13:44:04.707Z] 13:44:04 INFO - org.mozilla.geckoview.test | at org.mozilla.geckoview.test.util.UiThreadUtils.loopUntilIdle(UiThreadUtils.java:154)
[task 2019-05-21T13:44:04.707Z] 13:44:04 INFO - org.mozilla.geckoview.test | at org.mozilla.geckoview.test.rule.GeckoSessionTestRule.waitForInitialLoad(GeckoSessionTestRule.java:1314)
[task 2019-05-21T13:44:04.707Z] 13:44:04 INFO - org.mozilla.geckoview.test | at org.mozilla.geckoview.test.rule.GeckoSessionTestRule.waitForOpenSession(GeckoSessionTestRule.java:1263)
[task 2019-05-21T13:44:04.707Z] 13:44:04 INFO - org.mozilla.geckoview.test | at org.mozilla.geckoview.test.rule.GeckoSessionTestRule.openSession(GeckoSessionTestRule.java:1259)
[task 2019-05-21T13:44:04.707Z] 13:44:04 INFO - org.mozilla.geckoview.test | at org.mozilla.geckoview.test.rule.GeckoSessionTestRule.prepareStatement(GeckoSessionTestRule.java:1241)
[task 2019-05-21T13:44:04.708Z] 13:44:04 INFO - org.mozilla.geckoview.test | at org.mozilla.geckoview.test.rule.GeckoSessionTestRule$3$1.run(GeckoSessionTestRule.java:1421)
[task 2019-05-21T13:44:04.708Z] 13:44:04 INFO - org.mozilla.geckoview.test | at android.app.Instrumentation$SyncRunnable.run(Instrumentation.java:1719)
[task 2019-05-21T13:44:04.708Z] 13:44:04 INFO - org.mozilla.geckoview.test | at android.os.Handler.handleCallback(Handler.java:730)
[task 2019-05-21T13:44:04.708Z] 13:44:04 INFO - org.mozilla.geckoview.test | at android.os.Handler.dispatchMessage(Handler.java:92)
[task 2019-05-21T13:44:04.708Z] 13:44:04 INFO - org.mozilla.geckoview.test | at android.os.Looper.loop(Looper.java:137)
[task 2019-05-21T13:44:04.709Z] 13:44:04 INFO - org.mozilla.geckoview.test | at android.app.ActivityThread.main(ActivityThread.java:5103)
[task 2019-05-21T13:44:04.709Z] 13:44:04 INFO - org.mozilla.geckoview.test | at java.lang.reflect.Method.invokeNative(Native Method)
[task 2019-05-21T13:44:04.709Z] 13:44:04 INFO - org.mozilla.geckoview.test | at java.lang.reflect.Method.invoke(Method.java:525)
[task 2019-05-21T13:44:04.709Z] 13:44:04 INFO - org.mozilla.geckoview.test | at com.android.internal.os.ZygoteInit$MethodAndArgsCaller.run(ZygoteInit.java:737)
[task 2019-05-21T13:44:04.709Z] 13:44:04 INFO - org.mozilla.geckoview.test | at com.android.internal.os.ZygoteInit.main(ZygoteInit.java:553)
[task 2019-05-21T13:44:04.710Z] 13:44:04 INFO - org.mozilla.geckoview.test | at dalvik.system.NativeStart.main(Native Method)
[task 2019-05-21T13:44:04.710Z] 13:44:04 INFO - org.mozilla.geckoview.test |
[task 2019-05-21T13:44:04.710Z] 13:44:04 INFO - org.mozilla.geckoview.test | INSTRUMENTATION_STATUS: test=contentPortMessaging
[task 2019-05-21T13:44:04.710Z] 13:44:04 INFO - org.mozilla.geckoview.test | INSTRUMENTATION_STATUS_CODE: -2
[task 2019-05-21T13:44:04.710Z] 13:44:04 WARNING - TEST-UNEXPECTED-FAIL | org.mozilla.geckoview.test.WebExtensionTest.contentPortMessaging | status -2
[task 2019-05-21T13:44:04.710Z] 13:44:04 INFO - TEST-INFO took 122277ms
[task 2019-05-21T13:44:04.711Z] 13:44:04 INFO - org.mozilla.geckoview.test | INSTRUMENTATION_STATUS: id=AndroidJUnitRunner
[task 2019-05-21T13:44:04.711Z] 13:44:04 INFO - org.mozilla.geckoview.test | INSTRUMENTATION_STATUS: current=152
[task 2019-05-21T13:44:04.711Z] 13:44:04 INFO - org.mozilla.geckoview.test | INSTRUMENTATION_STATUS: class=org.mozilla.geckoview.test.WebExtensionTest
[task 2019-05-21T13:44:04.711Z] 13:44:04 INFO - org.mozilla.geckoview.test | INSTRUMENTATION_STATUS: stream=
[task 2019-05-21T13:44:04.711Z] 13:44:04 INFO - org.mozilla.geckoview.test | INSTRUMENTATION_STATUS: numtests=155
[task 2019-05-21T13:44:04.807Z] 13:44:04 INFO - org.mozilla.geckoview.test |
[task 2019-05-21T13:44:04.807Z] 13:44:04 INFO - org.mozilla.geckoview.test | INSTRUMENTATION_STATUS: test=contentPortDisconnectAfterRefresh
[task 2019-05-21T13:44:04.807Z] 13:44:04 INFO - org.mozilla.geckoview.test | INSTRUMENTATION_STATUS_CODE: 1

Blocks: geckoview-junit-x86_64
status-firefox69: --- → affected
OS: All → Android

[bulk change --> 69 fix-optional b/c intermittent]

status-firefox69: affected → fix-optional
Component: General → Extensions

There are 33 failures associated with this bug in the last 7 days: https://treeherder.mozilla.org/intermittent-failures.html#/bugdetails?startday=2019-12-05&endday=2019-12-12&tree=trunk&bug=1553354

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

This has failed on android-em-7-0-x86_64 - opt and debug build types.

Agi, do you think the spike is related with https://bugzilla.mozilla.org/show_bug.cgi?id=1599580?

Flags: needinfo?(agi)

Yeah that's very likely, I'll keep the ni so I remember to take a look tomorrow.

Flags: needinfo?(agi)
Flags: needinfo?(agi)
Flags: needinfo?(agi)
Keywords: leave-open

Looked into it, this is an actual bug in the code! connectNative is synchronous so we sometimes don't have a port object when the message is sent. This is made worse by the fact that my patch made that code path asynchronous. Patch incoming.

Assignee: nobody → agi

port.connectNative is synchronous, so there is the slim possibility that a
message could be sent before the app has been notified that the port has been
created. Similarly, if the app has not attached a listener yet, the port
message gets lost.

In either case, we now store this message in a list that we check when a
delegate is attached to the port object.

Pushed by asferro@mozilla.com: https://hg.mozilla.org/integration/autoland/rev/d356998226eb Add org.mozilla.gecko.MultiMap. r=snorp https://hg.mozilla.org/integration/autoland/rev/7ae6e38ed776 Store messages when either the port or the delegate cannot be found. r=snorp

No failure reports since my fix landed, marking as Fixed.

Status: NEW → RESOLVED
Closed: 6 years ago
Resolution: --- → FIXED

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

Summary: Intermittent org.mozilla.geckoview.test.WebExtensionTest.contentPortMessaging | status -2 → Intermittent org.mozilla.geckoview.test.WebExtensionTest#contentPortMessaging | status -2
You need to log in before you can comment on or make changes to this bug.

Attachment

General

Creator:
Created:
Updated:
Size: