Keep a failed Studio restart from reading as an operator stop

docs/USER_GUIDE.md

@@ -491,7 +491,16 @@ Decoys shows startup progress or an actionable diagnostic reason. Normal stopped
 and disabled states stay quiet. Pull down on the list or press **Command-R** to
 reload that evidence; refreshing does not bypass startup checks or restart the guest. An enabled
 host whose startup failed is retried on a later network scan, no more often
-than once per minute. An intentionally stopped host stays stopped.
+than once per minute. An intentionally stopped host stays stopped, and the
+sensor startup log says so: "Studio Mini deep decoy is stopped by the operator;
+enable it from the Decoys tab to publish it". A startup failure is logged as a
+warning that carries the reason shown on the Degraded badge.
+
+A Restart that stops the host but fails to bring it back saves the host as
+Degraded with the failure recorded, not as stopped. It is retried like any
+other startup failure, so an interrupted restart never turns into a silent
+stop across sensor restarts. Every enable, disable, and restart is written to
+the sensor log with the paired client that requested it and the outcome.
 
 Restarting or upgrading the sensor preserves the Studio host's saved state.
 Its five services do not count against the separate classic host-listener

sensor/src/squirrelops_home_sensor/__main__.py

@@ -799,6 +799,21 @@ async def stop(self) -> None:
         await self._orchestrator.stop_all()
 
 
+def _log_deep_decoy_not_started(diagnostics: dict[str, str | None]) -> None:
+    """Tell the operator whether Studio is stopped on purpose or failed to start."""
+    if diagnostics.get("status") == "stopped":
+        logger.info(
+            "Studio Mini deep decoy is stopped by the operator; enable it from "
+            "the Decoys tab to publish it"
+        )
+        return
+    logger.warning(
+        "Studio Mini deep decoy is unavailable; no real-protocol ports were "
+        "published. Reason: %s",
+        diagnostics.get("reason") or "no reason recorded",
+    )
+
+
 # ---------------------------------------------------------------------------
 # CLI argument parsing
 # ---------------------------------------------------------------------------
@@ -1480,10 +1495,7 @@ async def _ws_broadcast(event: dict) -> None:
                 runtime.deep_start_attempted = True
                 deep_started = await deep_orchestrator.start()
                 if not deep_started:
-                    logger.warning(
-                        "Studio Mini deep decoy is unavailable; no real-protocol "
-                        "ports were published"
-                    )
+                    _log_deep_decoy_not_started(deep_orchestrator.diagnostics)
             runtime.mimic_start_attempted = True
             resumed = await mimic_orchestrator.resume_active()
             if resumed:

sensor/src/squirrelops_home_sensor/api/routes_decoys.py

@@ -2,6 +2,7 @@
 from __future__ import annotations
 
 import json as json_mod
+import logging
 from datetime import UTC, datetime
 from typing import Any
 
@@ -12,9 +13,29 @@
 from squirrelops_home_sensor.api.deps import get_db, verify_client_cert
 from squirrelops_home_sensor.api.routes_scouts import get_mimic_orchestrator
 
+logger = logging.getLogger(__name__)
+
 router = APIRouter(prefix="/decoys", tags=["decoys"])
 
 
+def _audit_lifecycle_action(
+    action: str, row: Any, succeeded: bool, auth: dict[str, Any],
+) -> None:
+    """Leave a value-free trail of who changed a decoy's run state."""
+    logger.info(
+        "Decoy %s %s by %s (%s): %s '%s' (id=%d) on %s:%s",
+        action,
+        "succeeded" if succeeded else "failed",
+        str(auth.get("client_name") or "unknown"),
+        str(auth.get("fingerprint") or "unknown"),
+        row["decoy_type"],
+        row["name"],
+        int(row["id"]),
+        row["bind_address"],
+        row["port"],
+    )
+
+
 # ---------- Dependency stubs ----------
 
 
@@ -252,7 +273,7 @@ async def restart_decoy(
     orchestrator=Depends(get_decoy_orchestrator),
     mimic_orchestrator=Depends(get_mimic_orchestrator),
     deep_orchestrator=Depends(get_deep_decoy_orchestrator),
-    _auth: dict = Depends(verify_client_cert),
+    auth: dict = Depends(verify_client_cert),
 ):
     """Restart the live listener and report failure instead of faking state."""
     existing = await _get_decoy_or_404(db, decoy_id)
@@ -278,6 +299,7 @@ async def restart_decoy(
             )
         succeeded = await orchestrator.restart_decoy(decoy_id)
 
+    _audit_lifecycle_action("restart", existing, succeeded, auth)
     if not succeeded:
         raise HTTPException(
             status_code=status.HTTP_409_CONFLICT,
@@ -295,7 +317,7 @@ async def enable_decoy(
     orchestrator=Depends(get_decoy_orchestrator),
     mimic_orchestrator=Depends(get_mimic_orchestrator),
     deep_orchestrator=Depends(get_deep_decoy_orchestrator),
-    _auth: dict = Depends(verify_client_cert),
+    auth: dict = Depends(verify_client_cert),
 ):
     """Start a stopped decoy and only mark it active after it is reachable."""
     existing = await _get_decoy_or_404(db, decoy_id)
@@ -321,6 +343,7 @@ async def enable_decoy(
             )
         succeeded = await orchestrator.enable_decoy(decoy_id)
 
+    _audit_lifecycle_action("enable", existing, succeeded, auth)
     if not succeeded:
         raise HTTPException(
             status_code=status.HTTP_409_CONFLICT,
@@ -338,7 +361,7 @@ async def disable_decoy(
     orchestrator=Depends(get_decoy_orchestrator),
     mimic_orchestrator=Depends(get_mimic_orchestrator),
     deep_orchestrator=Depends(get_deep_decoy_orchestrator),
-    _auth: dict = Depends(verify_client_cert),
+    auth: dict = Depends(verify_client_cert),
 ):
     """Stop the live listener before reporting the decoy as stopped."""
     existing = await _get_decoy_or_404(db, decoy_id)
@@ -364,6 +387,7 @@ async def disable_decoy(
             )
         succeeded = await orchestrator.disable_decoy(decoy_id)
 
+    _audit_lifecycle_action("disable", existing, succeeded, auth)
     if not succeeded:
         raise HTTPException(
             status_code=status.HTTP_409_CONFLICT,

sensor/src/squirrelops_home_sensor/decoys/deep/orchestrator.py

@@ -218,7 +218,9 @@ async def start(self) -> bool:
             row = await cursor.fetchone()
             if row is None:
                 return await self._provision()
-            if row["status"] != "active":
+            if row["status"] == "stopped":
+                # Only an operator stop is intent. A persisted "degraded" row
+                # is a host that should run but failed, so it is retried.
                 self._startup_status = "stopped"
                 self._failure_reason = None
                 return False
@@ -839,10 +841,48 @@ async def enable(self, decoy_id: int) -> bool:
             return False if row is None else await self._activate_existing(row)
 
     async def restart(self, decoy_id: int) -> bool:
-        if self._active is not None:
-            if not await self.disable(decoy_id):
-                return False
-        return await self.enable(decoy_id)
+        """Stop and re-enable the host without turning a failure into a stop.
+
+        ``disable`` persists ``stopped`` so a crash between the two halves
+        fails closed. When the re-enable half fails the operator still wants
+        the host running, so the rows are returned to ``degraded`` with the
+        failure recorded, and the next startup or reconcile retries them
+        instead of reading the interrupted restart as an intentional stop.
+        """
+        was_running = self._active is not None
+        if was_running and not await self.disable(decoy_id):
+            return False
+        if await self.enable(decoy_id):
+            return True
+        if was_running:
+            await self._record_restart_failure(decoy_id)
+        return False
+
+    async def _record_restart_failure(self, decoy_id: int) -> None:
+        cursor = await self._db.execute(
+            """SELECT host_id FROM decoys
+               WHERE decoy_type = 'deep' AND retired_at IS NULL AND id = ?""",
+            (decoy_id,),
+        )
+        row = await cursor.fetchone()
+        if row is None or row["host_id"] is None:
+            return
+        now = datetime.now(UTC).isoformat()
+        await self._db.execute(
+            """UPDATE decoys
+               SET status = 'degraded',
+                   failure_count = failure_count + 1,
+                   last_failure_at = ?,
+                   updated_at = ?
+               WHERE host_id = ? AND retired_at IS NULL""",
+            (now, now, row["host_id"]),
+        )
+        await self._db.commit()
+        logger.warning(
+            "Studio Mini deep decoy restart failed after its stop completed; "
+            "saved as degraded for retry: %s",
+            self._failure_reason or "no reason recorded",
+        )
 
     async def handle_ip_conflict(self, ip: str) -> bool:
         """Stop the deep host if a real LAN device claims its address."""

sensor/tests/integration/test_deep_decoy_orchestrator.py

@@ -327,6 +327,110 @@ async def start(self):
         assert orchestrator.diagnostics["status"] == "stopped"
 
 
+@pytest.mark.asyncio
+async def test_persisted_degraded_host_is_retried_at_startup(tmp_path) -> None:
+    """Only ``stopped`` is operator intent; a saved ``degraded`` host should run."""
+    calls: list[str] = []
+    async with aiosqlite.connect(tmp_path / "degraded.db") as db:
+        db.row_factory = aiosqlite.Row
+        await apply_migrations(db)
+        first, _ = await _orchestrator(db, calls)
+        assert await first.start() is True
+        await first.stop_all()
+        await db.execute("UPDATE decoys SET status = 'degraded' WHERE decoy_type = 'deep'")
+        await db.commit()
+
+        second, _ = await _orchestrator(db, calls)
+        try:
+            assert await second.start() is True
+            assert calls.count("guest:start") == 2
+            statuses = await (
+                await db.execute("SELECT DISTINCT status FROM decoys WHERE decoy_type = 'deep'")
+            ).fetchall()
+            assert [row[0] for row in statuses] == ["active"]
+        finally:
+            await second.stop_all()
+
+
+class _GuestThatFailsOnce(_Guest):
+    """First boot works, the second raises, later boots work again."""
+
+    boots = 0
+
+    async def start(self) -> dict[int, int]:
+        type(self).boots += 1
+        if type(self).boots == 2:
+            raise RuntimeError("runtime rejected on restart")
+        return await super().start()
+
+
+@pytest.mark.asyncio
+async def test_failed_restart_is_saved_as_degraded_not_as_an_operator_stop(tmp_path) -> None:
+    calls: list[str] = []
+    _GuestThatFailsOnce.boots = 0
+    async with aiosqlite.connect(tmp_path / "restart-fail.db") as db:
+        db.row_factory = aiosqlite.Row
+        await apply_migrations(db)
+        orchestrator, _ = await _orchestrator(
+            db, calls, guest_factory=lambda **kw: _GuestThatFailsOnce(calls, **kw),
+        )
+        assert await orchestrator.start() is True
+        service_id = int((await (
+            await db.execute("SELECT id FROM decoys WHERE decoy_type = 'deep' AND port = 22")
+        ).fetchone())["id"])
+
+        assert await orchestrator.restart(service_id) is False
+
+        rows = await (await db.execute(
+            "SELECT status, failure_count, last_failure_at FROM decoys WHERE decoy_type = 'deep'"
+        )).fetchall()
+        assert len(rows) == 5
+        assert {row["status"] for row in rows} == {"degraded"}
+        assert {row["failure_count"] for row in rows} == {1}
+        assert all(row["last_failure_at"] for row in rows)
+        assert orchestrator.diagnostics["status"] == "degraded"
+        reason = orchestrator.diagnostics["reason"]
+        assert isinstance(reason, str) and "startup failed" in reason
+
+        # The interrupted restart is retried like any other startup failure.
+        orchestrator._next_retry_at = 0
+        assert await orchestrator.reconcile() is True
+        assert orchestrator.diagnostics["status"] == "active"
+        statuses = await (
+            await db.execute("SELECT DISTINCT status FROM decoys WHERE decoy_type = 'deep'")
+        ).fetchall()
+        assert [row[0] for row in statuses] == ["active"]
+        await orchestrator.stop_all()
+
+
+@pytest.mark.asyncio
+async def test_failed_enable_of_a_stopped_host_keeps_it_stopped(tmp_path) -> None:
+    """Enable has no prior running intent to restore, so its contract is unchanged."""
+    calls: list[str] = []
+    _GuestThatFailsOnce.boots = 0
+    async with aiosqlite.connect(tmp_path / "enable-fail.db") as db:
+        db.row_factory = aiosqlite.Row
+        await apply_migrations(db)
+        orchestrator, _ = await _orchestrator(
+            db, calls, guest_factory=lambda **kw: _GuestThatFailsOnce(calls, **kw),
+        )
+        assert await orchestrator.start() is True
+        service_id = int((await (
+            await db.execute("SELECT id FROM decoys WHERE decoy_type = 'deep' AND port = 22")
+        ).fetchone())["id"])
+        assert await orchestrator.disable(service_id) is True
+
+        assert await orchestrator.enable(service_id) is False
+
+        statuses = await (
+            await db.execute("SELECT DISTINCT status FROM decoys WHERE decoy_type = 'deep'")
+        ).fetchall()
+        assert [row[0] for row in statuses] == ["stopped"]
+        orchestrator._next_retry_at = 0
+        assert await orchestrator.reconcile() is False
+        assert orchestrator.diagnostics["status"] == "stopped"
+
+
 @pytest.mark.asyncio
 async def test_restart_withdraws_and_reverifies_address_before_republish(tmp_path) -> None:
     calls: list[str] = []

sensor/tests/integration/test_entry_point.py

@@ -8,6 +8,7 @@
 from __future__ import annotations
 
 import asyncio
+import logging
 from pathlib import Path
 from typing import Any
 from unittest.mock import AsyncMock, MagicMock, patch
@@ -334,6 +335,31 @@ def patched(mock_subsystems: dict[str, Any]):
 # ---------------------------------------------------------------------------
 
 
+def test_deep_decoy_operator_stop_is_reported_as_a_stop(caplog) -> None:
+    from squirrelops_home_sensor.__main__ import _log_deep_decoy_not_started
+
+    with caplog.at_level(logging.INFO, logger="squirrelops_home_sensor"):
+        _log_deep_decoy_not_started({"status": "stopped", "reason": None})
+
+    assert [record.levelname for record in caplog.records] == ["INFO"]
+    assert "stopped by the operator" in caplog.records[0].getMessage()
+    assert "Decoys tab" in caplog.records[0].getMessage()
+
+
+def test_deep_decoy_startup_failure_is_a_warning_with_its_reason(caplog) -> None:
+    from squirrelops_home_sensor.__main__ import _log_deep_decoy_not_started
+
+    with caplog.at_level(logging.INFO, logger="squirrelops_home_sensor"):
+        _log_deep_decoy_not_started(
+            {"status": "degraded", "reason": "Studio virtual IP could not be published."}
+        )
+        _log_deep_decoy_not_started({"status": "degraded", "reason": None})
+
+    assert [record.levelname for record in caplog.records] == ["WARNING", "WARNING"]
+    assert "Studio virtual IP could not be published." in caplog.records[0].getMessage()
+    assert "no reason recorded" in caplog.records[1].getMessage()
+
+
 @pytest.mark.asyncio
 async def test_open_db_enables_foreign_key_enforcement(tmp_path: Path) -> None:
     """Production connections must enforce the relationships in the schema."""