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

Status: RESOLVED FIXED

(Core :: Networking: Cache, defect)

Description

[Honza Bambas (:mayhemer)]

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.

Comment 1

[Honza Bambas (:mayhemer)]

Still there.

https://tbpl.mozilla.org/?tree=Gum
https://tbpl.mozilla.org/php/getParsedLog.php?id=33431357&tree=Gum

Comment 2

[Honza Bambas (:mayhemer)]

https://tbpl.mozilla.org/?tree=Gum&rev=212b73f337ca

Comment 3

[Legacy TBPL/Treeherder Robot]

honzab.moz%firemni.cz
https://tbpl.mozilla.org/php/getParsedLog.php?id=33467302&tree=Gum
Rev5 MacOSX Mountain Lion 10.8 gum opt test mochitest-1 on 2014-01-23 09:00:00
revision: 212b73f337ca
slave: talos-mtnlion-r5-047

38411 ERROR TEST-UNEXPECTED-FAIL | /tests/content/base/test/test_bug602838.html | Test timed out.
38416 ERROR TEST-UNEXPECTED-FAIL | /tests/content/base/test/test_bug602838.html | The first script should have run
38417 ERROR TEST-UNEXPECTED-FAIL | /tests/content/base/test/test_bug602838.html | [SimpleTest.finish()] this test already called finish!
38418 ERROR TEST-UNEXPECTED-FAIL | /tests/content/base/test/test_bug602838.html | called finish() multiple times

Comment 4

[Honza Bambas (:mayhemer)]

FYI, this test is not stable with the new HTTP cache on.  I'm already trying to find out what's wrong.

Comment 5

[Honza Bambas (:mayhemer)]

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).

Comment 6

[Honza Bambas (:mayhemer)]

Or more probably that request for "script_bug602838.sjs" goes out later then xhr for "script_bug602838.sjs?unblock" ?

Comment 7

[Boris Zbarsky [: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?

Comment 8

[Honza Bambas (:mayhemer)]

(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.

Comment 9

[Boris Zbarsky [:bzbarsky]]

> 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...

Comment 10

[Honza Bambas (:mayhemer)]

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?

Comment 11

[Boris Zbarsky [:bzbarsky]]

Nah, we just rewrite the SJS to deal with the requests happening in any order.

Comment 12

[Honza Bambas (:mayhemer)]

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!

Comment 13

[Boris Zbarsky [:bzbarsky]]

Attachment: Maybe give this a shot?

Comment 14

[Honza Bambas (:mayhemer)]

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!

Comment 15

[Honza Bambas (:mayhemer)]

As of fix of 963703 this longer blocks cache2=on.

Comment 16

[Boris Zbarsky [:bzbarsky]]

https://hg.mozilla.org/integration/mozilla-inbound/rev/a71bfd1260bd

Comment 17

[Carsten Book [:Tomcat]]

https://hg.mozilla.org/mozilla-central/rev/a71bfd1260bd

Comment 18

[Ryan VanderMeulen [:RyanVM]]

(In reply to Boris Zbarsky [:bz] from comment #16)
> https://hg.mozilla.org/integration/mozilla-inbound/rev/a71bfd1260bd

This commit was empty?

Comment 19

[Boris Zbarsky [:bzbarsky]]

Argh.

I'll do another try run, I guess.  :(

Comment 20

[Legacy TBPL/Treeherder Robot]

:nigelb
https://tbpl.mozilla.org/php/getParsedLog.php?id=44583316&tree=Mozilla-Inbound
Android 4.0 Panda mozilla-inbound opt test mochitest-1 on 2014-07-25 01:03:21
revision: 5f1dc690c111
slave: panda-0283

3134 INFO TEST-UNEXPECTED-FAIL | /tests/content/base/test/test_bug602838.html | Test timed out.
3136 INFO TEST-UNEXPECTED-FAIL | /tests/content/base/test/test_bug602838.html | The first script should have run

Comment 21

[Boris Zbarsky [:bzbarsky]]

https://hg.mozilla.org/integration/mozilla-inbound/rev/f2a04ae4c4cf

Comment 22

[Carsten Book [:Tomcat]]

https://hg.mozilla.org/mozilla-central/rev/f2a04ae4c4cf

Comment 23

[Ryan VanderMeulen [:RyanVM]]

https://hg.mozilla.org/releases/mozilla-aurora/rev/add6dcab0ca7
https://hg.mozilla.org/releases/mozilla-beta/rev/97b81de9d1a5
https://hg.mozilla.org/releases/mozilla-esr31/rev/54d888f1d726
https://hg.mozilla.org/releases/mozilla-b2g30_v1_4/rev/0f28729cab90

Comment 24

[Ryan VanderMeulen [:RyanVM]]

https://hg.mozilla.org/releases/mozilla-b2g32_v2_0/rev/97b81de9d1a5