personal memory agent
0

Configure Feed

Select the types of activity you want to include in your feed.

solstone / solstone / think / supervisor.py
107 kB 3122 lines
1# SPDX-License-Identifier: AGPL-3.0-only 2# Copyright (c) 2026 sol pbc 3 4from __future__ import annotations 5 6import argparse 7import asyncio 8import concurrent.futures 9import fcntl 10import getpass 11import json 12import logging 13import os 14import signal 15import socket 16import stat 17import subprocess 18import sys 19import tempfile 20import threading 21import time 22from collections import OrderedDict, deque 23from datetime import datetime, timezone 24from logging.handlers import RotatingFileHandler 25from pathlib import Path 26from typing import Any, Callable, Iterable, NoReturn 27 28import psutil 29 30from solstone.think import maintenance, scheduler 31from solstone.think.app_supervised import FLAG, is_app_supervised, resolve_parent_fd 32from solstone.think.backup.engine import BACKUP_MAX_RUNTIME, BACKUP_RUN_CMD 33from solstone.think.callosum import CallosumConnection, CallosumServer 34from solstone.think.catchup_state import ( 35 KIND_DAILY_CATCHUP, 36 STUCK_THRESHOLD, 37 day_eligible_to_drain, 38 reconcile_interrupted_attempts, 39 record_attempt, 40 record_outcome, 41) 42from solstone.think.display_powersave import ( 43 poll_display_powersave, 44 reset_display_powersave_monitor, 45) 46from solstone.think.maint import run_pending_tasks 47from solstone.think.models import LOCAL_MODEL, is_local_provider_needed 48from solstone.think.processing import ( 49 DISPLAY_POWERSAVE_UNAVAILABLE, 50 evaluate_drain_gate, 51 load_processing_settings, 52) 53from solstone.think.providers.mlx_server import MLX_SERVER_PROCESS_NAME 54from solstone.think.readiness import START_TIME_TOLERANCE_S, clear_ready, signal_ready 55from solstone.think.runner import ManagedProcess as RunnerManagedProcess 56from solstone.think.runner import _command_partition 57from solstone.think.sync_check import ( 58 DEFAULT_INTERVAL_SECONDS, 59 SyncCheckSnapshot, 60 check_journal_sync, 61 clear_self_heartbeat, 62 format_conflict_message, 63 write_self_heartbeat, 64) 65from solstone.think.utils import ( 66 EXIT_EMPTY, 67 EXIT_TEMPFAIL, 68 SOFT_RUNTIME_FRACTION, 69 day_path, 70 find_available_port, 71 get_journal, 72 get_journal_info, 73 get_rev, 74 is_solstone_up, 75 now_ms, 76 parse_duration_seconds, 77 read_service_port, 78 setup_cli, 79 updated_days, 80 write_service_port, 81) 82 83DEFAULT_TASK_MAX_RUNTIME = ( 84 1800 # 30m wall-clock default for any uncapped TaskQueue partition 85) 86REACTIVE_TASK_CAPS = { 87 "daily": 21600, # 6h daily/from-scratch reprocess 88 "segment": 4500, # 75m per-segment think 89 "indexer": 7200, # 2h indexer, above the code's own 1h rescan allotment 90 "importer": 3600, # 1h importer 91} 92DEFAULT_THRESHOLD = 60 93CHECK_INTERVAL = 30 94GATE_TICK_INTERVAL_S = 60 95MAX_UPDATED_CATCHUP = 4 96TEMPFAIL_DELAY = 15 # seconds to wait before retrying a tempfail exit 97CONVEY_READY_WINDOW_SECONDS = 60.0 98REALISTIC_COLD_BIND_SECONDS = 40.0 99HANDLE_SHUTDOWN_REAP_S = 3.0 100APP_SUPERVISED_SHUTDOWN_CEILING_S = 10.0 101APP_SUPERVISED_TASK_DRAIN_S = 2.0 102APP_SUPERVISED_CHILD_STOP_S = 2.0 103APP_SUPERVISED_CALLOSUM_JOIN_S = 2.0 104PARENT_DEATH_POLL_INTERVAL_S = 1.0 105STOPPED_TICKS_THRESHOLD = 2 106LOCAL_SERVER_PROCESS_NAME = "llama-server" 107LOCAL_WEDGE_THRESHOLD = 3 108LOCAL_WEDGE_RECYCLE_GRACE_S = 120.0 109LOCAL_WEDGE_PROVIDER_MAP_CAP = 512 110LOCAL_SERVER_READY_TIMEOUT_S = 300.0 111LOCAL_SERVER_HEALTH_POLL_INTERVAL_S = 1.0 112LOCAL_MODEL_WARMING_UP_COPY = "Local model is warming up..." 113# supervisor.log is size-rotated with a bounded on-disk footprint. 114# Hard ceiling = SUPERVISOR_LOG_MAX_BYTES * (SUPERVISOR_LOG_BACKUP_COUNT + 1) 115# = 16 MiB * 6 = 96 MiB. Older lines drop; the most-recent tail is kept. 116SUPERVISOR_LOG_MAX_BYTES = 16 * 1024 * 1024 117SUPERVISOR_LOG_BACKUP_COUNT = 5 118logger = logging.getLogger(__name__) 119 120 121def _compact_log_if_oversized(log_path: Path, max_bytes: int) -> None: 122 try: 123 size = log_path.stat().st_size 124 except FileNotFoundError: 125 return 126 except OSError as error: 127 logger.warning("Could not stat supervisor log before compaction: %s", error) 128 return 129 130 if size <= max_bytes: 131 return 132 133 compact_path = log_path.with_name(log_path.name + ".compact") 134 try: 135 with log_path.open("rb") as handle: 136 handle.seek(-max_bytes, os.SEEK_END) 137 tail = handle.read(max_bytes) 138 139 first_newline = tail.find(b"\n") 140 kept = tail[first_newline + 1 :] if first_newline != -1 else b"" 141 142 with compact_path.open("wb") as handle: 143 handle.write(kept) 144 compact_path.rename(log_path) 145 except OSError as error: 146 logger.warning("Could not compact oversized supervisor log: %s", error) 147 try: 148 compact_path.unlink(missing_ok=True) 149 except OSError: 150 pass 151 152 153def _configure_supervisor_logging( 154 log_path: Path, 155 level: int, 156 max_bytes: int = SUPERVISOR_LOG_MAX_BYTES, 157 backup_count: int = SUPERVISOR_LOG_BACKUP_COUNT, 158) -> None: 159 logging.getLogger().handlers = [] 160 _compact_log_if_oversized(log_path, max_bytes) 161 logging.basicConfig( 162 level=level, 163 handlers=[ 164 RotatingFileHandler( 165 log_path, 166 maxBytes=max_bytes, 167 backupCount=backup_count, 168 encoding="utf-8", 169 ) 170 ], 171 format="%(asctime)s [supervisor:log] %(levelname)s %(message)s", 172 datefmt="%Y-%m-%dT%H:%M:%S", 173 ) 174 175 176_SERVICE_LIFECYCLE_VERBS = { 177 "start", 178 "stop", 179 "restart", 180 "status", 181 "install", 182 "uninstall", 183 "logs", 184} 185 186# Global shutdown flag 187shutdown_requested = False 188_last_sync_tick: float = 0.0 189_last_gate_tick: float = 0.0 190_last_sync_snapshot: "SyncCheckSnapshot | None" = None 191_sync_conflict_shutdown: bool = False 192# Supervisor identity (set in main() once ref is assigned) 193_supervisor_ref: str | None = None 194_supervisor_start: float | None = None 195_parent_death_sigterm_sent = threading.Event() 196 197 198def app_supervised_graceful_budget_s() -> float: 199 """Sum of configured app-supervised graceful shutdown step budgets. 200 201 After the parent-death watcher self-SIGTERMs, the graceful path runs these 202 configured caps in finally-block order: handle_shutdown's managed-child 203 reap, task-queue drain, managed child-stop, and Callosum join. 204 205 The assertion that this budget stays below APP_SUPERVISED_SHUTDOWN_CEILING_S 206 guards that configured step budgets leave room under the hard parent-death 207 backstop. It is not a guarantee that wall time can never exceed this sum. 208 In the common non-D-state case, bounded terminate calls (timeout plus 209 KILL_REAP_GRACE_S) keep the graceful path well under the ceiling. For 210 pathological slow-to-reap children, a step may exceed its nominal cap; the 211 parent-death backstop remains the hard guarantee by sleeping to the ceiling, 212 SIGKILLing every child's process group, then calling os._exit(1). 213 """ 214 return ( 215 HANDLE_SHUTDOWN_REAP_S 216 + APP_SUPERVISED_TASK_DRAIN_S 217 + APP_SUPERVISED_CHILD_STOP_S 218 + APP_SUPERVISED_CALLOSUM_JOIN_S 219 ) 220 221 222def _sd_notify(state: str) -> None: 223 addr = os.environ.get("NOTIFY_SOCKET") 224 if not addr: 225 return 226 if addr.startswith("@"): 227 addr = "\0" + addr[1:] 228 try: 229 with socket.socket(socket.AF_UNIX, socket.SOCK_DGRAM) as s: 230 s.sendto(state.encode(), addr) 231 except OSError as exc: 232 logging.warning("sd_notify failed: %s", exc) 233 234 235def _parent_fd_is_usable(fd: int) -> bool: 236 try: 237 mode = os.fstat(fd).st_mode 238 flags = fcntl.fcntl(fd, fcntl.F_GETFL) 239 except OSError: 240 return False 241 access_mode = flags & os.O_ACCMODE 242 return stat.S_ISFIFO(mode) and access_mode in (os.O_RDONLY, os.O_RDWR) 243 244 245def wait_until_parent_gone( 246 parent_fd: int, *, poll_interval: float = PARENT_DEATH_POLL_INTERVAL_S 247) -> str: 248 if _parent_fd_is_usable(parent_fd): 249 while True: 250 try: 251 data = os.read(parent_fd, 4096) 252 except OSError: 253 return "fd-error" 254 if data == b"": 255 return "eof" 256 257 while True: 258 if os.getppid() == 1: 259 return "orphaned" 260 time.sleep(poll_interval) 261 262 263def enforce_parent_death_shutdown_deadline( 264 reason: str, 265 *, 266 ceiling: float = APP_SUPERVISED_SHUTDOWN_CEILING_S, 267 managed_procs: Iterable[RunnerManagedProcess] | None = None, 268 task_procs: Iterable[RunnerManagedProcess] | None = None, 269 sent_event: "threading.Event | None" = None, 270 kill: Callable[[int, int], None] | None = None, 271 killpg: Callable[[int, int], None] | None = None, 272 getpgid: Callable[[int], int] | None = None, 273 exit_now: Callable[[int], NoReturn] | None = None, 274 sleep: Callable[[float], None] | None = None, 275) -> None: 276 del reason 277 own_pid = os.getpid() 278 own_pgid = os.getpgrp() 279 kill_fn = kill or os.kill 280 killpg_fn = killpg or os.killpg 281 getpgid_fn = getpgid or os.getpgid 282 exit_now_fn = exit_now or os._exit 283 sleep_fn = sleep or time.sleep 284 sigterm_sent = sent_event if sent_event is not None else _parent_death_sigterm_sent 285 286 if not sigterm_sent.is_set(): 287 sigterm_sent.set() 288 kill_fn(own_pid, signal.SIGTERM) 289 290 sleep_fn(ceiling) 291 292 procs = managed_procs if managed_procs is not None else _managed_procs 293 if task_procs is not None: 294 task_snapshot = task_procs 295 elif _task_queue is not None: 296 with _task_queue._lock: 297 task_snapshot = list(_task_queue._active.values()) 298 else: 299 task_snapshot = [] 300 301 def _kill_group(managed: RunnerManagedProcess) -> None: 302 if not managed.is_running(): 303 return 304 try: 305 pgid = getpgid_fn(managed.process.pid) 306 except (ProcessLookupError, OSError): 307 logger.exception( 308 "parent-death backstop: could not resolve pgid for %s", 309 managed.name, 310 ) 311 return 312 313 if pgid == own_pgid or pgid == own_pid: 314 logger.warning( 315 "parent-death backstop: refusing to signal supervisor's own " 316 "group (pgid=%s) for %s", 317 pgid, 318 managed.name, 319 ) 320 return 321 322 try: 323 killpg_fn(pgid, signal.SIGKILL) 324 except Exception: 325 logger.exception( 326 "parent-death backstop: SIGKILL failed for %s", managed.name 327 ) 328 329 for managed in procs: 330 try: 331 _kill_group(managed) 332 except Exception: 333 logger.exception( 334 "parent-death backstop: unexpected failure for %s", 335 getattr(managed, "name", managed), 336 ) 337 for managed in task_snapshot: 338 try: 339 _kill_group(managed) 340 except Exception: 341 logger.exception( 342 "parent-death backstop: unexpected failure for %s", 343 getattr(managed, "name", managed), 344 ) 345 346 exit_now_fn(1) 347 348 349def _parent_death_watcher_main( 350 parent_fd: int, 351 *, 352 poll_interval: float = PARENT_DEATH_POLL_INTERVAL_S, 353 ceiling: float = APP_SUPERVISED_SHUTDOWN_CEILING_S, 354) -> None: 355 reason = wait_until_parent_gone(parent_fd, poll_interval=poll_interval) 356 logger.warning( 357 "parent-death detected (%s); converging to graceful shutdown", reason 358 ) 359 enforce_parent_death_shutdown_deadline(reason, ceiling=ceiling) 360 361 362def start_parent_death_watcher( 363 parent_fd: int | None = None, 364 *, 365 poll_interval: float = PARENT_DEATH_POLL_INTERVAL_S, 366 ceiling: float = APP_SUPERVISED_SHUTDOWN_CEILING_S, 367) -> threading.Thread: 368 fd = parent_fd if parent_fd is not None else resolve_parent_fd() 369 thread = threading.Thread( 370 target=_parent_death_watcher_main, 371 args=(fd,), 372 kwargs={"poll_interval": poll_interval, "ceiling": ceiling}, 373 name="parent-death-watcher", 374 daemon=True, 375 ) 376 thread.start() 377 return thread 378 379 380def _candidate_journal(proc: "psutil.Process") -> Path | None: 381 """Return the resolved SOLSTONE_JOURNAL of ``proc``, or None on any failure. 382 383 Used by the orphan sweep to skip candidates we cannot positively classify 384 as belonging to the caller's journal. Conservative on unknown: any failure 385 to read or parse the env value returns None so the candidate is skipped. 386 """ 387 try: 388 env = proc.environ() 389 except (psutil.AccessDenied, psutil.NoSuchProcess, OSError): 390 return None 391 raw = env.get("SOLSTONE_JOURNAL") 392 if not raw: 393 return None 394 try: 395 return Path(raw).resolve() 396 except (OSError, RuntimeError, ValueError): 397 return None 398 399 400# The long-lived journal proctitles set by setproctitle at sol_cli.py 401# (f"{binary}:{cmd}"). setproctitle is in-process and persists until the 402# process exits, so an orphaned service or task child still reports its title 403# via proc.name() after the supervisor dies, which is what lets the sweep find 404# it. The supervisor-owned `llama-server` reports its own bare binary name (no 405# colon prefix) and is included here so the sweep reaps it too. 406# The mlx-vlm server is a Python process, but our launcher sets the same 407# managed proctitle so proc.name() is stable for orphan sweeping. 408_LOCAL_SERVER_PROCTITLES = frozenset( 409 { 410 LOCAL_SERVER_PROCESS_NAME, 411 MLX_SERVER_PROCESS_NAME, 412 } 413) 414 415 416def _is_sweepable_orphan_name(name: str) -> bool: 417 """True if proc.name() identifies a sweepable orphan of this install. 418 419 Any `journal:*` proctitle - managed service or task-queue child - plus the 420 bare local-server binary names. A PPID-1, same-journal `journal:*` process 421 is by definition an orphan of a dead supervisor. `solstone:*`/`sol:*` and a 422 bare `journal` (no colon) are deliberately not matched because they cannot 423 be positively classified as a sub-command of this install. 424 """ 425 return name.startswith("journal:") or name in _LOCAL_SERVER_PROCTITLES 426 427 428def _sweep_orphaned_sol_processes(journal: Path, grace: float = 5.0) -> int: 429 journal = journal.resolve() 430 current_user = getpass.getuser() 431 own_pid = os.getpid() 432 targets: list[int] = [] 433 for proc in psutil.process_iter(["name", "ppid", "username", "pid"]): 434 try: 435 if not _is_sweepable_orphan_name(proc.name()): 436 continue 437 if proc.ppid() != 1: 438 continue 439 if proc.username() != current_user: 440 continue 441 if proc.pid == own_pid: 442 continue 443 candidate_journal = _candidate_journal(proc) 444 if candidate_journal != journal: 445 continue 446 targets.append(proc.pid) 447 except (psutil.NoSuchProcess, psutil.AccessDenied): 448 continue 449 450 if not targets: 451 return 0 452 453 logger.info( 454 "orphan sweep: terminating %d sol process(es) in journal %s", 455 len(targets), 456 journal, 457 ) 458 for pid in targets: 459 logger.debug("orphan sweep: SIGTERM pid=%d", pid) 460 try: 461 os.kill(pid, signal.SIGTERM) 462 except ProcessLookupError: 463 pass 464 465 deadline = time.time() + grace 466 while time.time() < deadline: 467 if not any(psutil.pid_exists(pid) for pid in targets): 468 break 469 time.sleep(0.1) 470 471 survivors = [pid for pid in targets if psutil.pid_exists(pid)] 472 for pid in survivors: 473 logger.debug("orphan sweep: SIGKILL pid=%d", pid) 474 try: 475 os.kill(pid, signal.SIGKILL) 476 except ProcessLookupError: 477 pass 478 return len(targets) 479 480 481class CallosumLogHandler(logging.Handler): 482 """Logging handler that emits log records as callosum ``logs`` tract events. 483 484 Silently drops events on any error — callosum mirroring is best-effort. 485 """ 486 487 def __init__(self, conn: CallosumConnection, ref: str): 488 super().__init__() 489 self._conn = conn 490 self._ref = ref 491 self._pid = os.getpid() 492 self._emitting = False 493 494 def emit(self, record: logging.LogRecord) -> None: 495 if self._emitting: 496 return 497 self._emitting = True 498 try: 499 self._conn.emit( 500 "logs", 501 "line", 502 ref=self._ref, 503 name="supervisor", 504 pid=self._pid, 505 stream="log", 506 line=self.format(record), 507 ) 508 except Exception: 509 pass 510 finally: 511 self._emitting = False 512 513 514class SupervisorArgumentParser(argparse.ArgumentParser): 515 def error(self, message: str) -> None: 516 mistaken = next( 517 (arg for arg in sys.argv[1:] if arg in _SERVICE_LIFECYCLE_VERBS), 518 None, 519 ) 520 if mistaken: 521 self.exit( 522 2, 523 "journal supervisor is the server-launch command (takes a port). " 524 "For lifecycle, use: journal service <verb>. " 525 f"Did you mean: journal service {mistaken} ?\n", 526 ) 527 super().error(message) 528 529 530class TaskQueue: 531 """Manages on-demand task execution with per-command serialization. 532 533 Tasks are serialized by command name - only one task per command runs at a time. 534 Additional requests for the same command are queued (deduped by exact cmd match). 535 Multiple callers requesting the same work have their refs coalesced so all get 536 notified when the task completes. 537 538 The lock only protects state mutations, never held during I/O operations. 539 """ 540 541 def __init__(self, on_queue_change: callable = None, ready: bool = True): 542 """Initialize task queue. 543 544 Args: 545 on_queue_change: Optional callback(cmd_name, running_ref, queue_entries) 546 called after queue state changes. Called outside lock. 547 """ 548 self._running: dict[ 549 str, dict 550 ] = {} # command_name -> {"ref": str, "thread": Thread} 551 self._queues: dict[str, list] = {} # command_name -> list of {refs, cmd} dicts 552 self._active: dict[str, RunnerManagedProcess] = {} # ref -> process 553 self._history: deque[dict[str, Any]] = deque(maxlen=100) 554 self._cap_terminated: set[str] = set() 555 self._stopped_ticks: dict[str, int] = {} 556 self._caps: dict[str, int] = {} 557 self._default_cap = DEFAULT_TASK_MAX_RUNTIME 558 self._pending: list[dict] = [] 559 self._ready = ready 560 self._lock = threading.Lock() 561 self._on_queue_change = on_queue_change 562 563 @staticmethod 564 def get_command_name(cmd: list[str]) -> str: 565 """Return the canonical queue/log partition for a command.""" 566 return _command_partition(cmd) 567 568 def _notify_queue_change(self, cmd_name: str) -> None: 569 """Notify listener of queue state change (called outside lock).""" 570 if not self._on_queue_change: 571 return 572 573 with self._lock: 574 if cmd_name == "pending": 575 queue = list(self._pending) 576 running_ref = None 577 else: 578 queue = list(self._queues.get(cmd_name, [])) 579 entry = self._running.get(cmd_name) 580 running_ref = entry["ref"] if entry else None 581 582 self._on_queue_change(cmd_name, running_ref, queue) 583 584 def submit( 585 self, 586 cmd: list[str], 587 ref: str | None = None, 588 day: str | None = None, 589 scheduler_name: str | None = None, 590 ) -> str | None: 591 """Submit a task for execution. 592 593 If no task of this command type is running, starts immediately. 594 Otherwise queues (deduped by exact cmd match, refs coalesced). 595 596 Args: 597 cmd: Command to execute 598 ref: Optional caller-provided ref for tracking 599 day: Optional day override (YYYYMMDD) for log placement 600 601 Returns: 602 ref if task was started/queued, None if already tracked (no change) 603 """ 604 ref = ref or str(now_ms()) 605 cmd_name = self.get_command_name(cmd) 606 607 with self._lock: 608 if not self._ready: 609 self._pending.append( 610 { 611 "refs": [ref], 612 "cmd": cmd, 613 "day": day, 614 "scheduler_name": scheduler_name, 615 } 616 ) 617 should_notify_pending = True 618 else: 619 should_notify_pending = False 620 621 if should_notify_pending: 622 self._notify_queue_change("pending") 623 return ref 624 625 should_notify = False 626 should_start = False 627 628 with self._lock: 629 # Detect stale running state (task thread died without clearing queue) 630 if cmd_name in self._running: 631 stale = self._running[cmd_name] 632 if stale["thread"] is not None and not stale["thread"].is_alive(): 633 logging.warning( 634 f"Clearing stale {cmd_name} queue " 635 f"(thread dead, ref={stale['ref']})" 636 ) 637 self._running.pop(cmd_name) 638 639 if cmd_name in self._running: 640 # Command already running - queue or coalesce 641 queue = self._queues.setdefault(cmd_name, []) 642 existing = next((q for q in queue if q["cmd"] == cmd), None) 643 if existing: 644 if ref not in existing["refs"]: 645 existing["refs"].append(ref) 646 logging.info( 647 f"Added ref {ref} to queued task {cmd_name} " 648 f"(refs: {len(existing['refs'])})" 649 ) 650 should_notify = True 651 else: 652 logging.debug(f"Ref already tracked for queued task: {ref}") 653 return None 654 else: 655 queue.append( 656 { 657 "refs": [ref], 658 "cmd": cmd, 659 "day": day, 660 "scheduler_name": scheduler_name, 661 } 662 ) 663 logging.info( 664 f"Queued task {cmd_name}: {' '.join(cmd)} ref={ref} " 665 f"(queue: {len(queue)})" 666 ) 667 should_notify = True 668 else: 669 # Not running - mark as running and start 670 # Thread is set to None here; _run_task registers it on entry 671 self._running[cmd_name] = { 672 "ref": ref, 673 "thread": None, 674 "scheduler_name": scheduler_name, 675 } 676 should_start = True 677 678 # Notify outside lock 679 if should_notify: 680 self._notify_queue_change(cmd_name) 681 return ref 682 683 # Start task outside lock 684 if should_start: 685 threading.Thread( 686 target=self._run_task, 687 args=([ref], cmd, cmd_name, day, scheduler_name), 688 daemon=True, 689 ).start() 690 return ref 691 692 return None 693 694 def set_cap(self, cmd_name: str, seconds: int) -> None: 695 """Set a max runtime cap in seconds for a queued command name.""" 696 with self._lock: 697 self._caps[cmd_name] = seconds 698 699 def _effective_cap(self, cmd_name: str) -> int: 700 """Resolve the wall-clock cap for a partition: explicit override or default. 701 702 Lock-free: reads only `self._caps` (atomic dict get) and the immutable 703 `self._default_cap`, so it is safe whether or not the caller holds 704 `self._lock`. 705 """ 706 return self._caps.get(cmd_name) or self._default_cap 707 708 def get_active_by_cmd_name(self, name: str) -> str | None: 709 """Return the first active ref matching a command name.""" 710 with self._lock: 711 for ref, managed in self._active.items(): 712 if self.get_command_name(managed.cmd) == name: 713 return ref 714 return None 715 716 def enforce_deadlines(self, now: float) -> None: 717 """Enforce configured task runtime caps without blocking the supervisor tick.""" 718 with self._lock: 719 for ref, managed in list(self._active.items()): 720 cmd_name = self.get_command_name(managed.cmd) 721 cap = self._effective_cap(cmd_name) 722 723 elapsed = now - managed.start_time 724 if elapsed <= cap: 725 continue 726 727 elapsed_seconds = int(elapsed) 728 logging.warning( 729 "Task %s (cmd=%s, ref=%s) exceeded max_runtime of %ds " 730 "(elapsed=%ds); terminating", 731 cmd_name, 732 " ".join(managed.cmd), 733 ref, 734 cap, 735 elapsed_seconds, 736 ) 737 self._cap_terminated.add(ref) 738 _start_termination_thread(ref, managed, timeout=2.0, reason="cap") 739 740 for ref, managed in list(self._active.items()): 741 if ref in self._cap_terminated: 742 continue 743 744 try: 745 state = psutil.Process(managed.process.pid).status() 746 except (psutil.NoSuchProcess, psutil.AccessDenied): 747 self._stopped_ticks.pop(ref, None) 748 continue 749 750 if state in (psutil.STATUS_STOPPED, psutil.STATUS_TRACING_STOP): 751 ticks = self._stopped_ticks.get(ref, 0) + 1 752 self._stopped_ticks[ref] = ticks 753 if ticks >= STOPPED_TICKS_THRESHOLD: 754 cmd_name = self.get_command_name(managed.cmd) 755 logging.warning( 756 "Task %s (cmd=%s, ref=%s) was stopped (state=%s) " 757 "for %d consecutive ticks; terminating", 758 cmd_name, 759 " ".join(managed.cmd), 760 ref, 761 state, 762 ticks, 763 ) 764 self._cap_terminated.add(ref) 765 _start_termination_thread( 766 ref, managed, timeout=2.0, reason="stopped" 767 ) 768 self._stopped_ticks.pop(ref, None) 769 else: 770 self._stopped_ticks.pop(ref, None) 771 772 def set_ready(self) -> None: 773 """Allow buffered tasks to start dispatching through the normal queue path.""" 774 with self._lock: 775 if self._ready: 776 return 777 self._ready = True 778 pending = list(self._pending) 779 self._pending.clear() 780 781 if pending: 782 self._notify_queue_change("pending") 783 for entry in pending: 784 self.submit( 785 entry["cmd"], 786 ref=entry["refs"][0], 787 day=entry.get("day"), 788 scheduler_name=entry.get("scheduler_name"), 789 ) 790 791 def _run_task( 792 self, 793 refs: list[str], 794 cmd: list[str], 795 cmd_name: str, 796 day: str | None = None, 797 scheduler_name: str | None = None, 798 ) -> None: 799 """Execute a task and handle completion. 800 801 Args: 802 refs: List of refs to notify on completion 803 cmd: Command to execute 804 cmd_name: Command name for queue management 805 day: Optional day override (YYYYMMDD) for log placement 806 """ 807 # Register this thread for stale-queue detection 808 with self._lock: 809 if cmd_name in self._running and self._running[cmd_name]["ref"] == refs[0]: 810 self._running[cmd_name]["thread"] = threading.current_thread() 811 812 callosum = CallosumConnection() 813 managed = None 814 primary_ref = refs[0] 815 service = cmd_name 816 exit_status = "error" 817 attempt_recorded = False 818 819 try: 820 callosum.start() 821 logging.info(f"Starting task {primary_ref}: {' '.join(cmd)}") 822 823 managed = RunnerManagedProcess.spawn( 824 cmd, ref=primary_ref, callosum=callosum, day=day 825 ) 826 with self._lock: 827 self._active[primary_ref] = managed 828 started_at = time.time() 829 record_attempt(cmd, day, primary_ref, started_at=started_at) 830 attempt_recorded = True 831 832 callosum.emit( 833 "supervisor", 834 "started", 835 service=service, 836 pid=managed.pid, 837 ref=primary_ref, 838 ) 839 840 exit_code = managed.wait() 841 exit_status = _exit_status_for_code(exit_code) 842 843 for ref in refs: 844 callosum.emit( 845 "supervisor", 846 "stopped", 847 service=service, 848 pid=managed.pid, 849 ref=ref, 850 exit_code=exit_code, 851 ) 852 853 if exit_code == 0: 854 logging.info(f"Task {cmd_name} ({primary_ref}) finished successfully") 855 else: 856 logging.warning( 857 f"Task {cmd_name} ({primary_ref}) failed with exit code {exit_code}" 858 ) 859 860 except Exception as e: 861 if isinstance(e, subprocess.TimeoutExpired): 862 exit_status = "timeout" 863 logging.exception( 864 f"Task {cmd_name} ({primary_ref}) encountered exception: {e}" 865 ) 866 for ref in refs: 867 callosum.emit( 868 "supervisor", 869 "stopped", 870 service=service, 871 pid=managed.pid if managed else 0, 872 ref=ref, 873 exit_code=-1, 874 ) 875 finally: 876 try: 877 if managed: 878 managed.cleanup() 879 except Exception: 880 logging.exception(f"Task {cmd_name} ({primary_ref}): cleanup failed") 881 with self._lock: 882 self._active.pop(primary_ref, None) 883 if primary_ref in self._cap_terminated: 884 exit_status = "timeout" 885 self._cap_terminated.discard(primary_ref) 886 self._stopped_ticks.pop(primary_ref, None) 887 ended_at = time.time() 888 self._history.append( 889 { 890 "name": cmd_name, 891 "cmd": list(cmd), 892 "ref": primary_ref, 893 "ended_at": ended_at, 894 "exit_status": exit_status, 895 "scheduler_name": scheduler_name, 896 } 897 ) 898 if scheduler_name: 899 try: 900 _record_scheduler_completion( 901 scheduler_name, 902 ended_at=ended_at, 903 exit_status=exit_status, 904 ref=primary_ref, 905 cmd=cmd, 906 ) 907 except Exception as exc: 908 logger.warning("scheduler completion writeback failed: %s", exc) 909 if attempt_recorded: 910 try: 911 outcome_result = record_outcome( 912 cmd, 913 day, 914 primary_ref, 915 exit_status=exit_status, 916 ended_at=ended_at, 917 ) 918 if outcome_result.entered_backoff: 919 _emit_catchup_backoff( 920 callosum, 921 day=outcome_result.day, 922 attempts=outcome_result.attempts, 923 consecutive=outcome_result.consecutive_non_completion, 924 last_outcome=outcome_result.last_outcome, 925 ) 926 except Exception: 927 logging.warning("catchup outcome writeback failed", exc_info=True) 928 try: 929 callosum.stop() 930 except Exception: 931 logging.exception( 932 f"Task {cmd_name} ({primary_ref}): callosum stop failed" 933 ) 934 self._process_next(cmd_name) 935 936 def _process_next(self, cmd_name: str) -> None: 937 """Process next queued task after completion.""" 938 next_cmd = None 939 refs = None 940 day = None 941 scheduler_name = None 942 943 with self._lock: 944 queue = self._queues.get(cmd_name, []) 945 if queue: 946 entry = queue.pop(0) 947 refs = entry["refs"] 948 next_cmd = entry["cmd"] 949 day = entry.get("day") 950 scheduler_name = entry.get("scheduler_name") 951 # Thread is set to None here; _run_task registers it on entry 952 self._running[cmd_name] = { 953 "ref": refs[0], 954 "thread": None, 955 "scheduler_name": scheduler_name, 956 } 957 logging.info( 958 f"Dequeued task {cmd_name}: {' '.join(next_cmd)} refs={refs} " 959 f"(remaining: {len(queue)})" 960 ) 961 else: 962 self._running.pop(cmd_name, None) 963 964 # Notify and spawn outside lock 965 self._notify_queue_change(cmd_name) 966 if next_cmd: 967 threading.Thread( 968 target=self._run_task, 969 args=(refs, next_cmd, cmd_name, day, scheduler_name), 970 daemon=True, 971 ).start() 972 973 def cancel(self, ref: str) -> bool: 974 """Cancel a running task. 975 976 Returns: 977 True if task was found and terminated, False otherwise 978 """ 979 if ref not in self._active: 980 logging.warning(f"Cannot cancel task {ref}: not found") 981 return False 982 983 managed = self._active[ref] 984 if not managed.is_running(): 985 logging.debug(f"Task {ref} already finished") 986 return False 987 988 logging.info(f"Cancelling task {ref}...") 989 managed.terminate() 990 return True 991 992 def shutdown(self, timeout: float = 10.0) -> int: 993 with self._lock: 994 active = list(self._active.items()) 995 if not active: 996 return 0 997 998 def _terminate(item: tuple[str, RunnerManagedProcess]) -> None: 999 ref, managed = item 1000 try: 1001 managed.terminate(timeout=timeout) 1002 except subprocess.TimeoutExpired: 1003 logger.warning( 1004 "task %s did not exit within %ss; KILL sent", ref, timeout 1005 ) 1006 except OSError as exc: 1007 logger.warning("task %s terminate raised: %s", ref, exc) 1008 1009 with concurrent.futures.ThreadPoolExecutor(max_workers=len(active)) as executor: 1010 list(executor.map(_terminate, active)) 1011 return len(active) 1012 1013 def get_status(self, ref: str) -> dict: 1014 """Get status of a task.""" 1015 if ref not in self._active: 1016 return {"status": "not_found"} 1017 1018 managed = self._active[ref] 1019 return { 1020 "status": "running" if managed.is_running() else "finished", 1021 "pid": managed.pid, 1022 "returncode": managed.returncode, 1023 "log_path": str(managed.log_writer.path), 1024 "cmd": managed.cmd, 1025 } 1026 1027 def collect_task_status(self) -> list[dict]: 1028 """Collect status of all running tasks for supervisor status.""" 1029 now = time.time() 1030 tasks = [] 1031 for ref, managed in self._active.items(): 1032 if managed.is_running(): 1033 duration = int(now - managed.start_time) 1034 cmd_name = TaskQueue.get_command_name(managed.cmd) 1035 cap = self._effective_cap(cmd_name) 1036 tasks.append( 1037 { 1038 "ref": ref, 1039 "name": cmd_name, 1040 "duration_seconds": duration, 1041 "max_runtime_seconds": cap, 1042 "slow": duration >= cap * SOFT_RUNTIME_FRACTION, 1043 "stuck": duration > cap, 1044 } 1045 ) 1046 return tasks 1047 1048 def collect_queue_counts(self) -> dict[str, int]: 1049 """Snapshot per-command queue depths for status reporting.""" 1050 with self._lock: 1051 counts = { 1052 cmd_name: len(queue) 1053 for cmd_name, queue in self._queues.items() 1054 if queue 1055 } 1056 if self._pending: 1057 counts["pending"] = len(self._pending) 1058 return counts 1059 1060 1061# Global task queue instance (initialized in main()) 1062_task_queue: TaskQueue | None = None 1063 1064# Global supervisor callosum connection for event emissions 1065_supervisor_callosum: CallosumConnection | None = None 1066 1067# Global reference to managed processes for restart control 1068_managed_procs: list[RunnerManagedProcess] = [] 1069_SERVICE_STATE: dict[str, dict[str, Any]] = {} 1070_termination_threads: dict[str, threading.Thread] = {} 1071_termination_threads_lock = threading.Lock() 1072_SCHEDULER_JSON_LOCK = threading.Lock() 1073 1074# Global reference to in-process Callosum server 1075_callosum_server: CallosumServer | None = None 1076_callosum_thread: threading.Thread | None = None 1077 1078# Track whether running in remote mode (upload-only, no local processing) 1079_is_remote_mode: bool = False 1080 1081# State for daily processing (tracks day boundary for midnight think trigger) 1082_daily_state = { 1083 "last_day": None, # Track which day we last processed 1084} 1085 1086# State for local provider recovery nudges 1087_recovery_state = { 1088 "local_server_down": False, 1089} 1090 1091# State for local provider wedge detection 1092_wedge_state: dict[str, Any] = { 1093 "providers": OrderedDict(), 1094 "failures": set(), 1095 "cooldown_until": 0.0, 1096 "awaiting_recovery": False, 1097} 1098 1099# Timeout before flushing stale segments (seconds) 1100FLUSH_TIMEOUT = 3600 1101 1102# State for segment flush (close out dangling agent state after inactivity) 1103_flush_state: dict = { 1104 "last_segment_ts": 0.0, # Wall-clock time of last observe.observed event 1105 "day": None, # Day of last observed segment 1106 "segment": None, # Last observed segment key 1107 "flushed": False, # Whether flush has already run for current segment 1108} 1109 1110 1111def _get_journal_path() -> Path: 1112 return Path(get_journal()) 1113 1114 1115def is_supervisor_up() -> bool: 1116 """Return True when supervisor.pid and supervisor.start_time identify a live supervisor process for the current journal.""" 1117 health_dir = Path(get_journal()) / "health" 1118 pid_path = health_dir / "supervisor.pid" 1119 try: 1120 pid = int(pid_path.read_text().strip()) 1121 except FileNotFoundError: 1122 return False 1123 except (OSError, ValueError): 1124 return False 1125 1126 try: 1127 os.kill(pid, 0) 1128 except ProcessLookupError: 1129 return False 1130 except PermissionError: 1131 return False 1132 except OSError: 1133 return False 1134 1135 start_time_path = health_dir / "supervisor.start_time" 1136 try: 1137 recorded_start = float(start_time_path.read_text().strip()) 1138 except FileNotFoundError: 1139 return False 1140 except (OSError, ValueError): 1141 return False 1142 1143 try: 1144 create_time = psutil.Process(pid).create_time() 1145 except psutil.NoSuchProcess: 1146 return False 1147 except psutil.Error: 1148 return False 1149 1150 return abs(recorded_start - create_time) <= START_TIME_TOLERANCE_S 1151 1152 1153class RestartPolicy: 1154 """Track restart attempts and compute backoff delays.""" 1155 1156 _SCHEDULE = (0, 1, 5) 1157 1158 def __init__(self) -> None: 1159 self.attempts = 0 1160 self.last_start = 0.0 1161 1162 def record_start(self) -> None: 1163 self.last_start = time.time() 1164 1165 def reset_attempts(self) -> None: 1166 self.attempts = 0 1167 1168 def next_delay(self) -> int: 1169 delay = self._SCHEDULE[min(self.attempts, len(self._SCHEDULE) - 1)] 1170 self.attempts += 1 1171 return delay 1172 1173 1174_RESTART_POLICIES: dict[str, RestartPolicy] = {} 1175 1176 1177def describe_exit(returncode: int) -> str: 1178 """Render a process return code, decoding signals for negative codes.""" 1179 if returncode >= 0: 1180 return f"exit {returncode}" 1181 try: 1182 name = signal.Signals(-returncode).name 1183 except ValueError: 1184 return f"exit {returncode} / signal {-returncode}" 1185 return f"exit {returncode} / {name}" 1186 1187 1188def _get_restart_policy(name: str) -> RestartPolicy: 1189 return _RESTART_POLICIES.setdefault(name, RestartPolicy()) 1190 1191 1192def _launch_process( 1193 name: str, 1194 cmd: list[str], 1195 *, 1196 restart: bool = False, 1197 shutdown_timeout: int = 15, 1198 ref: str | None = None, 1199 env: dict[str, str] | None = None, 1200) -> RunnerManagedProcess: 1201 # NOTE: All child processes should include -v for verbose logging by default. 1202 # This ensures their output is captured in logs for debugging. 1203 """Launch process with automatic output logging and restart policy tracking.""" 1204 policy: RestartPolicy | None = None 1205 if restart: 1206 policy = _get_restart_policy(name) 1207 1208 # Generate ref if not provided 1209 ref = ref if ref else str(now_ms()) 1210 1211 # Use unified runner to spawn process (share supervisor's callosum) 1212 try: 1213 managed = RunnerManagedProcess.spawn( 1214 cmd, ref=ref, callosum=_supervisor_callosum, env=env 1215 ) 1216 except RuntimeError as exc: 1217 logging.error(str(exc)) 1218 raise 1219 1220 if policy: 1221 policy.record_start() 1222 _SERVICE_STATE[name] = { 1223 "restart": restart, 1224 "shutdown_timeout": shutdown_timeout, 1225 } 1226 1227 # Emit started event 1228 if _supervisor_callosum: 1229 _supervisor_callosum.emit( 1230 "supervisor", 1231 "started", 1232 service=name, 1233 pid=managed.process.pid, 1234 ref=managed.ref, 1235 ) 1236 1237 return managed 1238 1239 1240def _terminate_managed( 1241 managed: RunnerManagedProcess, timeout: float, *, reason: str 1242) -> None: 1243 logger.info("Terminating %s for %s", managed.name, reason) 1244 try: 1245 managed.terminate(timeout=timeout) 1246 except subprocess.TimeoutExpired: 1247 logger.warning( 1248 "%s did not terminate within %.1fs for %s", 1249 managed.name, 1250 timeout, 1251 reason, 1252 ) 1253 1254 1255def _start_termination_thread( 1256 key: str, managed: RunnerManagedProcess, timeout: float, reason: str 1257) -> None: 1258 def run() -> None: 1259 try: 1260 _terminate_managed(managed, timeout, reason=reason) 1261 finally: 1262 with _termination_threads_lock: 1263 if _termination_threads.get(key) is threading.current_thread(): 1264 _termination_threads.pop(key, None) 1265 1266 with _termination_threads_lock: 1267 existing = _termination_threads.get(key) 1268 if existing and existing.is_alive(): 1269 return 1270 1271 thread = threading.Thread( 1272 target=run, 1273 daemon=True, 1274 name=f"terminate-{key}", 1275 ) 1276 _termination_threads[key] = thread 1277 thread.start() 1278 1279 1280def _stop_process( 1281 managed: RunnerManagedProcess, *, timeout_cap: float | None = None 1282) -> None: 1283 timeout = _SERVICE_STATE.get(managed.name, {}).get("shutdown_timeout", 15) 1284 if timeout_cap is not None: 1285 timeout = min(timeout, timeout_cap) 1286 _terminate_managed(managed, timeout, reason="shutdown") 1287 managed.cleanup() 1288 1289 1290def _exit_status_for_code(exit_code: int) -> str: 1291 """Map a scheduled task's process exit code to a scheduler status label. 1292 1293 0 -> "ok"; EXIT_EMPTY -> "empty" (a rollup ran over zero inputs - a distinct, 1294 non-error "nothing to do" outcome); any other non-zero code -> "error". 1295 Timeouts are mapped separately by the caller. 1296 """ 1297 if exit_code == 0: 1298 return "ok" 1299 if exit_code == EXIT_EMPTY: 1300 return "empty" 1301 return "error" 1302 1303 1304def _record_scheduler_completion( 1305 scheduler_name: str, 1306 *, 1307 ended_at: float, 1308 exit_status: str, 1309 ref: str, 1310 cmd: list[str], 1311) -> None: 1312 health_dir = Path(get_journal()) / "health" 1313 health_dir.mkdir(parents=True, exist_ok=True) 1314 state_path = health_dir / "scheduler.json" 1315 with _SCHEDULER_JSON_LOCK: 1316 try: 1317 with open(state_path, "r", encoding="utf-8") as file: 1318 state = json.load(file) 1319 except FileNotFoundError: 1320 state = {} 1321 except (json.JSONDecodeError, OSError) as exc: 1322 logger.warning( 1323 "Failed to load scheduler state for completion write: %s", exc 1324 ) 1325 state = {} 1326 1327 current = state.get(scheduler_name) 1328 if not isinstance(current, dict): 1329 current = {} 1330 current.update( 1331 { 1332 "last_run": ended_at, 1333 "last_status": exit_status, 1334 "last_ref": ref, 1335 } 1336 ) 1337 state[scheduler_name] = current 1338 1339 fd, tmp_path = tempfile.mkstemp( 1340 dir=health_dir, suffix=".tmp", prefix=".scheduler_" 1341 ) 1342 tmp_file = Path(tmp_path) 1343 try: 1344 with open(fd, "w", encoding="utf-8") as file: 1345 json.dump(state, file, indent=2) 1346 tmp_file.replace(state_path) 1347 except BaseException: 1348 tmp_file.unlink(missing_ok=True) 1349 raise 1350 1351 1352def _emit_catchup_backoff( 1353 callosum, 1354 *, 1355 day: str | None, 1356 attempts: int, 1357 consecutive: int, 1358 last_outcome: str, 1359) -> None: 1360 if callosum is None: 1361 return 1362 message = f"day {day} stuck after {attempts} attempts, last outcome {last_outcome}" 1363 try: 1364 callosum.emit( 1365 "storage", 1366 "warning", 1367 level="warning", 1368 type="catchup_backoff", 1369 message=message, 1370 current=consecutive, 1371 threshold=STUCK_THRESHOLD, 1372 ) 1373 callosum.emit( 1374 "notification", 1375 "show", 1376 title="Catchup stuck", 1377 message=message, 1378 icon="⚠️", 1379 action="/app/health", 1380 ) 1381 except Exception: 1382 logging.warning( 1383 "Failed to emit catchup backoff notification for %s", day, exc_info=True 1384 ) 1385 1386 1387def _emit_queue_event(cmd_name: str, running_ref: str, queue: list) -> None: 1388 """Emit supervisor.queue event with current queue state for a command. 1389 1390 This is the callback passed to TaskQueue for queue change notifications. 1391 """ 1392 if not _supervisor_callosum: 1393 return 1394 1395 _supervisor_callosum.emit( 1396 "supervisor", 1397 "queue", 1398 command=cmd_name, 1399 running=running_ref, 1400 queued=len(queue), 1401 queue=queue, 1402 ) 1403 1404 1405def _handle_task_request(message: dict) -> None: 1406 """Handle incoming task request from Callosum.""" 1407 if message.get("tract") != "supervisor" or message.get("event") != "request": 1408 return 1409 1410 cmd = message.get("cmd") 1411 if not cmd: 1412 logging.error(f"Invalid task request: missing cmd: {message}") 1413 return 1414 1415 ref = message.get("ref") or str(now_ms()) 1416 day = message.get("day") 1417 scheduler_name = message.get("scheduler_name") 1418 if _task_queue: 1419 cmd_name = TaskQueue.get_command_name(cmd) 1420 active_ref = _task_queue.get_active_by_cmd_name(cmd_name) 1421 if active_ref: 1422 with _task_queue._lock: 1423 managed = _task_queue._active.get(active_ref) 1424 cap = _task_queue._effective_cap(cmd_name) 1425 runtime = time.time() - managed.start_time if managed else 0 1426 reason = "wedged" if runtime > 2 * cap else "still_running" 1427 if _supervisor_callosum: 1428 _supervisor_callosum.emit( 1429 "supervisor", 1430 "skipped", 1431 reason=reason, 1432 ref=ref, 1433 active_ref=active_ref, 1434 cmd=cmd, 1435 scheduler_name=scheduler_name, 1436 ) 1437 return 1438 _task_queue.submit(cmd, ref, day=day, scheduler_name=scheduler_name) 1439 1440 1441def _restart_service(service: str) -> bool: 1442 """Terminate a managed service to trigger graceful restart. 1443 1444 Returns True if the service was found and running, False if not found 1445 or already exited. 1446 """ 1447 for proc in _managed_procs: 1448 if proc.name == service: 1449 if proc.process.poll() is not None: 1450 logging.debug( 1451 f"Ignoring restart for {service}: already exited, awaiting auto-restart" 1452 ) 1453 return False 1454 1455 state = _SERVICE_STATE.setdefault(service, {}) 1456 state["restart"] = True 1457 timeout = state.get("shutdown_timeout", 15) 1458 1459 logging.info(f"Restart requested for {service}, terminating...") 1460 1461 if _supervisor_callosum: 1462 _supervisor_callosum.emit( 1463 "supervisor", 1464 "restarting", 1465 service=service, 1466 pid=proc.process.pid, 1467 ref=proc.ref, 1468 ) 1469 1470 _start_termination_thread(service, proc, timeout=timeout, reason="restart") 1471 return True 1472 1473 logging.warning(f"Cannot restart {service}: not found in managed processes") 1474 return False 1475 1476 1477def _handle_supervisor_request(message: dict) -> None: 1478 """Handle incoming supervisor control messages.""" 1479 if message.get("tract") != "supervisor" or message.get("event") != "restart": 1480 return 1481 1482 service = message.get("service") 1483 if not service: 1484 logging.error("Invalid restart request: missing service") 1485 return 1486 if service == "supervisor": 1487 logging.debug("Ignoring restart request for supervisor itself") 1488 return 1489 1490 _restart_service(service) 1491 1492 1493def _handle_supervisor_drain(message: dict) -> None: 1494 """Handle incoming supervisor catchup drain requests.""" 1495 if message.get("tract") != "supervisor" or message.get("event") != "drain": 1496 return 1497 if _is_remote_mode: 1498 return 1499 1500 day = message.get("day") 1501 if day: 1502 run_catchup_drain(force_days={day}) 1503 else: 1504 run_catchup_drain() 1505 1506 1507def _handle_supervisor_start_local(message: dict) -> None: 1508 """Handle incoming local server start requests.""" 1509 if message.get("tract") != "supervisor" or message.get("event") != "start_local": 1510 return 1511 if _is_remote_mode: 1512 return 1513 from solstone.think.providers.local_endpoint import resolve_local_endpoint 1514 1515 if not resolve_local_endpoint().is_bundled: 1516 return 1517 1518 for proc in _managed_procs: 1519 if proc.name in _LOCAL_SERVER_PROCTITLES and proc.is_running(): 1520 logging.info("local server already running; ignoring start_local request") 1521 return 1522 1523 proc = start_local_server() 1524 if proc is not None: 1525 _managed_procs.append(proc) 1526 logging.info("started local server from start_local request") 1527 1528 1529def _handle_cortex_outcome(message: dict) -> None: 1530 """Recycle a wedged local model server after sustained generation failures.""" 1531 if message.get("tract") != "cortex": 1532 return 1533 event = message.get("event") 1534 if event not in {"start", "finish", "error"}: 1535 return 1536 if _is_remote_mode: 1537 return 1538 1539 use_id = message.get("use_id") 1540 if not use_id: 1541 return 1542 1543 if event == "start": 1544 providers = _wedge_state["providers"] 1545 providers[use_id] = message.get("provider") 1546 while len(providers) > LOCAL_WEDGE_PROVIDER_MAP_CAP: 1547 providers.popitem(last=False) 1548 return 1549 1550 provider = _wedge_state["providers"].get(use_id) 1551 if provider != "local": 1552 return 1553 from solstone.think.providers.local_endpoint import resolve_local_endpoint 1554 1555 if not resolve_local_endpoint().is_bundled: 1556 return 1557 1558 if time.monotonic() < _wedge_state["cooldown_until"]: 1559 return 1560 1561 failures = _wedge_state["failures"] 1562 if event == "finish": 1563 if _wedge_state["awaiting_recovery"]: 1564 logging.info("local server wedge: recovered after recycle") 1565 _wedge_state["awaiting_recovery"] = False 1566 failures.clear() 1567 return 1568 1569 if message.get("reason_code") != "provider_unavailable": 1570 return 1571 1572 failures.add(use_id) 1573 if len(failures) < LOCAL_WEDGE_THRESHOLD: 1574 return 1575 1576 logging.warning( 1577 "local server wedge: declared after %d local provider_unavailable failures " 1578 "(use_ids=%s)", 1579 len(failures), 1580 sorted(failures), 1581 ) 1582 port = read_service_port("local") 1583 if port is None: 1584 logging.warning( 1585 "local server wedge: recycle deferred; local service port unavailable" 1586 ) 1587 failures.clear() 1588 return 1589 1590 from solstone.think.providers import local_server 1591 1592 state, _ = local_server._probe_health(port) 1593 if state != local_server.STATE_READY: 1594 logging.warning( 1595 "local server wedge: recycle deferred; health state=%s", 1596 state, 1597 ) 1598 failures.clear() 1599 return 1600 1601 proctitle = ( 1602 MLX_SERVER_PROCESS_NAME 1603 if sys.platform == "darwin" 1604 else LOCAL_SERVER_PROCESS_NAME 1605 ) 1606 if _restart_service(proctitle): 1607 logging.warning("local server wedge: recycling %s", proctitle) 1608 failures.clear() 1609 _wedge_state["awaiting_recovery"] = True 1610 _wedge_state["cooldown_until"] = time.monotonic() + LOCAL_WEDGE_RECYCLE_GRACE_S 1611 else: 1612 logging.warning("local server wedge: recycle deferred; service not running") 1613 failures.clear() 1614 1615 1616def get_task_status(ref: str) -> dict: 1617 """Get status of a task. 1618 1619 Args: 1620 ref: Task correlation ID 1621 1622 Returns: 1623 Dict with status info, or {"status": "not_found"} if task doesn't exist 1624 """ 1625 if _task_queue: 1626 return _task_queue.get_status(ref) 1627 return {"status": "not_found"} 1628 1629 1630def collect_status(procs: list[RunnerManagedProcess]) -> dict: 1631 """Collect current supervisor status for broadcasting.""" 1632 now = time.time() 1633 1634 # Running services 1635 services = [] 1636 running_names = set() 1637 for proc in procs: 1638 if proc.process.poll() is None: # Still running 1639 policy = _get_restart_policy(proc.name) 1640 uptime = int(now - policy.last_start) if policy.last_start else 0 1641 services.append( 1642 { 1643 "name": proc.name, 1644 "ref": proc.ref, 1645 "pid": proc.process.pid, 1646 "uptime_seconds": uptime, 1647 } 1648 ) 1649 running_names.add(proc.name) 1650 1651 # Prepend supervisor itself 1652 if _supervisor_ref and _supervisor_start: 1653 services.insert( 1654 0, 1655 { 1656 "name": "supervisor", 1657 "ref": _supervisor_ref, 1658 "pid": os.getpid(), 1659 "uptime_seconds": int(now - _supervisor_start), 1660 }, 1661 ) 1662 1663 # Crashed services (in restart backoff) 1664 crashed = [] 1665 for name, policy in _RESTART_POLICIES.items(): 1666 if name not in running_names and policy.attempts > 0: 1667 crashed.append( 1668 { 1669 "name": name, 1670 "restart_attempts": policy.attempts, 1671 } 1672 ) 1673 1674 # Running tasks 1675 tasks = _task_queue.collect_task_status() if _task_queue else [] 1676 queues = _task_queue.collect_queue_counts() if _task_queue else {} 1677 1678 # Scheduled tasks 1679 schedules = scheduler.collect_status() 1680 # Connected callosum clients 1681 callosum_clients = _callosum_server.client_count() if _callosum_server else 0 1682 1683 return { 1684 "services": services, 1685 "crashed": crashed, 1686 "tasks": tasks, 1687 "queues": queues, 1688 "stale_heartbeats": [], 1689 "schedules": schedules, 1690 "callosum_clients": callosum_clients, 1691 } 1692 1693 1694def start_sense() -> RunnerManagedProcess: 1695 """Launch journal sense with output logging.""" 1696 return _launch_process("sense", ["journal", "sense", "-v"], restart=True) 1697 1698 1699def _start_mlx_local_server() -> RunnerManagedProcess | None: 1700 """Launch the supervisor-owned mlx-vlm server when artifacts are present.""" 1701 from solstone.think.providers import local_server, mlx_install 1702 1703 readiness = mlx_install.inspect_readiness() 1704 readiness_keys = ( 1705 "platform_supported", 1706 "package_available", 1707 "ram_sufficient", 1708 "model_installed", 1709 ) 1710 if not all(readiness.get(key) for key in readiness_keys): 1711 logging.info( 1712 "MLX local model not ready; skipping mlx-vlm server startup: %s", 1713 {key: readiness.get(key) for key in readiness_keys}, 1714 ) 1715 return None 1716 1717 runtime_dir = readiness["runtime_dir"] 1718 model_id = readiness["model_id"] 1719 port = find_available_port() 1720 write_service_port("local", port) 1721 script_path = str(Path(sys.executable).with_name(MLX_SERVER_PROCESS_NAME)) 1722 cmd = [ 1723 script_path, 1724 "--host", 1725 "127.0.0.1", 1726 "--port", 1727 str(port), 1728 "--model", 1729 str(runtime_dir), 1730 ] 1731 if "0.0.0.0" in cmd: 1732 raise RuntimeError("Local server may not bind 0.0.0.0.") 1733 1734 logging.info("Starting mlx-vlm server for %s from %s", model_id, runtime_dir) 1735 managed = _launch_process(MLX_SERVER_PROCESS_NAME, cmd, restart=True) 1736 print(f" {LOCAL_MODEL_WARMING_UP_COPY}", flush=True) 1737 1738 deadline = time.monotonic() + LOCAL_SERVER_READY_TIMEOUT_S 1739 while time.monotonic() < deadline: 1740 if managed.process.poll() is not None: 1741 logging.warning( 1742 "mlx-vlm server exited during warmup with code %s", 1743 managed.process.returncode, 1744 ) 1745 return managed 1746 state, error = local_server._probe_health(port) 1747 if state == local_server.STATE_READY: 1748 logging.info("mlx-vlm server ready on port %s", port) 1749 return managed 1750 if state == local_server.STATE_FAILED and error: 1751 logging.debug("mlx-vlm server health probe failed during warmup: %s", error) 1752 time.sleep(LOCAL_SERVER_HEALTH_POLL_INTERVAL_S) 1753 1754 logging.warning( 1755 "mlx-vlm server did not become ready within %.0fs; continuing startup", 1756 LOCAL_SERVER_READY_TIMEOUT_S, 1757 ) 1758 return managed 1759 1760 1761def _format_vulkan_devices(devices: list[Any], local_vulkan: Any) -> str: 1762 if not devices: 1763 return "none" 1764 return "; ".join( 1765 ( 1766 f"raw_index={device.index} name={device.name!r} " 1767 f"type={local_vulkan.classify(device)} vram_mib={device.vram_mib}" 1768 ) 1769 for device in devices 1770 ) 1771 1772 1773def _gpu_unavailable_reason(devices: list[Any], override: int | None) -> str: 1774 if not devices: 1775 return "no Vulkan devices enumerated" 1776 if override is not None: 1777 return f"Vulkan override raw index {override} is not an available hardware GPU" 1778 return "only non-hardware or software Vulkan devices were enumerated" 1779 1780 1781def _log_context_assertion( 1782 tier: Any, n_ctx: int | None, total_slots: int | None 1783) -> None: 1784 if n_ctx is None: 1785 logging.info( 1786 "llama-server context assertion skipped: n_ctx unavailable from /props" 1787 ) 1788 else: 1789 expected = {tier.context_tokens, tier.context_tokens * tier.parallel_slots} 1790 if n_ctx in expected: 1791 logging.info( 1792 "llama-server context OK: intended -c=%d parallel=%d actual n_ctx=%d", 1793 tier.context_tokens, 1794 tier.parallel_slots, 1795 n_ctx, 1796 ) 1797 else: 1798 logging.warning( 1799 "llama-server context MISMATCH: intended -c=%d parallel=%d " 1800 "actual n_ctx=%d", 1801 tier.context_tokens, 1802 tier.parallel_slots, 1803 n_ctx, 1804 ) 1805 1806 if isinstance(total_slots, int): 1807 if total_slots == tier.parallel_slots: 1808 logging.info("llama-server slots OK: %d", total_slots) 1809 else: 1810 logging.warning( 1811 "llama-server slots MISMATCH: intended=%d actual=%d", 1812 tier.parallel_slots, 1813 total_slots, 1814 ) 1815 else: 1816 logging.info("llama-server slot count not reported; skipped") 1817 1818 1819def start_local_server() -> RunnerManagedProcess | None: 1820 """Launch the supervisor-owned local llama-server when artifacts are present.""" 1821 from solstone.think.providers.local_endpoint import resolve_local_endpoint 1822 1823 if not resolve_local_endpoint().is_bundled: 1824 return None 1825 1826 if sys.platform == "darwin": 1827 return _start_mlx_local_server() 1828 1829 from solstone.think.providers import local_install, local_server, local_vulkan 1830 1831 try: 1832 binary_path, gguf_path, mmproj_path = local_install.ensure_artifacts_installed( 1833 LOCAL_MODEL 1834 ) 1835 # Defense in depth: refuse to launch a gguf/mmproj pair that does not 1836 # belong to the selected model, even if readiness ever regresses. A 1837 # mixed pair (e.g. a stale gguf from a prior model + the current mmproj) 1838 # aborts llama-server with an n_embd mismatch, so skip startup instead. 1839 expected_dir = local_install.model_dir(LOCAL_MODEL) 1840 if gguf_path.parent != expected_dir or ( 1841 mmproj_path is not None and mmproj_path.parent != expected_dir 1842 ): 1843 raise RuntimeError( 1844 f"local model artifacts are not under {expected_dir} " 1845 f"(gguf={gguf_path}, mmproj={mmproj_path}); refusing to launch " 1846 "a mismatched gguf/mmproj pair" 1847 ) 1848 except Exception as exc: 1849 logging.info("Local model not ready; skipping llama-server startup: %s", exc) 1850 return None 1851 1852 devices = local_vulkan.detect_gpus() 1853 override = local_install.gpu_device_override() 1854 selected = local_vulkan.select_device(devices, override_index=override) 1855 logging.info( 1856 "Vulkan GPU probe: devices=%s; selected=%s", 1857 _format_vulkan_devices(devices, local_vulkan), 1858 ( 1859 f"raw_index={selected.index} name={selected.name!r} " 1860 f"type={local_vulkan.classify(selected)}" 1861 if selected is not None 1862 else "none" 1863 ), 1864 ) 1865 if selected is None: 1866 reason = _gpu_unavailable_reason(devices, override) 1867 logging.info("gpu_unavailable: skipping llama-server startup: %s", reason) 1868 return None 1869 1870 port = find_available_port() 1871 write_service_port("local", port) 1872 tier = local_server.select_server_tier(selected.vram_mib) 1873 local_server.write_local_context_window(tier.context_tokens) 1874 logging.info( 1875 "local server tier=%s context=%d parallel=%d cache=%d MiB (vram=%d MiB)", 1876 tier.name, 1877 tier.context_tokens, 1878 tier.parallel_slots, 1879 tier.prompt_cache_mib, 1880 selected.vram_mib, 1881 ) 1882 cmd = [ 1883 str(binary_path), 1884 "-m", 1885 str(gguf_path), 1886 "--alias", 1887 LOCAL_MODEL, 1888 "--host", 1889 "127.0.0.1", 1890 "--port", 1891 str(port), 1892 "--jinja", 1893 "--n-gpu-layers", 1894 "999", 1895 "-c", 1896 str(tier.context_tokens), 1897 "--parallel", 1898 str(tier.parallel_slots), 1899 "--kv-unified", 1900 "--cache-ram", 1901 str(tier.prompt_cache_mib), 1902 "--no-context-shift", 1903 "--device", 1904 "Vulkan0", 1905 ] 1906 if mmproj_path is not None: 1907 cmd.extend(["--mmproj", str(mmproj_path)]) 1908 if "0.0.0.0" in cmd: 1909 raise RuntimeError("Local server may not bind 0.0.0.0.") 1910 1911 env = os.environ | {"GGML_VK_VISIBLE_DEVICES": str(selected.index)} 1912 vram_before_mib = local_vulkan.device_local_used_mib(selected.index) 1913 managed = _launch_process(LOCAL_SERVER_PROCESS_NAME, cmd, restart=True, env=env) 1914 print(f" {LOCAL_MODEL_WARMING_UP_COPY}", flush=True) 1915 1916 def fail_local_server_launch(reason: str) -> None: 1917 logging.warning("local server launch failed: %s", reason) 1918 timeout = _SERVICE_STATE.get(managed.name, {}).get("shutdown_timeout", 15) 1919 _SERVICE_STATE.pop(managed.name, None) 1920 _terminate_managed( 1921 managed, 1922 timeout, 1923 reason="local server launch failed", 1924 ) 1925 managed.cleanup() 1926 1927 deadline = time.monotonic() + LOCAL_SERVER_READY_TIMEOUT_S 1928 while time.monotonic() < deadline: 1929 if managed.process.poll() is not None: 1930 fail_local_server_launch( 1931 f"llama-server exited during warmup with code " 1932 f"{managed.process.returncode}" 1933 ) 1934 return None 1935 state, error = local_server._probe_health(port) 1936 if state == local_server.STATE_READY: 1937 vram_after_mib = local_vulkan.device_local_used_mib(selected.index) 1938 if vram_before_mib is not None and vram_after_mib is not None: 1939 logging.info( 1940 "local GPU: %s — VRAM used %+d MiB after model load (%d -> %d MiB)", 1941 selected.name, 1942 vram_after_mib - vram_before_mib, 1943 vram_before_mib, 1944 vram_after_mib, 1945 ) 1946 else: 1947 logging.info( 1948 "local GPU: %s — VRAM-usage delta unavailable " 1949 "(VK_EXT_memory_budget not reported)", 1950 selected.name, 1951 ) 1952 props = local_server.fetch_props(port) 1953 n_ctx = local_server._extract_n_ctx(props) if props is not None else None 1954 total_slots = props.get("total_slots") if isinstance(props, dict) else None 1955 _log_context_assertion(tier, n_ctx, total_slots) 1956 logging.info("llama-server ready on port %s", port) 1957 return managed 1958 if state == local_server.STATE_FAILED and error: 1959 logging.debug("llama-server health probe failed during warmup: %s", error) 1960 time.sleep(LOCAL_SERVER_HEALTH_POLL_INTERVAL_S) 1961 1962 logging.warning( 1963 "llama-server did not become ready within %.0fs; continuing startup", 1964 LOCAL_SERVER_READY_TIMEOUT_S, 1965 ) 1966 return managed 1967 1968 1969def start_callosum_in_process() -> CallosumServer: 1970 """Start Callosum message bus server in-process. 1971 1972 Runs the server in a background thread and waits for socket to be ready. 1973 1974 Returns: 1975 CallosumServer instance 1976 """ 1977 global _callosum_server, _callosum_thread 1978 1979 server = CallosumServer() 1980 _callosum_server = server 1981 1982 # Pre-delete stale socket to avoid race condition where the ready check 1983 # passes due to an old socket file before the server thread deletes it 1984 socket_path = server.socket_path 1985 socket_path.parent.mkdir(parents=True, exist_ok=True) 1986 if socket_path.exists(): 1987 socket_path.unlink() 1988 1989 # Start server in background thread (server.start() is blocking) 1990 thread = threading.Thread(target=server.start, daemon=False, name="callosum-server") 1991 thread.start() 1992 _callosum_thread = thread 1993 1994 # Wait for socket to be ready (with timeout) 1995 for _ in range(50): # Wait up to 500ms 1996 if socket_path.exists(): 1997 logging.info(f"Callosum server started on {socket_path}") 1998 return server 1999 time.sleep(0.01) 2000 2001 raise RuntimeError("Callosum server failed to create socket within 500ms") 2002 2003 2004def wait_for_convey_ready( 2005 convey_mp, *, timeout: float = CONVEY_READY_WINDOW_SECONDS, interval: float = 0.1 2006) -> bool: 2007 """Poll until Convey accepts TCP connections, or fail fast on death/timeout.""" 2008 start = time.monotonic() 2009 deadline = start + timeout 2010 while time.monotonic() < deadline: 2011 rc = convey_mp.process.poll() 2012 if rc is not None: 2013 logging.error( 2014 "Convey process exited during startup (rc=%d); continuing into supervise loop", 2015 rc, 2016 ) 2017 return False 2018 if is_solstone_up(timeout=0.1): 2019 logging.info("Convey ready after %.1fs", time.monotonic() - start) 2020 return True 2021 time.sleep(interval) 2022 alive = convey_mp.process.poll() is None 2023 logging.error( 2024 "Convey not ready after %.1fs (port=%s, pid alive=%s); continuing into supervise loop", 2025 time.monotonic() - start, 2026 read_service_port("convey"), 2027 alive, 2028 ) 2029 return False 2030 2031 2032def stop_callosum_in_process(join_timeout: float = 5.0) -> None: 2033 """Stop the in-process Callosum server.""" 2034 global _callosum_server, _callosum_thread 2035 2036 if _callosum_server: 2037 logging.info("Stopping Callosum server...") 2038 _callosum_server.stop() 2039 2040 if _callosum_thread: 2041 _callosum_thread.join(timeout=join_timeout) 2042 if _callosum_thread.is_alive(): 2043 logging.warning("Callosum server thread did not stop cleanly") 2044 2045 _callosum_server = None 2046 _callosum_thread = None 2047 2048 2049def start_cortex_server() -> RunnerManagedProcess: 2050 """Launch the Cortex WebSocket API server.""" 2051 cmd = ["journal", "cortex", "-v"] 2052 return _launch_process("cortex", cmd, restart=True) 2053 2054 2055def start_spl_service() -> RunnerManagedProcess: 2056 """Launch the spl tunnel service.""" 2057 cmd = ["journal", "spl", "-v"] 2058 return _launch_process("spl", cmd, restart=True) 2059 2060 2061def start_convey_server( 2062 verbose: bool, debug: bool = False, port: int = 0 2063) -> tuple[RunnerManagedProcess, int]: 2064 """Launch the Convey web application with optional verbose and debug logging. 2065 2066 Returns: 2067 Tuple of (RunnerManagedProcess, resolved_port) where resolved_port is the 2068 actual port being used (auto-selected if port was 0). 2069 """ 2070 # Resolve port 0 to an available port before launching 2071 resolved_port = port if port != 0 else find_available_port() 2072 2073 cmd = ["journal", "convey", "--port", str(resolved_port)] 2074 if debug: 2075 cmd.append("-d") 2076 elif verbose: 2077 cmd.append("-v") 2078 return _launch_process("convey", cmd, restart=True), resolved_port 2079 2080 2081def check_runner_exits( 2082 procs: list[RunnerManagedProcess], 2083) -> list[RunnerManagedProcess]: 2084 """Return managed processes that have exited.""" 2085 2086 exited: list[RunnerManagedProcess] = [] 2087 for managed in procs: 2088 if managed.process.poll() is not None: 2089 exited.append(managed) 2090 return exited 2091 2092 2093async def handle_runner_exits(procs: list[RunnerManagedProcess]) -> None: 2094 """Check for and handle exited processes with restart policy.""" 2095 exited = check_runner_exits(procs) 2096 if not exited: 2097 return 2098 2099 exited_names = [managed.name for managed in exited] 2100 2101 # Check if all exits are tempfail (session not ready) 2102 all_tempfail = all(m.process.returncode == EXIT_TEMPFAIL for m in exited) 2103 2104 if all_tempfail: 2105 logging.info("Runner waiting for session: %s", ", ".join(sorted(exited_names))) 2106 else: 2107 parts = [] 2108 for m in sorted(exited, key=lambda managed: managed.name): 2109 policy = _get_restart_policy(m.name) 2110 if policy.last_start: 2111 uptime = f"up {time.time() - policy.last_start:.1f}s" 2112 else: 2113 uptime = "up unknown" 2114 parts.append(f"{m.name} ({describe_exit(m.process.returncode)}, {uptime})") 2115 msg = f"Runner process exited: {', '.join(parts)}" 2116 logging.error(msg) 2117 2118 for managed in exited: 2119 returncode = managed.process.returncode 2120 is_tempfail = returncode == EXIT_TEMPFAIL 2121 logging.info("%s exited with code %s", managed.name, returncode) 2122 2123 # Emit stopped event 2124 if _supervisor_callosum: 2125 _supervisor_callosum.emit( 2126 "supervisor", 2127 "stopped", 2128 service=managed.name, 2129 pid=managed.process.pid, 2130 ref=managed.ref, 2131 exit_code=returncode, 2132 ) 2133 2134 # Remove from procs list 2135 try: 2136 procs.remove(managed) 2137 except ValueError: 2138 pass 2139 2140 managed.cleanup() 2141 2142 # Handle restart if needed 2143 restart = _SERVICE_STATE.get(managed.name, {}).get("restart", False) 2144 if restart and not shutdown_requested: 2145 # Tempfail: use fixed longer delay, don't burn through backoff 2146 if is_tempfail: 2147 delay = TEMPFAIL_DELAY 2148 else: 2149 policy = _get_restart_policy(managed.name) 2150 uptime = time.time() - policy.last_start if policy.last_start else 0 2151 if uptime >= 60: 2152 policy.reset_attempts() 2153 delay = policy.next_delay() 2154 if delay: 2155 logging.info("Waiting %ss before restarting %s", delay, managed.name) 2156 for _ in range(delay): 2157 if shutdown_requested: 2158 break 2159 await asyncio.sleep(1) 2160 if shutdown_requested: 2161 continue 2162 logging.info("Restarting %s...", managed.name) 2163 try: 2164 state = _SERVICE_STATE.get(managed.name, {}) 2165 new_proc = _launch_process( 2166 managed.name, 2167 managed.cmd, 2168 restart=True, 2169 shutdown_timeout=state.get("shutdown_timeout", 15), 2170 ) 2171 except Exception as exc: 2172 logging.exception("Failed to restart %s: %s", managed.name, exc) 2173 continue 2174 2175 procs.append(new_proc) 2176 if managed.name in _LOCAL_SERVER_PROCTITLES: 2177 _recovery_state["local_server_down"] = True 2178 logging.info("Restarted %s after exit code %s", managed.name, returncode) 2179 else: 2180 logging.info("Not restarting %s", managed.name) 2181 2182 2183def _nudge_catchup_drain() -> None: 2184 """Ask the supervisor loopback path to drain pending catchup work.""" 2185 if _supervisor_callosum is None: 2186 logging.warning("Cannot nudge catchup drain: supervisor callosum unavailable") 2187 return 2188 2189 try: 2190 _supervisor_callosum.emit("supervisor", "drain") 2191 except Exception as exc: 2192 logging.warning("Cannot nudge catchup drain: %s", exc) 2193 2194 2195async def _check_local_server_recovery() -> None: 2196 """Detect a recovered local server after supervisor-managed relaunch.""" 2197 if _is_remote_mode or not _recovery_state["local_server_down"]: 2198 return 2199 from solstone.think.providers.local_endpoint import resolve_local_endpoint 2200 2201 if not resolve_local_endpoint().is_bundled: 2202 return 2203 2204 port = read_service_port("local") 2205 if port is None: 2206 return 2207 2208 from solstone.think.providers import local_server 2209 2210 state, _ = await asyncio.to_thread(local_server._probe_health, port) 2211 if state != local_server.STATE_READY: 2212 return 2213 2214 _recovery_state["local_server_down"] = False 2215 _nudge_catchup_drain() 2216 2217 2218def run_catchup_drain( 2219 force_days: Iterable[str] | None = None, 2220 *, 2221 exclude: set[str] | None = None, 2222) -> list[str]: 2223 """Submit catchup daily think tasks for pending, eligible days.""" 2224 all_updated = updated_days(exclude=exclude) 2225 2226 def _eligible(day: str) -> bool: 2227 try: 2228 return day_eligible_to_drain(day, KIND_DAILY_CATCHUP) 2229 except Exception: 2230 logging.warning( 2231 "Catchup eligibility check failed for %s; treating as eligible", 2232 day, 2233 ) 2234 return True 2235 2236 eligible_natural = [day for day in all_updated if _eligible(day)] 2237 # AC3: force uses the same backoff gate. AC8: cap natural days after 2238 # eligibility; forced eligible days keep importer single-day intent. 2239 freshest = eligible_natural[-MAX_UPDATED_CATCHUP:] 2240 forced_eligible = [day for day in (force_days or []) if _eligible(day)] 2241 merged = set(freshest) | set(forced_eligible) 2242 if not merged: 2243 logging.info("no eligible days to process") 2244 return [] 2245 2246 if _task_queue is None: 2247 logging.warning("No task queue available for catchup drain: %s", sorted(merged)) 2248 return [] 2249 2250 days = sorted(merged) 2251 logging.info("Queuing catchup drain for %d day(s): %s", len(days), days) 2252 for day_str in days: 2253 cmd = ["journal", "think", "-v", "--day", day_str] 2254 _task_queue.submit(cmd, day=day_str) 2255 return days 2256 2257 2258def _startup_catchup_drain() -> None: 2259 try: 2260 transitions = reconcile_interrupted_attempts() 2261 for transition in transitions: 2262 _emit_catchup_backoff( 2263 _supervisor_callosum, 2264 day=transition.day, 2265 attempts=transition.attempts, 2266 consecutive=transition.consecutive_non_completion, 2267 last_outcome=transition.last_outcome, 2268 ) 2269 except Exception: 2270 logging.warning("Catchup reconciliation failed", exc_info=True) 2271 run_catchup_drain() 2272 2273 2274def handle_daily_tasks() -> None: 2275 """Check for day change and submit daily think for updated days (non-blocking). 2276 2277 Triggers once when the day rolls over at midnight. Queries ``updated_days()`` 2278 for journal days that have new stream data but haven't completed a daily 2279 think yet, then submits up to ``MAX_UPDATED_CATCHUP`` thinks in chronological 2280 order (oldest first, yesterday last) via the TaskQueue. 2281 2282 Think auto-detects updated state and enables ``--refresh`` internally, so we 2283 don't pass it here. 2284 2285 Skipped in remote mode (no local data to process). 2286 """ 2287 # Remote mode: no local processing, data is on the server 2288 if _is_remote_mode: 2289 return 2290 2291 today = datetime.now().date() 2292 2293 # Only trigger when day actually changes (at midnight) 2294 if today != _daily_state["last_day"]: 2295 # The day that just ended is what we process 2296 prev_day = _daily_state["last_day"] 2297 2298 # Guard against None (e.g., module reloaded without going through main()) 2299 if prev_day is None: 2300 logging.warning("Daily state not initialized, skipping daily processing") 2301 _daily_state["last_day"] = today 2302 return 2303 2304 prev_day_str = prev_day.strftime("%Y%m%d") 2305 2306 # Update state for new day 2307 _daily_state["last_day"] = today 2308 2309 # Flush any dangling segment state from the previous day before daily think 2310 if not _flush_state["flushed"] and _flush_state["day"] == prev_day_str: 2311 _check_segment_flush(force=True) 2312 2313 today_str = today.strftime("%Y%m%d") 2314 run_catchup_drain(exclude={today_str}) 2315 2316 2317def _handle_segment_observed(message: dict) -> None: 2318 """Handle segment completion events (from live observation or imports). 2319 2320 Submits journal think in segment mode via task queue, which handles both 2321 generators and segment agents. Also updates flush state to track 2322 segment recency. 2323 """ 2324 if message.get("tract") != "observe" or message.get("event") != "observed": 2325 return 2326 2327 segment = message.get("segment") # e.g., "163045_300" 2328 if not segment: 2329 logging.warning("observed event missing segment field") 2330 return 2331 2332 # Use day from event payload, fallback to today (for live observation) 2333 day = message.get("day") or datetime.now().strftime("%Y%m%d") 2334 2335 # Batch/historical re-sensing heals deterministically via daily catchup's 2336 # segment-think pre-phase. A lone volatile segment think for a re-sensed 2337 # past segment can rewind live activity-timeline state, so submit nothing; 2338 # also leave flush state untouched so stale segments cannot reset 2339 # _check_segment_flush or pollute handle_daily_tasks' force-flush gate. 2340 if message.get("batch"): 2341 logging.info( 2342 "Batch observed segment deferred to daily catchup; " 2343 "no volatile segment think submitted: %s/%s", 2344 day, 2345 segment, 2346 ) 2347 return 2348 2349 if load_processing_settings().mode == "deferred": 2350 logging.info( 2351 "Deferred mode: live segment %s/%s held for catchup drain; no live think", 2352 day, 2353 segment, 2354 ) 2355 return 2356 2357 stream = message.get("stream") 2358 2359 # Update flush state — new segment resets the flush timer 2360 _flush_state["last_segment_ts"] = time.time() 2361 _flush_state["day"] = day 2362 _flush_state["segment"] = segment 2363 _flush_state["stream"] = stream 2364 _flush_state["flushed"] = False 2365 2366 logging.info(f"Segment observed: {day}/{segment}, submitting processing...") 2367 2368 # Submit via task queue — serializes with other think invocations 2369 cmd = ["journal", "think", "-v", "--day", day, "--segment", segment] 2370 if stream: 2371 cmd.extend(["--stream", stream]) 2372 if not message.get("batch"): 2373 cmd.append("--live") 2374 if _task_queue: 2375 _task_queue.submit(cmd, day=day) 2376 else: 2377 logging.warning( 2378 "No task queue available for segment processing: %s/%s", day, segment 2379 ) 2380 2381 2382def _check_segment_flush(force: bool = False) -> None: 2383 """Check if the last observed segment needs flushing. 2384 2385 If no new segments have arrived within FLUSH_TIMEOUT seconds, runs 2386 ``journal think --flush`` on the last segment to let flush-enabled agents 2387 close out dangling state (e.g., end active activities). 2388 2389 Args: 2390 force: Skip timeout check (used at day boundary to flush 2391 before daily think regardless of elapsed time). 2392 2393 Skipped in remote mode (no local processing). 2394 """ 2395 if _is_remote_mode: 2396 return 2397 2398 last_ts = _flush_state["last_segment_ts"] 2399 if not last_ts or _flush_state["flushed"]: 2400 return 2401 2402 if load_processing_settings().mode == "deferred": 2403 return 2404 2405 if not force and time.time() - last_ts < FLUSH_TIMEOUT: 2406 return 2407 2408 day = _flush_state["day"] 2409 segment = _flush_state["segment"] 2410 if not day or not segment: 2411 return 2412 2413 _flush_state["flushed"] = True 2414 2415 stream = _flush_state.get("stream") 2416 cmd = ["journal", "think", "-v", "--day", day, "--segment", segment, "--flush"] 2417 if stream: 2418 cmd.extend(["--stream", stream]) 2419 if _task_queue: 2420 _task_queue.submit(cmd, day=day) 2421 logging.info(f"Queued segment flush: {day}/{segment}") 2422 else: 2423 logging.warning( 2424 "No task queue available for segment flush: %s/%s", day, segment 2425 ) 2426 2427 2428def _handle_segment_event_log(message: dict) -> None: 2429 """Log observe, think, and activity events with day+segment to segment/events.jsonl. 2430 2431 Any observe, think, or activity tract message with both day and segment fields 2432 gets logged to journal/day/segment/events.jsonl if that directory exists. 2433 """ 2434 if message.get("tract") not in {"observe", "think", "activity"}: 2435 return 2436 2437 day = message.get("day") 2438 segment = message.get("segment") 2439 2440 if not day or not segment: 2441 return 2442 2443 stream = message.get("stream") 2444 2445 try: 2446 if stream: 2447 segment_dir = day_path(day, create=False) / stream / segment 2448 else: 2449 segment_dir = day_path(day, create=False) / segment 2450 2451 # Only log if segment directory exists 2452 if not segment_dir.is_dir(): 2453 return 2454 2455 events_file = segment_dir / "events.jsonl" 2456 2457 # Append event as JSON line 2458 with open(events_file, "a", encoding="utf-8") as f: 2459 f.write(json.dumps(message, ensure_ascii=False) + "\n") 2460 2461 except Exception as e: 2462 logging.debug(f"Failed to log segment event: {e}") 2463 2464 2465def _handle_activity_recorded(message: dict) -> None: 2466 """Queue a per-activity think task when an activity is recorded. 2467 2468 Listens for activity.recorded events and submits a queued think task 2469 for per-activity agent processing (serialized via TaskQueue). 2470 """ 2471 if message.get("tract") != "activity" or message.get("event") != "recorded": 2472 return 2473 2474 record_id = message.get("id") 2475 facet = message.get("facet") 2476 day = message.get("day") 2477 2478 if not record_id or not facet or not day: 2479 logging.warning("activity.recorded event missing required fields") 2480 return 2481 2482 cmd = ["journal", "think", "--activity", record_id, "--facet", facet, "--day", day] 2483 2484 if _task_queue: 2485 _task_queue.submit(cmd, day=day) 2486 logging.info(f"Queued activity think: {record_id} for #{facet}") 2487 else: 2488 logging.warning("No task queue available for activity think: %s", record_id) 2489 2490 2491def _handle_think_daily_complete(message: dict) -> None: 2492 """Submit a heartbeat task after daily think processing completes. 2493 2494 Listens for think.daily_complete events. Skips if a heartbeat process 2495 is already running (PID file guard). 2496 """ 2497 if message.get("tract") != "think" or message.get("event") != "daily_complete": 2498 return 2499 2500 # Check if heartbeat is already running via PID file 2501 pid_file = Path(get_journal()) / "health" / "heartbeat.pid" 2502 if pid_file.exists(): 2503 try: 2504 existing_pid = int(pid_file.read_text().strip()) 2505 os.kill(existing_pid, 0) 2506 logging.info("Heartbeat already running (pid=%d), skipping", existing_pid) 2507 return 2508 except ProcessLookupError: 2509 pass # Stale PID file, proceed 2510 except PermissionError: 2511 logging.info( 2512 "Heartbeat running under different user (pid file exists), skipping" 2513 ) 2514 return 2515 except ValueError: 2516 pass # Corrupt PID file, proceed 2517 2518 cmd = ["journal", "heartbeat"] 2519 if _task_queue: 2520 _task_queue.submit(cmd) 2521 logging.info("Queued heartbeat after daily think completion") 2522 else: 2523 logging.warning("No task queue available for heartbeat submission") 2524 2525 2526def _handle_callosum_message(message: dict) -> None: 2527 """Dispatch incoming Callosum messages to appropriate handlers.""" 2528 _handle_task_request(message) 2529 _handle_supervisor_request(message) 2530 _handle_supervisor_drain(message) 2531 _handle_supervisor_start_local(message) 2532 _handle_segment_observed(message) 2533 _handle_activity_recorded(message) 2534 _handle_think_daily_complete(message) 2535 _handle_segment_event_log(message) 2536 _handle_cortex_outcome(message) 2537 2538 2539def _run_sync_tick(now: float) -> bool: 2540 """Write this supervisor's heartbeat and stop on live foreign writers.""" 2541 global _last_sync_tick, _last_sync_snapshot, _sync_conflict_shutdown 2542 global shutdown_requested 2543 2544 if now - _last_sync_tick < DEFAULT_INTERVAL_SECONDS: 2545 return True 2546 2547 try: 2548 write_self_heartbeat() 2549 result = check_journal_sync(previous=_last_sync_snapshot) 2550 _last_sync_snapshot = result.snapshot 2551 _last_sync_tick = now 2552 if not result.is_conflict: 2553 return True 2554 2555 primary = result.primary_conflict 2556 if primary is None: 2557 return True 2558 2559 machine_prefix = primary.machine_id[:8] if primary.machine_id else "(unknown)" 2560 logging.error( 2561 "Another solstone instance is writing to this journal " 2562 "(host=%s pid=%s machine=%s) - shutting down.", 2563 primary.display_hostname, 2564 primary.pid, 2565 machine_prefix, 2566 ) 2567 if _supervisor_callosum: 2568 try: 2569 _supervisor_callosum.emit( 2570 "supervisor", 2571 "sync_conflict", 2572 hostname=primary.display_hostname, 2573 journal_path=primary.journal_path, 2574 pid=primary.pid, 2575 machine_id_prefix=primary.machine_id[:8] 2576 if primary.machine_id 2577 else "", 2578 wall_time=datetime.now(timezone.utc) 2579 .isoformat(timespec="seconds") 2580 .replace("+00:00", "Z"), 2581 ) 2582 except Exception: 2583 logging.exception("Failed to emit sync_conflict event") 2584 shutdown_requested = True 2585 _sync_conflict_shutdown = True 2586 return False 2587 except Exception: 2588 logging.exception("Sync conflict check failed (continuing)") 2589 return True 2590 2591 2592def _run_gate_tick(now: float) -> None: 2593 global _last_gate_tick 2594 2595 if now - _last_gate_tick < GATE_TICK_INTERVAL_S: 2596 return 2597 _last_gate_tick = now 2598 if _is_remote_mode: 2599 return 2600 settings = load_processing_settings() 2601 if settings.mode != "deferred": 2602 return 2603 reading = ( 2604 poll_display_powersave(time.monotonic()) 2605 if settings.gate.display_powersave.enabled 2606 else DISPLAY_POWERSAVE_UNAVAILABLE 2607 ) 2608 gate = evaluate_drain_gate(settings, datetime.now(), reading) 2609 if not gate.open: 2610 return 2611 run_catchup_drain() 2612 2613 2614async def supervise( 2615 *, 2616 daily: bool = True, 2617 schedule: bool = True, 2618 procs: list[RunnerManagedProcess] | None = None, 2619) -> None: 2620 """Main supervision loop. Runs at 1-second intervals for responsiveness. 2621 2622 Monitors runner health, emits status, triggers daily processing, 2623 and checks scheduled agents. 2624 """ 2625 global _last_gate_tick, _last_sync_tick 2626 global _last_sync_snapshot, _sync_conflict_shutdown 2627 2628 last_status_emit = 0.0 2629 _last_gate_tick = 0.0 2630 reset_display_powersave_monitor() 2631 _last_sync_tick = 0.0 2632 _last_sync_snapshot = None 2633 _sync_conflict_shutdown = False 2634 2635 try: 2636 while ( 2637 not shutdown_requested 2638 ): # pragma: no cover - loop checked via unit tests by patching 2639 if _task_queue: 2640 _task_queue.enforce_deadlines(time.time()) 2641 2642 # Check for runner exits first (immediate alert) 2643 if procs: 2644 await handle_runner_exits(procs) 2645 await _check_local_server_recovery() 2646 2647 # Emit status every 5 seconds 2648 now = time.time() 2649 if now - last_status_emit >= 5: 2650 if _supervisor_callosum and procs: 2651 try: 2652 status = collect_status(procs) 2653 _supervisor_callosum.emit("supervisor", "status", **status) 2654 except Exception as e: 2655 logging.debug(f"Status emission failed: {e}") 2656 last_status_emit = now 2657 2658 # Check for segment flush (non-blocking, submits via task queue) 2659 _check_segment_flush() 2660 2661 # Check for journal sync conflicts (usually just heartbeat IO) 2662 if not _run_sync_tick(now): 2663 return 2664 2665 # Check for daily processing (non-blocking, submits via task queue) 2666 if daily: 2667 handle_daily_tasks() 2668 _run_gate_tick(now) 2669 2670 # Check periodic task schedules (non-blocking, submits via callosum) 2671 if schedule: 2672 scheduler.check() 2673 2674 # Sleep 1 second before next iteration (responsive to shutdown) 2675 await asyncio.sleep(1) 2676 finally: 2677 pass # Callosum cleanup happens in main() 2678 2679 2680def parse_args() -> argparse.ArgumentParser: 2681 parser = SupervisorArgumentParser(description="Monitor journaling health") 2682 parser.add_argument( 2683 "port", 2684 nargs="?", 2685 type=int, 2686 default=0, 2687 help="Convey port (0 = auto-select available port)", 2688 ) 2689 parser.add_argument( 2690 "--threshold", 2691 type=int, 2692 default=DEFAULT_THRESHOLD, 2693 help="Seconds before heartbeat considered stale", 2694 ) 2695 parser.add_argument( 2696 "--interval", type=int, default=CHECK_INTERVAL, help="Polling interval seconds" 2697 ) 2698 parser.add_argument( 2699 "--no-daily", 2700 action="store_true", 2701 help="Disable daily processing run at midnight", 2702 ) 2703 parser.add_argument( 2704 "--no-cortex", 2705 action="store_true", 2706 help="Do not start the Cortex server (run it manually for debugging)", 2707 ) 2708 parser.add_argument( 2709 "--no-spl", 2710 action="store_true", 2711 help="Do not start the spl tunnel service", 2712 ) 2713 parser.add_argument( 2714 "--no-convey", 2715 action="store_true", 2716 help="Do not start the Convey web application", 2717 ) 2718 parser.add_argument( 2719 "--no-schedule", 2720 action="store_true", 2721 help="Disable periodic task scheduler", 2722 ) 2723 parser.add_argument( 2724 FLAG, 2725 action="store_true", 2726 help=( 2727 "App-supervised mode: skip all service-unit work and self-exit when " 2728 "the parent process dies (used by the macOS app)." 2729 ), 2730 ) 2731 parser.add_argument( 2732 "--remote", 2733 type=str, 2734 help="Remote mode: URL for segment transfer (not yet implemented)", 2735 ) 2736 return parser 2737 2738 2739def handle_shutdown(signum, frame): 2740 """Handle shutdown signals gracefully.""" 2741 global shutdown_requested 2742 if not shutdown_requested: 2743 shutdown_requested = True 2744 logger.info("shutdown requested via signal %d", signum) 2745 live = [managed for managed in _managed_procs if managed.is_running()] 2746 if live: 2747 logger.info("shutdown: signaling %d managed child(ren)", len(live)) 2748 for managed in live: 2749 try: 2750 managed.process.terminate() 2751 except Exception: 2752 logger.exception("shutdown: terminate failed for %s", managed.name) 2753 2754 deadline = time.monotonic() + HANDLE_SHUTDOWN_REAP_S 2755 while time.monotonic() < deadline: 2756 if all(not managed.is_running() for managed in live): 2757 break 2758 time.sleep(0.05) 2759 2760 kills = 0 2761 for managed in live: 2762 if managed.is_running(): 2763 try: 2764 managed.process.kill() 2765 logger.warning( 2766 "shutdown: SIGKILL pid=%s name=%s", 2767 managed.process.pid, 2768 managed.name, 2769 ) 2770 kills += 1 2771 except Exception: 2772 logger.exception("shutdown: kill failed for %s", managed.name) 2773 2774 cleanly = len(live) - kills 2775 logger.info( 2776 "shutdown: reap complete (%d exited cleanly, %d SIGKILL'd)", 2777 cleanly, 2778 kills, 2779 ) 2780 raise KeyboardInterrupt 2781 # Second signal during shutdown: cleanup is already in progress. 2782 2783 2784def _ensure_venv_bin_on_path() -> None: 2785 """Prepend the venv bin dir (sibling of sys.executable) to PATH if absent. 2786 2787 Idempotent — safe to call repeatedly. Lets the supervisor spawn `sol` and 2788 other venv-installed entry points even when the operator's shell PATH does 2789 not include the venv bin dir. 2790 """ 2791 venv_bin = os.path.dirname(sys.executable) 2792 parts = os.environ.get("PATH", "").split(os.pathsep) 2793 if parts and parts[0] == venv_bin: 2794 return 2795 parts = [venv_bin] + [p for p in parts if p != venv_bin] 2796 os.environ["PATH"] = os.pathsep.join(parts) 2797 2798 2799def register_baseline_caps(queue: TaskQueue) -> None: 2800 """Register caps that must hold regardless of the schedule_enabled gate. 2801 2802 Reactive partitions (daily/segment/indexer/importer) and on-demand backup 2803 can reach _active even under --no-schedule, so their caps cannot live behind 2804 the schedule-only registration block. 2805 """ 2806 for name, seconds in REACTIVE_TASK_CAPS.items(): 2807 queue.set_cap(name, seconds) 2808 queue.set_cap( 2809 TaskQueue.get_command_name(BACKUP_RUN_CMD), 2810 parse_duration_seconds(BACKUP_MAX_RUNTIME), 2811 ) 2812 2813 2814def main() -> None: 2815 parser = parse_args() 2816 2817 # Capture journal info before setup_cli() hydrates os.environ from journal 2818 # config and strips shell-only managed provider keys. 2819 journal_info = get_journal_info() 2820 2821 args = setup_cli(parser) 2822 app_supervised = is_app_supervised(sys.argv) 2823 _ensure_venv_bin_on_path() 2824 2825 journal_path = _get_journal_path() 2826 2827 log_level = logging.DEBUG if args.debug else logging.INFO 2828 log_path = journal_path / "health" / "supervisor.log" 2829 log_path.parent.mkdir(parents=True, exist_ok=True) 2830 _configure_supervisor_logging(log_path, log_level) 2831 2832 if args.verbose or args.debug: 2833 console_handler = logging.StreamHandler() 2834 console_handler.setLevel(log_level) 2835 console_handler.setFormatter( 2836 logging.Formatter("%(asctime)s %(levelname)s %(message)s") 2837 ) 2838 logging.getLogger().addHandler(console_handler) 2839 2840 # Singleton guard: only one supervisor per journal 2841 health_dir = journal_path / "health" 2842 lock_path = health_dir / "supervisor.lock" 2843 pid_path = health_dir / "supervisor.pid" 2844 2845 lock_fd = open(lock_path, "w") 2846 try: 2847 fcntl.flock(lock_fd, fcntl.LOCK_EX | fcntl.LOCK_NB) 2848 except OSError: 2849 lock_fd.close() 2850 pid_str = "" 2851 try: 2852 pid_str = pid_path.read_text().strip() 2853 except OSError: 2854 pass 2855 pid_msg = f" (PID {pid_str})" if pid_str else "" 2856 if os.environ.get("INVOCATION_ID"): 2857 holder_pid = pid_str or "unknown" 2858 print( 2859 "Supervisor already running " 2860 f"(PID {holder_pid}) - exiting cleanly under systemd activation" 2861 ) 2862 sys.exit(0) 2863 sock_path = health_dir / "callosum.sock" 2864 if sock_path.exists(): 2865 try: 2866 from solstone.think.health_cli import health_check 2867 2868 print(f"Supervisor already running{pid_msg}\n") 2869 health_check() 2870 except Exception: 2871 print(f"Supervisor already running{pid_msg}") 2872 else: 2873 print(f"Supervisor already running{pid_msg}") 2874 sys.exit(1) 2875 2876 print( 2877 "Checking for other active solstone instances on this journal...", 2878 flush=True, 2879 ) 2880 snapshot = check_journal_sync(journal=journal_path) 2881 if snapshot.is_conflict: 2882 print(format_conflict_message(snapshot), file=sys.stderr) 2883 try: 2884 lock_fd.close() 2885 except Exception: 2886 pass 2887 sys.exit(1) 2888 write_self_heartbeat(journal=journal_path) 2889 2890 pid_path.write_text(str(os.getpid())) 2891 start_time_path = health_dir / "supervisor.start_time" 2892 # Stamp THIS process's kernel create_time() so the recorded value equals what 2893 # is_supervisor_up()/_valid_marker() later read via psutil for this pid — 2894 # eliminating (not minimizing) drift from a wall-clock time.time() stamp. 2895 start_time_path.write_text(str(psutil.Process().create_time())) 2896 logging.info("Singleton lock acquired (PID %d)", os.getpid()) 2897 _sweep_orphaned_sol_processes(journal_path) 2898 2899 # Set up signal handlers 2900 signal.signal(signal.SIGINT, handle_shutdown) 2901 signal.signal(signal.SIGTERM, handle_shutdown) 2902 2903 # Show journal path and source on startup 2904 path, source = journal_info 2905 print(f"Journal: {path} (from {source})") 2906 logging.info("Supervisor starting...") 2907 2908 global _managed_procs, _supervisor_callosum, _is_remote_mode 2909 global _task_queue 2910 procs: list[RunnerManagedProcess] = [] 2911 convey_port = None 2912 convey_proc = None 2913 2914 # Remote mode: run sync instead of local processing 2915 _is_remote_mode = bool(args.remote) 2916 2917 # Run pending journal-maintenance tasks before spawning any writer children. 2918 # Callosum isn't up yet (emit_fn=None); migrations log through supervisor's logger only. 2919 try: 2920 ran, succeeded = run_pending_tasks(journal_path, emit_fn=None) 2921 if ran > 0: 2922 print(f" Ran {ran} maintenance task(s)", flush=True) 2923 if ran == succeeded: 2924 logging.info("Completed %d/%d maintenance task(s)", succeeded, ran) 2925 else: 2926 logging.error( 2927 "Maintenance tasks completed with failures: %d/%d succeeded", 2928 succeeded, 2929 ran, 2930 ) 2931 except Exception: 2932 logging.exception("Maintenance runner raised; continuing startup") 2933 2934 try: 2935 from solstone.think.importers.journal_archive import sweep_stale_extract_dirs 2936 2937 swept = sweep_stale_extract_dirs() 2938 if swept > 0: 2939 logging.info("Swept %d stale journal-archive extract dir(s)", swept) 2940 except Exception: 2941 logging.exception("Journal archive extract sweep raised; continuing startup") 2942 2943 # Start Callosum in-process first - it's the message bus that other services depend on 2944 try: 2945 print(" Starting Callosum bus...", flush=True) 2946 start_callosum_in_process() 2947 except RuntimeError as e: 2948 logging.error(f"Failed to start Callosum server: {e}") 2949 parser.error(f"Failed to start Callosum server: {e}") 2950 return 2951 2952 # Connect supervisor's Callosum client to capture startup events from other services 2953 try: 2954 _supervisor_callosum = CallosumConnection(defaults={"rev": get_rev()}) 2955 _supervisor_callosum.start(callback=_handle_callosum_message) 2956 logging.info("Supervisor connected to Callosum") 2957 except Exception as e: 2958 logging.warning(f"Failed to start Callosum connection: {e}") 2959 2960 # Mirror supervisor log output to callosum logs tract (best-effort) 2961 supervisor_ref = str(now_ms()) 2962 global _supervisor_ref, _supervisor_start 2963 _supervisor_ref = supervisor_ref 2964 _supervisor_start = time.time() 2965 if _supervisor_callosum: 2966 try: 2967 handler = CallosumLogHandler(_supervisor_callosum, supervisor_ref) 2968 handler.setFormatter( 2969 logging.Formatter("%(asctime)s %(levelname)s %(message)s") 2970 ) 2971 logging.getLogger().addHandler(handler) 2972 except Exception: 2973 pass 2974 2975 # Initialize task queue with callosum event callback 2976 _task_queue = TaskQueue(on_queue_change=_emit_queue_event, ready=False) 2977 register_baseline_caps(_task_queue) 2978 2979 # Now start other services (their startup events will be captured) 2980 if _is_remote_mode: 2981 # Remote mode: transfer send will be added here 2982 pass 2983 else: 2984 # Local mode: convey first, then sense for file processing 2985 os.environ["SOL_SUPERVISOR_SPAWNED"] = "1" 2986 if not args.no_convey: 2987 print(f" Starting convey on port {args.port}...", flush=True) 2988 convey_proc, convey_port = start_convey_server( 2989 verbose=args.verbose, debug=args.debug, port=args.port 2990 ) 2991 procs.append(convey_proc) 2992 wait_for_convey_ready(convey_proc) 2993 print(" Convey ready", flush=True) 2994 from solstone.think.providers.local_endpoint import resolve_local_endpoint 2995 2996 if is_local_provider_needed() and resolve_local_endpoint().is_bundled: 2997 proc = start_local_server() 2998 if proc is not None: 2999 procs.append(proc) 3000 # Sense handles file processing 3001 print(" Starting sense...", flush=True) 3002 procs.append(start_sense()) 3003 # Cortex for agent execution 3004 if not args.no_cortex: 3005 print(" Starting cortex...", flush=True) 3006 procs.append(start_cortex_server()) 3007 # spl tunnel service (opt-out via --no-spl) 3008 if not args.no_spl: 3009 print(" Starting spl...", flush=True) 3010 procs.append(start_spl_service()) 3011 3012 # Make procs accessible to restart handler 3013 _managed_procs = procs 3014 3015 # Initialize daily state to today - think only triggers at midnight when day changes 3016 _daily_state["last_day"] = datetime.now().date() 3017 3018 # Initialize periodic task scheduler 3019 schedule_enabled = not args.no_schedule and not _is_remote_mode 3020 if schedule_enabled and _supervisor_callosum: 3021 try: 3022 maintenance.register_maintenance_schedules() 3023 except Exception: 3024 logging.error("Failed to register maintenance schedules", exc_info=True) 3025 scheduler.init(_supervisor_callosum) 3026 scheduler.register_defaults() 3027 if _task_queue: 3028 for cmd, seconds in scheduler.collect_runtime_caps(): 3029 cmd_name = TaskQueue.get_command_name(cmd) 3030 _task_queue.set_cap(cmd_name, seconds) 3031 logging.info( 3032 "Registered max_runtime cap for %s: %ss", 3033 cmd_name, 3034 seconds, 3035 ) 3036 3037 if _task_queue: 3038 _task_queue.set_ready() 3039 3040 # Show Convey URL if running 3041 if convey_port: 3042 print(f"Convey: http://localhost:{convey_port}/") 3043 3044 logging.info(f"Started {len(procs)} processes, entering supervision loop") 3045 daily_enabled = not args.no_daily and not _is_remote_mode 3046 if daily_enabled: 3047 logging.info("Daily processing scheduled for midnight") 3048 3049 # Startup catchup: submit thinks for days with pending stream data 3050 if daily_enabled: 3051 _startup_catchup_drain() 3052 3053 # Startup catch-up: submit overdue schedule entries missed while down 3054 if schedule_enabled and _supervisor_callosum: 3055 scheduler.catch_up() 3056 3057 try: 3058 convey_accepting = convey_proc is None or is_solstone_up(timeout=1.0) 3059 if convey_accepting: 3060 print(" Supervisor ready", flush=True) 3061 _sd_notify("READY=1") 3062 signal_ready() 3063 else: 3064 logging.error( 3065 "Convey is not accepting on :%s; withholding readiness marker, " 3066 "continuing into supervise loop", 3067 read_service_port("convey"), 3068 ) 3069 if app_supervised: 3070 start_parent_death_watcher() 3071 asyncio.run( 3072 supervise( 3073 daily=daily_enabled, 3074 schedule=schedule_enabled, 3075 procs=procs if procs else None, 3076 ) 3077 ) 3078 except KeyboardInterrupt: 3079 logging.info("Caught KeyboardInterrupt, shutting down...") 3080 finally: 3081 try: 3082 clear_ready() 3083 except Exception as exc: 3084 logging.warning("Failed to clear readiness marker during shutdown: %s", exc) 3085 try: 3086 if not _sync_conflict_shutdown: 3087 clear_self_heartbeat() 3088 except Exception as exc: 3089 logging.warning("Failed to clear sync heartbeat during shutdown: %s", exc) 3090 3091 logging.info("Stopping all processes...") 3092 print("\nShutting down gracefully (this may take a moment)...", flush=True) 3093 3094 if _task_queue: 3095 task_drain_timeout = APP_SUPERVISED_TASK_DRAIN_S if app_supervised else 10 3096 _task_queue.shutdown(timeout=task_drain_timeout) 3097 3098 # Stop services in reverse order 3099 child_stop_timeout = APP_SUPERVISED_CHILD_STOP_S if app_supervised else None 3100 for managed in reversed(procs): 3101 _stop_process(managed, timeout_cap=child_stop_timeout) 3102 3103 # Disconnect supervisor's Callosum connection 3104 if _supervisor_callosum: 3105 _supervisor_callosum.stop() 3106 logging.info("Supervisor disconnected from Callosum") 3107 3108 # Stop in-process Callosum server last 3109 callosum_join_timeout = ( 3110 APP_SUPERVISED_CALLOSUM_JOIN_S if app_supervised else 5.0 3111 ) 3112 stop_callosum_in_process(join_timeout=callosum_join_timeout) 3113 3114 logging.info("Supervisor shutdown complete.") 3115 print("Shutdown complete.", flush=True) 3116 3117 if _sync_conflict_shutdown: 3118 sys.exit(2) 3119 3120 3121if __name__ == "__main__": 3122 main()