Closed Bug 803604 Opened 7 years ago Closed 6 years ago

Frequent random orange: TEST-UNEXPECTED-FAIL | test-account-actions.js::test_account_actions

Categories

(Thunderbird :: Account Manager, defect)

x86_64
Linux
defect
Not set

Tracking

(Not tracked)

RESOLVED WORKSFORME

People

(Reporter: standard8, Unassigned)

Details

(Keywords: intermittent-failure)

This is a frequent random orange we're seeing on the Thunderbird tinderboxes:

WARNING: GetDefaultCharsetForLocale: need to add multi locale support: file ../../../../../../mozilla/intl/locale/src/unix/nsUNIXCharset.cpp, line 105
2012-10-19 08:42:25	mail.wizard	INFO	Initializing setup wizard
2012-10-19 08:42:25	mail.wizard	INFO	Email account setup dialog loaded.
2012-10-19 08:42:25	mail.wizard	INFO	switching to UI mode start
TEST-UNEXPECTED-FAIL | /home/cltbld/talos-slave/test/build/mozmill/account/test-account-actions.js | test-account-actions.js::test_account_actions
TEST-START | /home/cltbld/talos-slave/test/build/mozmill/account/test-account-actions.js | teardownModule
OS: Mac OS X → Linux
(Linux 64 bit debug boxes)
SUMMARY-PASS | test-account-actions.js::setupModule
SUMMARY-UNEXPECTED-FAIL | test-account-actions.js | test-account-actions.js::test_account_actions
  EXCEPTION: Timeout waiting for popup to open
    at: utils.js line 447
       TimeoutError utils.js 447
       waitFor utils.js 485
       wait_for_popup_to_open test-folder-display-helpers.js 1365
       subtest_check_account_actions test-account-actions.js 97
       Runner.prototype.wrapper frame.js 577
       WindowWatcher_notify test-window-helpers.js 332
SUMMARY-PASS | test-account-actions.js::teardownModule
Is this still happening? Didn't bug 803664 fix this?
Any ideas what this may be?
Not sure, I see a couple of "Test Failure: Timeout waiting for popup to open" which makes me wonder if this isn't being propagated back up the stack correctly.
We might be able to change that to TEST-UNEXPECTED-FAIL, though I'm not sure where "Test Failure" gets added (and we'd need to be careful if this is being hidden somewhere), also getting the name or id of the popup might be useful as well...

I also notice there's no indication of how far through the test we are. Maybe we could break it down into separate sub-tests somehow.
I tried to run this against the fancy log viewer, but I get a 404 when I try and use the "Download raw log" button from the full log.

Specifically, for the log viewer at:
http://clicky.visophyte.org/tools/arbpl-mozmill-standalone/?log=

And looking at https://tbpl.mozilla.org/php/getParsedLog.php?id=16950069&full=1&branch=comm-central to get the raw log, I tried:

http://clicky.visophyte.org/tools/arbpl-mozmill-standalone/?log=http://ftp.mozilla.org/pub/mozilla.org/thunderbird/tinderbox-builds/comm-central-linux64-debug/1352694040/comm-central_fedora64-debug_test-mozmill-bm18-tests1-linux-build340.txt.gz

and that didn't work because it appears the log has already been rotated out to someplace else.  The log clearly exists somewhere, so if you can figure out the URL, it might be worth trying out the fancy log viewer.
Ok, with that most recent log, the important bit seems to be:

resource://mozmill/modules/utils.js line 447 TimeoutError
resource://mozmill/modules/utils.js line 485 waitFor
file:///home/cltbld/talos-slave/test/build/mozmill/shared-modules/test-folder-display-helpers.js line 1367 wait_for_popup_to_open
file:///home/cltbld/talos-slave/test/build/mozmill/account/test-account-actions.js line 78 subtest_check_account_actions
file:///home/cltbld/talos-slave/test/build/mozmill/account/test-account-actions.js line 153
 resource://mozmill/modules/frame.jsline 577Runner.prototype.wrapper
file:///home/cltbld/talos-slave/test/build/mozmill/shared-modules/test-window-helpers.js line 332 WindowWatcher_notify

The account settings window is open, and the account actions button is focussed.

We open the popup several times during the test. My only thoughts would be if we're trying to do something a bit too quick for linux. Andrew, any ideas?
I am the author of that test so I am interested why it fails. I can not reproduce the failure on my linux box. The test log contains a screenshot of the Account settings window. It seems fine, the account actions button is focused but the dropdown is not shown. The "mail for tinderbox@example.com" account is selected, which is the first one to be tested. So the subtest_check_account_actions() can be called from these spots: http://hg.mozilla.org/comm-central/file/ef4833cf43da/mail/test/mozmill/account/test-account-actions.js#l102

http://hg.mozilla.org/comm-central/file/ef4833cf43da/mail/test/mozmill/account/test-account-actions.js#l127

http://hg.mozilla.org/comm-central/file/ef4833cf43da/mail/test/mozmill/account/test-account-actions.js#l140

http://hg.mozilla.org/comm-central/file/ef4833cf43da/mail/test/mozmill/account/test-account-actions.js#l153

Would it be safer to not use amc.click() but something like menupopup.openPopup() ?
openPopup might work better.  Our click_menus_in_sequence helper uses it, and it was created for popup nightmares, I think:
http://mxr.mozilla.org/comm-central/source/mail/test/mozmill/shared-modules/test-window-helpers.js#892

You may just want to try click_menus_in_sequence even if it's overkill for your problems.


Looking at the log:
http://clicky.visophyte.org/tools/arbpl-mozmill-standalone/?log=http://ftp.mozilla.org/pub/mozilla.org/thunderbird/tinderbox-builds/comm-central-linux64-debug/1353362894/comm-central_fedora64-debug_test-mozmill-bm18-tests1-linux-build356.txt.gz

We can see this old chestnut:
===
click button#accountActionsButton x: 5 y: 5
mousedown
mouse button left target: button#accountActionsButton in mailnews:accountmanager (12) original target: button#accountActionsButton
bubbled mousedown
mouse button 0 target: button#accountActionsButton in mailnews:accountmanager (12) original target: button#accountActionsButton
mouseup
mouse button left target: button#accountActionsButton in mailnews:accountmanager (12) original target: button#accountActionsButton
bubbled mouseup
mouse button 0 target: button#accountActionsButton in mailnews:accountmanager (12) original target: button#accountActionsButton
click
mouse button left target: button#accountActionsButton in mailnews:accountmanager (12) original target: button#accountActionsButton
bubbled click
mouse button 0 target: button#accountActionsButton in mailnews:accountmanager (12) original target: button#accountActionsButton
popupShowing
menupopup#accountActionsDropdown target: menupopup#accountActionsDropdown current target: menupopup#accountActionsDropdown
popupHiding
menupopup#accountActionsDropdown target: menupopup#accountActionsDropdown current target: menupopup#accountActionsDropdown
popupHidden
menupopup#accountActionsDropdown target: menupopup#accountActionsDropdown current target: menupopup#accountActionsDropdown
===

Specifically, we can see the click happens, the popup shows up, but then gets hidden in the same go and only then do we wait for the popup to show up.  This might have something to do with the click that happens on treechildren#account-tree-children immediately prior to that click:
===
mousedown
mouse button left target: treechildren#account-tree-children in mailnews:accountmanager (12) original target: treechildren#account-tree-children
bubbled mousedown
mouse button 0 target: treechildren#account-tree-children in mailnews:accountmanager (12) original target: treechildren#account-tree-children
mouseup
mouse button left target: treechildren#account-tree-children in mailnews:accountmanager (12) original target: treechildren#account-tree-children
bubbled mouseup
mouse button 0 target: treechildren#account-tree-children in mailnews:accountmanager (12) original target: treechildren#account-tree-children
click
mouse button left target: treechildren#account-tree-children in mailnews:accountmanager (12) original target: treechildren#account-tree-children
bubbled click
mouse button 0 target: treechildren#account-tree-children in mailnews:accountmanager (12) original target: treechildren#account-tree-children
===
Whiteboard: [tb-orange]
The click_menus_in_sequence fails too, e.g. in bug 726966.
Closing bugs where TBPLbot has previously commented, but have now not been modified for >3 months & do not contain the whiteboard strings for disabled/annotated tests or use the keyword leave-open. Filter on: mass-intermittent-bug-closure-2014-07
Status: NEW → RESOLVED
Closed: 6 years ago
Resolution: --- → WORKSFORME
You need to log in before you can comment on or make changes to this bug.