This patch adds SpecialPowers hooks that allow mochitests to listen for console messages. They are not quite the bare API, they enforce a particular way of writing such tests that should prevent race conditions and leaks. I think I have converted all in-tree tests that presently use nsIConsoleService via UniversalXPConnect, but I might have missed one or two. The full capabilities of the SimpleTest convenience function are not used in this patch, but I expect to use them in the tests I'll be writing for bug 229827 and bug 413598 (coming RSN). r?smaug for testing infrastructure and ?bz for console usage. Tangent: There is this comment in specialpowers.js: ... //XXX: these APIs really ought to be removed, they're not e10s-safe. // (also they're pretty Firefox-specific) _getTopChromeWindow: function(window) { ... There is no indication of how many subsequent functions are meant; there are lots. It was added by Ted in http://hg.mozilla.org/mozilla-central/diff/b1267148533d/testing/mochitest/specialpowers/content/specialpowers.js and that leaves me no more enlightened. I wasn't sure if I should put my new functions above or below that point. :-(

Er, I appear to have meant bug 413958. Got it wrong in my patch queue even.

Comment on attachment 538416 [details] [diff] [review] patch >+ SimpleTest.executeSoon(continuation !== undefined ? continuation >+ : function() { SimpleTest.finish() }); This could probably be: SimpleTest.executeSoon(continuation || function() { SimpleTest.finish() }); This looks good!

I guess that wouldn't do any harm in the case where caller passed something silly like 'false'.

I think things got muddied in specialpowers.js since I added that comment. The comment refers to _getTopChromeWindow, _getAutoCompletePopup, {add,remove}AutoCompletePopupEventListener, isBackButtonEnabled. All of those APIs expect to be able to touch chrome, which is not possible when the content script is actually running in a separate content process.

I'll add a marker to the end of that block in my tree. Thanks for clarifying, ted.

Boris's suggestion for 'continuation'; added a marker to the bottom of the block of problem APIs (two functions had to be moved out of that block); removed the definition of Cr, which is not used (it was in a version that never got off the drawing board); fixed the usage of defineLazyServiceGetter.

Comment on attachment 538619 [details] [diff] [review] patch v2 > /** >+ * Call TESTFN synchronously, and monitor its console output. >+ * >+ * Expect to receive as many console messages as there are elements of >+ * MSGS, an array; each element is an object which may have any number >+ * of the following properties: >+ * message, errorMessage, sourceName, sourceLine, category: >+ * string or regexp >+ * lineNumber, columnNumber: number >+ * isError, isException, isStrict: boolean >+ * Strings, numbers, and booleans must compare equal to the named >+ * property of the Nth console message. Regexps must match. Any >+ * fields present in the message but not in the pattern object are ignored. >+ * >+ * After TESTFN returns, CONTINUATION will be called asynchronously. >+ * If CONTINUATION is not given, SimpleTest.finish will be called >+ * instead. SimpleTest.finish handling is strange. I wouldn't expect method called expectConsoleMessages to call SimpleText.finish(). If you do give CONTINUATION, you are responsible for >+ * calling SimpleTest.finish at some point (note the first line of code). >+ */ >+SimpleTest.expectConsoleMessages = function (testfn, msgs, continuation) { >+ SimpleTest.waitForExplicitFinish(); >+ >+ var counter = 0; >+ function listener(msg) { >+ if (msg.message === "SENTINEL" && Object.keys(msg).length === 1) { Do we really need the rather strange SENTINEL handling?

(In reply to comment #7) > >+ * After TESTFN returns, CONTINUATION will be called asynchronously. > >+ * If CONTINUATION is not given, SimpleTest.finish will be called > >+ * instead. > SimpleTest.finish handling is strange. I wouldn't expect > method called expectConsoleMessages to call SimpleText.finish(). Look at the modified test cases - this winds up being the most natural behavior for small regression tests. > >+ if (msg.message === "SENTINEL" && Object.keys(msg).length === 1) { > Do we really need the rather strange SENTINEL handling? Yes. Without an explicit sentinel posted to the console, there is no way to tell when the test _should have_ finished posting console messages (independent of whether it _has_ finished). And only nsIConsoleMessage objects can be posted to the console, so the simplest thing is to use logStringMessage and check for it here as shown.

Comment on attachment 538619 [details] [diff] [review] patch v2 > /** >+ * Call TESTFN synchronously, and monitor its console output. >+ * >+ * Expect to receive as many console messages as there are elements of >+ * MSGS, an array; each element is an object which may have any number >+ * of the following properties: >+ * message, errorMessage, sourceName, sourceLine, category: >+ * string or regexp >+ * lineNumber, columnNumber: number >+ * isError, isException, isStrict: boolean >+ * Strings, numbers, and booleans must compare equal to the named >+ * property of the Nth console message. Regexps must match. Any >+ * fields present in the message but not in the pattern object are ignored. >+ * >+ * After TESTFN returns, CONTINUATION will be called asynchronously. >+ * If CONTINUATION is not given, SimpleTest.finish will be called >+ * instead. If you do give CONTINUATION, you are responsible for >+ * calling SimpleTest.finish at some point (note the first line of code). >+ */ Nit, there are no parameters, MSGS, TESTNF or CONTINUATION. Could you use the exact same names what you have for parameters. >+SimpleTest.expectConsoleMessages = function (testfn, msgs, continuation) { This method name doesn't still give any hint that it might call SimpleTest.Finish() Also, the API is a bit error prone, IMO >+ SimpleTest.waitForExplicitFinish(); >+ >+ var counter = 0; >+ function listener(msg) { >+ if (msg.message === "SENTINEL" && Object.keys(msg).length === 1) { >+ is(counter, msgs.length, "number of messages"); >+ SimpleTest.executeSoon(continuation || function() {SimpleTest.finish()}); >+ } else if (counter >= msgs.length) { >+ ok(false, "extra message: " + msg.message); >+ } else { >+ var pat = msgs[counter]; >+ for (k in pat) { >+ ok(k in msg, "["+counter+"]."+k+" present"); space before and after + Same also elsewhere But ok, r=me

(In reply to comment #9) > Nit, there are no parameters, MSGS, TESTNF or CONTINUATION. > Could you use the exact same names what you have for parameters. How am I supposed to make clear that these are parameter names if I can't use uppercase? > >+SimpleTest.expectConsoleMessages = function (testfn, msgs, continuation) { > This method name doesn't still give any hint that it might call > SimpleTest.Finish() Please suggest an alternative name, then? > Also, the API is a bit error prone, IMO Please elaborate?

(In reply to comment #10) > (In reply to comment #9) > > > Nit, there are no parameters, MSGS, TESTNF or CONTINUATION. > > Could you use the exact same names what you have for parameters. > > How am I supposed to make clear that these are parameter names if I can't > use uppercase? I've seen people use |paramName| before.

Updated this patch for the recent changes to SpecialPowers (bug 676274). Also made some changes to the new SimpleTest API that should address Olli's concerns above. Also subsumed the (presently unused due to bug 692605) {add,remove}ErrorConsoleListener API added by bent in bug 649537. bent: If the expectConsoleMessages API does not suit your workers tests, please let me know what you need instead. In discussion on IRC bent was of the opinion that new error-console tests should not land before bug 675221, however, it seems to me that this patch could maybe go ahead and land anyway, since it does not create *new* error-console tests, only modifies some that are presently unproblematic. Thoughts? Note also that I took out the use of enablePrivilege in SimpleTests.executeSoon() on the theory that bug 663291 means SpecialPowers can now be used from chrome mochitests so we don't need that anymore. The old executeSoon was breaking any test that uses the new API with an extra console message.

Accidentally left the old removeErrorConsoleListener function in the code.

Comment on attachment 567554 [details] [diff] [review] patch v3a >@@ -639,39 +639,17 @@ SimpleTest.waitForClipboard = function(a ... >+SimpleTest.executeSoon = SpecialPowers.executeSoon; Does this work always? Also with chrome and browser chrome tests? if so, r=me

(In reply to Olli Pettay [:smaug] from comment #14) > >+SimpleTest.executeSoon = SpecialPowers.executeSoon; > Does this work always? Also with chrome and browser chrome tests? jmaher says in bug 676274 that it doesn't quite work yet but he's on it. I'll make this bug depend on whatever is appropriate.

This could maybe actually land now, but I won't have time to blow the dust off it for another couple weeks; I'm in the middle of a cross-country move. If anyone is interested in picking up the ball, please be my guest.

Try run for 3654bf8c3490 is complete. Detailed breakdown of the results available here: https://tbpl.mozilla.org/?tree=Try&rev=3654bf8c3490 Results (out of 48 total builds): exception: 6 success: 26 warnings: 10 failure: 6 Builds (or logs if builds failed) available at: http://ftp.mozilla.org/pub/mozilla.org/firefox/try-builds/zackw@panix.com-3654bf8c3490

Try run for 83b9a2533936 is complete. Detailed breakdown of the results available here: https://tbpl.mozilla.org/?tree=Try&rev=83b9a2533936 Results (out of 13 total builds): success: 12 warnings: 1 Builds (or logs if builds failed) available at: http://ftp.mozilla.org/pub/mozilla.org/firefox/try-builds/zackw@panix.com-83b9a2533936

Things have changed enough since I touched this bug last that I think it probably needs a re-review. I'm tagging bent this time because he was responsible for several of the relevant changes. I am a little worried about race conditions in tests that monitor the console. Several tests install a console monitor, do a bunch of stuff that may _asynchronously_ generate console messages, and then remove the monitor again. The "sentinel" thingy is meant to ensure that the monitor doesn't go away till after all the messages have been processed, but I'm not sure it's good enough if you have something like install console monitor fire click event click event handler throws an exception executeSoon post sentinel -- is there actually a guarantee that the click event will be resolved before the executeSoon?

The patch I just posted has an implicit dependency on the patch in bug 791003.

We _ought_ to be able to reactivate the web-worker error propagation tests now; this patch does that. It's separate because I suspect further race conditions in that test and I don't want to tie the main patch's fate to it.

Comment on attachment 661199 [details] [diff] [review] sidecar: reactivate the web worker error propagation tests Reassigning review to Ted as I am informed Ben is on vacation.

Comment on attachment 661198 [details] [diff] [review] patch v4 Review of attachment 661198 [details] [diff] [review]: ----------------------------------------------------------------- I only skimmed the test changes, but I like the SpecialPowers API changes here. ::: testing/mochitest/tests/SimpleTest/SimpleTest.js @@ +720,5 @@ > + if (msg.message === "SENTINEL" && !msg.isScriptError) { > + is(counter, msgs.length, "number of messages"); > + SimpleTest.executeSoon(continuation); > + } else if (counter >= msgs.length) { > + ok(false, "extra message | " + JSON.stringify(msg)); The error messages here could probably be clearer that they're coming from monitorConsole. ::: testing/mochitest/tests/SimpleTest/specialpowersAPI.js @@ +418,5 @@ > + > + this.callback.call(undefined, m); > + > + if (!m.isScriptError && m.message === "SENTINEL") > + Services.console.unregisterListener(this); This is clever, I like it!

(In reply to Ted Mielczarek [:ted.mielczarek] from comment #23) > The error messages here could probably be clearer that they're coming from > monitorConsole. I will add "monitorConsole | " to the beginning of all the messages generated by that function, in the version I land. > > + if (!m.isScriptError && m.message === "SENTINEL") > > + Services.console.unregisterListener(this); > > This is clever, I like it! I sort of think it should be a dedicated nsIConsoleMessage subclass rather than just a magic string, but that seemed like way, way too much work. Thanks for quick review.

https://hg.mozilla.org/integration/mozilla-inbound/rev/40f38a8aa660 https://hg.mozilla.org/integration/mozilla-inbound/rev/b36eaac9ecf8

Unfortunately, something in the push for this bug and bug 229827 caused mochitest-1/3/4 failures (some perma, some intermittent). Backed out. https://hg.mozilla.org/integration/mozilla-inbound/rev/20fcf80a5242 Mochitest-1 (Intermittent) https://tbpl.mozilla.org/php/getParsedLog.php?id=17116584&tree=Mozilla-Inbound 59145 ERROR TEST-UNEXPECTED-FAIL | /tests/content/events/test/test_bug489671.html | monitorConsole | number of messages - got 2, expected 3 Mochitest-4 (Frequent) https://tbpl.mozilla.org/php/getParsedLog.php?id=17114235&tree=Mozilla-Inbound 851 ERROR TEST-UNEXPECTED-FAIL | /tests/dom/workers/test/test_errorPropagation.html | monitorConsole | extra message | {"message":"[JavaScript Error: \"Error: expectedError\" {file: \"http://mochi.test:8888/tests/dom/workers/test/errorPropagation_worker.js\" line: 48}]","errorMessage":"Error: expectedError","sourceName":"http://mochi.test:8888/tests/dom/workers/test/errorPropagation_worker.js","sourceLine":"","lineNumber":48,"columnNumber":0,"category":"Web Worker","windowID":173,"isScriptError":true,"isWarning":false,"isException":false,"isStrict":false} 852 ERROR TEST-UNEXPECTED-FAIL | /tests/dom/workers/test/test_errorPropagation.html | monitorConsole | extra message | {"message":"[JavaScript Error: \"Error: expectedError\" {file: \"http://mochi.test:8888/tests/dom/workers/test/errorPropagation_worker.js\" line: 48}]","errorMessage":"Error: expectedError","sourceName":"http://mochi.test:8888/tests/dom/workers/test/errorPropagation_worker.js","sourceLine":"","lineNumber":48,"columnNumber":0,"category":"Web Worker","windowID":173,"isScriptError":true,"isWarning":false,"isException":false,"isStrict":false} 853 ERROR TEST-UNEXPECTED-FAIL | /tests/dom/workers/test/test_errorPropagation.html | monitorConsole | extra message | {"message":"[JavaScript Error: \"Error: expectedError\" {file: \"http://mochi.test:8888/tests/dom/workers/test/errorPropagation_worker.js\" line: 48}]","errorMessage":"Error: expectedError","sourceName":"http://mochi.test:8888/tests/dom/workers/test/errorPropagation_worker.js","sourceLine":"","lineNumber":48,"columnNumber":0,"category":"Web Worker","windowID":173,"isScriptError":true,"isWarning":false,"isException":false,"isStrict":false} 854 ERROR TEST-UNEXPECTED-FAIL | /tests/dom/workers/test/test_errorPropagation.html | monitorConsole | extra message | {"message":"[JavaScript Error: \"Error: expectedError\" {file: \"http://mochi.test:8888/tests/dom/workers/test/errorPropagation_worker.js\" line: 48}]","errorMessage":"Error: expectedError","sourceName":"http://mochi.test:8888/tests/dom/workers/test/errorPropagation_worker.js","sourceLine":"","lineNumber":48,"columnNumber":0,"category":"Web Worker","windowID":173,"isScriptError":true,"isWarning":false,"isException":false,"isStrict":false} 855 ERROR TEST-UNEXPECTED-FAIL | /tests/dom/workers/test/test_errorPropagation.html | monitorConsole | extra message | {"message":"[JavaScript Error: \"Error: expectedError\" {file: \"http://mochi.test:8888/tests/dom/workers/test/errorPropagation_worker.js\" line: 48}]","errorMessage":"Error: expectedError","sourceName":"http://mochi.test:8888/tests/dom/workers/test/errorPropagation_worker.js","sourceLine":"","lineNumber":48,"columnNumber":0,"category":"Web Worker","windowID":173,"isScriptError":true,"isWarning":false,"isException":false,"isStrict":false} Mochitest-5 (Perma) https://tbpl.mozilla.org/php/getParsedLog.php?id=17114186&tree=Mozilla-Inbound 157805 ERROR TEST-UNEXPECTED-FAIL | /tests/parser/htmlparser/tests/mochitest/test_bug672453.html | monitorConsole | [7].errorMessage value - got An unsupported character encoding was declared for the HTML document using a meta tag. The declaration was ignored., strictly expected A meta tag was used to declare a character encoding the does not encode the Basic Latin range roughly like US-ASCII. The declaration was ignored.

This revision should fix two of the three problems. The Mochitest-5 permaorange is due to bug 801402, which changed the error message that test_bug672453.html was looking for. (Boo disabled tests!) Easily corrected. The Mochitest-1 intermittent is because if you do window.setTimeout("code", 0); SimpleTest.executeSoon(symbol); apparently the events can get run in either order. I've adjusted the code to prevent this. The Mochitest-4 intermittent is because apparently I did not use a sufficiently large hammer in removing all of the races from the web worker error propagation tests. I don't have time to dig into that right now, so what I'm going to do is move the "sidecar" patch to its own bug and re-land the other two.

Re-landed: https://hg.mozilla.org/integration/mozilla-inbound/rev/1cb8097025bf

The "sidecar" patch is now bug 812714. I do not plan to work on it further.