Skip to main content

rmcp_server_kit/
observability.rs

1use std::{
2    fmt,
3    io::{self, Write as _},
4    path::Path,
5    sync::{
6        Arc, Mutex, OnceLock,
7        atomic::{AtomicBool, AtomicU64, Ordering},
8        mpsc::{self, Receiver, SyncSender, TrySendError},
9    },
10    thread::{self, JoinHandle},
11    time::{Duration, Instant},
12};
13
14use tracing_subscriber::{
15    EnvFilter, Layer as _,
16    fmt::time::FormatTime,
17    layer::SubscriberExt,
18    util::{SubscriberInitExt, TryInitError},
19};
20
21use crate::{
22    config::ObservabilityConfig,
23    diagnostics::{DiagnosticExposure, set_diagnostic_exposure},
24    error::RmcpServerKitError,
25};
26
27const AUDIT_LOG_CHANNEL_CAPACITY: usize = 1024;
28const AUDIT_WRITER_POLL_INTERVAL: Duration = Duration::from_millis(50);
29const AUDIT_WRITER_JOIN_TIMEOUT: Duration = Duration::from_secs(5);
30const AUDIT_WRITER_JOIN_POLL: Duration = Duration::from_millis(10);
31const AUDIT_IO_FAILURE_WARNING_INTERVAL: Duration = Duration::from_secs(60);
32
33/// Timestamp formatter that emits local time via `chrono::Local`.
34#[derive(Clone, Copy)]
35struct LocalTime;
36
37impl FormatTime for LocalTime {
38    fn format_time(&self, w: &mut tracing_subscriber::fmt::format::Writer<'_>) -> fmt::Result {
39        write!(
40            w,
41            "{}",
42            chrono::Local::now().format("%Y-%m-%dT%H:%M:%S%.3f%:z")
43        )
44    }
45}
46
47/// Initialize structured logging from an [`ObservabilityConfig`].
48///
49/// Deprecated compatibility entry point. Prefer
50/// [`init_tracing_from_config_strict`], which returns a [`TracingGuard`] and
51/// fails closed when `audit_log_path` is configured but cannot be opened.
52///
53/// Respects `RUST_LOG` env var if set; otherwise uses `config.log_level`.
54/// When `log_format` is `"json"`, emits machine-readable JSON lines.
55/// When `audit_log_path` is set, appends an additional JSON log file
56/// at INFO level for audit trail purposes. This legacy function keeps its
57/// fail-open audit-log behaviour for source compatibility: audit setup errors
58/// are logged as warnings after subscriber initialization succeeds.
59///
60/// # Errors
61///
62/// Returns [`TryInitError`] if a global tracing subscriber has already
63/// been installed (e.g. by a previous call to this function or
64/// [`init_tracing`]). Callers that want to tolerate double-initialization
65/// (such as test harnesses) can ignore the error.
66#[deprecated(
67    since = "3.8.0",
68    note = "use `init_tracing_from_config_strict` and hold the returned `TracingGuard` for process lifetime"
69)]
70pub fn init_tracing_from_config(config: &ObservabilityConfig) -> Result<(), TryInitError> {
71    let filter =
72        EnvFilter::try_from_default_env().unwrap_or_else(|_| EnvFilter::new(&config.log_level));
73
74    let audit_setup = prepare_tracing_audit_lenient(config);
75
76    // "pretty" and "text" are aliases for human-readable output.
77    let result = if config.log_format == "json" {
78        let subscriber = tracing_subscriber::registry().with(filter).with(
79            tracing_subscriber::fmt::layer()
80                .json()
81                .with_timer(LocalTime)
82                .with_writer(io::stderr),
83        );
84        init_with_optional_audit(subscriber, audit_setup.writer)
85    } else {
86        let subscriber = tracing_subscriber::registry().with(filter).with(
87            tracing_subscriber::fmt::layer()
88                .with_timer(LocalTime)
89                .with_writer(io::stderr),
90        );
91        init_with_optional_audit(subscriber, audit_setup.writer)
92    };
93
94    if result.is_ok() {
95        retain_legacy_guard(audit_setup.guard);
96        for warning in audit_setup.warnings {
97            tracing::warn!(warning = %warning, "audit logging initialization warning");
98        }
99    }
100
101    result
102}
103
104/// Owns background resources installed by strict tracing initialization.
105///
106/// Hold this guard for the lifetime of the process. When an audit log is
107/// configured, the guard owns the dedicated audit writer thread's shutdown
108/// signal and join handle. Dropping it signals shutdown and makes a best-effort,
109/// time-bounded (5s) attempt to drain queued audit entries, flush the file, and
110/// join the writer thread. This is not a durability guarantee: audit events
111/// emitted after drop are lost, and if the writer thread is blocked on a slow or
112/// stuck filesystem past the timeout, `Drop` returns and remaining queued entries
113/// may never reach disk.
114#[must_use = "hold TracingGuard for the process lifetime so audit logs keep draining"]
115#[non_exhaustive]
116pub struct TracingGuard {
117    audit: Option<AuditWorkerGuard>,
118}
119
120impl fmt::Debug for TracingGuard {
121    fn fmt(&self, f: &mut fmt::Formatter<'_>) -> fmt::Result {
122        f.debug_struct("TracingGuard")
123            .field("audit_enabled", &self.audit.is_some())
124            .field(
125                "diagnostic_plaintext_oauth_tokens",
126                &crate::diagnostics::plaintext_oauth_tokens(),
127            )
128            .field(
129                "diagnostic_oauth_claim_values",
130                &crate::diagnostics::oauth_claim_values(),
131            )
132            .field(
133                "diagnostic_tool_call_arguments",
134                &crate::diagnostics::tool_call_arguments(),
135            )
136            .finish()
137    }
138}
139
140impl TracingGuard {
141    const fn none() -> Self {
142        Self { audit: None }
143    }
144
145    const fn audit(audit: AuditWorkerGuard) -> Self {
146        Self { audit: Some(audit) }
147    }
148}
149
150impl Drop for TracingGuard {
151    fn drop(&mut self) {
152        let _ = self.audit.take();
153    }
154}
155
156/// Initialize structured logging from an [`ObservabilityConfig`] and fail
157/// closed when the configured audit log cannot be opened.
158///
159/// Respects `RUST_LOG` env var if set; otherwise uses `config.log_level`.
160/// When `log_format` is `"json"`, emits machine-readable JSON lines. When
161/// `audit_log_path` is set, appends an additional JSON log file at INFO level
162/// through a bounded non-blocking channel drained by a dedicated writer thread.
163///
164/// Hold the returned [`TracingGuard`] for the process lifetime. Dropping it
165/// signals the audit writer to stop and makes a best-effort, time-bounded (5s)
166/// drain/flush attempt; audit events emitted after drop are lost, and a writer
167/// blocked past the timeout may leave queued entries unwritten.
168///
169/// # Errors
170///
171/// Returns [`RmcpServerKitError::Startup`] if audit-log directory creation,
172/// audit-log opening, audit writer thread spawning, or global tracing
173/// subscriber installation fails.
174pub fn init_tracing_from_config_strict(
175    config: &ObservabilityConfig,
176) -> Result<TracingGuard, RmcpServerKitError> {
177    let filter =
178        EnvFilter::try_from_default_env().unwrap_or_else(|_| EnvFilter::new(&config.log_level));
179    let audit_setup = prepare_tracing_audit_strict(config)?;
180
181    // "pretty" and "text" are aliases for human-readable output.
182    let result = if config.log_format == "json" {
183        let subscriber = tracing_subscriber::registry().with(filter).with(
184            tracing_subscriber::fmt::layer()
185                .json()
186                .with_timer(LocalTime)
187                .with_writer(io::stderr),
188        );
189        init_with_optional_audit(subscriber, audit_setup.writer)
190    } else {
191        let subscriber = tracing_subscriber::registry().with(filter).with(
192            tracing_subscriber::fmt::layer()
193                .with_timer(LocalTime)
194                .with_writer(io::stderr),
195        );
196        init_with_optional_audit(subscriber, audit_setup.writer)
197    };
198
199    result.map_err(|error| {
200        RmcpServerKitError::Startup(format!("failed to initialize tracing subscriber: {error}"))
201    })?;
202
203    // SECURITY: arm the process-global plaintext diagnostic switches only
204    // AFTER every fallible step has succeeded. Setting them first meant a
205    // failed strict init returned `Err` with secret logging left enabled
206    // process-wide, so an embedder that ignored the error (or fell back to
207    // the deprecated lenient initializer) would log tokens and claims.
208    set_diagnostic_exposure(&DiagnosticExposure {
209        plaintext_oauth_tokens: config.log_plaintext_oauth_tokens,
210        oauth_claim_values: config.log_oauth_claim_values,
211        tool_call_arguments: config.log_tool_call_arguments,
212        upstream_error_bodies: config.log_upstream_error_bodies,
213    });
214
215    for warning in audit_setup.warnings {
216        tracing::warn!(warning = %warning, "audit logging initialization warning");
217    }
218
219    Ok(audit_setup.guard)
220}
221
222/// Attach an optional audit JSON log layer and initialize the subscriber.
223///
224/// Extracted to avoid duplicating the audit layer construction in both
225/// the JSON and pretty format branches of strict and legacy initialization.
226///
227/// Uses [`SubscriberInitExt::try_init`] so that a previously-installed
228/// global subscriber yields [`TryInitError`] rather than panicking.
229fn init_with_optional_audit<S>(
230    subscriber: S,
231    audit_writer: Option<AuditFile>,
232) -> Result<(), TryInitError>
233where
234    S: tracing::Subscriber
235        + for<'span> tracing_subscriber::registry::LookupSpan<'span>
236        + Send
237        + Sync
238        + 'static,
239{
240    if let Some(writer) = audit_writer {
241        subscriber
242            .with(
243                tracing_subscriber::fmt::layer()
244                    .json()
245                    .with_timer(LocalTime)
246                    .with_writer(writer)
247                    .with_filter(tracing_subscriber::filter::LevelFilter::INFO),
248            )
249            .try_init()
250    } else {
251        subscriber.try_init()
252    }
253}
254
255/// Initialize structured logging with a simple filter string.
256///
257/// Convenience function for callers that don't use [`ObservabilityConfig`].
258/// Respects `RUST_LOG` env var. Falls back to `default_filter` (e.g. `"info"`).
259///
260/// # Errors
261///
262/// Returns [`TryInitError`] if a global tracing subscriber has already
263/// been installed. This makes the function safe to call repeatedly from
264/// tests or embedders without panicking.
265pub fn init_tracing(default_filter: &str) -> Result<(), TryInitError> {
266    tracing_subscriber::registry()
267        .with(EnvFilter::try_from_default_env().unwrap_or_else(|_| EnvFilter::new(default_filter)))
268        .with(
269            tracing_subscriber::fmt::layer()
270                .with_timer(LocalTime)
271                .with_writer(io::stderr),
272        )
273        .try_init()
274}
275
276/// Newtype wrapper around a non-blocking audit writer channel.
277///
278/// Implements `MakeWriter` so it can be used with `tracing_subscriber::fmt`.
279#[derive(Clone)]
280struct AuditFile {
281    sender: SyncSender<AuditMessage>,
282    dropped: Arc<AtomicU64>,
283}
284
285impl<'a> tracing_subscriber::fmt::MakeWriter<'a> for AuditFile {
286    type Writer = AuditFileWriter;
287
288    fn make_writer(&'a self) -> Self::Writer {
289        AuditFileWriter {
290            sender: self.sender.clone(),
291            dropped: Arc::clone(&self.dropped),
292        }
293    }
294}
295
296/// A non-blocking audit writer handle used directly at tracing call sites.
297struct AuditFileWriter {
298    sender: SyncSender<AuditMessage>,
299    dropped: Arc<AtomicU64>,
300}
301
302impl io::Write for AuditFileWriter {
303    fn write(&mut self, buf: &[u8]) -> io::Result<usize> {
304        if buf.is_empty() {
305            return Ok(0);
306        }
307
308        // Overflow policy: drop-newest when the bounded channel is full and
309        // account for the loss in an atomic counter. Blocking here would put
310        // request-handling tokio workers back on the slow/full disk path this
311        // writer exists to remove. The background writer emits the aggregate
312        // dropped count into the audit log once it catches up.
313        if matches!(
314            self.sender.try_send(AuditMessage::Write(buf.to_vec())),
315            Err(TrySendError::Full(_))
316        ) {
317            self.dropped.fetch_add(1, Ordering::Relaxed);
318        }
319        Ok(buf.len())
320    }
321
322    fn flush(&mut self) -> io::Result<()> {
323        let _ = self.sender.try_send(AuditMessage::Flush);
324        Ok(())
325    }
326}
327
328enum AuditMessage {
329    Write(Vec<u8>),
330    Flush,
331}
332
333struct AuditWorkerGuard {
334    shutdown: Arc<AtomicBool>,
335    wake_sender: SyncSender<AuditMessage>,
336    thread: Option<JoinHandle<()>>,
337}
338
339impl Drop for AuditWorkerGuard {
340    fn drop(&mut self) {
341        self.shutdown.store(true, Ordering::Release);
342        let _ = self.wake_sender.try_send(AuditMessage::Flush);
343
344        let Some(thread) = self.thread.take() else {
345            return;
346        };
347        let deadline = Instant::now() + AUDIT_WRITER_JOIN_TIMEOUT;
348        while !thread.is_finished() {
349            let now = Instant::now();
350            if now >= deadline {
351                return;
352            }
353            thread::park_timeout((deadline - now).min(AUDIT_WRITER_JOIN_POLL));
354        }
355        let _ = thread.join();
356    }
357}
358
359struct AuditWorker<W> {
360    file: W,
361    receiver: Receiver<AuditMessage>,
362    shutdown: Arc<AtomicBool>,
363    dropped: Arc<AtomicU64>,
364    io_failures: Arc<AtomicU64>,
365    last_io_failure_warning: Option<Instant>,
366}
367
368impl<W> AuditWorker<W>
369where
370    W: io::Write,
371{
372    fn run(mut self) {
373        loop {
374            match self.receiver.recv_timeout(AUDIT_WRITER_POLL_INTERVAL) {
375                Ok(message) => self.handle_message(message),
376                Err(mpsc::RecvTimeoutError::Timeout) => {
377                    if self.shutdown.load(Ordering::Acquire) {
378                        break;
379                    }
380                    continue;
381                }
382                Err(mpsc::RecvTimeoutError::Disconnected) => break,
383            }
384
385            if self.shutdown.load(Ordering::Acquire) {
386                break;
387            }
388        }
389
390        while let Ok(message) = self.receiver.try_recv() {
391            self.handle_message(message);
392        }
393        self.write_dropped_warning();
394        if let Err(error) = self.file.flush() {
395            self.record_io_failure("flush", &error);
396        }
397    }
398
399    fn handle_message(&mut self, message: AuditMessage) {
400        match message {
401            AuditMessage::Write(bytes) => {
402                if let Err(error) = self.file.write_all(&bytes) {
403                    self.record_io_failure("write", &error);
404                }
405                self.write_dropped_warning();
406            }
407            AuditMessage::Flush => {
408                self.write_dropped_warning();
409                if let Err(error) = self.file.flush() {
410                    self.record_io_failure("flush", &error);
411                }
412            }
413        }
414    }
415
416    fn write_dropped_warning(&mut self) {
417        let count = self.dropped.swap(0, Ordering::Relaxed);
418        if count == 0 {
419            return;
420        }
421        if let Err(error) = writeln!(
422            self.file,
423            "{{\"level\":\"WARN\",\"target\":\"rmcp_server_kit::observability\",\"message\":\"audit log entries dropped because writer channel was full\",\"dropped\":{count}}}"
424        ) {
425            self.record_io_failure("write_dropped_warning", &error);
426        }
427    }
428
429    fn record_io_failure(&mut self, operation: &'static str, error: &io::Error) {
430        let failure_count = self.io_failures.fetch_add(1, Ordering::Relaxed) + 1;
431        if self.io_failure_warning_due(Instant::now()) {
432            write_audit_io_failure_warning(operation, failure_count, error);
433        }
434    }
435
436    fn io_failure_warning_due(&mut self, now: Instant) -> bool {
437        let due = self
438            .last_io_failure_warning
439            .is_none_or(|last| now.duration_since(last) >= AUDIT_IO_FAILURE_WARNING_INTERVAL);
440        if due {
441            self.last_io_failure_warning = Some(now);
442        }
443        due
444    }
445}
446
447#[allow(
448    clippy::print_stderr,
449    reason = "audit writer failure reporting deliberately uses process stderr as the last-resort sink; routing through tracing would recurse into the failing audit writer"
450)]
451fn write_audit_io_failure_warning(
452    operation: &'static str,
453    failure_count: u64,
454    representative_error: &io::Error,
455) {
456    // This MUST NOT use tracing/log. The tracing subscriber owns the audit
457    // writer that just failed, so re-entering it from the writer thread could
458    // recursively enqueue more audit writes or deadlock during shutdown.
459    let mut stderr = io::stderr().lock();
460    let _ = writeln!(
461        stderr,
462        "rmcp-server-kit audit log {operation} failed; failures_total={failure_count}; error={representative_error}"
463    );
464}
465
466struct AuditSetup {
467    writer: Option<AuditFile>,
468    guard: TracingGuard,
469    warnings: Vec<String>,
470}
471
472impl AuditSetup {
473    const fn none() -> Self {
474        Self {
475            writer: None,
476            guard: TracingGuard::none(),
477            warnings: Vec::new(),
478        }
479    }
480}
481
482/// Open the audit log file for appending and spawn its writer thread.
483///
484/// Returns a non-blocking writer, its guard, and any warnings encountered while
485/// preparing it.
486///
487/// # Log rotation
488///
489/// The background writer thread opens the file in append mode and holds a
490/// long-lived handle for the lifetime of the [`TracingGuard`]. There is **no**
491/// built-in rotation, no SIGHUP-style reopen, and no compression. Operators are
492/// expected to use an external rotator such as `logrotate` (Linux) or
493/// `newsyslog` (BSD / macOS) configured with `copytruncate` (or equivalent) so
494/// the inode this handle points at is preserved across rotations. If the
495/// rotator instead renames + recreates the file, this writer will keep writing
496/// to the renamed (rotated) inode until the guard is dropped or the process
497/// restarts.
498fn open_audit_file(path: &Path) -> Result<AuditSetup, String> {
499    // Ensure parent directory exists.
500    if let Some(parent) = path.parent()
501        && !parent.as_os_str().is_empty()
502        && parent.exists()
503        && !parent.is_dir()
504    {
505        return Err(format!(
506            "audit log parent path is not a directory: {}",
507            parent.display()
508        ));
509    }
510    if let Some(parent) = path.parent()
511        && !parent.as_os_str().is_empty()
512        && !parent.exists()
513        && let Err(e) = std::fs::create_dir_all(parent)
514    {
515        return Err(format!(
516            "failed to create audit log directory {}: {e}",
517            parent.display()
518        ));
519    }
520
521    let file = create_private_audit_file(path)?;
522
523    let warnings = audit_file_permission_warnings(&file);
524
525    let (sender, receiver) = mpsc::sync_channel(AUDIT_LOG_CHANNEL_CAPACITY);
526    let dropped = Arc::new(AtomicU64::new(0));
527    let shutdown = Arc::new(AtomicBool::new(false));
528    let worker_dropped = Arc::clone(&dropped);
529    let worker_shutdown = Arc::clone(&shutdown);
530    let thread = thread::Builder::new()
531        .name("rmcp-audit-log-writer".into())
532        .spawn(move || {
533            AuditWorker {
534                file,
535                receiver,
536                shutdown: worker_shutdown,
537                dropped: worker_dropped,
538                io_failures: Arc::new(AtomicU64::new(0)),
539                last_io_failure_warning: None,
540            }
541            .run();
542        })
543        .map_err(|e| {
544            format!(
545                "failed to spawn audit log writer for {}: {e}",
546                path.display()
547            )
548        })?;
549
550    Ok(AuditSetup {
551        writer: Some(AuditFile {
552            sender: sender.clone(),
553            dropped,
554        }),
555        guard: TracingGuard::audit(AuditWorkerGuard {
556            shutdown,
557            wake_sender: sender,
558            thread: Some(thread),
559        }),
560        warnings,
561    })
562}
563
564fn prepare_tracing_audit_strict(
565    config: &ObservabilityConfig,
566) -> Result<AuditSetup, RmcpServerKitError> {
567    match config.audit_log_path.as_deref() {
568        Some(path) => open_audit_file(path).map_err(|error| {
569            RmcpServerKitError::Startup(format!("audit log initialization failed: {error}"))
570        }),
571        None => Ok(AuditSetup::none()),
572    }
573}
574
575fn prepare_tracing_audit_lenient(config: &ObservabilityConfig) -> AuditSetup {
576    match config.audit_log_path.as_deref() {
577        Some(path) => match open_audit_file(path) {
578            Ok(setup) => setup,
579            Err(warning) => AuditSetup {
580                writer: None,
581                guard: TracingGuard::none(),
582                warnings: vec![warning],
583            },
584        },
585        None => AuditSetup::none(),
586    }
587}
588
589fn retain_legacy_guard(guard: TracingGuard) {
590    if guard.audit.is_none() {
591        return;
592    }
593
594    let mut guards = match legacy_tracing_guards().lock() {
595        Ok(guards) => guards,
596        Err(poisoned) => poisoned.into_inner(),
597    };
598    guards.push(guard);
599}
600
601fn legacy_tracing_guards() -> &'static Mutex<Vec<TracingGuard>> {
602    static GUARDS: OnceLock<Mutex<Vec<TracingGuard>>> = OnceLock::new();
603    GUARDS.get_or_init(|| Mutex::new(Vec::new()))
604}
605
606/// Create (or append to) the audit log with owner-only permissions.
607///
608/// SECURITY: the mode is applied by `open` itself rather than by a following
609/// `set_permissions`. The two-step form leaves a window in which the file
610/// exists with umask-derived permissions, so any local principal can open it
611/// before the mode is tightened. Audit logs carry identities and, under the
612/// diagnostic switches, credential material.
613#[cfg(unix)]
614fn create_private_audit_file(path: &Path) -> Result<std::fs::File, String> {
615    use std::os::unix::fs::OpenOptionsExt as _;
616
617    std::fs::OpenOptions::new()
618        .mode(0o600)
619        .create(true)
620        .append(true)
621        .open(path)
622        .map_err(|e| format!("failed to open audit log file {}: {e}", path.display()))
623}
624
625/// Create (or append to) the audit log with an owner-only DACL.
626///
627/// SECURITY: Windows has no safe creation-time equivalent of `mode(0o600)`.
628/// Rust std cannot pass `SECURITY_ATTRIBUTES` to file creation
629/// (rust-lang/libs-team#324), so the file is created and the protected
630/// owner-only DACL applied immediately afterwards. That leaves a small
631/// create-then-harden window the Unix path does not have: this removes the
632/// *persistent* exposure, not the momentary one. It is not parity.
633///
634/// If hardening fails once the file exists, the file is deleted best-effort and
635/// the error states whether that succeeded, so an operator knows whether an
636/// unprotected audit log may remain on disk. Continuing instead would recreate
637/// the silent security-control failure this replaced.
638#[cfg(windows)]
639fn create_private_audit_file(path: &Path) -> Result<std::fs::File, String> {
640    use std::ffi::OsString;
641
642    use windows_permissions::{
643        LocalBox, SecurityDescriptor,
644        constants::{SeObjectType, SecurityInformation},
645        wrappers,
646    };
647
648    let file = std::fs::OpenOptions::new()
649        .create(true)
650        .append(true)
651        .open(path)
652        .map_err(|e| format!("failed to open audit log file {}: {e}", path.display()))?;
653
654    let harden = || -> Result<(), String> {
655        let sid = windows_permissions::utilities::current_process_sid()
656            .map_err(|e| format!("cannot determine the current process SID: {e}"))?;
657        // `D:P` protects the DACL, discarding inherited ACEs; a single
658        // FA (full access) ACE for this process's SID is the owner-only grant.
659        let sd: LocalBox<SecurityDescriptor> = format!("D:P(A;;FA;;;{sid})")
660            .parse()
661            .map_err(|e| format!("cannot build an owner-only security descriptor: {e}"))?;
662        let dacl = sd
663            .dacl()
664            .ok_or_else(|| "owner-only security descriptor carried no DACL".to_owned())?;
665        let name: OsString = path.as_os_str().to_owned();
666        wrappers::SetNamedSecurityInfo(
667            &name,
668            SeObjectType::SE_FILE_OBJECT,
669            SecurityInformation::Dacl | SecurityInformation::ProtectedDacl,
670            None,
671            None,
672            Some(dacl),
673            None,
674        )
675        .map_err(|e| format!("cannot apply the owner-only DACL: {e}"))
676    };
677
678    match harden() {
679        Ok(()) => Ok(file),
680        Err(reason) => {
681            drop(file);
682            let cleanup = match std::fs::remove_file(path) {
683                Ok(()) => "the unprotected file was deleted".to_owned(),
684                Err(e) => format!(
685                    "the unprotected file could NOT be deleted and may remain at {}: {e}",
686                    path.display()
687                ),
688            };
689            Err(format!(
690                "audit log ACL hardening failed for {}: {reason}; {cleanup}",
691                path.display()
692            ))
693        }
694    }
695}
696
697/// Refuse to create an audit log where owner-only access cannot be guaranteed.
698///
699/// SECURITY: this platform has neither POSIX mode bits nor a supported ACL
700/// path. Creating the file anyway would let it inherit directory permissions
701/// while the operator believes auditing is protected. Failing here turns a
702/// silent security-control failure into an explicit one: strict init reports a
703/// startup error, and the deprecated lenient init warns and installs no audit
704/// sink.
705#[cfg(not(any(unix, windows)))]
706fn create_private_audit_file(path: &Path) -> Result<std::fs::File, String> {
707    Err(format!(
708        "audit log private permissions are unsupported on this platform: cannot \
709         guarantee owner-only access for {}; audit logging disabled",
710        path.display()
711    ))
712}
713
714#[cfg(unix)]
715fn audit_file_permission_warnings(file: &std::fs::File) -> Vec<String> {
716    use std::os::unix::fs::PermissionsExt;
717
718    let mut warnings = Vec::new();
719    // A pre-existing file keeps its old mode: `OpenOptions::mode` applies only
720    // when `open` creates the file, so tighten it explicitly here.
721    if let Err(e) = file.set_permissions(std::fs::Permissions::from_mode(0o600)) {
722        warnings.push(format!("failed to set audit log permissions to 0o600: {e}"));
723    }
724    warnings
725}
726
727#[cfg(not(unix))]
728fn audit_file_permission_warnings(_file: &std::fs::File) -> Vec<String> {
729    Vec::new()
730}
731
732#[cfg(test)]
733mod tests {
734    #![allow(
735        clippy::unwrap_used,
736        clippy::expect_used,
737        clippy::panic,
738        clippy::indexing_slicing,
739        clippy::unwrap_in_result,
740        clippy::print_stdout,
741        clippy::print_stderr,
742        reason = "test-only relaxations; production code uses ? and tracing"
743    )]
744    #[cfg(unix)]
745    use std::io::Write as _;
746    use std::{
747        path::PathBuf,
748        sync::{
749            Arc,
750            atomic::{AtomicBool, AtomicU64, Ordering},
751            mpsc,
752        },
753        time::{Duration, Instant, SystemTime, UNIX_EPOCH},
754    };
755
756    #[cfg(unix)]
757    use tracing_subscriber::{Layer as _, fmt::MakeWriter as _, layer::SubscriberExt as _};
758
759    #[cfg(not(any(unix, windows)))]
760    use super::prepare_tracing_audit_lenient;
761    use super::{AuditMessage, AuditWorker, init_tracing, prepare_tracing_audit_strict};
762    use crate::{config::ObservabilityConfig, error::RmcpServerKitError};
763
764    struct FailingAuditSink;
765
766    impl std::io::Write for FailingAuditSink {
767        fn write(&mut self, _buf: &[u8]) -> std::io::Result<usize> {
768            Err(std::io::Error::other("injected audit sink write failure"))
769        }
770
771        fn flush(&mut self) -> std::io::Result<()> {
772            Err(std::io::Error::other("injected audit sink flush failure"))
773        }
774    }
775
776    #[test]
777    fn config_format_valid() {
778        let config = ObservabilityConfig {
779            log_level: "debug".into(),
780            log_format: "json".into(),
781            audit_log_path: None,
782            log_request_headers: false,
783            metrics_enabled: false,
784            metrics_bind: "127.0.0.1:9090".into(),
785            log_plaintext_oauth_tokens: false,
786            log_oauth_claim_values: false,
787            log_tool_call_arguments: false,
788            log_upstream_error_bodies: false,
789        };
790        assert!(config.log_format == "json" || config.log_format == "pretty");
791    }
792
793    /// Calling either `init_tracing` entry point twice in the same process
794    /// must NOT panic. The second (and any subsequent) call must return
795    /// `Err(TryInitError)` instead. This guards against regressions of the
796    /// pre-0.11 `.init()` behaviour, which aborted the process when a
797    /// global subscriber was already installed (e.g. by a sibling test).
798    ///
799    /// All four call orderings are exercised in a single test because the
800    /// global tracing subscriber is process-wide state - we cannot rely on
801    /// test isolation here.
802    #[test]
803    fn init_tracing_double_init_returns_err_not_panic() {
804        // First call: may succeed or fail depending on whether another
805        // test in this binary already installed a subscriber. Either is
806        // acceptable; we only require that it does not panic.
807        let _ = init_tracing("info");
808
809        // Second call: a global subscriber is now guaranteed to exist,
810        // so this MUST return Err and MUST NOT panic.
811        let second = init_tracing("debug");
812        assert!(
813            second.is_err(),
814            "second init_tracing must return Err once a global subscriber exists"
815        );
816
817        // The companion entry point must also report Err rather than panic.
818        let cfg = ObservabilityConfig {
819            log_level: "info".into(),
820            log_format: "pretty".into(),
821            audit_log_path: None,
822            log_request_headers: false,
823            metrics_enabled: false,
824            metrics_bind: "127.0.0.1:9090".into(),
825            log_plaintext_oauth_tokens: false,
826            log_oauth_claim_values: false,
827            log_tool_call_arguments: false,
828            log_upstream_error_bodies: false,
829        };
830        #[allow(
831            deprecated,
832            reason = "this regression test explicitly covers the legacy fail-open API"
833        )]
834        let third = super::init_tracing_from_config(&cfg);
835        assert!(
836            third.is_err(),
837            "init_tracing_from_config must return Err once a global subscriber exists"
838        );
839    }
840
841    #[test]
842    fn strict_init_fails_when_audit_path_unopenable() {
843        let root_file = unique_temp_path("audit-parent-file");
844        std::fs::write(&root_file, b"not a directory").expect("create parent file fixture");
845        let audit_path = root_file.join("audit.log");
846        let config = observability_config(Some(audit_path));
847
848        let result = prepare_tracing_audit_strict(&config);
849
850        assert!(
851            matches!(result, Err(RmcpServerKitError::Startup(_))),
852            "unopenable audit path must fail closed with Startup"
853        );
854        std::fs::remove_file(&root_file).expect("remove parent file fixture");
855    }
856
857    #[test]
858    fn strict_init_leaves_diagnostic_exposure_disarmed_on_startup_failure() {
859        // SECURITY regression: exposure used to be armed before the fallible
860        // audit setup, so a failed strict init returned Err with plaintext
861        // token/claim logging enabled process-wide.
862        let _guard = crate::diagnostics::ExposureTestGuard::acquire();
863        crate::diagnostics::set_diagnostic_exposure(
864            &crate::diagnostics::DiagnosticExposure::default(),
865        );
866        let root_file = unique_temp_path("audit-parent-file-diagnostics");
867        std::fs::write(&root_file, b"not a directory").expect("create parent file fixture");
868        let mut config = observability_config(Some(root_file.join("audit.log")));
869        config.log_plaintext_oauth_tokens = true;
870        config.log_oauth_claim_values = true;
871        config.log_tool_call_arguments = true;
872
873        let result = super::init_tracing_from_config_strict(&config);
874
875        assert!(
876            matches!(result, Err(RmcpServerKitError::Startup(_))),
877            "unopenable audit path must keep subscriber initialization out of this test"
878        );
879        assert!(!crate::diagnostics::plaintext_oauth_tokens());
880        assert!(!crate::diagnostics::oauth_claim_values());
881        assert!(!crate::diagnostics::tool_call_arguments());
882        std::fs::remove_file(&root_file).expect("remove parent file fixture");
883    }
884
885    #[test]
886    #[cfg(unix)]
887    fn strict_init_succeeds_and_writes_audit_line() {
888        let dir = unique_temp_path("audit-dir");
889        let audit_path = dir.join("audit.log");
890        let config = observability_config(Some(audit_path.clone()));
891        let setup = prepare_tracing_audit_strict(&config).expect("strict audit setup succeeds");
892        let writer = setup.writer.as_ref().expect("audit writer is configured");
893        let subscriber = tracing_subscriber::registry().with(
894            tracing_subscriber::fmt::layer()
895                .json()
896                .with_writer(writer.clone())
897                .with_filter(tracing_subscriber::filter::LevelFilter::INFO),
898        );
899
900        tracing::subscriber::with_default(subscriber, || {
901            tracing::info!(event = "phase3-test", "audit event");
902            let mut sink = writer.make_writer();
903            sink.flush().expect("enqueue flush");
904        });
905        drop(setup.guard);
906
907        let contents = std::fs::read_to_string(&audit_path).expect("read flushed audit file");
908        assert!(
909            contents.contains("audit event"),
910            "guard drop should drain this normal audit line before timeout; got {contents:?}"
911        );
912        std::fs::remove_dir_all(&dir).expect("remove audit temp dir");
913    }
914
915    #[test]
916    fn audit_worker_counts_write_and_flush_failures_without_panicking() {
917        let (_sender, receiver) = mpsc::sync_channel(1);
918        let io_failures = Arc::new(AtomicU64::new(0));
919        let mut worker = AuditWorker {
920            file: FailingAuditSink,
921            receiver,
922            shutdown: Arc::new(AtomicBool::new(false)),
923            dropped: Arc::new(AtomicU64::new(0)),
924            io_failures: Arc::clone(&io_failures),
925            last_io_failure_warning: Some(Instant::now()),
926        };
927
928        worker.handle_message(AuditMessage::Write(b"audit event\n".to_vec()));
929        worker.handle_message(AuditMessage::Flush);
930
931        assert_eq!(io_failures.load(Ordering::Relaxed), 2);
932    }
933
934    #[test]
935    fn audit_worker_io_failure_warning_is_time_throttled() {
936        let (_sender, receiver) = mpsc::sync_channel(1);
937        let mut worker = AuditWorker {
938            file: FailingAuditSink,
939            receiver,
940            shutdown: Arc::new(AtomicBool::new(false)),
941            dropped: Arc::new(AtomicU64::new(0)),
942            io_failures: Arc::new(AtomicU64::new(0)),
943            last_io_failure_warning: None,
944        };
945        let first = Instant::now();
946
947        assert!(worker.io_failure_warning_due(first));
948        assert!(!worker.io_failure_warning_due(first + Duration::from_secs(1)));
949        assert!(
950            worker.io_failure_warning_due(first + super::AUDIT_IO_FAILURE_WARNING_INTERVAL),
951            "warning should be eligible again after the throttle interval"
952        );
953    }
954
955    #[test]
956    fn strict_init_succeeds_with_no_audit_path() {
957        let config = observability_config(None);
958
959        let setup = prepare_tracing_audit_strict(&config).expect("no audit path needs no file I/O");
960
961        assert!(
962            setup.writer.is_none(),
963            "no audit path should install no audit writer"
964        );
965    }
966
967    fn observability_config(audit_log_path: Option<PathBuf>) -> ObservabilityConfig {
968        ObservabilityConfig {
969            log_level: "info".into(),
970            log_format: "pretty".into(),
971            audit_log_path,
972            log_request_headers: false,
973            metrics_enabled: false,
974            metrics_bind: "127.0.0.1:9090".into(),
975            log_plaintext_oauth_tokens: false,
976            log_oauth_claim_values: false,
977            log_tool_call_arguments: false,
978            log_upstream_error_bodies: false,
979        }
980    }
981
982    #[test]
983    #[cfg(unix)]
984    fn audit_file_is_created_owner_only() {
985        use std::os::unix::fs::PermissionsExt as _;
986
987        let dir = unique_temp_path("audit-mode");
988        let audit_path = dir.join("audit.log");
989        let config = observability_config(Some(audit_path.clone()));
990        let setup = prepare_tracing_audit_strict(&config).expect("strict audit setup succeeds");
991        drop(setup.guard);
992
993        let mode = std::fs::metadata(&audit_path)
994            .expect("audit file exists")
995            .permissions()
996            .mode();
997        assert_eq!(
998            mode & 0o077,
999            0,
1000            "audit log must never be group- or world-accessible, even transiently; \
1001             got mode {mode:o}"
1002        );
1003        std::fs::remove_dir_all(&dir).expect("remove audit temp dir");
1004    }
1005
1006    /// The audit log must end up with a protected, owner-only DACL: exactly one
1007    /// ACE, granting this process's SID, with inherited entries discarded.
1008    ///
1009    /// Read back through `windows-permissions` rather than shelling out to
1010    /// `icacls`, so the assertion does not depend on a subprocess.
1011    #[test]
1012    #[cfg(windows)]
1013    fn audit_file_dacl_is_owner_only() {
1014        use windows_permissions::{
1015            constants::{SeObjectType, SecurityInformation},
1016            wrappers,
1017        };
1018
1019        let dir = unique_temp_path("audit-dacl");
1020        let audit_path = dir.join("audit.log");
1021        let config = observability_config(Some(audit_path.clone()));
1022
1023        let setup = prepare_tracing_audit_strict(&config)
1024            .expect("Windows audit logging must succeed once the DACL is applied");
1025        drop(setup.guard);
1026
1027        assert!(
1028            audit_path.exists(),
1029            "the audit file must be created on Windows, not refused"
1030        );
1031
1032        let sd = wrappers::GetNamedSecurityInfo(
1033            audit_path.as_os_str(),
1034            SeObjectType::SE_FILE_OBJECT,
1035            SecurityInformation::Dacl,
1036        )
1037        .expect("reading the audit file security descriptor must succeed");
1038        let dacl = sd.dacl().expect("the audit file must carry a DACL");
1039
1040        let expected = windows_permissions::utilities::current_process_sid()
1041            .expect("current process SID must be resolvable");
1042
1043        assert_eq!(
1044            dacl.len(),
1045            1,
1046            "a protected owner-only DACL must contain exactly one ACE; \
1047             more means inherited entries survived"
1048        );
1049        let ace = dacl.get_ace(0).expect("the single ACE must be readable");
1050        assert_eq!(
1051            ace.sid().expect("the ACE must name a SID"),
1052            &*expected,
1053            "the only ACE must grant this process's SID"
1054        );
1055
1056        std::fs::remove_dir_all(&dir).expect("remove audit temp dir");
1057    }
1058
1059    #[test]
1060    #[cfg(not(any(unix, windows)))]
1061    fn strict_init_refuses_audit_log_without_private_permissions() {
1062        let dir = unique_temp_path("audit-unsupported");
1063        let audit_path = dir.join("audit.log");
1064        let config = observability_config(Some(audit_path.clone()));
1065
1066        let err = prepare_tracing_audit_strict(&config)
1067            .err()
1068            .expect("audit logging must fail closed where owner-only access is unguaranteed");
1069        let msg = err.to_string();
1070        assert!(
1071            msg.contains("private permissions are unsupported"),
1072            "error must explain why auditing was refused; got {msg:?}"
1073        );
1074        assert!(
1075            !audit_path.exists(),
1076            "the audit file must NOT be created when its permissions cannot be guaranteed"
1077        );
1078    }
1079
1080    #[test]
1081    #[cfg(not(any(unix, windows)))]
1082    fn lenient_init_warns_and_installs_no_audit_sink() {
1083        let dir = unique_temp_path("audit-lenient");
1084        let audit_path = dir.join("audit.log");
1085        let config = observability_config(Some(audit_path.clone()));
1086
1087        let setup = prepare_tracing_audit_lenient(&config);
1088        assert!(
1089            setup.writer.is_none(),
1090            "no audit sink may be installed when permissions cannot be guaranteed"
1091        );
1092        assert!(
1093            setup
1094                .warnings
1095                .iter()
1096                .any(|w| w.contains("private permissions are unsupported")),
1097            "lenient init must warn rather than fail silently; got {:?}",
1098            setup.warnings
1099        );
1100        assert!(!audit_path.exists(), "no audit file may be created");
1101    }
1102
1103    fn unique_temp_path(label: &str) -> PathBuf {
1104        let nanos = SystemTime::now()
1105            .duration_since(UNIX_EPOCH)
1106            .expect("system time is after Unix epoch")
1107            .as_nanos();
1108        std::env::temp_dir().join(format!(
1109            "rmcp-server-kit-{label}-{}-{nanos}",
1110            std::process::id()
1111        ))
1112    }
1113}