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

RESOLVED FIXED in Firefox 27

Status

()

defect
RESOLVED FIXED
6 years ago
6 years ago

People

(Reporter: RyanVM, Assigned: Irving)

Tracking

({intermittent-failure})

Trunk
mozilla29
x86_64
Linux
Points:
---
Bug Flags:
in-testsuite +

Firefox Tracking Flags

(firefox27 fixed, firefox28 fixed, firefox29 fixed, firefox-esr24 unaffected, b2g-v1.2 fixed, b2g-v1.3 fixed)

Details

Attachments

(1 attachment, 1 obsolete attachment)

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