feat: proper logging for the fetch-service (#56)

This commit redirects the output of the fetch-service to a file. Since we plan
to have the fetch-service outlive the application that spawned it, we need to
use bash to redirect the fetch-service's output to a file in a way that
persists after the application ends.

Fixes #51

craft_application/fetch.py

@@ -16,9 +16,12 @@
 """Utilities to interact with the fetch-service."""
 import contextlib
 import io
+import os
 import pathlib
 import shlex
+import signal
 import subprocess
+import time
 from dataclasses import dataclass
 from typing import Any, cast
 
@@ -181,10 +184,21 @@ def start_service() -> subprocess.Popen[str] | None:
     # Accept permissive sessions
     cmd.append("--permissive-mode")
 
-    emit.debug(f"Launching fetch-service with '{shlex.join(cmd)}'")
+    log_filepath = _get_log_filepath()
+    log_filepath.parent.mkdir(parents=True, exist_ok=True)
+
+    str_cmd = f"{shlex.join(cmd)} > {log_filepath.absolute()}"
+    emit.debug(f"Launching fetch-service with '{str_cmd}'")
 
     fetch_process = subprocess.Popen(
-        cmd, env=env, stdout=subprocess.PIPE, stderr=subprocess.STDOUT, text=True
+        ["bash", "-c", str_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
@@ -193,17 +207,18 @@ def start_service() -> subprocess.Popen[str] | None:
 
     if fetch_process.poll() is not None:
         # fetch-service already exited, something is wrong
-        stdout = ""
-        if fetch_process.stdout is not None:
-            stdout = fetch_process.stdout.read()
+        log = log_filepath.read_text()
+        lines = log.splitlines()
+        error_lines = [line for line in lines if "ERROR:" in line]
+        error_text = "\n".join(error_lines)
 
-        if "bind: address already in use" in stdout:
+        if "bind: address already in use" in error_text:
             proxy, control = _DEFAULT_CONFIG.proxy, _DEFAULT_CONFIG.control
             message = f"fetch-service ports {proxy} and {control} are already in use."
             details = None
         else:
             message = "Error spawning the fetch-service."
-            details = stdout
+            details = error_text
         raise errors.FetchServiceError(message, details=details)
 
     status = retry(
@@ -225,11 +240,16 @@ 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:
-        fetch_process.wait(timeout=1.0)
-    except subprocess.TimeoutExpired:
-        fetch_process.kill()
+        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)
 
 
 def create_session() -> SessionData:
@@ -490,3 +510,9 @@ def _get_certificate_dir() -> pathlib.Path:
 def _check_installed() -> bool:
     """Check whether the fetch-service is installed."""
     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"

tests/integration/services/test_fetch.py

@@ -47,25 +47,19 @@ def _set_test_certificate_dir():
     with mock.patch.object(fetch, "_get_certificate_dir", return_value=cert_dir):
         fetch._obtain_certificate()
 
-    yield
-
-    shutil.rmtree(cert_dir)
-
 
 @pytest.fixture(autouse=True)
 def _set_test_base_dirs(mocker):
     original = fetch._get_service_base_dir()
     test_dir = original / "test"
-    test_dir.mkdir(exist_ok=True)
+    if test_dir.exists():
+        shutil.rmtree(test_dir)
+    test_dir.mkdir()
     mocker.patch.object(fetch, "_get_service_base_dir", return_value=test_dir)
 
     cert_dir = _get_fake_certificate_dir()
     mocker.patch.object(fetch, "_get_certificate_dir", return_value=cert_dir)
 
-    yield
-
-    shutil.rmtree(test_dir)
-
 
 @pytest.fixture
 def app_service(app_metadata, fake_services):
@@ -149,6 +143,36 @@ def test_create_teardown_session(app_service, mocker, tmp_path, monkeypatch):
     assert expected_report.is_file()
 
 
+def test_service_logging(app_service, mocker, tmp_path, monkeypatch):
+    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()
+
+    app_service.setup()
+
+    mock_instance = mock.MagicMock(spec_set=craft_providers.Executor)
+
+    # Create and teardown two sessions
+    app_service.create_session(mock_instance)
+    app_service.teardown_session()
+    app_service.create_session(mock_instance)
+    app_service.teardown_session()
+
+    # Check the logfile for the creation/deletion of the two sessions
+    expected = 2
+    assert logfile.is_file()
+    lines = logfile.read_text().splitlines()
+    create = discard = 0
+    for line in lines:
+        if "creating session" in line:
+            create += 1
+        if "discarding session" in line:
+            discard += 1
+    assert create == discard == expected
+
+
 # Bash script to setup the build instance before the actual testing.
 setup_environment = (
     textwrap.dedent(

tests/unit/test_fetch.py

@@ -15,6 +15,7 @@
 #  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
@@ -123,19 +124,27 @@ def test_start_service(mocker, tmp_path):
     popen_call = mock_popen.mock_calls[0]
     assert popen_call == call(
         [
-            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",
+            "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",
+                ]
+            )
+            + f" > {fetch._get_log_filepath()}",
         ],
         env={"FETCH_SERVICE_AUTH": AUTH, "FETCH_APT_RELEASE_PUBLIC_KEY": "DEADBEEF"},
         stdout=subprocess.PIPE,
         stderr=subprocess.STDOUT,
         text=True,
+        start_new_session=True,
     )