1351753 - TEST-UNEXPECTED-FAIL | C:\slave\test\build\tests\mozmill\session-store\test-session-store.js | test-session-store.js::test_periodic_session_persistence_simple

Status: RESOLVED FIXED

(Thunderbird :: Testing Infrastructure, defect)

Description

[Jorg K (CEST = GMT+2)]

TEST-UNEXPECTED-FAIL | C:\slave\test\build\tests\mozmill\session-store\test-session-store.js | test-session-store.js::test_periodic_session_persistence_simple

Nothing much to say about this one, it comes an goes. Seen here for example:
https://treeherder.mozilla.org/#/jobs?repo=comm-central&revision=8eeb5667420daba2148746b6b9e470d0d8ebc35d

Comment 1

[alta88]

Attachment: sessionstore.patch

the only thing to do is increase the wait, see Bug 980346.

Comment 2

[Jorg K (CEST = GMT+2)]

Comment on attachment 8911265 [details] [diff] [review]
sessionstore.patch

If you don't mind, I'd prefer Aceman to look at this, he's the testing and Mozmill expert. I looked at the test and it sleeps nine times, which is rather unfortunate. Aceman used waitFor() on various occasions (last in test-font-chooser.js) to wait for async results, but that might not work here, as you said.

Comment 3

[:aceman]

Comment on attachment 8911265 [details] [diff] [review]
sessionstore.patch

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

Yeah, I would also like if we could active wait for some event and proceed immediately.
But in this test often there is no such event.
E.g. there are cases where there is no file and we wait for the predefined time to check that it will NOT be created again.
We can't wait for the file getting created as the event. We actually need to wait for some time and make sure there is no such event.
I think there is no such infrastructure and there probably can't be.

We could actively check for the inverse condition and FAIL the test if it happens.
So e.g. instead of:
sleep(3000)
assert_false(!file.exists())

we could do:
for (let i = 0; i < 30; i++) {
  sleep(100);
  if(file.exists())
    assert_true(false, "file shouldn't exist!")
}

But this is extra work optimizing the failing case. But the normal case (test passes) would still wait 3secs.
I don't know how this can be improved. Maybe by avoiding checking assertions of this 'negative' kind (but use the 'positive' assertions - wait for an event).

But there seem to be some places we could improve as there is an event, e.g.:
  // Wait for bad file async rename to finish.
  controller.sleep(kSaveDelayMs + asyncFileWriteDelayMS);
  
  // The bad session file should now not exist.
  assert_false(sessionStoreManager.sessionFile.exists(),
               "file should not exist");

Could be rewritten as:
  // Wait for bad file async rename to finish.
  controller.sleep(kSaveDelayMs);                  <-- I would keep this wait for safety, even if it may not be needed.
  
  // The bad session file should now not exist.
  controller.waitFor(() => !sessionStoreManager.sessionFile.exists(),
               "file should not exist");

We could proceed as soon as the file is gone, it does not need to be full 3secs.

Alta, would you mind changing the 1-2 cases of this kind in this test file?

Comment 4

[alta88]

Your proposed change results in:

SUMMARY-UNEXPECTED-FAIL | test-session-store.js | test-session-store.js::test_periodic_nondirty_session_persistence
  EXCEPTION: controller.waitFor is not a function
    at: test-session-store.js line 130

although there isn't an error in test_bad_session_file_simple() with the same code:
  controller.sleep(kSaveDelayMs);
  controller.waitFor(() => !sessionStoreManager.sessionFile.exists(),
                     "file should not exist");

I'm not going to look into why, as this is a drive by optimization unrelated to the failing test, for which "the only thing to do" is wait more on slow machines, as there is no event to wait for, file or UI or promise or anything.

Comment 5

[:aceman]

Yeah, that error is interesting, but I think test_periodic_nondirty_session_persistence() can't be converted to waitFor. Your condition in waitFor would be met immediately (no file) but we still need to wait for some time and see if it isn't re-created automatically.

I meant to convert test_bad_session_file_simple() and test_clean_shutdown_session_persistence_simple() .

Comment 6

[alta88]

Same error in test_clean_shutdown_session_persistence_simple() and disaster in waitForFileRefresh().  Only works in test_bad_session_file_simple().

Comment 7

[:aceman]

(In reply to alta88 from comment #6)
> Same error in test_clean_shutdown_session_persistence_simple() 

I think I also have a patch pending for this test file and there is a mess in controllers, because we close the windows so having a good controller is problematic.
I don't know to which window 'controller' is bound. Can you try abwc.waitFor() in this test?

Comment 8

[alta88]

Attachment: sessionstore.patch

abwc works in test_clean_shutdown_session_persistence_simple() and test_bad_session_file_simple().

not in waitForFileRefresh(), where something would be most useful, if saving 9 seconds is important.

Comment 9

[alta88]

(In reply to alta88 from comment #8)
> 
> not in waitForFileRefresh(), where something would be most useful, if saving
> 9 seconds is important.

actually, that's wrong; the wait there is for file changes with no (practical) catchable event.

Comment 10

[:aceman]

Comment on attachment 8912805 [details] [diff] [review]
sessionstore.patch

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

Yes I also this  waitForFileRefresh can't be optimized.

::: mail/test/mozmill/session-store/test-session-store.js
@@ -404,5 @@
>                 "saved state is bad so state object should be null");
>  
> -  // Wait for bad file async rename to finish.
> -  controller.sleep(kSaveDelayMs + asyncFileWriteDelayMS);
> -

Please keep this as controller.sleep(kSaveDelayMs);

@@ +406,2 @@
>    // The bad session file should now not exist.
> +  abwc.waitFor(() => !sessionStoreManager.sessionFile.exists(),

Abwc is not defined in this function. There is an error in the console but the test still passes. Neither controller works here.

Comment 11

[:aceman]

Attachment: session.patch

Would this work for you? It produces no errors for me.

Comment 12

[alta88]

(In reply to :aceman from comment #10)
> Comment on attachment 8912805 [details] [diff] [review]
> sessionstore.patch
> 
> Review of attachment 8912805 [details] [diff] [review]:
> -----------------------------------------------------------------
> 
> Yes I also this  waitForFileRefresh can't be optimized.
> 
> ::: mail/test/mozmill/session-store/test-session-store.js
> @@ -404,5 @@
> >                 "saved state is bad so state object should be null");
> >  
> > -  // Wait for bad file async rename to finish.
> > -  controller.sleep(kSaveDelayMs + asyncFileWriteDelayMS);
> > -
> 
> Please keep this as controller.sleep(kSaveDelayMs);

the kSaveDelayMs is solely for the saveSoon() api, which a rename isn't involved in at all, so the waitFor should be totally adequate.  but really, it doesn't matter, and we're wasting a lot of time on very low yield stuff.  the 1 second increase should have been rubber stamped 5 days ago.

> 
> @@ +406,2 @@
> >    // The bad session file should now not exist.
> > +  abwc.waitFor(() => !sessionStoreManager.sessionFile.exists(),
> 
> Abwc is not defined in this function. There is an error in the console but
> the test still passes. Neither controller works here.

Comment 13

[:aceman]

(In reply to alta88 from comment #12)
> > > -  // Wait for bad file async rename to finish.
> > > -  controller.sleep(kSaveDelayMs + asyncFileWriteDelayMS);
> > > -
> > 
> > Please keep this as controller.sleep(kSaveDelayMs);
> 
> the kSaveDelayMs is solely for the saveSoon() api, which a rename isn't
> involved in at all, so the waitFor should be totally adequate. 

OK, then let's remove it.

> but really,
> it doesn't matter, and we're wasting a lot of time on very low yield stuff. 
> the 1 second increase should have been rubber stamped 5 days ago.

As Jorg pointed out, it is 1 second at multiple places (about 9), which adds up. So if we can remove 2-4 seconds by optimizing the waiting then we can at least lessen the damage. So I think we are done here. Remove the sleep I kept, put your name in the patch and add a commit message and we can land it. Thanks

Comment 14

[alta88]

Attachment: sessionstore.patch

added import to prior patch.

Comment 15

[:aceman]

Comment on attachment 8912849 [details] [diff] [review]
sessionstore.patch

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

::: mail/test/mozmill/session-store/test-session-store.js
@@ +13,5 @@
>  var MODULE_REQUIRES = ["folder-display-helpers", "window-helpers"];
>  
>  var controller = {};
>  Cu.import("resource://mozmill/modules/controller.js", controller);
> + 

Surplus space.

@@ +409,2 @@
>    // The bad session file should now not exist.
> +  abwc.waitFor(() => !sessionStoreManager.sessionFile.exists(),

I used the 'utils' here instead of abwc (which I said doesn't work).

@@ +434,5 @@
>    }
>  
>    // Wait for window close async session write to finish.
> +  controller.sleep(kSaveDelayMs);
> +  abwc.waitFor(() => sessionStoreManager.sessionFile.exists(),

I used the 'utils' here instead of abwc.

Comment 16

[alta88]

Attachment: sessionstore.patch

Comment 17

[:aceman]

Comment on attachment 8912874 [details] [diff] [review]
sessionstore.patch

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

Thanks.

Comment 18

[Pulsebot]

Pushed by [e-mail]:
https://hg.mozilla.org/comm-central/rev/6a819eac9f9f
Fix test failure in test-session-store.js: Increase wait time for no event session store saves. r=aceman

Comment 19

[Jorg K (CEST = GMT+2)]

Still happening:
https://treeherder.mozilla.org/#/jobs?repo=comm-central&revision=39f86b4979da70f9ce94dbf24d39d3845a8fbe25&selectedJob=133906711

Comment 20

[alta88]

please backout the last patch and land the original 1 second increase patch.  x64 never used to fail; it's just been made worse.

Comment 21

[Jorg K (CEST = GMT+2)]

OK, will do.

Comment 22

[Pulsebot]

Pushed by [e-mail]:
https://hg.mozilla.org/comm-central/rev/7b4eb34746b3
Backed out changeset 6a819eac9f9f . a=jorgk
https://hg.mozilla.org/comm-central/rev/afe1ee892f5b
Fix test failure in test-session-store.js: Increase wait time for no event session store saves (take 2). rs=jorgk DONTBUILD

Comment 23

[:aceman]

And what would be the explanation of test-session-store.js::test_periodic_nondirty_session_persistence and test_bad_session_file_simple failing with the patch?
They are before test_clean_shutdown_session_persistence_simple and test_bad_session_file_simple that we touched.
Linux x64 passed for me locally with the extended patch.

Comment 24

[Jorg K (CEST = GMT+2)]

I'm happy to do a follow-up if you can get it sorted out. Increasing the wait time was past of both patches, so no harm done landing this by itself to see what it does.

Comment 25

[alta88]

Do these tests run serially?  Now that the underlying api is async, and there is no deterministic event for the session save part, they must follow each other strictly after a wait, and any failure should stop the rest. Can mozmill do that?

In any event, the increased wait didn't fix anything. And it's odd that only linux has a problem.

Comment 26

[Jorg K (CEST = GMT+2)]

(In reply to Pulsebot from comment #22)
> https://hg.mozilla.org/comm-central/rev/afe1ee892f5b
> Fix test failure in test-session-store.js: Increase wait time for no event
> session store saves (take 2). rs=jorgk DONTBUILD
Apologies for landing this in my name. The patch contained no author and at some stage the system must have assumed my authorship. Sorry.

Comment 27

[:aceman]

(In reply to alta88 from comment #25)
> Do these tests run serially?
> Now that the underlying api is async, and
> there is no deterministic event for the session save part, they must follow
> each other strictly after a wait, and any failure should stop the rest. Can
> mozmill do that?

Yes in mozmill the tests run serially in the order in which the test_* functions are declared in the test file.
 
> In any event, the increased wait didn't fix anything. And it's odd that only
> linux has a problem.

Yes, it seems even the timeout increase patch alone didn't fix anything.

I have tested locally that e.g. waitForFileRefresh really takes 3.5s so the controller.sleep seems to work.

Comment 28

[alta88]

I don't think there's anything else to try other than increasing the wait even more.  We know it doesn't happen for win/osx, but very very rarely on linux 64, and always on linux 32 test machines.  We also know that the saveSoon() function doesn't even pop the real save timer until kSaveDelayMS wait (1.5 sec). So 2 additional seconds isn't enough to teardown a window and have the file ready. One of the tests has many windows to close as well.

And we know all this works on our nice linux 64 machines since it can't be reproduced locally. Jorg, could you please land or try with the asyncFileWriteDelayMS = 3000. If we're really concerned about extra seconds, optimization with waitFor can be done once the wait is correct for the things that can't use waitFor.

Comment 29

[Jorg K (CEST = GMT+2)]

If Aceman agrees, I can land 3000 in your name this time. I can do that with DONTBUILD, so the next build will catch it.

<off-topic>
It's nice that you're looking into this, but I'm currently 500% stressed because TB is broken in the middle and we I don't yet know how to fix it, not even the cause for sure, see bug 1404003, bug 1404045 and bug 1403771 and maybe bug 1404489.

M-C made some Necko changes that broke us badly. They removed parameters from functions we did use(!!), so now we need to plug in intermediate stream handling (SlicedInputStream, bug 1404045 and bug 1403393) to bridge the missing functionality. Whilst this is mostly working, I still have IMAP downloading every message in every folder, so I'm not happy. Since there was Core::DOM bustage at the same time, I don't have Tinderbox builds after each M-C merge, so regressions ranges are much larger than usually. So currently it's all a mess.
</off-topic>

Comment 30

[:aceman]

We can try that.

But also we could try in test_periodic_nondirty_session_persistence to add a waitFor(!sessionFile.exists()) and then wait for the fixed amount of seconds for it to not appear again.

Comment 31

[Pulsebot]

Pushed by [e-mail]:
https://hg.mozilla.org/comm-central/rev/fbc536565d10
Fix test failure in test-session-store.js: Increase wait time for no event session store saves. rs=jorgk DONTBUILD

Comment 32

[alta88]

(In reply to :aceman from comment #30)
> We can try that.
> 
> But also we could try in test_periodic_nondirty_session_persistence to add a
> waitFor(!sessionFile.exists()) and then wait for the fixed amount of seconds
> for it to not appear again.

We could, but didn't it not work as expected in the prior patch?  Doesn't waitFor have its own timeout (which should be independent of the timers here) that's pretty generic for file exists() events.

ot: There isn't anyone who wouldn't say Jorg is doing an exceptional job keeping the tree going, in very difficult circumstances.  It may well be that sliced as implemented for Fx is no good for Tb purposes, and those driveby no-fork critics either figure it out themselves or pipe down, as a fork may unfortunately be necessary.  And just wait til the rdf fork comes around..

Comment 33

[:aceman]

(In reply to alta88 from comment #32)
> We could, but didn't it not work as expected in the prior patch?  Doesn't
> waitFor have its own timeout (which should be independent of the timers
> here) that's pretty generic for file exists() events.

No, we didn't touch test_periodic_nondirty_session_persistence in my proposal.
That I why I wondered why my patch could cause the problem in test_periodic_nondirty_session_persistence so that it was backed out.

WaitFor has its default timeout somewhere at 30seconds, but it is not fixed, only a hard limit. So we can use it and it will return whent he condition is met without us needing to know if it takes 1,2 or 20 seconds.

So my proposal is to wait for the file to be deleted first, then run out fixed sleep. Maybe we find the file isn't even removed in the first place due to some race.

Comment 34

[alta88]

I see. Well, let's see if the original problem test, test_periodic_session_persistence_simple, is fixed first and then go about optimizing file exists() with waitFor.

Comment 35

[alta88]

Attachment: session-store-linux64-OK.txt

linux64 successful test.

Comment 36

[alta88]

Attachment: session-store-linux32-Fail.txt

linux32 failed test.

So these debug build tests spew huge amounts of log records, and take 5 minutes for something that runs for < 1 locally non debug, but otherwise I can't see anything obvious that would show a fail reason on 32 and not 64.

Unless there's a better idea, Jorg can you please change/land the wait to 6000.

Comment 37

[Pulsebot]

Pushed by [e-mail]:
https://hg.mozilla.org/comm-central/rev/ba6ce4267a6c
Fix test failure in test-session-store.js: Increase wait time for no event session store saves. rs=jorgk

Comment 38

[Jorg K (CEST = GMT+2)]

Beta (TB 57) doesn't need a colourful tree due to those failures either:
https://hg.mozilla.org/releases/comm-beta/rev/822da2753c75caa2376f343446098c44510ddbe4

Comment 39

[alta88]

Attachment: sessionstore.patch

Ok, this is a refactor to
1) use close_window() instead of window.close() which latter doesn't wait; get rid of the waits.
2) use waitFor with file.exists() everywhere rather than sleeps, especially relevant to the usually failing test_clean_shutdown_session_persistence_simple().
3) kSaveDelayMs is only for saves when a window is not closed.

Works locally on non debug, as always.  So it needs to either go to try or live for a real testing.

Comment 40

[:aceman]

Comment on attachment 8923567 [details] [diff] [review]
sessionstore.patch

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

Thanks for pursuing this again.

::: mail/test/mozmill/session-store/test-session-store.js
@@ +101,5 @@
>    let sessionFile = sessionStoreManager.sessionFile;
>    if (sessionFile.exists())
>      sessionFile.remove(false);
>  
> +  utils.waitFor(() => !sessionFile.exists(),

I wonder where 'utils' come from as it isn't imported. But it seems to exist.

@@ +126,5 @@
>    sessionFile.remove(false);
>  
> +  // Since we didn't change the state of the session, the session file
> +  // should not be re-created.
> +  utils.waitFor(() => !sessionStoreManager.sessionFile.exists(),

Why sessionStoreManager.sessionFile instead of sessionFile? Does it make a difference?

@@ -125,5 @@
>    sessionFile.remove(false);
>  
> -  // since we didn't change the state of the session, the session file
> -  // should not be re-created
> -  controller.sleep(kSaveDelayMs + asyncFileWriteDelayMS);

I think you need to keep the sleep, otherwise the following waitFor does not really test anything.

Comment 41

[alta88]

(In reply to :aceman from comment #40)
> Comment on attachment 8923567 [details] [diff] [review]
> sessionstore.patch
> 
> Review of attachment 8923567 [details] [diff] [review]:
> -----------------------------------------------------------------
> 
> Thanks for pursuing this again.
> 
> ::: mail/test/mozmill/session-store/test-session-store.js
> @@ +101,5 @@
> >    let sessionFile = sessionStoreManager.sessionFile;
> >    if (sessionFile.exists())
> >      sessionFile.remove(false);
> >  
> > +  utils.waitFor(() => !sessionFile.exists(),
> 
> I wonder where 'utils' come from as it isn't imported. But it seems to exist.
> 
> @@ +126,5 @@
> >    sessionFile.remove(false);
> >  
> > +  // Since we didn't change the state of the session, the session file
> > +  // should not be re-created.
> > +  utils.waitFor(() => !sessionStoreManager.sessionFile.exists(),
> 
> Why sessionStoreManager.sessionFile instead of sessionFile? Does it make a
> difference?

No.
> 
> @@ -125,5 @@
> >    sessionFile.remove(false);
> >  
> > -  // since we didn't change the state of the session, the session file
> > -  // should not be re-created
> > -  controller.sleep(kSaveDelayMs + asyncFileWriteDelayMS);
> 
> I think you need to keep the sleep, otherwise the following waitFor does not
> really test anything.

Why, the waitFor itself loops until it isn't found.

Comment 42

[:aceman]

   sessionFile.remove(false);
-  // since we didn't change the state of the session, the session file
-  // should not be re-created
-  controller.sleep(kSaveDelayMs + asyncFileWriteDelayMS);
-  assert_false(sessionFile.exists(), "file should not exist");
+  // Since we didn't change the state of the session, the session file
+  // should not be re-created.
+  utils.waitFor(() => !sessionStoreManager.sessionFile.exists(),
+                "session file should not exist");

Without the sleep the waitFor returns immediately as you removed the file right now. The point of the test is to wait a while to see if the file isn't recreated again.

Comment 43

[alta88]

Attachment: sessionstore.patch

The prior _saveState() already has a wait, and it's that call that is being tested for non change. So this test was useless from the start, since the remove() and wait should precede that _saveState().

Comment 44

[alta88]

Comment on attachment 8923593 [details] [diff] [review]
sessionstore.patch

Not quite right..

Comment 45

[alta88]

Attachment: sessionstore.patch

Comment 46

[:aceman]

Comment on attachment 8923608 [details] [diff] [review]
sessionstore.patch

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

While the test with the patch passed for me locally, it still fails on try server on Linux debug and Windows debug:
https://treeherder.mozilla.org/#/jobs?repo=try-comm-central&revision=61a0adf6aa9baef3d1bebd4ad03d53ca69335866

Comment 47

[alta88]

Attachment: sessionstore.patch

please try this, it changes waitForFileRefresh() to wait for the timer to pop, then for the file to appear on disk, then some time for the write.

Comment 48

[:aceman]

Comment on attachment 8924561 [details] [diff] [review]
sessionstore.patch

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

OK, this surprisingly passes on all platforms:
https://treeherder.mozilla.org/#/jobs?repo=try-comm-central&revision=ef98fa7a65546bf3064dc99bd95311e80d09d940

::: mail/test/mozmill/session-store/test-session-store.js
@@ +49,5 @@
>  function waitForFileRefresh() {
> +  controller.sleep(kSaveDelayMs);
> +  utils.waitFor(() => sessionStoreManager.sessionFile.exists(),
> +                "session file should exist");
> +  controller.sleep(asyncFileWriteDelayMS);

Why is the sleep after waitFor needed?

Comment 49

[alta88]

comment 47..?  more verbose: just because the file is created doesn't mean its write/flush has completed so a nice json format data is available for readFile().

Comment 50

[Jorg K (CEST = GMT+2)]

Closed bugs don't show up in the search for "checkin needed". Will land this today.

Comment 51

[Pulsebot]

Pushed by [e-mail]:
https://hg.mozilla.org/comm-central/rev/c382516f2d6f
Follow-up: Fix test failure in test-session-store.js using waitFor() together with appropriate sleep(). r=aceman

Comment 52

[Jorg K (CEST = GMT+2)]

Beta (TB 57):
https://hg.mozilla.org/releases/comm-beta/rev/714d87c3cbe7a93f15f6c7c3893c422126f8f492

Comment 53

[Jorg K (CEST = GMT+2)]

Still failing, for example here:
https://treeherder.mozilla.org/#/jobs?repo=comm-central&revision=82337ca3ffd66f9b5205add87b23f9906f7cd7d4&selectedJob=142200286
https://treeherder.mozilla.org/#/jobs?repo=comm-central&revision=21ba31e50f44235767d1959b54e9fc7eb7738480&selectedJob=142183877

:-(

Comment 54

[alta88]

indeed. shooting in the dark if it can't be reproduced locally. linux32 debug runs these tests for 5 minutes and <20s on linux64 nondebug locally.  so the window closing log spew could be the culprit, on an old machine with who knows what gtk, etc.

you can try this again, and increase until it works:
-var asyncFileWriteDelayMS = 1000;
+var asyncFileWriteDelayMS = 2000;

or you can disable the test on linux32.

Comment 55

[Jorg K (CEST = GMT+2)]

(In reply to alta88 from comment #54)
> ... or you can disable the test on linux32.
Was far as I know, I can't disable a test on linux32 (debug) only. I'd have to disable it on all Linux, no?
For now, let's go with 3000ms.

Comment 56

[Pulsebot]

Pushed by [e-mail]:
https://hg.mozilla.org/comm-central/rev/9e6ce210f281
Increase wait time from 1000ms to 3000ms to fix test-session-store.js failure on Linux 32. r=me