Closed Bug 950636 Opened 11 years ago Closed 9 years ago

Intermittent test_modal_prompts.html | checking button0 default - got false, expected true

Categories

(Toolkit :: General, defect)

x86
Linux
defect
Not set
normal

Tracking

()

RESOLVED FIXED
mozilla43
Tracking Status
firefox42 --- fixed
firefox43 --- fixed

People

(Reporter: cbook, Assigned: Gijs)

References

()

Details

(Keywords: intermittent-failure)

Ubuntu VM 12.04 mozilla-inbound debug test mochitest-5 on 2013-12-16 00:42:20 PST for push ed71fd2a3a2d slave: tst-linux32-spot-478 https://tbpl.mozilla.org/php/getParsedLog.php?id=32016294&tree=Mozilla-Inbound 163867 ERROR TEST-UNEXPECTED-FAIL | /tests/toolkit/components/prompts/test/test_modal_prompts.html | checking button0 default - got false, expected true 163979 ERROR TEST-UNEXPECTED-FAIL | /tests/toolkit/components/prompts/test/test_modal_prompts.html | checking button0 default - got false, expected true 164099 ERROR TEST-UNEXPECTED-FAIL | /tests/toolkit/components/prompts/test/test_modal_prompts.html | checking button0 default - got false, expected true 164228 ERROR TEST-UNEXPECTED-FAIL | /tests/toolkit/components/prompts/test/test_modal_prompts.html | checking button2 default - got false, expected true
Summary: Intermittent TEST-UNEXPECTED-FAIL | /tests/toolkit/components/prompts/test/test_modal_prompts.html | checking button0 default - got false, expected true → Intermittent test_modal_prompts.html | checking button0 default - got false, expected true
This fails with runByDir enabled too. This fails specifically on mochitest plain for Linux x64 debug. Here's the results of a recent try push : https://treeherder.mozilla.org/#/jobs?repo=try&revision=87c487911773&filter-resultStatus=testfailed&filter-resultStatus=busted&filter-resultStatus=exception&filter-classifiedState=unclassified&filter-searchStr=linux%20x64%20m%285%29 12:39:54 INFO - 1709 INFO TEST-PASS | toolkit/components/prompts/test/test_modal_prompts.html | Checking accept-button is disabled 12:39:54 INFO - 1710 INFO TEST-PASS | toolkit/components/prompts/test/test_modal_prompts.html | Checking cancel-button isn't disabled 12:39:54 INFO - 1711 INFO TEST-PASS | toolkit/components/prompts/test/test_modal_prompts.html | Checking expected message 12:39:54 INFO - 1712 INFO TEST-PASS | toolkit/components/prompts/test/test_modal_prompts.html | Checking textbox visibility 12:39:54 INFO - 1713 INFO TEST-PASS | toolkit/components/prompts/test/test_modal_prompts.html | Checking passbox visibility 12:39:54 INFO - 1714 INFO TEST-PASS | toolkit/components/prompts/test/test_modal_prompts.html | Checking checkbox visibility 12:39:54 INFO - 1715 INFO TEST-PASS | toolkit/components/prompts/test/test_modal_prompts.html | Checking checkbox label 12:39:54 INFO - 1716 INFO TEST-PASS | toolkit/components/prompts/test/test_modal_prompts.html | Checking checkbox checked 12:39:54 INFO - 1717 INFO TEST-PASS | toolkit/components/prompts/test/test_modal_prompts.html | Checking expected icon CSS class 12:39:54 INFO - 1718 INFO TEST-PASS | toolkit/components/prompts/test/test_modal_prompts.html | Checking textbox value 12:39:54 INFO - 1719 INFO TEST-PASS | toolkit/components/prompts/test/test_modal_prompts.html | Checking passbox value 12:39:54 INFO - 1720 INFO TEST-PASS | toolkit/components/prompts/test/test_modal_prompts.html | checking button0 default 12:39:54 INFO - 1721 INFO TEST-PASS | toolkit/components/prompts/test/test_modal_prompts.html | checking button1 default 12:39:54 INFO - 1722 INFO TEST-PASS | toolkit/components/prompts/test/test_modal_prompts.html | checking button2 default 12:39:54 INFO - 1723 INFO TEST-PASS | toolkit/components/prompts/test/test_modal_prompts.html | focused element is a <null> 12:39:54 INFO - 1724 INFO TEST-FAIL | toolkit/components/prompts/test/test_modal_prompts.html | Focus seems missing on Linux 12:39:54 INFO - 1725 INFO TEST-PASS | toolkit/components/prompts/test/test_modal_prompts.html | dialog button is enabled now 12:39:54 INFO - 1726 INFO TEST-PASS | toolkit/components/prompts/test/test_modal_prompts.html | checked expected button num click 12:39:54 INFO - 1727 INFO TEST-PASS | toolkit/components/prompts/test/test_modal_prompts.html | handleDialog was invoked 12:39:54 INFO - 1728 INFO TEST-PASS | toolkit/components/prompts/test/test_modal_prompts.html | Running tests (isTabModal=true, usePromptService=false) 12:39:54 INFO - 1729 INFO TEST-PASS | toolkit/components/prompts/test/test_modal_prompts.html | got tabmodal promptbox 12:39:54 INFO - 1730 INFO TEST-PASS | toolkit/components/prompts/test/test_modal_prompts.html | --- handleDialog for test 1 --- (isTabModal=true, usePromptService=false) 12:39:54 INFO - 1731 INFO TEST-PASS | toolkit/components/prompts/test/test_modal_prompts.html | Checking expected message 12:39:54 INFO - 1732 INFO TEST-PASS | toolkit/components/prompts/test/test_modal_prompts.html | Checking textbox visibility 12:39:54 INFO - 1733 INFO TEST-PASS | toolkit/components/prompts/test/test_modal_prompts.html | Checking passbox visibility 12:39:54 INFO - 1734 INFO TEST-PASS | toolkit/components/prompts/test/test_modal_prompts.html | Checking checkbox visibility 12:39:54 INFO - 1735 INFO TEST-PASS | toolkit/components/prompts/test/test_modal_prompts.html | Checking checkbox label 12:39:54 INFO - 1736 INFO TEST-PASS | toolkit/components/prompts/test/test_modal_prompts.html | Checking checkbox checked 12:39:54 INFO - 1737 INFO TEST-PASS | toolkit/components/prompts/test/test_modal_prompts.html | Checking textbox value 12:39:55 INFO - 1738 INFO TEST-PASS | toolkit/components/prompts/test/test_modal_prompts.html | Checking passbox value 12:39:55 INFO - 1739 INFO TEST-PASS | toolkit/components/prompts/test/test_modal_prompts.html | checking button0 default 12:39:55 INFO - 1740 INFO TEST-PASS | toolkit/components/prompts/test/test_modal_prompts.html | checking button1 default 12:39:55 INFO - 1741 INFO TEST-PASS | toolkit/components/prompts/test/test_modal_prompts.html | checking button2 default 12:39:55 INFO - 1742 INFO TEST-PASS | toolkit/components/prompts/test/test_modal_prompts.html | focused element is a button 12:39:55 INFO - 1743 INFO TEST-PASS | toolkit/components/prompts/test/test_modal_prompts.html | Checking focused element 12:39:55 INFO - 1744 INFO TEST-PASS | toolkit/components/prompts/test/test_modal_prompts.html | handleDialog done 12:39:55 INFO - 1745 INFO TEST-PASS | toolkit/components/prompts/test/test_modal_prompts.html | handleDialog was invoked 12:39:55 INFO - 1746 INFO TEST-PASS | toolkit/components/prompts/test/test_modal_prompts.html | got tabmodal promptbox 12:39:55 INFO - 1747 INFO TEST-PASS | toolkit/components/prompts/test/test_modal_prompts.html | --- handleDialog for test 2 --- (isTabModal=true, usePromptService=false) 12:39:55 INFO - 1748 INFO TEST-PASS | toolkit/components/prompts/test/test_modal_prompts.html | Checking expected message 12:39:55 INFO - 1749 INFO TEST-PASS | toolkit/components/prompts/test/test_modal_prompts.html | Checking textbox visibility 12:39:55 INFO - 1750 INFO TEST-PASS | toolkit/components/prompts/test/test_modal_prompts.html | Checking passbox visibility 12:39:55 INFO - 1751 INFO TEST-PASS | toolkit/components/prompts/test/test_modal_prompts.html | Checking checkbox visibility 12:39:55 INFO - 1752 INFO TEST-PASS | toolkit/components/prompts/test/test_modal_prompts.html | Checking checkbox label 12:39:55 INFO - 1753 INFO TEST-PASS | toolkit/components/prompts/test/test_modal_prompts.html | Checking checkbox checked 12:39:55 INFO - 1754 INFO TEST-PASS | toolkit/components/prompts/test/test_modal_prompts.html | Checking textbox value 12:39:55 INFO - 1755 INFO TEST-PASS | toolkit/components/prompts/test/test_modal_prompts.html | Checking passbox value 12:39:55 INFO - 1756 INFO TEST-PASS | toolkit/components/prompts/test/test_modal_prompts.html | checking button0 default 12:39:55 INFO - 1757 INFO TEST-PASS | toolkit/components/prompts/test/test_modal_prompts.html | checking button1 default 12:39:55 INFO - 1758 INFO TEST-PASS | toolkit/components/prompts/test/test_modal_prompts.html | checking button2 default 12:39:55 INFO - 1759 INFO TEST-PASS | toolkit/components/prompts/test/test_modal_prompts.html | focused element is a button 12:39:55 INFO - 1760 INFO TEST-PASS | toolkit/components/prompts/test/test_modal_prompts.html | Checking focused element 12:39:55 INFO - 1761 INFO TEST-PASS | toolkit/components/prompts/test/test_modal_prompts.html | handleDialog done 12:39:55 INFO - 1762 INFO TEST-PASS | toolkit/components/prompts/test/test_modal_prompts.html | handleDialog was invoked 12:39:55 INFO - 1763 INFO TEST-PASS | toolkit/components/prompts/test/test_modal_prompts.html | got tabmodal promptbox 12:39:55 INFO - 1764 INFO TEST-PASS | toolkit/components/prompts/test/test_modal_prompts.html | --- handleDialog for test 3 --- (isTabModal=true, usePromptService=false) 12:39:55 INFO - 1765 INFO TEST-PASS | toolkit/components/prompts/test/test_modal_prompts.html | Checking expected message 12:39:55 INFO - 1766 INFO TEST-PASS | toolkit/components/prompts/test/test_modal_prompts.html | Checking textbox visibility 12:39:55 INFO - 1767 INFO TEST-PASS | toolkit/components/prompts/test/test_modal_prompts.html | Checking passbox visibility 12:39:55 INFO - 1768 INFO TEST-PASS | toolkit/components/prompts/test/test_modal_prompts.html | Checking checkbox visibility 12:39:55 INFO - 1769 INFO TEST-PASS | toolkit/components/prompts/test/test_modal_prompts.html | Checking checkbox label 12:39:55 INFO - 1770 INFO TEST-PASS | toolkit/components/prompts/test/test_modal_prompts.html | Checking checkbox checked 12:39:55 INFO - 1771 INFO TEST-PASS | toolkit/components/prompts/test/test_modal_prompts.html | Checking textbox value 12:39:55 INFO - 1772 INFO TEST-PASS | toolkit/components/prompts/test/test_modal_prompts.html | Checking passbox value 12:39:55 INFO - 1773 INFO TEST-PASS | toolkit/components/prompts/test/test_modal_prompts.html | checking button0 default 12:39:55 INFO - 1774 INFO TEST-PASS | toolkit/components/prompts/test/test_modal_prompts.html | checking button1 default 12:39:55 INFO - 1775 INFO TEST-PASS | toolkit/components/prompts/test/test_modal_prompts.html | checking button2 default 12:39:55 INFO - 1776 INFO TEST-PASS | toolkit/components/prompts/test/test_modal_prompts.html | focused element is a button 12:39:55 INFO - 1777 INFO TEST-PASS | toolkit/components/prompts/test/test_modal_prompts.html | Checking focused element 12:39:55 INFO - 1778 INFO TEST-PASS | toolkit/components/prompts/test/test_modal_prompts.html | handleDialog done 12:39:55 INFO - 1779 INFO TEST-PASS | toolkit/components/prompts/test/test_modal_prompts.html | handleDialog was invoked 12:39:55 INFO - 1780 INFO TEST-PASS | toolkit/components/prompts/test/test_modal_prompts.html | checkbox was checked 12:39:55 INFO - 1781 INFO TEST-PASS | toolkit/components/prompts/test/test_modal_prompts.html | got tabmodal promptbox 12:39:55 INFO - 1782 INFO TEST-PASS | toolkit/components/prompts/test/test_modal_prompts.html | --- handleDialog for test 4 --- (isTabModal=true, usePromptService=false) 12:39:55 INFO - 1783 INFO TEST-PASS | toolkit/components/prompts/test/test_modal_prompts.html | Checking expected message 12:39:55 INFO - 1784 INFO TEST-PASS | toolkit/components/prompts/test/test_modal_prompts.html | Checking textbox visibility 12:39:55 INFO - 1785 INFO TEST-PASS | toolkit/components/prompts/test/test_modal_prompts.html | Checking passbox visibility 12:39:55 INFO - 1786 INFO TEST-PASS | toolkit/components/prompts/test/test_modal_prompts.html | Checking checkbox visibility 12:39:55 INFO - 1787 INFO TEST-PASS | toolkit/components/prompts/test/test_modal_prompts.html | Checking checkbox label 12:39:55 INFO - 1788 INFO TEST-PASS | toolkit/components/prompts/test/test_modal_prompts.html | Checking checkbox checked 12:39:55 INFO - 1789 INFO TEST-PASS | toolkit/components/prompts/test/test_modal_prompts.html | Checking textbox value 12:39:55 INFO - 1790 INFO TEST-PASS | toolkit/components/prompts/test/test_modal_prompts.html | Checking passbox value 12:39:55 INFO - 1791 INFO TEST-PASS | toolkit/components/prompts/test/test_modal_prompts.html | checking button0 default 12:39:55 INFO - 1792 INFO TEST-PASS | toolkit/components/prompts/test/test_modal_prompts.html | checking button1 default 12:39:55 INFO - 1793 INFO TEST-PASS | toolkit/components/prompts/test/test_modal_prompts.html | checking button2 default 12:39:55 INFO - 1794 INFO TEST-PASS | toolkit/components/prompts/test/test_modal_prompts.html | focused element is a button 12:39:55 INFO - 1795 INFO TEST-PASS | toolkit/components/prompts/test/test_modal_prompts.html | Checking focused element 12:39:55 INFO - 1796 INFO TEST-PASS | toolkit/components/prompts/test/test_modal_prompts.html | handleDialog done 12:39:55 INFO - 1797 INFO TEST-PASS | toolkit/components/prompts/test/test_modal_prompts.html | checked expected retval 12:39:55 INFO - 1798 INFO TEST-PASS | toolkit/components/prompts/test/test_modal_prompts.html | handleDialog was invoked 12:39:55 INFO - 1799 INFO TEST-PASS | toolkit/components/prompts/test/test_modal_prompts.html | got tabmodal promptbox 12:39:55 INFO - 1800 INFO TEST-PASS | toolkit/components/prompts/test/test_modal_prompts.html | --- handleDialog for test 5 --- (isTabModal=true, usePromptService=false) 12:39:55 INFO - 1801 INFO TEST-PASS | toolkit/components/prompts/test/test_modal_prompts.html | Checking expected message 12:39:55 INFO - 1802 INFO TEST-PASS | toolkit/components/prompts/test/test_modal_prompts.html | Checking textbox visibility 12:39:55 INFO - 1803 INFO TEST-PASS | toolkit/components/prompts/test/test_modal_prompts.html | Checking passbox visibility 12:39:55 INFO - 1804 INFO TEST-PASS | toolkit/components/prompts/test/test_modal_prompts.html | Checking checkbox visibility 12:39:55 INFO - 1805 INFO TEST-PASS | toolkit/components/prompts/test/test_modal_prompts.html | Checking checkbox label 12:39:55 INFO - 1806 INFO TEST-PASS | toolkit/components/prompts/test/test_modal_prompts.html | Checking checkbox checked 12:39:55 INFO - 1807 INFO TEST-PASS | toolkit/components/prompts/test/test_modal_prompts.html | Checking textbox value 12:39:55 INFO - 1808 INFO TEST-PASS | toolkit/components/prompts/test/test_modal_prompts.html | Checking passbox value 12:39:55 INFO - 1809 INFO TEST-UNEXPECTED-FAIL | toolkit/components/prompts/test/test_modal_prompts.html | checking button0 default - got false, expected true
Hi Justin, You are probably the original author of this test. It would be really helpful if you could please take a look into this and help us sort this out.
Flags: needinfo?(dolske)
Blocks: 1162
Blocks: 1162003
No longer blocks: 1162
For a random sampling of a few reports, ooks like this is mainly (exclusively?) happening on Linux, and happens after the "--- handleDialog for test # ---" for test 6 or 7 or 8. Only a single isDefaultButton check is failing per subtext, looks like for the one that _should_ be the default but isn't. We do have code, in the blur/focus <handlers> for http://mxr.mozilla.org/mozilla-central/source/toolkit/components/prompts/content/tabprompts.xml#308, to clear the default button when focus goes elsewhere. So I'd suspect there's a race that is shifting focus to somewhere else. Might be interesting to add some temporary logging to display the currently focused element during the test run? Gijs, maybe you can help out?
Flags: needinfo?(dolske) → needinfo?(gijskruitbosch+bugs)
I can reproduce locally with a debug build, so I'll investigate from there.
(In reply to Justin Dolske [:Dolske] from comment #340) > For a random sampling of a few reports, ooks like this is mainly > (exclusively?) happening on Linux, and happens after the "--- handleDialog > for test # ---" for test 6 or 7 or 8. > > Only a single isDefaultButton check is failing per subtext, looks like for > the one that _should_ be the default but isn't. > > We do have code, in the blur/focus <handlers> for > http://mxr.mozilla.org/mozilla-central/source/toolkit/components/prompts/ > content/tabprompts.xml#308, to clear the default button when focus goes > elsewhere. So I logged all of these (focus + blur handlers) and it does seem like the blur handler somehow gets fired before the broken cases. I haven't yet figured out why. Need to instrument more. (moving to toolkit as this is definitely not xpconnect - not sure if this is what notifications & alerts is for, but w/e)
Assignee: nobody → gijskruitbosch+bugs
Component: XPConnect → General
Flags: needinfo?(gijskruitbosch+bugs)
Product: Core → Toolkit
This has proved stubborn so far. I can't seem to get something logged here that indicates what is going on. I have blur events, but logging focus events on either the browser window or the content window doesn't show anything useful. I don't understand why focus would move. The focus manager is useless because it doesn't seem to really be doing the right thing on Linux here anyway. Maybe Neil Deakin might know more? Going to poke at this a little more and then defer to him, I think. Just to check, jmaher, is this regressing 7 days ago "just" run-by-dir-based ?
Flags: needinfo?(jmaher)
:gijs, thanks for asking. All the comments in this bug are unrelated to run-by-dir, we find a perma fail on ASAN with run-by-dir for this specific test case. Likewise common failures in debug using run-by-dir. this is one of the few tests remaining before flipping the switch- once we have the others fully figured out we can determine to disable, or wait for a defined period of time to fix it. Probably next week we will have this well quantified.
Flags: needinfo?(jmaher)
(In reply to Joel Maher (:jmaher) from comment #373) > :gijs, thanks for asking. All the comments in this bug are unrelated to > run-by-dir, we find a perma fail on ASAN with run-by-dir for this specific > test case. Likewise common failures in debug using run-by-dir. > > this is one of the few tests remaining before flipping the switch- once we > have the others fully figured out we can determine to disable, or wait for a > defined period of time to fix it. Probably next week we will have this well > quantified. I'm confused. bug 1162003 seems to have landed 7 days ago, which coincides with this becoming more frequent. That seems like the likely cause of that - if you don't think so, can you run a regression check to see what did cause the increase in frequency?
Flags: needinfo?(jmaher)
somehow I overlooked the obvious. Yes, run-by-dir on opt is probably the most likely culprit here. I have initiated some retriggers: https://treeherder.mozilla.org/#/jobs?repo=mozilla-inbound&fromchange=f73333a589de&tochange=d95b0ae9564c&filter-searchStr=Ubuntu%20VM%2012.04%20mozilla-inbound%20opt%20test%20mochitest-5 if this doesn't show enough evidence, I will bump up the number to 20 instances and repeat until we find what we are looking for.
Flags: needinfo?(jmaher)
(In reply to Joel Maher (:jmaher) from comment #384) > somehow I overlooked the obvious. Yes, run-by-dir on opt is probably the > most likely culprit here. I have initiated some retriggers: > https://treeherder.mozilla.org/#/jobs?repo=mozilla- > inbound&fromchange=f73333a589de&tochange=d95b0ae9564c&filter- > searchStr=Ubuntu%20VM%2012.04%20mozilla-inbound%20opt%20test%20mochitest-5 > > if this doesn't show enough evidence, I will bump up the number to 20 > instances and repeat until we find what we are looking for. Yeah, that makes it pretty obvious. Talking to dolske, both of us think this is a test issue, though I've tried to figure out exactly what does happen to focus and failed. Logging hasn't proven enlightening, and trying to use the debugger caused fatal assertion failures. :-\ Neil, do you think you can take a look?
Flags: needinfo?(enndeakin)
I was trying to catch an RR replay of this. After 8 hours of running this test under chaos mode with RR I got a replay of this instead: /tests/toolkit/components/prompts/test/test_modal_prompts.html | Checking accept-button is disabled | got false, expected true - expected: PASS It might still be related to the original failure, which doesn't seem to really reproduce under RR. I can give you ssh access to the machine if it would be useful, otherwise let me know so I can try to get a replay of another intermittent.
Flags: needinfo?(gijskruitbosch+bugs)
(In reply to Benoit Girard (:BenWa) from comment #433) > I was trying to catch an RR replay of this. After 8 hours of running this > test under chaos mode with RR I got a replay of this instead: > /tests/toolkit/components/prompts/test/test_modal_prompts.html | Checking > accept-button is disabled | got false, expected true - expected: PASS > > It might still be related to the original failure, which doesn't seem to > really reproduce under RR. I can give you ssh access to the machine if it > would be useful, otherwise let me know so I can try to get a replay of > another intermittent. I'm interested! I don't know anything about RR though, apart from the fact that debugging JS with it isn't easily possible yet... can you send me SSH details and maybe a link or two about how to get going?
Flags: needinfo?(gijskruitbosch+bugs) → needinfo?(bgirard)
I've PM'ed the password. Here's the rest of the instruction again: ssh mozilla@orangehunter1.fantasytalesonline.com cd /home/mozilla/mozilla-central/tree cat run.log (if you want to see the execution and get the RR event IDs) ~/rr/obj/bin/rr replay rr-recording/latest-trace Note that you want to use ~/rr/obj/bin/rr and not 'rr' from the path.
Flags: needinfo?(bgirard)
Unfortunately, the RR issue seems like a separate issue. Two things that I noticed: 1) it is breaking when tabModal = false, and all the timeouts are for the tabmodal versions of the test. 2) in the 2-3 tests that run before the one that breaks, nsFocusManager::SendFocusOrBlurEvent does not fire even once (I set a breakpoint, it doesn't get hit until after the failure, when starting from the RR log IDs a while before the test failure). The latter could be the case on tinderbox generally as well, though it would surprise me: when logging blur/focus events locally, some items would run without pause without any events being triggered, and others didn't. The cases that broke didn't. So I'm not entirely sure what's going on here, but the fact that the failure that's in the RR dump is in the non-tabmodal case means that it's unlikely to help much further with debugging the tabmodal case. Benoit, feel free to reclaim the machine for trying to repro other failures... I'm still hoping Neil could provide some enlightenment here...
Considering both me and dolske think this is an issue with the test opening a gazillion prompts in a row (rather than an issue with prompt code), I decided to just add some waiting. That solves the issue for me locally on my linux vm. remote: https://treeherder.mozilla.org/#/jobs?repo=fx-team&revision=e4da9601cb2b
Flags: needinfo?(enndeakin)
Status: NEW → RESOLVED
Closed: 9 years ago
Resolution: --- → FIXED
Target Milestone: --- → mozilla43
You need to log in before you can comment on or make changes to this bug.