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

[zturner]

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.

[zturner]

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]

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]

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]

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]

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

[chaoren]

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]

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]

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]

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.

[zturner]

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

[chaoren]

test/dosep.py

1

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

[chaoren]

test/dosep.py

95

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

[dawn]

In D11816#219078, @zturner wrote:

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).

[zturner]

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.

[chaoren]

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.

test/dosep.py

-#!/usr/bin/env python
+#!/usr/bin/env python
 
 """
 Run the test suite using a separate process for each test file.

 test_counter = None
 total_tests = None
 dotest_options = None
+output_on_success = False
 
 def setup_global_variables(lock, counter, total, options):
     global output_lock, test_counter, total_tests, dotest_options

     total_tests = total
     dotest_options = options
 
-def update_status(name = None, command = None, output = None):
+def report_test_failure(name, command, output):
+    global output_lock
+    with output_lock:
+        print >> sys.stderr, "\n"
+        print >> sys.stderr, output
+        print >> sys.stderr, "Command invoked: %s" % ' '.join(command)
+        update_progress("FAILED", name)
+
+def report_test_pass(name, output):
+    global output_lock, output_on_success
+    with output_lock:
+        if output_on_success:
+            print >> sys.stderr, "\n"
+            print >> sys.stderr, output
+        update_progress("PASSED", name)
+
+def update_progress(test_name, result):
     global output_lock, test_counter, total_tests
     with output_lock:
-        if output is not None:
-            print >> sys.stderr
-            print >> sys.stderr, "Failed test suite: %s" % name
-            print >> sys.stderr, "Command invoked: %s" % ' '.join(command)
-            print >> sys.stderr, "stdout:\n%s" % output[0]
-            print >> sys.stderr, "stderr:\n%s" % output[1]
-        sys.stderr.write("\r%*d out of %d test suites processed" %
-            (len(str(total_tests)), test_counter.value, total_tests))
+        if test_name != None:
+            sys.stderr.write("\n[%s %s] - %d out of %d test suites processed" %
+                (result, test_name, test_counter.value, total_tests))
+        else:
+            sys.stderr.write("\n%d out of %d test suites processed" %
+                (test_counter.value, total_tests))
         test_counter.value += 1
-    sys.stderr.flush()
+        sys.stdout.flush()
+        sys.stderr.flush()
 
 def parse_test_results(output):
     passes = 0

     output = process.communicate()
     exit_status = process.returncode
     passes, failures = parse_test_results(output)
-    update_status(name, command, output if exit_status != 0 else None)
+    if exit_status == 0:
+        # stdout does not have any useful information from 'dotest.py', only stderr does.
+        report_test_pass(name, output[1])
+    else:
+        report_test_failure(name, command, output[1])
     return exit_status, passes, failures
 
 def process_dir(root, files, test_root, dotest_argv):

         test_work_items.append((root, files, test_directory, dotest_argv))
 
     global output_lock, test_counter, total_tests
-    output_lock = multiprocessing.Lock()
+    output_lock = multiprocessing.RLock()
     total_tests = len(test_work_items)
     test_counter = multiprocessing.Value('i', 0)
     print >> sys.stderr, "Testing: %d tests, %d threads" % (total_tests, num_threads)
-    update_status()
+    update_progress(None, None)
 
     # Run the items, either in a pool (for multicore speedup) or
     # calling each individually.

                       dest='dotest_options',
                       help="""The options passed to 'dotest.py' if specified.""")
 
+    parser.add_option('-s', '--output-on-success',
+                      action='store_true',
+                      dest='output_on_success',
+                      default=False,
+                      help="""Print full output of 'dotest.py' even when it succeeds.""")
+
     parser.add_option('-t', '--threads',
                       type='int',
                       dest='num_threads',

 
     parser = dotest_args.create_parser()
     global dotest_options
+    global output_on_success
+    output_on_success = opts.output_on_success
     dotest_options = dotest_args.parse_args(parser, dotest_argv)
 
     if not dotest_options.s: