• J
    test-lib: add --verbose-log option · 452320f1
    Jeff King 提交于
    The "--verbose" option redirects output from arbitrary
    test commands to stdout. This is useful for examining the
    output manually, like:
    
      ./t5547-push-quarantine.sh -v | less
    
    But it also means that the output is intermingled with the
    TAP directives, which can confuse a TAP parser like "prove".
    This has always been a potential problem, but became an
    issue recently when one test happened to output the word
    "ok" on a line by itself, which prove interprets as a test
    success:
    
      $ prove t5547-push-quarantine.sh :: -v
      t5547-push-quarantine.sh .. 1/? To dest.git
       * [new branch]      HEAD -> master
      To dest.git
       ! [remote rejected] reject -> reject (pre-receive hook declined)
      error: failed to push some refs to 'dest.git'
      fatal: git cat-file d08c8eba97f4e683ece08654c7c8d2ba0c03b129: bad file
      t5547-push-quarantine.sh .. Failed -1/4 subtests
    
      Test Summary Report
      -------------------
      t5547-push-quarantine.sh (Wstat: 0 Tests: 5 Failed: 0)
        Parse errors: Tests out of sequence.  Found (2) but expected (3)
                      Tests out of sequence.  Found (3) but expected (4)
                      Tests out of sequence.  Found (4) but expected (5)
                      Bad plan.  You planned 4 tests but ran 5.
      Files=1, Tests=5,  0 wallclock secs ( 0.01 usr +  0.01 sys =  0.02 CPU)
      Result: FAIL
    
    One answer is "if it hurts, don't do it", but that's not
    quite the whole story. The Travis tests use "--verbose
    --tee" so that they can get the benefit of prove's parallel
    options, along with a verbose log in case there is a
    failure. We just need the verbose output to go to the log,
    but keep stdout clean.
    
    Getting this right turns out to be surprisingly difficult.
    Here's the progression of alternatives I considered:
    
     1. Add an option to write verbose output to stderr. This is
        hard to capture, though, because we want each test to
        have its own log (because they're all run in parallel
        and the jumbled output would be useless).
    
     2. Add an option to write verbose output to a file in
        test-results. This works, but the log is missing all of
        the non-verbose output, which gives context.
    
     3. Like (2), but teach say_color() to additionally output
        to the log. This mostly works, but misses any output
        that happens outside of the say() functions (which isn't
        a lot, but is a potential maintenance headache).
    
     4. Like (2), but make the log file the same as the "--tee"
        file. That almost works, but now we have two processes
        opening the same file. That gives us two separate
        descriptors, each with their own idea of the current
        position. They'll each start writing at offset 0, and
        overwrite each other's data.
    
     5. Like (4), but in each case open the file for appending.
        That atomically positions each write at the end of the
        file.
    
        It's possible we may still get sheared writes between
        the two processes, but this is already the case when
        writing to stdout. It's not a problem in practice
        because the test harness generally waits for snippets to
        finish before writing the TAP output.
    
        We can ignore buffering issues with tee, because POSIX
        mandates that it does not buffer. Likewise, POSIX
        specifies "tee -a", so it should be available
        everywhere.
    
    This patch implements option (5), which seems to work well
    in practice.
    Signed-off-by: NJeff King <peff@peff.net>
    Signed-off-by: NJunio C Hamano <gitster@pobox.com>
    452320f1
test-lib.sh 25.6 KB