Closed Bug 1134841 Opened 9 years ago Closed 9 years ago

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

Categories

(Core :: DOM: Workers, defect)

ARM
Android
defect
Not set
normal

Tracking

()

RESOLVED FIXED
mozilla40
Tracking Status
firefox38 --- wontfix
firefox38.0.5 --- wontfix
firefox39 --- fixed
firefox40 --- fixed
firefox-esr31 --- unaffected
firefox-esr38 --- wontfix

People

(Reporter: RyanVM, Assigned: bkelly)

References

Details

(Keywords: intermittent-failure)

Attachments

(2 files)

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
I suspect the same cause as bug 1031928.
Summary: Intermittent test_fetch_event.html | Test timed out → Intermittent test_fetch_event.html,test_https_fetch.html | Test timed out
I think the spike yesterday/today was from bug 1154494.
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().
Depends on: 1160147
Taking this for now as the log suggests its caused by something like bug 1160147.
Assignee: nobody → bkelly
Status: NEW → ASSIGNED
Unfortunately bug 1160147 does not seem to help.  Let me see if I can reproduce locally on a windows opt build.
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.
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)
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.
It also seems we don't handle .waitUntil() at all for event's other than install.
Blocks: 1157219
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+
See Also: → 1160527
https://hg.mozilla.org/mozilla-central/rev/64f9806c4c16
Status: ASSIGNED → RESOLVED
Closed: 9 years ago
Resolution: --- → FIXED
Target Milestone: --- → mozilla40
Please request Aurora approval on this when you get a chance.
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+
Attached patch aurora patchSplinter Review
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)
Flags: needinfo?(ryanvm)
You need to log in before you can comment on or make changes to this bug.