Closed Bug 821208 Opened 8 years ago Closed 8 years ago

Intermittent browser_social_chatwindow.js | Test timed out

Categories

(Firefox Graveyard :: SocialAPI, defect)

x86_64
macOS
defect
Not set
normal

Tracking

(Not tracked)

RESOLVED FIXED
Firefox 21

People

(Reporter: ewong, Assigned: markh)

References

Details

(Keywords: intermittent-failure, Whiteboard: [qa-])

Attachments

(2 files, 1 obsolete file)

Rev4 MacOSX Snow Leopard 10.6 mozilla-inbound debug test mochitest-browser-chrome on 2012-12-12 19:42:54 PST for push 0368b4c03c63


TEST-INFO | chrome://mochitests/content/browser/browser/base/content/test/social/browser_social_chatwindow.js | sub-test testChatWindowChooser complete
--DOMWINDOW == 167 (0x14bd8dba8) [serial = 1796] [outer = 0x14e968f30] [url = https://example.com/browser/browser/base/content/test/social/social_worker.js]
--DOMWINDOW == 166 (0x14e968fb8) [serial = 1793] [outer = 0x0] [url = https://example.com/browser/browser/base/content/test/social/social_worker.js]
--DOMWINDOW == 165 (0x14b064f78) [serial = 1889] [outer = 0x1500ed9e0] [url = https://example.com/browser/browser/base/content/test/social/social_chat.html?id=first%20chat]
--DOMWINDOW == 164 (0x1500eda68) [serial = 1887] [outer = 0x0] [url = https://example.com/browser/browser/base/content/test/social/social_chat.html?id=first%20chat]
--DOMWINDOW == 163 (0x1505dd598) [serial = 1891] [outer = 0x15053e080] [url = about:blank]
--DOMWINDOW == 162 (0x15053e108) [serial = 1890] [outer = 0x0] [url = about:blank]
--DOMWINDOW == 161 (0x14b0b6808) [serial = 1894] [outer = 0x14fadda30] [url = https://example.com/browser/browser/base/content/test/social/social_chat.html?id=second%20chat]
--DOMWINDOW == 160 (0x14faddab8) [serial = 1892] [outer = 0x0] [url = https://example.com/browser/browser/base/content/test/social/social_chat.html?id=second%20chat]
--DOMWINDOW == 159 (0x1180822b8) [serial = 1896] [outer = 0x14ff49830] [url = about:blank]
--DOMWINDOW == 158 (0x14ff498b8) [serial = 1895] [outer = 0x0] [url = about:blank]
--DOMWINDOW == 157 (0x14b064298) [serial = 1899] [outer = 0x1486cdba0] [url = https://example.com/browser/browser/base/content/test/social/social_chat.html?id=third%20chat]
--DOMWINDOW == 156 (0x1486cdc28) [serial = 1897] [outer = 0x0] [url = https://example.com/browser/browser/base/content/test/social/social_chat.html?id=third%20chat]
--DOMWINDOW == 155 (0x14b040478) [serial = 1901] [outer = 0x14dd5cd50] [url = about:blank]
--DOMWINDOW == 154 (0x14dd5cdd8) [serial = 1900] [outer = 0x0] [url = about:blank]
--DOMWINDOW == 153 (0x14ff1e8c8) [serial = 1904] [outer = 0x14a9912b0] [url = https://example.com/browser/browser/base/content/test/social/social_chat.html?id=first%20chat]
--DOMWINDOW == 152 (0x14d8cd148) [serial = 1903] [outer = 0x14a9912b0] [url = about:blank]
--DOMWINDOW == 151 (0x14a991338) [serial = 1902] [outer = 0x0] [url = https://example.com/browser/browser/base/content/test/social/social_chat.html?id=first%20chat]
--DOMWINDOW == 150 (0x14bd06018) [serial = 1906] [outer = 0x149581580] [url = about:blank]
--DOMWINDOW == 149 (0x149581608) [serial = 1905] [outer = 0x0] [url = about:blank]
--DOMWINDOW == 148 (0x14ff48bf8) [serial = 1909] [outer = 0x14d85ed20] [url = https://example.com/browser/browser/base/content/test/social/social_chat.html?id=second%20chat]
--DOMWINDOW == 147 (0x149581ce8) [serial = 1908] [outer = 0x14d85ed20] [url = about:blank]
--DOMWINDOW == 146 (0x14d85eda8) [serial = 1907] [outer = 0x0] [url = https://example.com/browser/browser/base/content/test/social/social_chat.html?id=second%20chat]
--DOMWINDOW == 145 (0x147a70818) [serial = 1911] [outer = 0x11c2a33e0] [url = about:blank]
--DOMWINDOW == 144 (0x11c2a3468) [serial = 1910] [outer = 0x0] [url = about:blank]
--DOMWINDOW == 143 (0x14a9e4348) [serial = 1914] [outer = 0x14ac2ac30] [url = https://example.com/browser/browser/base/content/test/social/social_chat.html?id=third%20chat]
--DOMWINDOW == 142 (0x147aaac38) [serial = 1913] [outer = 0x14ac2ac30] [url = about:blank]
--DOMWINDOW == 141 (0x14ac2acb8) [serial = 1912] [outer = 0x0] [url = https://example.com/browser/browser/base/content/test/social/social_chat.html?id=third%20chat]
--DOMWINDOW == 140 (0x14adf9608) [serial = 1916] [outer = 0x150015c10] [url = about:blank]
--DOMWINDOW == 139 (0x150015c98) [serial = 1915] [outer = 0x0] [url = about:blank]
--DOMWINDOW == 138 (0x14a87b828) [serial = 1919] [outer = 0x14a8d52e0] [url = https://example.com/browser/browser/base/content/test/social/social_chat.html?id=first%20chat]
--DOMWINDOW == 137 (0x14aaf9e58) [serial = 1918] [outer = 0x14a8d52e0] [url = about:blank]
--DOMWINDOW == 136 (0x14a8d5368) [serial = 1917] [outer = 0x0] [url = https://example.com/browser/browser/base/content/test/social/social_chat.html?id=first%20chat]
--DOMWINDOW == 135 (0x14a9600b8) [serial = 1921] [outer = 0x14ffcd850] [url = about:blank]
--DOMWINDOW == 134 (0x14ffcd8d8) [serial = 1920] [outer = 0x0] [url = about:blank]
--DOMWINDOW == 133 (0x1505f8028) [serial = 1924] [outer = 0x14aa67b20] [url = https://example.com/browser/browser/base/content/test/social/social_chat.html?id=second%20chat]
--DOMWINDOW == 132 (0x14a881bd8) [serial = 1923] [outer = 0x14aa67b20] [url = about:blank]
--DOMWINDOW == 131 (0x14aa67ba8) [serial = 1922] [outer = 0x0] [url = https://example.com/browser/browser/base/content/test/social/social_chat.html?id=second%20chat]
--DOMWINDOW == 130 (0x14ebc20e8) [serial = 1926] [outer = 0x14a8b41c0] [url = about:blank]
--DOMWINDOW == 129 (0x14a8b4248) [serial = 1925] [outer = 0x0] [url = about:blank]
--DOMWINDOW == 128 (0x14f602888) [serial = 1929] [outer = 0x14f6927e0] [url = https://example.com/browser/browser/base/content/test/social/social_chat.html?id=third%20chat]
--DOMWINDOW == 127 (0x14eba2ee8) [serial = 1928] [outer = 0x14f6927e0] [url = about:blank]
--DOMWINDOW == 126 (0x14f692868) [serial = 1927] [outer = 0x0] [url = https://example.com/browser/browser/base/content/test/social/social_chat.html?id=third%20chat]
--DOMWINDOW == 125 (0x14e9575c8) [serial = 1931] [outer = 0x12ade44f0] [url = about:blank]
--DOMWINDOW == 124 (0x12ade4578) [serial = 1930] [outer = 0x0] [url = about:blank]
--DOMWINDOW == 123 (0x1485389c8) [serial = 1934] [outer = 0x1505e29c0] [url = https://example.com/browser/browser/base/content/test/social/social_chat.html?id=first%20chat]
--DOMWINDOW == 122 (0x127709a28) [serial = 1933] [outer = 0x1505e29c0] [url = about:blank]
--DOMWINDOW == 121 (0x1505e2a48) [serial = 1932] [outer = 0x0] [url = https://example.com/browser/browser/base/content/test/social/social_chat.html?id=first%20chat]
--DOMWINDOW == 120 (0x14a8c08d8) [serial = 1947] [outer = 0x14e9096d0] [url = about:blank]
--DOMWINDOW == 119 (0x14fa16548) [serial = 1936] [outer = 0x14e9096d0] [url = about:blank]
--DOMWINDOW == 118 (0x14e909758) [serial = 1935] [outer = 0x0] [url = about:blank]
--DOMWINDOW == 117 (0x14d899138) [serial = 1939] [outer = 0x14ebcc610] [url = https://example.com/browser/browser/base/content/test/social/social_chat.html?id=second%20chat]
--DOMWINDOW == 116 (0x14eb998c8) [serial = 1938] [outer = 0x14ebcc610] [url = about:blank]
--DOMWINDOW == 115 (0x14ebcc698) [serial = 1937] [outer = 0x0] [url = https://example.com/browser/browser/base/content/test/social/social_chat.html?id=second%20chat]
--DOMWINDOW == 114 (0x1495c80c8) [serial = 1941] [outer = 0x14ff13400] [url = about:blank]
--DOMWINDOW == 113 (0x14ff13488) [serial = 1940] [outer = 0x0] [url = about:blank]
--DOMWINDOW == 112 (0x15052ed38) [serial = 1944] [outer = 0x147ad5e90] [url = https://example.com/browser/browser/base/content/test/social/social_chat.html?id=third%20chat]
--DOMWINDOW == 111 (0x149516498) [serial = 1943] [outer = 0x147ad5e90] [url = about:blank]
--DOMWINDOW == 110 (0x147ad5f18) [serial = 1942] [outer = 0x0] [url = https://example.com/browser/browser/base/content/test/social/social_chat.html?id=third%20chat]
--DOMWINDOW == 109 (0x14bd3ad58) [serial = 1946] [outer = 0x14a83ed40] [url = about:blank]
--DOMWINDOW == 108 (0x14a83edc8) [serial = 1945] [outer = 0x0] [url = about:blank]
--DOMWINDOW == 107 (0x14eb2a7f8) [serial = 1949] [outer = 0x14a885250] [url = about:blank]
--DOMWINDOW == 106 (0x14a8852d8) [serial = 1948] [outer = 0x0] [url = https://example.com/browser/browser/base/content/test/social/social_chat.html]
--DOMWINDOW == 105 (0x14fa1f4d8) [serial = 1952] [outer = 0x11c503ab0] [url = about:blank]
--DOMWINDOW == 104 (0x11c503b38) [serial = 1951] [outer = 0x0] [url = about:blank]
--DOMWINDOW == 103 (0x14eb3c8c8) [serial = 1754] [outer = 0x0] [url = about:newtab]
--DOMWINDOW == 102 (0x14ddcd6a8) [serial = 1748] [outer = 0x0] [url = about:newtab]
--DOMWINDOW == 101 (0x148682a68) [serial = 1667] [outer = 0x0] [url = about:newtab]
--DOMWINDOW == 100 (0x146d96778) [serial = 1673] [outer = 0x0] [url = about:newtab]
--DOMWINDOW == 99 (0x14862e078) [serial = 1694] [outer = 0x0] [url = about:newtab]
--DOMWINDOW == 98 (0x1500deee8) [serial = 1751] [outer = 0x0] [url = about:newtab]
--DOMWINDOW == 97 (0x14cd135b8) [serial = 1670] [outer = 0x0] [url = about:newtab]
--DOMWINDOW == 96 (0x14b031718) [serial = 1691] [outer = 0x0] [url = about:newtab]
TEST-INFO | chrome://mochitests/content/browser/browser/base/content/test/social/browser_social_chatwindow.js | sub-test testCloseOnLogout starting
TEST-PASS | chrome://mochitests/content/browser/browser/base/content/test/social/browser_social_chatwindow.js | provider has a port
TEST-UNEXPECTED-FAIL | chrome://mochitests/content/browser/browser/base/content/test/social/browser_social_chatwindow.js | Test timed out
Hardware: x86 → x86_64
Summary: browser_social_chatwindow.js | Test timed out → Intermittent browser_social_chatwindow.js | Test timed out
Mark, please may you take a look at this?

At the moment, the failure rate of this test is high enough that it will be one of the ones disabled for too many intermittent failures, once I return from vacation in a few days time.

Cheers :-)
Flags: needinfo?(mhammond)
I've tried a couple of times to look at this without success - I've a try run at https://tbpl.mozilla.org/?tree=Try&rev=206e914027c9 with some debugging output added, but after many hundred retries I simply can't repro this error.  I'll keep trying though.  That try run shows lots of oranges - just not this one - and given we only have about 15 TBPL logs for this error since the middle of Dec, I'm surprised this is on the radar to be disabled - but as mentioned, I'll keep trying to provoke it with debug output.
Flags: needinfo?(mhammond)
(In reply to Mark Hammond (:markh) from comment #17)
> given we only have about 15 TBPL logs for this error
> since the middle of Dec, I'm surprised this is on the radar to be disabled -
> but as mentioned, I'll keep trying to provoke it with debug output.

I had chosen bugs with a failure rate of >5 in the 7 days prior. The failure rate of this test seems to have increased recently (especially given that over Christmas we should have seen fewer failures in a 7 day span, due to fewer pushes), although may just be coincidence.
I took a look at this.  On the surface, based on the log output and reading code, it seems to be a problem with the cleanup after the test is run.  The tests themselves all seem to finish (based on log output) prior to the hang.  It looks like finishSocialTest/removeAddedProviders in head.js is run twice, the first time as an explicit callback, the second time as a registerCleanupFunction.  It looks like the hang occurs during the first call.

This is really hard to figure out without being able to reproduce the failure locally, that is quite frustrating.

I also notice a comment in the logs about declaring functions at the top level in strict mode.  It seems that removeAddedProviders may need to be a top level function.  Not sure if that might be related to the failure or not.
hrmph - a try run with the failure is at:
https://tbpl.mozilla.org/?tree=Try&rev=26e68a0c6738

Log at:
https://tbpl.mozilla.org/php/getParsedLog.php?id=18700942&tree=Try&full=1

The log shows a successful chat as:
workerapi opened chat window
++DOMWINDOW == 151 (0x154d99f70) [serial = 2097] [outer = 0x1547718d0]
++DOCSHELL 0x14c759230 == 56 [id = 769]
++DOMWINDOW == 152 (0x12647aaf0) [serial = 2098] [outer = 0x0]
WARNING: NS_ENSURE_TRUE(NS_SUCCEEDED(rv) && subjPrincipal) failed: file ../../../docshell/base/nsDocShell.cpp, line 8211
WARNING: Unable to test style tree integrity -- no content node: file ../../../layout/base/nsCSSFrameConstructor.cpp, line 8265
WARNING: Subdocument container has no frame: file ../../../layout/base/nsDocumentViewer.cpp, line 2393
++DOMWINDOW == 153 (0x154dbb0f0) [serial = 2099] [outer = 0x12647aaf0]
socialchat - DOMContentLoaded

and the failed one as:
workerapi opened chat window
WARNING: attempt to modify an immutable nsStandardURL: file ../../../../netwerk/base/src/nsStandardURL.cpp, line 1210
++DOMWINDOW == 166 (0x14c4766d0) [serial = 2112] [outer = 0x14b4e1b10]
WARNING: NS_ENSURE_TRUE(mMutable) failed: file ../../../../netwerk/base/src/nsSimpleURI.cpp, line 273
TEST-UNEXPECTED-FAIL | chrome://mochitests/content/browser/browser/base/content/test/social/browser_social_chatwindow.js | Test timed out

Note the first WARNING which I currently can't explain - but the key difference is that the "load" event is not firing in the failure case (which may or may not be related to that warning)

Also note this only happens in debug builds, so I *might* be able to repro this locally - but sadly it will (probably) need to wait until I come back from vacation (ie, it will be a week or so until I can investigate further...)
heh - these tests do alot of work and debug builds are slow, so the test is simply timing out (at least that is what happened locally)

Try at https://tbpl.mozilla.org/?tree=Try&rev=c33fac5f9a5e
Assignee: nobody → mhammond
Attachment #700946 - Attachment is obsolete: true
https://hg.mozilla.org/mozilla-central/rev/a752f6f0994d
Status: NEW → RESOLVED
Closed: 8 years ago
Resolution: --- → FIXED
Target Milestone: --- → Firefox 21
Status: RESOLVED → REOPENED
Resolution: FIXED → ---
Pardon us, we didn't really mean those last 8, they were caused by bug 831489.
I pushed some diagnostics to try, and what's happening is that sometimes the XBL binding is being created later than we expect (which is also evident in bug 819141).  For some reason, bug 831489 caused this to happen more often.

The fix is quite simple and much cleaner; the <constructor> is fired when the binding is created (rather than when the object is created), so moving all the chat initialization to the constructor makes everyone happy (and also fixes bug 819141 - a new chat while in DOM full-screen mode is dutifuly created after full-screen mode finishes)
Attachment #718902 - Flags: review?(gavin.sharp)
Blocks: 819141
Comment on attachment 718902 [details] [diff] [review]
move chat init to the constructor

Thanks, this looks much nicer!

While you're moving the Social.jsm import into the constructor, you could re-write it to take advantage of the trick from bug 836470, which is a bit more concise:

let Social = Components.utils.import("resource:///modules/Social.jsm", {}).Social;
Attachment #718902 - Flags: review?(gavin.sharp) → review+
Something in this push caused frequent Linux64 debug mochitest-browser-chrome failures. Backed out.
https://hg.mozilla.org/integration/mozilla-inbound/rev/e067a8b6b4b1

https://tbpl.mozilla.org/php/getParsedLog.php?id=20224982&tree=Mozilla-Inbound

07:51:34     INFO -  TEST-PASS | chrome://mochitests/content/browser/browser/base/content/test/social/browser_social_chatwindowfocus.js | exactly 1 chat open
07:51:34     INFO -  TEST-PASS | chrome://mochitests/content/browser/browser/base/content/test/social/browser_social_chatwindowfocus.js | chat is minimized
07:51:34     INFO -  TEST-PASS | chrome://mochitests/content/browser/browser/base/content/test/social/browser_social_chatwindowfocus.js | tab should be focused
07:51:34     INFO -  ++DOMWINDOW == 149 (0x4c97508) [serial = 2236] [outer = 0x3cbc8d8]
07:51:34     INFO -  ++DOCSHELL 0x6a1bd40 == 50 [id = 808]
07:51:34     INFO -  ++DOMWINDOW == 150 (0x5c66a68) [serial = 2237] [outer = (nil)]
07:51:34     INFO -  WARNING: NS_ENSURE_TRUE(NS_SUCCEEDED(rv) && subjPrincipal) failed: file ../../../docshell/base/nsDocShell.cpp, line 8396
07:51:34  WARNING -  TEST-UNEXPECTED-FAIL | chrome://mochitests/content/browser/browser/base/content/test/social/browser_social_chatwindowfocus.js | uncaught exception - TypeError: navigator.mozSocial is undefined at https://example.com/browser/browser/base/content/test/social/social_chat.html?id=1:10
07:51:34  WARNING -  This is a harness error.
07:51:34     INFO -  Stack trace:
07:51:34     INFO -      JS frame :: chrome://mochikit/content/tests/SimpleTest/SimpleTest.js :: simpletestOnerror :: line 1105
07:51:34     INFO -      native frame :: <unknown filename> :: <TOP_LEVEL> :: line 0
07:51:34     INFO -  JavaScript error: https://example.com/browser/browser/base/content/test/social/social_chat.html?id=1, line 10: navigator.mozSocial is undefined
07:51:34     INFO -  WARNING: Unable to test style tree integrity -- no content node: file ../../../layout/base/nsCSSFrameConstructor.cpp, line 8403
07:51:34     INFO -  ++DOMWINDOW == 151 (0x46bc568) [serial = 2238] [outer = 0x5c66a68]
07:51:34     INFO -  TEST-INFO | chrome://mochitests/content/browser/browser/base/content/test/social/browser_social_chatwindowfocus.js | Console message: [JavaScript Error: "TypeError: navigator.mozSocial is undefined" {file: "https://example.com/browser/browser/base/content/test/social/social_chat.html?id=1" line: 10}]
07:51:34     INFO -  TEST-PASS | chrome://mochitests/content/browser/browser/base/content/test/social/browser_social_chatwindowfocus.js | still 1 chat open
07:51:34     INFO -  TEST-PASS | chrome://mochitests/content/browser/browser/base/content/test/social/browser_social_chatwindowfocus.js | chat no longer minimized
07:51:34     INFO -  TEST-PASS | chrome://mochitests/content/browser/browser/base/content/test/social/browser_social_chatwindowfocus.js | tab should still be focused
07:51:34     INFO -  TEST-INFO | chrome://mochitests/content/browser/browser/base/content/test/social/browser_social_chatwindowfocus.js | sub-test testNoFocusOnAutoRestore complete
07:51:34     INFO -  TEST-INFO | chrome://mochitests/content/browser/browser/base/content/test/social/browser_social_chatwindowfocus.js | sub-test testFocusOnExplicitRestore starting
07:51:34     INFO -  ++DOCSHELL 0x7a5a730 == 51 [id = 809]
07:51:34     INFO -  ++DOMWINDOW == 152 (0x6efd808) [serial = 2239] [outer = (nil)]
07:51:34     INFO -  ++DOMWINDOW == 153 (0x7fd4498) [serial = 2240] [outer = 0x6efd808]
07:51:34     INFO -  ++DOMWINDOW == 154 (0x565ab58) [serial = 2241] [outer = 0x6efd808]
07:51:34     INFO -  ++DOCSHELL 0x6e97440 == 52 [id = 810]
07:51:34     INFO -  ++DOMWINDOW == 155 (0x78573b8) [serial = 2242] [outer = (nil)]
07:51:34     INFO -  WARNING: NS_ENSURE_TRUE(NS_SUCCEEDED(rv) && subjPrincipal) failed: file ../../../docshell/base/nsDocShell.cpp, line 8396
07:51:34     INFO -  WARNING: Unable to test style tree integrity -- no content node: file ../../../layout/base/nsCSSFrameConstructor.cpp, line 8403
07:51:34     INFO -  ++DOMWINDOW == 156 (0x5992e68) [serial = 2243] [outer = 0x78573b8]
07:51:34     INFO -  TEST-PASS | chrome://mochitests/content/browser/browser/base/content/test/social/browser_social_chatwindowfocus.js | got chatbox message
07:51:34     INFO -  TEST-PASS | chrome://mochitests/content/browser/browser/base/content/test/social/browser_social_chatwindowfocus.js | tab should still be focused
https://hg.mozilla.org/mozilla-central/rev/3ae8720e2a11
Status: REOPENED → RESOLVED
Closed: 8 years ago8 years ago
Resolution: --- → FIXED
Whiteboard: [qa-]
Product: Firefox → Firefox Graveyard
You need to log in before you can comment on or make changes to this bug.