Intermittent (osx8 opt m1) test_bug602838.html | The first script should have run

RESOLVED FIXED in Firefox 32

Status

()

defect
RESOLVED FIXED
6 years ago
5 years ago

People

(Reporter: mayhemer, Assigned: bzbarsky)

Tracking

({intermittent-failure})

Other Branch
mozilla34
All
macOS
Points:
---

Firefox Tracking Flags

(firefox31 wontfix, firefox32 fixed, firefox33 fixed, firefox34 fixed, firefox-esr24 unaffected, firefox-esr31 fixed, b2g-v1.4 fixed, b2g-v2.0 fixed, b2g-v2.1 fixed)

Details

Attachments

(1 attachment)

38354 ERROR TEST-UNEXPECTED-FAIL | /tests/content/base/test/test_bug602838.html | The first script should have run
https://hg.mozilla.org/projects/gum/rev/f53229bb6090
https://tbpl.mozilla.org/php/getParsedLog.php?id=32622053&tree=Try&full=1
M(1)

Not a dupe of bug 945189, it has been fixed for this cs.
Blocks: cache2tests
No longer blocks: cache2enable
Summary: HTTP cache v2: test_bug602838.html | The first script should have run → HTTP cache v2: (osx8 opt m1) test_bug602838.html | The first script should have run
Status: NEW → RESOLVED
Closed: 6 years ago
Resolution: --- → FIXED
Resolution: FIXED → WORKSFORME
Still there.

https://tbpl.mozilla.org/?tree=Gum
https://tbpl.mozilla.org/php/getParsedLog.php?id=33431357&tree=Gum
Status: RESOLVED → REOPENED
Resolution: WORKSFORME → ---
Status: REOPENED → NEW
Summary: HTTP cache v2: (osx8 opt m1) test_bug602838.html | The first script should have run → HTTP cache v2: Intermittent (osx8 opt m1) test_bug602838.html | The first script should have run
FYI, this test is not stable with the new HTTP cache on.  I'm already trying to find out what's wrong.
Hmm.. better look into the test log shows this interesting thing:

09:09:04     INFO -  38410 INFO TEST-PASS | /tests/content/base/test/test_bug602838.html | Non-async should not have run yet.
09:09:04     INFO -  *** error running SJS at /builds/slave/talos-slave/test/build/tests/mochitest/tests/content/base/test/script_bug602838.sjs: TypeError: x is null on line 5
09:14:14     INFO -  libpng warning: zero length keyword
09:14:14     INFO -  libpng warning: Empty language field in iTXt chunk
09:14:20     INFO -  SCREENSHOT: data:image/png;base64,iVBORw0KGgo....
09:14:20     INFO -  38411 ERROR TEST-UNEXPECTED-FAIL | /tests/content/base/test/test_bug602838.html | Test timed out.

What means that the request for "script_bug602838.sjs" has not been made yet (has not arrived to httpd.js).
Or more probably that request for "script_bug602838.sjs" goes out later then xhr for "script_bug602838.sjs?unblock" ?
Flags: needinfo?(bzbarsky)
We ask necko for that first one first.  Are they getting reordered with the new cache because we do some sort of (async) cache lookup for the former but not the latter or something?
Flags: needinfo?(bzbarsky)
(In reply to Boris Zbarsky [:bz] from comment #7)
> We ask necko for that first one first.  Are they getting reordered with the
> new cache because we do some sort of (async) cache lookup for the former but
> not the latter or something?

Not sure but most has changed with the new cache and in some cases the cache goes forward synchronously.  I am not sure where you have heard that we process/send requests in the same order as they are requested from the upper levels.
> I am not sure where you have heard that we process/send requests in the same order as
> they are requested from the upper levels.

We obviously don't in general, because of channel priorities.  But in practice right now we do.

we should probably modify this test to handle this race, though...
Confirmed locally there is a (strong) possibility that XHR request will go out sooner then the script request since XHR is being looked up in the cache with OPEN_PRIORITY flag, so that the related cache entry may be open sooner then the entry for the script.  Opening cache entry is the main blocker before we send the request.  OPEN_PRIORITY is an important performance feature of the new cache.

I don't know how exactly to synchronize this, probably we may use an image with onload handler that will trigger the 'unblock()' function?
Nah, we just rewrite the SJS to deal with the requests happening in any order.
Different solution - made in the cache, however I think the test is not correct anyway: XHR is set loadUnblocked flag and I use it for setting the priority. But when reading carefully how this flag is used, seems like it's not an indication for a priority load.  It's something I should consider in general, fact that it fixes this intermittent test failure is a side product!
Depends on: 963703
Comment on attachment 8365249 [details] [diff] [review]
Maybe give this a shot?

Review of attachment 8365249 [details] [diff] [review]:
-----------------------------------------------------------------

Seems like this should work, tested locally, but only for the "correct order" case.  Thanks!
Attachment #8365249 - Flags: review+
No longer depends on: 963703
As of fix of 963703 this longer blocks cache2=on.
No longer blocks: cache2tests
Summary: HTTP cache v2: Intermittent (osx8 opt m1) test_bug602838.html | The first script should have run → Intermittent (osx8 opt m1) test_bug602838.html | The first script should have run
https://hg.mozilla.org/mozilla-central/rev/a71bfd1260bd
Status: NEW → RESOLVED
Closed: 6 years ago5 years ago
Resolution: --- → FIXED
Target Milestone: --- → mozilla34
(In reply to Boris Zbarsky [:bz] from comment #16)
> https://hg.mozilla.org/integration/mozilla-inbound/rev/a71bfd1260bd

This commit was empty?
Status: RESOLVED → REOPENED
Flags: needinfo?(bzbarsky)
Resolution: FIXED → ---
Target Milestone: mozilla34 → ---
Argh.

I'll do another try run, I guess.  :(
https://hg.mozilla.org/mozilla-central/rev/f2a04ae4c4cf
Status: REOPENED → RESOLVED
Closed: 5 years ago5 years ago
Resolution: --- → FIXED
Target Milestone: --- → mozilla34
QA Whiteboard: [qa-]
You need to log in before you can comment on or make changes to this bug.