500388 - xpcshell logs should be written out as the test is running not as it completes

Status: RESOLVED FIXED

(Testing :: XPCShell Harness, defect)

Description

[Dave Townsend [:mossop]]

When running an xpcshell test that hangs I have no way to see any of the tests output. The current logging is only dumped to disk or printed to stdout when the test completes. We should be outputting to the log file as the test is running so I can see what happened.

Comment 1

[Matt Brubeck (:mbrubeck)]

Tests(In reply to Dave Townsend (:Mossop) from comment #0)
> When running an xpcshell test that hangs I have no way to see any of the
> tests output.

This could also be fixed by bug 597064.  (Then the logs could include output for failed or hung tests, without cluttering it with output from successful tests.)

Comment 2

[Jason Duell]

If xpcshell is killed with a signal (control-C) it will dump out the output that happened up to the freeze.

The issue IIRC with just printing directly to stdout/stderr is that there's no way for the harness to do both that and grep the output for TEST-UNEXPECTED-FAIL.  But we could print to a log file and then open and grep the contents at completion.

Comment 3

[David Teller [:Yoric] - still alive but not very active]

If we forced timeouts from JavaScript (by adding a do_timeout to the header), would this improve the situation?

Comment 4

[Josh Matthews [:jdm]]

I'm pretty sure it would be an improvement, but it wouldn't help in situations where JS execution never returned to the event loop such as an endless loop.

Comment 5

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

Attachment: no-buffer-on-single-test.patch

This bug frustrates me, and I thought I recalled that running a single test would work around the problem - but doesn't.  So maybe it should :)

The following patch arranges that when a single test is run, output isn't redirected.  This means if you are debugging a hanging test, you can specify just that test and see the output without waiting for the timeout.

Not perfect, but pragmatic.  What do you think?

Comment 6

[Gregory Szorc [:gps]]

This work conflicts with the patches in bug 887054 and bug 896087. I believe patches in the latter indirectly enable the enhancements you seek. Although chmanchester will have to chime in here.

It sucks that your itch scratching will likely be bit rotted by patches that will imminently land :/

Comment 7

[Mihnea Dobrescu-Balaur (:mihneadb)]

It's a small patch and the main logic is the same, no need to worry about bit rotting.

Comment 8

[Chris Manchester (limited bugmail, email directly)]

I worked out a way to consume output with a callback as that output is available
as a follow-up to bug 896087, but I don't intend to land it as a part of that bug,
as it won't work on mobile platforms (the current set-up doesn't allow for this; we
have a session today for the a team work week to discuss how this might be possible).

So I don't think my work in that bug obsoletes this bug. In terms of bitrot, this is
a small change and I don't mind if it lands ahead of me. Or, if mine lands ahead of this, I would be glad to help get this in shape that will produce reasonable 
output for those trying to debug tests.

Comment 9

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

Comment on attachment 787358 [details] [diff] [review]
no-buffer-on-single-test.patch

Thank Minhea and Chris.  Given this seems acceptable and isn't going to cause extra work for anyone, I'll ask for review and hopefully land it (but I'll probably use [leave-open] as it only partially solves the general problem, and leave the resolution for when the patch Chris talks about finally lands)

Comment 10

[Chris Manchester (limited bugmail, email directly)]

Comment on attachment 787358 [details] [diff] [review]
no-buffer-on-single-test.patch

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

If we make this the default, anybody running a single test file that contains a failure will get output from the xpcshell process, followed by a test summary indicating the test has passed. This is confusing enough that it shouldn't be the default behavior. Tests can do a lot of output - answering the question of whether a test has failed when running a file could become significantly inconvenient.

I will upload a patch shortly that should solve this in a way visible to the python harness. If this isn't sufficient, maybe we can put this behind an option (perhaps pass '--raw-ouptut' to mach).

Comment 11

[Chris Manchester (limited bugmail, email directly)]

Attachment: Don't buffer xpcshell process output, use a callback to consume output as it is produced;

:markh, could you see if this is sufficient for your use case?

Comment 12

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

Comment on attachment 788018 [details] [diff] [review]
Don't buffer xpcshell process output, use a callback to consume output as it is produced;

sadly it doesn't.  I suspect it will log info() etc calls in the test itself, but output generated by the code under test still isn't seen until the test terminates.

Eg, the specific test I made was to modify toolkit/components/satchel/FormHistory.jsm with the following patch:

Then run: ./mach build toolkit/components/satchel/ && ./mach xpcshell-test toolkit/components/satchel/test/unit/test_async_expire.js

As expected, the test hung, but the dump() I added wasn't seen for 5 minutes when the test finally timed out.  Ditto if I change it to use Cu.reportError().  Also, on Windows, hitting Ctrl+C doesn't show the pending output (so the only option to see it is to wait for the timeout.)

Comment 13

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

oops - the patch I applied was:

--- a/toolkit/components/satchel/FormHistory.jsm
+++ b/toolkit/components/satchel/FormHistory.jsm
@@ -768,16 +768,19 @@ function expireOldEntriesVacuum(aExpireTime, aBeginningCount) {
     handleError: function(aError) {
       log("expireEndCountFailure");
     }
   });
 }

 this.FormHistory = {
   search : function formHistorySearch(aSelectTerms, aSearchData, aCallbacks) {
+    Cu.reportError("ERROR hang");
+    dump("about to hang\n");
+    return;
     // if no terms selected, select everything
     aSelectTerms = (aSelectTerms) ?  aSelectTerms : validFields;
     validateSearchData(aSearchData, "Search");

     let stmt = makeSearchStatement(aSearchData, aSelectTerms);

     let handlers = {
       handleResult : function(aResultSet) {

Comment 14

[Chris Manchester (limited bugmail, email directly)]

Attachment: Don't buffer xpcshell process output, use a callback to consume output as it is produced;

I think this was ineffective because of how I was reading the output
(|for line in| was trying to read the entire file before doing anything).

With this version of the patch applied, and testing with the hang, I see output
up to the same point as when output isn't redirected at all.

This will, however, buffer by line. I also noticed that neither approach
results in the dump("about to hang\n"); reaching the terminal.

Comment 15

[(not currently active) Ted Mielczarek]

We could presumably make xpcshell unbuffer its stdout/stderr to make this work properly.

Comment 16

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

Comment on attachment 790860 [details] [diff] [review]
Don't buffer xpcshell process output, use a callback to consume output as it is produced;

WFM on Windows.  If the dump doesn't have a trailing \n I don't see it (which is probably explained by stdout etc being line-buffered IIUC), but I think that's fine.

Thanks!

Comment 17

[Chris Manchester (limited bugmail, email directly)]

Attachment: Don't buffer xpcshell process output, use a callback to consume output as it is available;

This is a version of the previous patch that plays well with the strucutured
output for xpcshell that landed this morning. This has more invasive changes
output processing in runxpcshelltests.py, but they all serve the idea of
getting incremental results and making output consumers interchangeable, which
is desireable in general.

Try run to see what weirdness this might do on various platforms:

https://tbpl.mozilla.org/?tree=Try&rev=a3ed6b2c6d95

Comment 18

[Chris Manchester (limited bugmail, email directly)]

Attachment: Don't buffer xpcshell process output, use a callback to consume output as it is available;

Let's see that without the typo:

https://tbpl.mozilla.org/?tree=Try&rev=9db27de956a1

Comment 19

[Chris Manchester (limited bugmail, email directly)]

Attachment: Don't buffer xpcshell process output, use a callback to consume output as it is available;

Comment 20

[Chris Manchester (limited bugmail, email directly)]

Attachment: Don't buffer xpcshell process output, use a callback to consume output as it is available;

unbitrot

Comment 21

[(not currently active) Ted Mielczarek]

Comment on attachment 796952 [details] [diff] [review]
Don't buffer xpcshell process output, use a callback to consume output as it is available;

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

Sorry, I had the start of a review laying around in a tab here.

::: testing/xpcshell/runxpcshelltests.py
@@ +131,5 @@
>  
>          self.output_lines = []
>          self.has_failure_output = False
> +        self.seen_proc_start = False
> +        self.seen_proc_end = False

Can you make these "saw"? Reading it this way makes my head hurt.

@@ +443,5 @@
> +        """ Reports a message to a consumer. This implementation reports
> +        a message string in human-readable form. """
> +        message = self.message_from_line(line).strip()
> +        if self.on_message and (self.singleFile or self.verbose):
> +            self.on_message(message)

I feel like the consumer should make this decision, and this code should simply callback to on_message if it's set. Otherwise there's a confusing interplay here between on_message and the other variables. Seems simpler to say "if provided, your on_message handler will be called for every line of output".

Comment 22

[(not currently active) Ted Mielczarek]

Comment on attachment 801679 [details] [diff] [review]
Don't buffer xpcshell process output, use a callback to consume output as it is available;

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

::: testing/xpcshell/runxpcshelltests.py
@@ +133,5 @@
>  
>          self.output_lines = []
>          self.has_failure_output = False
> +        self.seen_proc_start = False
> +        self.seen_proc_end = False

Can you change these to either "saw" or "has_seen"? This variable name is killing me.

@@ +446,5 @@
> +        """ Reports a message to a consumer. This implementation reports
> +        a message string in human-readable form. """
> +        message = self.message_from_line(line).strip()
> +        if self.on_message and (self.singleFile or self.verbose):
> +            self.on_message(message)

Is it premature of me to want on_message to pass both the structured and human-readable lines? It'd be great for mach to get the structured output in realtime, we could definitely put a nicer UX on top of that.

Comment 23

[Chris Manchester (limited bugmail, email directly)]

Attachment: Don't buffer xpcshell process output, use a callback to consume output as it is available;

This is mostly the same as the previous patch, except mach decides whether it
cares about each line of output, and it gets both structured and human
formatted messages.

The callback still has an effect on the harness' behavior in this version -
output is either collected or passed to the callback, but not both.

Comment 24

[(not currently active) Ted Mielczarek]

Comment on attachment 804102 [details] [diff] [review]
Don't buffer xpcshell process output, use a callback to consume output as it is available;

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

Thanks for the changes, this looks good!

::: testing/xpcshell/mach_commands.py
@@ +142,5 @@
>              'debugger': debugger,
>              'debuggerArgs': debuggerArgs,
>              'debuggerInteractive': debuggerInteractive,
> +            'on_message': (lambda obj, msg: xpcshell.log.info(msg)) \
> +                            if test_path is not None else None,

This is a little awkward, but we can make it better if the callback becomes non-trivial.

Comment 25

[Ryan VanderMeulen [:RyanVM]]

https://hg.mozilla.org/integration/mozilla-inbound/rev/3c7913e853b8

Comment 26

[Ryan VanderMeulen [:RyanVM]]

https://hg.mozilla.org/mozilla-central/rev/3c7913e853b8

Comment 27

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

FTR, this regressed recently with the changes from bug 920849.  Given the regression didn't actually undo any of the changes here but just required a slightly different strategy, I opened bug 968581 instead of reopening this.