Automatic build fails, but manually triggered builds work

nlessmann · March 23, 2021, 12:13pm

For my site, builds using Python 3.7 and pipenv to install dependencies where working fine until recently. Then the automatic build started failing and in the logs I can see that Python 2.7 is being used instead of Python 3.7.

When I manually trigger the build (“Clear cache and deploy site”) everything works fine. However, the next automatic build seems to use the old cache and fails again. What can I do about this?

This is the deploy log of the failing log:

12:42:52 PM: Build ready to start
12:42:55 PM: build-image version: 3571f0130496395a23bffe9820bc78b4f73a6234
12:42:55 PM: build-image tag: v3.7.0
12:42:55 PM: buildbot version: b8a7cb2ab30309dc791e77b97759136f817b5561
12:42:55 PM: Fetching cached dependencies
12:42:55 PM: Starting to download cache of 249.3MB
12:42:56 PM: Finished downloading cache in 1.50022217s
12:42:56 PM: Starting to extract cache
12:43:08 PM: Finished extracting cache in 11.067560712s
12:43:08 PM: Finished fetching cache in 12.724508176s
12:43:08 PM: Starting to prepare the repo for build
12:43:08 PM: Preparing Git Reference refs/heads/master
12:43:09 PM: Parsing package.json dependencies
12:43:11 PM: Different publish path detected, going to use the one specified in the Netlify configuration file: ‘output’ versus ‘output/’ in the Netlify UI
12:43:11 PM: Starting build script
12:43:11 PM: Installing dependencies
12:43:11 PM: Found Pipfile restoring Pipenv virtualenv
12:43:11 PM: Started restoring cached python virtualenv
12:43:11 PM: Finished restoring cached python virtualenv
12:43:12 PM: Started restoring cached node version
12:43:17 PM: Finished restoring cached node version
12:43:17 PM: v10.24.0 is already installed.
12:43:19 PM: Now using node v10.24.0 (npm v6.14.11)
12:43:19 PM: Started restoring cached build plugins
12:43:19 PM: Finished restoring cached build plugins
12:43:19 PM: Attempting ruby version 2.6.2, read from environment
12:43:21 PM: Using ruby version 2.6.2
12:43:22 PM: Using PHP version 5.6
12:43:22 PM: Installing dependencies from Pipfile
12:43:24 PM: Installing dependencies from Pipfile.lock (b72235)…
12:43:33 PM: Traceback (most recent call last):
12:43:33 PM: File “/opt/buildhome/python2.7/bin/pipenv”, line 8, in
12:43:33 PM: sys.exit(cli())
12:43:33 PM: File “/opt/buildhome/python2.7/lib/python2.7/site-packages/pipenv/vendor/click/core.py”, line 829, in call
12:43:33 PM: return self.main(*args, **kwargs)
12:43:33 PM: File “/opt/buildhome/python2.7/lib/python2.7/site-packages/pipenv/vendor/click/core.py”, line 782, in main
12:43:33 PM: rv = self.invoke(ctx)
12:43:33 PM: File “/opt/buildhome/python2.7/lib/python2.7/site-packages/pipenv/vendor/click/core.py”, line 1259, in invoke
12:43:33 PM: return _process_result(sub_ctx.command.invoke(sub_ctx))
12:43:33 PM: File “/opt/buildhome/python2.7/lib/python2.7/site-packages/pipenv/vendor/click/core.py”, line 1066, in invoke
12:43:33 PM: return ctx.invoke(self.callback, **ctx.params)
12:43:33 PM: File “/opt/buildhome/python2.7/lib/python2.7/site-packages/pipenv/vendor/click/core.py”, line 610, in invoke
12:43:33 PM: return callback(*args, **kwargs)
12:43:33 PM: File “/opt/buildhome/python2.7/lib/python2.7/site-packages/pipenv/vendor/click/decorators.py”, line 73, in new_func
12:43:33 PM: return ctx.invoke(f, obj, *args, **kwargs)
12:43:33 PM: File “/opt/buildhome/python2.7/lib/python2.7/site-packages/pipenv/vendor/click/core.py”, line 610, in invoke
12:43:33 PM: return callback(*args, **kwargs)
12:43:33 PM: File “/opt/buildhome/python2.7/lib/python2.7/site-packages/pipenv/vendor/click/decorators.py”, line 21, in new_func
12:43:33 PM: return f(get_current_context(), *args, **kwargs)
12:43:33 PM: File “/opt/buildhome/python2.7/local/lib/python2.7/site-packages/pipenv/cli/command.py”, line 253, in install
12:43:33 PM: site_packages=state.site_packages
12:43:33 PM: File “/opt/buildhome/python2.7/local/lib/python2.7/site-packages/pipenv/core.py”, line 2063, in do_install
12:43:33 PM: keep_outdated=keep_outdated
12:43:33 PM: File “/opt/buildhome/python2.7/local/lib/python2.7/site-packages/pipenv/core.py”, line 1312, in do_init
12:43:33 PM: pypi_mirror=pypi_mirror,
12:43:33 PM: File “/opt/buildhome/python2.7/local/lib/python2.7/site-packages/pipenv/core.py”, line 871, in do_install_dependencies
12:43:33 PM: normal_deps, procs, failed_deps_queue, requirements_dir, **install_kwargs
12:43:33 PM: File “/opt/buildhome/python2.7/local/lib/python2.7/site-packages/pipenv/core.py”, line 735, in batch_install
12:43:33 PM: dep for dep in deps_to_install if not project.environment.is_satisfied(dep)
12:43:33 PM: File “/opt/buildhome/python2.7/local/lib/python2.7/site-packages/pipenv/environment.py”, line 790, in is_satisfied
12:43:33 PM: vcs_type == req.vcs and commit_id == req.commit_hash
12:43:33 PM: File “/opt/buildhome/python2.7/lib/python2.7/site-packages/pipenv/vendor/cached_property.py”, line 36, in get
12:43:33 PM: value = obj.dict[self.func.name] = self.func(obj)
12:43:33 PM: Failed during stage ‘building site’: Build script returned non-zero exit code: 1
12:43:33 PM: File “/opt/buildhome/python2.7/local/lib/python2.7/site-packages/pipenv/vendor/requirementslib/models/requirements.py”, line 2493, in commit_hash
12:43:33 PM: with self.req.locked_vcs_repo() as repo:
12:43:33 PM: File “/usr/lib/python2.7/contextlib.py”, line 17, in enter
12:43:33 PM: return self.gen.next()
12:43:33 PM: File “/opt/buildhome/python2.7/local/lib/python2.7/site-packages/pipenv/vendor/requirementslib/models/requirements.py”, line 2223, in locked_vcs_repo
12:43:33 PM: self._parsed_line.vcsrepo = vcsrepo
12:43:33 PM: File “/opt/buildhome/python2.7/local/lib/python2.7/site-packages/pipenv/vendor/requirementslib/models/requirements.py”, line 907, in vcsrepo
12:43:33 PM: kwargs=wheel_kwargs,
12:43:33 PM: File “/opt/buildhome/python2.7/local/lib/python2.7/site-packages/pipenv/vendor/requirementslib/models/setup_info.py”, line 1987, in create
12:43:33 PM: created.get_initial_info()
12:43:33 PM: File “/opt/buildhome/python2.7/local/lib/python2.7/site-packages/pipenv/vendor/requirementslib/models/setup_info.py”, line 1816, in get_initial_info
12:43:33 PM: self.update_from_dict(self.parse_setup_py())
12:43:33 PM: File “/opt/buildhome/python2.7/local/lib/python2.7/site-packages/pipenv/vendor/requirementslib/models/setup_info.py”, line 1514, in update_from_dict
12:43:33 PM: for section in set(list(extras_require.keys())) - set(list(self.extras.keys())):
12:43:33 PM: File “/opt/buildhome/python2.7/local/lib/python2.7/site-packages/pipenv/vendor/requirementslib/models/setup_info.py”, line 1442, in extras
12:43:33 PM: self.get_info()
12:43:33 PM: File “/opt/buildhome/python2.7/local/lib/python2.7/site-packages/pipenv/vendor/requirementslib/models/setup_info.py”, line 1834, in get_info
12:43:33 PM: self.build()
12:43:33 PM: File “/opt/buildhome/python2.7/local/lib/python2.7/site-packages/pipenv/vendor/requirementslib/models/setup_info.py”, line 1696, in build
12:43:33 PM: return self.run_setup()
12:43:33 PM: File “/opt/buildhome/python2.7/local/lib/python2.7/site-packages/pipenv/vendor/requirementslib/models/setup_info.py”, line 1567, in run_setup
12:43:33 PM: dist = run_setup(self.setup_py.as_posix(), egg_base=self.egg_base)
12:43:33 PM: File “/opt/buildhome/python2.7/local/lib/python2.7/site-packages/pipenv/vendor/requirementslib/models/setup_info.py”, line 1324, in run_setup
12:43:33 PM: _setup_distribution = get_metadata(egg_base, metadata_type=“egg”)
12:43:33 PM: File “/opt/buildhome/python2.7/local/lib/python2.7/site-packages/pipenv/vendor/requirementslib/models/setup_info.py”, line 569, in get_metadata
12:43:33 PM: dist = get_egginfo_dist(path, pkg_name=pkg_name)
12:43:33 PM: File “/opt/buildhome/python2.7/local/lib/python2.7/site-packages/pipenv/vendor/requirementslib/models/setup_info.py”, line 554, in get_egginfo_dist
12:43:33 PM: dist_iter = pkg_resources.distributions_from_metadata(path_metadata.egg_info)
12:43:33 PM: AttributeError: ‘module’ object has no attribute ‘distributions_from_metadata’
12:43:33 PM: Error installing Pipenv dependencies
12:43:33 PM: Please see GitHub - netlify/build-image: This is the build image used for running automated builds for current versions
12:43:33 PM: Build was terminated: Build script returned non-zero exit code: 1
12:43:33 PM: Failing build: Failed to build site
12:43:33 PM: Finished processing build request in 38.60486865s

And this is what it looks like when I manually trigger the deploy:

12:47:54 PM: Build ready to start
12:47:56 PM: build-image version: 3571f0130496395a23bffe9820bc78b4f73a6234
12:47:56 PM: build-image tag: v3.7.0
12:47:56 PM: buildbot version: b8a7cb2ab30309dc791e77b97759136f817b5561
12:47:56 PM: Building without cache
12:47:56 PM: Starting to prepare the repo for build
12:47:56 PM: No cached dependencies found. Cloning fresh repo
12:47:56 PM: git clone https://github.com/MIDL-Conference/midl-website-2021
12:47:58 PM: Preparing Git Reference refs/heads/master
12:48:00 PM: Parsing package.json dependencies
12:48:01 PM: Different publish path detected, going to use the one specified in the Netlify configuration file: ‘output’ versus ‘output/’ in the Netlify UI
12:48:01 PM: Starting build script
12:48:01 PM: Installing dependencies
12:48:01 PM: Found Pipfile restoring Pipenv virtualenv
12:48:01 PM: Started restoring cached python virtualenv
12:48:01 PM: Finished restoring cached python virtualenv
12:48:03 PM: Downloading and installing node v10.24.0…
12:48:03 PM: Downloading https://nodejs.org/dist/v10.24.0/node-v10.24.0-linux-x64.tar.xz…
12:48:03 PM: Computing checksum with sha256sum
12:48:03 PM: Checksums matched!
12:48:06 PM: Now using node v10.24.0 (npm v6.14.11)
12:48:06 PM: Started restoring cached build plugins
12:48:06 PM: Finished restoring cached build plugins
12:48:06 PM: Attempting ruby version 2.6.2, read from environment
12:48:07 PM: Using ruby version 2.6.2
12:48:08 PM: Using PHP version 5.6
12:48:08 PM: Installing dependencies from Pipfile
12:48:10 PM: Creating a virtualenv for this project…
12:48:10 PM: Pipfile: /opt/build/repo/Pipfile
12:48:10 PM: Using /usr/bin/python3.7m (3.7.10) to create virtualenv…
12:48:11 PM: created virtual environment CPython3.7.10.final.0-64 in 1055ms
12:48:11 PM: creator CPython3Posix(dest=/opt/build/repo/.venv, clear=False, no_vcs_ignore=False, global=False)
12:48:11 PM: seeder FromAppData(download=False, pip=bundle, wheel=bundle, setuptools=bundle, via=copy, app_data_dir=/opt/buildhome/.local/share/virtualenv)
12:48:11 PM: added seed packages: pip==21.0.1, setuptools==52.0.0, wheel==0.36.2
12:48:11 PM: activators PythonActivator,FishActivator,XonshActivator,CShellActivator,PowerShellActivator,BashActivator
12:48:11 PM: Successfully created virtual environment!
12:48:12 PM: Virtualenv location: /opt/build/repo/.venv
12:48:12 PM: Installing dependencies from Pipfile.lock (b72235)…
12:48:34 PM: To activate this project’s virtualenv, run pipenv shell.
Alternatively, run a command inside the virtualenv with pipenv run.
12:48:34 PM: Pipenv dependencies installed
12:48:35 PM: Python version set to Python 3.7.10
12:48:35 PM: Started restoring cached go cache
12:48:35 PM: Finished restoring cached go cache
12:48:35 PM: Installing Go version 1.12
12:48:42 PM: unset GOOS;
12:48:42 PM: unset GOARCH;
12:48:42 PM: export GOROOT=’/opt/buildhome/.gimme_cache/versions/go1.12.linux.amd64’;
12:48:42 PM: export PATH="/opt/buildhome/.gimme_cache/versions/go1.12.linux.amd64/bin:${PATH}";
12:48:42 PM: go version >&2;
12:48:42 PM: export GIMME_ENV="/opt/buildhome/.gimme_cache/env/go1.12.linux.amd64.env"
12:48:42 PM: go version go1.12 linux/amd64
12:48:42 PM: Installing missing commands
12:48:42 PM: Verify run directory
12:48:44 PM:
12:48:44 PM: ────────────────────────────────────────────────────────────────
12:48:44 PM: Netlify Build
12:48:44 PM: ────────────────────────────────────────────────────────────────
12:48:44 PM:
12:48:44 PM: ❯ Version
12:48:44 PM: @netlify/build 9.11.4
…

AaronP · March 23, 2021, 1:20pm

Interesting…
In your Pipfile, do you specify a specific version?

[requires]
python_version = "3.7"

I’ve looked at the build image here, that breaks down the default Python version and where it may look for overrides.

Python - PYTHON_VERSION, runtime.txt, Pipfile
2.7 (default)
3.5
3.7

Since you’re using the pipfile, I assume that’s where you are setting the version. However, just for testing, you could also try a PYTHON_VERSION env variable or runetime.txt?

The inclusion of [requires] python_version = "3.7" specifies that your application requires this version of Python, and will be used automatically when running pipenv install against this Pipfile in the future.

I think requiring this (if you are not already), could help.

Looking a bit deeper, I can see the build image is setting the PIPENV_RUNTIME to be 2.7.
As seen here

I have also come across this issue on github which people have a similar issue, after requiring a specific version (2.7 | 3.5 | 3.7) it seems for force the runtime to use the pip3 installation etc.

However, what’s most confusing for me is that the installation works manually but not automatically. Here, I am not very knowledgable of manual deploys so I hope the above is of some help!

As a side note: It’s worth pointing out a difference between the two builds seems that the manual deploy creates the virtualenv after installing deps from Pipfile, but the automatic one does nothing.

12:48:10 PM: Creating a virtualenv for this project…
12:48:10 PM: Pipfile: /opt/build/repo/Pipfile
12:48:10 PM: Using /usr/bin/python3.7m (3.7.10) to create virtualenv…
12:48:11 PM: created virtual environment CPython3.7.10.final.0-64 in 1055ms
12:48:11 PM: creator CPython3Posix(dest=/opt/build/repo/.venv, clear=False, no_vcs_ignore=False, global=False)
12:48:11 PM: seeder FromAppData(download=False, pip=bundle, wheel=bundle, setuptools=bundle, via=copy, app_data_dir=/opt/buildhome/.local/share/virtualenv)
12:48:11 PM: added seed packages: pip==21.0.1, setuptools==52.0.0, wheel==0.36.2
12:48:11 PM: activators PythonActivator,FishActivator,XonshActivator,CShellActivator,PowerShellActivator,BashActivator
12:48:11 PM: Successfully created virtual environment!
12:48:12 PM: Virtualenv location: /opt/build/repo/.venv

nlessmann · March 23, 2021, 1:50pm

Hi, thanks for the reply. I do specify a python version in the Pipfile, and I also tried an environment variable PYTHON_VERSION but I get the same error. Interestingly, when I run “Deploy site” manually it fails in the same way, only “Clear cache and deploy site” works.

It seems as if the automatic build is reusing an old cached virtualenv that is somehow linked to python 2.7. I would expect that “Clear cache and deploy site” would overwrite this old environment, but that does not seem to happen. I also cannot find any other button to clear the build cache.

nlessmann · March 23, 2021, 2:27pm

I switched to poetry for dependency management now in combination with a runtime.txt file, that seems to work fine.