Preserve verbosity across installs when 'v' is pressed.

- 'v' toggle was previously only good for the current install.
- subsequent installs needed user to press 'v' again.
- 'v' state is now preserved across dependency installs.

3 files changed, 159 insertions, 66 deletions

diff --git a/lib/spack/llnl/util/tty/log.py b/lib/spack/llnl/util/tty/log.py
index ac77e2dc8d..2b3ad22c2d 100644
--- a/lib/spack/llnl/util/tty/log.py
+++ b/lib/spack/llnl/util/tty/log.py
@@ -29,6 +29,7 @@ import os
 import re
 import select
 import sys
+import traceback
 from contextlib import contextmanager
 
 import llnl.util.tty as tty
@@ -44,6 +45,7 @@ _escape = re.compile(r'\x1b[^m]*m|\x1b\[?1034h')
 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)
@@ -76,6 +78,9 @@ class keyboard_input(object):
 
         Args:
             stream (file-like): stream on which to accept keyboard input
+
+        Note that stream can be None, in which case ``keyboard_input``
+        will do nothing.
         """
         self.stream = stream
 
@@ -88,7 +93,7 @@ class keyboard_input(object):
         self.old_cfg = None
 
         # Ignore all this if the input stream is not a tty.
-        if not self.stream.isatty():
+        if not self.stream or not self.stream.isatty():
             return
 
         try:
@@ -119,6 +124,30 @@ class keyboard_input(object):
                 self.stream.fileno(), termios.TCSADRAIN, self.old_cfg)
 
 
+def _file_descriptors_work():
+    """Whether we can get file descriptors for stdout and stderr.
+
+    This tries to call ``fileno()`` on ``sys.stdout`` and ``sys.stderr``
+    and returns ``False`` if anything goes wrong.
+
+    This can happen, when, e.g., the test framework replaces stdout with
+    a ``StringIO`` object.
+
+    We have to actually try this to see whether it works, rather than
+    checking for the fileno attribute, beacuse frameworks like pytest add
+    dummy fileno methods on their dummy file objects that return
+    ``UnsupportedOperationErrors``.
+
+    """
+    # test whether we can get fds for out and error
+    try:
+        sys.stdout.fileno()
+        sys.stderr.fileno()
+        return True
+    except:
+        return False
+
+
 class log_output(object):
     """Context manager that logs its output to a file.
 
@@ -135,7 +164,7 @@ class log_output(object):
             # do things ... output will be logged and printed out
 
     And, if you just want to echo *some* stuff from the parent, use
-    ``force_echo``:
+    ``force_echo``::
 
         with log_output('logfile.txt', echo=False) as logger:
             # do things ... output will be logged
@@ -155,7 +184,7 @@ class log_output(object):
     work within test frameworks like nose and pytest.
     """
 
-    def __init__(self, filename, echo=False, debug=False):
+    def __init__(self, filename=None, echo=False, debug=False):
         """Create a new output log context manager.
 
         Logger daemon is not started until ``__enter__()``.
@@ -166,10 +195,38 @@ class log_output(object):
 
         self._active = False  # used to prevent re-entry
 
+    def __call__(self, filename=None, echo=None, debug=None):
+        """Thie behaves the same as init. It allows a logger to be reused.
+
+        With the ``__call__`` function, you can save state between uses
+        of a single logger.  This is useful if you want to remember,
+        e.g., the echo settings for a prior ``with log_output()``::
+
+            logger = log_output()
+
+            with logger('foo.txt'):
+                # log things; user can change echo settings with 'v'
+
+            with logger('bar.txt'):
+                # log things; logger remembers prior echo settings.
+
+        """
+        if filename is not None:
+            self.filename = filename
+        if echo is not None:
+            self.echo = echo
+        if debug is not None:
+            self.debug = debug
+        return self
+
     def __enter__(self):
         if self._active:
             raise RuntimeError("Can't re-enter the same log_output!")
 
+        if self.filename is None:
+            raise RuntimeError(
+                "filename must be set by either __init__ or __call__")
+
         # 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.
@@ -183,10 +240,17 @@ class log_output(object):
         # OS-level pipe for redirecting output to logger
         self.read_fd, self.write_fd = os.pipe()
 
+        # Multiprocessing pipe for communication back from the daemon
+        # Currently only used to save echo value between uses
+        self.parent, self.child = multiprocessing.Pipe()
+
         # Sets a daemon that writes to file what it reads from a pipe
         try:
             # need to pass this b/c multiprocessing closes stdin in child.
-            input_stream = os.fdopen(os.dup(sys.stdin.fileno()))
+            try:
+                input_stream = os.fdopen(os.dup(sys.stdin.fileno()))
+            except:
+                input_stream = None  # just don't forward input if this fails
 
             self.process = multiprocessing.Process(
                 target=self._writer_daemon, args=(input_stream,))
@@ -195,7 +259,8 @@ class log_output(object):
             os.close(self.read_fd)  # close in the parent process
 
         finally:
-            input_stream.close()
+            if input_stream:
+                input_stream.close()
 
         # Flush immediately before redirecting so that anything buffered
         # goes to the original stream
@@ -203,8 +268,8 @@ class log_output(object):
         sys.stderr.flush()
 
         # Now do the actual output rediction.
-        self.use_fds = True
-        try:
+        self.use_fds = _file_descriptors_work()
+        if self.use_fds:
             # We try first to use OS-level file descriptors, as this
             # redirects output for subprocesses and system calls.
 
@@ -217,13 +282,11 @@ class log_output(object):
             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
+        else:
+            # Handle I/O the Python way. This won't redirect lower-level
+            # output, but it's the best we can do, and the caller
+            # shouldn't expect any better, since *they* have apparently
+            # redirected I/O the Python way.
 
             # Save old stdout and stderr file objects
             self._saved_stdout = sys.stdout
@@ -262,6 +325,9 @@ class log_output(object):
             sys.stdout = self._saved_stdout
             sys.stderr = self._saved_stderr
 
+        # recover and store echo settings from the child before it dies
+        self.echo = self.parent.recv()
+
         # join the daemon process. The daemon will quit automatically
         # when the write pipe is closed; we just wait for it here.
         self.process.join()
@@ -299,43 +365,53 @@ class log_output(object):
         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(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, _, xlist = select.select(
-                        [in_pipe, stdin], [], [], 0)
-
-                    # Allow user to toggle echo with 'v' key.
-                    # Currently ignores other chars.
-                    if stdin in rlist:
-                        if stdin.read(1) == 'v':
-                            echo = not echo
-
-                    # Handle output from the with block process.
-                    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 xon in controls:
-                            force_echo = True
-                        if xoff in controls:
-                            force_echo = False
+        # list of streams to select from
+        istreams = [in_pipe, stdin] if stdin else [in_pipe]
+
+        try:
+            with open(self.filename, 'w') as log_file:
+                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, _, xlist = select.select(istreams, [], [], 0)
+
+                        # Allow user to toggle echo with 'v' key.
+                        # Currently ignores other chars.
+                        if stdin in rlist:
+                            if stdin.read(1) == 'v':
+                                echo = not echo
+
+                        # Handle output from the with block process.
+                        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 xon in controls:
+                                force_echo = True
+                            if xoff in controls:
+                                force_echo = False
+
+        except:
+            tty.error("Exception occurred in writer daemon!")
+            traceback.print_exc()
+
+        # send echo value back to the parent so it can be preserved.
+        self.child.send(echo)
diff --git a/lib/spack/spack/build_environment.py b/lib/spack/spack/build_environment.py
index 53aa14ebc1..339468f4be 100644
--- a/lib/spack/spack/build_environment.py
+++ b/lib/spack/spack/build_environment.py
@@ -550,8 +550,8 @@ def fork(pkg, function, dirty=False):
 
         try:
             setup_package(pkg, dirty=dirty)
-            function()
-            child_pipe.send(None)
+            return_value = function()
+            child_pipe.send(return_value)
         except StopIteration as e:
             # StopIteration is used to stop installations
             # before the final stage, mainly for debug purposes
@@ -598,11 +598,12 @@ def fork(pkg, function, dirty=False):
         if input_stream is not None:
             input_stream.close()
 
-    child_exc = parent_pipe.recv()
+    child_result = parent_pipe.recv()
     p.join()
 
-    if child_exc is not None:
-        raise child_exc
+    if isinstance(child_result, ChildError):
+        raise child_result
+    return child_result
 
 
 def get_package_context(traceback):
diff --git a/lib/spack/spack/package.py b/lib/spack/spack/package.py
index c94772c2a5..ef1c411f66 100644
--- a/lib/spack/spack/package.py
+++ b/lib/spack/spack/package.py
@@ -542,6 +542,9 @@ class PackageBase(with_metaclass(PackageMeta, object)):
     #: Defaults to the empty string.
     license_url = ''
 
+    # Verbosity level, preserved across installs.
+    _verbose = None
+
     def __init__(self, spec):
         # this determines how the package should be built.
         self.spec = spec
@@ -1275,8 +1278,13 @@ class PackageBase(with_metaclass(PackageMeta, object)):
 
         # Then install the package itself.
         def build_process():
-            """Forked for each build. Has its own process and python
-               module space set up by build_environment.fork()."""
+            """This implements the process forked for each build.
+
+            Has its own process and python module space set up by
+            build_environment.fork().
+
+            This function's return value is returned to the parent process.
+            """
 
             start_time = time.time()
             if not fake:
@@ -1289,6 +1297,11 @@ class PackageBase(with_metaclass(PackageMeta, object)):
                 'Building {0} [{1}]'.format(self.name, self.build_system_class)
             )
 
+            # get verbosity from do_install() parameter or saved value
+            echo = verbose
+            if PackageBase._verbose is not None:
+                echo = PackageBase._verbose
+
             self.stage.keep = keep_stage
             with self._stage_and_write_lock():
                 # Run the pre-install hook in the child process after
@@ -1314,10 +1327,7 @@ class PackageBase(with_metaclass(PackageMeta, object)):
 
                     # Spawn a daemon that reads from a pipe and redirects
                     # everything to log_path
-                    with log_output(log_path,
-                                    echo=verbose,
-                                    debug=True) as logger:
-
+                    with log_output(log_path, echo, True) as logger:
                         for phase_name, phase_attr in zip(
                                 self.phases, self._InstallPhase_phases):
 
@@ -1328,6 +1338,7 @@ class PackageBase(with_metaclass(PackageMeta, object)):
                             phase = getattr(self, phase_attr)
                             phase(self.spec, self.prefix)
 
+                    echo = logger.echo
                     self.log()
                 # Run post install hooks before build stage is removed.
                 spack.hooks.post_install(self.spec)
@@ -1342,13 +1353,18 @@ class PackageBase(with_metaclass(PackageMeta, object)):
                      _hms(self._total_time)))
             print_pkg(self.prefix)
 
+            # preserve verbosity across runs
+            return echo
+
         try:
             # Create the install prefix and fork the build process.
             if not os.path.exists(self.prefix):
                 spack.store.layout.create_install_directory(self.spec)
 
             # Fork a child to do the actual installation
-            spack.build_environment.fork(self, build_process, dirty=dirty)
+            # we preserve verbosity settings across installs.
+            PackageBase._verbose = spack.build_environment.fork(
+                self, build_process, dirty=dirty)
 
             # If we installed then we should keep the prefix
             keep_prefix = self.last_phase is None or keep_prefix