1615889 - Intermittent [tier2] TEST-UNEXPECTED-TIMEOUT | /service-workers/service-worker/detached-context.https.html | Executor hit external timeout (this may indicate a hang)

Status: RESOLVED INCOMPLETE

(Core :: DOM: Service Workers, defect, P5)

Description

[Treeherder Bug Filer]

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

---

[task 2020-02-16T12:06:51.187Z] 12:06:51 INFO - TEST-START | /service-workers/service-worker/detached-context.https.html
[task 2020-02-16T12:06:51.189Z] 12:06:51 INFO - Closing window 88
[task 2020-02-16T12:06:51.428Z] 12:06:51 INFO - PID 28145 | Gtk-Message: 12:06:51.419: Failed to load module "canberra-gtk-module"
[task 2020-02-16T12:06:51.429Z] 12:06:51 INFO - PID 28145 | ###!!! [Child][MessageChannel] Error: (msgtype=0x370131,name=PContent::Msg_AsyncMessage) Channel closing: too late to send/recv, messages will be lost
[task 2020-02-16T12:06:51.429Z] 12:06:51 INFO - PID 28145 | ###!!! [Child][RunMessage] Error: Channel closing: too late to send/recv, messages will be lost
[task 2020-02-16T12:06:51.429Z] 12:06:51 INFO - PID 28145 | ###!!! [Child][RunMessage] Error: Channel closing: too late to send/recv, messages will be lost
[task 2020-02-16T12:06:51.430Z] 12:06:51 INFO - PID 28145 | ###!!! [Child][RunMessage] Error: Channel closing: too late to send/recv, messages will be lost
[task 2020-02-16T12:06:51.431Z] 12:06:51 INFO - PID 28145 | ###!!! [Child][MessageChannel] Error: (msgtype=0x3700B5,name=PContent::Msg_SetURITitle) Channel closing: too late to send/recv, messages will be lost
[task 2020-02-16T12:06:51.431Z] 12:06:51 INFO - PID 28145 | ###!!! [Child][MessageChannel] Error: (msgtype=0x1E0001,name=PBrowser::Msg_AsyncMessage) Channel closing: too late to send/recv, messages will be lost
[task 2020-02-16T12:06:51.431Z] 12:06:51 INFO - PID 28145 | ###!!! [Child][MessageChannel] Error: (msgtype=0x6A0028,name=PNecko::Msg_RequestContextAfterDOMContentLoaded) Channel closing: too late to send/recv, messages will be lost
[task 2020-02-16T12:06:51.432Z] 12:06:51 INFO - PID 28145 | Gtk-Message: 12:06:51.422: Failed to load module "canberra-gtk-module"
[task 2020-02-16T12:06:51.433Z] 12:06:51 INFO - PID 28145 | ###!!! [Child][MessageChannel] Error: (msgtype=0x370130,name=PContent::Msg_CommitBrowsingContextTransaction) Channel closing: too late to send/recv, messages will be lost
[task 2020-02-16T12:06:51.434Z] 12:06:51 INFO - PID 28145 | ###!!! [Child][MessageChannel] Error: (msgtype=0x1E002A,name=PBrowser::Msg_SetInputContext) Channel closing: too late to send/recv, messages will be lost
[task 2020-02-16T12:06:51.435Z] 12:06:51 INFO - PID 28145 | ###!!! [Child][MessageChannel] Error: (msgtype=0x1E002A,name=PBrowser::Msg_SetInputContext) Channel closing: too late to send/recv, messages will be lost
[task 2020-02-16T12:06:51.435Z] 12:06:51 INFO - PID 28145 | ###!!! [Child][MessageChannel] Error: (msgtype=0x1E0027,name=PBrowser::Msg_EnableDisableCommands) Channel closing: too late to send/recv, messages will be lost
[task 2020-02-16T12:06:51.436Z] 12:06:51 INFO - PID 28145 | ###!!! [Child][MessageChannel] Error: (msgtype=0x1E0048,name=PBrowser::Msg_OnStateChange) Channel closing: too late to send/recv, messages will be lost
[task 2020-02-16T12:06:51.436Z] 12:06:51 INFO - PID 28145 | JavaScript error: resource:///actors/AboutReaderChild.jsm, line 95: NS_ERROR_UNEXPECTED:
[task 2020-02-16T12:07:11.195Z] 12:07:11 INFO - TEST-UNEXPECTED-TIMEOUT | /service-workers/service-worker/detached-context.https.html | Executor hit external timeout (this may indicate a hang)
[task 2020-02-16T12:07:11.195Z] 12:07:11 INFO - File "/usr/lib/python2.7/threading.py", line 774, in __bootstrap
[task 2020-02-16T12:07:11.195Z] 12:07:11 INFO - self.__bootstrap_inner()
[task 2020-02-16T12:07:11.195Z] 12:07:11 INFO - File "/usr/lib/python2.7/threading.py", line 801, in __bootstrap_inner
[task 2020-02-16T12:07:11.195Z] 12:07:11 INFO - self.run()
[task 2020-02-16T12:07:11.195Z] 12:07:11 INFO - File "/usr/lib/python2.7/threading.py", line 1070, in run
[task 2020-02-16T12:07:11.195Z] 12:07:11 INFO - self.finished.wait(self.interval)
[task 2020-02-16T12:07:11.195Z] 12:07:11 INFO - File "/usr/lib/python2.7/threading.py", line 614, in wait
[task 2020-02-16T12:07:11.195Z] 12:07:11 INFO - self.__cond.wait(timeout)
[task 2020-02-16T12:07:11.196Z] 12:07:11 INFO - File "/usr/lib/python2.7/threading.py", line 359, in wait
[task 2020-02-16T12:07:11.196Z] 12:07:11 INFO - _sleep(delay)
[task 2020-02-16T12:07:11.196Z] 12:07:11 INFO - TEST-INFO took 20005ms
[task 2020-02-16T12:07:11.213Z] 12:07:11 INFO - PID 28145 | 1581854831201 Marionette INFO Stopped listening on port 42561
[task 2020-02-16T12:07:11.217Z] 12:07:11 INFO - PID 28145 | JavaScript error: chrome://browser/content/browser.js, line 8110: TypeError: can't access property "processMessageManager", browser.messageManager is null
[task 2020-02-16T12:07:11.261Z] 12:07:11 INFO - PID 28145 | WARNING: A blocker encountered an error while we were waiting.
[task 2020-02-16T12:07:11.262Z] 12:07:11 INFO - PID 28145 | Blocker: SessionStore: flushing all windows
[task 2020-02-16T12:07:11.262Z] 12:07:11 INFO - PID 28145 | Phase: quit-application-granted
[task 2020-02-16T12:07:11.262Z] 12:07:11 INFO - PID 28145 | State: {"total":-1,"current":-1}
[task 2020-02-16T12:07:11.262Z] 12:07:11 INFO - PID 28145 | WARNING: TypeError: can't access property "sendAsyncMessage", mm is null
[task 2020-02-16T12:07:11.262Z] 12:07:11 INFO - PID 28145 | WARNING: flush@resource:///modules/sessionstore/TabStateFlusher.jsm:97:5
[task 2020-02-16T12:07:11.263Z] 12:07:11 INFO - PID 28145 | flushWindow@resource:///modules/sessionstore/TabStateFlusher.jsm:127:28
[task 2020-02-16T12:07:11.263Z] 12:07:11 INFO - PID 28145 | flushWindow@resource:///modules/sessionstore/TabStateFlusher.jsm:31:36
[task 2020-02-16T12:07:11.263Z] 12:07:11 INFO - PID 28145 | flushAllWindowsAsync@resource:///modules/sessionstore/SessionStore.jsm:1905:50
[task 2020-02-16T12:07:11.263Z] 12:07:11 INFO - PID 28145 | ssi_onQuitApplicationGranted/<@resource:///modules/sessionstore/SessionStore.jsm:1829:32
[task 2020-02-16T12:07:11.264Z] 12:07:11 INFO - PID 28145 | trigger@resource://gre/modules/AsyncShutdown.jsm:725:23
[task 2020-02-16T12:07:11.264Z] 12:07:11 INFO - PID 28145 | _wait@resource://gre/modules/AsyncShutdown.jsm:877:15
[task 2020-02-16T12:07:11.264Z] 12:07:11 INFO - PID 28145 | wait@resource://gre/modules/AsyncShutdown.jsm:858:34
[task 2020-02-16T12:07:11.264Z] 12:07:11 INFO - PID 28145 | observe@resource://gre/modules/AsyncShutdown.jsm:533:10
[task 2020-02-16T12:07:11.265Z] 12:07:11 INFO - PID 28145 | GeckoDriver.prototype.quit@chrome://marionette/content/driver.js:3514:20
[task 2020-02-16T12:07:11.266Z] 12:07:11 INFO - PID 28145 | despatch@chrome://marionette/content/server.js:305:40
[task 2020-02-16T12:07:11.267Z] 12:07:11 INFO - PID 28145 | execute@chrome://marionette/content/server.js:275:16
[task 2020-02-16T12:07:11.268Z] 12:07:11 INFO - PID 28145 | onPacket/<@chrome://marionette/content/server.js:248:20
[task 2020-02-16T12:07:11.270Z] 12:07:11 INFO - PID 28145 | onPacket@chrome://marionette/content/server.js:249:9
[task 2020-02-16T12:07:11.270Z] 12:07:11 INFO - PID 28145 | _onJSONObjectReady/<@chrome://marionette/content/transport.js:501:20
[task 2020-02-16T12:07:11.310Z] 12:07:11 INFO - PID 28145 | JavaScript error: resource:///modules/sessionstore/TabStateFlusher.jsm, line 97: TypeError: can't access property "sendAsyncMessage", mm is null
[task 2020-02-16T12:07:11.318Z] 12:07:11 INFO - PID 28145 | JavaScript error: chrome://marionette/content/proxy.js, line 222: TypeError: can't access property "remove", this.browser.driver.dialogObserver is null
[task 2020-02-16T12:07:11.810Z] 12:07:11 INFO - Browser exited with return code 0
[task 2020-02-16T12:07:11.810Z] 12:07:11 INFO - PROCESS LEAKS None
[task 2020-02-16T12:07:11.810Z] 12:07:11 INFO - PROCESS LEAKS None
[task 2020-02-16T12:07:11.811Z] 12:07:11 INFO - IOError on command, setting status to CRASH
[task 2020-02-16T12:07:11.812Z] 12:07:11 INFO - Closing logging queue
[task 2020-02-16T12:07:11.812Z] 12:07:11 INFO - queue closed
[task 2020-02-16T12:07:11.828Z] 12:07:11 INFO - Setting up ssl
[task 2020-02-16T12:07:11.850Z] 12:07:11 INFO - certutil |
[task 2020-02-16T12:07:11.878Z] 12:07:11 INFO - certutil |
[task 2020-02-16T12:07:11.894Z] 12:07:11 INFO - certutil |
[task 2020-02-16T12:07:11.894Z] 12:07:11 INFO - Certificate Nickname Trust Attributes
[task 2020-02-16T12:07:11.894Z] 12:07:11 INFO - SSL,S/MIME,JAR/XPI
[task 2020-02-16T12:07:11.894Z] 12:07:11 INFO -
[task 2020-02-16T12:07:11.894Z] 12:07:11 INFO - web-platform-tests CT,,
[task 2020-02-16T12:07:11.894Z] 12:07:11 INFO -
[task 2020-02-16T12:07:11.930Z] 12:07:11 INFO - Application command: /builds/worker/workspace/build/application/firefox/firefox --marionette about:blank -profile /tmp/tmpVnbsPy.mozrunner
[task 2020-02-16T12:07:11.946Z] 12:07:11 INFO - Starting runner
[task 2020-02-16T12:07:12.025Z] 12:07:12 INFO - PID 29709 | Gtk-Message: 12:07:12.016: Failed to load module "canberra-gtk-module"
[task 2020-02-16T12:07:12.026Z] 12:07:12 INFO - PID 29709 | Gtk-Message: 12:07:12.018: Failed to load module "canberra-gtk-module"
[task 2020-02-16T12:07:12.329Z] 12:07:12 INFO - PID 29709 | 1581854832325 [e-mail] WARN Loading extension '[e-mail]': Reading manifest: Invalid extension permission: networkStatus
[task 2020-02-16T12:07:12.874Z] 12:07:12 INFO - PID 29709 | 1581854832870 [e-mail] WARN Loading extension '[e-mail]': Reading manifest: Invalid extension permission: mozillaAddons
[task 2020-02-16T12:07:12.875Z] 12:07:12 INFO - PID 29709 | 1581854832870 [e-mail] WARN Loading extension '[e-mail]': Reading manifest: Invalid extension permission: telemetry
[task 2020-02-16T12:07:12.875Z] 12:07:12 INFO - PID 29709 | 1581854832871 [e-mail] WARN Loading extension '[e-mail]': Reading manifest: Invalid extension permission: resource://pdf.js/
[task 2020-02-16T12:07:12.876Z] 12:07:12 INFO - PID 29709 | 1581854832871 [e-mail] WARN Loading extension '[e-mail]': Reading manifest: Invalid extension permission: about:reader*
[task 2020-02-16T12:07:13.480Z] 12:07:13 INFO - PID 29709 | Gtk-Message: 12:07:13.475: Failed to load module "canberra-gtk-module"
[task 2020-02-16T12:07:13.481Z] 12:07:13 INFO - PID 29709 | Gtk-Message: 12:07:13.477: Failed to load module "canberra-gtk-module"
[task 2020-02-16T12:07:13.670Z] 12:07:13 INFO - PID 29709 | Gtk-Message: 12:07:13.668: Failed to load module "canberra-gtk-module"
[task 2020-02-16T12:07:13.674Z] 12:07:13 INFO - PID 29709 | Gtk-Message: 12:07:13.671: Failed to load module "canberra-gtk-module"
[task 2020-02-16T12:07:14.920Z] 12:07:14 INFO - PID 29709 | GLib-GIO-Message: 12:07:14.916: Using the 'memory' GSettings backend. Your settings will not be saved or shared with other applications.
[task 2020-02-16T12:07:15.906Z] 12:07:15 INFO - PID 29709 | Gtk-Message: 12:07:15.895: Failed to load module "canberra-gtk-module"
[task 2020-02-16T12:07:15.907Z] 12:07:15 INFO - PID 29709 | Gtk-Message: 12:07:15.898: Failed to load module "canberra-gtk-module"
[task 2020-02-16T12:07:16.105Z] 12:07:16 INFO - PID 29709 | 1581854836101 Marionette INFO Listening on port 42561

Comment 1

[Intermittent Failures Robot]

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

Repository breakdown:

• mozilla-central: 1

Platform breakdown:

• linux1804-32-shippable: 1

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

Comment 2

[BugBot [:suhaib / :marco/ :calixte]]

https://wiki.mozilla.org/Bug_Triage#Intermittent_Test_Failure_Cleanup
For more information, please visit auto_nag documentation.