fix: properly log the fetch-service's output (#555)

The issue with redirecting the fetch-service's output to a file via bash is
this: as a strict snap, the fetch-service cannot inherit the file descriptors
from the bash process if said process is spawned by a classic snap. This is
the case when the integration is controlled by a snapped craft tool:

```
+----------------------------+        +-------------+
|(snapped) craft-tool -> bash| -----> |fetch-service|
+----------------------------+        +-------------+
```

The solution here is to pass the path to the logfile to the fetch-service itself
through a new, recently implemented command-line option. We also update the
logpath to use tmp, and print the path when emitting the warning about the
integration being experimental.

Refs:

- https://bugs.launchpad.net/ubuntu/+source/snapd/+bug/1849753

Fixes #550

craft_application/fetch.py

@@ -17,13 +17,11 @@
 import contextlib
 import io
 import logging
-import os
 import pathlib
 import shlex
-import signal
 import subprocess
-import time
 from dataclasses import dataclass
+from functools import cache
 from typing import Any, cast
 
 import craft_providers
@@ -137,14 +135,7 @@ def start_service() -> subprocess.Popen[str] | None:
         return None
 
     # Check that the fetch service is actually installed
-    if not _check_installed():
-        raise errors.FetchServiceError(
-            "The 'fetch-service' snap is not installed.",
-            resolution=(
-                "Install the fetch-service snap via "
-                "'snap install --channel=candidate fetch-service'."
-            ),
-        )
+    verify_installed()
 
     cmd = [_FETCH_BINARY]
 
@@ -173,21 +164,19 @@ def start_service() -> subprocess.Popen[str] | None:
     # Shutdown after 5 minutes with no live sessions
     cmd.append("--idle-shutdown=300")
 
-    log_filepath = _get_log_filepath()
+    log_filepath = get_log_filepath()
     log_filepath.parent.mkdir(parents=True, exist_ok=True)
+    cmd.append(f"--log-file={log_filepath}")
 
-    str_cmd = f"{shlex.join(cmd)} > {log_filepath.absolute()}"
+    str_cmd = shlex.join(cmd)
     emit.debug(f"Launching fetch-service with '{str_cmd}'")
 
     fetch_process = subprocess.Popen(
-        ["bash", "-c", str_cmd],
+        cmd,
         env=env,
         stdout=subprocess.PIPE,
         stderr=subprocess.STDOUT,
         text=True,
-        # Start a new session because when killing the service we need to kill
-        # both 'bash' and the 'fetch' it spawns.
-        start_new_session=True,
     )
 
     # Wait a bit for the service to come online
@@ -229,16 +218,11 @@ def stop_service(fetch_process: subprocess.Popen[str]) -> None:
 
     This function first calls terminate(), and then kill() after a short time.
     """
+    fetch_process.terminate()
     try:
-        os.killpg(os.getpgid(fetch_process.pid), signal.SIGTERM)
-    except ProcessLookupError:
-        return
-
-    # Give the shell and fetch-service a chance to terminate
-    time.sleep(0.2)
-
-    with contextlib.suppress(ProcessLookupError):
-        os.killpg(os.getpgid(fetch_process.pid), signal.SIGKILL)
+        fetch_process.wait(timeout=1.0)
+    except subprocess.TimeoutExpired:
+        fetch_process.kill()
 
 
 def create_session(*, strict: bool) -> SessionData:
@@ -294,6 +278,28 @@ def configure_instance(
     return net_info.env
 
 
+def get_log_filepath() -> pathlib.Path:
+    """Get the path containing the fetch-service's output."""
+    # All craft tools log to the same place, because it's a single fetch-service
+    # instance. It needs to be a location that the fetch-service, as a strict
+    # snap, can write to.
+    logdir = _get_service_base_dir() / "craft-logs"
+    logdir.mkdir(exist_ok=True, parents=True)
+    return logdir / "fetch-service.log"
+
+
+def verify_installed() -> None:
+    """Verify that the fetch-service is installed, raising an error if it isn't."""
+    if not _check_installed():
+        raise errors.FetchServiceError(
+            "The 'fetch-service' snap is not installed.",
+            resolution=(
+                "Install the fetch-service snap via "
+                "'snap install --channel=candidate fetch-service'."
+            ),
+        )
+
+
 def _service_request(
     verb: str, endpoint: str, json: dict[str, Any] | None = None
 ) -> requests.Response:
@@ -318,6 +324,7 @@ def _service_request(
     return response
 
 
+@cache
 def _get_service_base_dir() -> pathlib.Path:
     """Get the base directory to contain the fetch-service's runtime files."""
     input_line = "sh -c 'echo $SNAP_USER_COMMON'"
@@ -499,12 +506,6 @@ def _check_installed() -> bool:
     return pathlib.Path(_FETCH_BINARY).is_file()
 
 
-def _get_log_filepath() -> pathlib.Path:
-    base_dir = _get_service_base_dir()
-
-    return base_dir / "craft/fetch-log.txt"
-
-
 def _execute_run(
     instance: craft_providers.Executor, cmd: list[str]
 ) -> subprocess.CompletedProcess[str]:

craft_application/services/fetch.py

@@ -84,10 +84,14 @@ def setup(self) -> None:
         super().setup()
 
         if not self._services.ProviderClass.is_managed():
+            # Early fail if the fetch-service is not installed.
+            fetch.verify_installed()
+
             # Emit a warning, but only on the host-side.
+            logpath = fetch.get_log_filepath()
             emit.message(
-                "Warning: the fetch-service integration is experimental "
-                "and still in development."
+                "Warning: the fetch-service integration is experimental. "
+                f"Logging output to {str(logpath)!r}."
             )
 
             self._fetch_process = fetch.start_service()

docs/reference/changelog.rst

@@ -11,7 +11,9 @@ Application
 ===========
 
 - The fetch-service integration now assumes that the fetch-service snap is
-  tracking the ``latest/candidate`` channel.
+  tracking the ``latest/candidate``.
+- Fix an issue where the fetch-service output was not correctly logged when
+  running in a snapped craft tool.
 
 Commands
 ========

tests/integration/services/test_fetch.py

@@ -174,8 +174,17 @@ def test_service_logging(app_service, mocker, tmp_path, monkeypatch, mock_instan
     monkeypatch.chdir(tmp_path)
     mocker.patch.object(fetch, "_get_gateway", return_value="127.0.0.1")
 
-    logfile = fetch._get_log_filepath()
-    assert not logfile.is_file()
+    # Mock get_log_filepath() so that the test doesn't interfere with whatever
+    # fetch-service is running on the system.
+    original_logpath = fetch.get_log_filepath()
+    mocker.patch.object(
+        fetch,
+        "get_log_filepath",
+        return_value=original_logpath.with_name("fetch-testcraft.log"),
+    )
+
+    logfile = fetch.get_log_filepath()
+    logfile.unlink(missing_ok=True)
 
     app_service.setup()
 

tests/unit/services/test_fetch.py

@@ -24,6 +24,7 @@
 """
 import contextlib
 import json
+import pathlib
 import re
 import textwrap
 from datetime import datetime
@@ -175,13 +176,16 @@ def temporarily_pull_file(*, source, missing_ok):
 def test_warning_experimental(mocker, fetch_service, run_on_host, emitter):
     """The fetch-service warning should only be emitted when running on the host."""
     mocker.patch.object(fetch, "start_service")
+    mocker.patch.object(fetch, "verify_installed")
+    mocker.patch.object(fetch, "_get_service_base_dir", return_value=pathlib.Path())
     mocker.patch.object(ProviderService, "is_managed", return_value=not run_on_host)
 
     fetch_service.setup()
 
+    logpath = fetch.get_log_filepath()
     warning = (
-        "Warning: the fetch-service integration is experimental "
-        "and still in development."
+        "Warning: the fetch-service integration is experimental. "
+        f"Logging output to {str(logpath)!r}."
     )
     warning_emitted = call("message", warning) in emitter.interactions
 

tests/unit/test_fetch.py

@@ -15,7 +15,6 @@
 #  along with this program.  If not, see <http://www.gnu.org/licenses/>.
 """Tests for fetch-service-related functions."""
 import re
-import shlex
 import subprocess
 from pathlib import Path
 from unittest import mock
@@ -108,30 +107,23 @@ def test_start_service(mocker, tmp_path):
     popen_call = mock_popen.mock_calls[0]
     assert popen_call == call(
         [
-            "bash",
-            "-c",
-            shlex.join(
-                [
-                    fetch._FETCH_BINARY,
-                    f"--control-port={CONTROL}",
-                    f"--proxy-port={PROXY}",
-                    f"--config={tmp_path/'config'}",
-                    f"--spool={tmp_path/'spool'}",
-                    f"--cert={fake_cert}",
-                    f"--key={fake_key}",
-                    "--permissive-mode",
-                    "--idle-shutdown=300",
-                ]
-            )
-            + f" > {fetch._get_log_filepath()}",
+            fetch._FETCH_BINARY,
+            f"--control-port={CONTROL}",
+            f"--proxy-port={PROXY}",
+            f"--config={tmp_path / 'config'}",
+            f"--spool={tmp_path / 'spool'}",
+            f"--cert={fake_cert}",
+            f"--key={fake_key}",
+            "--permissive-mode",
+            "--idle-shutdown=300",
+            f"--log-file={tmp_path / 'craft-logs/fetch-service.log'}",
         ],
         env={
             "FETCH_SERVICE_AUTH": AUTH,
         },
         stdout=subprocess.PIPE,
         stderr=subprocess.STDOUT,
         text=True,
-        start_new_session=True,
     )