[lit] Factor out a helper for shell command results.

[• ddunbar]

Summary

[lit] Improve readability of failing scripts.

• This only applies to scripts executed by the _internal_ shell script interpreter.
• This patch reworks the log to look more like a shell transcript, and be less verbose (but in the interest of calling attention to the important parts).

Here is an example of the new format, for commands with/without failures and
with/without output:

$ true
$ echo hi
hi

$ false
note: command had no output on stdout or stderr
error: command failed with exit status 1

[lit] Improve logging with file redirection.

• This will cause lit to automatically include the first 1K of data in redirected output files when a command fails (previously if the command failed, but the main point of the test was, say, a FileCheck later on, then the log wasn't helpful in showing why the command failed).

[EricWF]

utils/lit/lit/TestRunner.py

117

Default parameters are mutable in python. The default should either be None or outputFiles needs to be copied on initialization.

400

Is there a reason to sort the files?

[• ddunbar]

utils/lit/lit/TestRunner.py

117

Good point, will fix.

400

To ensure the output is deterministic (and ordered in a canonical fashion), when shown to the user.

[MatzeB]

Have you seen this mail thread: http://lists.llvm.org/pipermail/llvm-commits/Week-of-Mon-20160523/360023.html

If I understand this correctly this is a nicer solution for those cases. At a general level do you know if there are performance or correctness problems with just always using the integrated shell parses to get consistent behavior?

utils/lit/lit/TestRunner.py

387

I think you should use errors="replace" here to avoid lit aborting on strange inputs.

[• ddunbar]

I merged this with corrections in 271608, 271610, and 272021.

utils/lit/lit/TestRunner.py

def _kill(self):
         """
         with self._lock:
             for p in self._procs:
                 lit.util.killProcessAndChildren(p.pid)
             # Empty the list and note that we've done a pass over the list
             self._procs = [] # Python2 doesn't have list.clear()
             self._doneKillPass = True
 
+class ShellCommandResult(object):
+    """Captures the result of an individual command."""
+
+    def __init__(self, command, stdout, stderr, exitCode, timeoutReached,
+                 outputFiles = []):
+        self.command = command
+        self.stdout = stdout
+        self.stderr = stderr
+        self.exitCode = exitCode
+        self.timeoutReached = timeoutReached
+        self.outputFiles = outputFiles
+               
 def executeShCmd(cmd, shenv, results, timeout=0):
     """
         Wrapper around _executeShCmd that handles
         timeout
     """
     # Use the helper even when no timeout is required to make
     # other code simpler (i.e. avoid bunch of ``!= None`` checks)
     timeoutHelper = TimeoutHelper(timeout)
for i,j in enumerate(cmd.commands):
                         # Make sure relative paths are relative to the cwd.
                         redir_filename = os.path.join(cmd_shenv.cwd, r[0])
                         r[2] = open(redir_filename, r[1])
                     # Workaround a Win32 and/or subprocess bug when appending.
                     #
                     # FIXME: Actually, this is probably an instance of PR6753.
                     if r[1] == 'a':
                         r[2].seek(0, 2)
-                    opened_files.append(r[2])
+                    opened_files.append(tuple(r) + (redir_filename,))
                 result = r[2]
             final_redirects.append(result)
 
         stdin, stdout, stderr = final_redirects
 
         # If stderr wants to come from stdout, but stdout isn't a pipe, then put
         # stderr on a pipe and treat it as stdout.
         if (stderr == subprocess.STDOUT and stdout != subprocess.PIPE):
for i,j in enumerate(cmd.commands):
             input = procs[-1].stderr
         else:
             input = subprocess.PIPE
 
     # Explicitly close any redirected files. We need to do this now because we
     # need to release any handles we may have on the temporary files (important
     # on Win32, for example). Since we have already spawned the subprocess, our
     # handles have already been transferred so we do not need them anymore.
-    for f in opened_files:
+    for (name, mode, f, path) in opened_files:
         f.close()
 
     # FIXME: There is probably still deadlock potential here. Yawn.
     procData = [None] * len(procs)
     procData[-1] = procs[-1].communicate()
 
     for i in range(len(procs) - 1):
         if procs[i].stdout is not None:
def _executeShCmd(cmd, shenv, results, timeoutHelper):
     for i,(out,err) in enumerate(procData):
         res = procs[i].wait()
         # Detect Ctrl-C in subprocess.
         if res == -signal.SIGINT:
             raise KeyboardInterrupt
 
         # Ensure the resulting output is always of string type.
         try:
+            if out is None:
+                out = ''
+            else:
                 out = to_string(out.decode('utf-8'))
         except:
             out = str(out)
         try:
+            if err is None:
+                err = ''
+            else:
                 err = to_string(err.decode('utf-8'))
         except:
             err = str(err)
 
-        results.append((cmd.commands[i], out, err, res, timeoutHelper.timeoutReached()))
+        # Gather the redirected output files.
+        output_files = []
+        for (name, mode, f, path) in sorted(opened_files):
+            if mode in ('w', 'a'):
+                try:
+                    with open(path) as f:
+                        data = f.read()
+                except:
+                    data = None
+                if data != None:
+                    output_files.append((name, path, data))
+            
+        results.append(ShellCommandResult(
+            cmd.commands[i], out, err, res, timeoutHelper.timeoutReached(),
+            output_files))
         if cmd.pipe_err:
             # Python treats the exit code as a signed char.
             if exitCode is None:
                 exitCode = res
             elif res < 0:
                 exitCode = min(exitCode, res)
             else:
                 exitCode = max(exitCode, res)
def executeScriptInternal(test, litConfig, tmpBase, commands, cwd):
     results = []
     timeoutInfo = None
     try:
         shenv = ShellEnvironment(cwd, test.config.environment)
         exitCode, timeoutInfo = executeShCmd(cmd, shenv, results, timeout=litConfig.maxIndividualTestTime)
     except InternalShellError:
         e = sys.exc_info()[1]
         exitCode = 127
-        results.append((e.command, '', e.message, exitCode, False))
+        results.append(
+            ShellCommandResult(e.command, '', e.message, exitCode, False))
 
     out = err = ''
-    for i,(cmd, cmd_out, cmd_err, res, timeoutReached) in enumerate(results):
-        out += 'Command %d: %s\n' % (i, ' '.join('"%s"' % s for s in cmd.args))
-        out += 'Command %d Result: %r\n' % (i, res)
+    for i,result in enumerate(results):
+        # Write the command line run.
+        out += '$ %s\n' % (' '.join('"%s"' % s
+                                    for s in result.command.args),)
+
+        # If nothing interesting happened, move on.
+        if litConfig.maxIndividualTestTime == 0 and \
+               result.exitCode == 0 and \
+               not result.stdout.strip() and not result.stderr.strip():
+            continue
+
+        # Otherwise, something failed or was printed, show it.
+
+        # Add the command output, if redirected.
+        for (name, path, data) in result.outputFiles:
+            if data.strip():
+                out += "# redirected output from %r:\n" % (name,)
+                data = to_string(data.decode('utf-8'))
+                if len(data) > 1024:
+                    out += data[:1024] + "\n...\n"
+                    out += "note: data was truncated\n"
+                else:
+                    out += data
+                out += "\n"
+                    
+        if result.stdout.strip():
+            out += '# command output:\n%s\n' % (result.stdout,)
+        if result.stderr.strip():
+            out += '# command stderr:\n%s\n' % (result.stderr,)
+        if not result.stdout.strip() and not result.stderr.strip():
+            out += "note: command had no output on stdout or stderr\n"
+
+        # Show the error conditions:
+        if result.exitCode != 0:
+            out += "error: command failed with exit status: %d\n" % (
+                result.exitCode,)
         if litConfig.maxIndividualTestTime > 0:
-            out += 'Command %d Reached Timeout: %s\n\n' % (i, str(timeoutReached))
-        out += 'Command %d Output:\n%s\n\n' % (i, cmd_out)
-        out += 'Command %d Stderr:\n%s\n\n' % (i, cmd_err)
+            out += 'error: command reached timeout: %s\n' % (
+                i, str(result.timeoutReached))
 
     return out, err, exitCode, timeoutInfo
 
 def executeScript(test, litConfig, tmpBase, commands, cwd):
     bashPath = litConfig.getBashPath();
     isWin32CMDEXE = (litConfig.isWindows and not bashPath)
     script = tmpBase + '.script'
     if isWin32CMDEXE:

utils/lit/tests/Inputs/shtest-output-printing/basic.txt

+# RUN: true
+# RUN: echo hi
+# RUN: wc missing-file &> %t.out

utils/lit/tests/Inputs/shtest-output-printing/lit.cfg

+import lit.formats
+config.name = 'shtest-output-printing'
+config.suffixes = ['.txt']
+config.test_format = lit.formats.ShTest(execute_external=False)

utils/lit/tests/shtest-format.py

 # CHECK-NEXT: --
 # CHECK-NEXT: printf "line 1
 # CHECK-NEXT: false
 # CHECK-NEXT: --
 # CHECK-NEXT: Exit Code: 1
 #
 # CHECK: Command Output (stdout):
 # CHECK-NEXT: --
-# CHECK-NEXT: Command 0: "printf"
-# CHECK-NEXT: Command 0 Result: 0
-# CHECK-NEXT: Command 0 Output:
+# CHECK-NEXT: $ "printf"
+# CHECK-NEXT: # command output:
 # CHECK-NEXT: line 1: failed test output on stdout
 # CHECK-NEXT: line 2: failed test output on stdout
 
 # CHECK: UNRESOLVED: shtest-format :: no-test-line.txt
 # CHECK: PASS: shtest-format :: pass.txt
 # CHECK: UNSUPPORTED: shtest-format :: requires-missing.txt
 # CHECK: PASS: shtest-format :: requires-present.txt
 # CHECK: UNSUPPORTED: shtest-format :: unsupported_dir/some-test.txt

utils/lit/tests/shtest-output-printing.py

+# Check the various features of the ShTest format.
+#
+# RUN: not %{lit} -j 1 -v %{inputs}/shtest-output-printing > %t.out
+# RUN: FileCheck --input-file %t.out %s
+#
+# END.
+
+# CHECK: -- Testing:
+
+# CHECK: FAIL: shtest-output-printing :: basic.txt
+# CHECK-NEXT: *** TEST 'shtest-output-printing :: basic.txt' FAILED ***
+# CHECK-NEXT: Script:
+# CHECK-NEXT: --
+# CHECK:      --
+# CHECK-NEXT: Exit Code: 1
+#
+# CHECK:      Command Output
+# CHECK-NEXT: --
+# CHECK-NEXT: $ "true"
+# CHECK-NEXT: $ "echo" "hi"
+# CHECK-NEXT: # command output:
+# CHECK-NEXT: hi
+#
+# CHECK:      $ "wc" "missing-file"
+# CHECK-NEXT: # redirected output from '{{.*}}/basic.txt.tmp.out':
+# CHECK-NEXT: missing-file{{.*}} No such file or directory
+# CHECK:      note: command had no output on stdout or stderr
+# CHECK-NEXT: error: command failed with exit status: 1

utils/lit/tests/shtest-shell.py

 # Check the internal shell handling component of the ShTest format.
 #
 # RUN: not %{lit} -j 1 -v %{inputs}/shtest-shell > %t.out
-# RUN: FileCheck < %t.out %s
+# RUN: FileCheck --input-file %t.out %s
 #
 # END.
 
 # CHECK: -- Testing:
 
 # CHECK: FAIL: shtest-shell :: error-0.txt
 # CHECK: *** TEST 'shtest-shell :: error-0.txt' FAILED ***
-# CHECK: Command 0: "not-a-real-command"
-# CHECK: Command 0 Result: 127
-# CHECK: Command 0 Stderr:
+# CHECK: $ "not-a-real-command"
+# CHECK: # command stderr:
 # CHECK: 'not-a-real-command': command not found
+# CHECK: error: command failed with exit status: 127
 # CHECK: ***
 
 # FIXME: The output here sucks.
 #
 # CHECK: FAIL: shtest-shell :: error-1.txt
 # CHECK: *** TEST 'shtest-shell :: error-1.txt' FAILED ***
 # CHECK: shell parser error on: 'echo "missing quote'
 # CHECK: ***