Closed Bug 1055580 Opened 6 years ago Closed 5 years ago

Intermittent test_cache2-14b-concurent-readers-complete.js | 1 == 3 | 2 == 1 | 3 == 2

Categories

(Core :: Networking: Cache, defect)

x86_64
macOS
defect
Not set

Tracking

()

RESOLVED FIXED
mozilla36
Tracking Status
firefox34 --- fixed
firefox35 --- fixed
firefox36 --- fixed
firefox-esr31 --- unaffected

People

(Reporter: emorley, Assigned: mayhemer)

References

Details

(Keywords: intermittent-failure)

Attachments

(1 file)

Rev4 MacOSX Snow Leopard 10.6 mozilla-central opt test xpcshell on 2014-08-19 04:51:22 PDT for push 111a1da2a95d

slave: t-snow-r4-0108

https://tbpl.mozilla.org/php/getParsedLog.php?id=46252889&tree=Mozilla-Central

{
05:11:48     INFO -  Retrying tests that failed when run in parallel.
05:11:48     INFO -  TEST-INFO | /builds/slave/talos-slave/test/build/tests/xpcshell/tests/netwerk/test/unit/test_cache2-14b-concurent-readers-complete.js | running test ...
05:11:48  WARNING -  TEST-UNEXPECTED-FAIL | /builds/slave/talos-slave/test/build/tests/xpcshell/tests/netwerk/test/unit/test_cache2-14b-concurent-readers-complete.js | test failed (with xpcshell return code: 0), see following log:
05:11:48     INFO -  >>>>>>>
05:11:48     INFO -  TEST-INFO | (xpcshell/head.js) | test MAIN run_test pending (1)
05:11:48     INFO -  TEST-INFO | CACHE2: callback #1(x1d) onCacheEntryAvailable, 1
05:11:48     INFO -  TEST-PASS | /builds/slave/talos-slave/test/build/tests/xpcshell/tests/netwerk/test/unit/head_cache2.js | [OpenCallback.prototype.onCacheEntryAvailable : 152] true == true
05:11:48     INFO -  TEST-PASS | /builds/slave/talos-slave/test/build/tests/xpcshell/tests/netwerk/test/unit/head_cache2.js | [OpenCallback.prototype.onCacheEntryAvailable : 155] true == true
05:11:48     INFO -  TEST-PASS | /builds/slave/talos-slave/test/build/tests/xpcshell/tests/netwerk/test/unit/head_cache2.js | [OpenCallback.prototype.onCacheEntryAvailable : 165] true == true
05:11:48     INFO -  TEST-INFO | (xpcshell/head.js) | test pending (2)
05:11:48     INFO -  TEST-INFO | (xpcshell/head.js) | test pending (3)
05:11:48     INFO -  TEST-INFO | (xpcshell/head.js) | test MAIN run_test finished (3)
05:11:48     INFO -  TEST-INFO | (xpcshell/head.js) | running event loop
05:11:48     INFO -  TEST-INFO | CACHE2: callback #2(x1d) onCacheEntryCheck
05:11:48     INFO -  TEST-PASS | /builds/slave/talos-slave/test/build/tests/xpcshell/tests/netwerk/test/unit/head_cache2.js | [OpenCallback.prototype.onCacheEntryCheck : 107] true == true
05:11:48     INFO -  TEST-PASS | /builds/slave/talos-slave/test/build/tests/xpcshell/tests/netwerk/test/unit/head_cache2.js | [OpenCallback.prototype.onCacheEntryCheck : 120] "x1m" == "x1m"
05:11:48     INFO -  TEST-PASS | /builds/slave/talos-slave/test/build/tests/xpcshell/tests/netwerk/test/unit/head_cache2.js | [OpenCallback.prototype.onCacheEntryCheck : 123] 0 != 96
05:11:48     INFO -  TEST-INFO | CACHE2: callback #2(x1d) onCacheEntryCheck DONE, return RECHECK_AFTER_WRITE_FINISHED
05:11:48     INFO -  TEST-INFO | CACHE2: callback #3(x1d) onCacheEntryCheck
05:11:48     INFO -  TEST-PASS | /builds/slave/talos-slave/test/build/tests/xpcshell/tests/netwerk/test/unit/head_cache2.js | [OpenCallback.prototype.onCacheEntryCheck : 107] true == true
05:11:48     INFO -  TEST-PASS | /builds/slave/talos-slave/test/build/tests/xpcshell/tests/netwerk/test/unit/head_cache2.js | [OpenCallback.prototype.onCacheEntryCheck : 120] "x1m" == "x1m"
05:11:48     INFO -  TEST-PASS | /builds/slave/talos-slave/test/build/tests/xpcshell/tests/netwerk/test/unit/head_cache2.js | [OpenCallback.prototype.onCacheEntryCheck : 123] 0 != 96
05:11:48     INFO -  TEST-INFO | CACHE2: callback #3(x1d) onCacheEntryCheck DONE, return ENTRY_WANTED
05:11:48     INFO -  TEST-INFO | CACHE2: callback #3(x1d) onCacheEntryAvailable, 0
05:11:48     INFO -  TEST-PASS | /builds/slave/talos-slave/test/build/tests/xpcshell/tests/netwerk/test/unit/head_cache2.js | [OpenCallback.prototype.onCacheEntryAvailable : 152] true == true
05:11:48     INFO -  TEST-PASS | /builds/slave/talos-slave/test/build/tests/xpcshell/tests/netwerk/test/unit/head_cache2.js | [OpenCallback.prototype.onCacheEntryAvailable : 155] false == false
05:11:48     INFO -  TEST-PASS | /builds/slave/talos-slave/test/build/tests/xpcshell/tests/netwerk/test/unit/head_cache2.js | [OpenCallback.prototype.onCacheEntryAvailable : 236] true == true
05:11:48     INFO -  TEST-PASS | /builds/slave/talos-slave/test/build/tests/xpcshell/tests/netwerk/test/unit/head_cache2.js | [OpenCallback.prototype.onCacheEntryAvailable : 237] "x1m" == "x1m"
05:11:48     INFO -  TEST-INFO | CACHE2: callback #4(x1d) onCacheEntryCheck
05:11:48     INFO -  TEST-PASS | /builds/slave/talos-slave/test/build/tests/xpcshell/tests/netwerk/test/unit/head_cache2.js | [OpenCallback.prototype.onCacheEntryCheck : 107] true == true
05:11:48     INFO -  TEST-PASS | /builds/slave/talos-slave/test/build/tests/xpcshell/tests/netwerk/test/unit/head_cache2.js | [OpenCallback.prototype.onCacheEntryCheck : 120] "x1m" == "x1m"
05:11:48     INFO -  TEST-PASS | /builds/slave/talos-slave/test/build/tests/xpcshell/tests/netwerk/test/unit/head_cache2.js | [OpenCallback.prototype.onCacheEntryCheck : 123] 0 != 96
05:11:48     INFO -  TEST-INFO | CACHE2: callback #4(x1d) onCacheEntryCheck DONE, return ENTRY_WANTED
05:11:48     INFO -  TEST-INFO | CACHE2: callback #4(x1d) onCacheEntryAvailable, 0
05:11:48     INFO -  TEST-PASS | /builds/slave/talos-slave/test/build/tests/xpcshell/tests/netwerk/test/unit/head_cache2.js | [OpenCallback.prototype.onCacheEntryAvailable : 152] true == true
05:11:48     INFO -  TEST-PASS | /builds/slave/talos-slave/test/build/tests/xpcshell/tests/netwerk/test/unit/head_cache2.js | [OpenCallback.prototype.onCacheEntryAvailable : 155] false == false
05:11:48     INFO -  TEST-PASS | /builds/slave/talos-slave/test/build/tests/xpcshell/tests/netwerk/test/unit/head_cache2.js | [OpenCallback.prototype.onCacheEntryAvailable : 236] true == true
05:11:48     INFO -  TEST-PASS | /builds/slave/talos-slave/test/build/tests/xpcshell/tests/netwerk/test/unit/head_cache2.js | [OpenCallback.prototype.onCacheEntryAvailable : 237] "x1m" == "x1m"
05:11:48     INFO -  TEST-INFO | (xpcshell/head.js) | test pending (3)
05:11:48     INFO -  TEST-INFO | (xpcshell/head.js) | test finished (3)
05:11:48     INFO -  TEST-INFO | CACHE2: callback #1(x1d) openOutputStream @ 0
05:11:48     INFO -  TEST-INFO | CACHE2: callback #1(x1d) writing data
05:11:48     INFO -  TEST-PASS | /builds/slave/talos-slave/test/build/tests/xpcshell/tests/netwerk/test/unit/head_cache2.js | [OpenCallback.prototype.onCacheEntryAvailable/</< : 226] 3 == 3
05:11:48     INFO -  TEST-INFO | (xpcshell/head.js) | test finished (2)
05:11:48     INFO -  TEST-INFO | CACHE2: callback #2(x1d) onCacheEntryCheck
05:11:48     INFO -  TEST-PASS | /builds/slave/talos-slave/test/build/tests/xpcshell/tests/netwerk/test/unit/head_cache2.js | [OpenCallback.prototype.onCacheEntryCheck : 107] true == true
05:11:48     INFO -  TEST-PASS | /builds/slave/talos-slave/test/build/tests/xpcshell/tests/netwerk/test/unit/head_cache2.js | [OpenCallback.prototype.onCacheEntryCheck : 120] "x1m" == "x1m"
05:11:48     INFO -  TEST-PASS | /builds/slave/talos-slave/test/build/tests/xpcshell/tests/netwerk/test/unit/head_cache2.js | [OpenCallback.prototype.onCacheEntryCheck : 123] 0 != 96
05:11:48     INFO -  TEST-INFO | CACHE2: callback #2(x1d) onCacheEntryCheck DONE, return ENTRY_WANTED
05:11:48     INFO -  TEST-INFO | CACHE2: callback #2(x1d) onCacheEntryAvailable, 0
05:11:48     INFO -  TEST-PASS | /builds/slave/talos-slave/test/build/tests/xpcshell/tests/netwerk/test/unit/head_cache2.js | [OpenCallback.prototype.onCacheEntryAvailable : 152] true == true
05:11:48     INFO -  TEST-PASS | /builds/slave/talos-slave/test/build/tests/xpcshell/tests/netwerk/test/unit/head_cache2.js | [OpenCallback.prototype.onCacheEntryAvailable : 155] false == false
05:11:48     INFO -  TEST-PASS | /builds/slave/talos-slave/test/build/tests/xpcshell/tests/netwerk/test/unit/head_cache2.js | [OpenCallback.prototype.onCacheEntryAvailable : 236] true == true
05:11:48     INFO -  TEST-PASS | /builds/slave/talos-slave/test/build/tests/xpcshell/tests/netwerk/test/unit/head_cache2.js | [OpenCallback.prototype.onCacheEntryAvailable : 237] "x1m" == "x1m"
05:11:48     INFO -  TEST-INFO | CACHE2: reading data 'x1d'
05:11:48     INFO -  TEST-INFO | CACHE2: done reading data: 0
05:11:48     INFO -  TEST-PASS | /builds/slave/talos-slave/test/build/tests/xpcshell/tests/netwerk/test/unit/head_cache2.js | [pumpReadStream/<.onStopRequest : 83] 0 == 0
05:11:48     INFO -  TEST-PASS | /builds/slave/talos-slave/test/build/tests/xpcshell/tests/netwerk/test/unit/head_cache2.js | [OpenCallback.prototype.onCacheEntryAvailable/< : 245] "x1d" == "x1d"
05:11:48     INFO -  TEST-INFO | CACHE2: callback #2(x1d) entry read done
05:11:48  WARNING -  TEST-UNEXPECTED-FAIL | /builds/slave/talos-slave/test/build/tests/xpcshell/tests/netwerk/test/unit/test_cache2-14b-concurent-readers-complete.js | 1 == 3 - See following stack:
05:11:48     INFO -  /builds/slave/talos-slave/test/build/tests/xpcshell/tests/netwerk/test/unit/test_cache2-14b-concurent-readers-complete.js:run_test/<:19
05:11:48     INFO -  /builds/slave/talos-slave/test/build/tests/xpcshell/tests/netwerk/test/unit/head_cache2.js:OpenCallback.prototype.onCacheEntryAvailable/<:248
05:11:48     INFO -  /builds/slave/talos-slave/test/build/tests/xpcshell/tests/netwerk/test/unit/head_cache2.js:pumpReadStream/<.onStopRequest:84
05:11:48     INFO -  /builds/slave/talos-slave/test/build/tests/xpcshell/head.js:_do_main:191
05:11:48     INFO -  /builds/slave/talos-slave/test/build/tests/xpcshell/head.js:_execute_test:405
05:11:48     INFO -  -e:null:1
05:11:48     INFO -  null:null:0
05:11:48     INFO -  TEST-INFO | (xpcshell/head.js) | exiting test
05:11:48     INFO -  TEST-INFO | CACHE2: reading data 'x1d'
05:11:48     INFO -  TEST-INFO | CACHE2: done reading data: 0
05:11:48     INFO -  TEST-PASS | /builds/slave/talos-slave/test/build/tests/xpcshell/tests/netwerk/test/unit/head_cache2.js | [pumpReadStream/<.onStopRequest : 83] 0 == 0
05:11:48     INFO -  TEST-PASS | /builds/slave/talos-slave/test/build/tests/xpcshell/tests/netwerk/test/unit/head_cache2.js | [OpenCallback.prototype.onCacheEntryAvailable/< : 245] "x1d" == "x1d"
05:11:48     INFO -  TEST-INFO | CACHE2: callback #3(x1d) entry read done
05:11:48  WARNING -  TEST-UNEXPECTED-FAIL | /builds/slave/talos-slave/test/build/tests/xpcshell/tests/netwerk/test/unit/test_cache2-14b-concurent-readers-complete.js | 2 == 1 - See following stack:
05:11:48     INFO -  /builds/slave/talos-slave/test/build/tests/xpcshell/tests/netwerk/test/unit/test_cache2-14b-concurent-readers-complete.js:run_test/<:26
05:11:48     INFO -  /builds/slave/talos-slave/test/build/tests/xpcshell/tests/netwerk/test/unit/head_cache2.js:OpenCallback.prototype.onCacheEntryAvailable/<:248
05:11:48     INFO -  /builds/slave/talos-slave/test/build/tests/xpcshell/tests/netwerk/test/unit/head_cache2.js:pumpReadStream/<.onStopRequest:84
05:11:48     INFO -  /builds/slave/talos-slave/test/build/tests/xpcshell/head.js:_do_main:194
05:11:48     INFO -  /builds/slave/talos-slave/test/build/tests/xpcshell/head.js:_execute_test:405
05:11:48     INFO -  -e:null:1
05:11:48     INFO -  null:null:0
05:11:48     INFO -  TEST-INFO | (xpcshell/head.js) | exiting test
05:11:48     INFO -  TEST-INFO | CACHE2: reading data 'x1d'
05:11:48     INFO -  TEST-INFO | CACHE2: done reading data: 0
05:11:48     INFO -  TEST-PASS | /builds/slave/talos-slave/test/build/tests/xpcshell/tests/netwerk/test/unit/head_cache2.js | [pumpReadStream/<.onStopRequest : 83] 0 == 0
05:11:48     INFO -  TEST-PASS | /builds/slave/talos-slave/test/build/tests/xpcshell/tests/netwerk/test/unit/head_cache2.js | [OpenCallback.prototype.onCacheEntryAvailable/< : 245] "x1d" == "x1d"
05:11:48     INFO -  TEST-INFO | CACHE2: callback #4(x1d) entry read done
05:11:48  WARNING -  TEST-UNEXPECTED-FAIL | /builds/slave/talos-slave/test/build/tests/xpcshell/tests/netwerk/test/unit/test_cache2-14b-concurent-readers-complete.js | 3 == 2 - See following stack:
05:11:48     INFO -  /builds/slave/talos-slave/test/build/tests/xpcshell/tests/netwerk/test/unit/test_cache2-14b-concurent-readers-complete.js:run_test/<:33
05:11:48     INFO -  /builds/slave/talos-slave/test/build/tests/xpcshell/tests/netwerk/test/unit/head_cache2.js:OpenCallback.prototype.onCacheEntryAvailable/<:248
05:11:48     INFO -  /builds/slave/talos-slave/test/build/tests/xpcshell/tests/netwerk/test/unit/head_cache2.js:pumpReadStream/<.onStopRequest:84
05:11:48     INFO -  /builds/slave/talos-slave/test/build/tests/xpcshell/head.js:_do_main:194
05:11:48     INFO -  /builds/slave/talos-slave/test/build/tests/xpcshell/head.js:_execute_test:405
05:11:48     INFO -  -e:null:1
05:11:48     INFO -  null:null:0
05:11:48     INFO -  TEST-INFO | (xpcshell/head.js) | exiting test
05:11:48     INFO -  <<<<<<<
}
I'd wait for bug 1053517 first.
Depends on: 1053517
(In reply to Honza Bambas (:mayhemer) from comment #1)
> I'd wait for bug 1053517 first.

How about now? :)
Flags: needinfo?(honzab.moz)
There is nothing wrong with the cache code (confirmed with a NSPR log from a "bad" run), but with the helper function that tells the test code which back end is used - newCacheBackEndUsed().  I'll rewrite that and submit a patch.
Assignee: nobody → honzab.moz
Status: NEW → ASSIGNED
Flags: needinfo?(honzab.moz)
(In reply to Honza Bambas (:mayhemer) from comment #45)
> There is nothing wrong with the cache code (confirmed with a NSPR log from a
> "bad" run), but with the helper function that tells the test code which back
> end is used - newCacheBackEndUsed().  I'll rewrite that and submit a patch.

Hm... on the other hand, there is something fishy...  NSPR log says everything is OK, but the console log says the callback we want to be called as 3rd in the order is actually called first (line 19 in the test).  This is what the reports here say and what I also caught locally.

I'm kinda lost..  problem might be somewhere else..
Status: ASSIGNED → NEW
Got it!  The thing is that cache2 behaves correctly.  But we call the JS test callbacks after we read/check the data in cache entries which is async and thread concurrent (there is a pool).  It depends on timing which read of the 3 happening in parallel makes it first.  Hence the test is unreliable.  I'll update the cache2 harness to notify at the moment we actually want.
Status: NEW → ASSIGNED
Attached patch v1Splinter Review
- there is a new flag instruction OpenCallback class to notify at the moment we actually get OnCacheEntryAvail and only then do the data content check
- callback function has a new optional arg indicating there is the "before data has been" read notification happening

Locally tested the test is not broken, I'll run the loop over night.
Attachment #8522342 - Flags: review?(michal.novotny)
Attachment #8522342 - Flags: review?(michal.novotny) → review+
https://hg.mozilla.org/mozilla-central/rev/df47866f00e2
Status: ASSIGNED → RESOLVED
Closed: 5 years ago
Resolution: --- → FIXED
Target Milestone: --- → mozilla36
You need to log in before you can comment on or make changes to this bug.