Closed Bug 899686 Opened 12 years ago Closed 11 years ago

Intermittent test_DeferredSave.js | test failed (with xpcshell return code: 0) | "Modified data to save with delay" == "First data to save with delay"

Categories

(Toolkit :: Add-ons Manager, defect)

Product:
Toolkit
Component:
Add-ons Manager
Platform:
x86_64
Linux
Type:
defect
Priority:
Not set
Severity:
normal

Tracking

()

Status:
RESOLVED FIXED
Milestone:
mozilla29
Tracking Flags:
Tracking Status
firefox27 --- fixed
firefox28 --- fixed
firefox29 --- fixed
firefox-esr24 --- unaffected
b2g-v1.2 --- fixed
b2g-v1.3 --- fixed

People

(Reporter: RyanVM, Assigned: Irving)

Details

(Keywords: intermittent-failure)

Attachments

(1 file, 1 obsolete file)

Mock out nsITimer, addressing review comments
18.12 KB, patch
Yoric
: review+
Details | Diff | Splinter Review
https://tbpl.mozilla.org/php/getParsedLog.php?id=25893794&tree=Mozilla-Central Ubuntu VM 12.04 x64 mozilla-central opt test xpcshell on 2013-07-29 19:52:25 PDT for push b8c7acba4b40 slave: tst-linux64-ec2-086 20:19:49 INFO - TEST-INFO | /builds/slave/test/build/tests/xpcshell/tests/toolkit/mozapps/extensions/test/xpcshell-unpack/test_DeferredSave.js | running test ... 20:19:49 WARNING - TEST-UNEXPECTED-FAIL | /builds/slave/test/build/tests/xpcshell/tests/toolkit/mozapps/extensions/test/xpcshell-unpack/test_DeferredSave.js | test failed (with xpcshell return code: 0), see following log: 20:19:49 INFO - >>>>>>> 20:19:49 INFO - TEST-INFO | (xpcshell/head.js) | test MAIN run_test pending (1) 20:19:49 INFO - TEST-INFO | (xpcshell/head.js) | test run_next_test 0 pending (2) 20:19:49 INFO - TEST-INFO | (xpcshell/head.js) | test MAIN run_test finished (2) 20:19:49 INFO - TEST-INFO | (xpcshell/head.js) | running event loop 20:19:49 INFO - TEST-INFO | /builds/slave/test/build/tests/xpcshell/tests/toolkit/mozapps/extensions/test/xpcshell-unpack/test_DeferredSave.js | Starting test_basic_save_succeeds 20:19:49 INFO - TEST-INFO | (xpcshell/head.js) | test test_basic_save_succeeds pending (2) 20:19:49 INFO - *** LOG DeferredSave/DeferredSaveTest: Save changes 20:19:49 INFO - TEST-INFO | (xpcshell/head.js) | test run_next_test 0 finished (2) 20:19:49 INFO - *** LOG DeferredSave/DeferredSaveTest: Starting timer 20:19:49 INFO - *** LOG DeferredSave/DeferredSaveTest: Starting write 20:19:49 INFO - TEST-INFO | /builds/slave/test/build/tests/xpcshell/tests/toolkit/mozapps/extensions/test/xpcshell-unpack/test_DeferredSave.js | "writeAtomic: /tmp/tmp3yczMq/DeferredSaveTest data: 'Test 1 Data', ({tmpPath:"/tmp/tmp3yczMq/DeferredSaveTest.tmp"})" 20:19:49 INFO - TEST-INFO | /builds/slave/test/build/tests/xpcshell/tests/toolkit/mozapps/extensions/test/xpcshell-unpack/test_DeferredSave.js | "default write callback" 20:19:49 INFO - TEST-INFO | (xpcshell/head.js) | test pending (2) 20:19:49 INFO - TEST-INFO | (xpcshell/head.js) | test finished (2) 20:19:49 INFO - *** LOG DeferredSave/DeferredSaveTest: Write succeeded 20:19:49 INFO - TEST-PASS | /builds/slave/test/build/tests/xpcshell/tests/toolkit/mozapps/extensions/test/xpcshell-unpack/test_DeferredSave.js | [test_basic_save_succeeds : 91] "Test 1 Data" == "Test 1 Data" 20:19:49 INFO - TEST-PASS | /builds/slave/test/build/tests/xpcshell/tests/toolkit/mozapps/extensions/test/xpcshell-unpack/test_DeferredSave.js | [test_basic_save_succeeds : 92] 1 == 1 20:19:49 INFO - TEST-INFO | (xpcshell/head.js) | test run_next_test 1 pending (2) 20:19:49 INFO - TEST-INFO | (xpcshell/head.js) | test test_basic_save_succeeds finished (2) 20:19:49 INFO - TEST-INFO | /builds/slave/test/build/tests/xpcshell/tests/toolkit/mozapps/extensions/test/xpcshell-unpack/test_DeferredSave.js | Starting test_two_saves 20:19:49 INFO - TEST-INFO | (xpcshell/head.js) | test test_two_saves pending (2) 20:19:49 INFO - *** LOG DeferredSave/DeferredSaveTest: Save changes 20:19:49 INFO - *** LOG DeferredSave/DeferredSaveTest: Save changes 20:19:49 INFO - TEST-INFO | (xpcshell/head.js) | test run_next_test 1 finished (2) 20:19:49 INFO - *** LOG DeferredSave/DeferredSaveTest: Starting timer 20:19:49 INFO - *** LOG DeferredSave/DeferredSaveTest: Starting write 20:19:49 INFO - TEST-INFO | /builds/slave/test/build/tests/xpcshell/tests/toolkit/mozapps/extensions/test/xpcshell-unpack/test_DeferredSave.js | "writeAtomic: /tmp/tmp3yczMq/DeferredSaveTest data: 'Test second save', ({tmpPath:"/tmp/tmp3yczMq/DeferredSaveTest.tmp"})" 20:19:49 INFO - TEST-INFO | /builds/slave/test/build/tests/xpcshell/tests/toolkit/mozapps/extensions/test/xpcshell-unpack/test_DeferredSave.js | "default write callback" 20:19:49 INFO - TEST-INFO | (xpcshell/head.js) | test pending (2) 20:19:49 INFO - TEST-INFO | (xpcshell/head.js) | test finished (2) 20:19:49 INFO - *** LOG DeferredSave/DeferredSaveTest: Write succeeded 20:19:49 INFO - TEST-PASS | /builds/slave/test/build/tests/xpcshell/tests/toolkit/mozapps/extensions/test/xpcshell-unpack/test_DeferredSave.js | [test_two_saves/< : 106] "Test second save" == "Test second save" 20:19:49 INFO - TEST-PASS | /builds/slave/test/build/tests/xpcshell/tests/toolkit/mozapps/extensions/test/xpcshell-unpack/test_DeferredSave.js | [test_two_saves/< : 107] false == false 20:19:49 INFO - TEST-PASS | /builds/slave/test/build/tests/xpcshell/tests/toolkit/mozapps/extensions/test/xpcshell-unpack/test_DeferredSave.js | [test_two_saves : 112] true == true 20:19:49 INFO - TEST-PASS | /builds/slave/test/build/tests/xpcshell/tests/toolkit/mozapps/extensions/test/xpcshell-unpack/test_DeferredSave.js | [test_two_saves : 113] "Test second save" == "Test second save" 20:19:49 INFO - TEST-PASS | /builds/slave/test/build/tests/xpcshell/tests/toolkit/mozapps/extensions/test/xpcshell-unpack/test_DeferredSave.js | [test_two_saves : 114] 1 == 1 20:19:49 INFO - TEST-INFO | (xpcshell/head.js) | test run_next_test 2 pending (2) 20:19:49 INFO - TEST-INFO | (xpcshell/head.js) | test test_two_saves finished (2) 20:19:49 INFO - TEST-INFO | /builds/slave/test/build/tests/xpcshell/tests/toolkit/mozapps/extensions/test/xpcshell-unpack/test_DeferredSave.js | Starting test_two_saves_delay 20:19:49 INFO - TEST-INFO | (xpcshell/head.js) | test test_two_saves_delay pending (2) 20:19:49 INFO - *** LOG DeferredSave/DeferredSaveTest: Save changes 20:19:49 INFO - TEST-INFO | (xpcshell/head.js) | test run_next_test 2 finished (2) 20:19:49 INFO - *** LOG DeferredSave/DeferredSaveTest: Starting timer 20:19:49 INFO - *** LOG DeferredSave/DeferredSaveTest: Save changes 20:19:49 INFO - *** LOG DeferredSave/DeferredSaveTest: Starting write 20:19:49 INFO - TEST-INFO | /builds/slave/test/build/tests/xpcshell/tests/toolkit/mozapps/extensions/test/xpcshell-unpack/test_DeferredSave.js | "writeAtomic: /tmp/tmp3yczMq/DeferredSaveTest data: 'First data to save with delay', ({tmpPath:"/tmp/tmp3yczMq/DeferredSaveTest.tmp"})" 20:19:49 INFO - TEST-INFO | /builds/slave/test/build/tests/xpcshell/tests/toolkit/mozapps/extensions/test/xpcshell-unpack/test_DeferredSave.js | "default write callback" 20:19:49 INFO - TEST-INFO | (xpcshell/head.js) | test pending (2) 20:19:49 INFO - TEST-INFO | (xpcshell/head.js) | test finished (2) 20:19:49 INFO - *** LOG DeferredSave/DeferredSaveTest: Write succeeded 20:19:49 INFO - TEST-PASS | /builds/slave/test/build/tests/xpcshell/tests/toolkit/mozapps/extensions/test/xpcshell-unpack/test_DeferredSave.js | [test_two_saves_delay/< : 128] false == false 20:19:49 INFO - TEST-PASS | /builds/slave/test/build/tests/xpcshell/tests/toolkit/mozapps/extensions/test/xpcshell-unpack/test_DeferredSave.js | [test_two_saves_delay/< : 129] true == true 20:19:49 WARNING - TEST-UNEXPECTED-FAIL | /builds/slave/test/build/tests/xpcshell/tests/toolkit/mozapps/extensions/test/xpcshell-unpack/test_DeferredSave.js | "Modified data to save with delay" == "First data to save with delay" - See following stack: 20:19:49 INFO - JS frame :: /builds/slave/test/build/tests/xpcshell/tests/toolkit/mozapps/extensions/test/xpcshell-unpack/test_DeferredSave.js :: test_two_saves_delay/< :: line 130 20:19:49 INFO - JS frame :: resource://gre/modules/Promise.jsm :: <TOP_LEVEL> :: line 554 20:19:49 INFO - JS frame :: resource://gre/modules/Promise.jsm :: <TOP_LEVEL> :: line 336 20:19:49 INFO - native frame :: <unknown filename> :: <TOP_LEVEL> :: line 0 20:19:49 INFO - TEST-INFO | (xpcshell/head.js) | exiting test 20:19:49 INFO - *** LOG DeferredSave/DeferredSaveTest: Starting timer 20:19:49 INFO - <<<<<<<
This was an interesting experiment. Not sure if we want to change the way we create timers in JS code to make this mocking easier to do, but I think this could turn out to be a useful tool. Green try on Linux (where all the failures were logged) at https://tbpl.mozilla.org/?tree=Try&rev=cc6da5045cf7
Assignee: nobody → irving
Status: NEW → ASSIGNED
Attachment #8349550 - Flags: review?(dteller)
Comment on attachment 8349550 [details] [diff] [review] Mock out nsITimer in test case to avoid race condition Review of attachment 8349550 [details] [diff] [review]: ----------------------------------------------------------------- ::: toolkit/mozapps/extensions/test/xpcshell/test_DeferredSave.js @@ +85,5 @@ > + }; > + DSContext.MakeTimer = () => { > + do_print("Creating quick timer"); > + return quickTimer; > + }; I like the idea of mock timers, but I'm not sure how/if that works. Since |MakeTimer| is not exported by DeferredSave.jsm, how can we replace it here? @@ +188,5 @@ > do_check_eq(secondData, tester.writtenData); > firstCallback_happened = true; > }, do_report_unexpected_exception); > > + yield delay(2); What's that magic constant? @@ +193,4 @@ > delayDone = true; > + let saving = tester.save(secondData); > + (yield timerPromise).callback(); > + yield saving; This looks good, but it deserves some comment. @@ +348,2 @@ > add_task(function flush_while_dirty() { > + let timerPromise = setPromiseMockTimer(); If I understand correctly, you don't use timerPromise for the time being, so let's not define it. @@ +361,5 @@ > // Also make sure that data changed after the flush call > // (even without a saveChanges() call) doesn't get written > let flushing = tester.flush(); > + // Could add a test hook to promise mock timer to make sure it is > + // cancelled here Is that a FIXME? @@ +394,5 @@ > do_check_eq(tester.writtenData, firstData); > firstCallback_happened = true; > }, do_report_unexpected_exception); > > + (yield promiseTimer).callback(); I don't understand why you call the |callback| manually. @@ +399,2 @@ > let writer = yield writeStarted.promise; > // the first write has started Here, too, a comment explaining the (yield promiseTimer) would be useful. @@ +409,5 @@ > secondCallback_happened = true; > }, do_report_unexpected_exception); > > let flushing = tester.flush(write_then_disable); > + // the promiseMockTimer should be cancelled now Could you detail that comment? Who should have cancelled it? @@ +496,5 @@ > } > > // This promise won't resolve until after writeStarted > let firstSave = tester.save(firstData, writeCallback); > + (yield timerPromise).callback(); Here, too, why do you need to call the callback yourself?
Attachment #8349550 - Flags: review?(dteller) → feedback+
(In reply to David Rajchenbach Teller [:Yoric] (away 20 Dec to Jan 4th - please use "needinfo?") from comment #11) > Comment on attachment 8349550 [details] [diff] [review] > Mock out nsITimer in test case to avoid race condition > > Review of attachment 8349550 [details] [diff] [review]: > ----------------------------------------------------------------- > > ::: toolkit/mozapps/extensions/test/xpcshell/test_DeferredSave.js > @@ +85,5 @@ > > + }; > > + DSContext.MakeTimer = () => { > > + do_print("Creating quick timer"); > > + return quickTimer; > > + }; > > I like the idea of mock timers, but I'm not sure how/if that works. Since > |MakeTimer| is not exported by DeferredSave.jsm, how can we replace it here? The context returned by Cu.import(module) is the top level 'this' for that module, and includes all globals in the module (as opposed to exports, which are copied into the context of the *caller* of Cu.import() ) > @@ +188,5 @@ > > do_check_eq(secondData, tester.writtenData); > > firstCallback_happened = true; > > }, do_report_unexpected_exception); > > > > + yield delay(2); > > What's that magic constant? I wanted to allow the event loop to spin for a short while so that async activities such as <promise>.then() calls inside tester.save() get a chance to run. > @@ +361,5 @@ > > // Also make sure that data changed after the flush call > > // (even without a saveChanges() call) doesn't get written > > let flushing = tester.flush(); > > + // Could add a test hook to promise mock timer to make sure it is > > + // cancelled here > > Is that a FIXME? Well, it was more of a "can't be bothered to fix me", but I went ahead and added that check. > @@ +394,5 @@ > > do_check_eq(tester.writtenData, firstData); > > firstCallback_happened = true; > > }, do_report_unexpected_exception); > > > > + (yield promiseTimer).callback(); > > I don't understand why you call the |callback| manually. I need to signal the DeferredSave to start writing; I can't use setQuickMockTimer() in this test because QuickMockTimers throw on cancel(), and this test (and other similar tests) invokes flush() which cancels the timer.
Attachment #8349550 - Attachment is obsolete: true
Attachment #8350169 - Flags: review?(dteller)
(In reply to :Irving Reid from comment #12) > > I like the idea of mock timers, but I'm not sure how/if that works. Since > > |MakeTimer| is not exported by DeferredSave.jsm, how can we replace it here? > > The context returned by Cu.import(module) is the top level 'this' for that > module, and includes all globals in the module (as opposed to exports, which > are copied into the context of the *caller* of Cu.import() ) I had no idea. Is that the same on B2G? > > > + yield delay(2); > > > > What's that magic constant? > > I wanted to allow the event loop to spin for a short while so that async > activities such as <promise>.then() calls inside tester.save() get a chance > to run. That sounds fragile. Please at least add a comment. > > @@ +394,5 @@ > > > do_check_eq(tester.writtenData, firstData); > > > firstCallback_happened = true; > > > }, do_report_unexpected_exception); > > > > > > + (yield promiseTimer).callback(); > > > > I don't understand why you call the |callback| manually. > > I need to signal the DeferredSave to start writing; I can't use > setQuickMockTimer() in this test because QuickMockTimers throw on cancel(), > and this test (and other similar tests) invokes flush() which cancels the > timer. Ok, so the idea is "wait until the timer is armed, then fire it", is that it? If so, please add a comment.
Attachment #8350169 - Flags: review?(dteller) → review+
Comment on attachment 8350169 [details] [diff] [review] Mock out nsITimer, addressing review comments Review of attachment 8350169 [details] [diff] [review]: ----------------------------------------------------------------- Thanks, the new comments are much better.
https://hg.mozilla.org/mozilla-central/rev/646a278134e3
Status: ASSIGNED → RESOLVED
Closed: 11 years ago
Flags: in-testsuite+
Resolution: --- → FIXED
Target Milestone: --- → mozilla29
You need to log in before you can comment on or make changes to this bug.

Attachment

General

Creator:
Created:
Updated:
Size: