Fix remote-device tool timing out on scheduled runs (Redis-backed broker) (#2511)

* fix: route remote-device tool through Redis so scheduled runs reach the device

The remote-device tool worked interactively but timed out on every scheduled
run. DeviceBroker was an in-process, in-memory singleton, but scheduled runs
execute in the Celery worker — a different process from the gunicorn web tier
that holds the device's SSE session — so a worker-side dispatch never reached
the device and the tool always hit its deadline.

Make the broker Redis-backed so every hop crosses the process boundary:
- queued commands       -> Redis list   dev:cmd:{device_id}
- output chunks         -> Redis stream dev:out:{invocation_id}
- invocation metadata   -> Redis hash   dev:inv:{invocation_id}
- SSE upgrade tickets    -> Redis key    dev:ticket:{device_id}
Per-connection SSE session state stays in the web process. Reuses the existing
get_redis_instance()/CACHE_REDIS_URL; no new infrastructure. Also makes the web
tier safe to scale past one worker.

Concurrency hardening (from adversarial review + real-Redis e2e):
- XADD the output/control chunk before flipping completed=1, and have
  drain_output do a final non-blocking flush after observing completion, so a
  reader can't see completion and stop before the control chunk lands (this had
  reintroduced the false "device did not respond (timed out)" under a race).
- _collect_result builds the result from drained chunks, checks the deadline
  only after capturing a chunk, and falls back to the authoritative snapshot
  (before cleanup) when no control chunk was observed.
- Audit outcome is written from locally-known fields so it survives the worker
  racing to delete the invocation; a denied command now records a terminal
  "denied" outcome instead of staying "dispatched".
- cmd-queue TTL raised to 900s (>= max drain deadline); dispatch-failure and
  reaped-invocation cleanup; UTF-8 byte counts.

Tests: new tests/devices/{conftest (FakeRedis double), test_broker_cross_process,
test_broker_race, test_submit_output_audit}; drain/cleanup/ticket tests rewritten
for the Redis contract. The race tests fail against the pre-fix code. ruff clean;
device + tool-executor suites green.

* fix: log instead of silently passing on failed-dispatch cleanup

Addresses the code-quality lint on the best-effort hash delete in
dispatch_invocation's failure path: replace the bare `except: pass` with a
logger.debug carrying the invocation_id. No behavior change — cleanup stays
best-effort and still returns a failed Invocation.

Author: dartpain

application/agents/tools/remote_device.py

@@ -246,37 +246,72 @@ def _matches_sticky(self, command: str) -> bool:
             return False
 
     def _collect_result(self, broker, inv, device: dict, timeout_ms: int) -> Dict[str, Any]:
-        """Drain output from the broker until the control chunk arrives."""
+        """Drain output from the broker until the control chunk arrives.
+
+        Result fields come from the drained chunks, not from ``inv``: the
+        invocation runs and reports back in a different process (the web
+        tier), so the dispatching process never sees ``inv`` mutated.
+        """
+        # Dispatch already failed (e.g. broker/Redis unavailable): report it.
+        if inv.completed and inv.error:
+            return {
+                "exit_code": None,
+                "stdout": "",
+                "stderr": "",
+                "duration_ms": None,
+                "device_name": device.get("name"),
+                "error": inv.error,
+            }
+
         deadline = time.time() + (timeout_ms / 1000.0) + 5.0
         stdout = []
         stderr = []
+        exit_code = None
+        duration_ms = None
+        error = None
+        saw_control = False
         try:
             for chunk in broker.drain_output(
                 inv.invocation_id, timeout=1.0, deadline=deadline
             ):
-                if time.time() > deadline:
-                    break
                 stream = chunk.get("stream")
                 if stream == "stdout":
                     stdout.append(chunk.get("chunk", ""))
                 elif stream == "stderr":
                     stderr.append(chunk.get("chunk", ""))
                 elif stream == "control":
-                    # control chunks include exit_code; drain loop will stop next iter
-                    pass
+                    saw_control = True
+                    exit_code = chunk.get("exit_code")
+                    duration_ms = chunk.get("duration_ms")
+                    error = chunk.get("error") or error
+                # Stop once past the deadline — but only AFTER capturing a chunk
+                # the drain already yielded, so a near-deadline control chunk
+                # isn't dropped and misreported as a timeout.
+                if time.time() > deadline:
+                    break
+            # No control chunk observed: consult the authoritative completion
+            # state (before cleanup deletes it) so a late or dropped control
+            # chunk isn't misreported as "device did not respond".
+            if not saw_control:
+                final = broker.get_invocation(inv.invocation_id)
+                if final is not None and final.completed:
+                    saw_control = True
+                    exit_code = final.exit_code
+                    duration_ms = final.duration_ms
+                    error = final.error or error
         finally:
             broker.cleanup_invocation(inv.invocation_id)
 
-        # Deadline hit with no control chunk: the device never connected or
+        # Deadline hit with no completion at all: the device never connected or
         # never finished. Surface a clear timeout instead of empty success.
-        if not inv.completed.is_set() and inv.exit_code is None and not inv.error:
-            inv.error = "device did not respond (timed out)"
+        if not saw_control and exit_code is None and not error:
+            error = "device did not respond (timed out)"
 
         return {
-            "exit_code": inv.exit_code,
-            "stdout": "".join(stdout) if stdout else "".join(inv.stdout_parts),
-            "stderr": "".join(stderr) if stderr else "".join(inv.stderr_parts),
-            "duration_ms": inv.duration_ms,
+            "exit_code": exit_code,
+            "stdout": "".join(stdout),
+            "stderr": "".join(stderr),
+            "duration_ms": duration_ms,
             "device_name": device.get("name"),
-            "error": inv.error,
+            "error": error,
         }

application/api/devices/session.py

@@ -7,7 +7,6 @@
 import json
 import logging
 import time
-from queue import Empty
 from typing import Iterator
 
 from flask import Response, jsonify, make_response, request, stream_with_context
@@ -118,16 +117,15 @@ def generate() -> Iterator[str]:
                     sess.last_event_id += 1
                     broker.close_session(sess.session_id, reason="idle")
                     return
-                try:
-                    inv = sess.invocation_queue.get(timeout=1.0)
-                except Empty:
+                envelope = broker.next_command(sess, timeout=1.0)
+                if envelope is None:
                     if time.time() - last_keepalive >= keepalive_interval:
                         last_keepalive = time.time()
                         yield ": heartbeat\n\n"
                     continue
                 sess.last_event_id += 1
                 sess.last_activity_at = time.time()
-                yield _sse_event("invocation", inv.envelope, sess.last_event_id)
+                yield _sse_event("invocation", envelope, sess.last_event_id)
                 last_keepalive = time.time()
         except GeneratorExit:
             logger.debug("device SSE generator exiting for session %s", sess.session_id)
@@ -164,6 +162,22 @@ def ack_invocation(session_id: str, invocation_id: str) -> Response:
             jsonify({"success": False, "error": "invocation_not_found"}), 404
         )
     broker.submit_ack(invocation_id, decision, reason)
+    if decision == "denied":
+        # A denial is terminal and produces no device output, so submit_output's
+        # audit write is never reached. Record the outcome here from locally
+        # known facts (not re-read Redis state the agent's drain races to clean
+        # up), so the audit row reflects the denial instead of staying
+        # "dispatched". Accepted/auto_approved runs record via submit_output.
+        from datetime import datetime, timezone
+        try:
+            with db_session() as conn:
+                DeviceAuditLogRepository(conn).record_result(
+                    invocation_id,
+                    finished_at=datetime.now(timezone.utc),
+                    error="denied",
+                )
+        except Exception:
+            logger.exception("audit record_result (denied) failed for %s", invocation_id)
     return make_response(jsonify({"success": True}), 200)
 
 
@@ -189,6 +203,7 @@ def submit_output(session_id: str, invocation_id: str) -> Response:
             )
 
     received = 0
+    control_chunk = None
     for line in io.BytesIO(body):
         line = line.strip()
         if not line:
@@ -199,33 +214,33 @@ def submit_output(session_id: str, invocation_id: str) -> Response:
             continue
         if not isinstance(chunk, dict):
             continue
+        if chunk.get("stream") == "control":
+            control_chunk = chunk
         broker.submit_output_chunk(invocation_id, chunk)
         received += 1
 
-    # Persist outcome on the audit row when a control chunk closed the stream.
-    if inv.completed.is_set():
+    # Persist the outcome when the closing control chunk arrived in this POST.
+    # Its fields are captured locally so the audit write survives the draining
+    # (worker) process racing to delete the invocation's Redis state. Byte
+    # totals / started_at live in the hash, read best-effort (the functional
+    # exit_code/error/duration still land even if the hash is already gone).
+    if control_chunk is not None:
+        from datetime import datetime, timezone
+        snap = broker.get_invocation(invocation_id)
         try:
-            from datetime import datetime, timezone
             with db_session() as conn:
                 DeviceAuditLogRepository(conn).record_result(
                     invocation_id,
                     started_at=(
-                        datetime.fromtimestamp(inv.started_at, tz=timezone.utc)
-                        if inv.started_at else None
+                        datetime.fromtimestamp(snap.started_at, tz=timezone.utc)
+                        if snap is not None and snap.started_at else None
                     ),
-                    finished_at=(
-                        datetime.fromtimestamp(inv.finished_at, tz=timezone.utc)
-                        if inv.finished_at else None
-                    ),
-                    exit_code=inv.exit_code,
-                    duration_ms=inv.duration_ms,
-                    stdout_bytes=sum(
-                        len(c) for c in inv.stdout_parts
-                    ),
-                    stderr_bytes=sum(
-                        len(c) for c in inv.stderr_parts
-                    ),
-                    error=inv.error,
+                    finished_at=datetime.now(timezone.utc),
+                    exit_code=_as_opt_int(control_chunk.get("exit_code")),
+                    duration_ms=_as_opt_int(control_chunk.get("duration_ms")),
+                    stdout_bytes=(snap.stdout_bytes if snap is not None else 0),
+                    stderr_bytes=(snap.stderr_bytes if snap is not None else 0),
+                    error=control_chunk.get("error"),
                 )
         except Exception:
             logger.exception("audit record_result failed for %s", invocation_id)
@@ -235,6 +250,16 @@ def submit_output(session_id: str, invocation_id: str) -> Response:
     )
 
 
+def _as_opt_int(value) -> int | None:
+    """Coerce a CLI-supplied JSON value to int for an INTEGER audit column."""
+    if value is None:
+        return None
+    try:
+        return int(value)
+    except (TypeError, ValueError):
+        return None
+
+
 def _sse_event(name: str, payload: dict, event_id: int) -> str:
     return (
         f"event: {name}\n"

application/core/settings.py

@@ -241,6 +241,14 @@ class Settings(BaseSettings):
     REMOTE_DEVICE_SESSION_IDLE_SECONDS: int = 60
     REMOTE_DEVICE_REQUIRE_SIGNATURE: bool = False
     REMOTE_DEVICE_PAIRING_TTL_SECONDS: int = 600
+    # Redis-backed broker tunables (route invocations cross-process so a
+    # scheduled/Celery run reaches the web-held device session). The command
+    # queue TTL must exceed the max command drain deadline (the tool caps
+    # timeout_ms at 600s, drained with a +5s margin = 605s) so a queued command
+    # for a briefly-offline device isn't evicted before its own drain gives up.
+    REMOTE_DEVICE_CMD_QUEUE_TTL_SECONDS: int = 900
+    REMOTE_DEVICE_INVOCATION_TTL_SECONDS: int = 900
+    REMOTE_DEVICE_OUTPUT_STREAM_MAXLEN: int = 10_000
 
     # Scheduler (see scheduler.md).
     SCHEDULE_DISPATCHER_INTERVAL: int = 30