1282522 - stderr not printed when we fatally assert at shutdown

Status: RESOLVED FIXED

(Testing :: XPCShell Harness, defect)

Description

[Kyle Huey (Exited; not receiving bugmail, old account, do not use)]

+++ 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

Comment 1

[Gregory Szorc [: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 :)

Comment 2

[Gregory Szorc [:gps]]

Attachment: Bug 1282522 - Record stderr from xpcshell test processes;

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/

Comment 3

[Gregory Szorc [:gps]]

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.

Comment 4

[(not currently active) Ted Mielczarek]

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

Comment 5

[Kyle Huey (Exited; not receiving bugmail, old account, do not use)]

Ping?

Comment 6

[Gregory Szorc [:gps]]

I'm not actively working on this.

Comment 7

[Chris Manchester (limited bugmail, email directly)]

I'll look into this.

Comment 8

[Chris Manchester (limited bugmail, email directly)]

Attachment: Bug 1282522 - Ensure stderr is printed in case of a shutdown crash in a passing xpcshell test.

There were two assumptions preventing this output from being logged, both
related to the case a test passes and xpcshell returns 0. The first was
that we would not find crash dumps in this case, and would therefore not
need to log the full output of the test process (in the case xpcshell
returned non-zero or a test failed, we would log this output prior to checking
for crashes). The second was that if a test was eligible to retry, we wouldn't
need to store a test's output at all, because this output would only relate to
a failure that we would consider non-fatal.

The first assumption does not hold because it's possible to fatally assert
at shutdown in tests spawning child processes without causing a test failure
or non-zero exit code.

The second assumption followed from the first, and is violated when the first
is violated, because in this case we would consider a found crash fatal even
when a test was eligible to retry.

This patch reverses these assumptions and logs the full output of a test that
passes but produces crash dumps. It's not clear that the existing code intended
for a crash to ever be considered fatal when a test was eligible to retry, but
to change this criteria now would reduce our effective test coverage by
ignoring crashes that are now considered fatal, so after this patch we continue
to consider this scenario fatal. If it is determined these crashes are related
to these tests running in parallel with other tests, or they are not relevant
for some other reason, these tests should be run sequentially, or this criteria
should be changed.

Review commit: https://reviewboard.mozilla.org/r/78486/diff/#index_header
See other reviews: https://reviewboard.mozilla.org/r/78486/

Comment 9

[Gregory Szorc [: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/#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?

Comment 10

[Chris Manchester (limited bugmail, email directly)]

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 11

[Chris Manchester (limited bugmail, email directly)]

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

Comment 12

[Gregory Szorc [: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

Comment 13

[Pulsebot]

Pushed by [e-mail]:
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

Comment 14

[Carsten Book [:Tomcat]]

https://hg.mozilla.org/mozilla-central/rev/7494f67a7779

Comment 15

[Ryan VanderMeulen [:RyanVM]]

https://hg.mozilla.org/releases/mozilla-aurora/rev/061867df5aab

Comment 16

[Ryan VanderMeulen [:RyanVM]]

https://hg.mozilla.org/releases/mozilla-beta/rev/abaadded8685