Page MenuHomePhabricator

Allow dosep.py to print full output of dotest.py, even when dotest succeeds.
ClosedPublic

Authored by zturner on Aug 6 2015, 1:36 PM.

Details

Summary

Previously all test output was reported by each individual
instance of dotest.py. After a recent patch, dosep gets dotest
outptu via a pipe, and selectively decides which output to
print.

This breaks certain scripts which rely on having full output
of each dotest instance to do various parsing and/or log-scraping.

While we make no promises about the format of dotest output, it's
easy to restore this to the old behavior for now, although it is
behind a flag. To re-enable full output, run dosep.py with the -s
option.

Diff Detail

Event Timeline

zturner updated this revision to Diff 31470.Aug 6 2015, 1:36 PM
zturner retitled this revision from to Allow dosep.py to print full output of dotest.py, even when dotest succeeds..
zturner updated this object.
zturner added reviewers: dawn, chaoren.
zturner added a subscriber: lldb-commits.

I want to make it clear again though that we do not support relying on the output of dotest.py when running dosep. The patch which originally broke this made it possible to collect detailed information about the tests that were run from within dosep. If you want to process the results of the test suite with some kind of scraping utility,, the proper way to do this is to have dosep.py do the aggregation and print it in a summary section of dosep.

chaoren added inline comments.Aug 6 2015, 3:09 PM
test/dosep.py
82

Why did you move this here? Could you please move stderr here too? It seems weird stderr is labeled but stdout isn't.

102

This and sys.stderr.flush() should be under the with output_lock:. My mistake. Sorry.

142

Could you please do:

if exit_status != 0:
    report_test_failure(...)
elif output_on_success:
    report_test_pass(...)

so it's completely silent on success?

143

Do you mean output[0]? For consistency, should we print stderr for success too? Even if it's mostly empty.

zturner added inline comments.Aug 6 2015, 3:26 PM
test/dosep.py
82

I played with various combinations, and this way seemed the most intuitive when you actually run it with the various options and see the output. The important thing is to make it consistent with the behavior of report_test_pass. Currently, the output will look like this:

UNSUPPORTED: LLDB (d:\src\llvmbuild\ninja_release\bin\clang.exe-i686) :: test_sb_api_directory (TestPublicAPIHeaders.SBDirCheckerCase) (This test is only for LLDB.framework built 64-bit and !lldb.test_remote)
----------------------------------------------------------------------
Ran 1 test in 0.157s

RESULT: PASSED (0 passes, 0 failures, 0 errors, 1 skipped, 0 expected failures, 0 unexpected successes)
[120998 refs]

[TestPublicAPIHeaders.py] PASSED
  1 out of 387 test suites processed

It looks awkward to me to label that with stdout. stdout is what people normally expect to see as output. So I kind of think only stderr should be labelled. (Even better would be to use colors, but that's a followup).

The reason I moved it before the `[%s] FAILED' line is because I think this is the easiest format for making sense of it when scanning it visually. First you want to see the output, then you want to see whether it passed or failed, then you want to see the errors. It's jarring to me to see the errors printed out before the message that says it failed. By the time you finish scanning through the errors to

143

Actually I guess I should pass both values in. For some arbitrary reason, the actual useful information from dotest is in stderr, not stdout. And stdout is mostly useless.

zturner added inline comments.Aug 6 2015, 3:29 PM
test/dosep.py
82

Actually, because of the strange behavior of dotest, maybe there's not a better solution. stdout is basically useless when a test passes *and* when it fails. We might as well not print it at all. So maybe I can just remove the stdout line, and only print stderr. Don't even need to label it. Because it's the only output that even means anything from dotest anyway AFAICT

zturner added inline comments.Aug 6 2015, 3:32 PM
test/dosep.py
142

I don't know that it should be completely silent. For starters, if you do it the way you suggest, it won't end up updating the progress, which is something you definitely need to see. But I think it's worthwhile to see the names of the individual tests that are running. The way I've written it now, you if output_on_success is False, you will only see one additional line, which is the name of the test being run. I think that's useful and does not add any noise to the output

zturner updated this revision to Diff 31482.Aug 6 2015, 3:40 PM
chaoren added inline comments.Aug 6 2015, 3:42 PM
test/dosep.py
142

Ah, I was thinking there would still be

\r x out of y test suites processed

my bad.

Could you change that to something like:

\r x out of y test suites processed - [test name]

with the carriage return (\r), so the screen doesn't scroll on success?

chaoren added inline comments.Aug 6 2015, 3:49 PM
test/dosep.py
146

To clarify, I mean something like:

with output_lock:
    if output_on_success:
        print >> sys.stderr, output
        print >> sys.stderr, "[%s] PASSED" % name # silent
    update_progress()

in report_test_pass.

and

sys.stderr.write("\r%*d out of %d test suites processed - [%s]\n" %
            (len(str(total_tests)), test_counter.value, total_tests), name)

in update_progress.

zturner updated this revision to Diff 31491.Aug 6 2015, 4:13 PM

Merge the test name into the progress line. If we want to get overwritable lines we will need to use a stateful line printer that can clear the contents of the current line after issuing a carriage return.

chaoren accepted this revision.Aug 6 2015, 4:24 PM
chaoren edited edge metadata.

LGTM. I'll do the overwritable lines in a follow up patch. You don't really need a stateful printer, just need to get the length of the longest test name.

This revision is now accepted and ready to land.Aug 6 2015, 4:24 PM

Dawn are you ok with this? I believe this fixes your issue, so i want to make sure before I commit.

chaoren requested changes to this revision.Aug 7 2015, 11:01 AM
chaoren edited edge metadata.
chaoren added inline comments.
test/dosep.py
1

I think you added a <U+FEFF> character here. Could you please double check before submitting?

This revision now requires changes to proceed.Aug 7 2015, 11:01 AM
chaoren added inline comments.Aug 7 2015, 11:44 AM
test/dosep.py
95

The order of test_name and result here is different from the invocation.

dawn edited edge metadata.EditedAug 7 2015, 2:48 PM

Dawn are you ok with this? I believe this fixes your issue, so i want to make sure before I commit.

Sounds like chaoren is much more familiar with this code, but agreed that the order of the parameters in update_progress looks wrong. I'll fix that locally and give it a try...

There was no difference in the reported number after applying this patch :(. What platform are you testing on? I'm saw the drop on OSX. I can test on Linux Monday to see if it's a platform thing (can't access that VM now). Did anyone else see a drop? I suppose most folks don't notice, but we set up our Jenkins build to fail if the total test count drops.

I'm sorry I haven't been more helpful - it's release time. I'll try to find time to debug the problem in a couple weeks, or at least figure out what tests are actually running (not sure I understand the code well enough to do much more - will try).

Chaoren, am I still missing any requested changes or is this good to go? I'm not sure if some of your original concerns still stand after the latest discussion.

Zach, there were two more comments since the LGTM.

test/dosep.py
1

Please remove the byte-order-mark that your editor added.

95

The order of test_name and result here is different from the invocation.

chaoren accepted this revision.Aug 12 2015, 12:26 PM
chaoren edited edge metadata.
This revision is now accepted and ready to land.Aug 12 2015, 12:26 PM
chaoren closed this revision.Aug 12 2015, 12:26 PM