Pybuilder does not parse/run tasks when run in Thoughtworks Go

[codesplicer]

I'm trying to run pybuilder as part of a CD pipeline using Thoughtworks Go. I have a setup script consisting of the following:

#!/usr/bin/env bash
set -e

CWD="$(pwd)"
echo "============================="
echo "In directory '$CWD'"
echo "============================="

echo "============================="
echo "Creating virtualenv"
echo "============================="
virtualenv --clear venv

echo "============================="
echo "Activating virtualenv venv"
echo "============================="
source venv/bin/activate

echo "============================="
echo "Upgrading setuptools..."
echo "============================="
pip install -U setuptools

echo "============================="
echo "Installing pybuilder..."
echo "============================="
pip install pybuilder

echo "============================="
echo "Installing dependencies.."
echo "============================="
pyb -X install_dependencies

# Run default tasks
echo "============================="
echo "Running default tasks..."
echo "============================="
pyb -X

However from looking at the output, pyb install_dependencies isn't run, resulting in 'build took 0 seconds'. If I run pyb -t from the Go task it correctly prints out the full task list however, so perhaps there's an issue in the way pybuilder is parsing the taskname arguments versus flags.

Debug output from the pipeline job is below:

10:40:02.610 [go] Job Started: 2015-11-18 10:40:02 GMT

10:40:02.610 [go] Start to prepare myproject-2.x/2.0.17/prepare/1/setup on ip-10-1-5-175 [/var/lib/go-agent-3]
10:40:02.638 [go] Start to update materials.

10:40:02.638 [go] Start updating files at revision 36ad9ac14a0c23207a6db914c2c452bf5dd2276c from git@github.com:foobar/myproject.git
10:40:02.642 Cloning into '/var/lib/go-agent-3/pipelines/myproject-2.x'...
10:40:08.425 [GIT] Fetch and reset in working directory pipelines/myproject-2.x
10:40:08.425 [GIT] Cleaning all unversioned files in working copy
10:40:08.428 [GIT] Cleaning submodule configurations in .git/config
10:40:08.429 [GIT] Fetching changes
10:40:08.559 [GIT] Performing git gc
10:40:08.661 [GIT] Updating working copy to revision 36ad9ac14a0c23207a6db914c2c452bf5dd2276c
10:40:08.665 HEAD is now at 36ad9ac enabled debug
10:40:08.665 [GIT] Removing modified files in submodules
10:40:08.676 [GIT] Cleaning all unversioned files in working copy
10:40:08.678 [go] Done.

10:40:08.714 [go] Start to build myproject-2.x/2.0.17/prepare/1/setup on ip-10-1-5-175 [/var/lib/go-agent-3]
10:40:08.714 [go] Current job status: passed.

10:40:08.714 [go] Start to execute task: <exec command="/bin/bash" >
<arg>go_build.sh</arg>
</exec>.
10:40:08.715 [go] setting environment variable 'GO_SERVER_URL' to value 'https://goserver.go.foobar.com:8154/go/'
10:40:08.715 [go] setting environment variable 'GO_TRIGGER_USER' to value 'changes'
10:40:08.715 [go] setting environment variable 'GO_PIPELINE_NAME' to value 'myproject-2.x'
10:40:08.715 [go] setting environment variable 'GO_PIPELINE_COUNTER' to value '17'
10:40:08.715 [go] setting environment variable 'GO_PIPELINE_LABEL' to value '2.0.17'
10:40:08.715 [go] setting environment variable 'GO_STAGE_NAME' to value 'prepare'
10:40:08.715 [go] setting environment variable 'GO_STAGE_COUNTER' to value '1'
10:40:08.715 [go] setting environment variable 'GO_JOB_NAME' to value 'setup'
10:40:08.715 [go] setting environment variable 'GO_REVISION' to value '36ad9ac14a0c23207a6db914c2c452bf5dd2276c'
10:40:08.716 [go] setting environment variable 'GO_TO_REVISION' to value '36ad9ac14a0c23207a6db914c2c452bf5dd2276c'
10:40:08.716 [go] setting environment variable 'GO_FROM_REVISION' to value '36ad9ac14a0c23207a6db914c2c452bf5dd2276c'
10:40:08.717 =============================
10:40:08.718 In directory '/var/lib/go-agent-3/pipelines/myproject-2.x'
10:40:08.718 =============================
10:40:08.718 =============================
10:40:08.718 Creating virtualenv
10:40:08.718 =============================
10:40:08.788 Not deleting venv/bin
10:40:08.788 New python executable in venv/bin/python
10:40:09.252 Installing distribute.............................................................................................................................................................................................done.
10:40:09.480 Installing pip...............done.
10:40:09.484 =============================
10:40:09.485 Activating virtualenv venv/
10:40:09.485 =============================
10:40:09.487 =============================
10:40:09.487 Upgrading setuptools...
10:40:09.487 =============================
10:40:10.396 Downloading/unpacking distribute from https://pypi.python.org/packages/source/d/distribute/distribute-0.7.3.zip#md5=c6c59594a7b180af57af8a0cc0cf5b4a
10:40:10.396   Running setup.py egg_info for package distribute
10:40:10.396     
10:40:10.396 Downloading/unpacking setuptools>=0.7 (from distribute)
10:40:10.396   Running setup.py egg_info for package setuptools
10:40:10.396     
10:40:10.396 Installing collected packages: distribute, setuptools
10:40:10.396   Found existing installation: distribute 0.6.24
10:40:10.396     Uninstalling distribute:
10:40:10.397       Successfully uninstalled distribute
10:40:10.397   Running setup.py install for distribute
10:40:10.397     
10:40:10.397   Running setup.py install for setuptools
10:40:10.397     
10:40:10.397     Installing easy_install script to /var/lib/go-agent-3/pipelines/myproject-2.x/venv/bin
10:40:10.397     Installing easy_install-2.7 script to /var/lib/go-agent-3/pipelines/myproject-2.x/venv/bin
10:40:10.397 Successfully installed distribute setuptools
10:40:10.397 Cleaning up...
10:40:10.404 =============================
10:40:10.404 Installing pybuilder...
10:40:10.404 =============================
10:40:11.407 Downloading/unpacking pybuilder
10:40:11.407   Running setup.py egg_info for package pybuilder
10:40:11.407     
10:40:11.407 Downloading/unpacking tblib (from pybuilder)
10:40:11.407   Downloading tblib-1.1.0.tar.gz
10:40:11.407   Running setup.py egg_info for package tblib
10:40:11.407     
10:40:11.407     warning: no files found matching 'AUTHORS'
10:40:11.407     warning: no files found matching '.coveragerc'
10:40:11.407     warning: no files found matching '.pylintrc'
10:40:11.407     warning: no directories found matching 'examples'
10:40:11.407     warning: no directories found matching 'docs'
10:40:11.407     warning: no previously-included files matching '*.pyc' found anywhere in distribution
10:40:11.407     warning: no previously-included files matching '*.pyo' found anywhere in distribution
10:40:11.407 Downloading/unpacking six (from tblib->pybuilder)
10:40:11.407   Downloading six-1.10.0.tar.gz
10:40:11.408   Running setup.py egg_info for package six
10:40:11.408     
10:40:11.408     no previously-included directories found matching 'documentation/_build'
10:40:11.408 Installing collected packages: pybuilder, tblib, six
10:40:11.408   Running setup.py install for pybuilder
10:40:11.408     changing mode of build/scripts-2.7/pyb from 664 to 775
10:40:11.408     
10:40:11.408     changing mode of /var/lib/go-agent-3/pipelines/myproject-2.x/venv/bin/pyb to 775
10:40:11.408     Installing pyb_ script to /var/lib/go-agent-3/pipelines/myproject-2.x/venv/bin
10:40:11.408   Running setup.py install for tblib
10:40:11.408     
10:40:11.408     warning: no files found matching 'AUTHORS'
10:40:11.408     warning: no files found matching '.coveragerc'
10:40:11.408     warning: no files found matching '.pylintrc'
10:40:11.408     warning: no directories found matching 'examples'
10:40:11.408     warning: no directories found matching 'docs'
10:40:11.408     warning: no previously-included files matching '*.pyc' found anywhere in distribution
10:40:11.408     warning: no previously-included files matching '*.pyo' found anywhere in distribution
10:40:11.408   Running setup.py install for six
10:40:11.408     
10:40:11.408     no previously-included directories found matching 'documentation/_build'
10:40:11.409 Successfully installed pybuilder tblib six
10:40:11.409 Cleaning up...
10:40:11.416 =============================
10:40:11.416 Installing dependencies..
10:40:11.416 =============================
10:40:11.459 PyBuilder version 0.11.3.dev20151114112735
10:40:11.459 Build started at 2015-11-18 10:40:11
10:40:11.459 ------------------------------------------------------------
10:40:11.459 [DEBUG] Loading project module from /var/lib/go-agent-3/pipelines/myproject-2.x/build.py
10:40:11.459 [DEBUG] Loading plugin 'python.core'
10:40:11.459 [DEBUG] Trying to load builtin plugin 'python.core'
10:40:11.459 [DEBUG] Loading plugin 'core'
10:40:11.459 [DEBUG] Trying to load builtin plugin 'core'
10:40:11.459 [DEBUG] Found builtin plugin 'pybuilder.plugins.core_plugin'
10:40:11.459 [DEBUG] Found task 'clean' with required dependencies [] and optional dependencies []
10:40:11.459 [DEBUG] Registering task 'clean'
10:40:11.459 [DEBUG] Found task 'compile_sources' with required dependencies [<function prepare at 0x1afa320>] and optional dependencies []
10:40:11.459 [DEBUG] Registering task 'compile_sources'
10:40:11.459 [DEBUG] Registering initializer 'init'
10:40:11.459 [DEBUG] Found task 'install' with required dependencies [<function package at 0x1afa488>] and optional dependencies [<function publish at 0x1afa5f0>]
10:40:11.459 [DEBUG] Registering task 'install'
10:40:11.460 [DEBUG] Found task 'package' with required dependencies [<function compile_sources at 0x1afa398>] and optional dependencies [<function run_unit_tests at 0x1afa410>]
10:40:11.460 [DEBUG] Registering task 'package'
10:40:11.460 [DEBUG] Found task 'prepare' with required dependencies [] and optional dependencies []
10:40:11.460 [DEBUG] Registering task 'prepare'
10:40:11.460 [DEBUG] Found task 'print_module_path' with required dependencies [] and optional dependencies []
10:40:11.460 [DEBUG] Registering task 'print_module_path'
10:40:11.460 [DEBUG] Found task 'print_scripts_path' with required dependencies [] and optional dependencies []
10:40:11.460 [DEBUG] Registering task 'print_scripts_path'
10:40:11.460 [DEBUG] Found task 'publish' with required dependencies [<function package at 0x1afa488>] and optional dependencies [<function verify at 0x1afa578>]
10:40:11.460 [DEBUG] Registering task 'publish'
10:40:11.460 [DEBUG] Found task 'run_integration_tests' with required dependencies [<function package at 0x1afa488>] and optional dependencies []
10:40:11.460 [DEBUG] Registering task 'run_integration_tests'
10:40:11.460 [DEBUG] Found task 'run_unit_tests' with required dependencies [<function compile_sources at 0x1afa398>] and optional dependencies []
10:40:11.460 [DEBUG] Registering task 'run_unit_tests'
10:40:11.460 [DEBUG] Found task 'verify' with required dependencies [<function run_integration_tests at 0x1afa500>] and optional dependencies []
10:40:11.461 [DEBUG] Registering task 'verify'
10:40:11.461 [DEBUG] Found builtin plugin 'pybuilder.plugins.python.core_plugin'
10:40:11.461 [DEBUG] Registering initializer 'init_python_directories'
10:40:11.461 [DEBUG] Found task 'package' with required dependencies [] and optional dependencies []
10:40:11.461 [DEBUG] Registering task 'package'
10:40:11.461 [DEBUG] Loading plugin 'python.unittest'
10:40:11.461 [DEBUG] Trying to load builtin plugin 'python.unittest'
10:40:11.461 [DEBUG] Found builtin plugin 'pybuilder.plugins.python.unittest_plugin'
10:40:11.461 [DEBUG] Registering initializer 'init_test_source_directory'
10:40:11.461 [DEBUG] Found task 'run_unit_tests' with required dependencies [] and optional dependencies []
10:40:11.461 [DEBUG] Registering task 'run_unit_tests'
10:40:11.461 [DEBUG] Loading plugin 'python.integrationtest'
10:40:11.461 [DEBUG] Trying to load builtin plugin 'python.integrationtest'
10:40:11.462 [DEBUG] Found builtin plugin 'pybuilder.plugins.python.integrationtest_plugin'
10:40:11.462 [DEBUG] Registering initializer 'initialize_integrationtest_plugin'
10:40:11.462 [DEBUG] Found task 'run_integration_tests' with required dependencies [] and optional dependencies []
10:40:11.462 [DEBUG] Registering task 'run_integration_tests'
10:40:11.462 [DEBUG] Loading plugin 'python.install_dependencies'
10:40:11.462 [DEBUG] Trying to load builtin plugin 'python.install_dependencies'
10:40:11.462 [DEBUG] Found builtin plugin 'pybuilder.plugins.python.install_dependencies_plugin'
10:40:11.462 [DEBUG] Found action check_pip_available
10:40:11.462 [DEBUG] Registering action 'check_pip_available'
10:40:11.462 [DEBUG] Found action create_install_log_directory
10:40:11.462 [DEBUG] Registering action 'create_install_log_directory'
10:40:11.462 [DEBUG] Registering initializer 'initialize_install_dependencies_plugin'
10:40:11.463 [DEBUG] Found task 'install_build_dependencies' with required dependencies [] and optional dependencies []
10:40:11.463 [DEBUG] Registering task 'install_build_dependencies'
10:40:11.463 [DEBUG] Found task 'install_dependencies' with required dependencies [] and optional dependencies []
10:40:11.465 [DEBUG] Registering task 'install_dependencies'
10:40:11.465 [DEBUG] Found task 'install_runtime_dependencies' with required dependencies [] and optional dependencies []
10:40:11.465 [DEBUG] Registering task 'install_runtime_dependencies'
10:40:11.465 [DEBUG] Found task 'list_dependencies' with required dependencies [] and optional dependencies []
10:40:11.466 [DEBUG] Registering task 'list_dependencies'
10:40:11.466 [DEBUG] Loading plugin 'python.flake8'
10:40:11.466 [DEBUG] Trying to load builtin plugin 'python.flake8'
10:40:11.466 [DEBUG] Found builtin plugin 'pybuilder.plugins.python.flake8_plugin'
10:40:11.466 [DEBUG] Found task 'analyze' with required dependencies ['prepare'] and optional dependencies []
10:40:11.466 [DEBUG] Registering task 'analyze'
10:40:11.466 [DEBUG] Found action assert_flake8_is_executable
10:40:11.466 [DEBUG] Registering action 'assert_flake8_is_executable'
10:40:11.466 [DEBUG] Registering initializer 'initialize_flake8_plugin'
10:40:11.466 [DEBUG] Loading plugin 'python.coverage'
10:40:11.466 [DEBUG] Trying to load builtin plugin 'python.coverage'
10:40:11.467 [DEBUG] Loading plugin 'analysis'
10:40:11.467 [DEBUG] Trying to load builtin plugin 'analysis'
10:40:11.467 [DEBUG] Found builtin plugin 'pybuilder.plugins.analysis_plugin'
10:40:11.467 [DEBUG] Found task 'analyze' with required dependencies ['run_unit_tests'] and optional dependencies []
10:40:11.467 [DEBUG] Registering task 'analyze'
10:40:11.467 [DEBUG] Found builtin plugin 'pybuilder.plugins.python.coverage_plugin'
10:40:11.467 [DEBUG] Registering initializer 'init_coverage_properties'
10:40:11.467 [DEBUG] Found action verify_coverage
10:40:11.467 [DEBUG] Registering action 'verify_coverage'
10:40:11.467 [DEBUG] Loading plugin 'python.distutils'
10:40:11.467 [DEBUG] Trying to load builtin plugin 'python.distutils'
10:40:11.468 [DEBUG] Found builtin plugin 'pybuilder.plugins.python.distutils_plugin'
10:40:11.468 [DEBUG] Found action build_binary_distribution
10:40:11.468 [DEBUG] Registering action 'build_binary_distribution'
10:40:11.468 [DEBUG] Registering initializer 'initialize_distutils_plugin'
10:40:11.468 [DEBUG] Found task 'install' with required dependencies [] and optional dependencies []
10:40:11.468 [DEBUG] Registering task 'install'
10:40:11.468 [DEBUG] Found task 'upload' with required dependencies [] and optional dependencies []
10:40:11.468 [DEBUG] Registering task 'upload'
10:40:11.468 [DEBUG] Found action write_manifest_file
10:40:11.468 [DEBUG] Registering action 'write_manifest_file'
10:40:11.468 [DEBUG] Found action write_setup_script
10:40:11.468 [DEBUG] Registering action 'write_setup_script'
10:40:11.469 [DEBUG] Loading plugin 'exec'
10:40:11.469 [DEBUG] Trying to load builtin plugin 'exec'
10:40:11.469 [DEBUG] Found builtin plugin 'pybuilder.plugins.exec_plugin'
10:40:11.469 [DEBUG] Found task 'analyze' with required dependencies [] and optional dependencies []
10:40:11.469 [DEBUG] Registering task 'analyze'
10:40:11.469 [DEBUG] Found task 'package' with required dependencies [] and optional dependencies []
10:40:11.469 [DEBUG] Registering task 'package'
10:40:11.469 [DEBUG] Found task 'publish' with required dependencies [] and optional dependencies []
10:40:11.469 [DEBUG] Registering task 'publish'
10:40:11.469 [DEBUG] Found task 'run_integration_tests' with required dependencies [] and optional dependencies []
10:40:11.469 [DEBUG] Registering task 'run_integration_tests'
10:40:11.470 [DEBUG] Found task 'run_unit_tests' with required dependencies [] and optional dependencies []
10:40:11.470 [DEBUG] Registering task 'run_unit_tests'
10:40:11.470 [DEBUG] Have loaded plugins python.core, core, python.unittest, python.integrationtest, python.install_dependencies, python.flake8, python.coverage, analysis, python.distutils, exec
10:40:11.470 [DEBUG] Registering initializer 'set_properties'
10:40:11.470 [DEBUG] Registering initializer 'set_properties_for_go_builds'
10:40:11.470 [DEBUG] Adding 'prepare' as a required dependency of task 'compile_sources'
10:40:11.470 [DEBUG] Adding 'package' as a required dependency of task 'install'
10:40:11.470 [DEBUG] Adding 'publish' as an optional dependency of task 'install'
10:40:11.470 [DEBUG] Adding 'compile_sources' as a required dependency of task 'package'
10:40:11.470 [DEBUG] Adding 'run_unit_tests' as an optional dependency of task 'package'
10:40:11.470 [DEBUG] Adding 'package' as a required dependency of task 'publish'
10:40:11.470 [DEBUG] Adding 'verify' as an optional dependency of task 'publish'
10:40:11.471 [DEBUG] Adding 'package' as a required dependency of task 'run_integration_tests'
10:40:11.471 [DEBUG] Adding 'compile_sources' as a required dependency of task 'run_unit_tests'
10:40:11.471 [DEBUG] Adding 'run_integration_tests' as a required dependency of task 'verify'
10:40:11.471 [DEBUG] Adding 'prepare' as a required dependency of task 'analyze'
10:40:11.471 [DEBUG] Adding 'run_unit_tests' as a required dependency of task 'analyze'
10:40:11.471 [DEBUG] Adding after action 'check_pip_available' for task 'prepare'
10:40:11.471 [DEBUG] Adding before action 'create_install_log_directory' for task 'install_build_dependencies'
10:40:11.471 [DEBUG] Adding before action 'create_install_log_directory' for task 'install_runtime_dependencies'
10:40:11.471 [DEBUG] Adding before action 'create_install_log_directory' for task 'install_dependencies'
10:40:11.471 [DEBUG] Adding after action 'assert_flake8_is_executable' for task 'prepare'
10:40:11.471 [DEBUG] Adding after action 'verify_coverage' for task 'analyze'
10:40:11.471 [DEBUG] Adding after action 'verify_coverage' for task 'verify'
10:40:11.472 [DEBUG] Adding before action 'build_binary_distribution' for task 'publish'
10:40:11.472 [DEBUG] Adding after action 'write_manifest_file' for task 'package'
10:40:11.472 [DEBUG] Adding after action 'write_setup_script' for task 'package'
10:40:11.472 [DEBUG] Verbose output enabled.
10:40:11.472 
10:40:11.472 [DEBUG] Executing initializer 'init' from 'pybuilder.plugins.core_plugin'
10:40:11.472 [DEBUG] Executing initializer 'init_python_directories' from 'pybuilder.plugins.python.core_plugin'
10:40:11.472 [DEBUG] Executing initializer 'init_test_source_directory' from 'pybuilder.plugins.python.unittest_plugin'
10:40:11.472 [DEBUG] Executing initializer 'initialize_integrationtest_plugin' from 'pybuilder.plugins.python.integrationtest_plugin'
10:40:11.472 [DEBUG] Executing initializer 'initialize_install_dependencies_plugin' from 'pybuilder.plugins.python.install_dependencies_plugin'
10:40:11.472 [DEBUG] Executing initializer 'initialize_flake8_plugin' from 'pybuilder.plugins.python.flake8_plugin'
10:40:11.472 [DEBUG] Executing initializer 'init_coverage_properties' from 'pybuilder.plugins.python.coverage_plugin'
10:40:11.473 [DEBUG] Executing initializer 'initialize_distutils_plugin' from 'pybuilder.plugins.python.distutils_plugin'
10:40:11.477 [DEBUG] Executing initializer 'set_properties' from 'build'
10:40:11.477 ------------------------------------------------------------
10:40:11.477 BUILD SUCCESSFUL
10:40:11.477 ------------------------------------------------------------
10:40:11.477 Build finished at 2015-11-18 10:40:11
10:40:11.477 Build took 0 seconds (13 ms)
10:40:11.477 =============================
10:40:11.477 Running default tasks...
10:40:11.477 =============================
10:40:11.531 PyBuilder version 0.11.3.dev20151114112735
10:40:11.531 Build started at 2015-11-18 10:40:11
10:40:11.531 ------------------------------------------------------------
10:40:11.531 [DEBUG] Loading project module from /var/lib/go-agent-3/pipelines/myproject-2.x/build.py
10:40:11.531 [DEBUG] Loading plugin 'python.core'
10:40:11.531 [DEBUG] Trying to load builtin plugin 'python.core'
10:40:11.531 [DEBUG] Loading plugin 'core'
10:40:11.531 [DEBUG] Trying to load builtin plugin 'core'
10:40:11.531 [DEBUG] Found builtin plugin 'pybuilder.plugins.core_plugin'
10:40:11.531 [DEBUG] Found task 'clean' with required dependencies [] and optional dependencies []
10:40:11.532 [DEBUG] Registering task 'clean'
10:40:11.532 [DEBUG] Found task 'compile_sources' with required dependencies [<function prepare at 0x23bc320>] and optional dependencies []
10:40:11.532 [DEBUG] Registering task 'compile_sources'
10:40:11.532 [DEBUG] Registering initializer 'init'
10:40:11.532 [DEBUG] Found task 'install' with required dependencies [<function package at 0x23bc488>] and optional dependencies [<function publish at 0x23bc5f0>]
10:40:11.532 [DEBUG] Registering task 'install'
10:40:11.532 [DEBUG] Found task 'package' with required dependencies [<function compile_sources at 0x23bc398>] and optional dependencies [<function run_unit_tests at 0x23bc410>]
10:40:11.532 [DEBUG] Registering task 'package'
10:40:11.532 [DEBUG] Found task 'prepare' with required dependencies [] and optional dependencies []
10:40:11.532 [DEBUG] Registering task 'prepare'
10:40:11.532 [DEBUG] Found task 'print_module_path' with required dependencies [] and optional dependencies []
10:40:11.532 [DEBUG] Registering task 'print_module_path'
10:40:11.532 [DEBUG] Found task 'print_scripts_path' with required dependencies [] and optional dependencies []
10:40:11.532 [DEBUG] Registering task 'print_scripts_path'
10:40:11.532 [DEBUG] Found task 'publish' with required dependencies [<function package at 0x23bc488>] and optional dependencies [<function verify at 0x23bc578>]
10:40:11.532 [DEBUG] Registering task 'publish'
10:40:11.532 [DEBUG] Found task 'run_integration_tests' with required dependencies [<function package at 0x23bc488>] and optional dependencies []
10:40:11.532 [DEBUG] Registering task 'run_integration_tests'
10:40:11.532 [DEBUG] Found task 'run_unit_tests' with required dependencies [<function compile_sources at 0x23bc398>] and optional dependencies []
10:40:11.532 [DEBUG] Registering task 'run_unit_tests'
10:40:11.533 [DEBUG] Found task 'verify' with required dependencies [<function run_integration_tests at 0x23bc500>] and optional dependencies []
10:40:11.533 [DEBUG] Registering task 'verify'
10:40:11.533 [DEBUG] Found builtin plugin 'pybuilder.plugins.python.core_plugin'
10:40:11.533 [DEBUG] Registering initializer 'init_python_directories'
10:40:11.533 [DEBUG] Found task 'package' with required dependencies [] and optional dependencies []
10:40:11.533 [DEBUG] Registering task 'package'
10:40:11.533 [DEBUG] Loading plugin 'python.unittest'
10:40:11.533 [DEBUG] Trying to load builtin plugin 'python.unittest'
10:40:11.533 [DEBUG] Found builtin plugin 'pybuilder.plugins.python.unittest_plugin'
10:40:11.533 [DEBUG] Registering initializer 'init_test_source_directory'
10:40:11.533 [DEBUG] Found task 'run_unit_tests' with required dependencies [] and optional dependencies []
10:40:11.533 [DEBUG] Registering task 'run_unit_tests'
10:40:11.533 [DEBUG] Loading plugin 'python.integrationtest'
10:40:11.533 [DEBUG] Trying to load builtin plugin 'python.integrationtest'
10:40:11.533 [DEBUG] Found builtin plugin 'pybuilder.plugins.python.integrationtest_plugin'
10:40:11.533 [DEBUG] Registering initializer 'initialize_integrationtest_plugin'
10:40:11.533 [DEBUG] Found task 'run_integration_tests' with required dependencies [] and optional dependencies []
10:40:11.533 [DEBUG] Registering task 'run_integration_tests'
10:40:11.533 [DEBUG] Loading plugin 'python.install_dependencies'
10:40:11.533 [DEBUG] Trying to load builtin plugin 'python.install_dependencies'
10:40:11.533 [DEBUG] Found builtin plugin 'pybuilder.plugins.python.install_dependencies_plugin'
10:40:11.534 [DEBUG] Found action check_pip_available
10:40:11.534 [DEBUG] Registering action 'check_pip_available'
10:40:11.534 [DEBUG] Found action create_install_log_directory
10:40:11.534 [DEBUG] Registering action 'create_install_log_directory'
10:40:11.534 [DEBUG] Registering initializer 'initialize_install_dependencies_plugin'
10:40:11.534 [DEBUG] Found task 'install_build_dependencies' with required dependencies [] and optional dependencies []
10:40:11.534 [DEBUG] Registering task 'install_build_dependencies'
10:40:11.534 [DEBUG] Found task 'install_dependencies' with required dependencies [] and optional dependencies []
10:40:11.537 [DEBUG] Registering task 'install_dependencies'
10:40:11.537 [DEBUG] Found task 'install_runtime_dependencies' with required dependencies [] and optional dependencies []
10:40:11.537 [DEBUG] Registering task 'install_runtime_dependencies'
10:40:11.537 [DEBUG] Found task 'list_dependencies' with required dependencies [] and optional dependencies []
10:40:11.537 [DEBUG] Registering task 'list_dependencies'
10:40:11.537 [DEBUG] Loading plugin 'python.flake8'
10:40:11.537 [DEBUG] Trying to load builtin plugin 'python.flake8'
10:40:11.537 [DEBUG] Found builtin plugin 'pybuilder.plugins.python.flake8_plugin'
10:40:11.537 [DEBUG] Found task 'analyze' with required dependencies ['prepare'] and optional dependencies []
10:40:11.537 [DEBUG] Registering task 'analyze'
10:40:11.537 [DEBUG] Found action assert_flake8_is_executable
10:40:11.538 [DEBUG] Registering action 'assert_flake8_is_executable'
10:40:11.538 [DEBUG] Registering initializer 'initialize_flake8_plugin'
10:40:11.538 [DEBUG] Loading plugin 'python.coverage'
10:40:11.538 [DEBUG] Trying to load builtin plugin 'python.coverage'
10:40:11.538 [DEBUG] Loading plugin 'analysis'
10:40:11.538 [DEBUG] Trying to load builtin plugin 'analysis'
10:40:11.538 [DEBUG] Found builtin plugin 'pybuilder.plugins.analysis_plugin'
10:40:11.538 [DEBUG] Found task 'analyze' with required dependencies ['run_unit_tests'] and optional dependencies []
10:40:11.538 [DEBUG] Registering task 'analyze'
10:40:11.538 [DEBUG] Found builtin plugin 'pybuilder.plugins.python.coverage_plugin'
10:40:11.538 [DEBUG] Registering initializer 'init_coverage_properties'
10:40:11.538 [DEBUG] Found action verify_coverage
10:40:11.538 [DEBUG] Registering action 'verify_coverage'
10:40:11.538 [DEBUG] Loading plugin 'python.distutils'
10:40:11.538 [DEBUG] Trying to load builtin plugin 'python.distutils'
10:40:11.538 [DEBUG] Found builtin plugin 'pybuilder.plugins.python.distutils_plugin'
10:40:11.539 [DEBUG] Found action build_binary_distribution
10:40:11.539 [DEBUG] Registering action 'build_binary_distribution'
10:40:11.539 [DEBUG] Registering initializer 'initialize_distutils_plugin'
10:40:11.539 [DEBUG] Found task 'install' with required dependencies [] and optional dependencies []
10:40:11.539 [DEBUG] Registering task 'install'
10:40:11.539 [DEBUG] Found task 'upload' with required dependencies [] and optional dependencies []
10:40:11.539 [DEBUG] Registering task 'upload'
10:40:11.539 [DEBUG] Found action write_manifest_file
10:40:11.539 [DEBUG] Registering action 'write_manifest_file'
10:40:11.539 [DEBUG] Found action write_setup_script
10:40:11.539 [DEBUG] Registering action 'write_setup_script'
10:40:11.539 [DEBUG] Loading plugin 'exec'
10:40:11.539 [DEBUG] Trying to load builtin plugin 'exec'
10:40:11.540 [DEBUG] Found builtin plugin 'pybuilder.plugins.exec_plugin'
10:40:11.540 [DEBUG] Found task 'analyze' with required dependencies [] and optional dependencies []
10:40:11.540 [DEBUG] Registering task 'analyze'
10:40:11.540 [DEBUG] Found task 'package' with required dependencies [] and optional dependencies []
10:40:11.540 [DEBUG] Registering task 'package'
10:40:11.540 [DEBUG] Found task 'publish' with required dependencies [] and optional dependencies []
10:40:11.540 [DEBUG] Registering task 'publish'
10:40:11.540 [DEBUG] Found task 'run_integration_tests' with required dependencies [] and optional dependencies []
10:40:11.540 [DEBUG] Registering task 'run_integration_tests'
10:40:11.540 [DEBUG] Found task 'run_unit_tests' with required dependencies [] and optional dependencies []
10:40:11.540 [DEBUG] Registering task 'run_unit_tests'
10:40:11.540 [DEBUG] Have loaded plugins python.core, core, python.unittest, python.integrationtest, python.install_dependencies, python.flake8, python.coverage, analysis, python.distutils, exec
10:40:11.541 [DEBUG] Registering initializer 'set_properties'
10:40:11.541 [DEBUG] Registering initializer 'set_properties_for_go_builds'
10:40:11.541 [DEBUG] Adding 'prepare' as a required dependency of task 'compile_sources'
10:40:11.541 [DEBUG] Adding 'package' as a required dependency of task 'install'
10:40:11.541 [DEBUG] Adding 'publish' as an optional dependency of task 'install'
10:40:11.541 [DEBUG] Adding 'compile_sources' as a required dependency of task 'package'
10:40:11.541 [DEBUG] Adding 'run_unit_tests' as an optional dependency of task 'package'
10:40:11.541 [DEBUG] Adding 'package' as a required dependency of task 'publish'
10:40:11.541 [DEBUG] Adding 'verify' as an optional dependency of task 'publish'
10:40:11.541 [DEBUG] Adding 'package' as a required dependency of task 'run_integration_tests'
10:40:11.541 [DEBUG] Adding 'compile_sources' as a required dependency of task 'run_unit_tests'
10:40:11.541 [DEBUG] Adding 'run_integration_tests' as a required dependency of task 'verify'
10:40:11.542 [DEBUG] Adding 'prepare' as a required dependency of task 'analyze'
10:40:11.542 [DEBUG] Adding 'run_unit_tests' as a required dependency of task 'analyze'
10:40:11.542 [DEBUG] Adding after action 'check_pip_available' for task 'prepare'
10:40:11.542 [DEBUG] Adding before action 'create_install_log_directory' for task 'install_build_dependencies'
10:40:11.542 [DEBUG] Adding before action 'create_install_log_directory' for task 'install_runtime_dependencies'
10:40:11.542 [DEBUG] Adding before action 'create_install_log_directory' for task 'install_dependencies'
10:40:11.542 [DEBUG] Adding after action 'assert_flake8_is_executable' for task 'prepare'
10:40:11.542 [DEBUG] Adding after action 'verify_coverage' for task 'analyze'
10:40:11.542 [DEBUG] Adding after action 'verify_coverage' for task 'verify'
10:40:11.542 [DEBUG] Adding before action 'build_binary_distribution' for task 'publish'
10:40:11.542 [DEBUG] Adding after action 'write_manifest_file' for task 'package'
10:40:11.543 [DEBUG] Adding after action 'write_setup_script' for task 'package'
10:40:11.543 [DEBUG] Verbose output enabled.
10:40:11.543 
10:40:11.543 [DEBUG] Executing initializer 'init' from 'pybuilder.plugins.core_plugin'
10:40:11.543 [DEBUG] Executing initializer 'init_python_directories' from 'pybuilder.plugins.python.core_plugin'
10:40:11.543 [DEBUG] Executing initializer 'init_test_source_directory' from 'pybuilder.plugins.python.unittest_plugin'
10:40:11.543 [DEBUG] Executing initializer 'initialize_integrationtest_plugin' from 'pybuilder.plugins.python.integrationtest_plugin'
10:40:11.543 [DEBUG] Executing initializer 'initialize_install_dependencies_plugin' from 'pybuilder.plugins.python.install_dependencies_plugin'
10:40:11.543 [DEBUG] Executing initializer 'initialize_flake8_plugin' from 'pybuilder.plugins.python.flake8_plugin'
10:40:11.543 [DEBUG] Executing initializer 'init_coverage_properties' from 'pybuilder.plugins.python.coverage_plugin'
10:40:11.543 [DEBUG] Executing initializer 'initialize_distutils_plugin' from 'pybuilder.plugins.python.distutils_plugin'
10:40:11.543 [DEBUG] Executing initializer 'set_properties' from 'build'
10:40:11.543 ------------------------------------------------------------
10:40:11.544 BUILD SUCCESSFUL
10:40:11.544 ------------------------------------------------------------
10:40:11.544 Build finished at 2015-11-18 10:40:11
10:40:11.544 Build took 0 seconds (12 ms)
10:40:11.665 [go] Current job status: passed.

10:40:11.675 [go] Start to create properties myproject-2.x/2.0.17/prepare/1/setup on ip-10-1-5-175 [/var/lib/go-agent-3]

[mriehl]

It seems PyBuilder is already installed or downloaded in the log you added, is it possible that you're not calling the pyb script from the virtualenv?

It's really strange however. The debug shows that the install_dependencies plugin was correctly loaded, but somehow the task is not run.
Can you add your build.py as a gist or code snippet? Especially any custom tasks and the base project definition.

[mriehl]

Looking at the code, the block Executing initializer... should be followed by at least the project properties (they are always logged in debug mode).

A simple explanation would be that there is a sys.exit being called somewhere (maybe you have a custom initializer that exits?), but maybe we have a bug.

[mriehl]

A further look at the log reveals that there is a custom initializer:

10:40:11.470 [DEBUG] Registering initializer 'set_properties_for_go_builds'

but exactly at the point in time when this initializer should be executed (the last executed initializer is set_properties, which is found just before set_properties_for_go_builds) the build suddenly stops.

I think there could be a problem with set_properties_for_go_builds. Can you post the initializer declaration here?

[codesplicer]

My build.py is below. PyBuilder is not installed system-wide on the agents. There is indeed a custom initialiser, to enable xml reporting when run from a Go pipeline task, but it shouldn't exit unless xmlrunner isn't installed?

import os
import sys
from pybuilder.core import use_plugin, init, Author, task


use_plugin("python.core")
use_plugin("python.unittest")
use_plugin("python.integrationtest")
use_plugin("python.install_dependencies")
use_plugin("python.flake8")
use_plugin("python.coverage")
use_plugin("python.distutils")
use_plugin("exec")


name = "myproject"
url = "http://github.com/foobar/myproject"

# Dependencies
RUNTIME_DEPENDENCIES = [
    "retrying",
    "boto",
    "requests",
    "psutil",
    "python-ldap",
    "prettytable",
    "argh"
]

BUILD_DEPENDENCIES = [
    "pytest",
    "pytest-xdist",
    "nose",
    "mock",
    "mockldap",
    "httpretty",
    "moto",
    "unittest-xml-reporting"
]


@init
def set_properties(project):
    # Set project dependencies
    for dependency in RUNTIME_DEPENDENCIES:
        project.depends_on(dependency)

    for dependency in BUILD_DEPENDENCIES:
        project.build_depends_on(dependency)

    project.default_task = ["clean", "analyze", "publish"]

    # Set project default parameters
    if is_go_build():
        project.version = "{0}".format(os.environ.get("GO_PIPELINE_LABEL", "2.0.0"))
        # Set xmlrunner for unittest reporting
        try:
            import xmlrunner
            unittest_runner = (
                lambda stream=None: __import__("xmlrunner").XMLTestRunner(project.expand_path("$dir_target/reports"), stream=stream),
                xmlrunner.XMLTestRunner._make_result)
            project.set_property("unittest_runner", unittest_runner)
        except ImportError:
            raise SystemExit("Could not import xmlrunner")
    else:
        project.version = "2"

    project.set_property("verbose", True)

    # Coverage properties
    project.set_property("coverage_break_build", True)
    project.set_property("coverage_threshold_warn", 70)

    # Test properties
    project.set_property("integrationtest_parallel", True)
    project.set_property("integrationtest_file_glob", "test_*.py")
    project.set_property("dir_source_unittest_python", "src/unittest/python")
    project.set_property("unittest_module_glob", "test_*.py")

    # Set linter properties
    project.set_property("flake8_ignore", "E501")
    project.set_property("flake8_break_build", True)
    project.set_property('flake8_verbose_output', True)

    # Enable debug output for unit tests
    project.set_property("run_unit_tests_propagate_stdout", True)
    project.set_property("run_unit_tests_propagate_stderr", True)


def is_go_build():
    """
    Checks if build is being run from a goagent

    :return: (bool) True if a Go build, else returns False
    """
    if os.environ.get('GO_PIPELINE_COUNTER'):
        return True
    return False


@init(environments="go")
def set_properties_for_go_builds(project):
    # Set version based on pipeline env vars
    project.version = "{0}".format(os.environ.get("GO_PIPELINE_LABEL", "2.0.0"))

[codesplicer]

Looks like the code that sets xmlrunner is what silently broke the build script. Remove that code from build.py and everything works again. Is there a better way to do this?

[mriehl]

XMLRunner is already the default, so you don't actually need to do this, but I agree this is poor user experience.
Also the problem might be that you __import__ to reference the class but not the _make_result which relies on the enclosing scope (doesn't work in a forked process then).

I don't really understand how this can silently fail instead of causing a crash - how did you get to the bottom of this, what gave it away?

[codesplicer]

Yes I just saw that too (on a sidenote, pyb generates 2 report files for each module being unit-tested during analyze).

I found the bug by progressively simplifying my build.py until it started working in Go. But yes, was expecting to see the exception output instead of silently failing. Unsure why the SystemExit wasn't breaking out of the script.

[arcivanov]

on a sidenote, pyb generates 2 report files for each module being unit-tested during analyze

it does that because of coverage - tests are run twice with and without coverage.

[mriehl]

Is it possible your initializer was raising the SystemExit due to missing xmlrunner?

Anyway, we need to catch SystemExit and deal with it (provide a backtrace, fail the build) if that's the case. Thank you for reporting this.

[codesplicer]

Yes my initialiser was raising the SystemExit but it was getting ignored by pybuilder.