Allow tty output to be timestamped (#10554)

* Spack debug output now includes microsecond-granularity timestamps.
* Timestamps can also be enabled with the `--timestamp` command line argument.

5 files changed, 103 insertions, 6 deletions

diff --git a/lib/spack/llnl/util/tty/__init__.py b/lib/spack/llnl/util/tty/__init__.py
index 567dbefd9b..383809295a 100644
--- a/lib/spack/llnl/util/tty/__init__.py
+++ b/lib/spack/llnl/util/tty/__init__.py
@@ -3,6 +3,7 @@
 #
 # SPDX-License-Identifier: (Apache-2.0 OR MIT)
 
+from datetime import datetime
 import fcntl
 import os
 import struct
@@ -18,6 +19,10 @@ from llnl.util.tty.color import cprint, cwrite, cescape, clen
 _debug = False
 _verbose = False
 _stacktrace = False
+_timestamp = False
+_msg_enabled = True
+_warn_enabled = True
+_error_enabled = True
 indent = "  "
 
 
@@ -43,6 +48,65 @@ def set_verbose(flag):
     _verbose = flag
 
 
+def set_timestamp(flag):
+    global _timestamp
+    _timestamp = flag
+
+
+def set_msg_enabled(flag):
+    global _msg_enabled
+    _msg_enabled = flag
+
+
+def set_warn_enabled(flag):
+    global _warn_enabled
+    _warn_enabled = flag
+
+
+def set_error_enabled(flag):
+    global _error_enabled
+    _error_enabled = flag
+
+
+def msg_enabled():
+    return _msg_enabled
+
+
+def warn_enabled():
+    return _warn_enabled
+
+
+def error_enabled():
+    return _error_enabled
+
+
+class SuppressOutput:
+    """Class for disabling output in a scope using 'with' keyword"""
+
+    def __init__(self,
+                 msg_enabled=True,
+                 warn_enabled=True,
+                 error_enabled=True):
+
+        self._msg_enabled_initial = _msg_enabled
+        self._warn_enabled_initial = _warn_enabled
+        self._error_enabled_initial = _error_enabled
+
+        self._msg_enabled = msg_enabled
+        self._warn_enabled = warn_enabled
+        self._error_enabled = error_enabled
+
+    def __enter__(self):
+        set_msg_enabled(self._msg_enabled)
+        set_warn_enabled(self._warn_enabled)
+        set_error_enabled(self._error_enabled)
+
+    def __exit__(self, exc_type, exc_val, exc_tb):
+        set_msg_enabled(self._msg_enabled_initial)
+        set_warn_enabled(self._warn_enabled_initial)
+        set_error_enabled(self._error_enabled_initial)
+
+
 def set_stacktrace(flag):
     global _stacktrace
     _stacktrace = flag
@@ -65,15 +129,28 @@ def process_stacktrace(countback):
     return st_text
 
 
+def get_timestamp(force=False):
+    """Get a string timestamp"""
+    if _debug or _timestamp or force:
+        return datetime.now().strftime("[%Y-%m-%d-%H:%M:%S.%f] ")
+    else:
+        return ''
+
+
 def msg(message, *args, **kwargs):
+    if not msg_enabled():
+        return
+
     newline = kwargs.get('newline', True)
     st_text = ""
     if _stacktrace:
         st_text = process_stacktrace(2)
     if newline:
-        cprint("@*b{%s==>} %s" % (st_text, cescape(message)))
+        cprint("@*b{%s==>} %s%s" % (
+            st_text, get_timestamp(), cescape(message)))
     else:
-        cwrite("@*b{%s==>} %s" % (st_text, cescape(message)))
+        cwrite("@*b{%s==>} %s%s" % (
+            st_text, get_timestamp(), cescape(message)))
     for arg in args:
         print(indent + str(arg))
 
@@ -88,8 +165,9 @@ def info(message, *args, **kwargs):
     st_text = ""
     if _stacktrace:
         st_text = process_stacktrace(st_countback)
-    cprint("@%s{%s==>} %s" % (format, st_text, cescape(str(message))),
-           stream=stream)
+    cprint("@%s{%s==>} %s%s" % (
+        format, st_text, get_timestamp(), cescape(str(message))),
+        stream=stream)
     for arg in args:
         if wrap:
             lines = textwrap.wrap(
@@ -115,12 +193,18 @@ def debug(message, *args, **kwargs):
 
 
 def error(message, *args, **kwargs):
+    if not error_enabled():
+        return
+
     kwargs.setdefault('format', '*r')
     kwargs.setdefault('stream', sys.stderr)
     info("Error: " + str(message), *args, **kwargs)
 
 
 def warn(message, *args, **kwargs):
+    if not warn_enabled():
+        return
+
     kwargs.setdefault('format', '*Y')
     kwargs.setdefault('stream', sys.stderr)
     info("Warning: " + str(message), *args, **kwargs)
diff --git a/lib/spack/spack/fetch_strategy.py b/lib/spack/spack/fetch_strategy.py
index 9ab402e6d8..bafd99f885 100644
--- a/lib/spack/spack/fetch_strategy.py
+++ b/lib/spack/spack/fetch_strategy.py
@@ -238,7 +238,7 @@ class URLFetchStrategy(FetchStrategy):
         if not spack.config.get('config:verify_ssl'):
             curl_args.append('-k')
 
-        if sys.stdout.isatty():
+        if sys.stdout.isatty() and tty.msg_enabled():
             curl_args.append('-#')  # status bar when using a tty
         else:
             curl_args.append('-sS')  # just errors when not.
diff --git a/lib/spack/spack/main.py b/lib/spack/spack/main.py
index c947a1139a..a5b0358c56 100644
--- a/lib/spack/spack/main.py
+++ b/lib/spack/spack/main.py
@@ -330,6 +330,9 @@ def make_argument_parser(**kwargs):
         '-d', '--debug', action='store_true',
         help="write out debug logs during compile")
     parser.add_argument(
+        '--timestamp', action='store_true',
+        help="Add a timestamp to tty output")
+    parser.add_argument(
         '--pdb', action='store_true',
         help="run spack under the pdb debugger")
 
@@ -399,6 +402,9 @@ def setup_main_options(args):
         spack.util.debug.register_interrupt_handler()
         spack.config.set('config:debug', True, scope='command_line')
 
+    if args.timestamp:
+        tty.set_timestamp(True)
+
     # override lock configuration if passed on command line
     if args.locks is not None:
         spack.util.lock.check_lock_safety(spack.paths.prefix)
diff --git a/lib/spack/spack/package.py b/lib/spack/spack/package.py
index ebdfb4b1f8..37c12b0bd5 100644
--- a/lib/spack/spack/package.py
+++ b/lib/spack/spack/package.py
@@ -1476,6 +1476,9 @@ class PackageBase(with_metaclass(PackageMeta, PackageViewMixin, object)):
                         # Save the build environment in a file before building.
                         dump_environment(self.env_path)
 
+                        # cache debug settings
+                        debug_enabled = tty.is_debug()
+
                         # Spawn a daemon that reads from a pipe and redirects
                         # everything to log_path
                         with log_output(self.log_path, echo, True) as logger:
@@ -1483,8 +1486,11 @@ class PackageBase(with_metaclass(PackageMeta, PackageViewMixin, object)):
                                     self.phases, self._InstallPhase_phases):
 
                                 with logger.force_echo():
+                                    inner_debug = tty.is_debug()
+                                    tty.set_debug(debug_enabled)
                                     tty.msg(
                                         "Executing phase: '%s'" % phase_name)
+                                    tty.set_debug(inner_debug)
 
                                 # Redirect stdout and stderr to daemon pipe
                                 phase = getattr(self, phase_attr)
diff --git a/lib/spack/spack/test/cmd/install.py b/lib/spack/spack/test/cmd/install.py
index f3e6a4d3ed..2b45fa25d7 100644
--- a/lib/spack/spack/test/cmd/install.py
+++ b/lib/spack/spack/test/cmd/install.py
@@ -6,6 +6,7 @@
 import argparse
 import os
 import filecmp
+import re
 from six.moves import builtins
 
 import pytest
@@ -129,7 +130,7 @@ def test_package_output(tmpdir, capsys, install_mockery, mock_fetch):
 
     # make sure that output from the actual package file appears in the
     # right place in the build log.
-    assert "BEFORE INSTALL\n==> './configure'" in out
+    assert re.search(r"BEFORE INSTALL\n==>( \[.+\])? './configure'", out)
     assert "'install'\nAFTER INSTALL" in out