Rework output redirection in Spack.

- Simplify interface to log_output. New interface requires only one
  context handler instead of two.  Before:

      with log_output('logfile.txt') as log_redirection:
           with log_redirection:
               # do things ... output will be logged

  After:

      with log_output('logfile.txt'):
          # do things ... output will be logged

  If you also want the output to be echoed to ``stdout``, use the
  `echo` parameter::

      with log_output('logfile.txt', echo=True):
          # do things ... output will be logged and printed out

  And, if you just want to echo *some* stuff from the parent, use
  ``force_echo``:

      with log_output('logfile.txt', echo=False) as logger:
          # do things ... output will be logged

          with logger.force_echo():
              # things here will be echoed *and* logged

  A key difference between this and the previous implementation is that
  *everything* in the context handler is logged.  Previously, things like
  `Executing phase 'configure'` would not be logged, only output to the
  screen, so understanding phases in the build log was difficult.

- The implementation of `log_output()` is different in two major ways:

  1. This implementation avoids race cases by using only one pipe (before
     we had a multiprocessing pipe and a unix pipe).  The logger daemon
     stops naturally when the input stream is closed, which avoids a race
     in the previous implementation where we'd miss some lines of output
     because the parent would shut the daemon down before it was done
     with all output.

  2. Instead of turning output redirection on and off, which prevented
     some things from being logged, this version uses control characters
     in the output stream to enable/disable forced echoing.  We're using
     the time-honored xon and xoff codes, which tell the daemon to echo
     anything between them AND write it to the log.  This is how
     `logger.force_echo()` works.

- Fix places where output could get stuck in buffers by flushing more
  aggressively.  This makes the output printed to the terminal the same
  as that which would be printed through a pipe to `cat` or to a file.
  Previously these could be weirdly different, and some output would be
  missing when redirecting Spack to a file or pipe.

- Simplify input and color handling in both `build_environment.fork()`
  and `llnl.util.tty.log.log_output()`.  Neither requires an input_stream
  parameter anymore; we assume stdin will be forwarded if possible.

- remove `llnl.util.lang.duplicate_stream()` and remove associated
  monkey-patching in tests, as these aren't needed if you just check
  whether stdin is a tty and has a fileno attribute.

1 files changed, 218 insertions, 145 deletions

diff --git a/lib/spack/llnl/util/tty/log.py b/lib/spack/llnl/util/tty/log.py
index 4bf7c77d2c..ac77e2dc8d 100644
--- a/lib/spack/llnl/util/tty/log.py
+++ b/lib/spack/llnl/util/tty/log.py
@@ -29,27 +29,28 @@ import os
 import re
 import select
 import sys
+from contextlib import contextmanager
 
-import llnl.util.lang as lang
 import llnl.util.tty as tty
-import llnl.util.tty.color as color
 
 # Use this to strip escape sequences
 _escape = re.compile(r'\x1b[^m]*m|\x1b\[?1034h')
 
+# control characters for enabling/disabling echo
+#
+# We use control characters to ensure that echo enable/disable are inline
+# with the other output.  We always follow these with a newline to ensure
+# one per line the following newline is ignored in output.
+xon, xoff = '\x11\n', '\x13\n'
+control = re.compile('(\x11\n|\x13\n)')
 
 def _strip(line):
     """Strip color and control characters from a line."""
     return _escape.sub('', line)
 
 
-class _SkipWithBlock():
-    """Special exception class used to skip a with block."""
-    pass
-
-
 class keyboard_input(object):
-    """Disable canonical input and echo on a stream within a with block.
+    """Context manager to disable line editing and echoing.
 
     Use this with ``sys.stdin`` for keyboard input, e.g.::
 
@@ -57,14 +58,33 @@ class keyboard_input(object):
             r, w, x = select.select([sys.stdin], [], [])
             # ... do something with keypresses ...
 
-    When the with block completes, this will restore settings before
-    canonical and echo were disabled.
-    """
+    This disables canonical input so that keypresses are available on the
+    stream immediately. Typically standard input allows line editing,
+    which means keypresses won't be sent until the user hits return.
 
+    It also disables echoing, so that keys pressed aren't printed to the
+    terminal.  So, the user can hit, e.g., 'v', and it's read on the
+    other end of the pipe immediately but not printed.
+
+    When the with block completes, prior TTY settings are restored.
+
+    Note: this depends on termios support.  If termios isn't available,
+    or if the stream isn't a TTY, this context manager has no effect.
+    """
     def __init__(self, stream):
+        """Create a context manager that will enable keyboard input on stream.
+
+        Args:
+            stream (file-like): stream on which to accept keyboard input
+        """
         self.stream = stream
 
     def __enter__(self):
+        """Enable immediate keypress input on stream.
+
+        If the stream is not a TTY or the system doesn't support termios,
+        do nothing.
+        """
         self.old_cfg = None
 
         # Ignore all this if the input stream is not a tty.
@@ -72,7 +92,7 @@ class keyboard_input(object):
             return
 
         try:
-            # import and mark whether it worked.
+            # If this fails, self.old_cfg will remain None
             import termios
 
             # save old termios settings
@@ -89,11 +109,10 @@ class keyboard_input(object):
             termios.tcsetattr(fd, termios.TCSADRAIN, self.new_cfg)
 
         except Exception:
-            pass  # Some OS's do not support termios, so ignore.
+            pass  # some OS's do not support termios, so ignore
 
     def __exit__(self, exc_type, exception, traceback):
-        # If termios was avaialble, restore old settings after the
-        # with block
+        """If termios was avaialble, restore old settings."""
         if self.old_cfg:
             import termios
             termios.tcsetattr(
@@ -101,168 +120,222 @@ class keyboard_input(object):
 
 
 class log_output(object):
-    """Spawns a daemon that reads from a pipe and writes to a file
+    """Context manager that logs its output to a file.
+
+    In the simplest case, the usage looks like this::
+
+        with log_output('logfile.txt'):
+            # do things ... output will be logged
+
+    Any output from the with block will be redirected to ``logfile.txt``.
+    If you also want the output to be echoed to ``stdout``, use the
+    ``echo`` parameter::
+
+        with log_output('logfile.txt', echo=True):
+            # do things ... output will be logged and printed out
 
-    Usage::
+    And, if you just want to echo *some* stuff from the parent, use
+    ``force_echo``:
 
-        # Spawns the daemon
-        with log_output('logfile.txt', 'w') as log_redirection:
-           # do things ... output is not redirected
-           with log_redirection:
-                # do things ... output will be logged
+        with log_output('logfile.txt', echo=False) as logger:
+            # do things ... output will be logged
 
-    or::
+            with logger.force_echo():
+                # things here will be echoed *and* logged
 
-        with log_output('logfile.txt', echo=True) as log_redirection:
-           # do things ... output is not redirected
-           with log_redirection:
-               # do things ... output will be logged
-               # and also printed to stdout.
+    Under the hood, we spawn a daemon and set up a pipe between this
+    process and the daemon.  The daemon writes our output to both the
+    file and to stdout (if echoing).  The parent process can communicate
+    with the daemon to tell it when and when not to echo; this is what
+    force_echo does.  You can also enable/disable echoing by typing 'v'.
 
-    Opens a stream in 'w' mode at daemon spawning and closes it at
-    daemon joining. If echo is True, also prints the output to stdout.
+    We try to use OS-level file descriptors to do the redirection, but if
+    stdout or stderr has been set to some Python-level file object, we
+    use Python-level redirection instead.  This allows the redirection to
+    work within test frameworks like nose and pytest.
     """
 
-    def __init__(
-            self,
-            filename,
-            echo=False,
-            force_color=False,
-            debug=False,
-            input_stream=sys.stdin
-    ):
+    def __init__(self, filename, echo=False, debug=False):
+        """Create a new output log context manager.
+
+        Logger daemon is not started until ``__enter__()``.
+        """
         self.filename = filename
-        # Various output options
         self.echo = echo
-        self.force_color = force_color
         self.debug = debug
 
-        # Default is to try file-descriptor reassignment unless the system
-        # out/err streams do not have an associated file descriptor
-        self.directAssignment = False
-        self.read, self.write = os.pipe()
-
-        # Needed to un-summon the daemon
-        self.parent_pipe, self.child_pipe = multiprocessing.Pipe()
-        # Input stream that controls verbosity interactively
-        self.input_stream = input_stream
+        self._active = False  # used to prevent re-entry
 
     def __enter__(self):
+        if self._active:
+            raise RuntimeError("Can't re-enter the same log_output!")
+
+        # record parent color settings before redirecting.  We do this
+        # because color output depends on whether the *original* stdout
+        # is a TTY.  New stdout won't be a TTY so we force colorization.
+        self._saved_color = tty.color._force_color
+        forced_color = tty.color.get_color_when()
+
+        # also record parent debug settings -- in case the logger is
+        # forcing debug output.
+        self._saved_debug = tty._debug
+
+        # OS-level pipe for redirecting output to logger
+        self.read_fd, self.write_fd = os.pipe()
+
         # Sets a daemon that writes to file what it reads from a pipe
         try:
-            fwd_input_stream = lang.duplicate_stream(self.input_stream)
-            self.p = multiprocessing.Process(
-                target=self._spawn_writing_daemon,
-                args=(self.read, fwd_input_stream),
-                name='logger_daemon'
-            )
-            self.p.daemon = True
-            self.p.start()
+            # need to pass this b/c multiprocessing closes stdin in child.
+            input_stream = os.fdopen(os.dup(sys.stdin.fileno()))
+
+            self.process = multiprocessing.Process(
+                target=self._writer_daemon, args=(input_stream,))
+            self.process.daemon = True  # must set before start()
+            self.process.start()
+            os.close(self.read_fd)  # close in the parent process
+
         finally:
-            fwd_input_stream.close()
-        return log_output.OutputRedirection(self)
+            input_stream.close()
 
-    def __exit__(self, exc_type, exc_val, exc_tb):
-        self.parent_pipe.send(True)
-        self.p.join(60.0)  # 1 minute to join the child
+        # Flush immediately before redirecting so that anything buffered
+        # goes to the original stream
+        sys.stdout.flush()
+        sys.stderr.flush()
 
-    def _spawn_writing_daemon(self, read, input_stream):
-        # This is the Parent: read from child, skip the with block.
+        # Now do the actual output rediction.
+        self.use_fds = True
+        try:
+            # We try first to use OS-level file descriptors, as this
+            # redirects output for subprocesses and system calls.
+
+            # Save old stdout and stderr file descriptors
+            self._saved_stdout = os.dup(sys.stdout.fileno())
+            self._saved_stderr = os.dup(sys.stderr.fileno())
+
+            # redirect to the pipe we created above
+            os.dup2(self.write_fd, sys.stdout.fileno())
+            os.dup2(self.write_fd, sys.stderr.fileno())
+            os.close(self.write_fd)
+
+        except AttributeError:
+            # Using file descriptors can fail if stdout and stderr don't
+            # have a fileno attribute. This can happen, when, e.g., the
+            # test framework replaces stdout with a StringIO object.  We
+            # handle thi the Python way. This won't redirect lower-level
+            # output, but it's the best we can do.
+            self.use_fds = False
+
+            # Save old stdout and stderr file objects
+            self._saved_stdout = sys.stdout
+            self._saved_stderr = sys.stderr
+
+            # create a file object for the pipe; redirect to it.
+            pipe_fd_out = os.fdopen(self.write_fd, 'w')
+            sys.stdout = pipe_fd_out
+            sys.stderr = pipe_fd_out
+
+        # Force color and debug settings now that we have redirected.
+        tty.color.set_color_when(forced_color)
+        tty._debug = self.debug
+
+        # track whether we're currently inside this log_output
+        self._active = True
+
+        # return this log_output object so that the user can do things
+        # like temporarily echo some ouptut.
+        return self
 
+    def __exit__(self, exc_type, exc_val, exc_tb):
+        # Flush any buffered output to the logger daemon.
+        sys.stdout.flush()
+        sys.stderr.flush()
+
+        # restore previous output settings, either the low-level way or
+        # the python way
+        if self.use_fds:
+            os.dup2(self._saved_stdout, sys.stdout.fileno())
+            os.close(self._saved_stdout)
+
+            os.dup2(self._saved_stderr, sys.stderr.fileno())
+            os.close(self._saved_stderr)
+        else:
+            sys.stdout = self._saved_stdout
+            sys.stderr = self._saved_stderr
+
+        # join the daemon process. The daemon will quit automatically
+        # when the write pipe is closed; we just wait for it here.
+        self.process.join()
+
+        # restore old color and debug settings
+        tty.color._force_color = self._saved_color
+        tty._debug = self._saved_debug
+
+        self._active = False  # safe to enter again
+
+    @contextmanager
+    def force_echo(self):
+        """Context manager to force local echo, even if echo is off."""
+        if not self._active:
+            raise RuntimeError(
+                "Can't call force_echo() outside log_output region!")
+
+        # This uses the xon/xoff to highlight regions to be echoed in the
+        # output. We us these control characters rather than, say, a
+        # separate pipe, because they're in-band and assured to appear
+        # exactly before and after the text we want to echo.
+        sys.stdout.write(xon)
+        sys.stdout.flush()
+        yield
+        sys.stdout.write(xoff)
+        sys.stdout.flush()
+
+    def _writer_daemon(self, stdin):
+        """Daemon that writes output to the log file and stdout."""
         # Use line buffering (3rd param = 1) since Python 3 has a bug
         # that prevents unbuffered text I/O.
-        read_file = os.fdopen(read, 'r', 1)
+        in_pipe = os.fdopen(self.read_fd, 'r', 1)
+        os.close(self.write_fd)
+
+        echo = self.echo        # initial echo setting, user-controllable
+        force_echo = False      # parent can force echo for certain output
 
         with open(self.filename, 'w') as log_file:
-            with keyboard_input(input_stream):
+            with keyboard_input(stdin):
                 while True:
-                    # Without the last parameter (timeout) select will wait
-                    # until at least one of the two streams are ready. This
-                    # may cause the function to hang.
-                    rlist, _, _ = select.select(
-                        [read_file, input_stream], [], [], 0
-                    )
+                    # Without the last parameter (timeout) select will
+                    # wait until at least one of the two streams are
+                    # ready. This may cause the function to hang.
+                    rlist, _, xlist = select.select(
+                        [in_pipe, stdin], [], [], 0)
 
                     # Allow user to toggle echo with 'v' key.
                     # Currently ignores other chars.
-                    if input_stream in rlist:
-                        if input_stream.read(1) == 'v':
-                            self.echo = not self.echo
+                    if stdin in rlist:
+                        if stdin.read(1) == 'v':
+                            echo = not echo
 
                     # Handle output from the with block process.
-                    if read_file in rlist:
-                        # If we arrive here it means that
-                        # read_file was ready for reading : it
-                        # should never happen that line is false-ish
-                        line = read_file.readline()
-
-                        # Echo to stdout if requested.
-                        if self.echo:
+                    if in_pipe in rlist:
+                        # If we arrive here it means that in_pipe was
+                        # ready for reading : it should never happen that
+                        # line is false-ish
+                        line = in_pipe.readline()
+                        if not line:
+                            break  # EOF
+
+                        # find control characters and strip them.
+                        controls = control.findall(line)
+                        line = re.sub(control, '', line)
+
+                        # Echo to stdout if requested or forced
+                        if echo or force_echo:
                             sys.stdout.write(line)
 
                         # Stripped output to log file.
                         log_file.write(_strip(line))
                         log_file.flush()
 
-                    if self.child_pipe.poll():
-                        break
-
-    def __del__(self):
-        """Closes the pipes"""
-        os.close(self.write)
-        os.close(self.read)
-
-    class OutputRedirection(object):
-
-        def __init__(self, other):
-            self.__dict__.update(other.__dict__)
-
-        def __enter__(self):
-            """Redirect output from the with block to a file.
-
-            Hijacks stdout / stderr and writes to the pipe
-            connected to the logger daemon
-            """
-            # remember these values for later.
-            self._force_color = color._force_color
-            self._debug = tty._debug
-            # Redirect this output to a pipe
-            write = self.write
-            try:
-                # Save old stdout and stderr
-                self._stdout = os.dup(sys.stdout.fileno())
-                self._stderr = os.dup(sys.stderr.fileno())
-
-                # redirect to the pipe.
-                os.dup2(write, sys.stdout.fileno())
-                os.dup2(write, sys.stderr.fileno())
-            except AttributeError:
-                self.directAssignment = True
-                self._stdout = sys.stdout
-                self._stderr = sys.stderr
-                output_redirect = os.fdopen(write, 'w')
-                sys.stdout = output_redirect
-                sys.stderr = output_redirect
-            if self.force_color:
-                color._force_color = True
-            if self.debug:
-                tty._debug = True
-
-        def __exit__(self, exc_type, exception, traceback):
-            """Plugs back the original file descriptors
-            for stdout and stderr
-            """
-            # Flush the log to disk.
-            sys.stdout.flush()
-            sys.stderr.flush()
-            if self.directAssignment:
-                # We seem to need this only to pass test/install.py
-                sys.stdout = self._stdout
-                sys.stderr = self._stderr
-            else:
-                os.dup2(self._stdout, sys.stdout.fileno())
-                os.dup2(self._stderr, sys.stderr.fileno())
-
-            # restore output options.
-            color._force_color = self._force_color
-            tty._debug = self._debug
+                        if xon in controls:
+                            force_echo = True
+                        if xoff in controls:
+                            force_echo = False