1116708 - nsIConsoleService messages written during a test should appear in the test output

Status: RESOLVED FIXED

(Testing :: XPCShell Harness, defect)

Description

[Mark Hammond [:markh] [:mhammond]]

Attachment: 0003-Bug-XXXXXXX-xpcshell-tests-now-log-console-messages.patch

It's not that uncommon to see code that reports an error via Cu.reportError() (or directly via the console service), but these messages don't appear in the test output.  This means it's possible to see a test hang without any clue as to why - the logged error can't be seen in the test output.

With this patch, test output now looks like:

> 0:06.54 PROCESS_OUTPUT: Thread-15 (pid:8648) "*** Search: _asyncLoadEnginesFromDir: Searching in o:\\src\\mozilla-git\\gecko-dev\\obj-release\\dist\\bin\\browser\\searchplugins for search engines."
> 0:06.42 LOG: Thread-15 INFO "CONSOLE_MESSAGE: (warn) [JavaScript Warning: "ReferenceError: reference to undefined property cache.directories" {file: "file:///o:/src/mozilla-git/gecko-dev/obj-release/dist/bin/components/nsSearchService.js" line: 3374}]"
> 0:06.42 LOG: Thread-15 INFO "CONSOLE_MESSAGE: (info) _asyncLoadEngines: Absent or outdated cache. Loading engines from disk."

Note that I'm not proposing these message change the semantics of the test, just that the console output be written to the test output.  There's a try at https://treeherder.mozilla.org/ui/#/jobs?repo=try&revision=1299469b713c with this patch and it doesn't cause any tests to fail.

The only real downsides are (a) most tests will now generate more output and some of that output isn't going to be relevant and (b) some tests will cause messages to be logged twice as the code under test *both* writes to the console service *and* does a dump() - but that seems OK to me.

Chris, please feel free to pass this on to someone else if that's appropriate.

Comment 1

[Chris Manchester (limited bugmail, email directly)]

Comment on attachment 8542852 [details] [diff] [review]
0003-Bug-XXXXXXX-xpcshell-tests-now-log-console-messages.patch

Review of attachment 8542852 [details] [diff] [review]:
-----------------------------------------------------------------

Makes sense to me. This would be a concern if tests are near the global timeout and this adds enough overhead to cause new intermittent failures. I would do a bunch of re-triggers with this applied if that sounds remotely possible. Alternatively we could add a facility for individual tests (or head.js files) to request this if it's relevant to a known subset of tests.

Comment 2

[Mark Hammond [:markh] [:mhammond]]

Comment on attachment 8542852 [details] [diff] [review]
0003-Bug-XXXXXXX-xpcshell-tests-now-log-console-messages.patch

(In reply to Chris Manchester [:chmanchester] from comment #1)

> Makes sense to me. This would be a concern if tests are near the global
> timeout and this adds enough overhead to cause new intermittent failures. I
> would do a bunch of re-triggers with this applied if that sounds remotely
> possible.

I guess it does sound remotely possible, but if that did happen we've just triggered an issue that's almost guaranteed to come up later anyway (IMO, etc :)

But https://treeherder.mozilla.org/ui/#/jobs?repo=try&revision=1299469b713c now has lots of retriggers and doesn't seem to strike this.

> Alternatively we could add a facility for individual tests (or
> head.js files) to request this if it's relevant to a known subset of tests.

I think alot of value would be lost if it was "opt-in" - eg, exceptions in nsIObserverService observers only write to the console, and many tests indirectly rely on such notifications working without error even if the test itself doesn't use them.

So my preference would be to just globally enable this and see if there's any negative feedback from people that causes us to rethink this (eg, later we could maybe work out how to fit this better into the structured logging concept and allow a command-line or manifest option to opt-out - but I think we should wait to see if that is actually something we need to consider before considering it :).

Comment 3

[(not currently active) Ted Mielczarek]

This seems generally fine, although don't these messages already make it to the console in debug builds?

Comment 4

[Mark Hammond [:markh] [:mhammond]]

Comment on attachment 8542852 [details] [diff] [review]
0003-Bug-XXXXXXX-xpcshell-tests-now-log-console-messages.patch

(In reply to Ted Mielczarek [:ted.mielczarek] from comment #3)
> although don't these messages already make it to the console in debug builds?

Good question - I haven't tried - I'll check it's sane there.

Comment 5

[Mark Hammond [:markh] [:mhammond]]

Comment on attachment 8542852 [details] [diff] [review]
0003-Bug-XXXXXXX-xpcshell-tests-now-log-console-messages.patch

(In reply to Ted Mielczarek [:ted.mielczarek] from comment #3)
> This seems generally fine, although don't these messages already make it to
> the console in debug builds?

In my testing on Windows, these strings do not appear in debug or release builds without this patch, and they do appear (once) with it.

Comment 6

[Mark Hammond [:markh] [:mhammond]]

https://hg.mozilla.org/integration/fx-team/rev/14e715ddc5ec

Comment 7

[Carsten Book [:Tomcat]]

https://hg.mozilla.org/mozilla-central/rev/14e715ddc5ec