540110 - test-folder-display-helpers.js' waitForEval timeouts should be treated as failures, logHelper should be mozmill aware

Status: RESOLVED FIXED

(Thunderbird :: Testing Infrastructure, defect)

Description

[Andrew Sutherland [:asuth] (he/him)]

Attachment: add timeouts, do more loghelper stuff v1

waitForEval does not throw if it times out without having its predicate satisfied, it only returns a value.  Even if the state of things when the timeout occurs is correct, we still want to explode because those timeouts really make the tests incredibly painful to run.

I made those changes a bit ago as part of a patch where I also improved things for debugging with logHelper/logsploder which I'm including.  These should have no meaningful effect in cases where logsploder is not being used.

It's possible this will make tests that think they currently pass instead fail.  This is part of my strategy to dig me (and everybody else) out of our mozmill trouble hole.

Comment 1

[Rain [:rain1] (inactive)]

Attachment: patch, unbitrotted to tip

(This is on top of all the patches in bugs that block this.)

Comment 2

[Rain [:rain1] (inactive)]

Comment on attachment 426705 [details] [diff] [review]
patch, unbitrotted to tip

This is wonderful work -- it'll go a long way towards tightening our Mozmill tests. It's already helped catch several bugs before even being checked in ;)

>   mc.folderTreeView.selectFolder(aFolder);
>   // ... so wait until it goes through by waiting on the displayedFolder...
>   function isDisplayedFolder() {
>     return mc.folderDisplay.displayedFolder == aFolder;
>   }
>-  controller.waitForEval('subject()', NORMAL_TIMEOUT, FAST_INTERVAL,
>-                         isDisplayedFolder);
>+  if(!controller.waitForEval('subject()', NORMAL_TIMEOUT, FAST_INTERVAL,
>+                             isDisplayedFolder))

Please fix the spacing here.

> 
>-  // XXX folder summary will impact this, but for now, nothing should be
>-  //  shown when we enter the folder.
>-  wait_for_blank_content_pane();
>-

I'm not sure why this was removed...

> 
> /**
>  * Assert that the currently selected tab is the given one.
>  *
>  * @param aTab The tab that should currently be selected.
>  */
> function assert_selected_tab(aTab) {
>   if (mc.tabmail.currentTabInfo != aTab)
>-    throw new Error("The currently selected tab should be at index " +
>-        mc.tabmail.tabInfo.indexOf(aTab) + ", but is actually at index " +
>-        mc.tabmail.tabInfo.indexOf(mc.tabmail.currentTabInfo));
>+    mark_failure(["The currently selected tab should be", aTab,
>+        "(index: " + mc.tabmail.tabInfo.indexOf(aTab) + ") but is",
>+        mc.tabmail.currentTabInfo,
>+        "(index: " + mc.tabmail.tabInfo.indexOf(mc.tabmail.currentTabInfo) + ")"
>+        ]);

This goes for all the throw new Errors that are changed to mark_failures: I'm not exactly clear about why some of these were changed and others weren't.

> 
> /**
>  * Close a message window by calling window.close() on the controller.
>  */
> function close_message_window(aController) {
>+  mark_action("fdh", "close_message_window", []);

I think passing in something useful here would be good -- even just the windowtype and title would be better than nothing at all.

> /**
>  * Middle-click on the tree-view in question, presumably opening a new message
>  *  tab.
>  *
>  * @return [The new tab, the message that you clicked on.]
>  */
> function middle_click_on_row(aViewIndex) {
>   let msgHdr = mc.dbView.getMsgHdrAt(aViewIndex);
>+  mark_action("fdh", "right_click_on_row", [aViewIndex, msgHdr]);

This should be middle_click_on_row.

>   if(!controller.waitForEval('subject.allMessagesLoaded', NORMAL_TIMEOUT,
>                               FAST_INTERVAL, aController.folderDisplay))
>-    throw new Error("Messages never finished loading.  Timed Out.");
>+    mark_failure(["Messages never finished loading.  Timed Out."]);

While you're here, please fix the spacing after the if.

>       return !urlRunningObj.value;
>     }
>     // not a mailnews URL, just check the busy flags...
>     return !docShell.busyFlags;
>   };
>-  controller.waitForEval('subject()',
>-                         NORMAL_TIMEOUT,
>-                         FAST_INTERVAL, isLoadedChecker);
>+  if (!controller.waitForEval('subject()', NORMAL_TIMEOUT, FAST_INTERVAL,
>+                              isLoadedChecker))
>+    mark_failure(["Timed out waiting for message display completion."]);

It would be useful here for other state to get printed here too, including the values of aLoadDemanded, messageLoaded, and the mailnews/docShell status.

> function make_display_unthreaded() {
>   wait_for_message_display_completion();
>+  mark_action("fdh", "make_folder_display_unthreaded", []);

make_display_unthreaded, and the current status would be useful here.

> function make_display_threaded() {
>   wait_for_message_display_completion();
>+  mark_action("fdh", "make_folder_display_threaded", []);

ditto here...

> function make_display_grouped() {
>   wait_for_message_display_completion();
>+  mark_action("fdh", "make_folder_display_grouped", []);

and here.

> function set_show_unread_only(aShowUnreadOnly) {
>   wait_for_message_display_completion();
>+  mark_action("fdh", "set_show_unread_only", [aShowUnreadOnly]);

Again, the current status would be useful here.

>diff --git a/mail/test/mozmill/shared-modules/test-window-helpers.js b/mail/test/mozmill/shared-modules/test-window-helpers.js
>--- a/mail/test/mozmill/shared-modules/test-window-helpers.js
>+++ b/mail/test/mozmill/shared-modules/test-window-helpers.js

>-    controller.waitForEval(
>-      'subject.monitorizeOpen()',
>-      this._firstWindowOpened ? WINDOW_OPEN_TIMEOUT_MS
>-                              : FIRST_WINDOW_EVER_TIMEOUT_MS,
>-      this._firstWindowOpened ? WINDOW_OPEN_CHECK_INTERVAL_MS
>-                              : FIRST_WINDOW_CHECK_INTERVAL_MS,
>-      this);
>+    if (!controller.waitForEval(
>+          'subject.monitorizeOpen()',
>+          this._firstWindowOpened ? WINDOW_OPEN_TIMEOUT_MS
>+            : FIRST_WINDOW_EVER_TIMEOUT_MS,
>+          this._firstWindowOpened ? WINDOW_OPEN_CHECK_INTERVAL_MS
>+            : FIRST_WINDOW_CHECK_INTERVAL_MS,
>+          this))
>+      throw new Error("Timed out waiting for window open!");

All your new additions in test-folder-display-helpers.js seem to be mark_failure calls, but all the ones in test-window-helpers.js are |throw new Error|s -- why?

>     this.waitingForOpen = null;
>     let xulWindow = this.waitingList[aWindowType];
>-dump("### XUL window: " + xulWindow + "\n");
>     let domWindow = xulWindow.docShell.QueryInterface(Ci.nsIInterfaceRequestor)
>                                       .getInterface(Ci.nsIDOMWindowInternal);
>-dump("domWindow: " + domWindow + "\n");

Thanks -- they've been bugging me for a while.

>   /**
>    * The current windowType we are waiting to close.  Same deal as
>    *  waitingForOpen, this makes the eval less crazy.
>    */
>   waitingForClose: null,
>   waitForWindowClose: function WindowWatcher_waitForWindowClose() {
>-    controller.waitForEval('subject.monitorizeClose()',
>-                           WINDOW_CLOSE_TIMEOUT_MS,
>-                           WINDOW_CLOSE_CHECK_INTERVAL_MS, this);
>+    if (!controller.waitForEval('subject.monitorizeClose()',
>+                                WINDOW_CLOSE_TIMEOUT_MS,
>+                                WINDOW_CLOSE_CHECK_INTERVAL_MS, this))
>+      throw new Error("Timeout waiting for window to close!");

Minor nit: I don't think we use exclamation marks for any other error messages.

>diff --git a/mailnews/test/resources/logHelper.js b/mailnews/test/resources/logHelper.js
>--- a/mailnews/test/resources/logHelper.js
>+++ b/mailnews/test/resources/logHelper.js

> 
>+// this defaults to undefined by test-folder-display-helpers can pre-clobber
>+var _do_not_wrap_xpcshell;

I'm having trouble parsing this comment... in any case, it'd be nice to be more explicit about xpcshell vs mozmill.

>   _errorConsoleTunnel.initialize();
> 
>   if (_logHelperInterestedListeners) {
>-    _wrap_xpcshell_functions();
>+    if (!_do_not_wrap_xpcshell)
>+      _wrap_xpcshell_functions();

[Mmm, it'd be nice if JS module code could reliably determine whether it's running in xpcshell.]

> function __simple_obj_copy(aObj, aDepthAllowed) {
>   let oot = {};
>   let nextDepth = aDepthAllowed - 1;
>-  for each (let [key, value] in Iterator(aObj)) {
>+  for each (let key in Iterator(aObj, true)) {
>+    // avoid triggering getters
>+    if (aObj.__lookupGetter__(key)) {
>+      oot[key] = "*getter*";
>+      continue;
>+    }
>+    let value = aObj[key];

Nice.

>     // array?  we don't count that as depth for now.
>-    else if ("length" in value) {
>-      oot[key] = [__simple_value_copy(v, nextDepth) for each
>+    else if (("length" in value) &&
>+             ("constructor" in value) &&
>+             (value.constructor.name == "Array")) {

else if (value instanceof Array) ?

Comment 3

[Andrew Sutherland [:asuth] (he/him)]

(In reply to comment #2)
> >-  // XXX folder summary will impact this, but for now, nothing should be
> >-  //  shown when we enter the folder.
> >-  wait_for_blank_content_pane();
> >-
> 
> I'm not sure why this was removed...

You put back in the remember selected message logic so the underlying assumption is no longer valid.  Also, the behavior was not codified in the documentation for the method so I'm inclined to just remove it.

> This goes for all the throw new Errors that are changed to mark_failures: I'm
> not exactly clear about why some of these were changed and others weren't.

I think this may have been a mash-up of two different patches initially.  I likely only converted things to mark_failure after the merge in cases where there was extra information that I needed.
 
> All your new additions in test-folder-display-helpers.js seem to be
> mark_failure calls, but all the ones in test-window-helpers.js are |throw new
> Error|s -- why?

test-window-helper doesn't have logHelper exposed to it.  It probably makes sense to do a refactoring pass in some future patch so that's not really an issue.
 
> >     // array?  we don't count that as depth for now.
> >-    else if ("length" in value) {
> >-      oot[key] = [__simple_value_copy(v, nextDepth) for each
> >+    else if (("length" in value) &&
> >+             ("constructor" in value) &&
> >+             (value.constructor.name == "Array")) {
> 
> else if (value instanceof Array) ?

Every JS module gets its own Array which are not instanceof comparable.  Or at least that used to be the case.

Comment 4

[Andrew Sutherland [:asuth] (he/him)]

Attachment: revised patch based on comments

I think I generally updated everything requested that I did not make excuses for :).

Based on current direction, I think my gameplan is to forget about logsploder (for now) but use this more sophisticated logging in some form of circular buffer that we dump for CouchDB persistence in the case of failure.

(Some form of non-circular logging might also be appropriate for specially executed runs that help illustrate what the system is actually doing for comprehension, but otherwise the data is gratuitous.  Noting that currently the extra cost is only paid when logsploder is attached or explicit logging is requested...)

Comment 5

[Rain [:rain1] (inactive)]

Rich review at http://reviews.visophyte.org/r/436518/

First-pass review -- I still need to run with the patch. All of this is really
minor stuff.


on file: mail/test/mozmill/shared-modules/test-folder-display-helpers.js line 383
>   if(!controller.waitForEval('subject()', NORMAL_TIMEOUT, FAST_INTERVAL,

Needs a space between the if and the (


on file: mail/test/mozmill/shared-modules/test-folder-display-helpers.js line 582
>     mark_failure(["The currently selected tab should be", aTab,
>         "(index: " + mc.tabmail.tabInfo.indexOf(aTab) + ") but is",
>         mc.tabmail.currentTabInfo,
>         "(index: " + mc.tabmail.tabInfo.indexOf(mc.tabmail.currentTabInfo) + ")"
>         ]);

It seems to make sense here to print mc.tabmail.tabInfo, like in the other
mark_failure messages.


on file: mail/test/mozmill/shared-modules/test-folder-display-helpers.js line 625
>     mark_failure(["There should be " + aNumber + " tabs open, but there " +
>                     "are actually " + actualNumber + " tabs open. Tabs:",

The second line needs to be indented a couple of spaces fewer.


on file: mail/test/mozmill/shared-modules/test-folder-display-helpers.js line 895
>   mark_action("fdh", "right_click_on_row", [aViewIndex, msgHdr]);

["index", aViewIndex, "message header", msgHdr] maybe?


on file: mail/test/mozmill/shared-modules/test-folder-display-helpers.js line 908
>   mark_action("fdh", "right_click_on_row", [aViewIndex, msgHdr]);

Same here.


on file: mail/test/mozmill/shared-modules/test-folder-display-helpers.js line 929
>  *
>  * @param aMode The expected folder mode.
>  * @param [aController] The controller in whose context to do this, defaults to
>  *     |mc| if omitted.
> 
>  */
> function assert_folder_mode(aMode, aController) {

You could get rid of that blank line entirely.


on file: mail/test/mozmill/shared-modules/test-folder-display-helpers.js line 1252
>   if(!controller.waitForEval('subject.allMessagesLoaded', NORMAL_TIMEOUT,
>                               FAST_INTERVAL, aController.folderDisplay))
>     mark_failure(["Messages never finished loading.  Timed Out."]);

Please add a space after the if


on file: mail/test/mozmill/shared-modules/test-folder-display-helpers.js line 1376
>   if (!controller.waitForEval('subject()', NORMAL_TIMEOUT, FAST_INTERVAL,
>                               isBlankChecker))
>     mark_failure(["Timeout waiting for blank content pane.  Current location:",
>                    aController.window.content.location.href]);

That last line looks like it's indented too much.


on file: mail/test/mozmill/shared-modules/test-folder-display-helpers.js line 2321
>   mark_action("fdh", "set_mail_view", [aMailViewIndex, aData]);

["index", aMailViewIndex, "mail view data", aData]?


on file: mailnews/test/resources/logHelper.js line 74
> // this defaults to undefined by test-folder-display-helpers can pre-clobber
> var _do_not_wrap_xpcshell;

That comment still needs fixing

Comment 6

[Rain [:rain1] (inactive)]

on file: mail/test/mozmill/shared-modules/test-folder-display-helpers.js line 908
>   mark_action("fdh", "right_click_on_row", [aViewIndex, msgHdr]);

And this needs to be middle_click_on_row.

Comment 7

[Rain [:rain1] (inactive)]

Comment on attachment 436518 [details] [diff] [review]
revised patch based on comments

All our tests work on my PC, save one related to deleting junk messages (and it seems clear why it doesn't work). r+, but please land only after that gets fixed.

Comment 8

[Rain [:rain1] (inactive)]

Attachment: fix for junk messages

I think it is the right thing to time out here. The alternative (not waiting for any folder events at all) might miss some cases where messages are deleted after we check whether any are deleted. In general, I think wherever we expect something not to happen, having timeouts in this sort of controlled fashion is fine.

Comment 9

[Rain [:rain1] (inactive)]

(this patch is on top of yours)

Comment 10

[Andrew Sutherland [:asuth] (he/him)]

Thanks for the review; sorry I had missed a few things.  I think I may have lost some changes due to having patches spread over multiple trees and machines there for a bit...

I agree with the general logic that there are cases where we are expecting no events and need to reliably be sure that they did not happen.  The general problem with our wait-for-blah usage is that in most cases, time is not actually a variable; we just want to be sure the program logic has quiesced before declaring a failure.  Time is a good-enough proxy for that in most cases and since the success case (which should be common) should be the fast case, that works out well enough.

But waiting the whole timeout for an expected failure seems wrong.  The 'simple' solution is to just spin the event loop until it runs out of events.  The potential problem there would be that something asynchronously I/O driven could get starved out just enough for that to break.  Since script blocking which can defer click event processing is in such a boat, that's a concern.  (Our attempt to ensure loads are complete would mitigate, but I'm not confident about our ability to not screw that up.)

The easiest solution to address that would seem to be to generate a synthetic click event that we handle or hook the real click event processing to know when it has executed...

Thoughts?

Comment 11

[Rain [:rain1] (inactive)]

(In reply to comment #10)
> But waiting the whole timeout for an expected failure seems wrong.  The
> 'simple' solution is to just spin the event loop until it runs out of events. 
> The potential problem there would be that something asynchronously I/O driven
> could get starved out just enough for that to break.  Since script blocking
> which can defer click event processing is in such a boat, that's a concern. 
> (Our attempt to ensure loads are complete would mitigate, but I'm not confident
> about our ability to not screw that up.)
> 
> The easiest solution to address that would seem to be to generate a synthetic
> click event that we handle or hook the real click event processing to know when
> it has executed...

While I agree that in this case hooking into the click event processing seems like a better solution, how do you think we would implement it?

1. We could add another onclick listener, but I don't know what would guarantee that we execute after the deleteJunkInFolder command.

2. We could possibly wrap around and monkey-patch the deleteJunkInFolder function, I guess.

Of course both 1 and 2 assume that deleteJunkInFolder itself is synchronous -- an assumption that is currently true, I think, but might not be true with IMAP.

3. We could modify deleteJunkInFolder to take an optional callback. I don't like this because we'd have to give up simulating a click. (IIRC the original motivation for the test was to make sure that the delete junk menu item isn't disabled.)

It seems like what we really need here is a way for XUL command handlers to express that whatever work was started by the XUL command has completed. To my knowledge XUL doesn't have such a capability.

Maybe I'm overthinking the problem, though :) Is there a simple solution I'm missing?

Comment 12

[Andrew Sutherland [:asuth] (he/him)]

(In reply to comment #11)
> (IIRC the original
> motivation for the test was to make sure that the delete junk menu item isn't
> disabled.)

Maybe we should just test that the icon isn't disabled in that case.

I agree that all the solutions to the negative evidence problem as posed are difficult to address comprehensively.  Some form of oracle that was aware of the creation of new URI objects and could wait on their resolution in conjunction with knowledge that the click event was prosecuted would likely be sufficient.  (And spinning the event loop to emptiness, of course.)

Comment 13

[Rain [:rain1] (inactive)]

Attachment: a better fix for the junk issue

I think this is better -- the rationale is explained in the comments.

This involves modifications to mailnews/, so asking bienvenu for sr.

Comment 14

[David :Bienvenu]

Comment on attachment 437272 [details] [diff] [review]
a better fix for the junk issue

sr=me for the mailnews part.

Comment 15

[Andrew Sutherland [:asuth] (he/him)]

Comment on attachment 437272 [details] [diff] [review]
a better fix for the junk issue

Very nicely done.  Should I land this with my fixed patch?

Comment 16

[Rain [:rain1] (inactive)]

(In reply to comment #15)
> (From update of attachment 437272 [details] [diff] [review])
> Very nicely done.  Should I land this with my fixed patch?

Yeah, that would be great.

Comment 17

[Andrew Sutherland [:asuth] (he/him)]

both patches pushed to comm-central:
http://hg.mozilla.org/comm-central/rev/a75909d4b0b1
http://hg.mozilla.org/comm-central/rev/6cb656f5dc98

Comment 18

[Andrew Sutherland [:asuth] (he/him)]

Thanks to some observant observations by sid0, it was discovered I pushed the wrong version of his patch.

the backout of the wrong patch:
http://hg.mozilla.org/comm-central/rev/de590cc07beb

the right patch, crossing fingers:
http://hg.mozilla.org/comm-central/rev/5616df8372c4