Closed Bug 1282522 Opened 3 years ago Closed 3 years ago

stderr not printed when we fatally assert at shutdown

Categories

(Testing :: XPCShell Harness, defect)

Version 3
defect
Not set

Tracking

(firefox50 fixed, firefox51 fixed, firefox52 fixed)

RESOLVED FIXED
mozilla52
Tracking Status
firefox50 --- fixed
firefox51 --- fixed
firefox52 --- fixed

People

(Reporter: khuey, Assigned: cmanchester)

References

(Depends on 1 open bug, Blocks 1 open bug)

Details

(Keywords: intermittent-failure)

Attachments

(1 file, 1 obsolete file)

+++ This bug was initially created as a clone of Bug #1281321 +++

This test crashes at shutdown but stderr is not printed, perhaps because the test already passed?  This makes it impossible to see what the assertion is, of course.

http://archive.mozilla.org/pub/firefox/tinderbox-builds/mozilla-inbound-macosx64-debug/1466541840/mozilla-inbound_yosemite_r7-debug_test-xpcshell-bm107-tests1-macosx-build2463.txt.gz
Flags: needinfo?(ted)
Flags: needinfo?(gps)
Something fishy is definitely going on.

From runxpcshelltests.py:

            # Communicate returns a tuple of (stdout, stderr), however we always
            # redirect stderr to stdout, so the second element is ignored.
            process_output, _ = self.communicate(proc)
            ...
            if process_output:
                # For the remote case, stdout is not yet depleted, so we parse
                # it here all at once.
                self.parse_output(process_output)

    ...

    def communicate(self, proc):
        """
          Simple wrapper to communicate with a process.
          On a remote system, this is overloaded to handle remote process communication.
        """
        # Processing of incremental output put here to
        # sidestep issues on remote platforms, where what we know
        # as proc is a file pulled off of a device.
        if proc.stdout:
            while True:
                line = proc.stdout.readline()
                if not line:
                    break
                self.process_line(line)

            if self.saw_proc_start and not self.saw_proc_end:
                self.has_failure_output = True

        return proc.communicate()

We see that communicate() isn't querying proc.stderr at all. However, proc.communicate() presumably will. That 2-tuple will get returned and stdout is fed into parse_output() and stderr is ignored. I'm not sure if the bug is in communicate() or us ignoring stderr in the initial caller. I'll write a patch and see what the reviewer has to say :)
Assignee: nobody → gps
Status: NEW → ASSIGNED
Flags: needinfo?(ted)
Flags: needinfo?(gps)
Before we were throwing away stderr wholesale. As the bug report
demonstrates, this was throwing away useful information to help debug
a crash.

This patch explicitly captures and processes stderr output so it
doesn't get lost.

Review commit: https://reviewboard.mozilla.org/r/62502/diff/#index_header
See other reviews: https://reviewboard.mozilla.org/r/62502/
Attachment #8768189 - Flags: review?(ted)
https://reviewboard.mozilla.org/r/62502/#review59248

I should have said this patch is more of a feedback level. I'm sure there is history here on why we're not reading stderr. I should also write tests.
Attachment #8768189 - Flags: review?(ted) → review-
Comment on attachment 8768189 [details]
Bug 1282522 - Record stderr from xpcshell test processes;

https://reviewboard.mozilla.org/r/62502/#review59442

I don't really understand how this fixes the problem--the harness is already piping stdout to stderr:
https://dxr.mozilla.org/mozilla-central/rev/95ffbc4ff63584631c408e8d9912961fcf68bb09/testing/xpcshell/runxpcshelltests.py#975
I'm not actively working on this.
Assignee: gps → nobody
Status: ASSIGNED → NEW
I'll look into this.
Assignee: nobody → cmanchester
Attachment #8768189 - Attachment is obsolete: true
Comment on attachment 8790874 [details]
Bug 1282522 - Ensure stderr is printed in case of a shutdown crash in a passing xpcshell test.

https://reviewboard.mozilla.org/r/78486/#review77640

There are subtle changes in this commit. And finding them would have been much more difficult without your very detailed commit message. Thank you for taking the time to write it!

I left 1 open issue. If you can convince me I'm wrong, I'll change this to a r+.

::: testing/xpcshell/runxpcshelltests.py
(Diff revision 1)
>          if proc and self.poll(proc) is None:
>              self.kill(proc)
>              message = "%s | Process still running after test!" % self.test_object['id']
>              if self.retry:
>                  self.log.info(message)
> -                self.log_full_output(self.output_lines)

Why was this line removed? Tracing the code, I think this is a regression in that we now lose output for processes that are forcefully killed if they don't shut down correctly and will be retried. Don't we want this in the logs to help us understand why a process failed to stop?
Attachment #8790874 - Flags: review?(gps) → review-
Comment on attachment 8790874 [details]
Bug 1282522 - Ensure stderr is printed in case of a shutdown crash in a passing xpcshell test.

https://reviewboard.mozilla.org/r/78486/#review77640

> Why was this line removed? Tracing the code, I think this is a regression in that we now lose output for processes that are forcefully killed if they don't shut down correctly and will be retried. Don't we want this in the logs to help us understand why a process failed to stop?

This is for tests that are eligible to retry, so prior to this patch we would always throw output away in this case. So this maintains the status quo. Because we never consider this fatal, there isn't really much hope of someone looking at the output and diagnosing the cause, so it sort of makes sense. If someone is interested in investigating a particular test, they can push to try with "verbose = true" in that tests' manifest entry.
Comment on attachment 8790874 [details]
Bug 1282522 - Ensure stderr is printed in case of a shutdown crash in a passing xpcshell test.

Re-requesting review based on comment 10
Attachment #8790874 - Flags: review- → review?(gps)
Comment on attachment 8790874 [details]
Bug 1282522 - Ensure stderr is printed in case of a shutdown crash in a passing xpcshell test.

https://reviewboard.mozilla.org/r/78486/#review79234
Attachment #8790874 - Flags: review?(gps) → review+
Pushed by gszorc@mozilla.com:
https://hg.mozilla.org/integration/autoland/rev/7494f67a7779
Ensure stderr is printed in case of a shutdown crash in a passing xpcshell test. r=gps
https://hg.mozilla.org/mozilla-central/rev/7494f67a7779
Status: NEW → RESOLVED
Closed: 3 years ago
Resolution: --- → FIXED
Target Milestone: --- → mozilla52
You need to log in before you can comment on or make changes to this bug.