diff --git a/lib/spack/spack/cmd/install.py b/lib/spack/spack/cmd/install.py index 1028bbb7daa2403871a1cc21eddd3332a3a009dd..af6f96d4e5371241f29b010ee15959382c563482 100644 --- a/lib/spack/spack/cmd/install.py +++ b/lib/spack/spack/cmd/install.py @@ -263,7 +263,7 @@ def install(parser, args, **kwargs): tty.warn("Deprecated option: --run-tests: use --test=all instead") # 1. Abstract specs from cli - reporter = spack.report.collect_info(args.log_format, args) + reporter = spack.report.collect_info('do_install', args.log_format, args) if args.log_file: reporter.filename = args.log_file diff --git a/lib/spack/spack/cmd/test.py b/lib/spack/spack/cmd/test.py index 759cbb000a5b0344c2855a67e14c35dc0b853838..d74571a141a766182bd232f2da95e81644b9734f 100644 --- a/lib/spack/spack/cmd/test.py +++ b/lib/spack/spack/cmd/test.py @@ -80,7 +80,7 @@ def test(parser, args): # Set up reporter setattr(args, 'package', [s.format() for s in specs_to_test]) - reporter = spack.report.collect_info(args.log_format, args) + reporter = spack.report.collect_info('do_test', args.log_format, args) if not reporter.filename: if args.log_file: if os.path.isabs(args.log_file): @@ -94,7 +94,7 @@ def test(parser, args): reporter.filename = log_file reporter.specs = specs_to_test - with reporter: + with reporter('test'): if args.smoke_test: for spec in specs_to_test: spec.package.do_test() diff --git a/lib/spack/spack/package.py b/lib/spack/spack/package.py index b04b41942152d54ff6e3d30337a014fb58e0ba61..6956ecd3e52207dcfd4afc7524589d24390a24b4 100644 --- a/lib/spack/spack/package.py +++ b/lib/spack/spack/package.py @@ -1576,17 +1576,25 @@ def do_install(self, **kwargs): do_install.__doc__ += install_args_docstring + @property + def test_log_name(self): + return 'test-%s' % self.spec.format('{name}-{hash:7}') + def do_test(self, dirty=False): def test_process(): - test_log_file = os.path.join( - os.getcwd(), 'test-%s' % self.spec.format('{name}-{hash:7}')) + test_log_file = os.path.join(os.getcwd(), self.test_log_name) with log_output(test_log_file) as logger: with logger.force_echo(): tty.msg('Testing package %s' % self.spec.format('{name}-{hash:7}')) old_debug = tty.is_debug() tty.set_debug(True) - self.test() + try: + self.test() + except Exception as e: + type, context, traceback = sys.exc_info() + print('Error: %s: %s' % (type, e.message)) + raise e, None, traceback tty.set_debug(old_debug) try: diff --git a/lib/spack/spack/report.py b/lib/spack/spack/report.py index e500f9fc05732450c02bc38fd347976192497e9f..bf19304301c2c0f32ea049e4bf1a9a8a7d474a24 100644 --- a/lib/spack/spack/report.py +++ b/lib/spack/spack/report.py @@ -9,6 +9,7 @@ import functools import time import traceback +import os import llnl.util.lang import spack.build_environment @@ -33,12 +34,16 @@ ] -def fetch_package_log(pkg): +def fetch_package_log_by_type(pkg, do_fn): + log_files = { + 'do_install': pkg.build_log_path, + 'do_test': os.path.join(os.getcwd(), pkg.test_log_name), + } try: - with codecs.open(pkg.build_log_path, 'r', 'utf-8') as f: + with codecs.open(log_files[do_fn.__name__], 'r', 'utf-8') as f: return ''.join(f.readlines()) except Exception: - return 'Cannot open build log for {0}'.format( + return 'Cannot open log for {0}'.format( pkg.spec.cshort_spec ) @@ -58,11 +63,14 @@ class InfoCollector(object): specs (list of Spec): specs whose install information will be recorded """ - #: Backup of PackageInstaller._install_task - _backup__install_task = spack.package.PackageInstaller._install_task - - def __init__(self, specs): - #: Specs that will be installed + def __init__(self, wrap_class, do_fn, specs): + #: Class for which to wrap a function + self.wrap_class = wrap_class + #: Action to be reported on + self.do_fn = do_fn + #: Backup of PackageBase function + self._backup_do_fn = getattr(self.wrap_class, do_fn) + #: Specs that will be acted on self.input_specs = specs #: This is where we record the data that will be included #: in our report. @@ -98,27 +106,34 @@ def __enter__(self): Property('compiler', input_spec.compiler)) # Check which specs are already installed and mark them as skipped - for dep in filter(lambda x: x.package.installed, - input_spec.traverse()): - package = { - 'name': dep.name, - 'id': dep.dag_hash(), - 'elapsed_time': '0.0', - 'result': 'skipped', - 'message': 'Spec already installed' - } - spec['packages'].append(package) - - def gather_info(_install_task): - """Decorates PackageInstaller._install_task to gather useful - information on PackageBase.do_install for a CI report. + # only for install_task + if self.do_fn == '_install_task': + for dep in filter(lambda x: x.package.installed, + input_spec.traverse()): + package = { + 'name': dep.name, + 'id': dep.dag_hash(), + 'elapsed_time': '0.0', + 'result': 'skipped', + 'message': 'Spec already installed' + } + spec['packages'].append(package) + + def gather_info(do_fn): + """Decorates do_fn to gather useful information for + a CI report. It's defined here to capture the environment and build this context as the installations proceed. """ - @functools.wraps(_install_task) - def wrapper(installer, task, *args, **kwargs): - pkg = task.pkg + @functools.wraps(do_fn) + def wrapper(instance, *args, **kwargs): + if isinstance(instance, PackageBase): + pkg = instance + elif hasattr(args[0], 'pkg'): + pkg = args[0].pkg + else: + raise Exception # We accounted before for what is already installed installed_on_entry = pkg.installed @@ -135,13 +150,12 @@ def wrapper(installer, task, *args, **kwargs): start_time = time.time() value = None try: - - value = _install_task(installer, task, *args, **kwargs) + value = _install_task(instance, *args, **kwargs) package['result'] = 'success' - package['stdout'] = fetch_package_log(pkg) + package['stdout'] = fetch_package_log_by_type(pkg, do_fn) package['installed_from_binary_cache'] = \ pkg.installed_from_binary_cache - if installed_on_entry: + if do_fn.__name__ == 'do_install' and installed_on_entry: return except spack.build_environment.InstallError as e: @@ -149,7 +163,7 @@ def wrapper(installer, task, *args, **kwargs): # didn't work correctly) package['result'] = 'failure' package['message'] = e.message or 'Installation failure' - package['stdout'] = fetch_package_log(pkg) + package['stdout'] = fetch_package_log_by_type(pkg, do_fn) package['stdout'] += package['message'] package['exception'] = e.traceback @@ -157,7 +171,7 @@ def wrapper(installer, task, *args, **kwargs): # Everything else is an error (the installation # failed outside of the child process) package['result'] = 'error' - package['stdout'] = fetch_package_log(pkg) + package['stdout'] = fetch_package_log_by_type(pkg, do_fn) package['message'] = str(e) or 'Unknown error' package['exception'] = traceback.format_exc() @@ -184,15 +198,14 @@ def wrapper(installer, task, *args, **kwargs): return wrapper - spack.package.PackageInstaller._install_task = gather_info( - spack.package.PackageInstaller._install_task - ) + setattr(self.wrap_class, self.do_fn, gather_info( + getattr(self.wrap_class, self.do_fn) + )) def __exit__(self, exc_type, exc_val, exc_tb): - # Restore the original method in PackageInstaller - spack.package.PackageInstaller._install_task = \ - InfoCollector._backup__install_task + # Restore the original method in PackageBase + setattr(self.wrap_class, self.do_fn, self._backup_do_fn) for spec in self.specs: spec['npackages'] = len(spec['packages']) @@ -240,7 +253,8 @@ class collect_info(object): Raises: ValueError: when ``format_name`` is not in ``valid_formats`` """ - def __init__(self, format_name, args): + def __init__(self, function, format_name, args): + self.function = function self.filename = None if args.cdash_upload_url: self.format_name = 'cdash' @@ -253,13 +267,17 @@ def __init__(self, format_name, args): .format(self.format_name)) self.report_writer = report_writers[self.format_name](args) + def __call__(self, type): + self.type = type + return self + def concretization_report(self, msg): self.report_writer.concretization_report(self.filename, msg) def __enter__(self): if self.format_name: # Start the collector and patch PackageInstaller._install_task - self.collector = InfoCollector(self.specs) + self.collector = InfoCollector(self.function, self.specs) self.collector.__enter__() def __exit__(self, exc_type, exc_val, exc_tb): @@ -269,4 +287,5 @@ def __exit__(self, exc_type, exc_val, exc_tb): self.collector.__exit__(exc_type, exc_val, exc_tb) report_data = {'specs': self.collector.specs} - self.report_writer.build_report(self.filename, report_data) + report_fn = getattr(self.report_writer, '%s_report' % self.type) + report_fn(self.filename, report_data) diff --git a/lib/spack/spack/reporter.py b/lib/spack/spack/reporter.py index 25d4042a5e54dcbbce3f8231cb93e33fe9cba68a..6314054139987af896cc031a3bd3d51c155ca283 100644 --- a/lib/spack/spack/reporter.py +++ b/lib/spack/spack/reporter.py @@ -16,5 +16,8 @@ def __init__(self, args): def build_report(self, filename, report_data): pass + def test_report(self, filename, report_data): + pass + def concretization_report(self, filename, msg): pass diff --git a/lib/spack/spack/reporters/cdash.py b/lib/spack/spack/reporters/cdash.py index 580df7866fafd8832007f7a5fb2fc7394e1c7901..cf4aadf333eb21e4d79f72270b52291ab199c827 100644 --- a/lib/spack/spack/reporters/cdash.py +++ b/lib/spack/spack/reporters/cdash.py @@ -98,7 +98,7 @@ def __init__(self, args): self.revision = git('rev-parse', 'HEAD', output=str).strip() self.multiple_packages = False - def report_for_package(self, directory_name, package, duration): + def build_report_for_package(self, directory_name, package, duration): if 'stdout' not in package: # Skip reporting on packages that did not generate any output. return @@ -250,7 +250,114 @@ def build_report(self, directory_name, input_data): if 'time' in spec: duration = int(spec['time']) for package in spec['packages']: - self.report_for_package(directory_name, package, duration) + self.build_report_for_package( + directory_name, package, duration) + self.print_cdash_link() + + def test_report_for_package(self, directory_name, package, duration): + if 'stdout' not in package: + # Skip reporting on packages that did not generate any output. + return + + self.current_package_name = package['name'] + self.buildname = "{0} - {1}".format( + self.base_buildname, package['name']) + report_data = self.initialize_report(directory_name) + + for phase in ('test', 'update'): + report_data[phase] = {} + report_data[phase]['loglines'] = [] + report_data[phase]['status'] = 0 + report_data[phase]['endtime'] = self.endtime + + # Track the phases we perform so we know what reports to create. + # We always report the update step because this is how we tell CDash + # what revision of Spack we are using. + phases_encountered = ['test', 'update'] + + # Generate a report for this package. + # The first line just says "Testing package name-hash" + report_data['test']['loglines'].append( + text_type("{0} output for {1}:".format( + 'test', package['name']))) + for line in package['stdout'].splitlines()[1:]: + report_data['test']['loglines'].append( + xml.sax.saxutils.escape(line)) + + self.starttime = self.endtime - duration + for phase in phases_encountered: + report_data[phase]['starttime'] = self.starttime + report_data[phase]['log'] = \ + '\n'.join(report_data[phase]['loglines']) + errors, warnings = parse_log_events(report_data[phase]['loglines']) + # Cap the number of errors and warnings at 50 each. + errors = errors[0:49] + warnings = warnings[0:49] + nerrors = len(errors) + + if phase == 'test': + # Convert log output from ASCII to Unicode and escape for XML. + def clean_log_event(event): + event = vars(event) + event['text'] = xml.sax.saxutils.escape(event['text']) + event['pre_context'] = xml.sax.saxutils.escape( + '\n'.join(event['pre_context'])) + event['post_context'] = xml.sax.saxutils.escape( + '\n'.join(event['post_context'])) + # source_file and source_line_no are either strings or + # the tuple (None,). Distinguish between these two cases. + if event['source_file'][0] is None: + event['source_file'] = '' + event['source_line_no'] = '' + else: + event['source_file'] = xml.sax.saxutils.escape( + event['source_file']) + return event + + # Convert errors to warnings if the package reported success. + if package['result'] == 'success': + warnings = errors + warnings + errors = [] + + report_data[phase]['errors'] = [] + report_data[phase]['warnings'] = [] + for error in errors: + report_data[phase]['errors'].append(clean_log_event(error)) + for warning in warnings: + report_data[phase]['warnings'].append( + clean_log_event(warning)) + + if phase == 'update': + report_data[phase]['revision'] = self.revision + + # Write the report. + report_name = phase.capitalize() + ".xml" + report_file_name = package['name'] + "_" + report_name + phase_report = os.path.join(directory_name, report_file_name) + + with codecs.open(phase_report, 'w', 'utf-8') as f: + env = spack.tengine.make_environment() + if phase != 'update': + # Update.xml stores site information differently + # than the rest of the CTest XML files. + site_template = os.path.join(self.template_dir, 'Site.xml') + t = env.get_template(site_template) + f.write(t.render(report_data)) + + phase_template = os.path.join(self.template_dir, report_name) + t = env.get_template(phase_template) + f.write(t.render(report_data)) + self.upload(phase_report) + + def test_report(self, directory_name, input_data): + # Generate reports for each package in each spec. + for spec in input_data['specs']: + duration = 0 + if 'time' in spec: + duration = int(spec['time']) + for package in spec['packages']: + self.test_report_for_package( + directory_name, package, duration) self.print_cdash_link() def concretization_report(self, directory_name, msg): diff --git a/share/spack/templates/reports/cdash/Test.xml b/share/spack/templates/reports/cdash/Test.xml new file mode 100644 index 0000000000000000000000000000000000000000..6aeed4e263ae715978ad7674c38f0d81dd29c3b8 --- /dev/null +++ b/share/spack/templates/reports/cdash/Test.xml @@ -0,0 +1,27 @@ + <Test> + <StartTestTime>{{ test.starttime }}</StartTestTime> + <TestCommand>{{ install_command }}</TestCommand> +{% for warning in test.warnings %} + <Warning> + <TestLogLine>{{ warning.line_no }}</TestLogLine> + <Text>{{ warning.text }}</Text> + <SourceFile>{{ warning.source_file }}</SourceFile> + <SourceLineNumber>{{ warning.source_line_no }}</SourceLineNumber> + <PreContext>{{ warning.pre_context }}</PreContext> + <PostContext>{{ warning.post_context }}</PostContext> + </Warning> +{% endfor %} +{% for error in test.errors %} + <Error> + <TestLogLine>{{ error.line_no }}</TestLogLine> + <Text>{{ error.text }}</Text> + <SourceFile>{{ error.source_file }}</SourceFile> + <SourceLineNumber>{{ error.source_line_no }}</SourceLineNumber> + <PreContext>{{ error.pre_context }}</PreContext> + <PostContext>{{ error.post_context }}</PostContext> + </Error> +{% endfor %} + <EndTestTime>{{ test.endtime }}</EndTestTime> + <ElapsedMinutes>0</ElapsedMinutes> + </Test> +</Site>