diff --git a/.facts b/.facts index 1db3f7d3..2a7658fb 100644 --- a/.facts +++ b/.facts @@ -47,9 +47,9 @@ - a Satelle Doctor Finding is a diagnostic result with a scope, severity, fixability, readiness impact, summary, evidence, and optional recovery command @mvp @implemented - a Satelle Doctor Probe is an individual diagnostic check with a stable probe id, scope, dependencies, resource locks, timeout, and cache policy @mvp @implemented - a Satelle Doctor Event is a diagnostic-stream record with its own versioned schema and is distinct from a lifecycle Satelle Event @mvp @implemented -- a Satelle Log Entry is a normalized redacted Host Daemon-owned diagnostic record with timestamp, source, severity, Host, optional Session id, message, structured fields, and redaction metadata @spec @mvp +- a Satelle Log Entry is a normalized redacted Host Daemon-owned diagnostic record with timestamp, source, severity, Host, optional Session id, message, structured fields, and redaction metadata @spec @mvp @implemented - a Satelle Log Cursor is an opaque durable position used to resume normalized log delivery without acting as a Satelle Event replay cursor @mvp @implemented -- a Satelle Operator Log File is a rotating plain-text mirror of redacted Satelle Log Entries for local inspection on the remote Host, not an authoritative store @spec @mvp +- a Satelle Operator Log File is a rotating plain-text mirror of redacted Satelle Log Entries for local inspection on the remote Host, not an authoritative store @spec @mvp @implemented - a Satelle Diagnostic Bundle is a redacted local archive for support and debugging that can include selected Host Daemon metadata, Doctor Findings, setup ledger summaries, recent Satelle Log Entries, and export metadata @spec @later - a Satelle Raw Diagnostic Export is a user-requested local diagnostic artifact that may include data excluded from normal Satelle diagnostics while preserving explicit consent, redaction, retention, and audit boundaries @spec @later - a Satelle Desktop Snapshot Export is a user-requested local artifact that captures the current visible desktop for one selected Host Identity and Desktop Binding at invocation time and never represents historical Session imagery @spec @later @@ -843,9 +843,9 @@ - GET /v1/logs returns schema_version satelle.logs.page.v1 in one flat envelope containing request_id, host_identity, entries, next_cursor, and truncated @spec @contract @mvp @implemented - a satelle.logs.page.v1 next_cursor is the last delivered Log Cursor when a forward page is truncated and otherwise advances to the Host-captured log high-water cursor even when no entry matches the filters @spec @contract @mvp @implemented - a satelle.logs.page.v1 truncated value is true when tail mode omitted older matching entries or forward mode has newer matching entries beyond the returned page @spec @contract @mvp @implemented -- satelle.logs.entry.v1 contains exactly schema_version, cursor, timestamp, source, severity, event, subject, message, and redacted; redacted is always true @spec @contract @mvp @implemented +- satelle.logs.entry.v1 contains exactly schema_version, cursor, timestamp, host_identity, source, severity, event, subject, message, and redacted; redacted is always true @spec @contract @mvp @implemented - satelle.logs.entry.v1 subject is either a host subject containing only kind host or a turn subject containing kind turn plus session_id, turn_id, session_state_revision, and turn_state_revision @spec @contract @mvp @implemented -- satelle.logs.entry.v1 source tokens are host_daemon, storage, and codex_adapter; severity tokens are info, warn, and error; current event tokens are session_started, follow_up_started, turn_state_committed, stop_confirmed, stop_not_confirmed, restart_recovery_pending, and store_opened @spec @contract @mvp @implemented +- satelle.logs.entry.v1 source tokens are host_daemon, storage, and codex_adapter; severity tokens are info, warn, and error; current event tokens are session_started, follow_up_started, native_readiness_summary, provider_smoke_summary, turn_state_committed, structured_execution_error, stop_confirmed, stop_not_confirmed, restart_recovery_pending, and store_opened @spec @contract @mvp @implemented - logs-cursor-expired uses HTTP 410 and schema_version satelle.error.v1; details.earliest_available_cursor contains the first retained entry cursor or null, while details.resume_cursor contains the exclusive cursor boundary that returns that first retained entry without skipping it @spec @contract @mvp @implemented - POST /v1/sessions, POST /v1/sessions/{session_id}/turns, and GET /v1/sessions/{session_id} return the exact response schema token satelle.session.v1 and one flat envelope containing request_id, host_identity, and the canonical PublicSession fields @spec @contract @mvp @implemented - POST /v1/sessions and POST /v1/sessions/{session_id}/turns return HTTP 202 only after durable asynchronous Turn admission, while GET /v1/sessions/{session_id} returns HTTP 200 @spec @contract @mvp @implemented @@ -1591,13 +1591,13 @@ - satelle logs targets the resolved current or default host when no host or session selector is provided @implemented @mvp - satelle logs supports --host to read host-scoped logs for a configured remote host @spec @mvp @implemented - satelle logs supports --session to read logs scoped to one Satelle session @implemented @mvp -- satelle logs reports a typed logs-target-required error when no host, default host, current host, or session selector can be resolved @spec @mvp +- satelle logs reports a typed logs-target-required error when no host, default host, current host, or session selector can be resolved @spec @mvp @implemented - satelle logs for SSH bootstrap hosts may restart the on-demand Host Daemon before reading stored normalized logs @spec @mvp @implemented - satelle logs supports --tail to limit output to the most recent n matching log entries @implemented @mvp - satelle logs defaults to --tail 200 when neither --tail nor --since is provided @implemented @mvp - satelle logs accepts --tail values from 1 through 10000 and reports a typed log-tail-limit-exceeded usage error for larger values @implemented @mvp - satelle logs supports --since to show only matching log entries at or after the requested time @implemented @mvp -- satelle logs supports -f and --follow to continue streaming new matching log entries after the initial result set @spec @mvp +- satelle logs supports -f and --follow to continue streaming new matching log entries after the initial result set @spec @mvp @implemented - satelle logs supports repeatable --source filters @spec @mvp @implemented - satelle logs without --source includes all MVP log sources that pass the default redaction policy @implemented @mvp - satelle logs supports --level as a minimum severity filter @spec @mvp @implemented @@ -1606,26 +1606,26 @@ - satelle logs uses stdout as the data output contract instead of adding file destination flags in MVP @implemented @mvp - satelle logs human output writes log entries to stdout and diagnostics or command errors to stderr @implemented @mvp - satelle logs --json emits the initial matching set as one LF-terminated satelle.logs.entry.v1 JSON record per entry without a top-level wrapper @spec @contract @mvp @implemented -- satelle logs --json without --follow exits 0 with empty stdout when no entries match, while satelle logs --json --follow remains attached waiting for later matching entries until interrupted or failed @spec @contract @mvp +- satelle logs --json without --follow exits 0 with empty stdout when no entries match, while satelle logs --json --follow remains attached waiting for later matching entries until interrupted or failed @spec @contract @mvp @implemented - satelle logs JSON records use the exact satelle.logs.entry.v1 fields defined by the Host Daemon contract and add no CLI-only wrapper, target, or structured-fields properties @spec @contract @mvp @implemented - satelle logs supports --after to return entries strictly after one previously delivered Log Cursor @spec @mvp @implemented - satelle logs reports a typed log-position-conflict usage error when --after is combined with --since or an explicit --tail @spec @mvp @implemented -- satelle logs --json --follow continues the same newline-delimited satelle.logs.entry.v1 record stream after the initial matching set @spec @contract @mvp -- satelle logs --follow exits 130 when interrupted by Ctrl-C and does not treat the interrupt as a remote host failure @spec @mvp -- satelle logs --follow automatically attempts to reconnect when the log stream ends because of transient transport loss or Host Daemon restart @spec @mvp -- satelle logs --follow resumes after reconnect by querying stored Satelle Log Entries newer than the last delivered log cursor instead of replaying missed live Satelle Events @spec @mvp -- satelle logs --follow validates target host identity and session scope before resuming after reconnect @spec @mvp -- satelle logs --follow stops reconnecting and reports a typed logs-follow-identity-changed error when the reconnected host identity or requested session scope does not match the original target @spec @mvp -- satelle logs --follow uses a default reconnect budget of 60 seconds per stream interruption @spec @mvp -- satelle logs --follow stops after 10 stream interruptions in one command and reports a typed logs-follow-reconnect-exhausted error @spec @mvp -- satelle logs --follow reconnect backoff starts at 250 milliseconds and caps at 5 seconds with jitter @spec @mvp -- satelle logs --follow does not retry forever after the reconnect budget or interruption cap is exhausted @spec @mvp -- satelle logs --follow reports a typed logs-follow-reconnect-exhausted error with the last delivered log cursor and a rerun command when reconnection fails within the budget @spec @mvp -- satelle logs --follow writes reconnect notices and reconnect failures to stderr while preserving stdout for log entries or JSON log-entry objects @spec @mvp -- satelle logs --json --follow does not emit reconnect control records to stdout in MVP @spec @mvp -- satelle logs --follow supports --no-reconnect to fail immediately on stream loss after reporting the last delivered log cursor @spec @mvp -- satelle logs show Satelle daemon events and normalized Codex event summaries by default @spec @mvp -- satelle MVP logs command exposes normalized daemon events, session lifecycle changes, readiness summaries, provider smoke-test summaries, and structured errors instead of raw protocol payloads @spec @mvp +- satelle logs --json --follow continues the same newline-delimited satelle.logs.entry.v1 record stream after the initial matching set @spec @contract @mvp @implemented +- satelle logs --follow exits 130 when interrupted by Ctrl-C and does not treat the interrupt as a remote host failure @spec @mvp @implemented +- satelle logs --follow automatically attempts to reconnect when the log stream ends because of transient transport loss or Host Daemon restart @spec @mvp @implemented +- satelle logs --follow resumes after reconnect by querying stored Satelle Log Entries newer than the last delivered log cursor instead of replaying missed live Satelle Events @spec @mvp @implemented +- satelle logs --follow validates target host identity and session scope before resuming after reconnect @spec @mvp @implemented +- satelle logs --follow stops reconnecting and reports a typed logs-follow-identity-changed error when the reconnected host identity or requested session scope does not match the original target @spec @mvp @implemented +- satelle logs --follow uses a default reconnect budget of 60 seconds per stream interruption @spec @mvp @implemented +- satelle logs --follow stops after 10 stream interruptions in one command and reports a typed logs-follow-reconnect-exhausted error @spec @mvp @implemented +- satelle logs --follow reconnect backoff starts at 250 milliseconds and caps at 5 seconds with jitter @spec @mvp @implemented +- satelle logs --follow does not retry forever after the reconnect budget or interruption cap is exhausted @spec @mvp @implemented +- satelle logs --follow reports a typed logs-follow-reconnect-exhausted error with the last delivered log cursor and a rerun command when reconnection fails within the budget @spec @mvp @implemented +- satelle logs --follow writes reconnect notices and reconnect failures to stderr while preserving stdout for log entries or JSON log-entry objects @spec @mvp @implemented +- satelle logs --json --follow does not emit reconnect control records to stdout in MVP @spec @mvp @implemented +- satelle logs --follow supports --no-reconnect to fail immediately on stream loss after reporting the last delivered log cursor @spec @mvp @implemented +- satelle logs show Satelle daemon events and normalized Codex event summaries by default @spec @mvp @implemented +- satelle MVP logs command exposes normalized daemon events, session lifecycle changes, readiness summaries, provider smoke-test summaries, and structured errors instead of raw protocol payloads @spec @mvp @implemented - satelle logs do not expose raw Codex app-server protocol messages by default @implemented @mvp - satelle MVP logs command does not expose raw Codex app-server protocol messages, provider request or response bodies, full prompts, screenshots, desktop recordings, or full transcripts by default @implemented @mvp - satelle later raw protocol diagnostics are implemented only as a command-specific Raw Diagnostic Export that explicitly selects raw Codex app-server protocol messages or provider request and response bodies for one Session or command scope @spec @later @@ -1634,7 +1634,7 @@ - satelle raw protocol diagnostic exports do not make raw Codex app-server protocol messages, provider request bodies, provider response bodies, full prompts, screenshots, desktop recordings, or full transcripts available through satelle logs, status, doctor, diagnostic bundles, Satelle Events, Satelle Operator Log Files, or setup action ledger summaries @spec @later - satelle stores minimal lifecycle metadata and structured errors by default instead of persisting desktop screenshots or full event transcripts @mvp @implemented - satelle does not persist full Satelle Event streams by default @mvp @implemented -- satelle MVP does not provide session recording modes, screenshot recording, full event transcript recording, desktop recording, or host-level recording defaults @spec @mvp +- satelle MVP does not provide session recording modes, screenshot recording, full event transcript recording, desktop recording, or host-level recording defaults @spec @mvp @implemented - satelle MVP normal status, logs, run, and steer commands do not capture, display, persist, or export desktop snapshot imagery by default @implemented @mvp - satelle later exposes satelle desktop snapshot --host --output as the only Desktop Snapshot Export command @spec @later - satelle desktop snapshot JSON v1 uses schema_version satelle.desktop.snapshot.v1 and includes source Host, Host Identity, Desktop Binding, output path, artifact format, artifact byte size, redaction metadata, and created_at @spec @contract @later @@ -1720,10 +1720,10 @@ - satelle Host Daemon continues running when a Satelle Platform-Native Log Sink fails while SQLite remains writable, and records the degraded platform-native log sink as a typed diagnostic finding @spec @later - satelle Satelle Platform-Native Log Sink retention and query behavior are treated as operating-system-managed mirror behavior and do not change SQLite Satelle Log Entry retention, Satelle Operator Log File retention, or satelle logs output semantics @spec @later - satelle SQLite Satelle Log Entries are retained for 7 days by default @spec @mvp @implemented -- satelle SQLite Satelle Log Entry retention can be configured per host or profile @spec @mvp +- satelle SQLite Satelle Log Entry retention can be configured per host or profile @spec @mvp @implemented - each persisted Satelle Log Entry receives a monotonic Log Cursor in its Host Daemon store @spec @mvp @implemented - logs pagination resumes strictly after the last delivered Log Cursor @spec @mvp @implemented -- logs follow reconnection uses a Log Cursor instead of timestamp alone @spec @mvp +- logs follow reconnection uses a Log Cursor instead of timestamp alone @spec @mvp @implemented - a Log Cursor older than retained log history reports a typed logs-cursor-expired error and identifies the earliest available cursor @spec @mvp @implemented - label: satelle stores the Satelle Setup Action Ledger in the remote Host Daemon SQLite store instead of storing it only on the local CLI machine command: cargo test --locked -p satelle-host --lib storage::tests::setup_ledger::setup_action_ledger_migrates_and_persists_ordered_state_transitions -- --exact diff --git a/.spec-gaps.md b/.spec-gaps.md index b6086957..7db0778f 100644 --- a/.spec-gaps.md +++ b/.spec-gaps.md @@ -127,6 +127,27 @@ Resolution: User configuration and named profiles use `log_verbosity = "off" | " - Packet/facts: source packet 22, `ju3` / L1798 - Decision: Canonical SQLite, sidecars, attachments, recovery data, Operator Logs, and recordings remain on the Host. Ordinary run, status, log, and setup operations never copy Host storage to a Controller or service. Only an explicit Operator export command may copy a redacted artifact, diagnostic, or recording to its operator-selected destination. Document this boundary and prove ordinary read paths have no export or write side effect. The task-artifact exception is exactly GAP-046. +### GAP-050: Log follow transport and reconnect contract + +- Status: resolved +- Packet/facts: source packet 23, `6b0`, `vrh`, `2mv`, `3w2`, `95q`, `nr7`, `r6y`, `vm3`, `lgn`, `4m1`, `gpk`, `c4sw`, `pcj`, `5ff`, `1wg`, `dww`, and `1db` +- Decision: Keep authenticated `GET /v1/logs` as the only normalized Log read route. Follow mode emits the requested initial finite result, stores the returned high-water Log Cursor, then polls forward from the last delivered cursor. A successful empty forward page means the command remains attached and waits 250 milliseconds; it is not a stream interruption. Each later page continues the same human line stream or newline-delimited `satelle.logs.entry.v1` JSON stream. Reconnect notices and errors use stderr only. Ctrl-C is terminal exit 130 and never consumes reconnect budget. +- Reconnect: Only Host reachability, daemon reachability, SSH bootstrap availability, and connection-level remote execution failures are transient. Recreate the transport for each attempt, query forward from the last delivered Log Cursor, and never use a timestamp or Satelle Event replay. Authentication, authorization, TLS trust, cursor, configuration, storage, and public-contract failures are terminal. One interruption owns a 60-second monotonic budget and an exponential delay starting at 250 milliseconds and capped at 5 seconds. Apply bounded 20 percent symmetric jitter to each delay without exceeding the 5-second cap. The tenth interruption or an expired per-interruption budget returns `logs-follow-reconnect-exhausted` with the last delivered cursor and an exact rerun command. `--no-reconnect` reports the cursor on stderr and returns the original terminal transport error without a retry. +- Identity and scope: The selected Host binding's expected Host Identity is the immutable follow identity. Each successful HTTP response is already identity-pinned by the transport. Before the initial read and after transport recreation, a requested Session selector must also resolve through an authenticated Session read on that same Host. A changed Host Identity or a Session that is absent from the reconnected Host returns `logs-follow-identity-changed` before any resumed entry is emitted. + +### GAP-051: SQLite Log Entry retention policy + +- Status: resolved +- Packet/facts: source packet 23, `z0p` +- Decision: Add Operator-owned `sqlite_log_retention = "7d"` to Host and Profile configuration. Reuse packet 22's `RetentionDuration` grammar and 7-day through 365-day bounds. The default is 7 days. A user-selected user-owned Profile overrides the user Host value; project configuration cannot set destructive retention. Resolve one duration at runtime and inject it into SQLite Log pruning. Keep it independent from `session_metadata_retention` and `operator_log_retained_files`. Persist it in service launch configuration, hard-cut the Windows service schema to the next version, and do not migrate older service configurations. + +### GAP-052: Normalized Log Entry and diagnostic vocabulary + +- Status: resolved +- Packet/facts: source packet 23, `727`, `j3h`, `ool`, and `05u` +- Decision: Keep `satelle.logs.entry.v1` as one closed normalized record. Every entry contains its durable cursor, timestamp, source, severity, exact Host Identity, typed event, structured subject, fixed event-derived message, and redaction marker. The structured subject carries the optional Session and Turn identities plus lifecycle revisions; no arbitrary payload map is added. SQLite remains authoritative and the rotating plain-text Operator Log File mirrors only committed entries. +- Vocabulary: Add typed events for native readiness summary, provider smoke-test summary, and structured execution failure. Readiness and provider summary entries correlate by Turn subject with the private durable result references already accepted and stored at admission; they do not duplicate those references or include probe payloads, credentials, prompts, screenshots, or provider bodies. Turn lifecycle commits use `codex_adapter` for normalized Codex state summaries; daemon-owned admission, stop, restart, and store events remain `host_daemon` or `storage`. Structured failures use the existing redacted terminal summary and revisions, not raw protocol errors. No full Satelle Event stream or recording surface is introduced. + ### GAP-021 - Installer-managed standalone Codex contract (RESOLVED) Resolution: PR 06 owns fail-closed runtime admission of an existing managed Codex installation; the later setup-install and Codex-update packets own acquisition, update, and receipt creation. The acquisition contract uses the official OpenAI standalone Codex `0.144.0` full package from release tag `rust-v0.144.0`, mapping native Host targets to `aarch64-apple-darwin`, `x86_64-apple-darwin`, `aarch64-pc-windows-msvc`, or `x86_64-pc-windows-msvc`. The selected `codex-package-.tar.gz` must match `codex-package_SHA256SUMS` before the official versioned installer runs. The accepted package root is an immutable installer-owned directory under `/packages/standalone/releases`; mutable `current` links or junctions and visible-bin shims are never execution identities. Satelle atomically writes its owner-only `codex-install-receipt.json` under the resolved Satelle state root only after post-install verification. The receipt records schema version, manager, Codex version, target, release tag, exact artifact URL and SHA-256, Codex home, immutable package root, immutable binary path and SHA-256, and installation time. Installation and receipt creation are separate ordered ledger actions, not one atomic transaction. If receipt creation or post-verification fails, the installed package remains untrusted; setup or repair may adopt it only after repeating complete package, metadata, target, binary-digest, and version verification. Readiness fails closed when the receipt is absent or drifts from package metadata, binary bytes, `codex --version`, or the app-server capability handshake. The Host launches only the immutable receipt-recorded binary and sets the receipt-recorded `CODEX_HOME` only on Codex child processes; it ignores npm packages, mutable aliases, shims, and `PATH`. diff --git a/crates/satelle-cli/src/error-output.rs b/crates/satelle-cli/src/error-output.rs index 2f370130..01a46f98 100644 --- a/crates/satelle-cli/src/error-output.rs +++ b/crates/satelle-cli/src/error-output.rs @@ -344,7 +344,8 @@ fn error_contract(code: ErrorCode) -> ErrorContract { }, ErrorCode::HostUnreachable | ErrorCode::HostDaemonUnreachable - | ErrorCode::DirectDaemonUnreachable => ErrorContract { + | ErrorCode::DirectDaemonUnreachable + | ErrorCode::LogsFollowReconnectExhausted => ErrorContract { category: ErrorCategory::RemoteExecution, retryable: true, outcome: "The Host could not be reached.", @@ -414,6 +415,7 @@ fn error_contract(code: ErrorCode) -> ErrorContract { | ErrorCode::OutputModeConflict | ErrorCode::LogTailLimitExceeded | ErrorCode::LogPositionConflict + | ErrorCode::LogsTargetRequired | ErrorCode::ConcurrencyLimitExceeded | ErrorCode::ConcurrencyWithoutRemoteUpdate | ErrorCode::ComponentSelectionConflict @@ -462,7 +464,8 @@ fn error_contract(code: ErrorCode) -> ErrorContract { | ErrorCode::CertificateExpired | ErrorCode::TlsVersionUnsupported | ErrorCode::TlsHandshakeFailed - | ErrorCode::HostIdentityMismatch => ErrorContract { + | ErrorCode::HostIdentityMismatch + | ErrorCode::LogsFollowIdentityChanged => ErrorContract { category: ErrorCategory::RemoteExecution, retryable: false, outcome: "The Host identity or secure connection was not accepted.", diff --git a/crates/satelle-cli/src/logs.rs b/crates/satelle-cli/src/logs.rs index 9d6e356c..a9ac647e 100644 --- a/crates/satelle-cli/src/logs.rs +++ b/crates/satelle-cli/src/logs.rs @@ -1,16 +1,27 @@ use super::output::{OutputArgs, OutputFormat}; use super::transport::{TransportClient, transport_for}; -use super::{CliFailure, ConfigContext, failure, parse_duration_ms}; +use super::{CliFailure, ConfigContext, failure, parse_duration_ms, shell_argument}; use clap::Args; -use satelle_core::{SatelleError, SessionId}; +use satelle_core::{ErrorCode, SatelleError, SessionId}; use satelle_host::{DaemonLogEntry, LogCursor, LogPageQuery, LogSeverity, LogSource}; use std::io::{self, Write}; use std::str::FromStr; +use std::sync::Arc; +use std::sync::atomic::{AtomicBool, AtomicU64, Ordering}; +use std::sync::mpsc; +use std::thread; +use std::time::{Duration as StdDuration, Instant, SystemTime}; use time::format_description::well_known::Rfc3339; use time::{Duration, OffsetDateTime}; const DEFAULT_LOG_PAGE_LIMIT: usize = 200; const MAX_LOG_PAGE_LIMIT: usize = 10_000; +const INTERRUPT_POLL_INTERVAL: StdDuration = StdDuration::from_millis(50); +const FOLLOW_IDLE_INTERVAL: StdDuration = StdDuration::from_millis(250); +const RECONNECT_BUDGET: StdDuration = StdDuration::from_secs(60); +const RECONNECT_INITIAL_DELAY: StdDuration = StdDuration::from_millis(250); +const RECONNECT_MAX_DELAY: StdDuration = StdDuration::from_secs(5); +const MAX_STREAM_INTERRUPTS: usize = 10; #[derive(Args, Debug)] pub(crate) struct LogsCommand { @@ -56,6 +67,18 @@ pub(crate) struct LogsCommand { help = "Set minimum severity: info, warn, or error (default: info)" )] level: Option, + #[arg( + short = 'f', + long, + help = "Continue streaming new matching Log Entries" + )] + follow: bool, + #[arg( + long, + requires = "follow", + help = "Fail on transport loss instead of reconnecting" + )] + no_reconnect: bool, #[command(flatten)] pub(crate) output_args: OutputArgs, } @@ -78,10 +101,13 @@ pub(crate) struct LogReadRequest { pub(crate) after: Option, pub(crate) source: Vec, pub(crate) level: Option, + pub(crate) follow: bool, + pub(crate) no_reconnect: bool, + pub(crate) format: OutputFormat, } -impl From for LogReadRequest { - fn from(command: LogsCommand) -> Self { +impl LogReadRequest { + fn from_command(command: LogsCommand, format: OutputFormat) -> Self { Self { host: command.host, session: command.session, @@ -90,8 +116,37 @@ impl From for LogReadRequest { after: command.after, source: command.source, level: command.level, + follow: command.follow, + no_reconnect: command.no_reconnect, + format, } } + + fn follow_rerun_command(&self, host: &str, cursor: LogCursor) -> String { + let mut command = format!("satelle logs --host {}", shell_argument(host)); + if let Some(session) = &self.session { + command.push_str(" --session "); + command.push_str(session); + } + for source in &self.source { + command.push_str(" --source "); + command.push_str(source); + } + if let Some(level) = &self.level { + command.push_str(" --level "); + command.push_str(level); + } + command.push_str(" --after "); + command.push_str(&cursor.to_string()); + command.push_str(" --follow"); + if self.format.is_json() { + command.push_str(" --json"); + } + if self.no_reconnect { + command.push_str(" --no-reconnect"); + } + command + } } #[derive(Clone, Copy)] @@ -109,6 +164,539 @@ struct LogReadPlan { position: LogPosition, } +trait FollowConnection: Send { + fn host_identity(&self) -> Result; + fn session( + &self, + session_id: &SessionId, + ) -> Result; + fn logs(&self, query: &LogPageQuery) -> Result; +} + +type FollowConnectionFactory = + Arc Result, SatelleError> + Send + Sync>; +type FollowReconnectResult = + Result<(Box, satelle_host::DaemonLogPage), SatelleError>; +type FollowInitialResult = (Box, LogCursor, Option); + +struct TransportFollowConnection { + transport: Box, +} + +impl FollowConnection for TransportFollowConnection { + fn host_identity(&self) -> Result { + self.transport.log_target_identity() + } + + fn session( + &self, + session_id: &SessionId, + ) -> Result { + self.transport.status(session_id) + } + + fn logs(&self, query: &LogPageQuery) -> Result { + self.transport.logs(query) + } +} + +trait FollowRuntime { + fn now(&self) -> Instant; + fn interrupted(&self) -> bool; + fn sleep(&self, duration: StdDuration); + fn jitter(&self, duration: StdDuration) -> StdDuration; + fn reconnect_budget(&self) -> StdDuration { + RECONNECT_BUDGET + } +} + +struct ProcessFollowRuntime { + interrupted: Arc, + jitter_sequence: AtomicU64, +} + +impl ProcessFollowRuntime { + fn new() -> Result { + let interrupted = Arc::new(AtomicBool::new(false)); + let signal_interrupted = Arc::clone(&interrupted); + let runtime = tokio::runtime::Builder::new_current_thread() + .enable_all() + .build() + .map_err(|error| { + SatelleError::config_error( + "could not initialize Ctrl-C handling", + Some(error.to_string()), + ) + })?; + thread::Builder::new() + .name("satelle-logs-follow-interrupt".to_string()) + .spawn(move || { + if runtime.block_on(tokio::signal::ctrl_c()).is_ok() { + signal_interrupted.store(true, Ordering::Release); + } + }) + .map_err(|error| { + SatelleError::config_error( + "could not start Ctrl-C handling", + Some(error.to_string()), + ) + })?; + Ok(Self { + interrupted, + jitter_sequence: AtomicU64::new(0), + }) + } +} + +impl FollowRuntime for ProcessFollowRuntime { + fn now(&self) -> Instant { + Instant::now() + } + + fn interrupted(&self) -> bool { + self.interrupted.load(Ordering::Acquire) + } + + fn sleep(&self, duration: StdDuration) { + let deadline = Instant::now() + duration; + while !self.interrupted() { + let now = Instant::now(); + if now >= deadline { + return; + } + thread::sleep((deadline - now).min(INTERRUPT_POLL_INTERVAL)); + } + } + + fn jitter(&self, duration: StdDuration) -> StdDuration { + let sequence = self.jitter_sequence.fetch_add(1, Ordering::Relaxed); + let sample = SystemTime::now() + .duration_since(SystemTime::UNIX_EPOCH) + .map_or(sequence, |time| time.as_nanos() as u64 ^ sequence); + jittered_delay(duration, sample) + } +} + +struct FollowOutput<'a> { + stdout: &'a mut dyn Write, + stderr: &'a mut dyn Write, +} + +struct FollowTarget<'a> { + plan: &'a LogReadPlan, + request: &'a LogReadRequest, + host_alias: &'a str, + expected_host_identity: &'a str, +} + +fn visit_forward_snapshot_pages( + snapshot: LogCursor, + mut cursor: Option, + page_limit: usize, + mut fetch: impl FnMut(Option, usize) -> Result, + mut visit: impl FnMut(&[DaemonLogEntry], LogCursor) -> Result<(), SatelleError>, +) -> Result<(), SatelleError> { + loop { + let page = fetch(cursor, page_limit)?; + let reached_snapshot = !page.truncated() + || page + .entries() + .last() + .is_some_and(|entry| entry.cursor() >= snapshot); + visit(page.entries(), snapshot)?; + if reached_snapshot { + return Ok(()); + } + cursor = Some(page.next_cursor()); + } +} + +fn follow_logs( + plan: &LogReadPlan, + request: &LogReadRequest, + host_alias: &str, + format: OutputFormat, + runtime: &dyn FollowRuntime, + connection_factory: &FollowConnectionFactory, + output: FollowOutput<'_>, +) -> Result<(), SatelleError> { + let FollowOutput { stdout, stderr } = output; + let (connection, expected_host_identity) = open_follow_connection( + Arc::clone(connection_factory), + None, + plan.session_id().cloned(), + false, + runtime, + )?; + let (mut connection, mut query_cursor, mut last_delivered) = plan + .emit_follow_initial(connection, runtime, format, stdout) + .map_err(|error| { + map_follow_identity_error( + error, + &expected_host_identity, + plan.session_id().map(SessionId::as_str), + ) + })?; + let mut stream_interruptions = 0; + + loop { + if runtime.interrupted() { + return Err(SatelleError::interrupted_attached_command()); + } + let query = plan.follow_query(query_cursor); + match read_follow_page(connection, query, runtime) { + Ok((returned_connection, page)) => { + connection = returned_connection; + write_entries_to(page.entries(), None, format, stdout)?; + if let Some(entry) = page.entries().last() { + last_delivered = Some(entry.cursor()); + } + query_cursor = page.next_cursor(); + if !page.truncated() { + runtime.sleep(FOLLOW_IDLE_INTERVAL); + } + } + Err(error) if transient_follow_error(error.code) => { + stream_interruptions += 1; + let report_cursor = last_delivered.unwrap_or(query_cursor); + if request.no_reconnect { + writeln!( + stderr, + "log follow stopped after transport loss; last cursor={report_cursor}" + ) + .map_err(log_output_error)?; + return Err(error); + } + if stream_interruptions >= MAX_STREAM_INTERRUPTS { + return Err(follow_reconnect_exhausted( + request, + host_alias, + report_cursor, + stream_interruptions, + )); + } + writeln!( + stderr, + "log follow reconnecting after interruption {stream_interruptions}/{MAX_STREAM_INTERRUPTS}; last cursor={report_cursor}" + ) + .map_err(log_output_error)?; + let target = FollowTarget { + plan, + request, + host_alias, + expected_host_identity: &expected_host_identity, + }; + let (reconnected, page) = reconnect_follow( + &target, + runtime, + connection_factory, + query_cursor, + report_cursor, + stream_interruptions, + stderr, + )?; + connection = reconnected; + write_entries_to(page.entries(), None, format, stdout)?; + if let Some(entry) = page.entries().last() { + last_delivered = Some(entry.cursor()); + } + query_cursor = page.next_cursor(); + if !page.truncated() { + runtime.sleep(FOLLOW_IDLE_INTERVAL); + } + } + Err(error) if error.code == ErrorCode::HostIdentityMismatch => { + return Err(SatelleError::logs_follow_identity_changed( + &expected_host_identity, + None, + plan.session_id().map(SessionId::as_str), + )); + } + Err(error) => return Err(error), + } + } +} + +fn reconnect_follow( + target: &FollowTarget<'_>, + runtime: &dyn FollowRuntime, + connection_factory: &FollowConnectionFactory, + query_cursor: LogCursor, + report_cursor: LogCursor, + stream_interruptions: usize, + stderr: &mut dyn Write, +) -> Result<(Box, satelle_host::DaemonLogPage), SatelleError> { + let deadline = runtime.now() + runtime.reconnect_budget(); + let mut delay = RECONNECT_INITIAL_DELAY; + let exhausted = || { + follow_reconnect_exhausted( + target.request, + target.host_alias, + report_cursor, + stream_interruptions, + ) + }; + loop { + if runtime.interrupted() { + return Err(SatelleError::interrupted_attached_command()); + } + let now = runtime.now(); + if now >= deadline { + return Err(exhausted()); + } + runtime.sleep(runtime.jitter(delay).min(deadline - now)); + if runtime.interrupted() { + return Err(SatelleError::interrupted_attached_command()); + } + let attempt_started_at = runtime.now(); + if attempt_started_at >= deadline { + return Err(exhausted()); + } + + let Some(attempt) = run_reconnect_attempt( + Arc::clone(connection_factory), + target.expected_host_identity.to_string(), + target.plan.session_id().cloned(), + target.plan.follow_query(query_cursor), + deadline - attempt_started_at, + runtime, + ) else { + return Err(exhausted()); + }; + match attempt { + Ok(reconnected) => { + writeln!( + stderr, + "log follow reconnected; resuming after cursor={query_cursor}" + ) + .map_err(log_output_error)?; + return Ok(reconnected); + } + Err(error) if transient_follow_error(error.code) => { + delay = delay.saturating_mul(2).min(RECONNECT_MAX_DELAY); + } + Err(error) => return Err(error), + } + } +} + +fn run_reconnect_attempt( + connection_factory: FollowConnectionFactory, + expected_host_identity: String, + session_id: Option, + query: LogPageQuery, + timeout: StdDuration, + runtime: &dyn FollowRuntime, +) -> Option { + match run_follow_operation(runtime, Some(timeout), move || { + let attempt = (|| { + let connection = connection_factory()?; + validate_follow_connection( + connection.as_ref(), + Some(&expected_host_identity), + session_id.as_ref(), + true, + )?; + let page = connection.logs(&query)?; + Ok((connection, page)) + })(); + attempt.map_err(|error: SatelleError| { + map_follow_identity_error( + error, + &expected_host_identity, + session_id.as_ref().map(SessionId::as_str), + ) + }) + }) { + Ok(FollowOperation::Completed(reconnected)) => Some(Ok(reconnected)), + Ok(FollowOperation::TimedOut) => None, + Err(error) => Some(Err(error)), + } +} + +enum FollowOperation { + Completed(T), + TimedOut, +} + +fn run_follow_operation( + runtime: &dyn FollowRuntime, + timeout: Option, + operation: impl FnOnce() -> Result + Send + 'static, +) -> Result, SatelleError> { + let (completed, completion) = mpsc::sync_channel(1); + thread::Builder::new() + .name("satelle-log-follow-io".to_string()) + .spawn(move || { + let _completed = completed.send(operation()); + }) + .map_err(|error| { + follow_runtime_error( + "could not start interruptible log follow I/O", + Some(error.to_string()), + ) + })?; + let receive_deadline = timeout.map(|timeout| Instant::now() + timeout); + loop { + if runtime.interrupted() { + return Err(SatelleError::interrupted_attached_command()); + } + let wait = match receive_deadline { + Some(deadline) => { + let remaining = deadline.saturating_duration_since(Instant::now()); + if remaining.is_zero() { + return Ok(FollowOperation::TimedOut); + } + remaining.min(INTERRUPT_POLL_INTERVAL) + } + None => INTERRUPT_POLL_INTERVAL, + }; + match completion.recv_timeout(wait) { + Ok(result) => return result.map(FollowOperation::Completed), + Err(mpsc::RecvTimeoutError::Timeout) => {} + Err(mpsc::RecvTimeoutError::Disconnected) => { + return Err(follow_runtime_error( + "interruptible log follow I/O stopped without a result", + None, + )); + } + } + } +} + +fn follow_runtime_error(message: impl Into, source_detail: Option) -> SatelleError { + SatelleError { + code: ErrorCode::RemoteExecution, + message: message.into(), + recovery_command: None, + source_detail, + details: std::collections::BTreeMap::new(), + } +} + +fn open_follow_connection( + connection_factory: FollowConnectionFactory, + expected_host_identity: Option, + session_id: Option, + reconnect: bool, + runtime: &dyn FollowRuntime, +) -> Result<(Box, String), SatelleError> { + match run_follow_operation(runtime, None, move || { + connection_factory().and_then(|connection| { + validate_follow_connection( + connection.as_ref(), + expected_host_identity.as_deref(), + session_id.as_ref(), + reconnect, + ) + .map(|observed_host_identity| (connection, observed_host_identity)) + }) + })? { + FollowOperation::Completed(connection) => Ok(connection), + FollowOperation::TimedOut => unreachable!("an initial follow operation has no timeout"), + } +} + +fn read_follow_page( + connection: Box, + query: LogPageQuery, + runtime: &dyn FollowRuntime, +) -> Result<(Box, satelle_host::DaemonLogPage), SatelleError> { + match run_follow_operation(runtime, None, move || { + let page = connection.logs(&query)?; + Ok((connection, page)) + })? { + FollowOperation::Completed(page) => Ok(page), + FollowOperation::TimedOut => unreachable!("an active follow read has no local timeout"), + } +} + +fn validate_follow_connection( + connection: &dyn FollowConnection, + expected_host_identity: Option<&str>, + session_id: Option<&SessionId>, + reconnect: bool, +) -> Result { + let observed_host_identity = connection.host_identity()?; + if let Some(expected) = expected_host_identity + && observed_host_identity != expected + { + return Err(SatelleError::logs_follow_identity_changed( + expected, + Some(&observed_host_identity), + session_id.map(SessionId::as_str), + )); + } + if let Some(session_id) = session_id { + let session = connection.session(session_id).map_err(|error| { + if error.code == ErrorCode::HostIdentityMismatch { + SatelleError::logs_follow_identity_changed( + expected_host_identity.unwrap_or(&observed_host_identity), + None, + Some(session_id.as_str()), + ) + } else if reconnect && error.code == ErrorCode::SessionNotFound { + SatelleError::logs_follow_identity_changed( + expected_host_identity.unwrap_or(&observed_host_identity), + Some(&observed_host_identity), + Some(session_id.as_str()), + ) + } else { + error + } + })?; + if session.session_id() != session_id { + return Err(SatelleError::logs_follow_identity_changed( + expected_host_identity.unwrap_or(&observed_host_identity), + Some(&observed_host_identity), + Some(session_id.as_str()), + )); + } + } + Ok(observed_host_identity) +} + +fn map_follow_identity_error( + error: SatelleError, + expected_host_identity: &str, + session_id: Option<&str>, +) -> SatelleError { + if error.code == ErrorCode::HostIdentityMismatch { + SatelleError::logs_follow_identity_changed(expected_host_identity, None, session_id) + } else { + error + } +} + +fn transient_follow_error(code: ErrorCode) -> bool { + matches!( + code, + ErrorCode::HostUnreachable + | ErrorCode::HostDaemonUnreachable + | ErrorCode::DirectDaemonUnreachable + | ErrorCode::SshBootstrapUnavailable + ) +} + +fn follow_reconnect_exhausted( + request: &LogReadRequest, + host_alias: &str, + cursor: LogCursor, + stream_interruptions: usize, +) -> SatelleError { + SatelleError::logs_follow_reconnect_exhausted( + &cursor.to_string(), + stream_interruptions, + &request.follow_rerun_command(host_alias, cursor), + ) +} + +fn jittered_delay(duration: StdDuration, sample: u64) -> StdDuration { + let basis_points = 8_000_u128 + u128::from(sample % 4_001); + let nanos = duration.as_nanos().saturating_mul(basis_points) / 10_000; + StdDuration::from_nanos(nanos.min(u128::from(u64::MAX)) as u64).min(RECONNECT_MAX_DELAY) +} + impl LogReadPlan { fn resolve(command: &LogReadRequest) -> Result { if command.after.is_some() && command.since.is_some() { @@ -214,14 +802,11 @@ impl LogReadPlan { write_entries(page.entries(), None, format) } LogPosition::After(cursor) => { - let query = self.query( - LogPageQuery::forward(Some(cursor), DEFAULT_LOG_PAGE_LIMIT) - .expect("the default forward Log limit is valid"), - ); - let page = transport.logs(&query)?; - write_entries(page.entries(), None, format) + self.emit_forward_snapshot(transport, Some(cursor), DEFAULT_LOG_PAGE_LIMIT, format) + } + LogPosition::SinceAll => { + self.emit_forward_snapshot(transport, None, MAX_LOG_PAGE_LIMIT, format) } - LogPosition::SinceAll => self.emit_since_snapshot(transport, format), } } @@ -234,22 +819,113 @@ impl LogReadPlan { Ok(transport.logs(&query)?.entries().to_vec()) } LogPosition::After(cursor) => { - let query = self.query( - LogPageQuery::forward(Some(cursor), DEFAULT_LOG_PAGE_LIMIT) - .expect("the default forward Log limit is valid"), - ); - Ok(transport.logs(&query)?.entries().to_vec()) + self.read_forward_snapshot(transport, Some(cursor), DEFAULT_LOG_PAGE_LIMIT) + } + LogPosition::SinceAll => { + self.read_forward_snapshot(transport, None, MAX_LOG_PAGE_LIMIT) } - LogPosition::SinceAll => self.read_since_snapshot(transport), } } - fn read_since_snapshot( + fn emit_follow_initial( + &self, + mut connection: Box, + runtime: &dyn FollowRuntime, + format: OutputFormat, + stdout: &mut dyn Write, + ) -> Result { + match self.position { + LogPosition::Tail(limit) => { + let (connection, page) = read_follow_page( + connection, + self.query( + LogPageQuery::tail(limit).expect("the validated tail Log limit is valid"), + ), + runtime, + )?; + write_entries_to(page.entries(), None, format, stdout)?; + Ok(( + connection, + page.next_cursor(), + page.entries().last().map(DaemonLogEntry::cursor), + )) + } + LogPosition::After(cursor) => { + let (connection, page) = read_follow_page( + connection, + self.query( + LogPageQuery::forward(Some(cursor), DEFAULT_LOG_PAGE_LIMIT) + .expect("the default forward Log limit is valid"), + ), + runtime, + )?; + write_entries_to(page.entries(), None, format, stdout)?; + Ok(( + connection, + page.next_cursor(), + page.entries().last().map(DaemonLogEntry::cursor), + )) + } + LogPosition::SinceAll => { + let (returned_connection, snapshot_page) = read_follow_page( + connection, + self.query( + LogPageQuery::tail(1).expect("the snapshot Log page limit is valid"), + ), + runtime, + )?; + connection = returned_connection; + let snapshot = snapshot_page.next_cursor(); + let mut cursor = None; + let mut last_delivered = None; + loop { + let (returned_connection, page) = read_follow_page( + connection, + self.query( + LogPageQuery::forward(cursor, MAX_LOG_PAGE_LIMIT) + .expect("the maximum forward Log limit is valid"), + ), + runtime, + )?; + connection = returned_connection; + let reached_snapshot = !page.truncated() + || page + .entries() + .last() + .is_some_and(|entry| entry.cursor() >= snapshot); + write_entries_to(page.entries(), Some(snapshot), format, stdout)?; + if let Some(entry) = page + .entries() + .iter() + .take_while(|entry| entry.cursor() <= snapshot) + .last() + { + last_delivered = Some(entry.cursor()); + } + if reached_snapshot { + return Ok((connection, snapshot, last_delivered)); + } + cursor = Some(page.next_cursor()); + } + } + } + } + + fn follow_query(&self, cursor: LogCursor) -> LogPageQuery { + self.query( + LogPageQuery::forward(Some(cursor), DEFAULT_LOG_PAGE_LIMIT) + .expect("the default forward Log limit is valid"), + ) + } + + fn read_forward_snapshot( &self, transport: &dyn TransportClient, + cursor: Option, + page_limit: usize, ) -> Result, SatelleError> { let mut entries = Vec::new(); - self.visit_since_snapshot(transport, |page, snapshot| { + self.visit_forward_snapshot(transport, cursor, page_limit, |page, snapshot| { entries.extend( page.iter() .take_while(|entry| entry.cursor() <= snapshot) @@ -260,22 +936,26 @@ impl LogReadPlan { Ok(entries) } - fn emit_since_snapshot( + fn emit_forward_snapshot( &self, transport: &dyn TransportClient, + cursor: Option, + page_limit: usize, format: OutputFormat, ) -> Result<(), SatelleError> { - self.visit_since_snapshot(transport, |entries, snapshot| { + self.visit_forward_snapshot(transport, cursor, page_limit, |entries, snapshot| { // Logs are record streams. If a later page fails, already-written complete records // remain valid stdout while the command reports failure on stderr and exits nonzero. write_entries(entries, Some(snapshot), format) }) } - fn visit_since_snapshot( + fn visit_forward_snapshot( &self, transport: &dyn TransportClient, - mut visit: impl FnMut(&[DaemonLogEntry], LogCursor) -> Result<(), SatelleError>, + cursor: Option, + page_limit: usize, + visit: impl FnMut(&[DaemonLogEntry], LogCursor) -> Result<(), SatelleError>, ) -> Result<(), SatelleError> { // Capture one Host high-water boundary before paging. New entries may arrive while this // finite command runs, but they belong to a later invocation and cannot extend this read. @@ -284,25 +964,19 @@ impl LogReadPlan { &self.query(LogPageQuery::tail(1).expect("the snapshot Log page limit is valid")), )? .next_cursor(); - let mut cursor = None; - - loop { - let query = self.query( - LogPageQuery::forward(cursor, MAX_LOG_PAGE_LIMIT) - .expect("the maximum forward Log limit is valid"), - ); - let page = transport.logs(&query)?; - let reached_snapshot = !page.truncated() - || page - .entries() - .last() - .is_some_and(|entry| entry.cursor() >= snapshot); - visit(page.entries(), snapshot)?; - if reached_snapshot { - return Ok(()); - } - cursor = Some(page.next_cursor()); - } + visit_forward_snapshot_pages( + snapshot, + cursor, + page_limit, + |cursor, limit| { + let query = self.query( + LogPageQuery::forward(cursor, limit) + .expect("the validated forward Log limit is valid"), + ); + transport.logs(&query) + }, + visit, + ) } } @@ -311,16 +985,63 @@ pub(crate) fn show_logs( config: ConfigContext<'_>, format: OutputFormat, ) -> Result<(), CliFailure> { - let request = LogReadRequest::from(command); + let request = LogReadRequest::from_command(command, format); let plan = LogReadPlan::resolve(&request)?; let host = match plan.session_id() { - Some(session_id) => config.resolve_session_host(request.host.as_deref(), session_id)?, - None => config.resolve_host(request.host.as_deref())?, + Some(session_id) => config + .resolve_session_host(request.host.as_deref(), session_id) + .or_else(|failure| unresolved_log_target(&request, failure))?, + None => config + .resolve_host(request.host.as_deref()) + .or_else(|failure| unresolved_log_target(&request, failure))?, }; + if request.follow { + let runtime = ProcessFollowRuntime::new().map_err(failure)?; + let follow_host = host.clone(); + let connection_factory: FollowConnectionFactory = Arc::new(move || { + transport_for(&follow_host) + .map(|transport| { + Box::new(TransportFollowConnection { transport }) as Box + }) + .map_err(|failure| failure.error) + }); + let stdout = io::stdout(); + let stderr = io::stderr(); + let mut stdout = stdout.lock(); + let mut stderr = stderr.lock(); + return follow_logs( + &plan, + &request, + &host.alias, + format, + &runtime, + &connection_factory, + FollowOutput { + stdout: &mut stdout, + stderr: &mut stderr, + }, + ) + .map_err(failure); + } let transport = transport_for(&host)?; plan.emit(transport.as_ref(), format).map_err(failure) } +fn unresolved_log_target( + request: &LogReadRequest, + failure: CliFailure, +) -> Result { + if request.host.is_none() + && (failure.error.code == ErrorCode::HostNotFound + || (failure.error.code == ErrorCode::InvalidUsage + && failure.error.details.get("candidate_count") == Some(&serde_json::json!(0)))) + { + Err(super::failure(SatelleError::logs_target_required())) + } else { + Err(failure) + } +} + pub(crate) fn read_logs_for_host( request: &LogReadRequest, host: &super::SelectedHost, @@ -336,12 +1057,21 @@ fn write_entries( format: OutputFormat, ) -> Result<(), SatelleError> { let mut stdout = io::stdout().lock(); + write_entries_to(entries, through, format, &mut stdout) +} + +fn write_entries_to( + entries: &[DaemonLogEntry], + through: Option, + format: OutputFormat, + stdout: &mut dyn Write, +) -> Result<(), SatelleError> { for entry in entries .iter() .take_while(|entry| through.is_none_or(|cursor| entry.cursor() <= cursor)) { if format.is_json() { - serde_json::to_writer(&mut stdout, entry) + serde_json::to_writer(&mut *stdout, entry) .map_err(|error| SatelleError::invalid_usage(error.to_string()))?; writeln!(stdout).map_err(log_output_error)?; } else { @@ -370,9 +1100,944 @@ fn parse_log_since(value: &str) -> Result { } let millis = parse_duration_ms(value)?; - Ok(OffsetDateTime::now_utc() - Duration::milliseconds(millis.min(i64::MAX as u64) as i64)) + OffsetDateTime::now_utc() + .checked_sub(Duration::milliseconds(millis.min(i64::MAX as u64) as i64)) + .ok_or_else(|| { + SatelleError::invalid_usage("--since duration is outside the supported timestamp range") + }) } fn log_output_error(error: io::Error) -> SatelleError { SatelleError::invalid_usage(format!("could not write log output: {error}")) } + +#[cfg(test)] +mod tests { + use super::*; + use std::cell::Cell; + use std::collections::VecDeque; + use std::sync::Mutex; + use std::sync::atomic::{AtomicBool, AtomicUsize}; + + struct FakeFollowConnection { + host_identity: String, + pages: Mutex>>, + interrupt_on_log: Option<(Arc, usize, StdDuration)>, + log_calls: AtomicUsize, + } + + struct SessionIdentityMismatchFollowConnection; + + struct SessionScopeMismatchFollowConnection { + returned_session: satelle_core::session::PublicSession, + } + + impl FakeFollowConnection { + fn new( + host_identity: &str, + pages: impl IntoIterator>, + ) -> Self { + Self { + host_identity: host_identity.to_string(), + pages: Mutex::new(pages.into_iter().collect()), + interrupt_on_log: None, + log_calls: AtomicUsize::new(0), + } + } + + fn with_interrupt_on_log( + mut self, + call: usize, + interrupted: Arc, + delay: StdDuration, + ) -> Self { + self.interrupt_on_log = Some((interrupted, call, delay)); + self + } + } + + impl FollowConnection for FakeFollowConnection { + fn host_identity(&self) -> Result { + Ok(self.host_identity.clone()) + } + + fn session( + &self, + _session_id: &SessionId, + ) -> Result { + Err(SatelleError::not_implemented( + "the no-Session follow fixture does not load Sessions", + )) + } + + fn logs(&self, _query: &LogPageQuery) -> Result { + let call = self.log_calls.fetch_add(1, Ordering::Relaxed) + 1; + if let Some((interrupted, interrupt_call, delay)) = &self.interrupt_on_log + && call == *interrupt_call + { + interrupted.store(true, Ordering::Release); + thread::sleep(*delay); + } + self.pages + .lock() + .expect("follow fixture queue lock") + .pop_front() + .expect("follow fixture has a response") + } + } + + impl FollowConnection for SessionIdentityMismatchFollowConnection { + fn host_identity(&self) -> Result { + Ok("host-original".to_string()) + } + + fn session( + &self, + _session_id: &SessionId, + ) -> Result { + Err(SatelleError::host_identity_mismatch("remote")) + } + + fn logs(&self, _query: &LogPageQuery) -> Result { + panic!("identity validation must fail before logs are requested") + } + } + + impl FollowConnection for SessionScopeMismatchFollowConnection { + fn host_identity(&self) -> Result { + Ok("host-original".to_string()) + } + + fn session( + &self, + _session_id: &SessionId, + ) -> Result { + Ok(self.returned_session.clone()) + } + + fn logs(&self, _query: &LogPageQuery) -> Result { + panic!("Session scope validation must fail before logs are requested") + } + } + + #[test] + fn forward_snapshot_visits_every_page_after_the_start_cursor() { + let start = LogCursor::parse("slc1_0000000000000005").expect("valid start cursor"); + let first_page_cursor = + LogCursor::parse("slc1_00000000000000c8").expect("valid first-page cursor"); + let snapshot = LogCursor::parse("slc1_00000000000000cd").expect("valid snapshot cursor"); + let mut pages = VecDeque::from([ + serde_json::from_value::(serde_json::json!({ + "entries": [], + "next_cursor": first_page_cursor, + "truncated": true + })) + .expect("the first forward page should decode"), + serde_json::from_value::(serde_json::json!({ + "entries": [], + "next_cursor": snapshot, + "truncated": false + })) + .expect("the final forward page should decode"), + ]); + let mut requested_cursors = Vec::new(); + let mut visited_pages = 0; + + visit_forward_snapshot_pages( + snapshot, + Some(start), + DEFAULT_LOG_PAGE_LIMIT, + |cursor, limit| { + assert_eq!(limit, DEFAULT_LOG_PAGE_LIMIT); + requested_cursors.push(cursor); + Ok(pages.pop_front().expect("the paginator requested a page")) + }, + |_, _| { + visited_pages += 1; + Ok(()) + }, + ) + .expect("the finite forward read should reach its snapshot"); + + assert_eq!(requested_cursors, [Some(start), Some(first_page_cursor)]); + assert_eq!(visited_pages, 2); + assert!(pages.is_empty()); + } + + fn public_session(session_id: &SessionId) -> satelle_core::session::PublicSession { + let turn_id = satelle_core::TurnId::new(); + serde_json::from_value(serde_json::json!({ + "session_id": session_id, + "display_name": null, + "session_state_revision": 1, + "created_at": "2024-01-01T00:00:00Z", + "updated_at": "2024-01-01T00:00:00Z", + "activity": { + "state": "starting", + "turn_id": turn_id, + "turn_state_revision": 1 + }, + "turns": [{ + "session_id": session_id, + "turn_id": turn_id, + "turn_state_revision": 1, + "state": "starting", + "started_at": "2024-01-01T00:00:00Z", + "updated_at": "2024-01-01T00:00:00Z", + "terminal_at": null, + "safe_summary": null + }] + })) + .expect("construct a coherent public Session fixture") + } + + fn queued_connection_factory( + connections: impl IntoIterator>, + ) -> FollowConnectionFactory { + let connections = Mutex::new(connections.into_iter().collect::>()); + Arc::new(move || { + connections + .lock() + .expect("follow connection fixture lock") + .pop_front() + .ok_or_else(|| SatelleError::host_unreachable("remote")) + }) + } + + struct FakeFollowRuntime { + started_at: Instant, + elapsed: Cell, + sleeps: Cell, + interrupt_after_sleeps: Option, + jitter_override: Option, + reconnect_budget: StdDuration, + external_interrupt: Option>, + } + + impl FakeFollowRuntime { + fn new(interrupt_after_sleeps: Option) -> Self { + Self { + started_at: Instant::now(), + elapsed: Cell::new(StdDuration::ZERO), + sleeps: Cell::new(0), + interrupt_after_sleeps, + jitter_override: None, + reconnect_budget: RECONNECT_BUDGET, + external_interrupt: None, + } + } + + fn with_jitter_override(mut self, jitter: StdDuration) -> Self { + self.jitter_override = Some(jitter); + self + } + + fn with_reconnect_budget(mut self, budget: StdDuration) -> Self { + self.reconnect_budget = budget; + self + } + + fn with_interrupt_flag(mut self, interrupted: Arc) -> Self { + self.external_interrupt = Some(interrupted); + self + } + } + + impl FollowRuntime for FakeFollowRuntime { + fn now(&self) -> Instant { + self.started_at + self.elapsed.get() + } + + fn interrupted(&self) -> bool { + self.external_interrupt + .as_ref() + .is_some_and(|interrupted| interrupted.load(Ordering::Acquire)) + || self + .interrupt_after_sleeps + .is_some_and(|limit| self.sleeps.get() >= limit) + } + + fn sleep(&self, duration: StdDuration) { + self.elapsed.set(self.elapsed.get() + duration); + self.sleeps.set(self.sleeps.get() + 1); + } + + fn jitter(&self, duration: StdDuration) -> StdDuration { + self.jitter_override.unwrap_or(duration) + } + + fn reconnect_budget(&self) -> StdDuration { + self.reconnect_budget + } + } + + fn request() -> LogReadRequest { + LogReadRequest { + host: Some("remote".to_string()), + session: None, + tail: Some(1), + since: None, + after: None, + source: Vec::new(), + level: None, + follow: true, + no_reconnect: false, + format: OutputFormat::Human, + } + } + + #[test] + fn relative_since_outside_the_timestamp_range_is_a_typed_usage_error() { + let error = parse_log_since("9223372036854775807ms") + .expect_err("an unrepresentable relative timestamp must be rejected"); + + assert_eq!(error.code, ErrorCode::InvalidUsage); + } + + #[test] + fn follow_worker_disconnect_is_a_runtime_error_without_config_recovery() { + let runtime = FakeFollowRuntime::new(None); + let error = match run_follow_operation::<()>(&runtime, None, || { + panic!("drop the worker result sender") + }) { + Err(error) => error, + Ok(_) => panic!("a panicked follow worker must fail closed"), + }; + + assert_eq!(error.code, ErrorCode::RemoteExecution); + assert_eq!(error.recovery_command, None); + } + + #[test] + fn follow_rerun_command_quotes_host_aliases() { + assert_eq!( + request().follow_rerun_command( + "host alias; echo owned", + serde_json::from_value(serde_json::json!("slc1_0000000000000001")) + .expect("valid opaque Log Cursor"), + ), + "satelle logs --host 'host alias; echo owned' --after slc1_0000000000000001 --follow" + ); + } + + #[test] + fn follow_rerun_command_preserves_json_output() { + let mut request = request(); + request.format = OutputFormat::Json; + + assert_eq!( + request.follow_rerun_command( + "remote", + serde_json::from_value(serde_json::json!("slc1_0000000000000001")) + .expect("valid opaque Log Cursor"), + ), + "satelle logs --host remote --after slc1_0000000000000001 --follow --json" + ); + } + + fn page(cursor: u64) -> satelle_host::DaemonLogPage { + serde_json::from_value(serde_json::json!({ + "entries": [{ + "schema_version": "satelle.logs.entry.v1", + "cursor": format!("slc1_{cursor:016x}"), + "timestamp": "2026-08-02T00:00:00Z", + "host_identity": "host-original", + "source": "storage", + "severity": "info", + "event": "store_opened", + "subject": {"kind": "host"}, + "message": "opened Host state store", + "redacted": true + }], + "next_cursor": format!("slc1_{cursor:016x}"), + "truncated": false + })) + .expect("valid normalized Log page fixture") + } + + #[test] + fn reconnect_resumes_the_same_ndjson_stream_from_the_stored_cursor() { + let request = request(); + let plan = + LogReadPlan::resolve(&request).unwrap_or_else(|_| panic!("resolve follow request")); + let factory = queued_connection_factory([ + Box::new(FakeFollowConnection::new( + "host-original", + [Ok(page(1)), Err(SatelleError::host_unreachable("remote"))], + )) as Box, + Box::new(FakeFollowConnection::new("host-original", [Ok(page(2))])) + as Box, + ]); + let runtime = FakeFollowRuntime::new(Some(2)); + let mut stdout = Vec::new(); + let mut stderr = Vec::new(); + + let error = follow_logs( + &plan, + &request, + "remote", + OutputFormat::Json, + &runtime, + &factory, + FollowOutput { + stdout: &mut stdout, + stderr: &mut stderr, + }, + ) + .expect_err("the fixture interrupts after the resumed page"); + + assert_eq!(error.code, ErrorCode::Interrupted); + let records = String::from_utf8(stdout) + .unwrap() + .lines() + .map(|line| serde_json::from_str::(line).unwrap()) + .collect::>(); + assert_eq!(records.len(), 2); + assert_eq!(records[0]["cursor"], "slc1_0000000000000001"); + assert_eq!(records[1]["cursor"], "slc1_0000000000000002"); + let notices = String::from_utf8(stderr).unwrap(); + assert!(notices.contains("reconnecting after interruption 1/10")); + assert!(notices.contains("resuming after cursor=slc1_0000000000000001")); + } + + #[test] + fn interrupt_during_initial_read_wins_over_the_transport_failure() { + let request = request(); + let plan = + LogReadPlan::resolve(&request).unwrap_or_else(|_| panic!("resolve follow request")); + let interrupted = Arc::new(AtomicBool::new(false)); + let connection = FakeFollowConnection::new( + "host-original", + [Err(SatelleError::host_unreachable("remote"))], + ) + .with_interrupt_on_log(1, Arc::clone(&interrupted), StdDuration::from_secs(2)); + let factory = + queued_connection_factory([Box::new(connection) as Box]); + let runtime = FakeFollowRuntime::new(None).with_interrupt_flag(interrupted); + + let started_at = Instant::now(); + let error = follow_logs( + &plan, + &request, + "remote", + OutputFormat::Human, + &runtime, + &factory, + FollowOutput { + stdout: &mut Vec::new(), + stderr: &mut Vec::new(), + }, + ) + .expect_err("Ctrl-C must take precedence over the interrupted initial read"); + + assert_eq!(error.code, ErrorCode::Interrupted); + assert!( + started_at.elapsed() < StdDuration::from_millis(500), + "Ctrl-C waited for the stalled initial read" + ); + } + + #[test] + fn initial_page_identity_failure_uses_the_typed_follow_error() { + let request = request(); + let plan = + LogReadPlan::resolve(&request).unwrap_or_else(|_| panic!("resolve follow request")); + let factory = queued_connection_factory([Box::new(FakeFollowConnection::new( + "host-original", + [Err(SatelleError::host_identity_mismatch("remote"))], + )) as Box]); + + let error = follow_logs( + &plan, + &request, + "remote", + OutputFormat::Human, + &FakeFollowRuntime::new(None), + &factory, + FollowOutput { + stdout: &mut Vec::new(), + stderr: &mut Vec::new(), + }, + ) + .expect_err("initial identity drift must use the follow error contract"); + + assert_eq!(error.code, ErrorCode::LogsFollowIdentityChanged); + assert_eq!(error.details["expected_host_identity"], "host-original"); + assert_eq!( + error.details["observed_host_identity"], + serde_json::Value::Null + ); + } + + #[test] + fn initial_session_validation_identity_failure_uses_the_typed_follow_error() { + let session_id = SessionId::new(); + let mut request = request(); + request.session = Some(session_id.to_string()); + let plan = + LogReadPlan::resolve(&request).unwrap_or_else(|_| panic!("resolve follow request")); + let factory = queued_connection_factory([ + Box::new(SessionIdentityMismatchFollowConnection) as Box, + ]); + + let error = follow_logs( + &plan, + &request, + "remote", + OutputFormat::Human, + &FakeFollowRuntime::new(None), + &factory, + FollowOutput { + stdout: &mut Vec::new(), + stderr: &mut Vec::new(), + }, + ) + .expect_err("initial Session identity drift must use the follow error contract"); + + assert_eq!(error.code, ErrorCode::LogsFollowIdentityChanged); + assert_eq!(error.details["expected_host_identity"], "host-original"); + assert_eq!(error.details["session_id"], session_id.as_str()); + } + + #[test] + fn interrupt_during_poll_read_wins_over_the_transport_failure() { + let request = request(); + let plan = + LogReadPlan::resolve(&request).unwrap_or_else(|_| panic!("resolve follow request")); + let interrupted = Arc::new(AtomicBool::new(false)); + let connection = FakeFollowConnection::new( + "host-original", + [Ok(page(1)), Err(SatelleError::host_unreachable("remote"))], + ) + .with_interrupt_on_log(2, Arc::clone(&interrupted), StdDuration::from_secs(2)); + let factory = + queued_connection_factory([Box::new(connection) as Box]); + let runtime = FakeFollowRuntime::new(None).with_interrupt_flag(interrupted); + + let started_at = Instant::now(); + let error = follow_logs( + &plan, + &request, + "remote", + OutputFormat::Human, + &runtime, + &factory, + FollowOutput { + stdout: &mut Vec::new(), + stderr: &mut Vec::new(), + }, + ) + .expect_err("Ctrl-C must take precedence over the interrupted poll read"); + + assert_eq!(error.code, ErrorCode::Interrupted); + assert!( + started_at.elapsed() < StdDuration::from_millis(500), + "Ctrl-C waited for the stalled poll read" + ); + } + + #[test] + fn reconnect_rejects_a_changed_host_identity_before_resuming() { + let request = request(); + let plan = + LogReadPlan::resolve(&request).unwrap_or_else(|_| panic!("resolve follow request")); + let factory = queued_connection_factory([ + Box::new(FakeFollowConnection::new( + "host-original", + [Ok(page(1)), Err(SatelleError::host_unreachable("remote"))], + )) as Box, + Box::new(FakeFollowConnection::new( + "host-replacement", + std::iter::empty::>(), + )) as Box, + ]); + let runtime = FakeFollowRuntime::new(None); + + let error = follow_logs( + &plan, + &request, + "remote", + OutputFormat::Json, + &runtime, + &factory, + FollowOutput { + stdout: &mut Vec::new(), + stderr: &mut Vec::new(), + }, + ) + .expect_err("identity drift is terminal"); + assert_eq!(error.code, ErrorCode::LogsFollowIdentityChanged); + assert_eq!(error.details["expected_host_identity"], "host-original"); + assert_eq!(error.details["observed_host_identity"], "host-replacement"); + } + + #[test] + fn reconnect_maps_factory_identity_failures_to_the_follow_error() { + let session_id = SessionId::new(); + let factory: FollowConnectionFactory = + Arc::new(|| Err(SatelleError::host_identity_mismatch("remote"))); + + let error = match run_reconnect_attempt( + factory, + "host-original".to_string(), + Some(session_id.clone()), + LogPageQuery::default(), + StdDuration::from_secs(1), + &FakeFollowRuntime::new(None), + ) { + Some(Err(error)) => error, + Some(Ok(_)) => panic!("the factory identity mismatch must be terminal"), + None => panic!("the reconnect attempt should finish"), + }; + + assert_eq!(error.code, ErrorCode::LogsFollowIdentityChanged); + assert_eq!(error.details["expected_host_identity"], "host-original"); + assert_eq!( + error.details["observed_host_identity"], + serde_json::Value::Null + ); + assert_eq!(error.details["session_id"], session_id.as_str()); + } + + #[test] + fn reconnect_maps_session_validation_identity_failures_to_the_follow_error() { + let session_id = SessionId::new(); + let factory: FollowConnectionFactory = Arc::new(|| { + Ok(Box::new(SessionIdentityMismatchFollowConnection) as Box) + }); + + let error = match run_reconnect_attempt( + factory, + "host-original".to_string(), + Some(session_id.clone()), + LogPageQuery::default(), + StdDuration::from_secs(1), + &FakeFollowRuntime::new(None), + ) { + Some(Err(error)) => error, + Some(Ok(_)) => panic!("the Session identity mismatch must be terminal"), + None => panic!("the reconnect attempt should finish"), + }; + + assert_eq!(error.code, ErrorCode::LogsFollowIdentityChanged); + assert_eq!(error.details["expected_host_identity"], "host-original"); + assert_eq!( + error.details["observed_host_identity"], + serde_json::Value::Null + ); + assert_eq!(error.details["session_id"], session_id.as_str()); + } + + #[test] + fn reconnect_rejects_a_session_response_for_another_session() { + let expected_session_id = SessionId::new(); + let returned_session_id = SessionId::new(); + let connection = SessionScopeMismatchFollowConnection { + returned_session: public_session(&returned_session_id), + }; + + let error = validate_follow_connection( + &connection, + Some("host-original"), + Some(&expected_session_id), + true, + ) + .expect_err("a contradictory nested Session ID must stop reconnect"); + + assert_eq!(error.code, ErrorCode::LogsFollowIdentityChanged); + assert_eq!(error.details["expected_host_identity"], "host-original"); + assert_eq!(error.details["observed_host_identity"], "host-original"); + assert_eq!(error.details["session_id"], expected_session_id.as_str()); + } + + #[test] + fn interrupt_while_reconnect_attempt_is_pending_returns_promptly() { + let request = request(); + let plan = + LogReadPlan::resolve(&request).unwrap_or_else(|_| panic!("resolve follow request")); + let interrupted = Arc::new(AtomicBool::new(false)); + let factory_interrupt = Arc::clone(&interrupted); + let factory: FollowConnectionFactory = Arc::new(move || { + factory_interrupt.store(true, Ordering::Release); + thread::sleep(StdDuration::from_secs(2)); + Err(SatelleError::host_unreachable("remote")) + }); + let runtime = FakeFollowRuntime::new(None).with_interrupt_flag(interrupted); + let target = FollowTarget { + plan: &plan, + request: &request, + host_alias: "remote", + expected_host_identity: "host-original", + }; + let cursor = page(1).next_cursor(); + let started_at = Instant::now(); + + let error = match reconnect_follow( + &target, + &runtime, + &factory, + cursor, + cursor, + 1, + &mut Vec::new(), + ) { + Err(error) => error, + Ok(_) => panic!("Ctrl-C must stop a pending reconnect attempt"), + }; + + assert_eq!(error.code, ErrorCode::Interrupted); + assert!( + started_at.elapsed() < StdDuration::from_millis(500), + "Ctrl-C waited for the pending transport attempt" + ); + } + + #[test] + fn daemon_api_failures_remain_terminal_during_follow() { + let request = request(); + let plan = + LogReadPlan::resolve(&request).unwrap_or_else(|_| panic!("resolve follow request")); + let factory_calls = Arc::new(AtomicUsize::new(0)); + let observed_factory_calls = Arc::clone(&factory_calls); + let factory: FollowConnectionFactory = Arc::new(move || { + observed_factory_calls.fetch_add(1, Ordering::Relaxed); + Ok(Box::new(FakeFollowConnection::new( + "host-original", + [ + Ok(page(1)), + Err(SatelleError::remote_api_error( + "remote", + "storage-integrity-failed", + )), + ], + )) as Box) + }); + let runtime = FakeFollowRuntime::new(None); + + let error = follow_logs( + &plan, + &request, + "remote", + OutputFormat::Json, + &runtime, + &factory, + FollowOutput { + stdout: &mut Vec::new(), + stderr: &mut Vec::new(), + }, + ) + .expect_err("a daemon API rejection is terminal"); + + assert_eq!(error.code, ErrorCode::RemoteExecution); + assert_eq!(factory_calls.load(Ordering::Relaxed), 1); + assert_eq!(runtime.sleeps.get(), 0, "a terminal API error cannot retry"); + } + + #[test] + fn reconnect_budget_is_finite_and_reports_the_resume_command() { + let request = request(); + let plan = + LogReadPlan::resolve(&request).unwrap_or_else(|_| panic!("resolve follow request")); + let factory_calls = Arc::new(AtomicUsize::new(0)); + let reconnect_factory_calls = Arc::clone(&factory_calls); + let factory: FollowConnectionFactory = Arc::new(move || { + let call = reconnect_factory_calls.fetch_add(1, Ordering::Relaxed); + let pages = if call == 0 { + vec![Ok(page(1)), Err(SatelleError::host_unreachable("remote"))] + } else { + vec![Err(SatelleError::host_unreachable("remote"))] + }; + Ok(Box::new(FakeFollowConnection::new("host-original", pages)) + as Box) + }); + let runtime = FakeFollowRuntime::new(None); + + let error = follow_logs( + &plan, + &request, + "remote", + OutputFormat::Json, + &runtime, + &factory, + FollowOutput { + stdout: &mut Vec::new(), + stderr: &mut Vec::new(), + }, + ) + .expect_err("the per-interruption reconnect budget is finite"); + assert_eq!(error.code, ErrorCode::LogsFollowReconnectExhausted); + assert_eq!( + error.details["last_delivered_cursor"], + "slc1_0000000000000001" + ); + assert_eq!( + error.recovery_command.as_deref(), + Some("satelle logs --host remote --after slc1_0000000000000001 --follow") + ); + assert!(runtime.elapsed.get() >= RECONNECT_BUDGET); + } + + #[test] + fn reconnect_deadline_reached_by_sleep_does_not_start_an_attempt() { + let request = request(); + let plan = + LogReadPlan::resolve(&request).unwrap_or_else(|_| panic!("resolve follow request")); + let factory_calls = Arc::new(AtomicUsize::new(0)); + let reconnect_factory_calls = Arc::clone(&factory_calls); + let factory: FollowConnectionFactory = Arc::new(move || { + let call = reconnect_factory_calls.fetch_add(1, Ordering::Relaxed); + assert_eq!( + call, 0, + "an expired reconnect budget started another attempt" + ); + Ok(Box::new(FakeFollowConnection::new( + "host-original", + [Ok(page(1)), Err(SatelleError::host_unreachable("remote"))], + )) as Box) + }); + let runtime = FakeFollowRuntime::new(None).with_jitter_override(RECONNECT_BUDGET); + + let error = follow_logs( + &plan, + &request, + "remote", + OutputFormat::Json, + &runtime, + &factory, + FollowOutput { + stdout: &mut Vec::new(), + stderr: &mut Vec::new(), + }, + ) + .expect_err("the attempt at the exact reconnect deadline is rejected"); + + assert_eq!(error.code, ErrorCode::LogsFollowReconnectExhausted); + assert_eq!(factory_calls.load(Ordering::Relaxed), 1); + assert_eq!(runtime.elapsed.get(), RECONNECT_BUDGET); + } + + #[test] + fn reconnect_attempt_is_bounded_by_the_remaining_budget() { + let request = request(); + let plan = + LogReadPlan::resolve(&request).unwrap_or_else(|_| panic!("resolve follow request")); + let runtime = FakeFollowRuntime::new(None) + .with_jitter_override(StdDuration::from_millis(1)) + .with_reconnect_budget(StdDuration::from_millis(100)); + let factory_calls = Arc::new(AtomicUsize::new(0)); + let reconnect_factory_calls = Arc::clone(&factory_calls); + let factory: FollowConnectionFactory = Arc::new(move || { + let call = reconnect_factory_calls.fetch_add(1, Ordering::Relaxed); + if call == 0 { + return Ok(Box::new(FakeFollowConnection::new( + "host-original", + [Ok(page(1)), Err(SatelleError::host_unreachable("remote"))], + )) as Box); + } + thread::sleep(StdDuration::from_millis(200)); + Ok( + Box::new(FakeFollowConnection::new("host-original", [Ok(page(2))])) + as Box, + ) + }); + + let error = follow_logs( + &plan, + &request, + "remote", + OutputFormat::Json, + &runtime, + &factory, + FollowOutput { + stdout: &mut Vec::new(), + stderr: &mut Vec::new(), + }, + ) + .expect_err("a stalled attempt reaches the reconnect deadline"); + + assert_eq!(error.code, ErrorCode::LogsFollowReconnectExhausted); + assert_eq!(factory_calls.load(Ordering::Relaxed), 2); + } + + #[test] + fn no_reconnect_returns_the_transport_failure_with_the_last_cursor() { + let mut request = request(); + request.no_reconnect = true; + let plan = + LogReadPlan::resolve(&request).unwrap_or_else(|_| panic!("resolve follow request")); + let factory = queued_connection_factory([Box::new(FakeFollowConnection::new( + "host-original", + [Ok(page(1)), Err(SatelleError::host_unreachable("remote"))], + )) as Box]); + let runtime = FakeFollowRuntime::new(None); + let mut stderr = Vec::new(); + + let error = follow_logs( + &plan, + &request, + "remote", + OutputFormat::Json, + &runtime, + &factory, + FollowOutput { + stdout: &mut Vec::new(), + stderr: &mut stderr, + }, + ) + .expect_err("--no-reconnect returns the first transport loss"); + assert_eq!(error.code, ErrorCode::HostUnreachable); + assert!( + String::from_utf8(stderr) + .unwrap() + .contains("last cursor=slc1_0000000000000001") + ); + } + + #[test] + fn the_tenth_stream_interruption_is_terminal() { + let request = request(); + let plan = + LogReadPlan::resolve(&request).unwrap_or_else(|_| panic!("resolve follow request")); + let factory_calls = Arc::new(AtomicU64::new(0)); + let reconnect_factory_calls = Arc::clone(&factory_calls); + let factory: FollowConnectionFactory = Arc::new(move || { + let call = reconnect_factory_calls.fetch_add(1, Ordering::Relaxed); + Ok(Box::new(FakeFollowConnection::new( + "host-original", + [ + Ok(page(call + 1)), + Err(SatelleError::host_unreachable("remote")), + ], + )) as Box) + }); + let runtime = FakeFollowRuntime::new(None); + + let error = follow_logs( + &plan, + &request, + "remote", + OutputFormat::Json, + &runtime, + &factory, + FollowOutput { + stdout: &mut Vec::new(), + stderr: &mut Vec::new(), + }, + ) + .expect_err("the interruption cap is finite"); + assert_eq!(error.code, ErrorCode::LogsFollowReconnectExhausted); + assert_eq!(error.details["stream_interruptions"], 10); + assert_eq!(factory_calls.load(Ordering::Relaxed), 10); + } + + #[test] + fn reconnect_jitter_stays_within_the_bounded_twenty_percent_window() { + let delay = StdDuration::from_secs(1); + assert_eq!(jittered_delay(delay, 0), StdDuration::from_millis(800)); + assert_eq!( + jittered_delay(delay, 4_000), + StdDuration::from_millis(1_200) + ); + assert!(jittered_delay(RECONNECT_MAX_DELAY, 4_000) <= RECONNECT_MAX_DELAY); + } +} diff --git a/crates/satelle-cli/src/main.rs b/crates/satelle-cli/src/main.rs index 0ba0263c..9503060e 100644 --- a/crates/satelle-cli/src/main.rs +++ b/crates/satelle-cli/src/main.rs @@ -31,7 +31,7 @@ use logs::{LogsCommand, show_logs}; use notify::{Config as NotifyConfig, Event, RecommendedWatcher, RecursiveMode, Watcher}; use output::{EventOutput, OutputArgs, OutputFormat, SessionResultSchemaVersion, StatusReport}; #[cfg(any(windows, test))] -use satelle_core::daemon_service::WindowsServiceConfigV3; +use satelle_core::daemon_service::WindowsServiceConfigV4; use satelle_core::daemon_service::{ DaemonServicePlatform, PersistentHostStoragePolicy, PersistentServiceDecision, SetupModeSelection, SetupModeSource, @@ -179,7 +179,7 @@ struct ConfigContext<'a> { resolved: Arc>>, } -#[derive(Debug)] +#[derive(Clone, Debug)] struct SelectedHost { alias: String, config: HostConfig, @@ -628,6 +628,9 @@ struct HostStartCommand { /// Internal resolved Session metadata retention for a persistent launchd service. #[arg(long, hide = true, value_name = "HOURS", requires = "launchd_service")] session_metadata_retention_hours: Option, + /// Internal resolved SQLite Log Entry retention for a persistent launchd service. + #[arg(long, hide = true, value_name = "HOURS", requires = "launchd_service")] + sqlite_log_retention_hours: Option, /// Internal resolved Operator Log File generation count for launchd. #[arg(long, hide = true, value_name = "COUNT", requires = "launchd_service")] operator_log_retained_files: Option, @@ -2141,6 +2144,7 @@ mod history_target_tests { on_demand_idle_timeout_ms: None, setup_ledger_retention_ms: None, session_metadata_retention_hours: None, + sqlite_log_retention_hours: None, operator_log_retained_files: None, service_config: None, output_args: OutputArgs::default(), @@ -2275,6 +2279,8 @@ mod history_target_tests { "3600000", "--session-metadata-retention-hours", "720", + "--sqlite-log-retention-hours", + "1080", "--operator-log-retained-files", "12", ]) @@ -2293,6 +2299,7 @@ mod history_target_tests { assert!(command.launchd_service); assert_eq!(command.setup_ledger_retention_ms, Some(3_600_000)); assert_eq!(command.session_metadata_retention_hours, Some(720)); + assert_eq!(command.sqlite_log_retention_hours, Some(1080)); assert_eq!(command.operator_log_retained_files, Some(12)); validate_host_start_mode(&command).expect("launchd service is a valid closed start mode"); } @@ -6747,6 +6754,7 @@ fn validate_host_start_mode(command: &HostStartCommand) -> Result<(), SatelleErr || command.on_demand_idle_timeout_ms.is_some() || command.setup_ledger_retention_ms.is_none() || command.session_metadata_retention_hours.is_none() + || command.sqlite_log_retention_hours.is_none() || command.operator_log_retained_files.is_none()) { return Err(SatelleError::invalid_usage( @@ -6765,6 +6773,7 @@ fn validate_host_start_mode(command: &HostStartCommand) -> Result<(), SatelleErr || command.on_demand_idle_timeout_ms.is_some() || command.setup_ledger_retention_ms.is_some() || command.session_metadata_retention_hours.is_some() + || command.sqlite_log_retention_hours.is_some() || command.operator_log_retained_files.is_some()) { return Err(SatelleError::invalid_usage( @@ -6912,6 +6921,9 @@ fn start_host_daemon_with( command .session_metadata_retention_hours .expect("launchd Session retention was validated"), + command + .sqlite_log_retention_hours + .expect("launchd SQLite Log retention was validated"), command .operator_log_retained_files .expect("launchd Operator Log retention was validated"), @@ -7190,7 +7202,7 @@ mod daemon_process_notice_tests { } #[cfg(any(windows, test))] -fn read_windows_service_config(path: &Path) -> Result { +fn read_windows_service_config(path: &Path) -> Result { if !path.is_absolute() { return Err(failure(SatelleError::invalid_usage( "Windows Host service config path must be absolute", @@ -7242,9 +7254,9 @@ mod windows_service_config_tests { log_dir: Some(PathBuf::from(r"C:\Users\owner\AppData\Local\Satelle\logs")), sources: BTreeMap::new(), }; - let storage_policy = - PersistentHostStoragePolicy::new(3_600_000, 30 * 24, 12).expect("build storage policy"); - let expected = WindowsServiceConfigV3::new("127.0.0.1:3001", &overrides, storage_policy) + let storage_policy = PersistentHostStoragePolicy::new(3_600_000, 30 * 24, 45 * 24, 12) + .expect("build storage policy"); + let expected = WindowsServiceConfigV4::new("127.0.0.1:3001", &overrides, storage_policy) .expect("build service config"); write_owner_only_config( &path, @@ -7296,7 +7308,7 @@ mod windows_service_config_tests { } #[cfg(windows)] -fn apply_windows_service_environment(config: &WindowsServiceConfigV3) { +fn apply_windows_service_environment(config: &WindowsServiceConfigV4) { const PATH_OVERRIDES: [&str; 5] = [ "SATELLE_HOME", "SATELLE_CONFIG_FILE", @@ -7847,6 +7859,7 @@ mod daemon_tls_watcher_tests { on_demand_idle_timeout_ms: None, setup_ledger_retention_ms: None, session_metadata_retention_hours: None, + sqlite_log_retention_hours: None, operator_log_retained_files: None, service_config: None, output_args: OutputArgs::default(), @@ -8373,6 +8386,7 @@ mod bootstrap_startup_tests { on_demand_idle_timeout_ms: Some(75_000), setup_ledger_retention_ms: None, session_metadata_retention_hours: None, + sqlite_log_retention_hours: None, operator_log_retained_files: None, service_config: None, output_args: OutputArgs::default(), diff --git a/crates/satelle-cli/src/mcp/arguments.rs b/crates/satelle-cli/src/mcp/arguments.rs index a1ca5529..0fc31b45 100644 --- a/crates/satelle-cli/src/mcp/arguments.rs +++ b/crates/satelle-cli/src/mcp/arguments.rs @@ -1,4 +1,5 @@ use super::super::logs::LogReadRequest; +use super::super::output::OutputFormat; use rmcp::ErrorData as McpError; use rmcp::model::JsonObject; use satelle_core::SessionId; @@ -102,6 +103,9 @@ impl LogsInput { after: self.after, source: self.source, level: self.level, + follow: false, + no_reconnect: false, + format: OutputFormat::Human, } } } diff --git a/crates/satelle-cli/src/ssh-bootstrap.rs b/crates/satelle-cli/src/ssh-bootstrap.rs index 4edbd292..d1733f41 100644 --- a/crates/satelle-cli/src/ssh-bootstrap.rs +++ b/crates/satelle-cli/src/ssh-bootstrap.rs @@ -2553,7 +2553,7 @@ impl<'a> PersistentServiceRemote<'a> { pub(super) fn publish_windows_service_config( &mut self, task: &satelle_core::daemon_service::WindowsTaskDefinition, - config: &satelle_core::daemon_service::WindowsServiceConfigV3, + config: &satelle_core::daemon_service::WindowsServiceConfigV4, ) -> Result<(), SshBootstrapError> { self.require_platform(satelle_core::daemon_service::DaemonServicePlatform::Windows)?; let contents = serde_json::to_vec_pretty(config) @@ -3629,7 +3629,7 @@ fn parse_service_path_overrides( output: &[u8], ) -> Result { if target.is_windows() { - let config: satelle_core::daemon_service::WindowsServiceConfigV3 = + let config: satelle_core::daemon_service::WindowsServiceConfigV4 = serde_json::from_slice(output) .map_err(|_| SshBootstrapError::InvalidServiceObservation)?; if config.bind() != "127.0.0.1:3001" { @@ -3691,6 +3691,8 @@ fn parse_launchd_service_definition( const RETENTION_PREFIX: &str = "--setup-ledger-retention-ms"; const SESSION_RETENTION_PREFIX: &str = "--session-metadata-retention-hours"; + const SQLITE_LOG_RETENTION_PREFIX: &str = + "--sqlite-log-retention-hours"; const OPERATOR_LOG_RETENTION_PREFIX: &str = "--operator-log-retained-files"; const ENVIRONMENT_PREFIX: &str = @@ -3723,9 +3725,12 @@ fn parse_launchd_service_definition( let (setup_ledger_retention_ms, body) = body .split_once(SESSION_RETENTION_PREFIX) .ok_or(SshBootstrapError::InvalidServiceObservation)?; - let (session_metadata_retention_hours, body) = - body.split_once(OPERATOR_LOG_RETENTION_PREFIX) - .ok_or(SshBootstrapError::InvalidServiceObservation)?; + let (session_metadata_retention_hours, body) = body + .split_once(SQLITE_LOG_RETENTION_PREFIX) + .ok_or(SshBootstrapError::InvalidServiceObservation)?; + let (sqlite_log_retention_hours, body) = body + .split_once(OPERATOR_LOG_RETENTION_PREFIX) + .ok_or(SshBootstrapError::InvalidServiceObservation)?; let (operator_log_retained_files, body) = body .split_once(ENVIRONMENT_PREFIX) .ok_or(SshBootstrapError::InvalidServiceObservation)?; @@ -3736,6 +3741,9 @@ fn parse_launchd_service_definition( session_metadata_retention_hours .parse::() .map_err(|_| SshBootstrapError::InvalidServiceObservation)?, + sqlite_log_retention_hours + .parse::() + .map_err(|_| SshBootstrapError::InvalidServiceObservation)?, operator_log_retained_files .parse::() .map_err(|_| SshBootstrapError::InvalidServiceObservation)?, @@ -4184,7 +4192,7 @@ impl RemoteUserDirectories { "$config=Get-Content -LiteralPath $path -Raw | ConvertFrom-Json; ", "$task=Get-ScheduledTask -TaskPath '\\Satelle\\' -TaskName {task_name} ", "-ErrorAction SilentlyContinue; ", - "if ($config.schema -cne 'satelle.host-service.v3' -or $null -eq $task) {{ ", + "if ($config.schema -cne 'satelle.host-service.v4' -or $null -eq $task) {{ ", "[Console]::Out.Write('absent'); exit 0 }}; ", "[xml]$xml=Export-ScheduledTask -TaskPath '\\Satelle\\' -TaskName {task_name}; ", "$root=$xml.Task; ", @@ -4274,11 +4282,11 @@ impl RemoteUserDirectories { .ok_or(SshBootstrapError::InvalidServiceObservation)?; let config = config.strip_suffix('\r').unwrap_or(config); let Ok(config) = serde_json::from_str::< - satelle_core::daemon_service::WindowsServiceConfigV3, + satelle_core::daemon_service::WindowsServiceConfigV4, >(config) else { return Ok(None); }; - let expected = satelle_core::daemon_service::WindowsServiceConfigV3::new( + let expected = satelle_core::daemon_service::WindowsServiceConfigV4::new( "127.0.0.1:3001", expected_path_overrides, expected_storage_policy, @@ -5658,6 +5666,7 @@ mod tests { satelle_core::daemon_service::PersistentHostStoragePolicy::new( satelle_core::daemon_service::DEFAULT_SETUP_LEDGER_RETENTION_MS, satelle_core::DEFAULT_SESSION_METADATA_RETENTION_HOURS, + satelle_core::DEFAULT_SQLITE_LOG_RETENTION_HOURS, satelle_core::DEFAULT_OPERATOR_LOG_RETAINED_FILES, ) .expect("valid default persistent storage policy") @@ -5931,6 +5940,7 @@ mod tests { satelle_core::daemon_service::PersistentHostStoragePolicy::new( 3_600_000, satelle_core::DEFAULT_SESSION_METADATA_RETENTION_HOURS, + satelle_core::DEFAULT_SQLITE_LOG_RETENTION_HOURS, satelle_core::DEFAULT_OPERATOR_LOG_RETAINED_FILES, ) .unwrap(), @@ -6010,11 +6020,12 @@ mod tests { "#!/bin/sh\nprintf '%s\\n' \"$@\" > {}\n", "printf 'managed\\r\\n", "aaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaa\\r\\n", - "{{\"schema\":\"satelle.host-service.v3\",", + "{{\"schema\":\"satelle.host-service.v4\",", "\"daemon_arguments\":[\"host\",\"start\",\"--foreground\",\"--bind\",", "\"127.0.0.1:3001\"],\"environment\":{{}},", "\"storage_policy\":{{\"setup_ledger_retention_ms\":2592000000,", "\"session_metadata_retention_hours\":168,", + "\"sqlite_log_retention_hours\":168,", "\"operator_log_retained_files\":5}}}}\\r\\n", "C:\\\\Users\\\\operator\\\\AppData\\\\Local\\\\Satelle\\\\host\\\\v0.1.0\\\\", "win32-x64-msvc\\\\satelle-", @@ -6056,6 +6067,7 @@ mod tests { satelle_core::daemon_service::PersistentHostStoragePolicy::new( 3_600_000, satelle_core::DEFAULT_SESSION_METADATA_RETENTION_HOURS, + satelle_core::DEFAULT_SQLITE_LOG_RETENTION_HOURS, satelle_core::DEFAULT_OPERATOR_LOG_RETAINED_FILES, ) .unwrap(), @@ -6117,11 +6129,12 @@ mod tests { concat!( "#!/bin/sh\nprintf 'managed\\r\\n", "aaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaa\\r\\n", - "{\"schema\":\"satelle.host-service.v3\",", + "{\"schema\":\"satelle.host-service.v4\",", "\"daemon_arguments\":[\"host\",\"start\",\"--foreground\",\"--bind\",", "\"127.0.0.1:3002\"],\"environment\":{},", "\"storage_policy\":{\"setup_ledger_retention_ms\":2592000000,", "\"session_metadata_retention_hours\":168,", + "\"sqlite_log_retention_hours\":168,", "\"operator_log_retained_files\":5}}\\r\\n", "C:\\\\Users\\\\operator\\\\AppData\\\\Local\\\\Satelle\\\\host\\\\v0.1.0\\\\", "win32-x64-msvc\\\\satelle-", @@ -6148,12 +6161,13 @@ mod tests { concat!( "#!/bin/sh\nprintf 'managed\\r\\n", "aaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaa\\r\\n", - "{\"schema\":\"satelle.host-service.v3\",", + "{\"schema\":\"satelle.host-service.v4\",", "\"daemon_arguments\":[\"host\",\"start\",\"--foreground\",\"--bind\",", "\"127.0.0.1:3001\"],", "\"environment\":{\"SATELLE_HOME\":\"C:\\\\\\\\Drifted\"},", "\"storage_policy\":{\"setup_ledger_retention_ms\":2592000000,", "\"session_metadata_retention_hours\":168,", + "\"sqlite_log_retention_hours\":168,", "\"operator_log_retained_files\":5}}\\r\\n", "C:\\\\Users\\\\operator\\\\AppData\\\\Local\\\\Satelle\\\\host\\\\v0.1.0\\\\", "win32-x64-msvc\\\\satelle-", @@ -6593,12 +6607,13 @@ mod tests { #[test] fn persistent_service_path_override_parsers_are_closed() { let windows = br#"{ - "schema":"satelle.host-service.v3", + "schema":"satelle.host-service.v4", "daemon_arguments":["host","start","--foreground","--bind","127.0.0.1:3001"], "environment":{"SATELLE_STATE_DIR":"C:\\Users\\operator\\AppData\\Local\\Satelle\\state"}, "storage_policy":{ "setup_ledger_retention_ms":3600000, "session_metadata_retention_hours":168, + "sqlite_log_retention_hours":168, "operator_log_retained_files":5 } }"#; @@ -6611,7 +6626,7 @@ mod tests { assert!( parse_service_path_overrides( RemoteTarget::WindowsX64Msvc, - br#"{"schema":"satelle.host-service.v3","daemon_arguments":["host","start","--foreground","--bind","127.0.0.1:3001"],"environment":{"OTHER":"C:\\safe"},"storage_policy":{"setup_ledger_retention_ms":3600000,"session_metadata_retention_hours":168,"operator_log_retained_files":5}}"#, + br#"{"schema":"satelle.host-service.v4","daemon_arguments":["host","start","--foreground","--bind","127.0.0.1:3001"],"environment":{"OTHER":"C:\\safe"},"storage_policy":{"setup_ledger_retention_ms":3600000,"session_metadata_retention_hours":168,"sqlite_log_retention_hours":168,"operator_log_retained_files":5}}"#, ) .is_err() ); @@ -6630,6 +6645,7 @@ mod tests { satelle_core::daemon_service::PersistentHostStoragePolicy::new( 3_600_000, satelle_core::DEFAULT_SESSION_METADATA_RETENTION_HOURS, + satelle_core::DEFAULT_SQLITE_LOG_RETENTION_HOURS, satelle_core::DEFAULT_OPERATOR_LOG_RETAINED_FILES, ) .unwrap(), @@ -7931,6 +7947,7 @@ mod tests { provider_smoke_failure_cache_ttl: None, setup_ledger_retention: None, session_metadata_retention: None, + sqlite_log_retention: None, operator_log_retained_files: None, daemon_idle_timeout: None, desktop_user: None, diff --git a/crates/satelle-cli/src/tailscale-serve.rs b/crates/satelle-cli/src/tailscale-serve.rs index fe524af0..a251d114 100644 --- a/crates/satelle-cli/src/tailscale-serve.rs +++ b/crates/satelle-cli/src/tailscale-serve.rs @@ -973,6 +973,7 @@ mod tests { daemon_idle_timeout: None, setup_ledger_retention: None, session_metadata_retention: None, + sqlite_log_retention: None, operator_log_retained_files: None, desktop_user: None, desktop_session_preference: None, diff --git a/crates/satelle-cli/src/tailscale.rs b/crates/satelle-cli/src/tailscale.rs index dc343fce..eb6edec6 100644 --- a/crates/satelle-cli/src/tailscale.rs +++ b/crates/satelle-cli/src/tailscale.rs @@ -812,6 +812,7 @@ mod tests { daemon_idle_timeout: None, setup_ledger_retention: None, session_metadata_retention: None, + sqlite_log_retention: None, operator_log_retained_files: None, desktop_user: None, desktop_session_preference: None, diff --git a/crates/satelle-cli/src/transport-tests.rs b/crates/satelle-cli/src/transport-tests.rs index 5595cbb0..b4134eca 100644 --- a/crates/satelle-cli/src/transport-tests.rs +++ b/crates/satelle-cli/src/transport-tests.rs @@ -4440,13 +4440,14 @@ impl DirectFixture { .expect("construct event runtime"); Self { service, - host_identity, + host_identity: host_identity.clone(), address, server: Some(server), server_runtime, transport: Some(DirectTransport { alias: "direct-test".to_string(), mode: "direct", + host_identity: host_identity.as_str().to_owned(), client: Arc::new(client), event_client, event_runtime, @@ -5768,6 +5769,55 @@ fn direct_logs_reject_contradictory_cursor_expiry_details() { ); } +#[test] +fn direct_logs_classify_a_dropped_response_body_as_transient_reachability_loss() { + let listener = TcpListener::bind("127.0.0.1:0").expect("bind partial logs response fixture"); + let address = listener + .local_addr() + .expect("read partial response address"); + let server = thread::spawn(move || { + let (mut stream, _) = listener.accept().expect("accept logs client"); + let mut request = Vec::new(); + let mut chunk = [0_u8; 1024]; + while !request.windows(4).any(|bytes| bytes == b"\r\n\r\n") { + let read = stream.read(&mut chunk).expect("read logs request"); + assert_ne!(read, 0, "logs request ended before its headers"); + request.extend_from_slice(&chunk[..read]); + } + let request = String::from_utf8(request).expect("logs request headers should be UTF-8"); + let request_id = request + .lines() + .find_map(|line| { + let (name, value) = line.split_once(':')?; + name.eq_ignore_ascii_case("satelle-request-id") + .then(|| value.trim()) + }) + .expect("logs request must carry a request ID"); + let partial_body = r#"{"schema_version":"satelle.logs.page.v1""#; + write!( + stream, + "HTTP/1.1 200 OK\r\nSatelle-Request-Id: {request_id}\r\nSatelle-Host-Identity: host-direct-test\r\nContent-Type: application/json\r\nContent-Length: {}\r\nConnection: close\r\n\r\n{partial_body}", + partial_body.len() + 100 + ) + .expect("write partial logs response"); + stream.flush().expect("flush partial logs response"); + }); + let client = DaemonClient::loopback( + address, + ApiBearerToken::generate().expect("generate logs fixture token"), + "host-direct-test", + ) + .expect("construct logs fixture client"); + + let daemon_error = client + .logs(&LogPageQuery::tail(1).expect("valid logs query")) + .expect_err("the partial response body must fail"); + let error = direct_logs_error("direct-test", daemon_error); + server.join().expect("join partial logs response fixture"); + + assert_eq!(error.code, ErrorCode::HostUnreachable); +} + #[test] fn direct_attached_run_and_steer_follow_committed_host_events() { let fixture = DirectFixture::start(); @@ -6168,6 +6218,58 @@ fn direct_session_resource_reads_preserve_session_not_found_identity() { assert!(mapped.message.contains(session_id.as_str())); } +#[test] +fn direct_session_resource_reads_classify_a_dropped_body_as_reachability_loss() { + let listener = TcpListener::bind("127.0.0.1:0").expect("bind partial session response fixture"); + let address = listener + .local_addr() + .expect("read partial session response address"); + let server = thread::spawn(move || { + let (mut stream, _) = listener.accept().expect("accept session client"); + let mut request = Vec::new(); + let mut chunk = [0_u8; 1024]; + while !request.windows(4).any(|bytes| bytes == b"\r\n\r\n") { + let read = stream.read(&mut chunk).expect("read session request"); + assert_ne!(read, 0, "session request ended before its headers"); + request.extend_from_slice(&chunk[..read]); + } + let request = String::from_utf8(request).expect("session request headers should be UTF-8"); + let request_id = request + .lines() + .find_map(|line| { + let (name, value) = line.split_once(':')?; + name.eq_ignore_ascii_case("satelle-request-id") + .then(|| value.trim()) + }) + .expect("session request must carry a request ID"); + let partial_body = r#"{"schema_version":"satelle.session.read.v1""#; + write!( + stream, + "HTTP/1.1 200 OK\r\nSatelle-Request-Id: {request_id}\r\nSatelle-Host-Identity: host-direct-test\r\nContent-Type: application/json\r\nContent-Length: {}\r\nConnection: close\r\n\r\n{partial_body}", + partial_body.len() + 100 + ) + .expect("write partial session response"); + stream.flush().expect("flush partial session response"); + }); + let client = DaemonClient::loopback( + address, + ApiBearerToken::generate().expect("generate session fixture token"), + "host-direct-test", + ) + .expect("construct session fixture client"); + let session_id = SessionId::new(); + + let daemon_error = client + .read_session(&session_id) + .expect_err("the partial session response body must fail"); + let error = direct_session_resource_error("direct-test", &session_id, daemon_error); + server + .join() + .expect("join partial session response fixture"); + + assert_eq!(error.code, ErrorCode::HostUnreachable); +} + #[test] fn stop_not_confirmed_api_details_are_validated_and_preserved() { let session_id = SessionId::new(); diff --git a/crates/satelle-cli/src/transport.rs b/crates/satelle-cli/src/transport.rs index 7630eda7..8e44abbd 100644 --- a/crates/satelle-cli/src/transport.rs +++ b/crates/satelle-cli/src/transport.rs @@ -1,7 +1,7 @@ use crate::{CliFailure, SelectedHost, bootstrap_lock, failure, on_demand_idle_timeout}; use satelle_core::daemon_service::{ DaemonArtifactPlan, DaemonServicePlan, DaemonServicePlatform, PersistentHostStoragePolicy, - PersistentServiceDecision, SetupModeSelection, WindowsServiceConfigV3, WindowsTaskDefinition, + PersistentServiceDecision, SetupModeSelection, WindowsServiceConfigV4, WindowsTaskDefinition, }; use satelle_core::doctor::DoctorScopeSelection; use satelle_core::session::{HostIdentityRef, PublicSession, TurnAdmissionFailure}; @@ -265,7 +265,9 @@ fn setup_provider_intent( /// The command surface is intentionally exhaustive. A new transport operation /// must be implemented or explicitly rejected by every backend. -pub(crate) trait TransportClient { +pub(crate) trait TransportClient: Send { + fn log_target_identity(&self) -> Result; + fn supported_image_media_types(&self) -> Result, SatelleError> { Ok(Vec::new()) } @@ -657,6 +659,12 @@ fn interrupted_admission_race_error(alias: &str) -> SatelleError { } impl TransportClient for LocalTransport { + fn log_target_identity(&self) -> Result { + self.service + .daemon_runtime_status() + .map(|status| status.host_identity().to_string()) + } + fn supported_image_media_types(&self) -> Result, SatelleError> { let capabilities = self.service.daemon_runtime_capabilities()?; Ok(if capabilities.image_attachments() { @@ -1191,6 +1199,7 @@ fn local_turn_intent(request: &TurnRequest) -> Result, event_client: DaemonEventClient, event_runtime: tokio::runtime::Runtime, @@ -1340,7 +1349,7 @@ fn coordinate_persistent_setup( enum PreparedPersistentService { Windows { task: Box, - config: Box, + config: Box, }, Launchd(ssh_bootstrap::LaunchdServiceDefinition), } @@ -2464,7 +2473,7 @@ impl SshSetupTransport { artifact, ) .map_err(|error| map_ssh_daemon_bootstrap_error(&self.alias, error))?; - let config = WindowsServiceConfigV3::new( + let config = WindowsServiceConfigV4::new( "127.0.0.1:3001", daemon_path_overrides, storage_policy, @@ -6748,6 +6757,10 @@ fn setup_token_lock_error(path: &Path, error: impl std::fmt::Display) -> Satelle } impl TransportClient for SshSetupTransport { + fn log_target_identity(&self) -> Result { + Ok(self.binding.expected_host_identity().to_string()) + } + fn setup( &self, dry_run: bool, @@ -7013,6 +7026,10 @@ impl TransportClient for SshSetupTransport { } impl TransportClient for DirectTransport { + fn log_target_identity(&self) -> Result { + Ok(self.host_identity.clone()) + } + fn supported_image_media_types(&self) -> Result, SatelleError> { Ok(self .client @@ -7321,6 +7338,7 @@ fn direct_transport(host: &SelectedHost) -> Result SatelleError { - if matches!( - &error, - DaemonClientError::Api { error, .. } if error.code() == ApiErrorCode::SessionNotFound - ) { - SatelleError::session_not_found(session_id) - } else { - direct_transport_error(host, error) + match error { + DaemonClientError::Api { error, .. } if error.code() == ApiErrorCode::SessionNotFound => { + SatelleError::session_not_found(session_id) + } + DaemonClientError::InvalidResponse(error) if response_connection_lost(&error) => { + SatelleError::host_unreachable(host) + } + error => direct_transport_error(host, error), } } @@ -8193,10 +8213,42 @@ fn direct_logs_error(host: &str, error: DaemonClientError) -> SatelleError { DaemonClientError::Api { error, .. } if error.code() == ApiErrorCode::InvalidRequest => { SatelleError::invalid_usage("the Host rejected the logs query") } + DaemonClientError::InvalidResponse(error) if response_connection_lost(&error) => { + SatelleError::host_unreachable(host) + } error => direct_transport_error(host, error), } } +fn response_connection_lost(error: &reqwest::Error) -> bool { + if error.is_body() || error.is_timeout() { + return true; + } + + // reqwest classifies an incomplete declared body as a decode error, but + // its source chain retains the connection-level I/O failure. Keep JSON + // and schema decode failures terminal while allowing body loss to reconnect. + let mut source = std::error::Error::source(error); + while let Some(current) = source { + if current + .downcast_ref::() + .is_some_and(|error| { + matches!( + error.kind(), + std::io::ErrorKind::UnexpectedEof + | std::io::ErrorKind::ConnectionReset + | std::io::ErrorKind::ConnectionAborted + | std::io::ErrorKind::BrokenPipe + ) + }) + { + return true; + } + source = current.source(); + } + false +} + // Cursor expiry is the one API failure whose details are required to resume // safely. Validate that recovery boundary at the transport boundary instead // of collapsing it into the generic remote API error used for other codes. diff --git a/crates/satelle-cli/tests/cli.rs b/crates/satelle-cli/tests/cli.rs index cd3d1509..a208c3df 100644 --- a/crates/satelle-cli/tests/cli.rs +++ b/crates/satelle-cli/tests/cli.rs @@ -25,7 +25,7 @@ use std::process::Stdio; use std::sync::mpsc::{self, Receiver}; #[cfg(target_os = "linux")] use std::thread::{self, JoinHandle}; -#[cfg(target_os = "linux")] +#[cfg(unix)] use std::time::{Duration, Instant}; #[path = "support/test-file.rs"] @@ -1118,7 +1118,7 @@ fn corrupt_sqlite_fails_closed_without_mutating_or_leaking_state() { let output = satelle() .env("SATELLE_STATE_DIR", state.path()) - .args(["status", &session_id, "--json"]) + .args(["status", &session_id, "--host", "local-demo", "--json"]) .assert() .failure() .get_output() @@ -2142,16 +2142,7 @@ fn logs_json_applies_tail_session_source_level_and_since_on_the_host() { let output = satelle() .env("SATELLE_STATE_DIR", state.path()) .env("SATELLE_CACHE_DIR", &cache) - .args([ - "logs", - "--session", - &session, - "--source", - "host_daemon", - "--tail", - "2", - "--json", - ]) + .args(["logs", "--session", &session, "--tail", "2", "--json"]) .assert() .success() .get_output() @@ -2159,12 +2150,16 @@ fn logs_json_applies_tail_session_source_level_and_since_on_the_host() { assert!(output.stderr.is_empty()); let entries = parse_json_lines(&output.stdout); assert_eq!(entries.len(), 2); - assert!(entries.iter().all(|entry| { - entry["source"] == "host_daemon" && entry["subject"]["session_id"] == session - })); + assert!( + entries + .iter() + .all(|entry| entry["subject"]["session_id"] == session) + ); assert_eq!(entries[0]["event"], "turn_state_committed"); + assert_eq!(entries[0]["source"], "codex_adapter"); assert_eq!(entries[0]["severity"], "info"); assert_eq!(entries[1]["event"], "stop_confirmed"); + assert_eq!(entries[1]["source"], "host_daemon"); assert_eq!(entries[1]["severity"], "warn"); let output = satelle() @@ -2340,6 +2335,103 @@ fn logs_accepts_only_canonical_sources_and_severities() { } } +#[test] +fn logs_help_exposes_follow_and_reconnect_controls() { + satelle() + .args(["logs", "--help"]) + .assert() + .success() + .stdout(predicate::str::contains("-f, --follow")) + .stdout(predicate::str::contains("--no-reconnect")); +} + +#[cfg(unix)] +#[test] +fn logs_follow_waits_on_an_empty_page_and_ctrl_c_exits_130() { + let state = state_dir(); + let (session, cache) = completed_log_session(&state); + let mut command = std::process::Command::new(assert_cmd::cargo::cargo_bin!("satelle")); + for name in [ + "SATELLE_HOME", + "SATELLE_CONFIG_FILE", + "SATELLE_STATE_DIR", + "SATELLE_CACHE_DIR", + "SATELLE_LOG_DIR", + "SATELLE_HOST", + "SATELLE_PROFILE", + ] { + command.env_remove(name); + } + let mut child = command + .env("SATELLE_STATE_DIR", state.path()) + .env("SATELLE_CACHE_DIR", &cache) + .args([ + "logs", + "--host", + "local-demo", + "--session", + &session, + "--since", + "2099-01-01T00:00:00Z", + "--json", + "--follow", + ]) + .stdout(Stdio::piped()) + .stderr(Stdio::piped()) + .spawn() + .expect("spawn empty Log follow"); + + // An empty finite page is not end-of-stream in follow mode. Give the + // process several poll intervals to prove that it remains attached. + let attached_deadline = Instant::now() + Duration::from_secs(1); + while Instant::now() < attached_deadline { + if child.try_wait().expect("poll empty Log follow").is_some() { + let output = child + .wait_with_output() + .expect("collect early Log follow failure"); + panic!( + "empty Log follow exited before interruption: stdout={} stderr={}", + String::from_utf8_lossy(&output.stdout), + String::from_utf8_lossy(&output.stderr), + ); + } + std::thread::sleep(Duration::from_millis(10)); + } + + let pid = rustix::process::Pid::from_raw(child.id() as i32).expect("child PID is nonzero"); + rustix::process::kill_process(pid, rustix::process::Signal::INT) + .expect("send SIGINT to empty Log follow"); + let output = child + .wait_with_output() + .expect("reap interrupted empty Log follow"); + assert_eq!(output.status.code(), Some(130)); + assert!(output.stdout.is_empty()); + let error = parse_json_output(&output.stderr); + assert_eq!(error["code"], "interrupted"); +} + +#[test] +fn logs_reports_a_typed_error_when_no_target_can_be_resolved() { + let state = state_dir(); + let unknown_session = SessionId::new().to_string(); + let output = satelle() + .env("SATELLE_STATE_DIR", state.path()) + .env("SATELLE_CACHE_DIR", state.path().join("cache")) + .args(["logs", "--session", &unknown_session, "--json"]) + .assert() + .code(64) + .get_output() + .clone(); + + assert!(output.stdout.is_empty()); + let error = parse_json_output(&output.stderr); + assert_eq!(error["code"], "logs-target-required"); + assert_eq!( + error["suggested_commands"], + serde_json::json!(["pass --host or --session "]) + ); +} + #[test] fn production_setup_dry_run_reports_plan_without_mutating_declared_paths() { let sandbox = state_dir(); diff --git a/crates/satelle-cli/tests/report-schema-contract.rs b/crates/satelle-cli/tests/report-schema-contract.rs index 80672c64..39ce3bd8 100644 --- a/crates/satelle-cli/tests/report-schema-contract.rs +++ b/crates/satelle-cli/tests/report-schema-contract.rs @@ -560,7 +560,14 @@ fn logs_json_lines_use_the_exact_entry_v1_contract() { let output = satelle() .env("SATELLE_STATE_DIR", state.path()) - .args(["logs", "--session", session, "--json"]) + .args([ + "logs", + "--host", + "local-demo", + "--session", + session, + "--json", + ]) .assert() .success() .get_output() @@ -572,6 +579,7 @@ fn logs_json_lines_use_the_exact_entry_v1_contract() { let expected_fields = [ "cursor", "event", + "host_identity", "message", "redacted", "schema_version", diff --git a/crates/satelle-cli/tests/session-host-routing.rs b/crates/satelle-cli/tests/session-host-routing.rs index 226b8239..c745baa3 100644 --- a/crates/satelle-cli/tests/session-host-routing.rs +++ b/crates/satelle-cli/tests/session-host-routing.rs @@ -269,6 +269,24 @@ api_token = {{ kind = "file", path = {token_path} }} .unwrap() .contains("exactly one configured Host") ); + + let ambiguous_logs = satelle() + .env("SATELLE_CONFIG_FILE", &user_config) + .env("SATELLE_STATE_DIR", state.path()) + .env("SATELLE_CACHE_DIR", &cache_root) + .args(["logs", "--session", &session, "--json"]) + .assert() + .failure() + .get_output() + .clone(); + let ambiguous_logs_error = parse_json_output(&ambiguous_logs.stderr); + assert_eq!(ambiguous_logs_error["code"], "invalid-usage"); + assert!( + ambiguous_logs_error["message"] + .as_str() + .unwrap() + .contains("exactly one configured Host") + ); } #[test] diff --git a/crates/satelle-core/src/daemon-service.rs b/crates/satelle-core/src/daemon-service.rs index c3c61d35..3fa9b0b2 100644 --- a/crates/satelle-core/src/daemon-service.rs +++ b/crates/satelle-core/src/daemon-service.rs @@ -7,7 +7,7 @@ use std::net::SocketAddr; use std::path::{Path, PathBuf}; use thiserror::Error; -pub const WINDOWS_SERVICE_CONFIG_SCHEMA: &str = "satelle.host-service.v3"; +pub const WINDOWS_SERVICE_CONFIG_SCHEMA: &str = "satelle.host-service.v4"; pub const DEFAULT_SETUP_LEDGER_RETENTION_MS: u64 = 30 * 24 * 60 * 60 * 1_000; #[derive(Clone, Copy, Debug, Serialize, Deserialize, PartialEq, Eq)] @@ -482,6 +482,7 @@ pub fn render_launchd_user_plist( "--bind{}", "--setup-ledger-retention-ms{}", "--session-metadata-retention-hours{}", + "--sqlite-log-retention-hours{}", "--operator-log-retained-files{}", "EnvironmentVariables{}", "RunAtLoadKeepAlive", @@ -491,6 +492,7 @@ pub fn render_launchd_user_plist( xml_escape(&bind.to_string()), storage_policy.setup_ledger_retention_ms, storage_policy.session_metadata_retention_hours, + storage_policy.sqlite_log_retention_hours, storage_policy.operator_log_retained_files, environment )) @@ -532,6 +534,7 @@ pub enum WindowsServiceDefinitionError { pub struct PersistentHostStoragePolicy { setup_ledger_retention_ms: u64, session_metadata_retention_hours: u64, + sqlite_log_retention_hours: u64, operator_log_retained_files: usize, } @@ -546,6 +549,12 @@ impl PersistentHostStoragePolicy { crate::DEFAULT_SESSION_METADATA_RETENTION_HOURS, |retention| retention.hours(), ), + sqlite_log_retention_hours: config + .sqlite_log_retention + .as_ref() + .map_or(crate::DEFAULT_SQLITE_LOG_RETENTION_HOURS, |retention| { + retention.hours() + }), operator_log_retained_files: config .operator_log_retained_files .unwrap_or(crate::DEFAULT_OPERATOR_LOG_RETAINED_FILES), @@ -555,11 +564,13 @@ impl PersistentHostStoragePolicy { pub fn new( setup_ledger_retention_ms: u64, session_metadata_retention_hours: u64, + sqlite_log_retention_hours: u64, operator_log_retained_files: usize, ) -> Result { let policy = Self { setup_ledger_retention_ms, session_metadata_retention_hours, + sqlite_log_retention_hours, operator_log_retained_files, }; policy @@ -580,6 +591,10 @@ impl PersistentHostStoragePolicy { self.operator_log_retained_files } + pub const fn sqlite_log_retention_hours(self) -> u64 { + self.sqlite_log_retention_hours + } + fn validate(self) -> Result<(), &'static str> { validate_setup_ledger_retention_ms(self.setup_ledger_retention_ms)?; if !(crate::MIN_SESSION_METADATA_RETENTION_HOURS @@ -588,6 +603,12 @@ impl PersistentHostStoragePolicy { { return Err("invalid session metadata retention"); } + if !(crate::MIN_SESSION_METADATA_RETENTION_HOURS + ..=crate::MAX_SESSION_METADATA_RETENTION_HOURS) + .contains(&self.sqlite_log_retention_hours) + { + return Err("invalid SQLite Log Entry retention"); + } if !(1..=crate::MAX_OPERATOR_LOG_RETAINED_FILES).contains(&self.operator_log_retained_files) { return Err("invalid operator log retention"); @@ -597,14 +618,14 @@ impl PersistentHostStoragePolicy { } #[derive(Clone, Debug, Serialize, PartialEq, Eq)] -pub struct WindowsServiceConfigV3 { +pub struct WindowsServiceConfigV4 { schema: String, daemon_arguments: Vec, environment: BTreeMap, storage_policy: PersistentHostStoragePolicy, } -impl WindowsServiceConfigV3 { +impl WindowsServiceConfigV4 { pub fn new( bind: &str, overrides: &DaemonPathOverrides, @@ -720,7 +741,7 @@ impl WindowsServiceConfigV3 { } } -impl<'de> Deserialize<'de> for WindowsServiceConfigV3 { +impl<'de> Deserialize<'de> for WindowsServiceConfigV4 { fn deserialize(deserializer: D) -> Result where D: serde::Deserializer<'de>, @@ -978,7 +999,7 @@ mod tests { } fn storage_policy() -> PersistentHostStoragePolicy { - PersistentHostStoragePolicy::new(3_600_000, 30 * 24, 12) + PersistentHostStoragePolicy::new(3_600_000, 30 * 24, 45 * 24, 12) .expect("valid persistent storage policy") } @@ -1036,7 +1057,7 @@ mod tests { log_dir: Some(PathBuf::from(r"C:\Satelle\logs")), ..DaemonPathOverrides::default() }; - let config = WindowsServiceConfigV3::new("127.0.0.1:3001", &overrides, storage_policy()) + let config = WindowsServiceConfigV4::new("127.0.0.1:3001", &overrides, storage_policy()) .expect("valid service config"); assert_eq!(config.schema(), WINDOWS_SERVICE_CONFIG_SCHEMA); assert_eq!( @@ -1081,7 +1102,7 @@ mod tests { "environment": {}, "storage_policy": storage_policy() }); - assert!(serde_json::from_value::(invalid_arguments).is_err()); + assert!(serde_json::from_value::(invalid_arguments).is_err()); let invalid_environment = serde_json::json!({ "schema": WINDOWS_SERVICE_CONFIG_SCHEMA, @@ -1089,7 +1110,7 @@ mod tests { "environment": {"PATH": "C:\\attacker"}, "storage_policy": storage_policy() }); - assert!(serde_json::from_value::(invalid_environment).is_err()); + assert!(serde_json::from_value::(invalid_environment).is_err()); let invalid_retention = serde_json::json!({ "schema": WINDOWS_SERVICE_CONFIG_SCHEMA, @@ -1098,10 +1119,11 @@ mod tests { "storage_policy": { "setup_ledger_retention_ms": 0, "session_metadata_retention_hours": 720, + "sqlite_log_retention_hours": 1080, "operator_log_retained_files": 12 } }); - assert!(serde_json::from_value::(invalid_retention).is_err()); + assert!(serde_json::from_value::(invalid_retention).is_err()); } #[test] @@ -1359,7 +1381,7 @@ mod tests { state_dir: Some(PathBuf::from(r"C:\Users\operator\Satelle\state")), ..DaemonPathOverrides::default() }; - let config = WindowsServiceConfigV3::new("127.0.0.1:3001", &overrides, storage_policy()) + let config = WindowsServiceConfigV4::new("127.0.0.1:3001", &overrides, storage_policy()) .expect("valid Windows service config"); assert_eq!(config.path_overrides(), overrides); diff --git a/crates/satelle-core/src/lib.rs b/crates/satelle-core/src/lib.rs index 1f7dfcc0..6b0cdfd3 100644 --- a/crates/satelle-core/src/lib.rs +++ b/crates/satelle-core/src/lib.rs @@ -114,6 +114,7 @@ impl SatelleConfig { daemon_idle_timeout: None, setup_ledger_retention: None, session_metadata_retention: None, + sqlite_log_retention: None, operator_log_retained_files: None, desktop_user: None, desktop_session_preference: None, @@ -300,6 +301,7 @@ pub struct HostConfig { pub daemon_idle_timeout: Option, pub setup_ledger_retention: Option, pub session_metadata_retention: Option, + pub sqlite_log_retention: Option, pub operator_log_retained_files: Option, pub desktop_user: Option, pub desktop_session_preference: Option, @@ -1646,6 +1648,7 @@ impl ExplicitDuration { } pub const DEFAULT_SESSION_METADATA_RETENTION_HOURS: u64 = 7 * 24; +pub const DEFAULT_SQLITE_LOG_RETENTION_HOURS: u64 = 7 * 24; pub const MIN_SESSION_METADATA_RETENTION_HOURS: u64 = 7 * 24; pub const MAX_SESSION_METADATA_RETENTION_HOURS: u64 = 365 * 24; pub const DEFAULT_OPERATOR_LOG_RETAINED_FILES: usize = 5; @@ -3234,6 +3237,7 @@ fn reject_interpolation(path: &Path, value: &toml::Value) -> Result<(), SatelleE "daemon_idle_timeout", "setup_ledger_retention", "session_metadata_retention", + "sqlite_log_retention", ] { collect_interpolation_for_value( &format!("{host_path}.{key}"), @@ -3506,6 +3510,15 @@ fn reject_timeout_config_errors(path: &Path, value: &toml::Value) -> Result<(), return Err(SatelleError::duration_unit_required(path, &retention_path)); } } + if let Some(value) = host_table.get("sqlite_log_retention") { + let retention_path = format!("{host_path}.sqlite_log_retention"); + let Some(value) = value.as_str() else { + return Err(SatelleError::duration_unit_required(path, &retention_path)); + }; + if RetentionDuration::parse(value).is_none() { + return Err(SatelleError::duration_unit_required(path, &retention_path)); + } + } if let Some(value) = host_table.get("operator_log_retained_files") { let retained_files = value .as_integer() @@ -3822,6 +3835,7 @@ fn reject_unknown_user_config_keys(path: &Path, value: &toml::Value) -> Result<( "daemon_idle_timeout", "setup_ledger_retention", "session_metadata_retention", + "sqlite_log_retention", "operator_log_retained_files", "desktop_user", "desktop_session_preference", @@ -4043,7 +4057,7 @@ mod session_metadata_retention_tests { fn host_retention_and_operator_log_count_validate_at_config_boundary() { let parsed = parse_user_config( Path::new("/test/config.toml"), - "[hosts.local-demo]\ntransport = \"local\"\nadapter = \"codex\"\nsession_metadata_retention = \"30d\"\noperator_log_retained_files = 12\n", + "[hosts.local-demo]\ntransport = \"local\"\nadapter = \"codex\"\nsession_metadata_retention = \"30d\"\nsqlite_log_retention = \"45d\"\noperator_log_retained_files = 12\n", ) .expect("parse bounded retention policy"); let host = parsed.config.hosts.get(LOCAL_DEMO_HOST).unwrap(); @@ -4052,9 +4066,11 @@ mod session_metadata_retention_tests { 30 * 24 ); assert_eq!(host.operator_log_retained_files, Some(12)); + assert_eq!(host.sqlite_log_retention.as_ref().unwrap().hours(), 45 * 24); for field in [ "session_metadata_retention = \"60m\"", + "sqlite_log_retention = \"366d\"", "operator_log_retained_files = 0", "operator_log_retained_files = 101", ] { @@ -4271,6 +4287,9 @@ pub enum ErrorCode { LogTailLimitExceeded, LogPositionConflict, LogsCursorExpired, + LogsTargetRequired, + LogsFollowIdentityChanged, + LogsFollowReconnectExhausted, CapacityExceeded, ConcurrencyLimitExceeded, ConcurrencyWithoutRemoteUpdate, @@ -4409,6 +4428,9 @@ impl ErrorCode { Self::LogTailLimitExceeded => "log-tail-limit-exceeded", Self::LogPositionConflict => "log-position-conflict", Self::LogsCursorExpired => "logs-cursor-expired", + Self::LogsTargetRequired => "logs-target-required", + Self::LogsFollowIdentityChanged => "logs-follow-identity-changed", + Self::LogsFollowReconnectExhausted => "logs-follow-reconnect-exhausted", Self::CapacityExceeded => "capacity-exceeded", Self::ConcurrencyLimitExceeded => "concurrency-limit-exceeded", Self::ConcurrencyWithoutRemoteUpdate => "concurrency-without-remote-update", @@ -4458,6 +4480,7 @@ impl ErrorCode { | Self::OutputModeConflict | Self::LogTailLimitExceeded | Self::LogPositionConflict + | Self::LogsTargetRequired | Self::ConcurrencyLimitExceeded | Self::ConcurrencyWithoutRemoteUpdate | Self::ComponentSelectionConflict @@ -4517,7 +4540,8 @@ impl ErrorCode { | Self::HostDaemonUnreachable | Self::DirectDaemonUnreachable | Self::SshBootstrapUnavailable - | Self::ReleaseVerifierUnavailable => 69, + | Self::ReleaseVerifierUnavailable + | Self::LogsFollowReconnectExhausted => 69, Self::CertificateUntrusted | Self::CertificateHostnameMismatch | Self::CertificateExpired @@ -4527,6 +4551,7 @@ impl ErrorCode { | Self::AuthenticationFailed | Self::AuthorizationInsufficientScope | Self::HostIdentityMismatch + | Self::LogsFollowIdentityChanged | Self::StoreInUse | Self::RemoteExecution | Self::HostUpdateRecoveryPending @@ -5818,6 +5843,71 @@ impl SatelleError { } } + pub fn logs_target_required() -> Self { + Self { + code: ErrorCode::LogsTargetRequired, + message: "logs requires a resolvable Host or Session target".to_string(), + recovery_command: Some("pass --host or --session ".to_string()), + source_detail: None, + details: BTreeMap::new(), + } + } + + pub fn logs_follow_identity_changed( + expected_host_identity: &str, + observed_host_identity: Option<&str>, + session_id: Option<&str>, + ) -> Self { + let mut details = BTreeMap::new(); + details.insert( + "expected_host_identity".to_string(), + Value::String(expected_host_identity.to_string()), + ); + details.insert( + "observed_host_identity".to_string(), + observed_host_identity + .map_or(Value::Null, |identity| Value::String(identity.to_string())), + ); + details.insert( + "session_id".to_string(), + session_id.map_or(Value::Null, |session| Value::String(session.to_string())), + ); + Self { + code: ErrorCode::LogsFollowIdentityChanged, + message: "the reconnected log target no longer matches the original Host or Session" + .to_string(), + recovery_command: Some( + "verify the Host identity and Session owner before starting a new log follow" + .to_string(), + ), + source_detail: None, + details, + } + } + + pub fn logs_follow_reconnect_exhausted( + last_delivered_cursor: &str, + stream_interruptions: usize, + rerun_command: &str, + ) -> Self { + let mut details = BTreeMap::new(); + details.insert( + "last_delivered_cursor".to_string(), + Value::String(last_delivered_cursor.to_string()), + ); + details.insert( + "stream_interruptions".to_string(), + Value::from(stream_interruptions), + ); + Self { + code: ErrorCode::LogsFollowReconnectExhausted, + message: "log follow reconnect budget was exhausted".to_string(), + recovery_command: Some(rerun_command.to_string()), + source_detail: None, + details, + } + } + pub fn concurrency_limit_exceeded(value: u8) -> Self { let mut details = BTreeMap::new(); details.insert("concurrency".to_string(), Value::from(value)); @@ -6934,6 +7024,60 @@ mod error_contract_tests { assert_eq!(error.exit_code(), 64); } } + + #[test] + fn log_follow_errors_have_stable_typed_contracts() { + let target = SatelleError::logs_target_required(); + assert_eq!(target.code, ErrorCode::LogsTargetRequired); + assert_eq!(target.code.as_str(), "logs-target-required"); + assert_eq!(target.exit_code(), 64); + assert_eq!( + target.recovery_command.as_deref(), + Some("pass --host or --session ") + ); + + let identity = SatelleError::logs_follow_identity_changed( + "host-original", + Some("host-replacement"), + Some("0195f6d5-18da-7a80-8000-000000000003"), + ); + assert_eq!(identity.code, ErrorCode::LogsFollowIdentityChanged); + assert_eq!(identity.code.as_str(), "logs-follow-identity-changed"); + assert_eq!(identity.exit_code(), 74); + assert_eq!( + identity.details.get("expected_host_identity"), + Some(&serde_json::json!("host-original")) + ); + assert_eq!( + identity.details.get("observed_host_identity"), + Some(&serde_json::json!("host-replacement")) + ); + assert_eq!( + identity.details.get("session_id"), + Some(&serde_json::json!("0195f6d5-18da-7a80-8000-000000000003")) + ); + + let exhausted = SatelleError::logs_follow_reconnect_exhausted( + "slc1_0000000000000042", + 10, + "satelle logs --host remote --after slc1_0000000000000042 --follow", + ); + assert_eq!(exhausted.code, ErrorCode::LogsFollowReconnectExhausted); + assert_eq!(exhausted.code.as_str(), "logs-follow-reconnect-exhausted"); + assert_eq!(exhausted.exit_code(), 69); + assert_eq!( + exhausted.details.get("last_delivered_cursor"), + Some(&serde_json::json!("slc1_0000000000000042")) + ); + assert_eq!( + exhausted.details.get("stream_interruptions"), + Some(&serde_json::json!(10)) + ); + assert_eq!( + exhausted.recovery_command.as_deref(), + Some("satelle logs --host remote --after slc1_0000000000000042 --follow") + ); + } } fn host_access_error( diff --git a/crates/satelle-core/src/profiles.rs b/crates/satelle-core/src/profiles.rs index 64155580..3cf04c97 100644 --- a/crates/satelle-core/src/profiles.rs +++ b/crates/satelle-core/src/profiles.rs @@ -27,6 +27,7 @@ const PROFILE_KEYS: &[&str] = &[ "daemon_idle_timeout", "setup_ledger_retention", "session_metadata_retention", + "sqlite_log_retention", "operator_log_retained_files", ]; const TIMEOUT_KEYS: &[&str] = &["native_readiness", "provider_smoke_test", "turn_execution"]; @@ -89,6 +90,7 @@ pub(super) struct ProfileConfig { daemon_idle_timeout: Option, setup_ledger_retention: Option, session_metadata_retention: Option, + sqlite_log_retention: Option, operator_log_retained_files: Option, } @@ -183,6 +185,9 @@ impl ProfileConfig { if let Some(retention) = &self.session_metadata_retention { host.session_metadata_retention = Some(retention.clone()); } + if let Some(retention) = &self.sqlite_log_retention { + host.sqlite_log_retention = Some(retention.clone()); + } if let Some(retained_files) = self.operator_log_retained_files { host.operator_log_retained_files = Some(retained_files); } @@ -436,6 +441,11 @@ fn reject_profile_interpolation( table.get("session_metadata_retention"), &mut interpolations, ); + collect_interpolation_for_value( + &format!("{profile_path}.sqlite_log_retention"), + table.get("sqlite_log_retention"), + &mut interpolations, + ); if let Some(timeouts) = table.get("timeouts").and_then(toml::Value::as_table) { for key in TIMEOUT_KEYS { collect_interpolation_for_value( @@ -503,6 +513,15 @@ fn reject_profile_duration_errors( return Err(SatelleError::duration_unit_required(path, &retention_path)); } } + if let Some(value) = table.get("sqlite_log_retention") { + let retention_path = format!("{profile_path}.sqlite_log_retention"); + let Some(value) = value.as_str() else { + return Err(SatelleError::duration_unit_required(path, &retention_path)); + }; + if RetentionDuration::parse(value).is_none() { + return Err(SatelleError::duration_unit_required(path, &retention_path)); + } + } if let Some(value) = table.get("operator_log_retained_files") { let retained_files = value .as_integer() @@ -779,7 +798,7 @@ mod timeout_profile_tests { #[test] fn only_user_selected_profiles_override_destructive_retention() { let profile: ProfileConfig = toml::from_str( - "session_metadata_retention = \"30d\"\noperator_log_retained_files = 12\n", + "session_metadata_retention = \"30d\"\nsqlite_log_retention = \"45d\"\noperator_log_retained_files = 12\n", ) .expect("parse profile retention policy"); @@ -794,6 +813,7 @@ mod timeout_profile_tests { 30 * 24 ); assert_eq!(host.operator_log_retained_files, Some(12)); + assert_eq!(host.sqlite_log_retention.as_ref().unwrap().hours(), 45 * 24); } for source in [ @@ -803,6 +823,7 @@ mod timeout_profile_tests { let mut host = base_host(); profile.apply_to_host(super::super::LOCAL_DEMO_HOST, &mut host, source); assert!(host.session_metadata_retention.is_none()); + assert!(host.sqlite_log_retention.is_none()); assert!(host.operator_log_retained_files.is_none()); } } diff --git a/crates/satelle-host/src/daemon-reconnect-tests.rs b/crates/satelle-host/src/daemon-reconnect-tests.rs index 929e2bd3..9c84ac4d 100644 --- a/crates/satelle-host/src/daemon-reconnect-tests.rs +++ b/crates/satelle-host/src/daemon-reconnect-tests.rs @@ -101,6 +101,8 @@ fn daemon_reconnect_restores_current_state_and_cursor_logs_without_event_replay( .collect::>(), [ LogEvent::FollowUpStarted, + LogEvent::NativeReadinessSummary, + LogEvent::ProviderSmokeSummary, LogEvent::TurnStateCommitted, LogEvent::TurnStateCommitted, ] diff --git a/crates/satelle-host/src/lib-tests.rs b/crates/satelle-host/src/lib-tests.rs index 2bc4bccb..6dc516f5 100644 --- a/crates/satelle-host/src/lib-tests.rs +++ b/crates/satelle-host/src/lib-tests.rs @@ -89,6 +89,7 @@ fn production_service_reports_the_frozen_service_config_path_set() { satelle_core::daemon_service::PersistentHostStoragePolicy::new( 3_600_000, satelle_core::DEFAULT_SESSION_METADATA_RETENTION_HOURS, + 45 * 24, satelle_core::DEFAULT_OPERATOR_LOG_RETAINED_FILES, ) .expect("valid persistent storage policy"), @@ -110,6 +111,10 @@ fn production_service_reports_the_frozen_service_config_path_set() { service.setup_ledger_retention_for_tests(), time::Duration::hours(1) ); + assert_eq!( + service.sqlite_log_retention_for_tests(), + time::Duration::days(45) + ); } struct ReadyTestTransportProbe; diff --git a/crates/satelle-host/src/lib.rs b/crates/satelle-host/src/lib.rs index 99a85525..dcc0c07f 100644 --- a/crates/satelle-host/src/lib.rs +++ b/crates/satelle-host/src/lib.rs @@ -2769,6 +2769,15 @@ impl HostService { )) .ok_or_else(|| SatelleError::config_error("invalid service Session retention", None))?, ); + config.sqlite_log_retention = Some( + satelle_core::RetentionDuration::parse(&format!( + "{}h", + storage_policy.sqlite_log_retention_hours() + )) + .ok_or_else(|| { + SatelleError::config_error("invalid service SQLite log retention", None) + })?, + ); config.operator_log_retained_files = Some(storage_policy.operator_log_retained_files()); Ok(Self::production_for_host(&config)) } @@ -2778,6 +2787,11 @@ impl HostService { self.runtime.setup_ledger_retention_for_tests() } + #[cfg(test)] + fn sqlite_log_retention_for_tests(&self) -> time::Duration { + self.runtime.sqlite_log_retention_for_tests() + } + /// Builds an on-demand Host whose only bootstrap credential is held in /// process memory and expires independently of durable Host state. pub fn production_for_ssh_bootstrap( diff --git a/crates/satelle-host/src/log-page.rs b/crates/satelle-host/src/log-page.rs index f8a79593..b6b7b14b 100644 --- a/crates/satelle-host/src/log-page.rs +++ b/crates/satelle-host/src/log-page.rs @@ -1,4 +1,4 @@ -use satelle_core::session::{SessionStateRevision, TurnStateRevision}; +use satelle_core::session::{HostIdentityRef, SessionStateRevision, TurnStateRevision}; use satelle_core::{SessionId, TurnId}; use serde::{Deserialize, Deserializer, Serialize, Serializer}; use std::collections::BTreeSet; @@ -136,7 +136,10 @@ impl LogSeverity { pub enum LogEvent { SessionStarted, FollowUpStarted, + NativeReadinessSummary, + ProviderSmokeSummary, TurnStateCommitted, + StructuredExecutionError, StopConfirmed, StopNotConfirmed, RestartRecoveryPending, @@ -148,7 +151,10 @@ impl LogEvent { match self { Self::SessionStarted => "session_started", Self::FollowUpStarted => "follow_up_started", + Self::NativeReadinessSummary => "native_readiness_summary", + Self::ProviderSmokeSummary => "provider_smoke_summary", Self::TurnStateCommitted => "turn_state_committed", + Self::StructuredExecutionError => "structured_execution_error", Self::StopConfirmed => "stop_confirmed", Self::StopNotConfirmed => "stop_not_confirmed", Self::RestartRecoveryPending => "restart_recovery_pending", @@ -160,7 +166,10 @@ impl LogEvent { match self { Self::SessionStarted => "created Session", Self::FollowUpStarted => "admitted follow-up Turn", + Self::NativeReadinessSummary => "native Computer Use readiness passed", + Self::ProviderSmokeSummary => "provider smoke test passed", Self::TurnStateCommitted => "committed Turn state", + Self::StructuredExecutionError => "recorded a structured execution failure", Self::StopConfirmed => "confirmed stop request", Self::StopNotConfirmed => "stop request requires recovery", Self::RestartRecoveryPending => "Turn requires restart recovery", @@ -171,6 +180,21 @@ impl LogEvent { pub(crate) const fn has_turn_subject(self) -> bool { !matches!(self, Self::StoreOpened) } + + pub(crate) const fn source(self) -> LogSource { + match self { + Self::SessionStarted + | Self::FollowUpStarted + | Self::NativeReadinessSummary + | Self::StopConfirmed + | Self::StopNotConfirmed + | Self::RestartRecoveryPending => LogSource::HostDaemon, + Self::ProviderSmokeSummary + | Self::TurnStateCommitted + | Self::StructuredExecutionError => LogSource::CodexAdapter, + Self::StoreOpened => LogSource::Storage, + } + } } #[derive(Clone, Debug, Deserialize, Eq, PartialEq, Serialize)] @@ -244,6 +268,7 @@ impl<'de> Deserialize<'de> for Redacted { pub struct DaemonLogEntry { cursor: LogCursor, timestamp: OffsetDateTime, + host_identity: HostIdentityRef, source: LogSource, severity: LogSeverity, event: LogEvent, @@ -254,6 +279,7 @@ impl DaemonLogEntry { pub(crate) fn from_parts( cursor: u64, timestamp: OffsetDateTime, + host_identity: HostIdentityRef, source: LogSource, severity: LogSeverity, event: LogEvent, @@ -262,6 +288,7 @@ impl DaemonLogEntry { let entry = Self { cursor: LogCursor::from_position(cursor), timestamp, + host_identity, source, severity, event, @@ -278,6 +305,9 @@ impl DaemonLogEntry { if self.event.has_turn_subject() != matches!(self.subject, LogSubject::Turn { .. }) { return Err("the Log Entry event contradicts its subject"); } + if self.source != self.event.source() { + return Err("the Log Entry source contradicts its event"); + } Ok(()) } @@ -289,6 +319,10 @@ impl DaemonLogEntry { self.timestamp } + pub const fn host_identity(&self) -> &HostIdentityRef { + &self.host_identity + } + pub const fn source(&self) -> LogSource { self.source } @@ -312,6 +346,7 @@ struct DaemonLogEntryRef<'a> { cursor: LogCursor, #[serde(with = "time::serde::rfc3339")] timestamp: OffsetDateTime, + host_identity: &'a str, source: LogSource, severity: LogSeverity, event: LogEvent, @@ -329,6 +364,7 @@ impl Serialize for DaemonLogEntry { schema_version: LogEntrySchema, cursor: self.cursor, timestamp: self.timestamp, + host_identity: self.host_identity.as_str(), source: self.source, severity: self.severity, event: self.event, @@ -348,6 +384,7 @@ struct DaemonLogEntryOwned { cursor: LogCursor, #[serde(with = "time::serde::rfc3339")] timestamp: OffsetDateTime, + host_identity: String, source: LogSource, severity: LogSeverity, event: LogEvent, @@ -371,6 +408,8 @@ impl<'de> Deserialize<'de> for DaemonLogEntry { let entry = Self { cursor: wire.cursor, timestamp: wire.timestamp, + host_identity: HostIdentityRef::new(wire.host_identity) + .map_err(serde::de::Error::custom)?, source: wire.source, severity: wire.severity, event: wire.event, @@ -517,6 +556,20 @@ impl LogPageQuery { self.session_id.as_ref() } + /// Returns whether a normalized Log Entry satisfies every requested filter. + pub fn matches_entry(&self, entry: &DaemonLogEntry) -> bool { + let session_matches = self.session_id.as_ref().is_none_or(|requested_session| { + matches!( + entry.subject(), + LogSubject::Turn { session_id, .. } if session_id == requested_session + ) + }); + session_matches + && self.includes_source(entry.source()) + && entry.severity() >= self.minimum_severity + && self.since.is_none_or(|since| entry.timestamp() >= since) + } + pub(crate) fn includes_source(&self, source: LogSource) -> bool { self.sources .as_ref() @@ -730,6 +783,7 @@ mod tests { let entry = DaemonLogEntry::from_parts( 2, OffsetDateTime::UNIX_EPOCH, + HostIdentityRef::new("host-log-test").unwrap(), LogSource::Storage, LogSeverity::Info, LogEvent::StoreOpened, @@ -750,4 +804,50 @@ mod tests { }); assert!(serde_json::from_value::(invalid_page).is_err()); } + + #[test] + fn log_entry_deserialization_rejects_every_event_source_contradiction() { + let events = [ + (LogEvent::SessionStarted, LogSource::HostDaemon), + (LogEvent::FollowUpStarted, LogSource::HostDaemon), + (LogEvent::NativeReadinessSummary, LogSource::HostDaemon), + (LogEvent::ProviderSmokeSummary, LogSource::CodexAdapter), + (LogEvent::TurnStateCommitted, LogSource::CodexAdapter), + (LogEvent::StructuredExecutionError, LogSource::CodexAdapter), + (LogEvent::StopConfirmed, LogSource::HostDaemon), + (LogEvent::StopNotConfirmed, LogSource::HostDaemon), + (LogEvent::RestartRecoveryPending, LogSource::HostDaemon), + (LogEvent::StoreOpened, LogSource::Storage), + ]; + for (index, (event, source)) in events.into_iter().enumerate() { + let subject = if event.has_turn_subject() { + LogSubject::Turn { + session_id: SessionId::parse("rs_01890a5d-ac96-7b7c-8f89-37c3d0a66e11") + .unwrap(), + turn_id: TurnId::parse("rt_01890a5d-ac96-7b7c-8f89-37c3d0a66e21").unwrap(), + session_state_revision: SessionStateRevision::initial(), + turn_state_revision: TurnStateRevision::initial(), + } + } else { + LogSubject::Host + }; + let entry = DaemonLogEntry::from_parts( + u64::try_from(index + 1).unwrap(), + OffsetDateTime::UNIX_EPOCH, + HostIdentityRef::new("host-log-test").unwrap(), + source, + LogSeverity::Info, + event, + subject, + ) + .unwrap(); + let mut value = serde_json::to_value(&entry).unwrap(); + value["source"] = serde_json::json!(if source == LogSource::Storage { + LogSource::HostDaemon.as_str() + } else { + LogSource::Storage.as_str() + }); + assert!(serde_json::from_value::(value).is_err()); + } + } } diff --git a/crates/satelle-host/src/runtime-codex-tests.rs b/crates/satelle-host/src/runtime-codex-tests.rs index 39cc8229..56adde42 100644 --- a/crates/satelle-host/src/runtime-codex-tests.rs +++ b/crates/satelle-host/src/runtime-codex-tests.rs @@ -1,3 +1,5 @@ +#[cfg(unix)] +use super::control_plane::perform_handshake; use super::control_plane::{ CodexImageInputMode, ControlPlaneAdmission, configure_app_server_command, probe_control_plane_with, @@ -8,6 +10,8 @@ use std::fs::File; use std::path::{Path, PathBuf}; use std::process::Command; use std::time::Duration; +#[cfg(unix)] +use std::time::Instant; const FIXTURE_MODE: &str = "SATELLE_CODEX_CONTROL_PLANE_FIXTURE"; const FIXTURE_SCHEMA_DIR: &str = "SATELLE_CODEX_SCHEMA_FIXTURE_DIR"; @@ -320,24 +324,26 @@ fn production_stdio_timeout_terminates_stdout_inheriting_descendants() { #[test] fn production_stdio_deadline_survives_a_group_escaping_pipe_holder() { let fixture = compile_stdio_fixture(); - let started = std::time::Instant::now(); - - let probe = run_production_stdio_fixture_with( - &fixture, - "hang-with-escaped-descendant-exit", - Duration::from_millis(100), + let mut app_server = Command::new(fixture.executable()); + app_server.arg("hang-with-escaped-descendant-exit"); + let started = Instant::now(); + + let handshake_completed = perform_handshake( + app_server, + fixture + .executable() + .parent() + .expect("the fixture executable must have a parent directory"), + Instant::now() + Duration::from_millis(100), ); assert!( started.elapsed() < Duration::from_secs(1), "an escaped stdout holder exceeded the hard protocol deadline" ); - assert_eq!( - ControlPlaneAdmission::from_probe(probe) - .admit(ControlPlaneOperation::Run) - .expect_err("an incomplete escaped-child handshake must remain blocked") - .details["reason"], - serde_json::json!("handshake_unavailable") + assert!( + !handshake_completed, + "an incomplete escaped-child handshake must remain blocked" ); } diff --git a/crates/satelle-host/src/runtime-codex.rs b/crates/satelle-host/src/runtime-codex.rs index b6452a4a..d7c8f6cc 100644 --- a/crates/satelle-host/src/runtime-codex.rs +++ b/crates/satelle-host/src/runtime-codex.rs @@ -423,7 +423,11 @@ fn declares_method(value: &Value, expected: &str) -> bool { }) } -fn perform_handshake(mut command: Command, working_dir: &Path, deadline: Instant) -> bool { +pub(super) fn perform_handshake( + mut command: Command, + working_dir: &Path, + deadline: Instant, +) -> bool { if Instant::now() >= deadline { return false; } diff --git a/crates/satelle-host/src/runtime-tests.rs b/crates/satelle-host/src/runtime-tests.rs index 1243be32..94577853 100644 --- a/crates/satelle-host/src/runtime-tests.rs +++ b/crates/satelle-host/src/runtime-tests.rs @@ -127,11 +127,14 @@ fn host_retention_config_becomes_the_runtime_storage_policy() { .expect("the built-in local Host config exists"); config.session_metadata_retention = Some(satelle_core::RetentionDuration::parse("30d").expect("parse session retention")); + config.sqlite_log_retention = + Some(satelle_core::RetentionDuration::parse("45d").expect("parse Log retention")); config.operator_log_retained_files = Some(12); let policy = super::RuntimeStoragePolicy::from_host_config(&config); assert_eq!(policy.session_metadata_retention, time::Duration::days(30)); + assert_eq!(policy.sqlite_log_retention, time::Duration::days(45)); assert_eq!(policy.operator_log_retained_files, 12); assert_eq!( policy.setup_ledger_retention, diff --git a/crates/satelle-host/src/runtime.rs b/crates/satelle-host/src/runtime.rs index 5147da53..7f2490af 100644 --- a/crates/satelle-host/src/runtime.rs +++ b/crates/satelle-host/src/runtime.rs @@ -633,6 +633,7 @@ pub(crate) struct RuntimeEngine { #[derive(Clone, Copy)] pub(crate) struct RuntimeStoragePolicy { session_metadata_retention: time::Duration, + sqlite_log_retention: time::Duration, setup_ledger_retention: time::Duration, operator_log_retained_files: usize, } @@ -646,6 +647,12 @@ impl RuntimeStoragePolicy { .map_or(crate::storage::DEFAULT_SESSION_RETENTION, |retention| { time::Duration::hours(retention.hours() as i64) }), + sqlite_log_retention: config + .sqlite_log_retention + .as_ref() + .map_or(crate::storage::DEFAULT_LOG_RETENTION, |retention| { + time::Duration::hours(retention.hours() as i64) + }), setup_ledger_retention: config.setup_ledger_retention.as_ref().map_or( crate::storage::DEFAULT_SETUP_LEDGER_RETENTION, crate::duration_to_time, @@ -661,6 +668,7 @@ impl Default for RuntimeStoragePolicy { fn default() -> Self { Self { session_metadata_retention: crate::storage::DEFAULT_SESSION_RETENTION, + sqlite_log_retention: crate::storage::DEFAULT_LOG_RETENTION, setup_ledger_retention: crate::storage::DEFAULT_SETUP_LEDGER_RETENTION, operator_log_retained_files: satelle_core::DEFAULT_OPERATOR_LOG_RETAINED_FILES, } @@ -731,8 +739,9 @@ impl RuntimeEngine { ) -> Result, SatelleError> { let process_identity = ProcessIdentity::current().map_err(model::process_identity_failure)?; - let storage = + let mut storage = Storage::open_without_restart_recovery(state_root).map_err(model::storage_failure)?; + storage.set_log_retention(storage_policy.sqlite_log_retention); if let Some(fingerprinter) = provider_smoke_fingerprinter { let key = storage .provider_smoke_hmac_key() @@ -3001,6 +3010,15 @@ impl RuntimeHandle { .setup_ledger_retention } + #[cfg(test)] + pub(crate) fn sqlite_log_retention_for_tests(&self) -> time::Duration { + self.lazy + .lock() + .unwrap_or_else(std::sync::PoisonError::into_inner) + .storage_policy + .sqlite_log_retention + } + #[cfg(any(test, feature = "test-support"))] pub(crate) fn new_with_readiness_probe_driver( state_root: Result, diff --git a/crates/satelle-host/src/storage.rs b/crates/satelle-host/src/storage.rs index ca7bdd6d..a552cdac 100644 --- a/crates/satelle-host/src/storage.rs +++ b/crates/satelle-host/src/storage.rs @@ -44,7 +44,9 @@ pub(crate) use self::provider_secret_journal::{ ProviderSecretProvisioningPreflight, ProviderSecretProvisioningReplay, provider_secret_file_paths, }; -pub(crate) use self::retention::{DEFAULT_SESSION_RETENTION, DEFAULT_SETUP_LEDGER_RETENTION}; +pub(crate) use self::retention::{ + DEFAULT_LOG_RETENTION, DEFAULT_SESSION_RETENTION, DEFAULT_SETUP_LEDGER_RETENTION, +}; pub(crate) use self::setup_ledger::{ MaintenanceLeaseCapability, MaintenanceLeaseState, MaintenanceRecoverySubject, }; @@ -428,10 +430,11 @@ mod ssh_identity_commit_tests { (13, "fnv1a64:5db2b0aa00a5f745"), (14, "fnv1a64:fb04115e0082c148"), (15, "fnv1a64:efae7b5838392fa8"), + (16, "fnv1a64:8478b3aeb5aaa616"), ]; const EXPECTED_SCHEMA_ROW_COUNT: usize = 71; const EXPECTED_SCHEMA_SHA256: &str = - "87bd4af01a35dd9f7f5aced198f5a447e2d26f8a23bb66ef3dd78bd6bfd366de"; + "cb18a92b0454a5115622a829f3fb1523ad296b62421c9a40b397ab8f32005e8c"; fn identity() -> HostIdentityRef { HostIdentityRef::new(HOST_IDENTITY.to_string()).expect("valid Host Identity fixture") @@ -580,7 +583,7 @@ mod ssh_identity_commit_tests { let user_version: i64 = connection .query_row("PRAGMA user_version", [], |row| row.get(0)) .expect("read schema user version"); - assert_eq!(user_version, 15); + assert_eq!(user_version, 16); let schema = connection .prepare( @@ -1621,6 +1624,7 @@ pub(crate) struct Storage { // Field order is a drop invariant: SQLite must close every delegated file // before the ownership lock and pinned state directory are released. connection: Connection, + log_retention: time::Duration, _ownership_lock: open::OwnershipLock, _state_directory: open::StateDirectory, } @@ -1638,11 +1642,16 @@ impl Storage { auth::validate_sensitive_state(&connection)?; Ok(Self { connection, + log_retention: DEFAULT_LOG_RETENTION, _ownership_lock: ownership_lock, _state_directory: state_directory, }) } + pub(crate) fn set_log_retention(&mut self, retention: time::Duration) { + self.log_retention = retention; + } + pub(crate) fn has_existing_state(state_root: &Path) -> Result { open::prepare_state_root(state_root)?.has_existing_store_state() } @@ -1698,6 +1707,7 @@ impl Storage { })?; let mut storage = Self { connection, + log_retention: DEFAULT_LOG_RETENTION, _ownership_lock: ownership_lock, _state_directory: state_directory, }; @@ -2989,6 +2999,30 @@ impl Storage { session.updated_at(), )?, )?; + if let Some(readiness) = &context.readiness_ref { + insert_safe_log( + &transaction, + &canonical_log( + LogEvent::NativeReadinessSummary, + LogSeverity::Info, + session, + &turn_id, + session.updated_at(), + )?, + )?; + if readiness.provider_result_id().is_some() { + insert_safe_log( + &transaction, + &canonical_log( + LogEvent::ProviderSmokeSummary, + LogSeverity::Info, + session, + &turn_id, + session.updated_at(), + )?, + )?; + } + } let recovery_subject = load_recovery_subject(&transaction, session, &turn_id)?; transaction .commit() @@ -3101,6 +3135,30 @@ impl Storage { session.updated_at(), )?, )?; + if let Some(readiness) = &context.readiness_ref { + insert_safe_log( + &transaction, + &canonical_log( + LogEvent::NativeReadinessSummary, + LogSeverity::Info, + &session, + &turn_id, + session.updated_at(), + )?, + )?; + if readiness.provider_result_id().is_some() { + insert_safe_log( + &transaction, + &canonical_log( + LogEvent::ProviderSmokeSummary, + LogSeverity::Info, + &session, + &turn_id, + session.updated_at(), + )?, + )?; + } + } let recovery_subject = load_recovery_subject(&transaction, &session, &turn_id)?; transaction .commit() @@ -3119,6 +3177,10 @@ impl Storage { transition: TurnTransition, at: OffsetDateTime, ) -> Result { + let structured_execution_error = matches!( + &transition, + TurnTransition::Blocked | TurnTransition::Failed | TurnTransition::RecoveryFailed + ); let transaction = self .connection .transaction_with_behavior(TransactionBehavior::Immediate) @@ -3149,6 +3211,18 @@ impl Storage { session.updated_at(), )?, )?; + if structured_execution_error { + insert_safe_log( + &transaction, + &canonical_log( + LogEvent::StructuredExecutionError, + LogSeverity::Error, + &session, + turn_id, + session.updated_at(), + )?, + )?; + } transaction .commit() .map_err(|source| sqlite_error(StorageErrorKind::OperationFailed, source))?; diff --git a/crates/satelle-host/src/storage/0016_normalized_log_events.sql b/crates/satelle-host/src/storage/0016_normalized_log_events.sql new file mode 100644 index 00000000..e232bf00 --- /dev/null +++ b/crates/satelle-host/src/storage/0016_normalized_log_events.sql @@ -0,0 +1,89 @@ +ALTER TABLE logs RENAME TO logs_v15; + +CREATE TABLE logs ( + log_cursor INTEGER PRIMARY KEY AUTOINCREMENT, + recorded_at TEXT NOT NULL, + recorded_at_unix_nanos INTEGER NOT NULL, + source TEXT NOT NULL + CHECK (source IN ('host_daemon', 'storage', 'codex_adapter')), + severity TEXT NOT NULL + CHECK (severity IN ('info', 'warning', 'error')), + event_kind TEXT NOT NULL + CHECK (event_kind IN ( + 'session_started', + 'follow_up_started', + 'native_readiness_summary', + 'provider_smoke_summary', + 'turn_state_committed', + 'structured_execution_error', + 'stop_confirmed', + 'stop_not_confirmed', + 'restart_recovery_pending', + 'store_opened' + )), + session_id TEXT REFERENCES sessions(session_id) ON DELETE SET NULL, + turn_id TEXT REFERENCES turns(turn_id) ON DELETE SET NULL, + session_state_revision TEXT, + turn_state_revision TEXT, + redacted INTEGER NOT NULL DEFAULT 1 CHECK (redacted = 1), + CHECK ( + ( + event_kind = 'store_opened' + AND session_id IS NULL + AND turn_id IS NULL + AND session_state_revision IS NULL + AND turn_state_revision IS NULL + ) + OR ( + event_kind != 'store_opened' + AND session_id IS NOT NULL + AND turn_id IS NOT NULL + AND session_state_revision IS NOT NULL + AND turn_state_revision IS NOT NULL + ) + ) +) STRICT; + +INSERT INTO logs ( + log_cursor, + recorded_at, + recorded_at_unix_nanos, + source, + severity, + event_kind, + session_id, + turn_id, + session_state_revision, + turn_state_revision, + redacted +) +SELECT + log_cursor, + recorded_at, + recorded_at_unix_nanos, + -- Version 15 attributed every lifecycle write to the Host Daemon. The + -- normalized contract assigns adapter-observed Turn commits to Codex. + CASE event_kind + WHEN 'turn_state_committed' THEN 'codex_adapter' + ELSE source + END, + severity, + event_kind, + session_id, + turn_id, + session_state_revision, + turn_state_revision, + redacted +FROM logs_v15 +ORDER BY log_cursor; + +DROP TABLE logs_v15; + +CREATE INDEX logs_by_cursor + ON logs(log_cursor); + +CREATE INDEX logs_by_session_cursor + ON logs(session_id, log_cursor); + +CREATE INDEX logs_by_recorded_at_cursor + ON logs(recorded_at_unix_nanos, log_cursor); diff --git a/crates/satelle-host/src/storage/codec.rs b/crates/satelle-host/src/storage/codec.rs index 3f6af677..855cc1a2 100644 --- a/crates/satelle-host/src/storage/codec.rs +++ b/crates/satelle-host/src/storage/codec.rs @@ -670,7 +670,10 @@ pub(super) fn log_event_token(value: LogEvent) -> &'static str { match value { LogEvent::SessionStarted => "session_started", LogEvent::FollowUpStarted => "follow_up_started", + LogEvent::NativeReadinessSummary => "native_readiness_summary", + LogEvent::ProviderSmokeSummary => "provider_smoke_summary", LogEvent::TurnStateCommitted => "turn_state_committed", + LogEvent::StructuredExecutionError => "structured_execution_error", LogEvent::StopConfirmed => "stop_confirmed", LogEvent::StopNotConfirmed => "stop_not_confirmed", LogEvent::RestartRecoveryPending => "restart_recovery_pending", @@ -682,7 +685,10 @@ fn parse_log_event(value: &str) -> Result { match value { "session_started" => Ok(LogEvent::SessionStarted), "follow_up_started" => Ok(LogEvent::FollowUpStarted), + "native_readiness_summary" => Ok(LogEvent::NativeReadinessSummary), + "provider_smoke_summary" => Ok(LogEvent::ProviderSmokeSummary), "turn_state_committed" => Ok(LogEvent::TurnStateCommitted), + "structured_execution_error" => Ok(LogEvent::StructuredExecutionError), "stop_confirmed" => Ok(LogEvent::StopConfirmed), "stop_not_confirmed" => Ok(LogEvent::StopNotConfirmed), "restart_recovery_pending" => Ok(LogEvent::RestartRecoveryPending), diff --git a/crates/satelle-host/src/storage/logs.rs b/crates/satelle-host/src/storage/logs.rs index 2a95216b..64c072a7 100644 --- a/crates/satelle-host/src/storage/logs.rs +++ b/crates/satelle-host/src/storage/logs.rs @@ -79,9 +79,12 @@ pub(super) fn canonical_log( let turn = session .turn(turn_id) .ok_or_else(|| StorageError::new(StorageErrorKind::InvalidStoredState))?; + if event == LogEvent::StoreOpened { + return Err(StorageError::new(StorageErrorKind::InvalidInput)); + } SafeLogRecord::new( recorded_at, - LogSource::HostDaemon, + event.source(), severity, event, LogSubject::Turn { @@ -140,7 +143,7 @@ impl Storage { if stored.len() != 1 || stored[0].cursor != cursor { return Err(StorageError::new(StorageErrorKind::InvalidStoredState)); } - stored_page_entry(stored.remove(0)) + stored_page_entry(stored.remove(0), self.host_identity()?) } pub(crate) fn latest_log_cursor(&self) -> Result { @@ -160,11 +163,12 @@ impl Storage { ) -> Result, StorageError> { let query = LogPageQuery::forward(Some(LogCursor::from_position(cursor)), limit) .map_err(|_| StorageError::new(StorageErrorKind::InvalidInput))?; + let host_identity = self.host_identity()?; load_log_page_records(&self.connection, &query, limit)? .into_iter() .map(|stored| { let cursor = stored.cursor; - stored_page_entry(stored).map(|entry| (cursor, entry)) + stored_page_entry(stored, host_identity.clone()).map(|entry| (cursor, entry)) }) .collect() } @@ -219,9 +223,10 @@ impl Storage { if query.mode() == LogPageMode::Tail { stored.reverse(); } + let host_identity = self.host_identity()?; let entries = stored .into_iter() - .map(stored_page_entry) + .map(|stored| stored_page_entry(stored, host_identity.clone())) .collect::, _>>()?; let next_cursor = if query.mode() == LogPageMode::Forward && truncated { entries.last().map_or_else( @@ -235,25 +240,29 @@ impl Storage { } fn prune_logs_if_needed(&mut self, observed_at: OffsetDateTime) -> Result<(), StorageError> { - if !logs_need_pruning(&self.connection, observed_at)? { + if !logs_need_pruning(&self.connection, observed_at, self.log_retention)? { return Ok(()); } let transaction = self .connection .transaction_with_behavior(TransactionBehavior::Immediate) .map_err(|source| sqlite_error(StorageErrorKind::OperationFailed, source))?; - prune_expired_logs(&transaction, observed_at)?; + prune_expired_logs(&transaction, observed_at, self.log_retention)?; transaction .commit() .map_err(|source| sqlite_error(StorageErrorKind::OperationFailed, source)) } } -fn stored_page_entry(stored: StoredLogRecord) -> Result { +fn stored_page_entry( + stored: StoredLogRecord, + host_identity: satelle_core::session::HostIdentityRef, +) -> Result { let record = stored.record; DaemonLogEntry::from_parts( stored.cursor, record.recorded_at, + host_identity, record.source, record.severity, record.event, diff --git a/crates/satelle-host/src/storage/open.rs b/crates/satelle-host/src/storage/open.rs index b1d8c503..4f83f7f7 100644 --- a/crates/satelle-host/src/storage/open.rs +++ b/crates/satelle-host/src/storage/open.rs @@ -48,7 +48,7 @@ const BUSY_TIMEOUT: Duration = Duration::from_secs(5); const BACKUP_FORMAT_VERSION: u32 = 1; const RESTORE_ACTIVATION_JOURNAL: &str = ".satelle-restore-activation-v1"; const RESTORE_ACTIVATION_JOURNAL_LIMIT: usize = 64 * 1024; -const MIGRATIONS: [Migration; 15] = [ +const MIGRATIONS: [Migration; 16] = [ Migration { version: 1, sql: include_str!("0001_initial.sql"), @@ -139,6 +139,12 @@ const MIGRATIONS: [Migration; 15] = [ seeds_sensitive_state: false, irreversible: false, }, + Migration { + version: 16, + sql: include_str!("0016_normalized_log_events.sql"), + seeds_sensitive_state: false, + irreversible: true, + }, ]; #[derive(Clone, Copy)] diff --git a/crates/satelle-host/src/storage/operator-log.rs b/crates/satelle-host/src/storage/operator-log.rs index 601daf7f..77584016 100644 --- a/crates/satelle-host/src/storage/operator-log.rs +++ b/crates/satelle-host/src/storage/operator-log.rs @@ -322,8 +322,9 @@ fn format_entry(entry: &DaemonLogEntry) -> Result Result { - if logs_need_pruning(connection, observed_at)? { + if logs_need_pruning(connection, observed_at, log_retention)? { return Ok(true); } if admission_cancellations_need_pruning(connection, observed_at)? { @@ -100,7 +108,8 @@ fn retention_needs_pruning( if !expired_sessionless_idempotency(connection, observed_at)?.is_empty() { return Ok(true); } - for session_id in terminal_session_candidates(connection, session_cutoff, session_cutoff_nanos)? + for session_id in + terminal_session_candidates(connection, session_cutoff, retained_log_cutoff_nanos)? { if idempotency_records_allow_deletion(connection, &session_id, observed_at)? { return Ok(true); diff --git a/crates/satelle-host/src/storage/sql.rs b/crates/satelle-host/src/storage/sql.rs index 29cdc6e0..47994577 100644 --- a/crates/satelle-host/src/storage/sql.rs +++ b/crates/satelle-host/src/storage/sql.rs @@ -20,8 +20,6 @@ use satelle_core::session::{ use satelle_core::{SessionId, TurnId}; use time::OffsetDateTime; -const DEFAULT_LOG_RETENTION: time::Duration = time::Duration::days(7); - #[derive(Debug)] pub(super) struct StoredIdempotency { pub(super) request_digest: String, @@ -86,16 +84,16 @@ pub(super) fn insert_safe_log( .map_err(|source| sqlite_error(StorageErrorKind::OperationFailed, source))?; let cursor = u64::try_from(transaction.last_insert_rowid()) .map_err(|_| StorageError::new(StorageErrorKind::InvalidStoredState))?; - prune_expired_logs(transaction, effective_at)?; Ok(cursor) } pub(super) fn prune_expired_logs( transaction: &Transaction<'_>, observed_at: OffsetDateTime, + retention: time::Duration, ) -> Result<(), StorageError> { let cutoff = observed_at - .checked_sub(DEFAULT_LOG_RETENTION) + .checked_sub(retention) .ok_or_else(|| StorageError::new(StorageErrorKind::InvalidInput))?; let cutoff_nanos = unix_timestamp_nanos(cutoff)?; let first_retained = transaction @@ -137,9 +135,10 @@ pub(super) fn prune_expired_logs( pub(super) fn logs_need_pruning( connection: &Connection, observed_at: OffsetDateTime, + retention: time::Duration, ) -> Result { let cutoff = observed_at - .checked_sub(DEFAULT_LOG_RETENTION) + .checked_sub(retention) .ok_or_else(|| StorageError::new(StorageErrorKind::InvalidInput))?; let cutoff_nanos = unix_timestamp_nanos(cutoff)?; connection diff --git a/crates/satelle-host/src/storage/tests/lifecycle.rs b/crates/satelle-host/src/storage/tests/lifecycle.rs index 31099a80..e0a08014 100644 --- a/crates/satelle-host/src/storage/tests/lifecycle.rs +++ b/crates/satelle-host/src/storage/tests/lifecycle.rs @@ -111,6 +111,21 @@ fn terminal_session_round_trips_with_follow_up_and_exact_snapshot() { ) .expect("complete follow-up"); let expected = session.snapshot(); + let normalized_events = storage + .logs_after(None, 20) + .expect("read normalized lifecycle summaries"); + assert!(normalized_events.iter().any(|log| { + log.record().event() == LogEvent::NativeReadinessSummary + && log.record().source() == LogSource::HostDaemon + })); + assert!(normalized_events.iter().any(|log| { + log.record().event() == LogEvent::ProviderSmokeSummary + && log.record().source() == LogSource::CodexAdapter + })); + assert!(normalized_events.iter().any(|log| { + log.record().event() == LogEvent::TurnStateCommitted + && log.record().source() == LogSource::CodexAdapter + })); drop(storage); let (storage, recovery) = Storage::open(state.path()).expect("reopen storage"); diff --git a/crates/satelle-host/src/storage/tests/logs.rs b/crates/satelle-host/src/storage/tests/logs.rs index 7b6a05b0..5f580bf4 100644 --- a/crates/satelle-host/src/storage/tests/logs.rs +++ b/crates/satelle-host/src/storage/tests/logs.rs @@ -6,6 +6,7 @@ use std::fs; use std::path::Path; fn host_log(at: OffsetDateTime, source: LogSource, severity: LogSeverity) -> SafeLogRecord { + assert_eq!(source, LogSource::Storage); SafeLogRecord::new( at, source, @@ -89,10 +90,13 @@ fn operator_log_formats_the_authoritative_normalized_entry_only() { assert!(matches!(outcome, OperatorLogWriteOutcome::Written)); assert_eq!( fs::read_to_string(log_root.join("satelle-host.log")).expect("read operator log fixture"), - concat!( - "2026-01-02T03:04:01Z level=warn source=storage ", - "event=store_opened subject=host cursor=slc1_0000000000000002 ", - "message=\"opened Host state store\"\n", + format!( + concat!( + "2026-01-02T03:04:01Z level=warn host={} source=storage ", + "event=store_opened subject=host cursor=slc1_0000000000000002 ", + "redacted=true message=\"opened Host state store\"\n", + ), + normalized.host_identity().as_str(), ) ); } @@ -109,7 +113,7 @@ fn operator_log_rotates_only_above_the_threshold_and_retains_newest_generations( let first = committed_host_log( &mut storage, at(0), - LogSource::HostDaemon, + LogSource::Storage, LogSeverity::Warning, ); let probe_root = state.path().join("operator-log-probe"); @@ -132,7 +136,7 @@ fn operator_log_rotates_only_above_the_threshold_and_retains_newest_generations( let second = committed_host_log( &mut storage, at(0), - LogSource::HostDaemon, + LogSource::Storage, LogSeverity::Warning, ); assert!(matches!( @@ -150,7 +154,7 @@ fn operator_log_rotates_only_above_the_threshold_and_retains_newest_generations( let third = committed_host_log( &mut storage, at(0), - LogSource::HostDaemon, + LogSource::Storage, LogSeverity::Warning, ); assert!(matches!( @@ -170,7 +174,7 @@ fn operator_log_rotates_only_above_the_threshold_and_retains_newest_generations( let entry = committed_host_log( &mut storage, at(0), - LogSource::HostDaemon, + LogSource::Storage, LogSeverity::Warning, ); assert!(matches!( @@ -206,7 +210,7 @@ fn operator_log_rotates_only_above_the_threshold_and_retains_newest_generations( let twelfth = committed_host_log( &mut storage, at(0), - LogSource::HostDaemon, + LogSource::Storage, LogSeverity::Warning, ); let mut reduced = @@ -375,14 +379,14 @@ fn log_pages_filter_before_limiting_and_resume_after_the_delivered_cursor() { let second = storage .append_safe_log(&host_log( now + time::Duration::seconds(1), - LogSource::HostDaemon, + LogSource::Storage, LogSeverity::Warning, )) .expect("append second log"); let third = storage .append_safe_log(&host_log( now + time::Duration::seconds(2), - LogSource::CodexAdapter, + LogSource::Storage, LogSeverity::Error, )) .expect("append third log"); @@ -404,7 +408,7 @@ fn log_pages_filter_before_limiting_and_resume_after_the_delivered_cursor() { .log_page( &LogPageQuery::forward(Some(LogCursor::from_position(first)), 1) .expect("valid forward query") - .with_sources([LogSource::CodexAdapter]), + .with_minimum_severity(LogSeverity::Error), now, ) .expect("read filtered forward page"); @@ -748,3 +752,62 @@ fn log_reads_enforce_retention_even_when_no_new_log_has_been_written() { assert_eq!(error.earliest_available_cursor(), None); assert_eq!(error.resume_cursor(), Some(expired)); } + +#[test] +fn log_reads_use_the_configured_sqlite_retention() { + let state = TempDir::new().expect("temporary state directory"); + let (mut storage, _) = Storage::open(state.path()).expect("open storage"); + storage.set_log_retention(time::Duration::days(30)); + let observed_at = OffsetDateTime::now_utc(); + let retained = storage + .append_safe_log(&host_log( + observed_at - time::Duration::days(8), + LogSource::Storage, + LogSeverity::Info, + )) + .expect("append a Log Entry inside configured retention"); + + let page = storage + .log_page( + &LogPageQuery::tail(10).expect("valid tail query"), + observed_at, + ) + .expect("read with configured retention"); + assert_eq!( + page.entries() + .iter() + .map(|entry| entry.cursor().position()) + .collect::>(), + vec![retained] + ); +} + +#[test] +fn failed_turns_persist_a_normalized_structured_error_without_raw_payloads() { + let state = TempDir::new().expect("temporary state directory"); + let (mut storage, _) = Storage::open(state.path()).expect("open storage"); + let session = initial_session(&storage, SESSION_1, TURN_1, at(0)); + storage + .begin_session( + &session, + &admission(IdempotentOperation::Run, "run-log-error", "request", at(0)), + ) + .expect("admit Session"); + storage + .commit_lifecycle( + session.id(), + &turn_id(TURN_1), + revisions(&session, TURN_1), + TurnTransition::Failed, + at(1), + ) + .expect("commit failed Turn"); + + let logs = storage.logs_after(None, 10).expect("read normalized logs"); + let error = logs + .iter() + .find(|log| log.record().event() == LogEvent::StructuredExecutionError) + .expect("failed Turn should persist a structured error summary"); + assert_eq!(error.record().source(), LogSource::CodexAdapter); + assert_eq!(error.record().severity(), LogSeverity::Error); +} diff --git a/crates/satelle-host/src/storage/tests/operational.rs b/crates/satelle-host/src/storage/tests/operational.rs index 3cba9229..0bf44062 100644 --- a/crates/satelle-host/src/storage/tests/operational.rs +++ b/crates/satelle-host/src/storage/tests/operational.rs @@ -11,6 +11,52 @@ use crate::{ use sha2::{Digest, Sha256}; use std::path::{Path, PathBuf}; +fn rebuild_logs_as_v15_fixture(connection: &Connection) { + // Migration metadata is not a historical fixture. Restore the exact + // predecessor table so migration 16 proves its real ALTER/COPY boundary. + connection + .execute_batch( + "DROP INDEX logs_by_cursor; + DROP INDEX logs_by_session_cursor; + DROP INDEX logs_by_recorded_at_cursor; + ALTER TABLE logs RENAME TO logs_v16_fixture; + + CREATE TABLE logs ( + log_cursor INTEGER PRIMARY KEY AUTOINCREMENT, + recorded_at TEXT NOT NULL, + recorded_at_unix_nanos INTEGER NOT NULL, + source TEXT NOT NULL CHECK (source IN ('host_daemon', 'storage', 'codex_adapter')), + severity TEXT NOT NULL CHECK (severity IN ('info', 'warning', 'error')), + event_kind TEXT NOT NULL CHECK (event_kind IN ( + 'session_started', 'follow_up_started', 'turn_state_committed', + 'stop_confirmed', 'stop_not_confirmed', 'restart_recovery_pending', + 'store_opened' + )), + session_id TEXT REFERENCES sessions(session_id) ON DELETE SET NULL, + turn_id TEXT REFERENCES turns(turn_id) ON DELETE SET NULL, + session_state_revision TEXT, + turn_state_revision TEXT, + redacted INTEGER NOT NULL DEFAULT 1 CHECK (redacted = 1), + CHECK ( + (event_kind = 'store_opened' + AND session_id IS NULL AND turn_id IS NULL + AND session_state_revision IS NULL AND turn_state_revision IS NULL) + OR + (event_kind != 'store_opened' + AND session_id IS NOT NULL AND turn_id IS NOT NULL + AND session_state_revision IS NOT NULL AND turn_state_revision IS NOT NULL) + ) + ) STRICT; + + INSERT INTO logs SELECT * FROM logs_v16_fixture; + DROP TABLE logs_v16_fixture; + CREATE INDEX logs_by_cursor ON logs(log_cursor); + CREATE INDEX logs_by_session_cursor ON logs(session_id, log_cursor); + CREATE INDEX logs_by_recorded_at_cursor ON logs(recorded_at_unix_nanos, log_cursor);", + ) + .expect("restore the exact version fifteen logs schema"); +} + fn begin_maintenance( storage: &mut Storage, operation_id: &str, @@ -373,19 +419,19 @@ fn rebuild_storage_as_version_eleven_fixture(connection: &Connection) { DROP TABLE provider_smoke_hmac_key; ALTER TABLE setup_runs DROP COLUMN host_update_target_version; ALTER TABLE setup_runs DROP COLUMN host_update_artifact_digest; - DELETE FROM schema_migrations WHERE version IN (12, 13, 14, 15); + DELETE FROM schema_migrations WHERE version IN (12, 13, 14, 15, 16); PRAGMA user_version = 11;", ) .expect("restore the exact version eleven storage schema"); } #[test] -fn operational_evidence_schema_is_migrated_atomically_to_version_fifteen() { +fn operational_evidence_schema_is_migrated_atomically_to_version_sixteen() { let state = TempDir::new().expect("temporary state directory"); let (storage, _) = Storage::open(state.path()).expect("open storage"); let connection = storage.connection_for_test(); - assert_eq!(15_i64, pragma_integer(connection, "user_version")); + assert_eq!(16_i64, pragma_integer(connection, "user_version")); let versions = connection .prepare("SELECT version FROM schema_migrations ORDER BY version") .unwrap() @@ -396,7 +442,7 @@ fn operational_evidence_schema_is_migrated_atomically_to_version_fifteen() { assert_eq!( vec![ 1_i64, 2_i64, 3_i64, 4_i64, 5_i64, 6_i64, 7_i64, 8_i64, 9_i64, 10_i64, 11_i64, 12_i64, - 13_i64, 14_i64, 15_i64, + 13_i64, 14_i64, 15_i64, 16_i64, ], versions ); @@ -432,6 +478,120 @@ fn operational_evidence_schema_is_migrated_atomically_to_version_fifteen() { assert!(migration_backups(state.path()).is_empty()); } +#[test] +fn version_fifteen_logs_upgrade_preserves_rows_and_normalizes_lifecycle_sources() { + let state = TempDir::new().expect("temporary state directory"); + let (mut storage, _) = Storage::open(state.path()).expect("open current storage"); + let session = initial_session(&storage, SESSION_1, TURN_1, at(0)); + storage + .begin_session( + &session, + &admission( + IdempotentOperation::Run, + "migration-log-source", + "migration-log-source-request", + at(0), + ), + ) + .expect("persist a lifecycle Log Entry"); + let connection = storage.connection_for_test(); + rebuild_logs_as_v15_fixture(connection); + assert_eq!( + 1, + connection + .execute( + "INSERT INTO logs ( + recorded_at, recorded_at_unix_nanos, source, severity, event_kind, + session_id, turn_id, session_state_revision, turn_state_revision, redacted + ) + SELECT ?1, ?2, 'host_daemon', 'info', 'turn_state_committed', + sessions.session_id, turns.turn_id, + sessions.session_state_revision, turns.turn_state_revision, 1 + FROM sessions + JOIN turns ON turns.session_id = sessions.session_id + WHERE sessions.session_id = ?3 AND turns.turn_id = ?4", + params![at(1).format(&Rfc3339).unwrap(), 1_i64, SESSION_1, TURN_1,], + ) + .expect("insert a version fifteen lifecycle Log Entry"), + "the migration fixture must contain one legacy lifecycle Log Entry", + ); + let lifecycle_cursor = connection.last_insert_rowid(); + connection + .execute( + "INSERT INTO logs ( + recorded_at, recorded_at_unix_nanos, source, severity, + event_kind, redacted + ) VALUES (?1, ?2, 'storage', 'info', 'store_opened', 1)", + params![at(1).format(&Rfc3339).unwrap(), 1_i64], + ) + .expect("insert a version fifteen Log Entry"); + let preserved_cursor = connection.last_insert_rowid(); + let legacy_cursor_high_water = connection + .query_row( + "SELECT seq FROM sqlite_sequence WHERE name = 'logs'", + [], + |row| row.get::<_, i64>(0), + ) + .expect("load the version fifteen Log cursor high-water mark"); + connection + .execute("DELETE FROM schema_migrations WHERE version = 16", []) + .expect("remove version sixteen history"); + connection + .pragma_update(None, "user_version", 15) + .expect("mark version fifteen source schema"); + drop(storage); + + let (upgraded, _) = Storage::open(state.path()).expect("upgrade version fifteen storage"); + assert_eq!( + 1, + migration_backups(state.path()).len(), + "the destructive log-table rewrite must retain a rollback backup", + ); + let connection = upgraded.connection_for_test(); + assert_eq!(16_i64, pragma_integer(connection, "user_version")); + assert_eq!( + (lifecycle_cursor, "codex_adapter".to_string()), + connection + .query_row( + "SELECT log_cursor, source FROM logs WHERE log_cursor = ?1", + [lifecycle_cursor], + |row| Ok((row.get(0)?, row.get(1)?)), + ) + .expect("load the normalized lifecycle Log Entry") + ); + assert_eq!( + (preserved_cursor, "store_opened".to_string()), + connection + .query_row( + "SELECT log_cursor, event_kind FROM logs WHERE log_cursor = ?1", + [preserved_cursor], + |row| Ok((row.get(0)?, row.get(1)?)), + ) + .expect("load the preserved Log Entry") + ); + let post_upgrade_cursor_high_water = connection + .query_row( + "SELECT seq FROM sqlite_sequence WHERE name = 'logs'", + [], + |row| row.get::<_, i64>(0), + ) + .expect("load the upgraded Log cursor high-water mark"); + assert!(post_upgrade_cursor_high_water >= legacy_cursor_high_water); + connection + .execute( + "INSERT INTO logs ( + recorded_at, recorded_at_unix_nanos, source, severity, + event_kind, redacted + ) VALUES (?1, ?2, 'storage', 'info', 'store_opened', 1)", + params![at(2).format(&Rfc3339).unwrap(), 2_i64], + ) + .expect("append after the version sixteen migration"); + assert_eq!( + post_upgrade_cursor_high_water + 1, + connection.last_insert_rowid() + ); +} + #[test] fn version_eleven_provider_smoke_rows_upgrade_to_credential_scoped_cache() { let state = TempDir::new().expect("temporary state directory"); @@ -487,7 +647,7 @@ fn version_eleven_provider_smoke_rows_upgrade_to_credential_scoped_cache() { let mut upgraded = Storage::open_without_restart_recovery(state.path()) .expect("upgrade the version eleven store"); assert_eq!( - 15_i64, + 16_i64, pragma_integer(upgraded.connection_for_test(), "user_version") ); let credential_columns: i64 = upgraded @@ -590,7 +750,7 @@ fn version_ten_operation_rows_upgrade_without_data_loss_or_foreign_key_damage() storage .connection_for_test() .execute( - "DELETE FROM schema_migrations WHERE version IN (11, 12, 13, 14, 15)", + "DELETE FROM schema_migrations WHERE version IN (11, 12, 13, 14, 15, 16)", [], ) .expect("remove version eleven and twelve history"); @@ -603,7 +763,7 @@ fn version_ten_operation_rows_upgrade_without_data_loss_or_foreign_key_damage() let upgraded = Storage::open_without_restart_recovery(state.path()) .expect("upgrade populated version ten storage"); let connection = upgraded.connection_for_test(); - assert_eq!(15_i64, pragma_integer(connection, "user_version")); + assert_eq!(16_i64, pragma_integer(connection, "user_version")); assert_eq!( ("run".to_string(), "in_progress".to_string()), connection @@ -781,13 +941,13 @@ fn newer_schema_history_is_rejected_without_downgrade() { .connection_for_test() .execute( "INSERT INTO schema_migrations (version, checksum, applied_at) - VALUES (16, ?1, '2026-07-21T00:00:00Z')", + VALUES (17, ?1, '2026-07-21T00:00:00Z')", ["aaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaa"], ) .expect("insert future migration"); storage .connection_for_test() - .pragma_update(None, "user_version", 16) + .pragma_update(None, "user_version", 17) .expect("mark future schema"); drop(storage); @@ -798,7 +958,7 @@ fn newer_schema_history_is_rejected_without_downgrade() { assert_eq!(error.kind(), StorageErrorKind::MigrationIntegrity); let connection = Connection::open(state.path().join(DATABASE_FILE_NAME)) .expect("future database remains readable"); - assert_eq!(pragma_integer(&connection, "user_version"), 16); + assert_eq!(pragma_integer(&connection, "user_version"), 17); } #[test] @@ -834,7 +994,7 @@ fn version_seven_api_tokens_upgrade_to_explicit_active_state() { DROP TABLE provider_smoke_hmac_key; ALTER TABLE setup_runs DROP COLUMN host_update_target_version; ALTER TABLE setup_runs DROP COLUMN host_update_artifact_digest; - DELETE FROM schema_migrations WHERE version IN (8, 9, 10, 11, 12, 13, 14, 15); + DELETE FROM schema_migrations WHERE version IN (8, 9, 10, 11, 12, 13, 14, 15, 16); PRAGMA user_version = 7;", ) .expect("recreate the version seven token schema"); @@ -842,7 +1002,7 @@ fn version_seven_api_tokens_upgrade_to_explicit_active_state() { let (storage, _) = Storage::open(state.path()).expect("upgrade version seven storage"); assert_eq!( - 15_i64, + 16_i64, pragma_integer(storage.connection_for_test(), "user_version") ); let token_state: String = storage @@ -2101,7 +2261,7 @@ fn version_one_store_upgrades_without_replacing_existing_state() { ALTER TABLE api_tokens DROP COLUMN token_state; DROP TABLE authorized_provider_bindings; DROP TABLE provider_smoke_hmac_key; - DELETE FROM schema_migrations WHERE version IN (2, 3, 4, 5, 6, 7, 8, 9, 10, 11, 12, 13, 14, 15); + DELETE FROM schema_migrations WHERE version IN (2, 3, 4, 5, 6, 7, 8, 9, 10, 11, 12, 13, 14, 15, 16); PRAGMA user_version = 1;", ) .unwrap(); @@ -2110,7 +2270,7 @@ fn version_one_store_upgrades_without_replacing_existing_state() { let (storage, _) = Storage::open(state.path()).expect("upgrade version one storage"); assert_eq!(expected_host, storage.host_identity().unwrap()); assert_eq!( - 15_i64, + 16_i64, pragma_integer(storage.connection_for_test(), "user_version") ); @@ -2209,7 +2369,7 @@ fn assert_version_one_corruption_rejected_before_migration( DROP INDEX idempotency_operation_identity; DROP TABLE authorized_provider_bindings; DROP TABLE provider_smoke_hmac_key; - DELETE FROM schema_migrations WHERE version IN (2, 3, 4, 5, 6, 7, 8, 9, 10, 11, 12, 13, 14, 15); + DELETE FROM schema_migrations WHERE version IN (2, 3, 4, 5, 6, 7, 8, 9, 10, 11, 12, 13, 14, 15, 16); PRAGMA user_version = 1;", ) .expect("create a logically corrupt version one store"); @@ -2277,7 +2437,7 @@ fn failed_migration_rolls_back_partial_schema_and_preserves_existing_state() { DROP INDEX idempotency_operation_identity; DROP TABLE authorized_provider_bindings; DROP TABLE provider_smoke_hmac_key; - DELETE FROM schema_migrations WHERE version IN (2, 3, 4, 5, 6, 7, 8, 9, 10, 11, 12, 13, 14, 15); + DELETE FROM schema_migrations WHERE version IN (2, 3, 4, 5, 6, 7, 8, 9, 10, 11, 12, 13, 14, 15, 16); PRAGMA user_version = 1; CREATE TABLE migration_sentinel (value TEXT NOT NULL) STRICT; INSERT INTO migration_sentinel (value) VALUES ('preserve-me'); diff --git a/crates/satelle-host/src/storage/tests/retention.rs b/crates/satelle-host/src/storage/tests/retention.rs index ef27ffc6..8b2bbdd1 100644 --- a/crates/satelle-host/src/storage/tests/retention.rs +++ b/crates/satelle-host/src/storage/tests/retention.rs @@ -351,6 +351,33 @@ fn configured_session_retention_changes_only_the_session_cutoff() { ); } +#[test] +fn shorter_session_retention_waits_for_the_independent_log_window() { + let state = TempDir::new().expect("temporary state directory"); + let (mut storage, _) = Storage::open(state.path()).expect("open storage"); + let observed_at = at(40); + let terminal_at = observed_at - time::Duration::days(8); + storage.set_log_retention(time::Duration::days(30)); + let session = terminal_session( + &mut storage, + SESSION_1, + TURN_1, + terminal_at - time::Duration::seconds(1), + terminal_at, + ); + + storage + .prune_expired_session_metadata_with_retention( + observed_at, + time::Duration::days(7), + super::super::retention::DEFAULT_SETUP_LEDGER_RETENTION, + ) + .expect("retained logs must delay Session cleanup without a state conflict"); + + assert!(storage.load_session(session.id()).unwrap().is_some()); + assert!(table_rows_for_session(&storage, "logs", session.id()) > 0); +} + #[test] fn setup_ledger_retention_preserves_recovery_work_and_unrelated_host_state() { let state = TempDir::new().expect("temporary state directory"); diff --git a/crates/satelle-transport/src/client.rs b/crates/satelle-transport/src/client.rs index 80abe329..7b824fd9 100644 --- a/crates/satelle-transport/src/client.rs +++ b/crates/satelle-transport/src/client.rs @@ -25,7 +25,7 @@ use reqwest::redirect::Policy; use reqwest::{Method, StatusCode}; use satelle_core::session::{EffectiveModelRef, ProviderBindingRef}; use satelle_core::{DirectHostBinding, SessionId}; -use satelle_host::{ApiBearerToken, LogPageQuery}; +use satelle_host::{ApiBearerToken, LogPageMode, LogPageQuery}; use serde::de::DeserializeOwned; use std::fmt; use std::io::{self, Read}; @@ -646,7 +646,8 @@ impl DaemonClient { pub fn logs(&self, query: &LogPageQuery) -> Result { let (request, request_id) = self.protected_request(Method::GET, "/v1/logs")?; - self.send_authenticated(request.query(query), request_id, StatusCode::OK) + let response = self.send_authenticated(request.query(query), request_id, StatusCode::OK)?; + validate_logs_response(query, response) } pub fn create_session( @@ -881,6 +882,38 @@ impl DaemonClient { } } +fn validate_logs_response( + query: &LogPageQuery, + response: LogsPageResponse, +) -> Result { + let page = response.page(); + // Deserialization proves strict entry order and that next_cursor does not + // precede the final entry. Bind the remaining page claims to this exact + // authenticated request before any entry or continuation can be exposed. + let cursor_is_bound = query.cursor().is_none_or(|requested_cursor| { + page.next_cursor() >= requested_cursor + && page + .entries() + .first() + .is_none_or(|entry| entry.cursor() > requested_cursor) + }); + let continuation_is_exact = query.mode() != LogPageMode::Forward + || !page.truncated() + || page + .entries() + .last() + .is_some_and(|entry| page.next_cursor() == entry.cursor()); + let filters_are_bound = page + .entries() + .iter() + .all(|entry| query.matches_entry(entry)); + let size_is_bound = page.entries().len() <= query.limit(); + if !cursor_is_bound || !continuation_is_exact || !filters_are_bound || !size_is_bound { + return Err(DaemonClientError::ResponseContractViolation); + } + Ok(response) +} + impl fmt::Debug for DaemonClient { fn fmt(&self, formatter: &mut fmt::Formatter<'_>) -> fmt::Result { formatter @@ -1101,7 +1134,7 @@ fn validate_response_context( if response.request_id() != request_id { return Err(DaemonClientError::ResponseRequestIdMismatch); } - if response.host_identity() != expected_host_identity { + if !response.matches_host_identity(expected_host_identity) { return Err(DaemonClientError::ResponseHostIdentityMismatch); } Ok(()) @@ -1113,6 +1146,7 @@ mod tests { use satelle_core::{ ApiTokenSource, DirectHostBindingError, HostConfig, SatelleConfig, TransportKind, }; + use satelle_host::LogCursor; use std::io::{Read, Write}; use std::net::TcpListener; use std::sync::Arc; @@ -1508,6 +1542,294 @@ mod tests { } } + #[test] + fn logs_response_rejects_entry_from_another_host_identity() { + let request_id = RequestId::new(); + let response = serde_json::from_value::(serde_json::json!({ + "schema_version": "satelle.logs.page.v1", + "request_id": request_id.as_str(), + "host_identity": "host-expected", + "entries": [{ + "schema_version": "satelle.logs.entry.v1", + "cursor": "slc1_0000000000000001", + "timestamp": "1970-01-01T00:00:00Z", + "host_identity": "host-other", + "source": "storage", + "severity": "info", + "event": "store_opened", + "subject": { "kind": "host" }, + "message": "opened Host state store", + "redacted": true + }], + "next_cursor": "slc1_0000000000000001", + "truncated": false + })) + .expect("decode the contradictory log page fixture"); + + assert!(matches!( + validate_response_context(&response, &request_id, "host-expected"), + Err(DaemonClientError::ResponseHostIdentityMismatch) + )); + } + + #[test] + fn logs_response_rejects_a_forward_page_that_rewinds_the_requested_cursor() { + let request_id = RequestId::new(); + let requested_cursor = + LogCursor::parse("slc1_0000000000000002").expect("construct requested Log Cursor"); + let query = + LogPageQuery::forward(Some(requested_cursor), 50).expect("construct forward Log query"); + let stale_entry = serde_json::json!({ + "schema_version": "satelle.logs.entry.v1", + "cursor": "slc1_0000000000000001", + "timestamp": "1970-01-01T00:00:00Z", + "host_identity": "host-expected", + "source": "storage", + "severity": "info", + "event": "store_opened", + "subject": { "kind": "host" }, + "message": "opened Host state store", + "redacted": true + }); + + for (entries, next_cursor) in [ + (serde_json::json!([stale_entry]), "slc1_0000000000000002"), + (serde_json::json!([]), "slc1_0000000000000001"), + ] { + let response = serde_json::from_value::(serde_json::json!({ + "schema_version": "satelle.logs.page.v1", + "request_id": request_id.as_str(), + "host_identity": "host-expected", + "entries": entries, + "next_cursor": next_cursor, + "truncated": false + })) + .expect("decode the contradictory forward page fixture"); + + assert!(matches!( + validate_logs_response(&query, response), + Err(DaemonClientError::ResponseContractViolation) + )); + } + } + + #[test] + fn logs_response_rejects_a_truncated_page_that_skips_its_continuation() { + let request_id = RequestId::new(); + let requested_cursor = + LogCursor::parse("slc1_0000000000000002").expect("construct requested Log Cursor"); + let query = + LogPageQuery::forward(Some(requested_cursor), 50).expect("construct forward Log query"); + let entry = serde_json::json!({ + "schema_version": "satelle.logs.entry.v1", + "cursor": "slc1_0000000000000003", + "timestamp": "1970-01-01T00:00:00Z", + "host_identity": "host-expected", + "source": "storage", + "severity": "info", + "event": "store_opened", + "subject": { "kind": "host" }, + "message": "opened Host state store", + "redacted": true + }); + + for (entries, next_cursor) in [ + (serde_json::json!([entry]), "slc1_0000000000000005"), + (serde_json::json!([]), "slc1_0000000000000002"), + ] { + let response = serde_json::from_value::(serde_json::json!({ + "schema_version": "satelle.logs.page.v1", + "request_id": request_id.as_str(), + "host_identity": "host-expected", + "entries": entries, + "next_cursor": next_cursor, + "truncated": true + })) + .expect("decode the contradictory truncated page fixture"); + + assert!(matches!( + validate_logs_response(&query, response), + Err(DaemonClientError::ResponseContractViolation) + )); + } + } + + #[test] + fn logs_response_rejects_an_entry_outside_the_requested_session() { + let request_id = RequestId::new(); + let requested_session = SessionId::parse("rs_01890a5d-ac96-7b7c-8f89-37c3d0a66e11") + .expect("construct requested Session ID"); + let query = LogPageQuery::tail(50) + .expect("construct tail Log query") + .with_session(requested_session); + let response = serde_json::from_value::(serde_json::json!({ + "schema_version": "satelle.logs.page.v1", + "request_id": request_id.as_str(), + "host_identity": "host-expected", + "entries": [{ + "schema_version": "satelle.logs.entry.v1", + "cursor": "slc1_0000000000000001", + "timestamp": "1970-01-01T00:00:00Z", + "host_identity": "host-expected", + "source": "codex_adapter", + "severity": "info", + "event": "turn_state_committed", + "subject": { + "kind": "turn", + "session_id": "rs_01890a5d-ac96-7b7c-8f89-37c3d0a66e12", + "turn_id": "rt_01890a5d-ac96-7b7c-8f89-37c3d0a66e21", + "session_state_revision": 1, + "turn_state_revision": 1 + }, + "message": "committed Turn state", + "redacted": true + }], + "next_cursor": "slc1_0000000000000001", + "truncated": false + })) + .expect("decode the cross-Session Log page fixture"); + + assert!(matches!( + validate_logs_response(&query, response), + Err(DaemonClientError::ResponseContractViolation) + )); + } + + #[test] + fn logs_response_accepts_a_truncated_tail_page_at_the_host_high_water_cursor() { + let request_id = RequestId::new(); + let requested_session = SessionId::parse("rs_01890a5d-ac96-7b7c-8f89-37c3d0a66e11") + .expect("construct requested Session ID"); + let query = LogPageQuery::tail(1) + .expect("construct tail Log query") + .with_session(requested_session); + let response = serde_json::from_value::(serde_json::json!({ + "schema_version": "satelle.logs.page.v1", + "request_id": request_id.as_str(), + "host_identity": "host-expected", + "entries": [{ + "schema_version": "satelle.logs.entry.v1", + "cursor": "slc1_0000000000000003", + "timestamp": "1970-01-01T00:00:00Z", + "host_identity": "host-expected", + "source": "codex_adapter", + "severity": "info", + "event": "turn_state_committed", + "subject": { + "kind": "turn", + "session_id": "rs_01890a5d-ac96-7b7c-8f89-37c3d0a66e11", + "turn_id": "rt_01890a5d-ac96-7b7c-8f89-37c3d0a66e21", + "session_state_revision": 1, + "turn_state_revision": 1 + }, + "message": "committed Turn state", + "redacted": true + }], + "next_cursor": "slc1_0000000000000005", + "truncated": true + })) + .expect("decode the valid truncated tail page fixture"); + + assert!(validate_logs_response(&query, response).is_ok()); + } + + #[test] + fn logs_response_rejects_entries_outside_requested_filters() { + let request_id = RequestId::new(); + let requested_session = SessionId::parse("rs_01890a5d-ac96-7b7c-8f89-37c3d0a66e11") + .expect("construct requested Session ID"); + let query = LogPageQuery::tail(50) + .expect("construct tail Log query") + .with_session(requested_session) + .with_sources([satelle_host::LogSource::CodexAdapter]) + .with_minimum_severity(satelle_host::LogSeverity::Warning) + .with_since(time::OffsetDateTime::UNIX_EPOCH); + let valid_entry = serde_json::json!({ + "schema_version": "satelle.logs.entry.v1", + "cursor": "slc1_0000000000000001", + "timestamp": "1970-01-01T00:00:01Z", + "host_identity": "host-expected", + "source": "codex_adapter", + "severity": "warn", + "event": "turn_state_committed", + "subject": { + "kind": "turn", + "session_id": "rs_01890a5d-ac96-7b7c-8f89-37c3d0a66e11", + "turn_id": "rt_01890a5d-ac96-7b7c-8f89-37c3d0a66e21", + "session_state_revision": 1, + "turn_state_revision": 1 + }, + "message": "committed Turn state", + "redacted": true + }); + let response = |entry| { + serde_json::from_value::(serde_json::json!({ + "schema_version": "satelle.logs.page.v1", + "request_id": request_id.as_str(), + "host_identity": "host-expected", + "entries": [entry], + "next_cursor": "slc1_0000000000000001", + "truncated": false + })) + .expect("decode the filtered Log page fixture") + }; + assert!( + validate_logs_response(&query, response(valid_entry.clone())).is_ok(), + "the exact requested predicate must remain valid" + ); + + let mut wrong_source = valid_entry.clone(); + wrong_source["source"] = serde_json::json!("host_daemon"); + wrong_source["event"] = serde_json::json!("native_readiness_summary"); + wrong_source["message"] = serde_json::json!("native Computer Use readiness passed"); + let mut wrong_severity = valid_entry.clone(); + wrong_severity["severity"] = serde_json::json!("info"); + let mut wrong_timestamp = valid_entry.clone(); + wrong_timestamp["timestamp"] = serde_json::json!("1969-12-31T23:59:59Z"); + for entry in [wrong_source, wrong_severity, wrong_timestamp] { + assert!(matches!( + validate_logs_response(&query, response(entry)), + Err(DaemonClientError::ResponseContractViolation) + )); + } + } + + #[test] + fn logs_response_rejects_more_entries_than_the_requested_limit() { + let query = LogPageQuery::tail(1).expect("construct bounded tail Log query"); + let entry = |cursor| { + serde_json::json!({ + "schema_version": "satelle.logs.entry.v1", + "cursor": cursor, + "timestamp": "1970-01-01T00:00:00Z", + "host_identity": "host-expected", + "source": "storage", + "severity": "info", + "event": "store_opened", + "subject": { "kind": "host" }, + "message": "opened Host state store", + "redacted": true + }) + }; + let response = serde_json::from_value::(serde_json::json!({ + "schema_version": "satelle.logs.page.v1", + "request_id": RequestId::new().as_str(), + "host_identity": "host-expected", + "entries": [ + entry("slc1_0000000000000001"), + entry("slc1_0000000000000002") + ], + "next_cursor": "slc1_0000000000000002", + "truncated": false + })) + .expect("decode the oversized Log page fixture"); + + assert!(matches!( + validate_logs_response(&query, response), + Err(DaemonClientError::ResponseContractViolation) + )); + } + #[test] fn direct_client_bounds_stalled_requests() { let listener = TcpListener::bind("127.0.0.1:0").expect("bind stalled TLS server"); diff --git a/crates/satelle-transport/src/contract.rs b/crates/satelle-transport/src/contract.rs index 493e0949..abf19fc9 100644 --- a/crates/satelle-transport/src/contract.rs +++ b/crates/satelle-transport/src/contract.rs @@ -101,6 +101,10 @@ pub(super) use define_schema_token; pub(crate) trait AuthenticatedResponseContract { fn request_id(&self) -> &RequestId; fn host_identity(&self) -> &str; + + fn matches_host_identity(&self, expected_host_identity: &str) -> bool { + self.host_identity() == expected_host_identity + } } #[derive(Clone, Debug, Eq, Hash, Ord, PartialEq, PartialOrd)] diff --git a/crates/satelle-transport/src/contract/logs.rs b/crates/satelle-transport/src/contract/logs.rs index 5ef10a83..e12258bc 100644 --- a/crates/satelle-transport/src/contract/logs.rs +++ b/crates/satelle-transport/src/contract/logs.rs @@ -45,4 +45,15 @@ impl AuthenticatedResponseContract for LogsPageResponse { fn host_identity(&self) -> &str { self.host_identity() } + + fn matches_host_identity(&self, expected_host_identity: &str) -> bool { + // Entries are flattened under this authenticated envelope, so each + // nested identity must remain bound to the Host that produced it. + self.host_identity() == expected_host_identity + && self + .page() + .entries() + .iter() + .all(|entry| entry.host_identity().as_str() == expected_host_identity) + } } diff --git a/crates/satelle-transport/src/server/host_error.rs b/crates/satelle-transport/src/server/host_error.rs index 60948b77..7bcb529e 100644 --- a/crates/satelle-transport/src/server/host_error.rs +++ b/crates/satelle-transport/src/server/host_error.rs @@ -425,6 +425,11 @@ fn failure(error: &SatelleError) -> ApiFailure { // Process interruption is a Controller-local process-exit contract. // If it crosses the Host boundary, expose no extra API surface. | ErrorCode::Interrupted + // Log targeting and follow recovery are also Controller-local. The + // Host API exposes finite pages, not the CLI's polling lifecycle. + | ErrorCode::LogsTargetRequired + | ErrorCode::LogsFollowIdentityChanged + | ErrorCode::LogsFollowReconnectExhausted | ErrorCode::SshHostKeyVerificationRequired => ApiFailure { status: StatusCode::INTERNAL_SERVER_ERROR, code: ApiErrorCode::InternalError, diff --git a/docs/reference/configuration.mdx b/docs/reference/configuration.mdx index 0a192867..f74ae874 100644 --- a/docs/reference/configuration.mdx +++ b/docs/reference/configuration.mdx @@ -30,6 +30,7 @@ native_readiness_cache_ttl = "5m" provider_smoke_success_cache_ttl = "1440m" provider_smoke_failure_cache_ttl = "10m" session_metadata_retention = "30d" +sqlite_log_retention = "45d" operator_log_retained_files = 12 yolo = false @@ -42,9 +43,10 @@ Host fields include `transport`, `adapter`, `address`, `network`, `timeouts`, desktop selection, daemon path overrides, `setup_mode`, experimental-provider opt-in, daemon and readiness cache TTLs, Host-scoped `yolo`, project-selection permission, direct-transport identity and trust fields, and provider Secret -Source descriptors. `session_metadata_retention` accepts `h` or `d` values from -7 days through 365 days. `operator_log_retained_files` keeps 1 through 100 -rotated 10 MiB files and does not change SQLite log retention. +Source descriptors. `session_metadata_retention` and `sqlite_log_retention` +accept `h` or `d` values from 7 days through 365 days. They are independent. +`operator_log_retained_files` keeps 1 through 100 rotated 10 MiB files and does +not change SQLite log retention. The duration parser requires explicit units such as `500ms`, `30s`, or `2m`. Configuration does not perform environment-variable interpolation. @@ -65,6 +67,7 @@ provider_smoke_failure_cache_ttl = "5m" log_verbosity = "debug" trusted_profile = "maintenance" session_metadata_retention = "30d" +sqlite_log_retention = "45d" operator_log_retained_files = 12 yolo = false diff --git a/docs/reference/generated-cli.mdx b/docs/reference/generated-cli.mdx index e26ff6e9..4eee7e54 100644 --- a/docs/reference/generated-cli.mdx +++ b/docs/reference/generated-cli.mdx @@ -474,6 +474,8 @@ Options: --after Return entries strictly after this opaque cursor; conflicts with --since and --tail --source Include a source: host_daemon, storage, or codex_adapter; repeat to select multiple --level Set minimum severity: info, warn, or error (default: info) + -f, --follow Continue streaming new matching Log Entries + --no-reconnect Fail on transport loss instead of reconnecting --format [possible values: human, json] --json Alias for --format json -h, --help Print help