Intermittent test_fetch_event.html,test_https_fetch.html | Test timed out

RESOLVED FIXED in Firefox 39

Status

()

Core
DOM: Workers
RESOLVED FIXED
3 years ago
3 years ago

People

(Reporter: RyanVM, Assigned: bkelly)

Tracking

({intermittent-failure})

Trunk
mozilla40
ARM
Android
intermittent-failure
Points:
---
Dependency tree / graph
Bug Flags:
in-testsuite +

Firefox Tracking Flags

(firefox38 wontfix, firefox38.0.5 wontfix, firefox39 fixed, firefox40 fixed, firefox-esr31 unaffected, firefox-esr38 wontfix)

Details

Attachments

(2 attachments)

(Reporter)

Description

3 years ago
09:22:47 INFO - 117 INFO TEST-START | dom/workers/test/serviceworkers/test_fetch_event.html
09:22:47 INFO - 118 INFO TEST-UNEXPECTED-FAIL | dom/workers/test/serviceworkers/test_fetch_event.html | Test timed out. - expected PASS
09:22:47 INFO - 119 INFO TEST-OK | dom/workers/test/serviceworkers/test_fetch_event.html | took 331091ms
Comment hidden (Treeherder Robot)
(Assignee)

Updated

3 years ago
Blocks: 1059784
I suspect the same cause as bug 1031928.
Comment hidden (Treeherder Robot)
Comment hidden (Treeherder Robot)
Comment hidden (Treeherder Robot)
Comment hidden (Treeherder Robot)
Comment hidden (Treeherder Robot)
Comment hidden (Treeherder Robot)
Comment hidden (Treeherder Robot)
Comment hidden (Treeherder Robot)
Comment hidden (Treeherder Robot)
Comment hidden (Treeherder Robot)
Comment hidden (Treeherder Robot)
(Reporter)

Updated

3 years ago
Summary: Intermittent test_fetch_event.html | Test timed out → Intermittent test_fetch_event.html,test_https_fetch.html | Test timed out
Comment hidden (Treeherder Robot)
Comment hidden (Treeherder Robot)
Comment hidden (Treeherder Robot)
Comment hidden (Treeherder Robot)
Comment hidden (Treeherder Robot)
Comment hidden (Treeherder Robot)
Comment hidden (Treeherder Robot)
Comment hidden (Treeherder Robot)
Comment hidden (Treeherder Robot)
Comment hidden (Treeherder Robot)
Comment hidden (Treeherder Robot)
Comment hidden (Treeherder Robot)
Comment hidden (Treeherder Robot)
Comment hidden (Treeherder Robot)
Comment hidden (Treeherder Robot)
Comment hidden (Treeherder Robot)
Comment hidden (Treeherder Robot)
Comment hidden (Treeherder Robot)
Comment hidden (Treeherder Robot)
Comment hidden (Treeherder Robot)
Comment hidden (Treeherder Robot)
Comment hidden (Treeherder Robot)
Comment hidden (Treeherder Robot)
Comment hidden (Treeherder Robot)
Comment hidden (Treeherder Robot)
Comment hidden (Treeherder Robot)
Comment hidden (Treeherder Robot)
Comment hidden (Treeherder Robot)
Comment hidden (Treeherder Robot)
Comment hidden (Treeherder Robot)
Comment hidden (Treeherder Robot)
Comment hidden (Treeherder Robot)
Comment hidden (Treeherder Robot)
Comment hidden (Treeherder Robot)
Comment hidden (Treeherder Robot)
Comment hidden (Treeherder Robot)
Comment hidden (Treeherder Robot)
Comment hidden (Treeherder Robot)
Comment hidden (Treeherder Robot)
Comment hidden (Treeherder Robot)
Comment hidden (Treeherder Robot)
Comment hidden (Treeherder Robot)
Comment hidden (Treeherder Robot)
Comment hidden (Treeherder Robot)
Comment hidden (Treeherder Robot)
Comment hidden (Treeherder Robot)
Comment hidden (Treeherder Robot)
Comment hidden (Treeherder Robot)
Comment hidden (Treeherder Robot)
Comment hidden (Treeherder Robot)
Comment hidden (Treeherder Robot)
Comment hidden (Treeherder Robot)
Comment hidden (Treeherder Robot)
Comment hidden (Treeherder Robot)
Comment hidden (Treeherder Robot)
Comment hidden (Treeherder Robot)
Comment hidden (Treeherder Robot)
Comment hidden (Treeherder Robot)
Comment hidden (Treeherder Robot)
Comment hidden (Treeherder Robot)
Comment hidden (Treeherder Robot)
Comment hidden (Treeherder Robot)
Comment hidden (Treeherder Robot)
I think the spike yesterday/today was from bug 1154494.
Comment hidden (Treeherder Robot)
Comment hidden (Treeherder Robot)
Comment hidden (Treeherder Robot)
Comment hidden (Treeherder Robot)
Comment hidden (Treeherder Robot)
Comment hidden (Treeherder Robot)
Comment hidden (Treeherder Robot)
Comment hidden (Treeherder Robot)
Comment hidden (Treeherder Robot)
Comment hidden (Treeherder Robot)
Comment hidden (Treeherder Robot)
Comment hidden (Treeherder Robot)
Comment hidden (Treeherder Robot)
Comment hidden (Treeherder Robot)
Comment hidden (Treeherder Robot)
Comment hidden (Treeherder Robot)
Comment hidden (Treeherder Robot)
Comment hidden (Treeherder Robot)
Comment hidden (Treeherder Robot)
Comment hidden (Treeherder Robot)
Comment hidden (Treeherder Robot)
Comment hidden (Treeherder Robot)
Comment hidden (Treeherder Robot)
(Assignee)

Comment 101

3 years ago
Hmm, I see this in the log:

  JavaScript error: https://example.com/tests/dom/workers/test/serviceworkers/fetch/https/https_test.js, line 3: AbortError: The operation was aborted. 

The js its referring to is:

  self.addEventListener("install", function(event) {
    event.waitUntil(caches.open("cache").then(function(cache) {
      return cache.add("index.html");
    }));
  });

I wonder if the ServiceWorker is getting shut down too early and causing the cache to abort the add().
Comment hidden (Treeherder Robot)
(Assignee)

Updated

3 years ago
Depends on: 1160147
Comment hidden (Treeherder Robot)
Comment hidden (Treeherder Robot)
Comment hidden (Treeherder Robot)
Comment hidden (Treeherder Robot)
Comment hidden (Treeherder Robot)
Comment hidden (Treeherder Robot)
(Assignee)

Comment 109

3 years ago
Taking this for now as the log suggests its caused by something like bug 1160147.
Assignee: nobody → bkelly
Status: NEW → ASSIGNED
Comment hidden (Treeherder Robot)
Comment hidden (Treeherder Robot)
Comment hidden (Treeherder Robot)
Comment hidden (Treeherder Robot)
Comment hidden (Treeherder Robot)
Comment hidden (Treeherder Robot)
Comment hidden (Treeherder Robot)
Comment hidden (Treeherder Robot)
Comment hidden (Treeherder Robot)
(Assignee)

Comment 119

3 years ago
Unfortunately bug 1160147 does not seem to help.  Let me see if I can reproduce locally on a windows opt build.
(Assignee)

Comment 120

3 years ago
Actually, I got lucky and hit a trigger on a debug build in try:

13:52:34     INFO -  481 INFO TEST-START | dom/workers/test/serviceworkers/test_https_fetch.html
13:52:34     INFO -  ++DOMWINDOW == 35 (000000C6636A4400) [pid = 3348] [serial = 1036] [outer = 000000C66E769800]
13:52:34     INFO -  ++DOCSHELL 000000C65F044800 == 11 [pid = 3348] [id = 232]
13:52:34     INFO -  ++DOMWINDOW == 36 (000000C65EA5B400) [pid = 3348] [serial = 1037] [outer = 0000000000000000]
13:52:34     INFO -  [3348] WARNING: Subdocument container has no frame: file c:\builds\moz2_slave\try-w64-d-00000000000000000000\build\src\layout\base\nsDocumentViewer.cpp, line 2512
13:52:34     INFO -  ++DOMWINDOW == 37 (000000C66369C000) [pid = 3348] [serial = 1038] [outer = 000000C65EA5B400]
13:52:34     INFO -  [3348] WARNING: Subdocument container has no frame: file c:\builds\moz2_slave\try-w64-d-00000000000000000000\build\src\layout\base\nsDocumentViewer.cpp, line 2512
13:52:34     INFO -  ++DOMWINDOW == 38 (000000C6636A5000) [pid = 3348] [serial = 1039] [outer = 000000C65EA5B400]
13:52:36     INFO -  [3348] WARNING: Called close() before start()!: 'mStarted', file c:\builds\moz2_slave\try-w64-d-00000000000000000000\build\src\dom\workers\MessagePort.cpp, line 214
13:52:36     INFO -  [3348] WARNING: Called close() before start()!: 'mStarted', file c:\builds\moz2_slave\try-w64-d-00000000000000000000\build\src\dom\workers\MessagePort.cpp, line 214
13:52:36     INFO -  [3348] WARNING: Called close() before start()!: 'mStarted', file c:\builds\moz2_slave\try-w64-d-00000000000000000000\build\src\dom\workers\MessagePort.cpp, line 214
13:52:36     INFO -  [3348] WARNING: Called close() before start()!: 'mStarted', file c:\builds\moz2_slave\try-w64-d-00000000000000000000\build\src\dom\workers\MessagePort.cpp, line 214
13:52:36     INFO -  --DOMWINDOW == 37 (000000C66961F400) [pid = 3348] [serial = 1006] [outer = 0000000000000000] [url = http://mochi.test:8888/tests/dom/workers/test/serviceworkers/test_bug1151916.html]
13:52:36     INFO -  --DOMWINDOW == 36 (000000C668979000) [pid = 3348] [serial = 1025] [outer = 0000000000000000] [url = http://mochi.test:8888/tests/SimpleTest/iframe-between-tests.html]
13:52:36     INFO -  [3348] WARNING: Could not add WorkerFetchResolver feature to worker: file c:\builds\moz2_slave\try-w64-d-00000000000000000000\build\src\dom\fetch\Fetch.cpp, line 164
13:52:36     INFO -  [3348] WARNING: '!worker->AddFeature(worker->GetJSContext(), mFeature)', file c:\builds\moz2_slave\try-w64-d-00000000000000000000\build\src\dom\promise\Promise.cpp, line 1368
13:52:36     INFO -  JavaScript error: https://example.com/tests/dom/workers/test/serviceworkers/fetch/https/https_test.js, line 3: AbortError: The operation was aborted.
13:52:36     INFO -  [3348] WARNING: '!aInstallEventSuccess', file c:\builds\moz2_slave\try-w64-d-00000000000000000000\build\src\dom\workers\ServiceWorkerManager.cpp, line 835
13:52:36     INFO -  [3348] WARNING: 'NS_FAILED(aStatus)', file c:\builds\moz2_slave\try-w64-d-00000000000000000000\build\src\dom\workers\ServiceWorkerManager.cpp, line 136
13:52:36     INFO -  [3348] WARNING: ServiceWorkerJob failed with error: NS_ERROR_DOM_ABORT_ERR
13:52:36     INFO -  : file c:\builds\moz2_slave\try-w64-d-00000000000000000000\build\src\dom\workers\ServiceWorkerManager.cpp, line 142

So it seems the ServiceWorker is being shutdown even though there is a .waitUntil() in the test.
Comment hidden (Treeherder Robot)
(Assignee)

Comment 122

3 years ago
It seems we're not holding a reference to the ServiceWorker object while the `.waitUntil()` runs.  I think we need a strong ref to ensure we don't start the Worker shutdown.  In this case the Fetch() that Cache.add() does is getting aborted because it can't get a feature:

  WARNING: Could not add WorkerFetchResolver feature to worker: file c:\builds\moz2_slave\try-w64-d-00000000000000000000\build\src\dom\fetch\Fetch.cpp, line 164

Are we holding this ref in some way I'm not seeing?  Or do you agree its missing?  Any chance you could take this bug?  I don't know the lifecycle code very well.
No longer depends on: 1160147
Flags: needinfo?(nsm.nikhil)
(Assignee)

Comment 123

3 years ago
Hmm, maybe I just need to make LifecycleEventPromiseHandler require an ServiceWorker ref in its constructor so it can hold it alive.  I'll try that.
Comment hidden (Treeherder Robot)
(Assignee)

Comment 125

3 years ago
Created attachment 8600090 [details] [diff] [review]
Hold ServiceWorker alive during install event's waitUntil(). r=nsm

Candidate patch.  Lets see how it does in try:

 https://treeherder.mozilla.org/#/jobs?repo=try&revision=e142b1d9714d
Flags: needinfo?(nsm.nikhil)
(Assignee)

Comment 126

3 years ago
It also seems we don't handle .waitUntil() at all for event's other than install.
Comment hidden (Treeherder Robot)
Comment hidden (Treeherder Robot)
Comment hidden (Treeherder Robot)
Comment hidden (Treeherder Robot)
Comment hidden (Treeherder Robot)
Comment hidden (Treeherder Robot)
Comment hidden (Treeherder Robot)
Comment hidden (Treeherder Robot)
Comment hidden (Treeherder Robot)
Comment hidden (Treeherder Robot)
Comment hidden (Treeherder Robot)
Comment hidden (Treeherder Robot)
Comment hidden (Treeherder Robot)
Comment hidden (Treeherder Robot)
Comment hidden (Treeherder Robot)
Comment hidden (Treeherder Robot)
(Assignee)

Updated

3 years ago
Blocks: 1157219
Comment hidden (Treeherder Robot)
(Assignee)

Comment 144

3 years ago
Comment on attachment 8600090 [details] [diff] [review]
Hold ServiceWorker alive during install event's waitUntil(). r=nsm

Boris, do you mind looking at this since the usual suspects are out today?

Basically, the spec suggests that .waitUntil() should keep the ServiceWorker alive until the passed promise resolves:

  https://slightlyoff.github.io/ServiceWorker/spec/service_worker/index.html#wait-until-method

We do not currently hold a strong ref to the ServiceWorker object during this time, though.  So the Worker shutdown logic starts firing causing operations to abort.

This patch just makes sure the ref is held until the waitUntil() promise resolves.
Attachment #8600090 - Flags: review?(bzbarsky)
Comment on attachment 8600090 [details] [diff] [review]
Hold ServiceWorker alive during install event's waitUntil(). r=nsm

r=me
Attachment #8600090 - Flags: review?(bzbarsky) → review+
(Assignee)

Updated

3 years ago
Duplicate of this bug: 1152508
(Assignee)

Updated

3 years ago
See Also: → bug 1160527
Comment hidden (Treeherder Robot)
Comment hidden (Treeherder Robot)
Comment hidden (Treeherder Robot)
Comment hidden (Treeherder Robot)
Comment hidden (Treeherder Robot)
Comment hidden (Treeherder Robot)
Comment hidden (Treeherder Robot)
Comment hidden (Treeherder Robot)
Comment hidden (Treeherder Robot)
Comment hidden (Treeherder Robot)
Comment hidden (Treeherder Robot)
Comment hidden (Treeherder Robot)
Comment hidden (Treeherder Robot)
Comment hidden (Treeherder Robot)
Comment hidden (Treeherder Robot)
Comment hidden (Treeherder Robot)
Comment hidden (Treeherder Robot)
Comment hidden (Treeherder Robot)
Comment hidden (Treeherder Robot)
https://hg.mozilla.org/mozilla-central/rev/64f9806c4c16
Status: ASSIGNED → RESOLVED
Last Resolved: 3 years ago
status-firefox40: --- → fixed
Resolution: --- → FIXED
Target Milestone: --- → mozilla40
Comment hidden (Treeherder Robot)
Comment hidden (Treeherder Robot)
Comment hidden (Treeherder Robot)
Comment hidden (Treeherder Robot)
(Reporter)

Comment 172

3 years ago
Please request Aurora approval on this when you get a chance.
status-firefox38: --- → wontfix
status-firefox38.0.5: --- → wontfix
status-firefox39: --- → affected
status-firefox-esr31: --- → unaffected
status-firefox-esr38: --- → wontfix
Flags: needinfo?(bkelly)
(Assignee)

Comment 173

3 years ago
Comment on attachment 8600090 [details] [diff] [review]
Hold ServiceWorker alive during install event's waitUntil(). r=nsm

Approval Request Comment
[Feature/regressing bug #]: ServiceWorkers
[User impact if declined]: Lots of intermittent oranges in automation.
[Describe test coverage new/current, TreeHerder]: Existing ServiceWorker tests.
[Risks and why]: Low risk.  Its a very small patch in a non-release feature.  The patch appears to solve a very noisy intermittent in trunk.
[String/UUID change made/needed]: None
Flags: needinfo?(bkelly)
Attachment #8600090 - Flags: approval-mozilla-aurora?
Comment on attachment 8600090 [details] [diff] [review]
Hold ServiceWorker alive during install event's waitUntil(). r=nsm

Approved for uplift to aurora. Looks promising!
Attachment #8600090 - Flags: approval-mozilla-aurora? → approval-mozilla-aurora+

Updated

3 years ago
Duplicate of this bug: 1157901
(Reporter)

Comment 176

3 years ago
https://hg.mozilla.org/releases/mozilla-aurora/rev/19b46672d236
status-firefox39: affected → fixed
Flags: in-testsuite+
(Assignee)

Comment 178

3 years ago
Created attachment 8602416 [details] [diff] [review]
aurora patch

Ryan, here is an aurora patch.  I compiled it and ran tests locally in DEBUG.  Sorry I don't have time to test it further.
Flags: needinfo?(bkelly) → needinfo?(ryanvm)
(Assignee)

Comment 179

3 years ago
A try build as well, but I can't wait for it:

  https://treeherder.mozilla.org/#/jobs?repo=try&revision=8f861fab4000
(Assignee)

Updated

3 years ago
Flags: needinfo?(ryanvm)
You need to log in before you can comment on or make changes to this bug.