fix(logging): quiet the 30s reconcile summary and the rmcp SDK in the default log (#894)

Two routine INFO lines made up most of the default server log:

- the wiki watcher's "reconciliation pass complete" summary fired every
  RECONCILE_INTERVAL (30s) regardless of activity; drop it to debug. Its
  failure signals stay loud (the per-page warn!, the watcher_degraded
  error!, and the info! recovery transition).
- the external rmcp MCP SDK logs per-request lifecycle at info, which the
  default filter did not cap. Prepend `rmcp=warn` to the default filter so
  an operator can restore it via log_level (e.g. "info,rmcp=info") or
  RUST_LOG, while `tracing_appender=warn` stays appended and thus
  non-overridable — the invariant #15 feedback-loop guard.

Extract the filter string into a pure `default_filter` helper and unit-test
the ordering: the default suppresses both targets, log_level can restore
rmcp, and log_level cannot lower tracing_appender below warn.

Co-Authored-By: Claude Opus 4.8 <noreply@anthropic.com>
Claude-Session: https://claude.ai/code/session_01MDbhmszrjG9s5MrPrTuNtm

CHANGELOG.md

@@ -19,6 +19,15 @@ and this project adheres to [Semantic Versioning](https://semver.org/spec/v2.0.0
   server's 20 s completion timeout, which made the reranker stall every
   query before falling back. (#873)
 
+### Changed
+- Quieted the default server log: the reconciliation-pass summary that fired
+  every 30 s regardless of activity dropped from `info` to `debug`, and the
+  default log filter now pins the external `rmcp` MCP SDK to `warn` (its
+  per-request lifecycle logging at `info` was the other half of a near-empty
+  server's log). Both are restorable through `log_level` (e.g.
+  `"info,rmcp=info"` or `"debug"`) or `RUST_LOG`; the `tracing_appender=warn`
+  feedback-loop guard stays non-overridable. (#894)
+
 ### Fixed
 - Tool-family labels no longer leak into automatic handoffs and session-page
   titles, and the file-activity handoff warning fires again. Every closed-tool

crates/ai-memory-cli/src/logging.rs

@@ -87,6 +87,25 @@ fn resolve_file_appender(
     (None, notices)
 }
 
+/// The `EnvFilter` directive used when `RUST_LOG` is unset.
+///
+/// Two overrides bracket the operator's `log_level`, and order is
+/// load-bearing because a later directive wins in an `EnvFilter`:
+///
+/// - `rmcp=warn` is **prepended**, so it is the weakest directive and an
+///   operator can restore the external MCP SDK's per-request info logs
+///   through `log_level` (e.g. `info,rmcp=info`) without setting `RUST_LOG`.
+///   Left at info, `rmcp` alone is ~half the default server log (#894).
+/// - `tracing_appender=warn` stays **appended**, so it is the strongest and
+///   cannot be lowered through `log_level`. That guard is invariant #15: the
+///   appender must never log at its own level or it feeds itself (the loop
+///   that filled 137 GB for agentmemory #519).
+///
+/// `RUST_LOG` (`EnvFilter::try_from_default_env`) still overrides all of this.
+fn default_filter(log_level: &str) -> String {
+    format!("rmcp=warn,{log_level},tracing_appender=warn")
+}
+
 /// Initialise the global tracing subscriber.
 ///
 /// Returns a guard whose drop flushes any pending log lines; `None` when no
@@ -106,9 +125,8 @@ pub fn init(config: &Config, warnings: DegradeWarnings) -> Result<Option<WorkerG
         }
     }
 
-    let default_filter = format!("{},tracing_appender=warn", config.log_level);
-    let env_filter =
-        EnvFilter::try_from_default_env().unwrap_or_else(|_| EnvFilter::new(default_filter));
+    let env_filter = EnvFilter::try_from_default_env()
+        .unwrap_or_else(|_| EnvFilter::new(default_filter(&config.log_level)));
 
     let stderr_layer = tracing_subscriber::fmt::layer()
         .with_target(true)
@@ -139,6 +157,56 @@ pub fn init(config: &Config, warnings: DegradeWarnings) -> Result<Option<WorkerG
 mod tests {
     use super::*;
 
+    /// The effective per-target level `EnvFilter` resolves the default filter
+    /// to. `EnvFilter`'s `Display` reprints its live directives (last wins per
+    /// target), so it reflects the real conflict resolution, not the raw
+    /// string. Returns `None` for a target the filter carries no directive for.
+    fn effective_level(log_level: &str, target: &str) -> Option<String> {
+        let printed = EnvFilter::new(default_filter(log_level)).to_string();
+        printed
+            .split(',')
+            .find_map(|d| d.strip_prefix(&format!("{target}=")).map(str::to_owned))
+    }
+
+    #[test]
+    fn default_filter_suppresses_rmcp_and_the_appender() {
+        // (a) With a plain `info` level, both the noisy external MCP SDK and
+        // the appender are pinned to warn.
+        assert_eq!(effective_level("info", "rmcp").as_deref(), Some("warn"));
+        assert_eq!(
+            effective_level("info", "tracing_appender").as_deref(),
+            Some("warn")
+        );
+    }
+
+    #[test]
+    fn operator_can_restore_rmcp_through_log_level() {
+        // (b) `rmcp=warn` is prepended (weakest), so a log_level directive for
+        // the same target wins and brings the SDK's info logs back — while the
+        // appender stays warn.
+        assert_eq!(
+            effective_level("info,rmcp=info", "rmcp").as_deref(),
+            Some("info"),
+            "an operator must be able to restore rmcp via log_level"
+        );
+        assert_eq!(
+            effective_level("info,rmcp=info", "tracing_appender").as_deref(),
+            Some("warn"),
+            "restoring rmcp must not disturb the appender guard"
+        );
+    }
+
+    #[test]
+    fn log_level_cannot_lower_the_appender_below_warn() {
+        // (c) `tracing_appender=warn` is appended (strongest), so no log_level
+        // directive can lower it — the invariant #15 feedback-loop guard.
+        assert_eq!(
+            effective_level("info,tracing_appender=trace", "tracing_appender").as_deref(),
+            Some("warn"),
+            "the appender guard must be non-overridable through log_level"
+        );
+    }
+
     // Issue #158: the log directory EXISTS but the filesystem is read-only —
     // dir creation "succeeds", file creation fails. The old code panicked
     // here (RollingFileAppender::new); the chain must fall through to the

crates/ai-memory-wiki/src/watcher.rs

@@ -26,7 +26,7 @@ use ai_memory_core::{PagePath, ProjectId, WorkspaceId};
 use notify::{EventKind, RecursiveMode};
 use notify_debouncer_full::{DebounceEventResult, Debouncer, RecommendedCache, new_debouncer_opt};
 use tokio::sync::mpsc;
-use tracing::{debug, info, warn};
+use tracing::{debug, warn};
 
 use crate::error::{WikiError, WikiResult};
 use crate::wiki::Wiki;
@@ -414,7 +414,11 @@ async fn reconcile(wiki: &Wiki) -> WikiResult<ReconcileStats> {
             }
         }
     }
-    info!(
+    // debug!, not info!: this fires every RECONCILE_INTERVAL regardless of
+    // activity, so at info it is ~half the default server log (#894). Its
+    // failure signals stay loud — the per-page `warn!` above, the
+    // `watcher_degraded` `error!`, and the `info!` recovery transition.
+    debug!(
         indexed = stats.indexed,
         skipped_orphans = stats.skipped_orphans,
         skipped_purged_sessions = stats.skipped_purged_sessions,

docs/ARCHITECTURE.md

@@ -599,7 +599,11 @@ prefixed `AI_MEMORY_*`.
 
 ```toml
 bind = "127.0.0.1:49374"
-log_level = "info"
+log_level = "info"                 # default filter also pins `rmcp=warn` (the MCP SDK's
+                                   # per-request info logs) and drops the 30s reconcile
+                                   # summary to debug (#894). Restore either via log_level
+                                   # (e.g. "info,rmcp=info", "debug") or RUST_LOG;
+                                   # `tracing_appender=warn` stays forced (feedback-loop guard)
 tcp_keepalive_secs = 60            # idle time before TCP keepalive probes an accepted `serve`
                                    # connection; reaps sockets left half-open by a dead peer
                                    # (laptop sleep, VPN flap) that would otherwise leak fds