Improve error handling and log output of {pre,post}_compile hooks (#…

…1667)

* If the hooks fail, there is now an explicit error message (plus metrics event).
* The build log step now references the full script location to aid.
  with understanding of what's happening.
* Any output of the hooks is now indented to aid readability.
* The hooks implementation has been refactored and moved to `lib/`
  as part of the overall buildpack reorganisation/refactoring.
* Test coverage has been added for the failing hooks cases (previously only
  the successful hooks scenario was tested).

(This is one step towards ensuring all buildpack failure cases have an explicit
error message and a metrics `failure_reason`.)

GUS-W-8059892.

CHANGELOG.md

@@ -3,6 +3,7 @@
 ## [Unreleased]
 
 - Updated buildpack-generated warning messages to use colour and be more consistently formatted. ([#1666](https://github.com/heroku/heroku-buildpack-python/pull/1666))
+- Improved build log output and error messages for the `bin/pre_compile` and `bin/post_compile` customisation hooks. ([#1667](https://github.com/heroku/heroku-buildpack-python/pull/1667))
 
 ## [v261] - 2024-10-14
 

bin/compile

@@ -19,6 +19,7 @@ ENV_DIR="${3}"
 BUILDPACK_DIR=$(cd "$(dirname "$(dirname "${BASH_SOURCE[0]}")")" && pwd)
 
 source "${BUILDPACK_DIR}/bin/utils"
+source "${BUILDPACK_DIR}/lib/hooks.sh"
 source "${BUILDPACK_DIR}/lib/metadata.sh"
 source "${BUILDPACK_DIR}/lib/output.sh"
 source "${BUILDPACK_DIR}/lib/package_manager.sh"
@@ -119,7 +120,7 @@ if [[ -d "$CACHE_DIR/.heroku/src" ]]; then
 fi
 
 # Runs a `bin/pre_compile` script if found in the app source, allowing build customisation.
-source "${BUILDPACK_DIR}/bin/steps/hooks/pre_compile"
+hooks::run_hook "pre_compile"
 
 # TODO: Clear the cache if this isn't a valid version, as part of the cache refactor.
 # (Currently the version is instead validated in `read_requested_python_version()`)
@@ -297,7 +298,7 @@ cp "${BUILDPACK_DIR}/vendor/WEB_CONCURRENCY.sh" "$WEB_CONCURRENCY_PROFILE_PATH"
 cp "${BUILDPACK_DIR}/vendor/python.gunicorn.sh" "$GUNICORN_PROFILE_PATH"
 
 # Runs a `bin/post_compile` script if found in the app source, allowing build customisation.
-source "${BUILDPACK_DIR}/bin/steps/hooks/post_compile"
+hooks::run_hook "post_compile"
 
 # Store new artifacts in the cache.
 rm -rf "$CACHE_DIR/.heroku/python"

lib/hooks.sh

@@ -0,0 +1,41 @@
+#!/usr/bin/env bash
+
+# This is technically redundant, since all consumers of this lib will have enabled these,
+# however, it helps Shellcheck realise the options under which these functions will run.
+set -euo pipefail
+
+# Used to run the `bin/pre_compile` and `bin/post_compile`s scripts if found in the app source,
+# allowing for build customisation.
+function hooks::run_hook() {
+	local hook_name="${1}"
+	local script_path="bin/${hook_name}"
+
+	if [[ -f "${script_path}" ]]; then
+		local hook_start_time
+		hook_start_time=$(nowms)
+		output::step "Running ${script_path} hook"
+		meta_set "${hook_name}_hook" "true"
+		chmod +x "${script_path}"
+
+		# shellcheck disable=SC2310 # This function is invoked in an 'if' condition so set -e will be disabled.
+		if ! sub_env "${script_path}" |& output::indent; then
+			output::error <<-EOF
+				Error: Failed to run the ${script_path} script.
+
+				We found a '${script_path}' script in your app source, so ran
+				it to allow for customisation of the build process.
+
+				However, this script exited with a non-zero exit status.
+
+				Fix any errors output by your script above, or remove/rename
+				the script to prevent it from being run during the build.
+			EOF
+			meta_set "failure_reason" "hooks::${hook_name}"
+			exit 1
+		fi
+
+		meta_time "${hook_name}_hook_duration" "${hook_start_time}"
+	else
+		meta_set "${hook_name}_hook" "false"
+	fi
+}

spec/fixtures/hooks_failing_post_compile/bin/post_compile

@@ -0,0 +1,6 @@
+#!/usr/bin/env bash
+
+set -euo pipefail
+
+echo 'Some post_compile error!' >&2
+exit 1

spec/fixtures/hooks_failing_pre_compile/bin/pre_compile

@@ -0,0 +1,6 @@
+#!/usr/bin/env bash
+
+set -euo pipefail
+
+echo 'Some pre_compile error!' >&2
+exit 1

spec/hatchet/ci_spec.rb

@@ -23,20 +23,20 @@
                  .*
                  Successfully installed .* pytest-8.3.3
           -----> Skipping Django collectstatic since the env var DISABLE_COLLECTSTATIC is set.
-          -----> Running post-compile hook
-          CI=true
-          CPLUS_INCLUDE_PATH=/app/.heroku/python/include
-          C_INCLUDE_PATH=/app/.heroku/python/include
-          DISABLE_COLLECTSTATIC=1
-          INSTALL_TEST=1
-          LANG=en_US.UTF-8
-          LC_ALL=C.UTF-8
-          LD_LIBRARY_PATH=/app/.heroku/python/lib
-          LIBRARY_PATH=/app/.heroku/python/lib
-          PATH=/app/.heroku/python/bin::/usr/local/bin:/usr/local/bin:/usr/bin:/bin:/app/.sprettur/bin/
-          PIP_NO_PYTHON_VERSION_WARNING=1
-          PKG_CONFIG_PATH=/app/.heroku/python/lib/pkg-config
-          PYTHONUNBUFFERED=1
+          -----> Running bin/post_compile hook
+                 CI=true
+                 CPLUS_INCLUDE_PATH=/app/.heroku/python/include
+                 C_INCLUDE_PATH=/app/.heroku/python/include
+                 DISABLE_COLLECTSTATIC=1
+                 INSTALL_TEST=1
+                 LANG=en_US.UTF-8
+                 LC_ALL=C.UTF-8
+                 LD_LIBRARY_PATH=/app/.heroku/python/lib
+                 LIBRARY_PATH=/app/.heroku/python/lib
+                 PATH=/app/.heroku/python/bin::/usr/local/bin:/usr/local/bin:/usr/bin:/bin:/app/.sprettur/bin/
+                 PIP_NO_PYTHON_VERSION_WARNING=1
+                 PKG_CONFIG_PATH=/app/.heroku/python/lib/pkg-config
+                 PYTHONUNBUFFERED=1
           -----> Inline app detected
           LANG=en_US.UTF-8
           LD_LIBRARY_PATH=/app/.heroku/python/lib
@@ -77,7 +77,7 @@
           -----> Installing requirements with pip
           -----> Installing test dependencies...
           -----> Skipping Django collectstatic since the env var DISABLE_COLLECTSTATIC is set.
-          -----> Running post-compile hook
+          -----> Running bin/post_compile hook
         OUTPUT
       end
     end
@@ -99,20 +99,20 @@
                  Installing dependencies from Pipfile.lock \\(.+\\)...
                  Installing dependencies from Pipfile.lock \\(.+\\)...
           -----> Skipping Django collectstatic since the env var DISABLE_COLLECTSTATIC is set.
-          -----> Running post-compile hook
-          CI=true
-          CPLUS_INCLUDE_PATH=/app/.heroku/python/include
-          C_INCLUDE_PATH=/app/.heroku/python/include
-          DISABLE_COLLECTSTATIC=1
-          INSTALL_TEST=1
-          LANG=en_US.UTF-8
-          LC_ALL=C.UTF-8
-          LD_LIBRARY_PATH=/app/.heroku/python/lib
-          LIBRARY_PATH=/app/.heroku/python/lib
-          PATH=/app/.heroku/python/bin::/usr/local/bin:/usr/local/bin:/usr/bin:/bin:/app/.sprettur/bin/
-          PIP_NO_PYTHON_VERSION_WARNING=1
-          PKG_CONFIG_PATH=/app/.heroku/python/lib/pkg-config
-          PYTHONUNBUFFERED=1
+          -----> Running bin/post_compile hook
+                 CI=true
+                 CPLUS_INCLUDE_PATH=/app/.heroku/python/include
+                 C_INCLUDE_PATH=/app/.heroku/python/include
+                 DISABLE_COLLECTSTATIC=1
+                 INSTALL_TEST=1
+                 LANG=en_US.UTF-8
+                 LC_ALL=C.UTF-8
+                 LD_LIBRARY_PATH=/app/.heroku/python/lib
+                 LIBRARY_PATH=/app/.heroku/python/lib
+                 PATH=/app/.heroku/python/bin::/usr/local/bin:/usr/local/bin:/usr/bin:/bin:/app/.sprettur/bin/
+                 PIP_NO_PYTHON_VERSION_WARNING=1
+                 PKG_CONFIG_PATH=/app/.heroku/python/lib/pkg-config
+                 PYTHONUNBUFFERED=1
           -----> Inline app detected
           LANG=en_US.UTF-8
           LD_LIBRARY_PATH=/app/.heroku/python/lib
@@ -154,7 +154,7 @@
                  Installing dependencies from Pipfile.lock \\(.+\\)...
                  Installing dependencies from Pipfile.lock \\(.+\\)...
           -----> Skipping Django collectstatic since the env var DISABLE_COLLECTSTATIC is set.
-          -----> Running post-compile hook
+          -----> Running bin/post_compile hook
         REGEX
       end
     end

spec/hatchet/hooks_spec.rb

@@ -14,50 +14,100 @@
 
         expect(output).to include(<<~OUTPUT)
           remote: -----> Python app detected
-          remote: -----> Running pre-compile hook
-          remote: ~ pre_compile ran with env vars:
-          remote: BUILD_DIR=/tmp/build_<hash>
-          remote: CACHE_DIR=/tmp/codon/tmp/cache
-          remote: C_INCLUDE_PATH=/app/.heroku/python/include
-          remote: CPLUS_INCLUDE_PATH=/app/.heroku/python/include
-          remote: ENV_DIR=/tmp/...
-          remote: HOME=/app
-          remote: LANG=en_US.UTF-8
-          remote: LD_LIBRARY_PATH=/app/.heroku/python/lib
-          remote: LIBRARY_PATH=/app/.heroku/python/lib
-          remote: PATH=/app/.heroku/python/bin::/usr/local/bin:/usr/local/sbin:/usr/local/bin:/usr/sbin:/usr/bin:/sbin:/bin
-          remote: PIP_NO_PYTHON_VERSION_WARNING=1
-          remote: PKG_CONFIG_PATH=/app/.heroku/python/lib/pkg-config
-          remote: PWD=/tmp/build_<hash>
-          remote: PYTHONUNBUFFERED=1
-          remote: SOME_APP_CONFIG_VAR=1
-          remote: SOURCE_VERSION=...
-          remote: STACK=#{app.stack}
-          remote: ~ pre_compile complete
+          remote: -----> Running bin/pre_compile hook
+          remote:        ~ pre_compile ran with env vars:
+          remote:        BUILD_DIR=/tmp/build_<hash>
+          remote:        CACHE_DIR=/tmp/codon/tmp/cache
+          remote:        C_INCLUDE_PATH=/app/.heroku/python/include
+          remote:        CPLUS_INCLUDE_PATH=/app/.heroku/python/include
+          remote:        ENV_DIR=/tmp/...
+          remote:        HOME=/app
+          remote:        LANG=en_US.UTF-8
+          remote:        LD_LIBRARY_PATH=/app/.heroku/python/lib
+          remote:        LIBRARY_PATH=/app/.heroku/python/lib
+          remote:        PATH=/app/.heroku/python/bin::/usr/local/bin:/usr/local/sbin:/usr/local/bin:/usr/sbin:/usr/bin:/sbin:/bin
+          remote:        PIP_NO_PYTHON_VERSION_WARNING=1
+          remote:        PKG_CONFIG_PATH=/app/.heroku/python/lib/pkg-config
+          remote:        PWD=/tmp/build_<hash>
+          remote:        PYTHONUNBUFFERED=1
+          remote:        SOME_APP_CONFIG_VAR=1
+          remote:        SOURCE_VERSION=...
+          remote:        STACK=#{app.stack}
+          remote:        ~ pre_compile complete
         OUTPUT
 
         expect(output).to include(<<~OUTPUT)
           remote: -----> Installing requirements with pip
-          remote: -----> Running post-compile hook
-          remote: ~ post_compile ran with env vars:
-          remote: BUILD_DIR=/tmp/build_<hash>
-          remote: CACHE_DIR=/tmp/codon/tmp/cache
-          remote: C_INCLUDE_PATH=/app/.heroku/python/include
-          remote: CPLUS_INCLUDE_PATH=/app/.heroku/python/include
-          remote: ENV_DIR=/tmp/...
-          remote: HOME=/app
-          remote: LANG=en_US.UTF-8
-          remote: LD_LIBRARY_PATH=/app/.heroku/python/lib
-          remote: LIBRARY_PATH=/app/.heroku/python/lib
-          remote: PATH=/app/.heroku/python/bin::/usr/local/bin:/usr/local/sbin:/usr/local/bin:/usr/sbin:/usr/bin:/sbin:/bin
-          remote: PIP_NO_PYTHON_VERSION_WARNING=1
-          remote: PKG_CONFIG_PATH=/app/.heroku/python/lib/pkg-config
-          remote: PWD=/tmp/build_<hash>
-          remote: PYTHONUNBUFFERED=1
-          remote: SOME_APP_CONFIG_VAR=1
-          remote: SOURCE_VERSION=...
-          remote: STACK=#{app.stack}
-          remote: ~ post_compile complete
+          remote: -----> Running bin/post_compile hook
+          remote:        ~ post_compile ran with env vars:
+          remote:        BUILD_DIR=/tmp/build_<hash>
+          remote:        CACHE_DIR=/tmp/codon/tmp/cache
+          remote:        C_INCLUDE_PATH=/app/.heroku/python/include
+          remote:        CPLUS_INCLUDE_PATH=/app/.heroku/python/include
+          remote:        ENV_DIR=/tmp/...
+          remote:        HOME=/app
+          remote:        LANG=en_US.UTF-8
+          remote:        LD_LIBRARY_PATH=/app/.heroku/python/lib
+          remote:        LIBRARY_PATH=/app/.heroku/python/lib
+          remote:        PATH=/app/.heroku/python/bin::/usr/local/bin:/usr/local/sbin:/usr/local/bin:/usr/sbin:/usr/bin:/sbin:/bin
+          remote:        PIP_NO_PYTHON_VERSION_WARNING=1
+          remote:        PKG_CONFIG_PATH=/app/.heroku/python/lib/pkg-config
+          remote:        PWD=/tmp/build_<hash>
+          remote:        PYTHONUNBUFFERED=1
+          remote:        SOME_APP_CONFIG_VAR=1
+          remote:        SOURCE_VERSION=...
+          remote:        STACK=#{app.stack}
+          remote:        ~ post_compile complete
+        OUTPUT
+      end
+    end
+  end
+
+  context 'when an app has a failing bin/pre_compile script' do
+    let(:app) { Hatchet::Runner.new('spec/fixtures/hooks_failing_pre_compile', allow_failure: true) }
+
+    it 'aborts the build with a suitable error message' do
+      app.deploy do |app|
+        expect(clean_output(app.output)).to include(<<~OUTPUT)
+          remote: -----> Running bin/pre_compile hook
+          remote:        Some pre_compile error!
+          remote: 
+          remote:  !     Error: Failed to run the bin/pre_compile script.
+          remote:  !     
+          remote:  !     We found a 'bin/pre_compile' script in your app source, so ran
+          remote:  !     it to allow for customisation of the build process.
+          remote:  !     
+          remote:  !     However, this script exited with a non-zero exit status.
+          remote:  !     
+          remote:  !     Fix any errors output by your script above, or remove/rename
+          remote:  !     the script to prevent it from being run during the build.
+          remote: 
+          remote:  !     Push rejected, failed to compile Python app.
+        OUTPUT
+      end
+    end
+  end
+
+  context 'when an app has a failing bin/post_compile script' do
+    let(:app) { Hatchet::Runner.new('spec/fixtures/hooks_failing_post_compile', allow_failure: true) }
+
+    it 'aborts the build with a suitable error message' do
+      app.deploy do |app|
+        expect(clean_output(app.output)).to include(<<~OUTPUT)
+          remote: -----> Running bin/post_compile hook
+          remote:        Some post_compile error!
+          remote: 
+          remote:  !     Error: Failed to run the bin/post_compile script.
+          remote:  !     
+          remote:  !     We found a 'bin/post_compile' script in your app source, so ran
+          remote:  !     it to allow for customisation of the build process.
+          remote:  !     
+          remote:  !     However, this script exited with a non-zero exit status.
+          remote:  !     
+          remote:  !     Fix any errors output by your script above, or remove/rename
+          remote:  !     the script to prevent it from being run during the build.
+          remote: 
+          remote:  !     Push rejected, failed to compile Python app.
         OUTPUT
       end
     end

spec/hatchet/pip_spec.rb

@@ -140,16 +140,16 @@
     it 'rewrites .pth, .egg-link and finder paths correctly for hooks, later buildpacks, runtime and cached builds' do
       app.deploy do |app|
         expect(clean_output(app.output)).to match(Regexp.new(<<~REGEX))
-          remote: -----> Running post-compile hook
-          remote: easy-install.pth:/app/.heroku/src/gunicorn
-          remote: easy-install.pth:/tmp/build_.*/packages/local_package_setup_py
-          remote: __editable___local_package_pyproject_toml_0_0_1_finder.py:/tmp/build_.*/packages/local_package_pyproject_toml/local_package_pyproject_toml'}
-          remote: gunicorn.egg-link:/app/.heroku/src/gunicorn
-          remote: local-package-setup-py.egg-link:/tmp/build_.*/packages/local_package_setup_py
-          remote: 
-          remote: Running entrypoint for the pyproject.toml-based local package: Hello pyproject.toml!
-          remote: Running entrypoint for the setup.py-based local package: Hello setup.py!
-          remote: Running entrypoint for the VCS package: gunicorn \\(version 20.1.0\\)
+          remote: -----> Running bin/post_compile hook
+          remote:        easy-install.pth:/app/.heroku/src/gunicorn
+          remote:        easy-install.pth:/tmp/build_.*/packages/local_package_setup_py
+          remote:        __editable___local_package_pyproject_toml_0_0_1_finder.py:/tmp/build_.*/packages/local_package_pyproject_toml/local_package_pyproject_toml'}
+          remote:        gunicorn.egg-link:/app/.heroku/src/gunicorn
+          remote:        local-package-setup-py.egg-link:/tmp/build_.*/packages/local_package_setup_py
+          remote:        
+          remote:        Running entrypoint for the pyproject.toml-based local package: Hello pyproject.toml!
+          remote:        Running entrypoint for the setup.py-based local package: Hello setup.py!
+          remote:        Running entrypoint for the VCS package: gunicorn \\(version 20.1.0\\)
           remote: -----> Inline app detected
           remote: easy-install.pth:/app/.heroku/src/gunicorn
           remote: easy-install.pth:/tmp/build_.*/packages/local_package_setup_py
@@ -179,16 +179,16 @@
         app.commit!
         app.push!
         expect(clean_output(app.output)).to match(Regexp.new(<<~REGEX))
-          remote: -----> Running post-compile hook
-          remote: easy-install.pth:/app/.heroku/src/gunicorn
-          remote: easy-install.pth:/tmp/build_.*/packages/local_package_setup_py
-          remote: __editable___local_package_pyproject_toml_0_0_1_finder.py:/tmp/build_.*/packages/local_package_pyproject_toml/local_package_pyproject_toml'}
-          remote: gunicorn.egg-link:/app/.heroku/src/gunicorn
-          remote: local-package-setup-py.egg-link:/tmp/build_.*/packages/local_package_setup_py
-          remote: 
-          remote: Running entrypoint for the pyproject.toml-based local package: Hello pyproject.toml!
-          remote: Running entrypoint for the setup.py-based local package: Hello setup.py!
-          remote: Running entrypoint for the VCS package: gunicorn \\(version 20.1.0\\)
+          remote: -----> Running bin/post_compile hook
+          remote:        easy-install.pth:/app/.heroku/src/gunicorn
+          remote:        easy-install.pth:/tmp/build_.*/packages/local_package_setup_py
+          remote:        __editable___local_package_pyproject_toml_0_0_1_finder.py:/tmp/build_.*/packages/local_package_pyproject_toml/local_package_pyproject_toml'}
+          remote:        gunicorn.egg-link:/app/.heroku/src/gunicorn
+          remote:        local-package-setup-py.egg-link:/tmp/build_.*/packages/local_package_setup_py
+          remote:        
+          remote:        Running entrypoint for the pyproject.toml-based local package: Hello pyproject.toml!
+          remote:        Running entrypoint for the setup.py-based local package: Hello setup.py!
+          remote:        Running entrypoint for the VCS package: gunicorn \\(version 20.1.0\\)
           remote: -----> Inline app detected
           remote: easy-install.pth:/app/.heroku/src/gunicorn
           remote: easy-install.pth:/tmp/build_.*/packages/local_package_setup_py