feat(web): add boundary log lines to job worker execution

l4d2host/instances.py

@@ -8,6 +8,14 @@ from l4d2host.service_control import start_service, stop_service
 from l4d2host.spec import load_spec
 
 
+def _emit_step(msg: str, on_stdout: Callable[[str], None] | None, passthrough: bool) -> None:
+    formatted = f"Step: {msg}"
+    if on_stdout is not None:
+        on_stdout(formatted)
+    elif passthrough:
+        print(formatted, flush=True)
+
+
 DEFAULT_ROOT = DEFAULT_LEFT4ME_ROOT
 
 
@@ -24,6 +32,7 @@ def initialize_instance(
     root = get_left4me_root() if root is None else Path(root)
     spec = load_spec(spec_path)
 
+    _emit_step("creating instance directories...", on_stdout, passthrough)
     instance_dir = root / "instances" / name
     runtime_dir = root / "runtime" / name
     (runtime_dir / "upper").mkdir(parents=True, exist_ok=True)
@@ -34,6 +43,7 @@ def initialize_instance(
     lowerdirs = [str(overlay_path(overlay, root=root)) for overlay in spec.overlays]
     lowerdirs.append(str(root / "installation"))
 
+    _emit_step("writing instance.env...", on_stdout, passthrough)
     instance_env = "\n".join(
         [
             f"L4D2_PORT={spec.port}",
@@ -43,8 +53,10 @@ def initialize_instance(
     ) + "\n"
     (instance_dir / "instance.env").write_text(instance_env)
 
+    _emit_step("writing server.cfg...", on_stdout, passthrough)
     server_cfg = "\n".join(spec.config) if spec.config else ""
     (instance_dir / "server.cfg").write_text(server_cfg)
+    _emit_step("initialization complete.", on_stdout, passthrough)
 
 
 def _load_instance_env(path: Path) -> dict[str, str]:
@@ -72,6 +84,7 @@ def start_instance(
 
     env = _load_instance_env(instance_dir / "instance.env")
 
+    _emit_step("mounting runtime overlay...", on_stdout, passthrough)
     run_command(
         [
             "fuse-overlayfs",
@@ -89,10 +102,12 @@ def start_instance(
         should_cancel=should_cancel,
     )
 
+    _emit_step("copying server.cfg to runtime...", on_stdout, passthrough)
     target_cfg = runtime_dir / "merged" / "left4dead2" / "cfg" / "server.cfg"
     target_cfg.parent.mkdir(parents=True, exist_ok=True)
     shutil.copy2(instance_dir / "server.cfg", target_cfg)
 
+    _emit_step("starting systemd service...", on_stdout, passthrough)
     start_service(
         name,
         on_stdout=on_stdout,
@@ -100,6 +115,7 @@ def start_instance(
         passthrough=passthrough,
         should_cancel=should_cancel,
     )
+    _emit_step("start complete.", on_stdout, passthrough)
 
 
 def stop_instance(
@@ -112,6 +128,7 @@ def stop_instance(
     should_cancel: Callable[[], bool] | None = None,
 ) -> None:
     root = get_left4me_root() if root is None else Path(root)
+    _emit_step("stopping systemd service...", on_stdout, passthrough)
     stop_service(
         name,
         on_stdout=on_stdout,
@@ -119,6 +136,7 @@ def stop_instance(
         passthrough=passthrough,
         should_cancel=should_cancel,
     )
+    _emit_step("unmounting runtime overlay...", on_stdout, passthrough)
     run_command(
         ["fusermount3", "-u", str(root / "runtime" / name / "merged")],
         on_stdout=on_stdout,
@@ -126,6 +144,7 @@ def stop_instance(
         passthrough=passthrough,
         should_cancel=should_cancel,
     )
+    _emit_step("stop complete.", on_stdout, passthrough)
 
 
 def delete_instance(
@@ -144,6 +163,7 @@ def delete_instance(
     if not instance_dir.exists() and not runtime_dir.exists():
         return
 
+    _emit_step("stopping systemd service (if running)...", on_stdout, passthrough)
     stop_service(
         name,
         on_stdout=on_stdout,
@@ -154,6 +174,7 @@ def delete_instance(
 
     merged = runtime_dir / "merged"
     if merged.is_mount():
+        _emit_step("unmounting runtime overlay (if mounted)...", on_stdout, passthrough)
         run_command(
             ["fusermount3", "-u", str(merged)],
             on_stdout=on_stdout,
@@ -162,7 +183,9 @@ def delete_instance(
             should_cancel=should_cancel,
         )
 
+    _emit_step("removing instance files...", on_stdout, passthrough)
     if instance_dir.exists():
         shutil.rmtree(instance_dir)
     if runtime_dir.exists():
         shutil.rmtree(runtime_dir)
+    _emit_step("delete complete.", on_stdout, passthrough)

l4d2host/tests/test_initialize.py

@@ -1,6 +1,8 @@
+import sys
+from io import StringIO
 from pathlib import Path
 
-from l4d2host.instances import initialize_instance
+from l4d2host.instances import initialize_instance, _emit_step
 
 
 def test_initialize_writes_files(tmp_path: Path) -> None:
@@ -31,3 +33,35 @@ def test_initialize_uses_configured_left4me_root(tmp_path: Path, monkeypatch) ->
 
     env = (tmp_path / "instances/alpha/instance.env").read_text()
     assert f"L4D2_LOWERDIRS={tmp_path}/overlays/standard:{tmp_path}/installation" in env
+
+
+def test_emit_step_uses_callback() -> None:
+    calls: list[str] = []
+    _emit_step("test step", on_stdout=calls.append, passthrough=False)
+    assert calls == ["Step: test step"]
+
+
+def test_emit_step_uses_passthrough_stdout(monkeypatch) -> None:
+    fake_out = StringIO()
+    monkeypatch.setattr(sys, "stdout", fake_out)
+    _emit_step("passthrough step", on_stdout=None, passthrough=True)
+    assert fake_out.getvalue() == "Step: passthrough step\n"
+
+
+def test_emit_step_does_nothing_if_no_target() -> None:
+    _emit_step("silent step", on_stdout=None, passthrough=False)
+
+
+def test_initialize_instance_emits_steps(tmp_path: Path) -> None:
+    spec = tmp_path / "spec.yaml"
+    spec.write_text("port: 27015\noverlays: [standard]\n")
+
+    steps: list[str] = []
+    initialize_instance("alpha", spec, root=tmp_path, on_stdout=steps.append)
+
+    assert steps == [
+        "Step: creating instance directories...",
+        "Step: writing instance.env...",
+        "Step: writing server.cfg...",
+        "Step: initialization complete.",
+    ]

l4d2web/services/job_worker.py

@@ -7,6 +7,8 @@ import time
 from sqlalchemy import func, select
 from sqlalchemy.orm import Session
 
+from typing import Callable
+
 from l4d2web.db import session_scope
 from l4d2web.models import Job, JobLog, Server
 from l4d2web.services.host_commands import CommandCancelledError
@@ -80,12 +82,17 @@ def run_worker_once() -> bool:
 def run_job(job_id: int) -> None:
     from l4d2web.services import l4d2_facade
 
+    server_name = "unknown"
     with session_scope() as db:
         job = db.scalar(select(Job).where(Job.id == job_id))
         if job is None:
             return
         operation = job.operation
         server_id = job.server_id
+        if server_id is not None:
+            server = db.scalar(select(Server).where(Server.id == server_id))
+            if server is not None:
+                server_name = server.name
 
     max_chars = 4096
 
@@ -104,21 +111,73 @@ def run_job(job_id: int) -> None:
         if should_cancel():
             raise CommandCancelledError(returncode=1, cmd=[operation], output="", stderr="")
 
+    def _run_with_boundaries(action: str, target: str, func: Callable, *args, **kwargs):
+        append_job_log_line(job_id, "stdout", f"starting {action} for {target}")
+        func(*args, **kwargs)
+        append_job_log_line(job_id, "stdout", f"finished {action} successfully")
+
     try:
         if operation == "install":
-            l4d2_facade.install_runtime(on_stdout=on_stdout, on_stderr=on_stderr, should_cancel=should_cancel)
+            _run_with_boundaries(
+                "install",
+                "server",
+                l4d2_facade.install_runtime,
+                on_stdout=on_stdout,
+                on_stderr=on_stderr,
+                should_cancel=should_cancel,
+            )
         elif operation in SERVER_OPERATIONS and server_id is None:
             raise ValueError(f"{operation} job has no server_id")
         elif operation == "initialize":
-            l4d2_facade.initialize_server(server_id, on_stdout=on_stdout, on_stderr=on_stderr, should_cancel=should_cancel)
+            _run_with_boundaries(
+                "initialize",
+                server_name,
+                l4d2_facade.initialize_server,
+                server_id,
+                on_stdout=on_stdout,
+                on_stderr=on_stderr,
+                should_cancel=should_cancel,
+            )
         elif operation == "start":
-            l4d2_facade.initialize_server(server_id, on_stdout=on_stdout, on_stderr=on_stderr, should_cancel=should_cancel)
+            _run_with_boundaries(
+                "initialize",
+                server_name,
+                l4d2_facade.initialize_server,
+                server_id,
+                on_stdout=on_stdout,
+                on_stderr=on_stderr,
+                should_cancel=should_cancel,
+            )
             raise_if_cancelled()
-            l4d2_facade.start_server(server_id, on_stdout=on_stdout, on_stderr=on_stderr, should_cancel=should_cancel)
+            _run_with_boundaries(
+                "start",
+                server_name,
+                l4d2_facade.start_server,
+                server_id,
+                on_stdout=on_stdout,
+                on_stderr=on_stderr,
+                should_cancel=should_cancel,
+            )
         elif operation == "stop":
-            l4d2_facade.stop_server(server_id, on_stdout=on_stdout, on_stderr=on_stderr, should_cancel=should_cancel)
+            _run_with_boundaries(
+                "stop",
+                server_name,
+                l4d2_facade.stop_server,
+                server_id,
+                on_stdout=on_stdout,
+                on_stderr=on_stderr,
+                should_cancel=should_cancel,
+            )
         elif operation == "delete":
-            l4d2_facade.delete_server(server_id, on_stdout=on_stdout, on_stderr=on_stderr, should_cancel=should_cancel)
+            _run_with_boundaries(
+                "delete",
+                server_name,
+                l4d2_facade.delete_server,
+                server_id,
+                on_stdout=on_stdout,
+                on_stderr=on_stderr,
+                should_cancel=should_cancel,
+            )
         else:
             raise ValueError(f"unknown job operation: {operation}")
 

l4d2web/tests/test_job_worker.py

@@ -126,13 +126,13 @@ def test_successful_start_job_logs_and_refreshes_server_state(seeded_worker, mon
     def fake_initialize(server_id, *, on_stdout=None, on_stderr=None, should_cancel=None):
         del should_cancel
         calls.append(("initialize", server_id))
-        on_stdout("initialized")
+        on_stdout("Step: creating instance directories...")
         on_stderr("init warning")
 
     def fake_start(server_id, *, on_stdout=None, on_stderr=None, should_cancel=None):
         del should_cancel
         calls.append(("start", server_id))
-        on_stdout("started")
+        on_stdout("Step: mounting runtime overlay...")
 
     monkeypatch.setattr(l4d2_facade, "initialize_server", fake_initialize)
     monkeypatch.setattr(l4d2_facade, "start_server", fake_start)
@@ -154,9 +154,13 @@ def test_successful_start_job_logs_and_refreshes_server_state(seeded_worker, mon
     assert job.finished_at is not None
     assert job.updated_at is not None
     assert lines == [
-        (1, "stdout", "initialized"),
-        (2, "stderr", "init warning"),
-        (3, "stdout", "started"),
+        (1, "stdout", "starting initialize for alpha"),
+        (2, "stdout", "Step: creating instance directories..."),
+        (3, "stderr", "init warning"),
+        (4, "stdout", "finished initialize successfully"),
+        (5, "stdout", "starting start for alpha"),
+        (6, "stdout", "Step: mounting runtime overlay..."),
+        (7, "stdout", "finished start successfully"),
     ]
     assert server is not None
     assert server.actual_state == "running"
@@ -192,6 +196,7 @@ def test_called_process_error_fails_job_and_sets_server_error(seeded_worker, mon
     assert job.exit_code == 7
     assert server is not None
     assert server.last_error == "stop failed"
+    assert "starting stop for alpha" in lines
     assert "stop failed" in lines
 
 
@@ -218,6 +223,8 @@ def test_refresh_failure_does_not_hide_operation_failure(seeded_worker, monkeypa
     assert job.exit_code == 7
     assert server is not None
     assert server.last_error == "stop failed"
+    assert "starting stop for alpha" in lines
+    assert "stop failed" in lines
     assert "status refresh failed: status down" in lines
 
 
@@ -292,6 +299,7 @@ def test_cancelled_process_finishes_job_as_cancelled(seeded_worker, monkeypatch)
     assert job.finished_at is not None
     assert server is not None
     assert server.last_error == "job cancelled; runtime state may be partial"
+    assert "starting stop for alpha" in lines
     assert "terminating" in lines
     assert "job cancelled; runtime state may be partial" in lines