Skip to content

Show build log on build failure#5016

Merged
tgamblin merged 6 commits intodevelopfrom
features/show-build-log-on-build-failure
Aug 22, 2017
Merged

Show build log on build failure#5016
tgamblin merged 6 commits intodevelopfrom
features/show-build-log-on-build-failure

Conversation

@tgamblin
Copy link
Copy Markdown
Member

@tgamblin tgamblin commented Aug 7, 2017

Currently, if you get a build error in Spack, you get this:

$ spack install elfutils
==> Installing elfutils
==> Using cached archive: /Users/gamblin2/src/spack/var/spack/cache/elfutils/elfutils-0.163.tar.bz2
==> Staging archive: /Users/gamblin2/src/spack/var/spack/stage/elfutils-0.163-qyris2qgf3oq4fob5ss6hsfijy4crd6a/elfutils-0.163.tar.bz2
==> Created stage in /Users/gamblin2/src/spack/var/spack/stage/elfutils-0.163-qyris2qgf3oq4fob5ss6hsfijy4crd6a
==> No patches needed for elfutils
==> Building elfutils [AutotoolsPackage]
==> Executing phase : 'autoreconf'
==> Executing phase : 'configure'
==> Error: ProcessError: Command exited with status 1:
    '/Users/gamblin2/src/spack/var/spack/stage/elfutils-0.163-qyris2qgf3oq4fob5ss6hsfijy4crd6a/elfutils-0.163/configure' '--prefix=/Users/gamblin2/src/spack/opt/spack/darwin-sierra-x86_64/clang-7.0.2-apple/elfutils-0.163-qyris2qgf3oq4fob5ss6hsfijy4crd6a' '--enable-maintainer-mode'
/Users/gamblin2/src/spack/lib/spack/spack/build_systems/autotools.py:268, in configure:
     260      def configure(self, spec, prefix):
     261          """Runs configure with the arguments specified in
     262          :py:meth:`~.AutotoolsPackage.configure_args`
     263          and an appropriately set prefix.
     264          """
     265          options = ['--prefix={0}'.format(prefix)] + self.configure_args()
     266  
     267          with working_dir(self.build_directory, create=True):
  >> 268              inspect.getmodule(self).configure(*options)

See build log for details:
  /private/var/folders/0s/q_y0zhfj6xdd5n7rn780zz6h001qr7/T/pytest-of-gamblin2/pytest-194/test_keep_exceptions0/tmp/spack-stage/spack-stage-wLLSsa/elfutils-0.163/spack-build.out

Spack is trying to be helpful by showing Python context for the package, but usually you don't get a Python error. You get some type of build error, and you just want to look at the build log. Also, with our various build system classes, the Python context is often in a class the user knows nothing about (like the configure method in AutotoolsPackage shown here), and doesn't really tell you what the issue is.

This PR changes the behavior. If the error raised is a ProcessError from some script or tool invoked by the build process (e.g., make or configure), we'll show errors from the build log instead. If the error is some other error (e.g. one that actually comes from Python code) we'll show Python context. So, here's the new output:

$ spack install elfutils
==> Installing elfutils
==> Using cached archive: /Users/gamblin2/src/spack/var/spack/cache/elfutils/elfutils-0.163.tar.bz2
==> Already staged elfutils-0.163-qyris2qgf3oq4fob5ss6hsfijy4crd6a in /Users/gamblin2/src/spack/var/spack/stage/elfutils-0.163-qyris2qgf3oq4fob5ss6hsfijy4crd6a
==> No patches needed for elfutils
==> Building elfutils [AutotoolsPackage]
==> Executing phase : 'autoreconf'
==> Executing phase : 'configure'
==> Error: ProcessError: Command exited with status 1:
    '/Users/gamblin2/src/spack/var/spack/stage/elfutils-0.163-qyris2qgf3oq4fob5ss6hsfijy4crd6a/elfutils-0.163/configure' '--prefix=/Users/gamblin2/src/spack/opt/spack/darwin-sierra-x86_64/clang-7.0.2-apple/elfutils-0.163-qyris2qgf3oq4fob5ss6hsfijy4crd6a' '--enable-maintainer-mode'

2 errors in build log:
     [ ... ]
     12    checking build system type... x86_64-apple-darwin16.6.0
     13    checking host system type... x86_64-apple-darwin16.6.0
     14    checking for gcc... /Users/gamblin2/src/spack/lib/spack/env/clang/clang
     15    checking whether the C compiler works... yes
     16    checking for C compiler default output file name... a.out
     17    checking for suffix of executables...
  >> 18    checking whether we are cross compiling... configure: error: in `/private/var/folders/0s/q_y0zhfj6xdd5n7rn780zz6h001qr7/T/pytest-of-gamblin2/pytest-194/test_keep_exceptions0/tmp/spack-stage/spack-stage-wLLSsa/elfutils-0.163':
  >> 19    configure: error: cannot run C compiled programs.

See build log for details:
  /private/var/folders/0s/q_y0zhfj6xdd5n7rn780zz6h001qr7/T/pytest-of-gamblin2/pytest-194/test_keep_exceptions0/tmp/spack-stage/spack-stage-wLLSsa/elfutils-0.163/spack-build.out

Users now get a chunk of the build log with the error lines highlighted. If there are multiple errors, each will be shown with 6 lines of context before and after (with [...] in between the sections). If color is enabled, the errors are highlighted in red.

Hopefully this means people won't need to take the extra step of opening the build log in their editor to see what happened, even if they didn't use spack install -v.

Tasks:

  • Add some code to parse build logs for errors
  • Make install failures display the errors from the build log if the error came from the build and not from Python.
  • Add some color support so that the highlighted error lines for both Python and build errors are shown in red.
  • Tests

Copy link
Copy Markdown
Member

@becker33 becker33 left a comment

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

This looks good to me, approved pending testing.


log_events = []
for i, line in enumerate(lines):
if re.search('error', line, re.IGNORECASE):
Copy link
Copy Markdown
Member

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

I would highly recommend using error: instead of error. The latter will pick up hundreds of lines of the compiler linking to error-related modules.

Copy link
Copy Markdown
Member Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

I think this will evolve into lots of heuristics (like eventually getting warnings as well). I'll change it to error for now.

Copy link
Copy Markdown
Member

@alalazo alalazo left a comment

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

This will be a huge usability improvement. Probably we'll get neater bug report on failed builds as a side-effect. 👍 💯

context from the Python code.

SpackError handles displaying the special traceback if we're in debug
mode with spack -d.
Copy link
Copy Markdown
Member

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

👍

if self.build_log:
events = parse_log_events(self.build_log)
out.write("\n%d errors in build log:\n" % len(events))
out.write(make_log_context(events))
Copy link
Copy Markdown
Member

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Parsing all the errors and showing them is great!

logfile (str): name of the build log to parse
context (int): lines of context to extract around each log event

Currently looks for lines that contain the string 'error', ignoring case.
Copy link
Copy Markdown
Member

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

the string 'error:'

@tgamblin tgamblin force-pushed the features/show-build-log-on-build-failure branch 2 times, most recently from 08b80a6 to cb3c5ee Compare August 14, 2017 10:53
@tgamblin
Copy link
Copy Markdown
Member Author

Ok I think I've addressed all comments here -- I'm about to add tests but it needs a rework of I/O redirection. Currently I can't get the output I need to test this functionality. I'll push a new PR and rebase on it.

@tgamblin tgamblin mentioned this pull request Aug 14, 2017
8 tasks
@tgamblin tgamblin force-pushed the features/show-build-log-on-build-failure branch from cb3c5ee to f29f82d Compare August 22, 2017 21:40
@tgamblin tgamblin added tests General test capability(ies) and removed WIP labels Aug 22, 2017
- If a failure comes from an external command and NOT the Python code,
  display errors highlighted with some context.

- Add some rudimentary support for parsing errors out of the build log
  (not very sophisticated yet).

- Build errors in Python code will still display with Python context.
@tgamblin tgamblin force-pushed the features/show-build-log-on-build-failure branch from f29f82d to 0df994a Compare August 22, 2017 21:41
- install and probably other commands were designed to run once, but now
  we can to test them from within Spack with SpackCommand

- cmd/install.py assumed that it could modify do_install in PackageBase
  and leave it that way; this makes the decorator temporary

- package.py didn't properly initialize its stage if the same package had
  been built successfully before (and the stage removed).
  - manage stage lifecycle better and remember when Package needs to
    re-create the stage
- Update handling of ChildError so that its output is capturable from a
  SpackCommand

- Update cmd/install test to make sure Python and build log output is
  being displayed properly.
@tgamblin tgamblin merged commit 40e9171 into develop Aug 22, 2017
@adamjstewart adamjstewart deleted the features/show-build-log-on-build-failure branch August 23, 2017 01:46
@pramodskumbhar
Copy link
Copy Markdown
Contributor

@tgamblin : I am trying this with latest develop and bit confused about how this works. I don't see error/log message :

$ spack install zlib  %[email protected]
==> Installing zlib
==> Using cached archive: /gpfs/bbp.cscs.ch/scratch/gss/bgq/kumbhar-adm/SPACK_HOME/var/spack/cache/zlib/zlib-1.2.11.tar.gz
==> Already staged zlib-1.2.11-d2efq5vvsjlod3a2rpjnuhcohq65prax in /gpfs/bbp.cscs.ch/home/kumbhar-adm/SPACK_HOME/spack/var/spack/stage/zlib-1.2.11-d2efq5vvsjlod3a2rpjnuhcohq65prax
==> No patches needed for zlib
==> Building zlib [Package]
==> Executing phase: 'install'
==> Error: ProcessError: Command exited with status 1:
    './configure' '--prefix=/gpfs/bbp.cscs.ch/scratch/gss/bgq/kumbhar-adm/SPACK_HOME/install_home/bbpviz_full/install/linux-rhel6-x86_64/gcc-4.9.0/zlib-1.2.11-d2efq5vv'
See build log for details:
  /tmp/kumbhar-adm/spack-stage/spack-stage-9cSA1o/zlib-1.2.11/spack-build.out

I thought with this PR we will get behaviour of using -v (in case of failure):

$ spack install -v zlib  %[email protected]
==> Installing zlib
==> Using cached archive: /gpfs/bbp.cscs.ch/scratch/gss/bgq/kumbhar-adm/SPACK_HOME/var/spack/cache/zlib/zlib-1.2.11.tar.gz
==> Already staged zlib-1.2.11-d2efq5vvsjlod3a2rpjnuhcohq65prax in /gpfs/bbp.cscs.ch/home/kumbhar-adm/SPACK_HOME/spack/var/spack/stage/zlib-1.2.11-d2efq5vvsjlod3a2rpjnuhcohq65prax
==> No patches needed for zlib
==> Building zlib [Package]
==> Executing phase: 'install'
==> './configure' '--prefix=/gpfs/bbp.cscs.ch/scratch/gss/bgq/kumbhar-adm/SPACK_HOME/install_home/bbpviz_full/install/linux-rhel6-x86_64/gcc-4.9.0/zlib-1.2.11-d2efq5vv'
Compiler error reporting is too harsh for ./configure (perhaps remove -Werror).
** ./configure aborting.
==> Error: ProcessError: Command exited with status 1:
    './configure' '--prefix=/gpfs/bbp.cscs.ch/scratch/gss/bgq/kumbhar-adm/SPACK_HOME/install_home/bbpviz_full/install/linux-rhel6-x86_64/gcc-4.9.0/zlib-1.2.11-d2efq5vv'
See build log for details:

This is useful for for travis builds where we can't use -v for everything due to output log limit of 4MB.

@adamjstewart
Copy link
Copy Markdown
Member

I thought with this PR we will get behaviour of using -v (in case of failure):

Nope. Depending on the build, this would result in thousands of lines of useless output. The goal of this PR is to grep the build log for things like error:, so that the only things that display are useful error messages. You can always view the build log for more details.

This is useful for for travis builds where we can't use -v for everything due to output log limit of 4MB.

Hmm. Could you do something like:

$ spack install zlib || cat $BUILD_LOG

That would give you the behavior you desire. I just don't know where to get $BUILD_LOG from...

@pramodskumbhar
Copy link
Copy Markdown
Contributor

thanks for clarification!

The goal of this PR is to grep the build log for things like error:, so that the only things that display are useful error messages.

Hmm...typically I look at last X lines of stack-build.out.

Could you do something like: $ spack install zlib || cat $BUILD_LOG

yes, currently my travis config has something like:

            # install package
            echo " == > INSTALLING PACKAGE : spack install $install_options $full_spec"
            spack install $install_options $full_spec

            # if there is no matching package then show build log
            if [[ `spack find $full_spec` == *"No package matches"* ]]; then
                echo "Package installation check failed for $full_spec, Install log :"
                cat `spack location $full_spec`/spack-build.out
                exit 1
            fi

and I thought I don't need this anymore.

@tgamblin
Copy link
Copy Markdown
Member Author

@pramodskumbhar: are there errors this isn't catching? If so you could add them to the filter so they're printed out without -v. Note that it's not just the lines but also context and line numbers that are printed by his command.

Also, once the test-suite PR is done, that command will be able to upload full logs to cdash with errors highlighted, and install will be able to spit out a cdash log as well. So you could potentially use those from travis and view logs externally.

@pramodskumbhar
Copy link
Copy Markdown
Contributor

are there errors this isn't catching?

Simple test I am trying to use with compilers that require dirty. For example, if I try installing zlib as:

→ spack install zlib %gcc
==> Installing zlib
==> Using cached archive: /some-path/spack/var/spack/cache/zlib/zlib-1.2.11.tar.gz
==> Staging archive: /some-path/spack/var/spack/stage/zlib-1.2.11-d2efq5vvsjlod3a2rpjnuhcohq65prax/zlib-1.2.11.tar.gz
==> Created stage in /some-path/spack/var/spack/stage/zlib-1.2.11-d2efq5vvsjlod3a2rpjnuhcohq65prax
==> Building zlib [Package]
==> Executing phase: 'install'
==> Error: ProcessError: Command exited with status 1:
    './configure' '--prefix=/gpfs/bbp.cscs.ch/scratch/gss/viz/kumbhar/neuron_music_home/install/linux-rhel6-x86_64/gcc-4.9.0/zlib-1.2.11-d2efq5'
See build log for details:
  /some-path/spack/var/spack/stage/zlib-1.2.11-d2efq5vvsjlod3a2rpjnuhcohq65prax/zlib-1.2.11/spack-build.out

But actual error is:

$tail /some-path/zlib-1.2.11/configure.log
...
/some-path/spack/lib/spack/env/gcc/gcc -c -fPIC ztest961.c
/gpfs/bbp.cscs.ch/apps/viz/tools/gcc/gcc-4.9.0/install/bin/../libexec/gcc/x86_64-unknown-linux-gnu/4.9.0/cc1: error while loading shared libraries: libmpc.so.3: cannot open shared object file: No such file or directory
(exit code 1)
Compiler error reporting is too harsh for ./configure (perhaps remove -Werror).
** ./configure aborting.
--------------------

So my expectation was to capture error while loading shared libraries: libmpc.so.

I have related question: In our internal jenkins/travis plans we would like to cat spack-build.out on failure and abort. I am using:

cat `spack location $spec`/spack-build.out

But if the dependency is failed then this doesn't work. So I would like to know how to get the path of spack-build.out of last package that was being built. I can redirect everything to file but then we loose progress information.

@adamjstewart
Copy link
Copy Markdown
Member

my expectation was to capture error while loading shared libraries: libmpc.so.

Currently, our regex only looks for error: with a colon after it. We were afraid that error would be too generic, as many libraries come with files containing the word error in the name. We could make the regex less strict, but I think we would see a lot more false positives than we would lose false negatives.

@alalazo
Copy link
Copy Markdown
Member

alalazo commented Sep 17, 2017

@adamjstewart True, but if we also look for : error we'll catch this and won't incur in a lot of false positives, right?

@tgamblin
Copy link
Copy Markdown
Member Author

I'm tempted to look at what ctest does in the next couple weeks. I want this for cdash error output anyway. Ctest has some magic heuristics it uses and I'm sure they're better tested than what we could come up with.

But for @pramodskumbhar right now, we could just add an option to install that dumps the log on error. Seems less cumbersome than the shell scripting alternative, and it's easy enough to do... thoughts?

@pramodskumbhar
Copy link
Copy Markdown
Contributor

pramodskumbhar commented Sep 17, 2017

we could just add an option to install that dumps the log on error. Seems less cumbersome than the shell scripting alternative

this is my / our developers expectation for nightly travis/jenkins builds of different software components.

@tgamblin tgamblin added this to the v0.11.0 milestone Nov 12, 2017
@tgamblin tgamblin mentioned this pull request Jan 28, 2018
4 tasks
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment

Labels

Projects

None yet

Development

Successfully merging this pull request may close these issues.

5 participants