1727486 - Intermittent TEST-UNEXPECTED-CRASH | /service-workers/service-worker/unregister-immediately.https.html | expected TIMEOUT

Status: RESOLVED DUPLICATE of bug 1741152

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

Description

[Treeherder Bug Filer]

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

---

[task 2021-08-25T05:35:54.596Z] 05:35:54     INFO - TEST-START | /service-workers/service-worker/unregister-immediately.https.html
[task 2021-08-25T05:35:54.601Z] 05:35:54     INFO - Closing window ec276c83-51a4-4258-a147-a87d13d9cff3
[task 2021-08-25T05:35:54.740Z] 05:35:54     INFO - PID 28539 | ###!!! [Parent][RunMessage] Error: Channel closing: too late to send/recv, messages will be lost
[task 2021-08-25T05:35:54.917Z] 05:35:54     INFO - PID 28539 | [Parent 28539, IPC I/O Parent] WARNING: Failed to launch tab subprocess: file /builds/worker/checkouts/gecko/ipc/glue/GeckoChildProcessHost.cpp:749
[task 2021-08-25T05:35:54.924Z] 05:35:54     INFO - PID 28539 | JavaScript error: chrome://browser/content/tabbrowser.js, line 1899: NS_ERROR_ILLEGAL_VALUE: Component returned failure code: 0x80070057 (NS_ERROR_ILLEGAL_VALUE) [nsIWebProgress.removeProgressListener]
[task 2021-08-25T05:35:54.926Z] 05:35:54     INFO - PID 28539 | JavaScript error: chrome://browser/content/tabbrowser.js, line 1899: NS_ERROR_ILLEGAL_VALUE: Component returned failure code: 0x80070057 (NS_ERROR_ILLEGAL_VALUE) [nsIWebProgress.removeProgressListener]
[task 2021-08-25T05:35:55.104Z] 05:35:55     INFO - PID 28539 | 1629869755099	Marionette	ERROR	TypeError: can't access property "addMessageListener", this.mm is null(chrome://remote/content/marionette/dom.js:50:5) JS Stack trace: [e-mail]:50:5
[task 2021-08-25T05:35:55.105Z] 05:35:55     INFO - PID 28539 | [e-mail]:398:26
[task 2021-08-25T05:35:55.106Z] 05:35:55     INFO - PID 28539 | [e-mail]:1220:35
[task 2021-08-25T05:35:55.107Z] 05:35:55     INFO - PID 28539 | [e-mail]:1160:18
[task 2021-08-25T05:35:55.107Z] 05:35:55     INFO - PID 28539 | [e-mail]:306:40
[task 2021-08-25T05:35:55.108Z] 05:35:55     INFO - PID 28539 | [e-mail]:279:16
[task 2021-08-25T05:35:55.109Z] 05:35:55     INFO - PID 28539 | onPacket/<@server.js:252:20
[task 2021-08-25T05:35:55.109Z] 05:35:55     INFO - PID 28539 | [e-mail]:253:9
[task 2021-08-25T05:35:55.109Z] 05:35:55     INFO - PID 28539 | _onJSONObjectReady/<@transport.js:500:20
[task 2021-08-25T05:35:55.114Z] 05:35:55     INFO - NoSuchWindowException on command, setting status to CRASH
[task 2021-08-25T05:35:55.115Z] 05:35:55     INFO - TEST-UNEXPECTED-CRASH | /service-workers/service-worker/unregister-immediately.https.html | expected TIMEOUT
[task 2021-08-25T05:35:55.115Z] 05:35:55     INFO - TEST-INFO expected TIMEOUT | took 518ms
[task 2021-08-25T05:35:55.123Z] 05:35:55     INFO - PID 28539 | 1629869755122	Marionette	INFO	Stopped listening on port 39704
[task 2021-08-25T05:35:55.265Z] 05:35:55     INFO - PID 28539 | WARNING: A blocker encountered an error while we were waiting.
[task 2021-08-25T05:35:55.266Z] 05:35:55     INFO - PID 28539 |           Blocker:  SessionStore: flushing all windows
[task 2021-08-25T05:35:55.266Z] 05:35:55     INFO - PID 28539 |           Phase: quit-application-granted
[task 2021-08-25T05:35:55.267Z] 05:35:55     INFO - PID 28539 |           State: {"total":-1,"current":-1}
[task 2021-08-25T05:35:55.270Z] 05:35:55     INFO - PID 28539 | WARNING: TypeError: can't access property "sendAsyncMessage", mm is null
[task 2021-08-25T05:35:55.270Z] 05:35:55     INFO - PID 28539 | WARNING: flush@resource:///modules/sessionstore/TabStateFlusher.jsm:131:7
[task 2021-08-25T05:35:55.270Z] 05:35:55     INFO - PID 28539 | flushWindow@resource:///modules/sessionstore/TabStateFlusher.jsm:173:28
[task 2021-08-25T05:35:55.270Z] 05:35:55     INFO - PID 28539 | flushWindow@resource:///modules/sessionstore/TabStateFlusher.jsm:42:36
[task 2021-08-25T05:35:55.270Z] 05:35:55     INFO - PID 28539 | flushAllWindowsAsync@resource:///modules/sessionstore/SessionStore.jsm:2134:50
[task 2021-08-25T05:35:55.270Z] 05:35:55     INFO - PID 28539 | ssi_onQuitApplicationGranted/<@resource:///modules/sessionstore/SessionStore.jsm:2058:32
[task 2021-08-25T05:35:55.270Z] 05:35:55     INFO - PID 28539 | trigger@resource://gre/modules/AsyncShutdown.jsm:747:23
[task 2021-08-25T05:35:55.271Z] 05:35:55     INFO - PID 28539 | _wait@resource://gre/modules/AsyncShutdown.jsm:899:15
[task 2021-08-25T05:35:55.271Z] 05:35:55     INFO - PID 28539 | wait@resource://gre/modules/AsyncShutdown.jsm:880:34
[task 2021-08-25T05:35:55.272Z] 05:35:55     INFO - PID 28539 | observe@resource://gre/modules/AsyncShutdown.jsm:557:10
[task 2021-08-25T05:35:55.272Z] 05:35:55     INFO - PID 28539 | GeckoDriver.prototype.quit@chrome://remote/content/marionette/driver.js:2662:20
[task 2021-08-25T05:35:55.273Z] 05:35:55     INFO - PID 28539 | despatch@chrome://remote/content/marionette/server.js:306:40
[task 2021-08-25T05:35:55.274Z] 05:35:55     INFO - PID 28539 | execute@chrome://remote/content/marionette/server.js:279:16
[task 2021-08-25T05:35:55.274Z] 05:35:55     INFO - PID 28539 | onPacket/<@chrome://remote/content/marionette/server.js:252:20
[task 2021-08-25T05:35:55.274Z] 05:35:55     INFO - PID 28539 | onPacket@chrome://remote/content/marionette/server.js:253:9
[task 2021-08-25T05:35:55.274Z] 05:35:55     INFO - PID 28539 | _onJSONObjectReady/<@chrome://remote/content/marionette/transport.js:500:20
[task 2021-08-25T05:35:55.648Z] 05:35:55     INFO - PID 28539 | JavaScript error: resource:///modules/sessionstore/TabStateFlusher.jsm, line 131: TypeError: can't access property "sendAsyncMessage", mm is null
[task 2021-08-25T05:35:55.649Z] 05:35:55     INFO - PID 28539 | JavaScript error: resource:///modules/Interactions.jsm, line 230: NS_ERROR_FAILURE: Component returned failure code: 0x80004005 (NS_ERROR_FAILURE) [nsIUserIdleService.removeIdleObserver]
[task 2021-08-25T05:35:57.277Z] 05:35:57     INFO - PID 28539 | ###!!! [Parent][RunMessage] Error: Channel closing: too late to send/recv, messages will be lost
[task 2021-08-25T05:36:02.556Z] 05:36:02     INFO - Browser exited with return code 0
[task 2021-08-25T05:36:02.558Z] 05:36:02     INFO - Closing logging queue
[task 2021-08-25T05:36:02.559Z] 05:36:02     INFO - queue closed
[task 2021-08-25T05:36:02.646Z] 05:36:02     INFO - INFO | runtests.py | TSan using symbolizer at /builds/worker/workspace/build/application/firefox/llvm-symbolizer
[task 2021-08-25T05:36:02.647Z] 05:36:02     INFO - Application command: /builds/worker/workspace/build/application/firefox/firefox --marionette about:blank -profile /tmp/tmpubjtmsxx
[task 2021-08-25T05:36:02.667Z] 05:36:02     INFO - PID 28820 | 1629869119126	Marionette	INFO	Marionette enabled
[task 2021-08-25T05:36:02.667Z] 05:36:02     INFO - PID 28820 | console.warn: SearchSettings: "get: No settings file exists, new profile?" (new NotFoundError("Could not open the file at /tmp/tmpteyqyhby/search.json.mozlz4", (void 0)))
[task 2021-08-25T05:36:02.668Z] 05:36:02     INFO - PID 28820 | 1629869143696	Marionette	INFO	Listening on port 42978
[task 2021-08-25T05:36:02.668Z] 05:36:02     INFO - PID 28820 | 1629869509184	addons.xpi	ERROR	System addon update list error Error: Failed downloading XML, status: 0, reason: error
[task 2021-08-25T05:36:02.669Z] 05:36:02     INFO - Starting runner
[task 2021-08-25T05:36:04.965Z] 05:36:04     INFO - TEST-START | /service-workers/service-worker/unregister-then-register-new-script.https.html

Comment 1

[Intermittent Failures Robot]

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

Repository breakdown:

• mozilla-central: 1

Platform and build breakdown:

• linux1804-64-tsan-qr: 1
  • opt: 1

For more details, see:
https://treeherder.mozilla.org/intermittent-failures/bugdetails?bug=1727486&startday=2021-08-23&endday=2021-08-29&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.

Comment 3

[Iulian Moraru]

Recent failure log: https://treeherder.mozilla.org/logviewer?job_id=357011171&repo=mozilla-central&lineNumber=4296

Comment 4

[Jens Stutte [:jstutte]]

What stands out in this log:

[task 2021-11-04T16:49:04.990Z] 16:49:04     INFO - Closing window 70541fc4-840f-476f-a7b3-3315fd56d083
[task 2021-11-04T16:49:05.141Z] 16:49:05     INFO - PID 9223 | ###!!! [Parent][RunMessage] Error: Channel closing: too late to send/recv, messages will be lost
[task 2021-11-04T16:49:05.344Z] 16:49:05     INFO - PID 9223 | [Parent 9223, IPC I/O Parent] WARNING: Failed to launch tab subprocess: file /builds/worker/checkouts/gecko/ipc/glue/GeckoChildProcessHost.cpp:750
[task 2021-11-04T16:49:05.351Z] 16:49:05     INFO - PID 9223 | JavaScript error: chrome://browser/content/tabbrowser.js, line 1909: NS_ERROR_ILLEGAL_VALUE: Component returned failure code: 0x80070057 (NS_ERROR_ILLEGAL_VALUE) [nsIWebProgress.removeProgressListener]
[task 2021-11-04T16:49:05.354Z] 16:49:05     INFO - PID 9223 | JavaScript error: chrome://browser/content/tabbrowser.js, line 1909: NS_ERROR_ILLEGAL_VALUE: Component returned failure code: 0x80070057 (NS_ERROR_ILLEGAL_VALUE) [nsIWebProgress.removeProgressListener]
[task 2021-11-04T16:49:05.543Z] 16:49:05     INFO - PID 9223 | 1636044545539	Marionette	ERROR	TypeError: can't access property "addMessageListener", this.mm is null(chrome://remote/content/marionette/dom.js:50:5) JS Stack trace: [e-mail]:50:5
[task 2021-11-04T16:49:05.544Z] 16:49:05     INFO - PID 9223 | [e-mail]:398:26

is that we:

• fail to launch a sub-process
• then get an NS_ERROR_ILLEGAL_VALUE (numerical identical to NS_ERROR_INVALID_ARG) probably coming from BrowsingContextWebProgress::RemoveProgressListener as we probably got a null filter here.

It feels as if we should have failed earlier after not being able to launch a sub-process?

Comment 5

[Jens Stutte [:jstutte]]

This seems to be followed by a frequent issue on a various number of tests finishing then with:

[task 2021-10-26T21:25:41.136Z] 21:25:41     INFO - PID 23855 | WARNING: A blocker encountered an error while we were waiting.
[task 2021-10-26T21:25:41.136Z] 21:25:41     INFO - PID 23855 |           Blocker:  SessionStore: flushing all windows
[task 2021-10-26T21:25:41.138Z] 21:25:41     INFO - PID 23855 |           Phase: quit-application-granted
[task 2021-10-26T21:25:41.140Z] 21:25:41     INFO - PID 23855 |           State: {"total":-1,"current":-1}

I assume this means we hit an exception while executing SessionStore: flushing all windows that makes throw that promise. I do not think that the single tests matter here.

Comment 6

[Intermittent Failures Robot]

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

Repository breakdown:

• mozilla-central: 1

Platform and build breakdown:

• linux1804-64-tsan-qr: 1
  • opt: 1

For more details, see:
https://treeherder.mozilla.org/intermittent-failures/bugdetails?bug=1727486&startday=2021-11-01&endday=2021-11-07&tree=all

Comment 7

[Randell Jesup [:jesup] (needinfo me)]

Yes, though I suspect it's an issue in the chrome JS code not getting notified that something down lower failed