From ceecd2ce4152227f413484afad98d576348ec857 Mon Sep 17 00:00:00 2001 From: Todd Gamblin Date: Fri, 29 May 2015 17:18:33 -0700 Subject: [PATCH 1/5] Add ability to test whether tty verbose or debug is enabled. --- lib/spack/llnl/util/tty/__init__.py | 8 ++++++++ 1 file changed, 8 insertions(+) diff --git a/lib/spack/llnl/util/tty/__init__.py b/lib/spack/llnl/util/tty/__init__.py index aba9e61f4f..48368543ff 100644 --- a/lib/spack/llnl/util/tty/__init__.py +++ b/lib/spack/llnl/util/tty/__init__.py @@ -36,6 +36,14 @@ _verbose = False indent = " " +def is_verbose(): + return _verbose + + +def is_debug(): + return _debug + + def set_debug(flag): global _debug _debug = flag From 9b40d93fc28772d0f3d8c314789ae0aea704b0be Mon Sep 17 00:00:00 2001 From: Todd Gamblin Date: Fri, 29 May 2015 17:19:03 -0700 Subject: [PATCH 2/5] Add ability to force color mode even if terminal is NOT a tty --- lib/spack/llnl/util/tty/color.py | 8 ++++++-- 1 file changed, 6 insertions(+), 2 deletions(-) diff --git a/lib/spack/llnl/util/tty/color.py b/lib/spack/llnl/util/tty/color.py index 81688d7f14..22080a7b37 100644 --- a/lib/spack/llnl/util/tty/color.py +++ b/lib/spack/llnl/util/tty/color.py @@ -99,6 +99,10 @@ def __init__(self, message): color_re = r'@(?:@|\.|([*_])?([a-zA-Z])?(?:{((?:[^}]|}})*)})?)' +# Force color even if stdout is not a tty. +_force_color = False + + class match_to_ansi(object): def __init__(self, color=True): self.color = color @@ -162,7 +166,7 @@ def cwrite(string, stream=sys.stdout, color=None): then it will be set based on stream.isatty(). """ if color is None: - color = stream.isatty() + color = stream.isatty() or _force_color stream.write(colorize(string, color=color)) @@ -189,7 +193,7 @@ def write(self, string, **kwargs): if raw: color=True else: - color = self._stream.isatty() + color = self._stream.isatty() or _force_color raw_write(colorize(string, color=color)) def writelines(self, sequence, **kwargs): From 00351001863f22d61bda745e2be031e160b5f51f Mon Sep 17 00:00:00 2001 From: Todd Gamblin Date: Fri, 29 May 2015 17:20:08 -0700 Subject: [PATCH 3/5] SPACK-69: Add context manager to fork and log output in a with block. --- lib/spack/llnl/util/tty/log.py | 178 +++++++++++++++++++++++++++++++++ 1 file changed, 178 insertions(+) create mode 100644 lib/spack/llnl/util/tty/log.py diff --git a/lib/spack/llnl/util/tty/log.py b/lib/spack/llnl/util/tty/log.py new file mode 100644 index 0000000000..6ccd0e66d9 --- /dev/null +++ b/lib/spack/llnl/util/tty/log.py @@ -0,0 +1,178 @@ +############################################################################## +# Copyright (c) 2013-2015, Lawrence Livermore National Security, LLC. +# Produced at the Lawrence Livermore National Laboratory. +# +# This file is part of Spack. +# Written by Todd Gamblin, tgamblin@llnl.gov, All rights reserved. +# LLNL-CODE-647188 +# +# For details, see https://scalability-llnl.github.io/spack +# Please also see the LICENSE file for our notice and the LGPL. +# +# This program is free software; you can redistribute it and/or modify +# it under the terms of the GNU General Public License (as published by +# the Free Software Foundation) version 2.1 dated February 1999. +# +# This program is distributed in the hope that it will be useful, but +# WITHOUT ANY WARRANTY; without even the IMPLIED WARRANTY OF +# MERCHANTABILITY or FITNESS FOR A PARTICULAR PURPOSE. See the terms and +# conditions of the GNU General Public License for more details. +# +# You should have received a copy of the GNU Lesser General Public License +# along with this program; if not, write to the Free Software Foundation, +# Inc., 59 Temple Place, Suite 330, Boston, MA 02111-1307 USA +############################################################################## +"""Utility classes for logging the output of blocks of code. +""" +import sys +import os +import re +import select +import inspect +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') + +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 log_output(object): + """Redirects output and error of enclosed block to a file. + + Usage: + with log_output(open('logfile.txt', 'w')): + # do things ... output will be logged. + + or: + with log_output(open('logfile.txt', 'w'), echo=True): + # do things ... output will be logged + # and also printed to stdout. + + Closes the provided stream when done with the block. + If echo is True, also prints the output to stdout. + """ + def __init__(self, stream, echo=False, force_color=False, debug=False): + self.stream = stream + + # various output options + self.echo = echo + self.force_color = force_color + self.debug = debug + + def trace(self, frame, event, arg): + """Jumps to __exit__ on the child process.""" + raise _SkipWithBlock() + + + def __enter__(self): + """Redirect output from the with block to a file. + + This forks the with block as a separate process, with stdout + and stderr redirected back to the parent via a pipe. If + echo is set, also writes to standard out. + + """ + # remember these values for later. + self._force_color = color._force_color + self._debug = tty._debug + + read, write = os.pipe() + + self.pid = os.fork() + if self.pid: + # Parent: read from child, skip the with block. + os.close(write) + + read_file = os.fdopen(read, 'r', 0) + with self.stream as log_file: + while True: + rlist, w, x = select.select([read_file], [], []) + if not rlist: + break + + line = read_file.readline() + if not line: + break + + # Echo to stdout if requested. + if self.echo: + sys.stdout.write(line) + + # Stripped output to log file. + log_file.write(_strip(line)) + + read_file.flush() + read_file.close() + + # Set a trace function to skip the with block. + sys.settrace(lambda *args, **keys: None) + frame = inspect.currentframe(1) + frame.f_trace = self.trace + + else: + # Child: redirect output, execute the with block. + os.close(read) + + # 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()) + + if self.force_color: + color._force_color = True + + if self.debug: + tty._debug = True + + + def __exit__(self, exc_type, exception, traceback): + """Exits on child, handles skipping the with block on parent.""" + # Child should just exit here. + if self.pid == 0: + # Flush the log to disk. + sys.stdout.flush() + sys.stderr.flush() + + if exception: + # Restore stdout on the child if there's an exception, + # and let it be raised normally. + # + # This assumes that even if the exception is caught, + # the child will exit with a nonzero return code. If + # it doesn't, the child process will continue running. + # + # TODO: think about how this works outside install. + # TODO: ideally would propagate exception to parent... + os.dup2(self._stdout, sys.stdout.fileno()) + os.dup2(self._stderr, sys.stderr.fileno()) + + return False + + else: + # Die quietly if there was no exception. + os._exit(0) + + else: + # If the child exited badly, parent also should exit. + pid, returncode = os.waitpid(self.pid, 0) + if returncode != 0: + os._exit(1) + + # restore output options. + color._force_color = self._force_color + tty._debug = self._debug + + # Suppresses exception if it's our own. + return exc_type is _SkipWithBlock From 92c21d713458c011dc7adefb9b0b36cec83892ab Mon Sep 17 00:00:00 2001 From: Todd Gamblin Date: Fri, 29 May 2015 17:21:30 -0700 Subject: [PATCH 4/5] debug instead of info logging in llnl.util.filesystem --- lib/spack/llnl/util/filesystem.py | 4 ++-- 1 file changed, 2 insertions(+), 2 deletions(-) diff --git a/lib/spack/llnl/util/filesystem.py b/lib/spack/llnl/util/filesystem.py index 1fdd25f608..3b34e04740 100644 --- a/lib/spack/llnl/util/filesystem.py +++ b/lib/spack/llnl/util/filesystem.py @@ -152,7 +152,7 @@ def copy_mode(src, dest): def install(src, dest): """Manually install a file to a particular location.""" - tty.info("Installing %s to %s" % (src, dest)) + tty.debug("Installing %s to %s" % (src, dest)) shutil.copy(src, dest) set_install_permissions(dest) copy_mode(src, dest) @@ -160,7 +160,7 @@ def install(src, dest): def install_tree(src, dest, **kwargs): """Manually install a file to a particular location.""" - tty.info("Installing %s to %s" % (src, dest)) + tty.debug("Installing %s to %s" % (src, dest)) shutil.copytree(src, dest, **kwargs) for s, d in traverse_tree(src, dest, follow_nonexisting=False): From ea7b65e2f2fb866d83d34cc1f1b22f8e5a378d63 Mon Sep 17 00:00:00 2001 From: Todd Gamblin Date: Fri, 29 May 2015 17:22:33 -0700 Subject: [PATCH 5/5] SPACK-69: spack install now logs build output to install directory. - spack install suppresses build output by default. - use install -v to show build output on the console too - package.py uses log_output context to redirect output and log it to a file - filters color codes out of output written to file - optionally echos to the terminal - YAML directory layout knows about its build log. - can get path to install build log to from directory layout - Package.install now copies the build log to $prefix/.spack/build.out - Error message from failed install execution now includes build log location --- lib/spack/spack/cmd/install.py | 4 ++ lib/spack/spack/directory_layout.py | 7 ++- lib/spack/spack/error.py | 7 ++- lib/spack/spack/package.py | 91 ++++++++++++++++++----------- lib/spack/spack/util/executable.py | 89 +++++++++++++++++++++------- 5 files changed, 140 insertions(+), 58 deletions(-) diff --git a/lib/spack/spack/cmd/install.py b/lib/spack/spack/cmd/install.py index 820444a404..acb688a092 100644 --- a/lib/spack/spack/cmd/install.py +++ b/lib/spack/spack/cmd/install.py @@ -47,6 +47,9 @@ def setup_parser(subparser): subparser.add_argument( '-n', '--no-checksum', action='store_true', dest='no_checksum', help="Do not check packages against checksum") + subparser.add_argument( + '-v', '--verbose', action='store_true', dest='verbose', + help="Display verbose build output while installing.") subparser.add_argument( '--fake', action='store_true', dest='fake', help="Fake install. Just remove the prefix and touch a fake file in it.") @@ -73,4 +76,5 @@ def install(parser, args): keep_stage=args.keep_stage, ignore_deps=args.ignore_deps, make_jobs=args.jobs, + verbose=args.verbose, fake=args.fake) diff --git a/lib/spack/spack/directory_layout.py b/lib/spack/spack/directory_layout.py index fe02fff3b0..e61929d8fd 100644 --- a/lib/spack/spack/directory_layout.py +++ b/lib/spack/spack/directory_layout.py @@ -35,7 +35,6 @@ from llnl.util.lang import memoized from llnl.util.filesystem import join_path, mkdirp -import spack from spack.spec import Spec from spack.error import SpackError @@ -175,6 +174,7 @@ def __init__(self, root, **kwargs): self.spec_file_name = 'spec.yaml' self.extension_file_name = 'extensions.yaml' + self.build_log_name = 'build.out' # TODO: use config file. # Cache of already written/read extension maps. self._extension_maps = {} @@ -233,6 +233,11 @@ def metadata_path(self, spec): return join_path(self.path_for_spec(spec), self.metadata_dir) + def build_log_path(self, spec): + return join_path(self.path_for_spec(spec), self.metadata_dir, + self.build_log_name) + + def create_install_directory(self, spec): _check_concrete(spec) diff --git a/lib/spack/spack/error.py b/lib/spack/spack/error.py index e483ea613b..e8fa756682 100644 --- a/lib/spack/spack/error.py +++ b/lib/spack/spack/error.py @@ -30,7 +30,12 @@ class SpackError(Exception): def __init__(self, message, long_message=None): super(SpackError, self).__init__() self.message = message - self.long_message = long_message + self._long_message = long_message + + + @property + def long_message(self): + return self._long_message def __str__(self): diff --git a/lib/spack/spack/package.py b/lib/spack/spack/package.py index 691caa913d..5dd410d0e4 100644 --- a/lib/spack/spack/package.py +++ b/lib/spack/spack/package.py @@ -36,7 +36,7 @@ import os import re import time -import inspect +import itertools import subprocess import platform as py_platform import multiprocessing @@ -45,6 +45,7 @@ from StringIO import StringIO import llnl.util.tty as tty +from llnl.util.tty.log import log_output from llnl.util.link_tree import LinkTree from llnl.util.filesystem import * from llnl.util.lang import * @@ -55,12 +56,12 @@ import spack.mirror import spack.hooks import spack.directives -import spack.build_environment as build_env -import spack.url as url +import spack.build_environment +import spack.url +import spack.util.web import spack.fetch_strategy as fs from spack.version import * from spack.stage import Stage -from spack.util.web import get_pages from spack.util.compression import allowed_archive, extension from spack.util.executable import ProcessError @@ -427,8 +428,8 @@ def url_for_version(self, version): return version_urls[version] # If we have no idea, try to substitute the version. - return url.substitute_version(self.nearest_url(version), - self.url_version(version)) + return spack.url.substitute_version(self.nearest_url(version), + self.url_version(version)) @property @@ -711,20 +712,28 @@ def do_fake_install(self): mkdirp(self.prefix.man1) - def do_install(self, **kwargs): - """This class should call this version of the install method. - Package implementations should override install(). + def _build_logger(self, log_path): + """Create a context manager to log build output.""" + + + + def do_install(self, + keep_prefix=False, keep_stage=False, ignore_deps=False, + skip_patch=False, verbose=False, make_jobs=None, fake=False): + """Called by commands to install a package and its dependencies. + + Package implementations should override install() to describe + their build process. + + Args: + keep_prefix -- Keep install prefix on failure. By default, destroys it. + keep_stage -- Keep stage on successful build. By default, destroys it. + ignore_deps -- Do not install dependencies before installing this package. + fake -- Don't really build -- install fake stub files instead. + skip_patch -- Skip patch stage of build if True. + verbose -- Display verbose build output (by default, suppresses it) + make_jobs -- Number of make jobs to use for install. Default is ncpus. """ - # whether to keep the prefix on failure. Default is to destroy it. - keep_prefix = kwargs.get('keep_prefix', False) - keep_stage = kwargs.get('keep_stage', False) - ignore_deps = kwargs.get('ignore_deps', False) - fake_install = kwargs.get('fake', False) - skip_patch = kwargs.get('skip_patch', False) - - # Override builtin number of make jobs. - self.make_jobs = kwargs.get('make_jobs', None) - if not self.spec.concrete: raise ValueError("Can only install concrete packages.") @@ -735,10 +744,13 @@ def do_install(self, **kwargs): tty.msg("Installing %s" % self.name) if not ignore_deps: - self.do_install_dependencies(**kwargs) + self.do_install_dependencies( + keep_prefix=keep_prefix, keep_stage=keep_stage, ignore_deps=ignore_deps, + fake=fake, skip_patch=skip_patch, verbose=verbose, + make_jobs=make_jobs) start_time = time.time() - if not fake_install: + if not fake: if not skip_patch: self.do_patch() else: @@ -768,16 +780,26 @@ def real_work(): spack.hooks.pre_install(self) # Set up process's build environment before running install. - if fake_install: + if fake: self.do_fake_install() else: - # Subclasses implement install() to do the real work. + # Do the real install in the source directory. self.stage.chdir_to_source() - self.install(self.spec, self.prefix) + + # This redirects I/O to a build log (and optionally to the terminal) + log_path = join_path(os.getcwd(), 'spack-build.out') + log_file = open(log_path, 'w') + with log_output(log_file, verbose, sys.stdout.isatty(), True): + self.install(self.spec, self.prefix) # Ensure that something was actually installed. self._sanity_check_install() + # Move build log into install directory on success + if not fake: + log_install_path = spack.install_layout.build_log_path(self.spec) + install(log_path, log_install_path) + # On successful install, remove the stage. if not keep_stage: self.stage.destroy() @@ -792,6 +814,9 @@ def real_work(): print_pkg(self.prefix) except ProcessError, e: + # Annotate with location of build log. + e.build_log = log_path + # One of the processes returned an error code. # Suppress detailed stack trace here unless in debug mode if spack.debug: @@ -808,7 +833,7 @@ def real_work(): cleanup() raise - build_env.fork(self, real_work) + spack.build_environment.fork(self, real_work) # Once everything else is done, run post install hooks spack.hooks.post_install(self) @@ -868,9 +893,7 @@ def install(self, spec, prefix): raise InstallError("Package %s provides no install method!" % self.name) - def do_uninstall(self, **kwargs): - force = kwargs.get('force', False) - + def do_uninstall(self, force=False): if not self.installed: raise InstallError(str(self.spec) + " is not installed.") @@ -913,14 +936,13 @@ def _sanity_check_extension(self): raise ActivationError("%s does not extend %s!" % (self.name, self.extendee.name)) - def do_activate(self, **kwargs): + def do_activate(self, force=False): """Called on an etension to invoke the extendee's activate method. Commands should call this routine, and should not call activate() directly. """ self._sanity_check_extension() - force = kwargs.get('force', False) spack.install_layout.check_extension_conflict( self.extendee_spec, self.spec) @@ -930,7 +952,7 @@ def do_activate(self, **kwargs): for spec in self.spec.traverse(root=False): if spec.package.extends(self.extendee_spec): if not spec.package.activated: - spec.package.do_activate(**kwargs) + spec.package.do_activate(force=force) self.extendee_spec.package.activate(self, **self.extendee_args) @@ -1084,12 +1106,13 @@ def find_versions_of_archive(*archive_urls, **kwargs): if list_url: list_urls.add(list_url) for aurl in archive_urls: - list_urls.add(url.find_list_url(aurl)) + list_urls.add(spack.url.find_list_url(aurl)) # Grab some web pages to scrape. page_map = {} for lurl in list_urls: - page_map.update(get_pages(lurl, depth=list_depth)) + pages = spack.util.web.get_pages(lurl, depth=list_depth) + page_map.update(pages) # Scrape them for archive URLs regexes = [] @@ -1098,7 +1121,7 @@ def find_versions_of_archive(*archive_urls, **kwargs): # the version part of the URL. The capture group is converted # to a generic wildcard, so we can use this to extract things # on a page that look like archive URLs. - url_regex = url.wildcard_version(aurl) + url_regex = spack.url.wildcard_version(aurl) # We'll be a bit more liberal and just look for the archive # part, not the full path. diff --git a/lib/spack/spack/util/executable.py b/lib/spack/spack/util/executable.py index 81759d3053..6eede0f78e 100644 --- a/lib/spack/spack/util/executable.py +++ b/lib/spack/spack/util/executable.py @@ -143,27 +143,72 @@ def which(name, **kwargs): class ProcessError(spack.error.SpackError): - def __init__(self, msg, long_msg=None): - # Friendlier exception trace info for failed executables - long_msg = long_msg + "\n" if long_msg else "" - for f in inspect.stack(): - frame = f[0] - loc = frame.f_locals - if 'self' in loc: - obj = loc['self'] - if isinstance(obj, spack.Package): - long_msg += "---\n" - long_msg += "Context:\n" - long_msg += " %s:%d, in %s:\n" % ( - inspect.getfile(frame.f_code), - frame.f_lineno, - frame.f_code.co_name) + def __init__(self, msg, long_message=None): + # These are used for detailed debugging information for + # package builds. They're built up gradually as the exception + # propagates. + self.package_context = _get_package_context() + self.build_log = None - lines, start = inspect.getsourcelines(frame) - for i, line in enumerate(lines): - mark = ">> " if start + i == frame.f_lineno else " " - long_msg += " %s%-5d%s\n" % ( - mark, start + i, line.rstrip()) - break + super(ProcessError, self).__init__(msg, long_message) - super(ProcessError, self).__init__(msg, long_msg) + @property + def long_message(self): + msg = self._long_message + if msg: msg += "\n\n" + + if self.build_log: + msg += "See build log for details:\n" + msg += " %s" % self.build_log + + if self.package_context: + if msg: msg += "\n\n" + msg += '\n'.join(self.package_context) + + return msg + + +def _get_package_context(): + """Return some context for an error message when the build fails. + + This should be called within a ProcessError when the exception is + thrown. + + Args: + process_error -- A ProcessError raised during install() + + This function inspects the stack to find where we failed in the + package file, and it adds detailed context to the long_message + from there. + + """ + lines = [] + + # Walk up the stack + for f in inspect.stack(): + frame = f[0] + + # Find a frame with 'self' in the local variables. + if not 'self' in frame.f_locals: + continue + + # Look only at a frame in a subclass of spack.Package + obj = frame.f_locals['self'] + if type(obj) != spack.Package and isinstance(obj, spack.Package): + break + else: + # Didn't find anything + return lines + + # Build a message showing where in install we failed. + lines.append("%s:%d, in %s:" % ( + inspect.getfile(frame.f_code), + frame.f_lineno, + frame.f_code.co_name)) + + sourcelines, start = inspect.getsourcelines(frame) + for i, line in enumerate(sourcelines): + mark = ">> " if start + i == frame.f_lineno else " " + lines.append(" %s%-5d%s" % (mark, start + i, line.rstrip())) + + return lines