### Bug Description Hi Snapcraft folks! We’ve hit an interesting race condition in using `snapcraft` during initialization. We’ve spent some time debugging and we’ve noticed that there’s a potential race during initialization of the lxc container, which in the case of our system, seems to be hit more consistently. **Background**: we’re attempting to use `snapcraft` in an environment that we manage where Ubuntu runs in a privileged container for distribution purposes. It mimics the base Ubuntu experience, including using systemd as a supervisor, but with a few small differences. ### Our Debugging We’ve narrowed down the minimal set of `lxc` calls to reproduce the issue in our environment: ``` echo "$(date +"%T.%6N") start copy" && sudo lxc --project snapcraft copy local:base-instance-snapcraft-buildd-base-v7-c-f91ee4af44ccdf02cefb local:test-container && echo "$(date +"%T.%6N") copy done" && sudo lxc --project snapcraft start local:test-container && echo "$(date +"%T.%6N") start done" && echo "$(date +"%T.%6N") container info: $(sudo lxc --project snapcraft info local:test-container -v --show-log)" && echo "container config: $(sudo lxc --project snapcraft exec local:test-container -- env CRAFT_MANAGED_MODE=1 SNAPCRAFT_BUILD_INFO=1 'SNAPCRAFT_IMAGE_INFO={"build_url":"https://github.com/nscloud-demo/breakpoint/actions/runs/12892802672"}' DEBIAN_FRONTEND=noninteractive DEBCONF_NONINTERACTIVE_SEEN=true DEBIAN_PRIORITY=critical cat /etc/craft-instance.conf)" ``` And here is the output: ``` 13:03:57.303233 start copy 13:04:01.219672 copy done 13:04:01.518316 start done 13:04:01.519478 container info: Name: test-container Status: ERROR Type: container Architecture: x86_64 Created: 2025/01/23 13:03 UTC Last Used: 2025/01/23 13:04 UTC Log: lxc snapcraft_test-container 20250123130401.420 WARN idmap_utils - ../src/src/lxc/idmap_utils.c:lxc_map_ids:165 - newuidmap binary is missing lxc snapcraft_test-container 20250123130401.420 WARN idmap_utils - ../src/src/lxc/idmap_utils.c:lxc_map_ids:171 - newgidmap binary is missing lxc snapcraft_test-container 20250123130401.420 WARN idmap_utils - ../src/src/lxc/idmap_utils.c:lxc_map_ids:165 - newuidmap binary is missing lxc snapcraft_test-container 20250123130401.420 WARN idmap_utils - ../src/src/lxc/idmap_utils.c:lxc_map_ids:171 - newgidmap binary is missing container config: compatibility_tag: snapcraft-buildd-base-v7 setup: true snaps: core22: revision: '1722' source: host snapcraft: revision: '13181' source: host ``` After few milliseconds, the container status switches from `ERROR` to `RUNNING`, that’s why the final `exec cat /etc/craft-instance.conf` succeeds. But without the call to `lxc info`, the `exec` call fails often. At the same time we’ve attached `lxc monitor --all-projects --type=logging --pretty --loglevel=debug` and we collected the below log records: ``` DEBUG [2025-01-23T09:37:08Z] Retrieved PID of executing child process attachedPid=22038 instance=test-container instanceType=container project=snapcraft DEBUG [2025-01-23T09:37:08Z] Exec control handler started PID=22038 instance=test-container interactive=false project=snapcraft DEBUG [2025-01-23T09:37:08Z] Exec mirror websocket started PID=22038 instance=test-container interactive=false number=2 project=snapcraft DEBUG [2025-01-23T09:37:08Z] Exec mirror websocket finished PID=22038 err="<nil>" instance=test-container interactive=false number=0 project=snapcraft DEBUG [2025-01-23T09:37:08Z] Websocket: Stopped write mirror address=@ err="<nil>" DEBUG [2025-01-23T09:37:08Z] Websocket: Started write mirror address=@ DEBUG [2025-01-23T09:37:08Z] Exec mirror websocket started PID=22038 instance=test-container interactive=false number=0 project=snapcraft DEBUG [2025-01-23T09:37:08Z] Websocket: Got barrier message address=@ DEBUG [2025-01-23T09:37:08Z] Websocket: Started read mirror address=@ DEBUG [2025-01-23T09:37:08Z] Exec mirror websocket started PID=22038 instance=test-container interactive=false number=1 project=snapcraft DEBUG [2025-01-23T09:37:08Z] Websocket: Started read mirror address=@ DEBUG [2025-01-23T09:37:08Z] Websocket: Sending barrier message address=@ DEBUG [2025-01-23T09:37:08Z] Exec mirror websocket finished PID=22038 err="<nil>" instance=test-container interactive=false number=2 project=snapcraft DEBUG [2025-01-23T09:37:08Z] Websocket: Stopped read mirror address=@ err="<nil>" DEBUG [2025-01-23T09:37:08Z] Websocket: Sending barrier message address=@ DEBUG [2025-01-23T09:37:08Z] Updated metadata for operation class=websocket description="Executing command" operation=3cfd880b-6ada-475a-ba9a-e63ca3fe5d86 project=snapcraft DEBUG [2025-01-23T09:37:08Z] Exec mirror websocket finished PID=22038 err="<nil>" instance=test-container interactive=false number=1 project=snapcraft DEBUG [2025-01-23T09:37:08Z] Exec control handler finished PID=22038 instance=test-container interactive=false project=snapcraft DEBUG [2025-01-23T09:37:08Z] Instance process stopped PID=22038 err="<nil>" exitStatus=0 instance=test-container interactive=false project=snapcraft DEBUG [2025-01-23T09:37:08Z] Success for operation class=websocket description="Executing command" operation=3cfd880b-6ada-475a-ba9a-e63ca3fe5d86 project=snapcraft DEBUG [2025-01-23T09:37:08Z] Websocket: Stopped read mirror address=@ err="<nil>" DEBUG [2025-01-23T09:37:08Z] Event listener server handler stopped listener=0d0760a8-43e8-4055-8658-68807bef0160 local=/var/snap/lxd/common/lxd/unix.socket remote=@ DEBUG [2025-01-23T09:37:08Z] Syscall handler received fds 46(/proc/<pid>), 69(/proc/<pid>/mem), and 75([seccomp notify]) ERROR [2025-01-23T09:37:13Z] Failed to find container for monitor 21909 DEBUG [2025-01-23T09:37:13Z] Send seccomp notification for id(11735253732989671774) DEBUG [2025-01-23T09:37:13Z] Syscall handler received fds 46(/proc/<pid>), 69(/proc/<pid>/mem), and 75([seccomp notify]) ERROR [2025-01-23T09:37:18Z] Failed to find container for monitor 21909 DEBUG [2025-01-23T09:37:18Z] Send seccomp notification for id(11735253732989671775) ``` We don’t see the logs lines `Failed to find container for monitor 21909` when running the same commands in an Ubuntu VM. In addition, the Ubuntu VM shows the following logs from `lxc monitor`, that we don’t observe in our system. ``` DEBUG [2025-01-23T09:39:52Z] Failed forwarding signal PID=24343 err="no such process" instance=test-container interactive=false project=snapcraft signal=21 DEBUG [2025-01-23T09:39:52Z] Failed forwarding signal PID=24343 err="no such process" instance=test-container interactive=false project=snapcraft signal=21 DEBUG [2025-01-23T09:39:52Z] Failed forwarding signal PID=24343 err="no such process" instance=test-container interactive=false project=snapcraft signal=21 DEBUG [2025-01-23T09:39:52Z] Failed forwarding signal PID=24343 err="no such process" instance=test-container interactive=false project=snapcraft signal=21 DEBUG [2025-01-23T09:39:52Z] Failed forwarding signal PID=24343 err="no such process" instance=test-container interactive=false project=snapcraft signal=21 DEBUG [2025-01-23T09:39:52Z] Failed forwarding signal PID=24343 err="no such process" instance=test-container interactive=false project=snapcraft signal=21 DEBUG [2025-01-23T09:39:52Z] Failed forwarding signal PID=24343 err="no such process" instance=test-container interactive=false project=snapcraft signal=21 DEBUG [2025-01-23T09:39:52Z] Failed forwarding signal PID=24343 err="no such process" instance=test-container interactive=false project=snapcraft signal=21 DEBUG [2025-01-23T09:39:52Z] Exec control handler finished PID=24343 instance=test-container interactive=false project=snapcraft ``` Both systems use `lxc` 5.21.2 LTS and Ubuntu 24.04. We’ve also looked into the `snapcraft` code and found that after the container is started, there is no explicit wait on the container status, before checking if the instance configuration is there. See here: https://github.com/canonical/craft-providers/blob/main/craft_providers/lxd/launcher.py#L224-L229. The `base_configuration.warmup` will try to `exec test -f /etc/craft-instance.conf` inside the container, and if this one is not yet running, the whole build fails. See here https://github.com/canonical/craft-providers/blob/main/craft_providers/lxd/lxd_instance.py#L439-L443. Is this expected? It looks like `lxc start` is async and returns immediately even if the container may have not yet started. And there is no guarantee that the following `lxc exec` will find it running. ### Potential Solution In our testing, adding a call to `lxc info`, between `lxc start` and `lxc exec` is enough to give time to the container to fully initialize and start. We believe a potential fix is to add a retry-loop calling `lxc info` and checking that container status is `RUNNING`. And only then run the check for container configuration (i.e. calling `lxc exec -- test -f /etc/craft-instance.conf`). If you believe this is the correct direction, we’d be more than happy to send a PR! ### To Reproduce You can reproduce this in our system, available as [Namespace Runners for GitHub Actions](https://namespace.so/docs/features/faster-github-actions). To try it yourselves, feel free to create an account at https://cloud.namespace.so/ and let us know the workspace identifier, and we’ll change it to a test environment. Then, you can fork our minimal reproduction and run its GitHub Actions workflow: https://github.com/nscloud-demo/snapcraft-repro. GitHub actions snippet that triggers this condition: ``` jobs: namespace: runs-on: - nscloud-ubuntu-24.04-systemd-amd64-4x16 steps: - name: Checkout uses: actions/checkout@v4 - uses: snapcore/action-build@v1 ``` And frequently, the build action fails to start the build container. Here are the last records of `snapcraft` logs: ``` 2025-01-22 10:40:37.257 Starting instance 2025-01-22 10:40:37.257 Executing on host: lxc --project snapcraft start local:snapcraft-ghostty-on-amd64-for-amd64-1740 2025-01-22 10:40:37.537 Executing in container: lxc --project snapcraft exec local:snapcraft-ghostty-on-amd64-for-amd64-1740 -- env CRAFT_MANAGED_MODE=1 SNAPCRAFT_BUILD_INFO=1 'SNAPCRAFT_IMAGE_INFO={"build_url":"https://github.com/nscloud-demo/breakpoint/actions/runs/12892802672"}' DEBIAN_FRONTEND=noninteractive DEBCONF_NONINTERACTIVE_SEEN=true DEBIAN_PRIORITY=critical test -f /etc/craft-instance.conf 2025-01-22 10:40:42.610 Incompatible base detected: instance config is empty. 2025-01-22 10:40:42.614 Traceback (most recent call last): 2025-01-22 10:40:42.614 File "/snap/snapcraft/13181/lib/python3.10/site-packages/craft_application/application.py", line 663, in run 2025-01-22 10:40:42.614 return_code = self._run_inner() 2025-01-22 10:40:42.614 File "/snap/snapcraft/13181/lib/python3.10/site-packages/snapcraft/application.py", line 202, in _run_inner 2025-01-22 10:40:42.614 return_code = super()._run_inner() 2025-01-22 10:40:42.614 File "/snap/snapcraft/13181/lib/python3.10/site-packages/craft_application/application.py", line 647, in _run_inner 2025-01-22 10:40:42.614 self.run_managed(platform, build_for) 2025-01-22 10:40:42.614 File "/snap/snapcraft/13181/lib/python3.10/site-packages/craft_application/application.py", line 443, in run_managed 2025-01-22 10:40:42.614 with self.services.provider.instance( 2025-01-22 10:40:42.614 File "/snap/snapcraft/13181/usr/lib/python3.10/contextlib.py", line 135, in __enter__ 2025-01-22 10:40:42.614 return next(self.gen) 2025-01-22 10:40:42.614 File "/snap/snapcraft/13181/lib/python3.10/site-packages/craft_application/services/provider.py", line 153, in instance 2025-01-22 10:40:42.614 with provider.launched_environment( 2025-01-22 10:40:42.614 File "/snap/snapcraft/13181/usr/lib/python3.10/contextlib.py", line 135, in __enter__ 2025-01-22 10:40:42.614 return next(self.gen) 2025-01-22 10:40:42.614 File "/snap/snapcraft/13181/lib/python3.10/site-packages/craft_providers/lxd/lxd_provider.py", line 143, in launched_environment 2025-01-22 10:40:42.614 instance = launch( 2025-01-22 10:40:42.614 File "/snap/snapcraft/13181/lib/python3.10/site-packages/craft_providers/lxd/launcher.py", line 783, in launch 2025-01-22 10:40:42.614 _create_instance( 2025-01-22 10:40:42.614 File "/snap/snapcraft/13181/lib/python3.10/site-packages/craft_providers/lxd/launcher.py", line 229, in _create_instance 2025-01-22 10:40:42.614 base_configuration.warmup(executor=instance) 2025-01-22 10:40:42.614 File "/snap/snapcraft/13181/lib/python3.10/site-packages/craft_providers/base.py", line 1082, in warmup 2025-01-22 10:40:42.614 self._ensure_setup_completed(executor=executor) 2025-01-22 10:40:42.614 File "/snap/snapcraft/13181/lib/python3.10/site-packages/craft_providers/base.py", line 227, in _ensure_setup_completed 2025-01-22 10:40:42.614 raise BaseCompatibilityError(reason="instance config is empty") 2025-01-22 10:40:42.614 craft_providers.errors.BaseCompatibilityError: Incompatible base detected: instance config is empty. 2025-01-22 10:40:42.614 Clean incompatible instance and retry the requested operation. 2025-01-22 10:40:42.614 Recommended resolution: Clean incompatible instance and retry the requested operation. 2025-01-22 10:40:42.614 Full execution log: '/home/runner/.local/state/snapcraft/log/snapcraft-20250122-103913.054722.log' ``` ### part yaml ```shell ``` ### Relevant log output See above. But we can provide the full log files if needed. Let us know!