Troubleshooting

Sometimes builds don’t go as planned or something crashes. We need to find the root cause.

The first decision point - where the problem? Is it:

1. In a specific build step (eg syntax error in a Python file that is being built?)
2. In the build script (eg a build step being called when it shouldn’t)
3. Within the toolchain, eg Dovetail?

But, before we examine the different error categories, how do you know your build completed successfully?

A successful build will produce a report on the console something like:

===============================================================================
2012-07-17 14:44:39

  Task 'build:test' SUCCESS, returning None

  Environment:
    Hostname:    macbook.example.com
    Username:    builder
    Python:      /Users/builder/dovetailenv/bin/python
    Working dir: /Users/builder/dovetail
    Build file:  build.py
    Tasks:       100
    Elapsed:     63.421s

===============================================================================

This message reports:

• When the build completed

• The task build:test (i.e. function test() in build.py) ran successfully, and its result

• The environment

  • User that ran the build
  • The hostname of the computer
  • Which Python was used. This is often is a virtual environment
  • Working directory of the build
  • The build script’s filename

• How many tasks were executed

• How long it took

Build script syntax error

If the build file won’t load and complains of a syntax error, the problem is with the script. Dovetail does not add to or change Python syntax in any way.

The only gotcha is that Dovetail build files cannot be placed in a package directory - a directory with a file named __init__.py. Dovetail build files can import other packages that are on the site package path.

Task failed due to a declaration

In a good script, the build script author will validate that individual steps have completed successfully. If there is an error, the build should fail immediately reporting the issue.

To support this, Dovetail has several declarations, described in Deliberately failing the build, to catch errors in the build, and direct the build to fail:

• @check_result: If the value returned from a function is non-zero (as per Unix command-line convention)
• @fail_if(): Evaluates a predicate to determine if the task should be failed
• @fail_if_skipped: Automatically failed if this task is skipped

If Dovetail is told to fail a build due to one of these declarations, it is reported to the command-line in the build report. For example, if the task was declared:

@task
@check_result
@fail_if(StdErr())
def warranty():
    ...

And it wrote to stderr, the report would look like:

===============================================================================
2012-07-17 15:20:01

  Task 'build:test' FAILED
    In file:  /Users/builder/dovetail/test/command_line/build.py
    Task:     warranty
    Message:  FailIf: FAILING test.command_line.build:warranty because Task wrote to sys.stderr

  Environment:
    Hostname:    macbook.example.com
    Username:    builder
    Python:      /Users/builder/crashtest/bin/python
    Working dir: /Users/builder/dovetail
    Build file:  build.py
    Tasks:       71
    Elapsed:     0.735s

===============================================================================

Exception thrown within a task

This is a condition where the implementation of a task fails - this is almost always a problem with the build implementation, rather than with Dovetail.

Below is an example of the end of the console output when there is an exception or assertion thrown in one step of the build:

...

STARTING Task test.command_line.build:warranty
vvvvvvvvvvvvvvvvvvvvvvvvvvvvvv
^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
Traceback (most recent call last):
  File "/Users/builder/crashtest/lib/python2.7/site-packages/Dovetail-1.0beta-py2.7.egg/dovetail/engine.py", line 688, in execute
    result = task.get_function()()
  File "/Users/builder/crashtest/lib/python2.7/site-packages/Dovetail-1.0beta-py2.7.egg/dovetail/directives/core.py", line 64, in wrapped
    return f(*kw, **kwargs)
  File "/Users/builder/dovetail/test/command_line/build.py", line 58, in warranty
    assert "Disclaimer of Warranty." == lines[0].strip()
AssertionError

FAILED: Task test.command_line.build:warranty raised AssertionError:
ABORTED: Task test.command_line.build:information_options raised AssertionError:
ABORTED: Task test.command_line.build:test raised AssertionError:
ABORTED: Task test.build:test raised AssertionError:
ABORTED: Task build:test raised AssertionError:

===============================================================================
2012-07-17 14:30:30

  Task 'build:test' FAILED
    In file:  /Users/builder/dovetail/test/command_line/build.py
    Task:     warranty
    Message:  AssertionError:

  Environment:
    Hostname:    macbook.example.com
    Username:    builder
    Python:      /Users/builder/crashtest/bin/python
    Working dir: /Users/builder/dovetail
    Build file:  build.py
    Tasks:       71
    Elapsed:     0.717s

===============================================================================
Traceback (most recent call last):
  File "/Users/builder/crashtest/lib/python2.7/site-packages/Dovetail-1.0beta-py2.7.egg/dovetail/engine.py", line 688, in execute
    result = task.get_function()()
  File "/Users/builder/crashtest/lib/python2.7/site-packages/Dovetail-1.0beta-py2.7.egg/dovetail/directives/core.py", line 64, in wrapped
    return f(*kw, **kwargs)
  File "/Users/builder/dovetail/test/command_line/build.py", line 58, in warranty
    assert "Disclaimer of Warranty." == lines[0].strip()
AssertionError

Look for the report block (between the horizontal lines). This reports in detail where the problem first occurred:

===============================================================================
2012-07-17 14:30:30

  Task 'build:test' FAILED
    In file:  /Users/builder/dovetail/test/command_line/build.py
    Task:     warranty
    Message:  AssertionError:

The report block tells us there was an AssertionError in the task warranty in the build file /Users/ ... /command_line/build.py.

Just above this, Dovetail has printed the Python stack trace of the exception:

Traceback (most recent call last):
  File "/Users/builder/crashtest/lib/python2.7/site-packages/Dovetail-1.0beta-py2.7.egg/dovetail/engine.py", line 688, in execute
    result = task.get_function()()
  File "/Users/builder/crashtest/lib/python2.7/site-packages/Dovetail-1.0beta-py2.7.egg/dovetail/directives/core.py", line 64, in wrapped
    return f(*kw, **kwargs)
  File "/Users/builder/dovetail/test/command_line/build.py", line 58, in warranty
    assert "Disclaimer of Warranty." == lines[0].strip()
AssertionError

There is also a report of how the task was invoked which is useful for more deeply nested builds:

FAILED: Task test.command_line.build:warranty raised AssertionError:
ABORTED: Task test.command_line.build:information_options raised AssertionError:
ABORTED: Task test.command_line.build:test raised AssertionError:
ABORTED: Task test.build:test raised AssertionError:
ABORTED: Task build:test raised AssertionError:

Working from the last line upwards, you can trace the call from the command line:

Fully qualified name	Function	File
build:test	test()	build.py
test.build:test	test()	test/build.py
test.command_line.build:test	test()	test/command_line/build.py
test.command_line.build:information_options	information_options()	test/command_line/build.py
test.command_line.build:warranty	warranty()	test/command_line/build.py

After the warranty task FAILED, the exception is propagated upwards. Note that the parent tasks are marked ABORTED rather than FAILED. This help distinguish the task that actually failed from those that were the victim of failure.

Maybe this is enough to resolve the problem - in this case we can identify that the warranty contains the wrong text. We can fix that and the build works again.

But that step should not have been called?

First a quick recap. Tasks are invoked by Dovetail because:

• They were explicitly invoked from the command line
• An invoked task @depends on another task (see Task dependencies and Task names)
• A build file loads another build file, and contains a task with the same name (see Automatic dependencies)
• It is invoked by another task using the build() API

When a task is invoked, it can be skipped if:

• @skip_if is True, or
• @do_if is False

For example:

@task
@do_if(Env(DOVETAIL_SYSTEM='Windows'))
def windows():
    print "Only called on Windows"

Sometimes we might have failed because a build step did (or did not) get called. How can we quickly see what tasks are called? And how can we see why Dovetail skipped some tasks and not others?

Rerun the build with the “-r tree” option to generate the tree report. Dovetail will add an ASCII tree similar to the one below at the end of the console log, before the build report. In the example below we see both several SKIPPED tasks as well as a task that FAILED:

================================================================================
REPORTS

--------------------------------------------------------------------------------
Task structure and results
  +-. ABORTED: Task build:test raised AssertionError:
    | Elapsed: 0.720s, internal: 0.000
    |
    +-. SUCCEEDED: Task build:develop
    | | Elapsed: 0.255s, internal: 0.000
    | |
    | +-- SUCCEEDED: Task src.build:develop returned 0
    |     Elapsed: 0.255s, internal: 0.255
    |
    +-. ABORTED: Task test.build:test raised AssertionError:
      | Elapsed: 0.465s, internal: 0.001
      |
      +-. SUCCEEDED: Task test.conditional_platform.build:test
      | | Elapsed: 0.001s, internal: 0.001
      | |
      | +-- SUCCEEDED: Task test.conditional_platform.build:macosx
      | |   Elapsed: 0.000s, internal: 0.000
      | |
      | +-- SKIPPED: Task test.conditional_platform.build:windows because '$DOVETAIL_SYSTEM="Windows"' is False
      | |   Elapsed: 0.000s, internal: 0.000
      | |
      | +-- SKIPPED: Task test.conditional_platform.build:linux because '$DOVETAIL_SYSTEM="Linux"' is False
      | |   Elapsed: 0.000s, internal: 0.000
      | |
      | +-- SUCCEEDED: Task test.conditional_platform.build:not_windows_java
      |     Elapsed: 0.000s, internal: 0.000
      |
      +-. ABORTED: Task test.command_line.build:test raised AssertionError:
        | Elapsed: 0.420s, internal: 0.000
        |
        +-. ABORTED: Task test.command_line.build:information_options raised AssertionError:
          | Elapsed: 0.420s, internal: 0.001
          |
          +-- SUCCEEDED: Task test.command_line.build:help returned 0
          |   Elapsed: 0.217s, internal: 0.217
          |
          +-- FAILED: Task test.command_line.build:warranty raised AssertionError:
              Elapsed: 0.202s, internal: 0.202

Errors in Dovetail or third-party decorators or predicates

When a task itself fails through an exception, or when a task is failed with the @fail_if directive, Dovetail treats this as an ‘expected’ error, as described earlier in this page. However, if Dovetail crashes somewhere else, it produces a very different message for example:

Traceback (most recent call last):
  File "/Users/builder/crashtest/lib/python2.7/site-packages/Dovetail-1.0beta-py2.7.egg/dovetail/main.py", line 163, in execute_in_vm
    result = build(task, handle_exceptions=True)
  File "/Users/builder/crashtest/lib/python2.7/site-packages/Dovetail-1.0beta-py2.7.egg/dovetail/engine.py", line 935, in build
    result = Result(PROCESSOR._execute(task))
  File "/Users/builder/crashtest/lib/python2.7/site-packages/Dovetail-1.0beta-py2.7.egg/dovetail/engine.py", line 801, in _execute
    wrapper.before(execution)
  File "/Users/builder/crashtest/lib/python2.7/site-packages/Dovetail-1.0beta-py2.7.egg/dovetail/model.py", line 156, in before
    return self._before(execution)
  File "/Users/builder/crashtest/lib/python2.7/site-packages/Dovetail-1.0beta-py2.7.egg/dovetail/directives/core.py", line 140, in before
    if call_predicate(predicate, execution):
  File "/Users/builder/crashtest/lib/python2.7/site-packages/Dovetail-1.0beta-py2.7.egg/dovetail/directives/core.py", line 68, in call_predicate
    return predicate()
  File "/Users/builder/dovetail/test/failure/build.py", line 11, in __call__
    return 10 / self.divisor > 1
ZeroDivisionError: integer division or modulo by zero

===============================================================================

SYSTEM ERROR while processing the following task(s): divide_by_zero_fail

===============================================================================

If you see the “SYSTEM ERROR” message, then the problem could have originated in one of two places - the key is to look at the last line of the stack trace:

  File "/Users/builder/dovetail/test/failure/build.py", line 11, in __call__
    return 10 / self.divisor > 1
ZeroDivisionError: integer division or modulo by zero

Examine the path to see if the problem is in the Dovetail package (likely installed in your site-packages) or elsewhere:

• Bug in Dovetail: If the call stack shows only Python files in your site-packages (or wherever you installed Dovetail), then the bug is in Dovetail. Please contact the maintainer or create an issue in BitBucket

• Bug in third-party predicates or directives: In the stack-trace above, the last line does not come the Dovetail package - it comes from a build script. In this case the build script that caused the problem was:

  from dovetail import task, do_if
  
  class DivideByPredicate(object):
      """Returns true if 10 / divisor > 1, but designed to create an
      exception if the divisor equals 0"""
      def __init__(self, divisor):
          self.divisor = divisor
  
      def __call__(self):
          return 10 / self.divisor > 1
  
      def __str__(self):
          print "Divide by {0} > 1 predicate"
  
  @task
  @do_if(DivideByPredicate(0))
  def divide_by_zero_fail():
      """Should fail with a divide by zero error, crashing Dovetail"""
      pass
  

  The predicate raised a divide-by-zero exception which caused Dovetail to crash. This system exception should be resolved by fixing the third-party predicate.