When I try to build a package, the process enters an infinite loop of calling getent hosts snapcraft.io:
2023-11-07 18:41:07.069 Executing in container: lxc --project snapcraft exec local:snapcraft-brave-on-amd64-for-amd64-8526475 -- env PATH=/usr/local/sbin:/usr/local/bin:/usr/sbin:/usr/bin:/sbin:/bin:/snap/bin SNAPCRAFT_MANAGED_MODE=1 getent hosts snapcraft.io
This started today. Worked fine earlier. No local changes afaict.
Looks like this is only happening when I’m on a VPN. That’s new - it worked over a VPN with no issues for a long time. The command does return IPs and exits with 0, with and without the VPN, so what is the issue? There are no error messages.
Here’s the latest failure flavor (VPN disabled):
2023-11-17 17:05:55.464 The http error when checking the store for gtk-common-themes is 500 (retries left 5)
2023-11-17 17:06:35.501 The http error when checking the store for gtk-common-themes is 500 (retries left 4)
2023-11-17 17:07:15.519 The http error when checking the store for gtk-common-themes is 500 (retries left 3)
2023-11-17 17:07:55.547 The http error when checking the store for gtk-common-themes is 500 (retries left 2)
2023-11-17 17:08:35.571 The http error when checking the store for gtk-common-themes is 500 (retries left 1)
2023-11-17 17:09:15.599 The http error when checking the store for gnome-42-2204-sdk is 500 (retries left 5)
2023-11-17 17:09:55.621 The http error when checking the store for gnome-42-2204-sdk is 500 (retries left 4)
2023-11-17 17:10:35.637 The http error when checking the store for gnome-42-2204-sdk is 500 (retries left 3)
2023-11-17 17:11:15.649 The http error when checking the store for gnome-42-2204-sdk is 500 (retries left 2)
2023-11-17 17:11:55.658 The http error when checking the store for gnome-42-2204-sdk is 500 (retries left 1)
2023-11-17 17:12:35.665 The http error when checking the store for gnome-42-2204 is 500 (retries left 5)
2023-11-17 17:13:15.695 The http error when checking the store for gnome-42-2204 is 500 (retries left 4)
2023-11-17 17:13:55.701 The http error when checking the store for gnome-42-2204 is 500 (retries left 3)
2023-11-17 17:14:35.709 The http error when checking the store for gnome-42-2204 is 500 (retries left 2)
2023-11-17 17:15:15.716 The http error when checking the store for gnome-42-2204 is 500 (retries left 1)
2023-11-17 17:15:55.724 The http error when checking the store for core22 is 500 (retries left 5)
2023-11-17 17:16:35.734 The http error when checking the store for core22 is 500 (retries left 4)
2023-11-17 17:17:15.744 The http error when checking the store for core22 is 500 (retries left 3)
2023-11-17 17:17:55.757 The http error when checking the store for core22 is 500 (retries left 2)
2023-11-17 17:18:35.763 The http error when checking the store for core22 is 500 (retries left 1)
2023-11-17 17:18:35.775 verify plugin environment for part 'brave'
2023-11-17 17:18:35.776 verify plugin environment for part 'gnome/sdk'
2023-11-17 17:18:35.777 Executing parts lifecycle: repull brave ('source' property changed)
2023-11-17 17:18:35.777 Executing action
2023-11-17 17:18:35.777 execute action brave:Action(part_name='brave', step=Step.PULL, action_type=ActionType.RERUN, reason="'source' property changed", project_vars=None, properties=ActionProperties(changed_files=None, changed_dirs=None))
2023-11-17 17:18:35.777 clean brave:Step.PULL
2023-11-17 17:18:35.777 remove directory /root/parts/brave/src
2023-11-17 17:18:35.791 clean brave:Step.BUILD
2023-11-17 17:18:35.792 remove directory /root/parts/brave/build
2023-11-17 17:18:35.805 remove directory /root/parts/brave/install
2023-11-17 17:18:35.816 clean brave:Step.STAGE
2023-11-17 17:18:35.816 load state file: /root/parts/brave/state/stage
2023-11-17 17:18:35.857 load state file: /root/parts/gnome/sdk/state/stage
2023-11-17 17:18:35.868 clean brave:Step.PRIME
2023-11-17 17:18:35.868 load state file: /root/parts/brave/state/prime
2023-11-17 17:18:35.890 load state file: /root/parts/gnome/sdk/state/prime
2023-11-17 17:18:35.916 :: + set -eu
2023-11-17 17:18:35.917 :: + craftctl default
2023-11-17 18:27:30.358 :: 2023-11-17 17:27:29.714 :: error: Network request error: network request failed (request=<PreparedRequest [GET]>, response=None).
2023-11-17 18:27:30.358 :: 2023-11-17 17:27:29.926 'override-pull' in part 'brave' failed with code 1.
2023-11-17 18:27:30.359 :: Review the scriptlet and make sure it's correct.
2023-11-17 18:27:30.359 :: 2023-11-17 17:27:29.950 Traceback (most recent call last):
2023-11-17 18:27:30.359 :: 2023-11-17 17:27:29.950 File "/snap/snapcraft/9726/lib/python3.8/site-packages/snapcraft/parts/parts.py", line 191, in run
2023-11-17 18:27:30.359 :: 2023-11-17 17:27:29.950 aex.execute(action, stdout=stream, stderr=stream)
2023-11-17 18:27:30.359 :: 2023-11-17 17:27:29.950 File "/snap/snapcraft/9726/lib/python3.8/site-packages/craft_parts/executor/executor.py", line 304, in execute
2023-11-17 18:27:30.359 :: 2023-11-17 17:27:29.950 self._executor.execute(actions, stdout=stdout, stderr=stderr)
2023-11-17 18:27:30.359 :: 2023-11-17 17:27:29.950 File "/snap/snapcraft/9726/lib/python3.8/site-packages/craft_parts/executor/executor.py", line 128, in execute
2023-11-17 18:27:30.359 :: 2023-11-17 17:27:29.950 self._run_action(act, stdout=stdout, stderr=stderr)
2023-11-17 18:27:30.359 :: 2023-11-17 17:27:29.950 File "/snap/snapcraft/9726/lib/python3.8/site-packages/craft_parts/executor/executor.py", line 193, in _run_action
2023-11-17 18:27:30.359 :: 2023-11-17 17:27:29.950 handler.run_action(action, stdout=stdout, stderr=stderr)
2023-11-17 18:27:30.359 :: 2023-11-17 17:27:29.950 File "/snap/snapcraft/9726/lib/python3.8/site-packages/craft_parts/executor/part_handler.py", line 172, in run_action
2023-11-17 18:27:30.359 :: 2023-11-17 17:27:29.950 state = handler(step_info, stdout=stdout, stderr=stderr)
2023-11-17 18:27:30.359 :: 2023-11-17 17:27:29.950 File "/snap/snapcraft/9726/lib/python3.8/site-packages/craft_parts/executor/part_handler.py", line 198, in _run_pull
2023-11-17 18:27:30.359 :: 2023-11-17 17:27:29.950 self._run_step(
2023-11-17 18:27:30.359 :: 2023-11-17 17:27:29.950 File "/snap/snapcraft/9726/lib/python3.8/site-packages/craft_parts/executor/part_handler.py", line 485, in _run_step
2023-11-17 18:27:30.359 :: 2023-11-17 17:27:29.950 step_handler.run_scriptlet(
2023-11-17 18:27:30.359 :: 2023-11-17 17:27:29.950 File "/snap/snapcraft/9726/lib/python3.8/site-packages/craft_parts/executor/step_handler.py", line 278, in run_scriptlet
2023-11-17 18:27:30.359 :: 2023-11-17 17:27:29.950 raise errors.ScriptletRunError(
2023-11-17 18:27:30.359 :: 2023-11-17 17:27:29.951 craft_parts.errors.ScriptletRunError: 'override-pull' in part 'brave' failed with code 1.
2023-11-17 18:27:30.359 :: 2023-11-17 17:27:29.951 Review the scriptlet and make sure it's correct.
2023-11-17 18:27:30.359 :: 2023-11-17 17:27:29.951
2023-11-17 18:27:30.359 :: 2023-11-17 17:27:29.951 The above exception was the direct cause of the following exception:
2023-11-17 18:27:30.359 :: 2023-11-17 17:27:29.951 Traceback (most recent call last):
2023-11-17 18:27:30.359 :: 2023-11-17 17:27:29.951 File "/snap/snapcraft/9726/lib/python3.8/site-packages/snapcraft/parts/lifecycle.py", line 302, in _run_command
2023-11-17 18:27:30.359 :: 2023-11-17 17:27:29.951 _run_lifecycle_and_pack(
2023-11-17 18:27:30.359 :: 2023-11-17 17:27:29.951 File "/snap/snapcraft/9726/lib/python3.8/site-packages/snapcraft/parts/lifecycle.py", line 345, in _run_lifecycle_and_pack
2023-11-17 18:27:30.359 :: 2023-11-17 17:27:29.951 lifecycle.run(
2023-11-17 18:27:30.359 :: 2023-11-17 17:27:29.951 File "/snap/snapcraft/9726/lib/python3.8/site-packages/snapcraft/parts/parts.py", line 206, in run
2023-11-17 18:27:30.359 :: 2023-11-17 17:27:29.951 raise errors.PartsLifecycleError(str(err)) from err
2023-11-17 18:27:30.360 :: 2023-11-17 17:27:29.951 snapcraft.errors.PartsLifecycleError: 'override-pull' in part 'brave' failed with code 1.
2023-11-17 18:27:30.360 :: 2023-11-17 17:27:29.951 Review the scriptlet and make sure it's correct.
2023-11-17 18:27:31.799 Failed to execute build in instance.
2023-11-17 18:27:31.799 Detailed information: Run the same command again with --debug to shell into the environment if you wish to introspect this failure.
2023-11-17 18:27:31.800 Traceback (most recent call last):
2023-11-17 18:27:31.800 File "/var/lib/snapd/snap/snapcraft/9726/lib/python3.8/site-packages/snapcraft/parts/lifecycle.py", line 577, in _run_in_provider
2023-11-17 18:27:31.800 instance.execute_run(cmd, check=True, cwd=output_dir)
2023-11-17 18:27:31.800 File "/var/lib/snapd/snap/snapcraft/9726/lib/python3.8/site-packages/craft_providers/lxd/lxd_instance.py", line 289, in execute_run
2023-11-17 18:27:31.800 return self.lxc.exec(
2023-11-17 18:27:31.800 File "/var/lib/snapd/snap/snapcraft/9726/lib/python3.8/site-packages/craft_providers/lxd/lxc.py", line 371, in exec
2023-11-17 18:27:31.800 return runner(final_cmd, **kwargs) # pylint: disable=subprocess-run-check
2023-11-17 18:27:31.800 File "/var/lib/snapd/snap/snapcraft/9726/usr/lib/python3.8/subprocess.py", line 516, in run
2023-11-17 18:27:31.800 raise CalledProcessError(retcode, process.args,
2023-11-17 18:27:31.800 subprocess.CalledProcessError: Command '['lxc', '--project', 'snapcraft', 'exec', 'local:snapcraft-brave-on-amd64-for-amd64-8526475', '--cwd', '/root/project', '--', 'env', 'PATH=/usr/local/sbin:/usr/local/bin:/usr/sbin:/usr/bin:/sbin:/bin:/snap/bin', 'SNAPCRAFT_MANAGED_MODE=1', 'snapcraft', 'build', '--verbosity=debug', '--build-for', 'amd64']' returned non-zero exit status 1.
Each of the retries above takes 40s, so that’s almost 15min wasted. There’s no indication of eventual success either. And then at the end the build just hangs on craftctl default for almost 10min before failing.
And now 10min later everything works, with and without the VPN. No loops, http 500s…
Hi @wknapik,
Sorry about that infinite loop for getent hosts snapcraft.io. A fix for that was recently added to snapcraft, but it hasn’t yet been released to the stable channel.
I’ve heard another report of snapcraft not working when using a VPN. It has something to do with LXD and the host’s network config, but I’m not sure what. Next time it occurs, will you create a bug report?