From a76c50d1ee696c5b1a8b3c99978892bbe9b0d74a Mon Sep 17 00:00:00 2001 From: sknigh Date: Wed, 13 Feb 2019 10:14:35 -0800 Subject: 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. --- lib/spack/llnl/util/tty/__init__.py | 92 +++++++++++++++++++++++++++++++++++-- lib/spack/spack/fetch_strategy.py | 2 +- lib/spack/spack/main.py | 6 +++ lib/spack/spack/package.py | 6 +++ lib/spack/spack/test/cmd/install.py | 3 +- 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 @@ -329,6 +329,9 @@ def make_argument_parser(**kwargs): parser.add_argument( '-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 -- cgit v1.2.3-70-g09d2