1588339 - Intermittent TEST-UNEXPECTED-TIMEOUT | /service-workers/service-worker/update-not-allowed.https.html | ServiceWorkerRegistration.update() from installing service worker throws. - Test timed out

Status: RESOLVED INCOMPLETE

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

Description

[Treeherder Bug Filer]

Filed by: dvarga [at] mozilla.com
Parsed log: https://treeherder.mozilla.org/logviewer.html#?job_id=271022508&repo=autoland
Full log: https://queue.taskcluster.net/v1/task/DUnc-6TLRyeK2ehTq-3uFA/runs/0/artifacts/public/logs/live_backing.log

---

[task 2019-10-12T20:43:24.545Z] 20:43:24     INFO - TEST-PASS | /service-workers/service-worker/update-not-allowed.https.html | ServiceWorkerRegistration.update() from client succeeds while installing service worker. 
[task 2019-10-12T20:43:24.545Z] 20:43:24     INFO - TEST-UNEXPECTED-TIMEOUT | /service-workers/service-worker/update-not-allowed.https.html | ServiceWorkerRegistration.update() from installing service worker throws. - Test timed out
[task 2019-10-12T20:43:24.546Z] 20:43:24     INFO - 
[task 2019-10-12T20:43:24.546Z] 20:43:24     INFO - TEST-UNEXPECTED-NOTRUN | /service-workers/service-worker/update-not-allowed.https.html | ServiceWorkerRegistration.update() from active service worker succeeds while installing service worker. - expected PASS
[task 2019-10-12T20:43:24.546Z] 20:43:24     INFO - TEST-UNEXPECTED-TIMEOUT | /service-workers/service-worker/update-not-allowed.https.html | expected ERROR
[task 2019-10-12T20:43:24.546Z] 20:43:24     INFO - TEST-INFO expected ERROR | took 30613ms
[task 2019-10-12T20:43:24.567Z] 20:43:24     INFO - PID 22200 | 1570913004562	Marionette	INFO	Stopped listening on port 53028
[task 2019-10-12T20:43:24.644Z] 20:43:24     INFO - PID 22200 | --DOCSHELL 0x7ff57f386800 == 2 [pid = 22267] [id = {90f0bc69-6ce4-47c1-83a8-9610403b1f71}] [url = moz-extension://3dbc59c3-bdcf-4780-91be-1d35cf35e92e/_generated_background_page.html]
[task 2019-10-12T20:43:24.644Z] 20:43:24     INFO - PID 22200 | --DOCSHELL 0x7ff56581f000 == 1 [pid = 22267] [id = {b1489c87-86f9-42c7-b04b-2827b31a72f7}] [url = moz-extension://50b66cb1-480d-4fe5-b7a8-959cca499d41/_generated_background_page.html]
[task 2019-10-12T20:43:24.644Z] 20:43:24     INFO - PID 22200 | --DOCSHELL 0x7ff564fcb800 == 0 [pid = 22267] [id = {2f67545b-5874-4be0-a4d0-e7c1062eef9d}] [url = moz-extension://59fddd4a-f1df-4117-8195-9757c9b2b178/_generated_background_page.html]
[task 2019-10-12T20:43:24.789Z] 20:43:24     INFO - PID 22200 | ###!!! [Parent][RunMessage] Error: Channel closing: too late to send/recv, messages will be lost
[task 2019-10-12T20:43:24.825Z] 20:43:24     INFO - PID 22200 | --DOCSHELL 0x7fc14150b000 == 3 [pid = 22200] [id = {b0cb4832-09e6-40c1-9e52-5fe2f726af39}] [url = resource://gre-resources/hiddenWindow.html]
[task 2019-10-12T20:43:24.825Z] 20:43:24     INFO - PID 22200 | --DOCSHELL 0x7fc148503800 == 2 [pid = 22200] [id = {bfe02f73-39b5-4a60-813a-f22ff5b12425}] [url = chrome://extensions/content/dummy.xul]
[task 2019-10-12T20:43:24.826Z] 20:43:24     INFO - PID 22200 | --DOCSHELL 0x7fc145159000 == 1 [pid = 22200] [id = {8b5f0e9f-f1ec-4da9-a110-a06ea7d45684}] [url = about:blank]
[task 2019-10-12T20:43:24.882Z] 20:43:24     INFO - PID 22200 | --DOCSHELL 0x7f4c5f2c6000 == 0 [pid = 29201] [id = {34ec9272-8695-4113-a28b-18d3fe8f2426}] [url = https://web-platform.test:8443/service-workers/service-worker/update-not-allowed.https.html]
[task 2019-10-12T20:43:24.930Z] 20:43:24     INFO - PID 22200 | [2019-10-12T20:43:24Z WARN  xulstore::persist] tried to remove key that isn't in the store
[task 2019-10-12T20:43:24.930Z] 20:43:24     INFO - PID 22200 | [2019-10-12T20:43:24Z WARN  xulstore::persist] tried to remove key that isn't in the store
[task 2019-10-12T20:43:24.937Z] 20:43:24     INFO - PID 22200 | --DOMWINDOW == 1 (0x7f4c5faafc00) [pid = 29201] [serial = 4] [outer = (nil)] [url = https://web-platform.test:8443/service-workers/service-worker/update-not-allowed.https.html]
[task 2019-10-12T20:43:24.938Z] 20:43:24     INFO - PID 22200 | --DOMWINDOW == 0 (0x7f4c5f219f20) [pid = 29201] [serial = 1] [outer = (nil)] [url = https://web-platform.test:8443/service-workers/service-worker/update-not-allowed.https.html]
[task 2019-10-12T20:43:24.953Z] 20:43:24     INFO - PID 22200 | --DOMWINDOW == 5 (0x7ff566ae53e0) [pid = 22267] [serial = 5] [outer = (nil)] [url = moz-extension://3dbc59c3-bdcf-4780-91be-1d35cf35e92e/_generated_background_page.html]
[task 2019-10-12T20:43:24.954Z] 20:43:24     INFO - PID 22200 | --DOMWINDOW == 4 (0x7ff566ae66a0) [pid = 22267] [serial = 3] [outer = (nil)] [url = moz-extension://50b66cb1-480d-4fe5-b7a8-959cca499d41/_generated_background_page.html]
[task 2019-10-12T20:43:24.954Z] 20:43:24     INFO - PID 22200 | --DOMWINDOW == 3 (0x7ff566ae64c0) [pid = 22267] [serial = 1] [outer = (nil)] [url = moz-extension://59fddd4a-f1df-4117-8195-9757c9b2b178/_generated_background_page.html]
[task 2019-10-12T20:43:24.955Z] 20:43:24     INFO - PID 22200 | --DOMWINDOW == 2 (0x7ff566a19400) [pid = 22267] [serial = 9] [outer = (nil)] [url = moz-extension://59fddd4a-f1df-4117-8195-9757c9b2b178/_generated_background_page.html]
[task 2019-10-12T20:43:24.955Z] 20:43:24     INFO - PID 22200 | --DOMWINDOW == 1 (0x7ff566c88c00) [pid = 22267] [serial = 10] [outer = (nil)] [url = moz-extension://50b66cb1-480d-4fe5-b7a8-959cca499d41/_generated_background_page.html]
[task 2019-10-12T20:43:24.955Z] 20:43:24     INFO - PID 22200 | --DOMWINDOW == 0 (0x7ff566c8ac00) [pid = 22267] [serial = 11] [outer = (nil)] [url = moz-extension://3dbc59c3-bdcf-4780-91be-1d35cf35e92e/_generated_background_page.html]
[task 2019-10-12T20:43:24.970Z] 20:43:24     INFO - PID 22200 | nsStringStats
[task 2019-10-12T20:43:24.970Z] 20:43:24     INFO - PID 22200 |  => mAllocCount:           9257
[task 2019-10-12T20:43:24.971Z] 20:43:24     INFO - PID 22200 |  => mReallocCount:            0
[task 2019-10-12T20:43:24.974Z] 20:43:24     INFO - PID 22200 |  => mFreeCount:            9257
[task 2019-10-12T20:43:24.974Z] 20:43:24     INFO - PID 22200 |  => mShareCount:           9310
[task 2019-10-12T20:43:24.974Z] 20:43:24     INFO - PID 22200 |  => mAdoptCount:            603
[task 2019-10-12T20:43:24.974Z] 20:43:24     INFO - PID 22200 |  => mAdoptFreeCount:        623
[task 2019-10-12T20:43:24.974Z] 20:43:24     INFO - PID 22200 |  => Process ID: 29201, Thread ID: 139966455072576
[task 2019-10-12T20:43:24.974Z] 20:43:24     INFO - PID 22200 | nsStringStats
[task 2019-10-12T20:43:24.974Z] 20:43:24     INFO - PID 22200 |  => mAllocCount:          16428
[task 2019-10-12T20:43:24.974Z] 20:43:24     INFO - PID 22200 |  => mReallocCount:            0
[task 2019-10-12T20:43:24.974Z] 20:43:24     INFO - PID 22200 |  => mFreeCount:           16428
[task 2019-10-12T20:43:24.974Z] 20:43:24     INFO - PID 22200 |  => mShareCount:           9657
[task 2019-10-12T20:43:24.974Z] 20:43:24     INFO - PID 22200 |  => mAdoptCount:            389
[task 2019-10-12T20:43:24.975Z] 20:43:24     INFO - PID 22200 |  => mAdoptFreeCount:        413
[task 2019-10-12T20:43:24.975Z] 20:43:24     INFO - PID 22200 |  => Process ID: 22267, Thread ID: 140692401751872
[task 2019-10-12T20:43:26.643Z] 20:43:26     INFO - PID 22200 | [Parent 22200, Main Thread] WARNING: 'NS_FAILED(rv)', file /builds/worker/workspace/build/src/dom/xhr/XMLHttpRequestMainThread.cpp, line 2646
[task 2019-10-12T20:43:32.844Z] 20:43:32     INFO - PID 22200 | --DOCSHELL 0x7f7691bc5800 == 1 [pid = 22295] [id = {428cfc3d-d117-40a5-bd1b-93bfbf785d8c}] [url = https://web-platform.test:8443/testharness_runner.html]
[task 2019-10-12T20:43:32.961Z] 20:43:32     INFO - PID 22200 | --DOMWINDOW == 4 (0x7f76937ee2e0) [pid = 22295] [serial = 5] [outer = (nil)] [url = about:newtab]
[task 2019-10-12T20:43:32.961Z] 20:43:32     INFO - PID 22200 | --DOMWINDOW == 3 (0x7f76937edf20) [pid = 22295] [serial = 1] [outer = (nil)] [url = https://web-platform.test:8443/testharness_runner.html]
[task 2019-10-12T20:43:32.961Z] 20:43:32     INFO - PID 22200 | --DOCSHELL 0x7f7691b8d000 == 0 [pid = 22295] [id = {9eec31b1-01ab-4c6d-ad8d-fded690d52f7}] [url = about:newtab]
[task 2019-10-12T20:43:34.822Z] 20:43:34     INFO - PID 22200 | WARNING: At least one completion condition is taking too long to complete. Conditions: [{"name":"ServiceWorkerShutdownBlocker: shutting down Service Workers","state":{"pendingPromises":2,"acceptingPromises":false},"filename":"/builds/worker/workspace/build/src/dom/serviceworkers/ServiceWorkerShutdownBlocker.cpp","lineNumber":82,"stack":"Service Workers shutdown"}] Barrier: profile-change-teardown
[task 2019-10-12T20:43:36.946Z] 20:43:36     INFO - PID 22200 | --DOMWINDOW == 2 (0x7f76ac0d7000) [pid = 22295] [serial = 8] [outer = (nil)] [url = http://web-platform.test:8000/testharness_runner.html]
[task 2019-10-12T20:43:36.946Z] 20:43:36     INFO - PID 22200 | --DOMWINDOW == 1 (0x7f7691783c00) [pid = 22295] [serial = 9] [outer = (nil)] [url = https://web-platform.test:8443/testharness_runner.html]
[task 2019-10-12T20:43:36.946Z] 20:43:36     INFO - PID 22200 | --DOMWINDOW == 0 (0x7f769371a000) [pid = 22295] [serial = 7] [outer = (nil)] [url = about:newtab]
[task 2019-10-12T20:43:39.782Z] 20:43:39     INFO - PID 22200 | console.error: (new Error("SessionFile is closed", "resource:///modules/sessionstore/SessionFile.jsm", 433))
[task 2019-10-12T20:44:25.826Z] 20:44:25     INFO - PID 22200 | FATAL ERROR: AsyncShutdown timeout in profile-change-teardown Conditions: [{"name":"ServiceWorkerShutdownBlocker: shutting down Service Workers","state":{"pendingPromises":2,"acceptingPromises":false},"filename":"/builds/worker/workspace/build/src/dom/serviceworkers/ServiceWorkerShutdownBlocker.cpp","lineNumber":82,"stack":"Service Workers shutdown"}] At least one completion condition failed to complete within a reasonable amount of time. Causing a crash to ensure that we do not leave the user with an unresponsive process draining resources.
[task 2019-10-12T20:44:25.826Z] 20:44:25     INFO - PID 22200 | [Parent 22200, Main Thread] ###!!! ABORT: file /builds/worker/workspace/build/src/dom/serviceworkers/ServiceWorkerShutdownBlocker.cpp, line 82
[task 2019-10-12T20:44:48.991Z] 20:44:48     INFO - PID 22200 | #01: NS_InvokeByIndex
[task 2019-10-12T20:44:48.991Z] 20:44:48     INFO - 
[task 2019-10-12T20:44:48.991Z] 20:44:48     INFO - PID 22200 | #02: CallMethodHelper::Call() [js/xpconnect/src/XPCWrappedNative.cpp:1183]
[task 2019-10-12T20:44:48.991Z] 20:44:48     INFO - 
[task 2019-10-12T20:44:48.992Z] 20:44:48     INFO - PID 22200 | #03: XPCWrappedNative::CallMethod(XPCCallContext&, XPCWrappedNative::CallMode) [js/xpconnect/src/XPCWrappedNative.cpp:1149]
[task 2019-10-12T20:44:48.992Z] 20:44:48     INFO - 
[task 2019-10-12T20:44:48.992Z] 20:44:48     INFO - PID 22200 | #04: XPC_WN_CallMethod(JSContext*, unsigned int, JS::Value*) [js/xpconnect/src/XPCWrappedNativeJSOps.cpp:946]

Comment 1

[Intermittent Failures Robot]

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

Repository breakdown:

• autoland: 1

Platform breakdown:

• linux64: 1

For more details, see:
https://treeherder.mozilla.org/intermittent-failures.html#/bugdetails?bug=1588339&startday=2019-10-07&endday=2019-10-13&tree=all

Comment 2

[Intermittent Failures Robot]

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

Repository breakdown:

• autoland: 1

Platform breakdown:

• linux64: 1

For more details, see:
https://treeherder.mozilla.org/intermittent-failures.html#/bugdetails?bug=1588339&startday=2019-10-14&endday=2019-10-20&tree=all

Comment 3

[Intermittent Failures Robot]

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

Repository breakdown:

• autoland: 1

Platform breakdown:

• linux64: 1

For more details, see:
https://treeherder.mozilla.org/intermittent-failures.html#/bugdetails?bug=1588339&startday=2019-10-28&endday=2019-11-03&tree=all

Comment 4

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

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