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

RESOLVED FIXED in mozilla26

Status

Testing
XPCShell Harness
RESOLVED FIXED
9 years ago
4 years ago

People

(Reporter: mossop, Assigned: chmanchester)

Tracking

unspecified
mozilla26
Points:
---
Dependency tree / graph

Firefox Tracking Flags

(Not tracked)

Details

Attachments

(1 attachment, 7 obsolete attachments)

(Reporter)

Description

9 years ago
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.
Blocks: 744698
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.)
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.
If we forced timeouts from JavaScript (by adding a do_timeout to the header), would this improve the situation?

Comment 4

6 years ago
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.
Created attachment 787358 [details] [diff] [review]
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?
Attachment #787358 - Flags: feedback?

Comment 6

5 years ago
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 :/
Flags: needinfo?(cmanchester)
It's a small patch and the main logic is the same, no need to worry about bit rotting.
(Assignee)

Comment 8

5 years ago
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.
Flags: needinfo?(cmanchester)
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)
Attachment #787358 - Flags: feedback? → review?(cmanchester)
(Assignee)

Comment 10

5 years ago
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).
Attachment #787358 - Flags: review?(cmanchester)
(Assignee)

Comment 11

5 years ago
Created attachment 788018 [details] [diff] [review]
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?
(Assignee)

Updated

5 years ago
Attachment #788018 - Flags: feedback?(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.)
Attachment #788018 - Flags: feedback?(mhammond) → feedback-
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) {
(Assignee)

Comment 14

5 years ago
Created attachment 790860 [details] [diff] [review]
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.
(Assignee)

Updated

5 years ago
Attachment #788018 - Attachment is obsolete: true
(Assignee)

Updated

5 years ago
Attachment #790860 - Flags: feedback?(mhammond)
We could presumably make xpcshell unbuffer its stdout/stderr to make this work properly.
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!
Attachment #790860 - Flags: feedback?(mhammond) → feedback+
(Assignee)

Updated

5 years ago
Attachment #790860 - Flags: review?(ted)
(Assignee)

Comment 17

5 years ago
Created attachment 794718 [details] [diff] [review]
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
Attachment #794718 - Flags: review?(ted)
(Assignee)

Updated

5 years ago
Assignee: nobody → cmanchester
(Assignee)

Updated

5 years ago
Attachment #790860 - Attachment is obsolete: true
Attachment #790860 - Flags: review?(ted)
(Assignee)

Comment 18

5 years ago
Created attachment 794753 [details] [diff] [review]
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
(Assignee)

Updated

5 years ago
Attachment #794718 - Attachment is obsolete: true
Attachment #794718 - Flags: review?(ted)
(Assignee)

Comment 19

4 years ago
Created attachment 796952 [details] [diff] [review]
Don't buffer xpcshell process output, use a callback to consume output as it is available;
Attachment #796952 - Flags: review?(ted)
(Assignee)

Comment 20

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

unbitrot
Attachment #801679 - Flags: review?(ted)
(Assignee)

Updated

4 years ago
Attachment #794753 - Attachment is obsolete: true
(Assignee)

Updated

4 years ago
Attachment #796952 - Attachment is obsolete: true
Attachment #796952 - Flags: review?(ted)
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".
Attachment #796952 - Attachment is obsolete: false
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.
Attachment #801679 - Flags: review?(ted) → review+
(Assignee)

Comment 23

4 years ago
Created attachment 804102 [details] [diff] [review]
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.
Attachment #804102 - Flags: review?(ted)
(Assignee)

Updated

4 years ago
Attachment #796952 - Attachment is obsolete: true
(Assignee)

Updated

4 years ago
Attachment #801679 - Attachment is obsolete: true
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.
Attachment #804102 - Flags: review?(ted) → review+
(Assignee)

Updated

4 years ago
Keywords: checkin-needed
Attachment #787358 - Attachment is obsolete: true
https://hg.mozilla.org/mozilla-central/rev/3c7913e853b8
Status: NEW → RESOLVED
Last Resolved: 4 years ago
Resolution: --- → FIXED
Target Milestone: --- → mozilla26
Depends on: 917627
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.
You need to log in before you can comment on or make changes to this bug.