M0: compilable skeleton — Kigi 0.1.0 fork surgery
Hard fork of xai-org/grok-build (Apache-2.0) re-targeted as Kigi, an
unofficial Kimi Code CLI community build.
Rename & identity
- 72 xai-*/xai-grok-* crates -> kigi-* (explicit: xai-grok-pager-bin ->
kigi-bin [binary `kigi`], xai-grok-pager -> kigi-tui; rest mechanical);
ptyctl, ptyctl-cli, third_party/ unchanged; proto package
xai.grok.tools.v1 -> kigi.tools.v1
- Config home ~/.kigi (KIGI_SHARE_DIR override), env prefix GROK_* ->
KIGI_*, `kigi --version` carries the unofficial-community-build notice
- clap identity, help text, startup banner, prompt templates rebranded
(templates re-encrypted)
Deletions (PRD removal list #5/#6/#7/#9/#10)
- voice input (xai-grok-voice) and all TUI wiring
- telemetry: Mixpanel client, external OTel stream, Sentry, OTLP layers,
trace/GCS/S3 upload queues (kigi-file-utils halved), workspace upload
module & dc_log, heap-profile uploader, auth-diagnostics uploader,
session-analytics halves of feedback; local zero-egress observability
preserved in new kigi-log crate (unified log, --debug firehose,
subsystem file logs, opt-in instrumentation)
- announcements (crate, remote-settings fields, TUI surfaces)
- plugin marketplace (crate, sources/browse/CTA/extensions-modal tab);
direct plugin install/uninstall/update via kigi-agent git_install kept
- relay/gateway/assets endpoints and features (agent relay, headless
relay transport, gateway bridge, LeaderEnvUrls); leader IPC socket now
~/.kigi/leader.sock + KIGI_LEADER_SOCKET, no ws-url derivation
- functional types rehomed instead of deleted: PermissionMode ->
kigi-config-types, McpInitStrategy -> kigi-mcp, PrCreationSource ->
session signals, TerminalDiagnostics -> kigi-pager-render, agent_id ->
shell util
Endpoints
- kigi-env rewritten: single production KigiEndpoints {coding_api_base_url
https://api.kimi.com/coding/v1 (KIGI_CODE_BASE_URL), oauth_host
https://auth.kimi.com (KIGI_OAUTH_HOST), update_base_url (GitHub
Releases API), upgrade_page_url}; GrokBuildEnvironment enum deleted
Toolchain & workspace hygiene
- Rust 1.97.0 pinned; edition 2024; full cargo update; git2 hoisted to
workspace at 0.21 (Option->Result API migration), quick-xml 0.41
- Root Cargo.toml hand-maintained (PRD §8.1): version 0.1.0 inherited by
all members, members sorted, unused deps pruned
- cargo-deny advisories gate (deny.toml with documented transitive
exceptions); CI workflow (check/clippy/fmt/deny/test, macOS+Linux)
- cross-crate test seams re-gated behind `test-support` cargo feature;
insta snapshot baselines renamed to the kigi_tui prefix
- clippy --workspace --all-targets: zero warnings; fmt clean
Fixes surfaced by the port
- updater probe/installer divergence (bin/kigi vs bin/grok symlink set)
- idle model-metadata refresh dead under KIGI_CODE_BASE_URL override
(new is_effective_coding_endpoint_url, loopback+override aware)
- macOS symlinked-TMPDIR fixture canonicalization (foreign_sessions,
fast-worktree); RSS measurement tests serialized via serial_test
Docs & legal (Apache §4)
- NOTICE added (upstream attribution + change statement); THIRD-PARTY
notices sustained; kigi-tools ported-code notices extended; README,
CONTRIBUTING, SECURITY, AGENTS.md rewritten
Out of scope for M0 (tracked): Kimi auth/inference (M1), search/fetch,
command parity, config import (M2), Computer Hub excision & final
brand-token sweep (M2), distribution & self-update rewrite (M3).
This commit is contained in:
@@ -0,0 +1,46 @@
|
||||
//! Shared non-blocking file appender + worker-guard registry for telemetry file-log layers.
|
||||
|
||||
use std::path::Path;
|
||||
use std::sync::{Mutex, OnceLock};
|
||||
|
||||
use tracing_appender::non_blocking::{NonBlocking, WorkerGuard};
|
||||
|
||||
// Park every worker guard for process lifetime; dropping a guard flushes and
|
||||
// shuts down that file's writer thread, so accumulate (never overwrite) to let
|
||||
// multiple file-log layers coexist.
|
||||
static FILE_LOG_GUARDS: OnceLock<Mutex<Vec<WorkerGuard>>> = OnceLock::new();
|
||||
|
||||
/// Shared non-blocking file writer for telemetry file-log layers. Opens `path`
|
||||
/// in append mode and parks the worker guard for process lifetime so buffered
|
||||
/// logs aren't lost. Sibling loggers (hooks/memory/sampling/instrumentation) can
|
||||
/// migrate onto this in a follow-up.
|
||||
pub(crate) fn non_blocking_file_writer(path: &Path) -> std::io::Result<NonBlocking> {
|
||||
if let Some(parent) = path.parent() {
|
||||
let _ = std::fs::create_dir_all(parent);
|
||||
}
|
||||
|
||||
let file = std::fs::OpenOptions::new()
|
||||
.create(true)
|
||||
.append(true)
|
||||
.open(path)?;
|
||||
|
||||
let (non_blocking, guard) = tracing_appender::non_blocking(file);
|
||||
let guards = FILE_LOG_GUARDS.get_or_init(|| Mutex::new(Vec::new()));
|
||||
// Recover from a poisoned mutex so the guard is always parked; dropping it
|
||||
// would shut down the writer thread and silently lose buffered logs.
|
||||
let mut guards = guards
|
||||
.lock()
|
||||
.unwrap_or_else(|poisoned| poisoned.into_inner());
|
||||
guards.push(guard);
|
||||
Ok(non_blocking)
|
||||
}
|
||||
|
||||
/// Drop all parked worker guards, flushing their non-blocking writers. Call at
|
||||
/// process exit so short-lived runs (e.g. headless `grok -p`) don't lose buffered logs.
|
||||
pub(crate) fn flush_file_log_guards() {
|
||||
if let Some(m) = FILE_LOG_GUARDS.get() {
|
||||
// Recover from a poisoned mutex so exit-flush still drains the guards.
|
||||
let mut guards = m.lock().unwrap_or_else(|poisoned| poisoned.into_inner());
|
||||
guards.clear(); // dropping each WorkerGuard flushes + joins its writer thread
|
||||
}
|
||||
}
|
||||
@@ -0,0 +1,961 @@
|
||||
//! Reusable non-blocking file-logging tracing layers for the `--debug` firehose.
|
||||
//!
|
||||
//! Two install modes, chosen by env precedence (see `resolve_debug_target_inner`):
|
||||
//! - PerSession (`KIGI_DEBUG_LOG=1`): a routing layer fans each session's
|
||||
//! firehose to `~/.kigi/debug/<session_id>.txt` (one file per session), with a
|
||||
//! `<role>-<pid>.txt` catch-all for events fired outside any session span, and
|
||||
//! a `latest.txt` symlink pointing at the most-recently-opened session file.
|
||||
//! - SingleFile (explicit path via `KIGI_LOG_FILE` or `KIGI_DEBUG_LOG=<path>`):
|
||||
//! one flat `fmt` file, routing bypassed. Disk IO stays off the tracing hot
|
||||
//! path via `tracing_appender`'s non-blocking writer in both modes.
|
||||
|
||||
use std::collections::HashMap;
|
||||
use std::ffi::OsStr;
|
||||
use std::io::Write as _;
|
||||
use std::path::{Path, PathBuf};
|
||||
use std::sync::{Mutex, MutexGuard};
|
||||
|
||||
use tracing::Subscriber;
|
||||
use tracing::field::{Field, Visit};
|
||||
use tracing_appender::non_blocking::NonBlocking;
|
||||
use tracing_subscriber::filter::{EnvFilter, LevelFilter};
|
||||
use tracing_subscriber::layer::{Context, Layer};
|
||||
use tracing_subscriber::registry::LookupSpan;
|
||||
|
||||
use crate::session_ctx::SESSION_ID_FIELD;
|
||||
use kigi_config::kigi_home;
|
||||
|
||||
/// Which env var requested a single-file debug log (drives filter and diagnostics).
|
||||
#[derive(Debug, Clone, Copy, PartialEq, Eq)]
|
||||
pub(crate) enum DebugSource {
|
||||
GrokLogFile,
|
||||
GrokDebugLog,
|
||||
}
|
||||
|
||||
impl DebugSource {
|
||||
fn label(self) -> &'static str {
|
||||
match self {
|
||||
Self::GrokLogFile => "KIGI_LOG_FILE",
|
||||
Self::GrokDebugLog => "KIGI_DEBUG_LOG",
|
||||
}
|
||||
}
|
||||
}
|
||||
|
||||
/// Target for the pager's always-on compact ACP update summary line
|
||||
/// (kind, ids, status, payload sizes).
|
||||
///
|
||||
/// Lives here (not in `kigi-tui`) so the firehose directives below and
|
||||
/// the pager's own filter are built from the same constants — a rename can't
|
||||
/// silently desync them into a no-op directive.
|
||||
pub const ACP_UPDATE_TARGET: &str = "acp_update";
|
||||
|
||||
/// Target for the pager's full ACP update payload dump (plain JSON).
|
||||
///
|
||||
/// Off in the pager's release filter; the firehose is the always-available
|
||||
/// subscriber for full payloads, and it writes to disk, where the volume is
|
||||
/// safe. See `kigi-tui/src/tracing.rs` for the consumer side.
|
||||
pub const ACP_UPDATE_PAYLOAD_TARGET: &str = "acp_update_payload";
|
||||
|
||||
/// Module path of rmcp 2.1's per-reconnect SSE warn (`sse stream error: ...`),
|
||||
/// which subscribers demote to `error` to drop the flood. Re-check on rmcp bump.
|
||||
pub const RMCP_SSE_NOISE_TARGET: &str = "rmcp::transport::common::client_side_sse";
|
||||
|
||||
// Broad firehose filter for the routing/KIGI_DEBUG_LOG sources: capture our
|
||||
// crates at debug regardless of a narrowing RUST_LOG, with deps at info so they
|
||||
// don't flood. Curated first-party allowlist: new grok crates default to `info`
|
||||
// until added here.
|
||||
const FIREHOSE_BASE_DIRECTIVES: &str = "info,kigi_tui=debug,kigi_shell=debug,kigi_tools=debug,kigi_log=debug,kigi_agent=debug,kigi_mcp=debug,kigi_acp_lib=debug,sampling_log=off";
|
||||
|
||||
// Full firehose directives: the curated crate list plus the pager's ACP
|
||||
// update target (built from the constant above, not a literal).
|
||||
fn firehose_directives() -> String {
|
||||
format!("{FIREHOSE_BASE_DIRECTIVES},{ACP_UPDATE_TARGET}=debug")
|
||||
}
|
||||
|
||||
// The broad firehose filter, used by both the routing layer and the
|
||||
// KIGI_DEBUG_LOG single-file source (mirrors `default_file_filter`).
|
||||
fn firehose_filter() -> EnvFilter {
|
||||
EnvFilter::new(firehose_directives())
|
||||
}
|
||||
|
||||
// RUST_LOG-respecting filter for the KIGI_LOG_FILE source: DEBUG default, honor
|
||||
// RUST_LOG, silence sampling_log (preserves KIGI_LOG_FILE back-compat).
|
||||
fn default_file_filter() -> EnvFilter {
|
||||
EnvFilter::builder()
|
||||
.with_default_directive(LevelFilter::DEBUG.into())
|
||||
.from_env_lossy()
|
||||
.add_directive(
|
||||
"sampling_log=off"
|
||||
.parse()
|
||||
.expect("static directive is valid"),
|
||||
)
|
||||
}
|
||||
|
||||
// Open `path` as a non-blocking flat `fmt` layer with `filter`; ansi off, target on.
|
||||
fn build_file_layer<S>(path: &Path, filter: EnvFilter) -> std::io::Result<impl Layer<S>>
|
||||
where
|
||||
S: Subscriber + for<'span> LookupSpan<'span>,
|
||||
{
|
||||
let non_blocking = crate::appender::non_blocking_file_writer(path)?;
|
||||
let fmt_layer = tracing_subscriber::fmt::layer()
|
||||
.with_target(true)
|
||||
.with_ansi(false)
|
||||
.with_writer(non_blocking)
|
||||
.with_filter(filter);
|
||||
Ok(fmt_layer)
|
||||
}
|
||||
|
||||
// ── Per-session routing layer ───────────────────────────────────────────────
|
||||
|
||||
/// Filesystem-safe session key. Sanitized once at capture (`on_new_span`) and
|
||||
/// stashed in the span's tracing extensions, so events fired anywhere under the
|
||||
/// span route to the right file without re-sanitizing on the hot path.
|
||||
#[derive(Clone)]
|
||||
struct SessionId(String);
|
||||
|
||||
/// Visits span attributes to pull out the `session_id` field. Production records
|
||||
/// it via `%` (Display → `record_debug`, no quotes); like `EventVisitor`, the
|
||||
/// single `record_debug` impl captures every field type (the other recorders
|
||||
/// default to it).
|
||||
#[derive(Default)]
|
||||
struct SessionIdVisitor(Option<String>);
|
||||
|
||||
impl Visit for SessionIdVisitor {
|
||||
fn record_debug(&mut self, field: &Field, value: &dyn std::fmt::Debug) {
|
||||
if field.name() == SESSION_ID_FIELD {
|
||||
self.0 = Some(format!("{value:?}"));
|
||||
}
|
||||
}
|
||||
}
|
||||
|
||||
/// Renders an event's message + remaining fields into plain strings. All field
|
||||
/// types funnel through `record_debug` (the trait's other recorders default to
|
||||
/// it), so this one impl captures everything.
|
||||
#[derive(Default)]
|
||||
struct EventVisitor {
|
||||
message: String,
|
||||
fields: String,
|
||||
}
|
||||
|
||||
impl Visit for EventVisitor {
|
||||
fn record_debug(&mut self, field: &Field, value: &dyn std::fmt::Debug) {
|
||||
use std::fmt::Write as _;
|
||||
if field.name() == "message" {
|
||||
let _ = write!(self.message, "{value:?}");
|
||||
} else {
|
||||
let _ = write!(self.fields, " {}={:?}", field.name(), value);
|
||||
}
|
||||
}
|
||||
}
|
||||
|
||||
// Format one compact, ANSI-free firehose line. Intentionally NOT byte-identical
|
||||
// to `fmt::Layer`: its `FormatEvent` can't be reused from another layer and a
|
||||
// `MakeWriter` can't see span context, so we render here. Span context is
|
||||
// omitted on purpose — the file name already carries the session id.
|
||||
fn format_event(event: &tracing::Event<'_>) -> String {
|
||||
let meta = event.metadata();
|
||||
let mut visitor = EventVisitor::default();
|
||||
event.record(&mut visitor);
|
||||
let ts = chrono::Utc::now().to_rfc3339_opts(chrono::SecondsFormat::Micros, true);
|
||||
let level = meta.level();
|
||||
let target = meta.target();
|
||||
// Skip the message gap when there's no `message` field so a field-only event
|
||||
// renders "target: k=v" (each field already carries a leading space), not
|
||||
// "target: k=v" with a dangling double space.
|
||||
if visitor.message.is_empty() {
|
||||
format!("{ts} {level} {target}:{}\n", visitor.fields)
|
||||
} else {
|
||||
format!(
|
||||
"{ts} {level} {target}: {}{}\n",
|
||||
visitor.message, visitor.fields
|
||||
)
|
||||
}
|
||||
}
|
||||
|
||||
// Keep per-session file names filesystem-safe. A session id is normally a UUID,
|
||||
// but never let an unexpected value (path separators, `..`) escape the dir.
|
||||
fn sanitize_key(id: &str) -> String {
|
||||
let safe: String = id
|
||||
.chars()
|
||||
.map(|c| {
|
||||
if c.is_ascii_alphanumeric() || matches!(c, '-' | '_' | '.') {
|
||||
c
|
||||
} else {
|
||||
'_'
|
||||
}
|
||||
})
|
||||
.collect();
|
||||
// Map empty / dot-only keys ("", ".", "..", "...") to a constant: those are
|
||||
// filesystem-special, and relying on the `.txt` suffix to neutralize them is
|
||||
// incidental. Make the safety explicit instead.
|
||||
if safe.is_empty() || safe.bytes().all(|b| b == b'.') {
|
||||
return "_".to_owned();
|
||||
}
|
||||
safe
|
||||
}
|
||||
|
||||
// `latest.txt` link + swap-temp name parts, shared by `update_latest_symlink`
|
||||
// (create/rename) and `prune_old_logs` (spare rule + orphan cleanup) so the
|
||||
// sites can never drift. Tests pin the literals on purpose: orphans created by
|
||||
// already-shipped binaries must stay reapable across a rename of these consts.
|
||||
const LATEST_LINK_NAME: &str = "latest.txt";
|
||||
const LATEST_TMP_PREFIX: &str = ".latest.";
|
||||
const LATEST_TMP_SUFFIX: &str = ".tmp";
|
||||
|
||||
/// Repoint `<dir>/latest.txt` at `target` (a sibling session file) for
|
||||
/// `tail -f`. Best-effort and Unix-only; the relative target keeps the link
|
||||
/// valid regardless of the dir's absolute path.
|
||||
#[cfg(unix)]
|
||||
fn update_latest_symlink(dir: &Path, target: &Path) {
|
||||
let Some(name) = target.file_name() else {
|
||||
return;
|
||||
};
|
||||
// Atomic swap: symlink a unique temp then rename it over latest.txt (rename
|
||||
// is atomic on POSIX), so a racing `tail -f` never sees latest.txt missing.
|
||||
// The temp name is keyed by the target file so concurrent opens of different
|
||||
// sessions don't collide on it.
|
||||
let tmp = dir.join(format!(
|
||||
"{LATEST_TMP_PREFIX}{}{LATEST_TMP_SUFFIX}",
|
||||
name.to_string_lossy()
|
||||
));
|
||||
let _ = std::fs::remove_file(&tmp);
|
||||
if std::os::unix::fs::symlink(name, &tmp).is_ok()
|
||||
&& std::fs::rename(&tmp, dir.join(LATEST_LINK_NAME)).is_err()
|
||||
{
|
||||
// Rename failed: remove the temp symlink now rather than leaving an
|
||||
// orphan for prune to reap only after LOG_RETENTION.
|
||||
let _ = std::fs::remove_file(&tmp);
|
||||
}
|
||||
}
|
||||
|
||||
#[cfg(not(unix))]
|
||||
fn update_latest_symlink(_dir: &Path, _target: &Path) {}
|
||||
|
||||
/// Per-session sinks plus a single fallback sink, all behind the routing layer's
|
||||
/// mutex. There is no cap or eviction: each distinct session id opens one file +
|
||||
/// non-blocking worker + parked guard that persist for the process lifetime
|
||||
/// (reclaimed only when the process/leader restarts). That is acceptable for an
|
||||
/// opt-in, debug-only firehose; a long-lived `--debug` leader holds one fd per
|
||||
/// session it logs. The central guard parking (`appender`) is what lets
|
||||
/// `flush()` drain these at exit, so we do not reclaim per session.
|
||||
#[derive(Default)]
|
||||
struct SinkMap {
|
||||
sessions: HashMap<String, NonBlocking>,
|
||||
fallback: Option<NonBlocking>,
|
||||
}
|
||||
|
||||
/// Routes the firehose per session: events under a `session` span go to
|
||||
/// `<dir>/<session_id>.txt`; everything else to `<dir>/<role>-<pid>.txt`.
|
||||
struct RoutingLayer {
|
||||
dir: PathBuf,
|
||||
role: String,
|
||||
pid: u32,
|
||||
// The lock is scoped to map access ONLY — file opens (fs + a worker-thread
|
||||
// spawn + the appender's own mutex) run OUTSIDE it, so a tracing event
|
||||
// emitted on the open path can't re-enter and deadlock this non-reentrant
|
||||
// Mutex. Lock-on-write is otherwise fine: the firehose is opt-in/debug-only.
|
||||
sinks: Mutex<SinkMap>,
|
||||
}
|
||||
|
||||
impl RoutingLayer {
|
||||
fn new(dir: PathBuf, role: String, pid: u32) -> Self {
|
||||
Self {
|
||||
dir,
|
||||
role,
|
||||
pid,
|
||||
sinks: Mutex::new(SinkMap::default()),
|
||||
}
|
||||
}
|
||||
|
||||
fn lock(&self) -> MutexGuard<'_, SinkMap> {
|
||||
self.sinks.lock().unwrap_or_else(|p| p.into_inner())
|
||||
}
|
||||
|
||||
// Append `line` to the session's file. `key` is already sanitized. Opens (and
|
||||
// points `latest.txt` at) the file on first use; open failures degrade to a
|
||||
// no-op for that file.
|
||||
fn write_session(&self, key: &str, line: &[u8]) {
|
||||
// Fast path: writer already open. Hold the lock only for the lookup + the
|
||||
// (non-blocking, channel-only) write.
|
||||
{
|
||||
let mut map = self.lock();
|
||||
if let Some(writer) = map.sessions.get_mut(key) {
|
||||
let _ = writer.write_all(line);
|
||||
return;
|
||||
}
|
||||
}
|
||||
// First event for this session: open OUTSIDE the lock.
|
||||
let path = self.dir.join(format!("{key}.txt"));
|
||||
let Ok(mut writer) = crate::appender::non_blocking_file_writer(&path) else {
|
||||
return;
|
||||
};
|
||||
update_latest_symlink(&self.dir, &path);
|
||||
let _ = writer.write_all(line);
|
||||
let mut map = self.lock();
|
||||
// If a concurrent event opened it first, keep that one and drop ours (the
|
||||
// line we wrote already reached the file via our worker).
|
||||
map.sessions.entry(key.to_owned()).or_insert(writer);
|
||||
}
|
||||
|
||||
// Append `line` to the `<role>-<pid>.txt` catch-all, opening it on first use.
|
||||
fn write_fallback(&self, line: &[u8]) {
|
||||
{
|
||||
let mut map = self.lock();
|
||||
if let Some(writer) = map.fallback.as_mut() {
|
||||
let _ = writer.write_all(line);
|
||||
return;
|
||||
}
|
||||
}
|
||||
let path = self.dir.join(format!("{}-{}.txt", self.role, self.pid));
|
||||
let Ok(mut writer) = crate::appender::non_blocking_file_writer(&path) else {
|
||||
return;
|
||||
};
|
||||
let _ = writer.write_all(line);
|
||||
let mut map = self.lock();
|
||||
if map.fallback.is_none() {
|
||||
map.fallback = Some(writer);
|
||||
}
|
||||
}
|
||||
}
|
||||
|
||||
impl<S> Layer<S> for RoutingLayer
|
||||
where
|
||||
S: Subscriber + for<'span> LookupSpan<'span>,
|
||||
{
|
||||
fn on_new_span(
|
||||
&self,
|
||||
attrs: &tracing::span::Attributes<'_>,
|
||||
id: &tracing::span::Id,
|
||||
ctx: Context<'_, S>,
|
||||
) {
|
||||
let mut visitor = SessionIdVisitor::default();
|
||||
attrs.record(&mut visitor);
|
||||
if let Some(sid) = visitor.0
|
||||
&& let Some(span) = ctx.span(id)
|
||||
{
|
||||
// Sanitize once at capture so the stored key is always filesystem-safe
|
||||
// and `on_event` never re-sanitizes on the hot path.
|
||||
span.extensions_mut().insert(SessionId(sanitize_key(&sid)));
|
||||
}
|
||||
}
|
||||
|
||||
fn on_event(&self, event: &tracing::Event<'_>, ctx: Context<'_, S>) {
|
||||
// Nearest enclosing span (leaf→root) carrying a session id wins. The key
|
||||
// is already sanitized (stored at `on_new_span`).
|
||||
let session_key = ctx.event_scope(event).and_then(|scope| {
|
||||
scope
|
||||
.into_iter()
|
||||
.find_map(|span| span.extensions().get::<SessionId>().map(|s| s.0.clone()))
|
||||
});
|
||||
let line = format_event(event);
|
||||
match session_key {
|
||||
Some(key) => self.write_session(&key, line.as_bytes()),
|
||||
None => self.write_fallback(line.as_bytes()),
|
||||
}
|
||||
}
|
||||
}
|
||||
|
||||
// ── Install + lifecycle ──────────────────────────────────────────────────────
|
||||
|
||||
/// Resolve the requested debug target and install the matching firehose layer on
|
||||
/// `registry`, then init the subscriber.
|
||||
///
|
||||
/// PerSession installs the routing layer (firehose filter, RUST_LOG-immune) and
|
||||
/// prunes old session logs; SingleFile installs a flat `fmt` file picking the
|
||||
/// filter by source (KIGI_LOG_FILE respects RUST_LOG). Open failures warn AFTER
|
||||
/// init in the single-file case; routing open failures are per-file at write
|
||||
/// time and degrade gracefully. `role` names the per-pid fallback file.
|
||||
pub fn install_firehose<S>(registry: S, role: &str)
|
||||
where
|
||||
S: Subscriber + for<'span> LookupSpan<'span> + Send + Sync + 'static,
|
||||
{
|
||||
use tracing_subscriber::layer::SubscriberExt as _;
|
||||
use tracing_subscriber::util::SubscriberInitExt as _;
|
||||
|
||||
match resolve_debug_target() {
|
||||
Some(DebugTarget::PerSession { dir }) => {
|
||||
let layer = RoutingLayer::new(dir, role.to_owned(), std::process::id())
|
||||
.with_filter(firehose_filter());
|
||||
registry.with(layer).init();
|
||||
// Tie pruning to actually routing a firehose, not to the flag.
|
||||
sweep_old_logs();
|
||||
}
|
||||
Some(DebugTarget::SingleFile { path, src }) => {
|
||||
let filter = match src {
|
||||
DebugSource::GrokLogFile => default_file_filter(),
|
||||
DebugSource::GrokDebugLog => firehose_filter(),
|
||||
};
|
||||
match build_file_layer::<S>(&path, filter) {
|
||||
Ok(layer) => registry.with(layer).init(),
|
||||
Err(e) => {
|
||||
registry.init();
|
||||
tracing::warn!("failed to open {} {path:?}: {e}", src.label());
|
||||
}
|
||||
}
|
||||
}
|
||||
None => registry.init(),
|
||||
}
|
||||
}
|
||||
|
||||
/// Flush parked firehose writers at process exit (no-op when none installed).
|
||||
pub fn flush() {
|
||||
crate::appender::flush_file_log_guards();
|
||||
}
|
||||
|
||||
/// Where the firehose should go, if anywhere.
|
||||
#[derive(Debug, PartialEq, Eq)]
|
||||
pub(crate) enum DebugTarget {
|
||||
/// `KIGI_DEBUG_LOG=1` → route per session into `<dir>` (`~/.kigi/debug`).
|
||||
PerSession { dir: PathBuf },
|
||||
/// An explicit path → one flat `fmt` file, routing bypassed.
|
||||
SingleFile { path: PathBuf, src: DebugSource },
|
||||
}
|
||||
|
||||
/// Resolve the debug target, honoring precedence: explicit KIGI_LOG_FILE wins
|
||||
/// (single file, RUST_LOG filter); else KIGI_DEBUG_LOG — a truthy bool routes
|
||||
/// per session into `~/.kigi/debug`, an explicit path writes a single file.
|
||||
///
|
||||
/// Read via `var_os` (not `var`) so a non-UTF-8 path isn't silently dropped.
|
||||
pub(crate) fn resolve_debug_target() -> Option<DebugTarget> {
|
||||
let grok_log_file = std::env::var_os("KIGI_LOG_FILE");
|
||||
let grok_debug_log = std::env::var_os("KIGI_DEBUG_LOG");
|
||||
resolve_debug_target_inner(
|
||||
grok_log_file.as_deref(),
|
||||
grok_debug_log.as_deref(),
|
||||
&kigi_home().join("debug"),
|
||||
)
|
||||
}
|
||||
|
||||
// Empty / whitespace (when valid UTF-8) counts as unset; a non-UTF-8 value is
|
||||
// never blank.
|
||||
fn is_blank(v: &OsStr) -> bool {
|
||||
v.to_str().is_some_and(|s| s.trim().is_empty())
|
||||
}
|
||||
|
||||
// Build a path from an env value: trim surrounding whitespace when it is valid
|
||||
// UTF-8, and preserve the raw bytes otherwise (non-UTF-8 paths must survive).
|
||||
fn os_path(v: &OsStr) -> PathBuf {
|
||||
match v.to_str() {
|
||||
Some(s) => PathBuf::from(s.trim()),
|
||||
None => PathBuf::from(v),
|
||||
}
|
||||
}
|
||||
|
||||
// Env-free precedence core so the resolution rules are unit-testable. The role
|
||||
// and pid are no longer part of resolution: the routing layer owns fallback
|
||||
// naming, so resolution only decides routing-dir vs single-file-path. Takes
|
||||
// `OsStr` so non-UTF-8 paths round-trip; only the bool-vs-path discrimination
|
||||
// needs UTF-8 (a non-UTF-8 value can't be a bool keyword, so it's a path).
|
||||
fn resolve_debug_target_inner(
|
||||
grok_log_file: Option<&OsStr>,
|
||||
grok_debug_log: Option<&OsStr>,
|
||||
debug_dir: &Path,
|
||||
) -> Option<DebugTarget> {
|
||||
if let Some(raw) = grok_log_file
|
||||
&& !is_blank(raw)
|
||||
{
|
||||
return Some(DebugTarget::SingleFile {
|
||||
path: os_path(raw),
|
||||
src: DebugSource::GrokLogFile,
|
||||
});
|
||||
}
|
||||
let raw = grok_debug_log?;
|
||||
match raw.to_str().map(str::trim) {
|
||||
Some("" | "0" | "false" | "off" | "no") => None,
|
||||
Some("1" | "true" | "on" | "yes") => Some(DebugTarget::PerSession {
|
||||
dir: debug_dir.to_path_buf(),
|
||||
}),
|
||||
// Any other UTF-8 value, or a non-UTF-8 value (`None`), is an explicit path.
|
||||
_ => Some(DebugTarget::SingleFile {
|
||||
path: os_path(raw),
|
||||
src: DebugSource::GrokDebugLog,
|
||||
}),
|
||||
}
|
||||
}
|
||||
|
||||
/// Retention window for firehose debug logs: files older than this are pruned.
|
||||
const LOG_RETENTION: std::time::Duration = std::time::Duration::from_secs(7 * 24 * 60 * 60);
|
||||
|
||||
/// Prune `*.txt` firehose files (and orphaned `latest.txt` swap temps) under
|
||||
/// `~/.kigi/debug` older than [`LOG_RETENTION`] so the dir doesn't grow
|
||||
/// unbounded. Age-based (not count-based) so a still-open log from a concurrent
|
||||
/// process is never unlinked mid-write; best-effort, ignore errors.
|
||||
pub(crate) fn sweep_old_logs() {
|
||||
prune_old_logs(&kigi_home().join("debug"), LOG_RETENTION);
|
||||
}
|
||||
|
||||
// Pure prune core: remove `*.txt` files and orphaned `latest.txt` swap temps in
|
||||
// `dir` older than `max_age`. Age-based so a recently-written (active) log is
|
||||
// never deleted; spares the `latest.txt` symlink (a stale link is harmless and
|
||||
// never an active file); best-effort so cleanup never fails logging setup;
|
||||
// testable against a tempdir.
|
||||
fn prune_old_logs(dir: &Path, max_age: std::time::Duration) {
|
||||
let Ok(entries) = std::fs::read_dir(dir) else {
|
||||
return;
|
||||
};
|
||||
let now = std::time::SystemTime::now();
|
||||
for entry in entries.flatten() {
|
||||
let path = entry.path();
|
||||
let Some(name) = path.file_name().and_then(|n| n.to_str()) else {
|
||||
continue;
|
||||
};
|
||||
let is_log = name.ends_with(".txt") && name != LATEST_LINK_NAME;
|
||||
// Swap temps matching this shape that survive the age gate below are
|
||||
// orphans of a crash between `update_latest_symlink`'s create and rename.
|
||||
let is_latest_swap_tmp =
|
||||
name.starts_with(LATEST_TMP_PREFIX) && name.ends_with(LATEST_TMP_SUFFIX);
|
||||
if !is_log && !is_latest_swap_tmp {
|
||||
continue;
|
||||
}
|
||||
// `DirEntry::metadata` does not follow symlinks, so a dangling orphaned
|
||||
// temp still yields its own mtime here.
|
||||
let Ok(modified) = entry.metadata().and_then(|m| m.modified()) else {
|
||||
continue;
|
||||
};
|
||||
if now.duration_since(modified).is_ok_and(|age| age > max_age) {
|
||||
let _ = std::fs::remove_file(&path);
|
||||
}
|
||||
}
|
||||
}
|
||||
|
||||
#[cfg(test)]
|
||||
mod tests {
|
||||
use super::*;
|
||||
|
||||
// Routing tests drive real non-blocking writers whose worker guards are
|
||||
// parked in a process-lifetime static; flushing drains ALL of them. Serialize
|
||||
// such tests so a concurrent `cargo test` thread can't clear another's guards
|
||||
// before it reads. (nextest already isolates each test in its own process.)
|
||||
fn flush_test_lock() -> std::sync::MutexGuard<'static, ()> {
|
||||
static LOCK: Mutex<()> = Mutex::new(());
|
||||
LOCK.lock().unwrap_or_else(|p| p.into_inner())
|
||||
}
|
||||
|
||||
#[test]
|
||||
fn build_file_layer_creates_parent_dir_and_file() {
|
||||
let dir = tempfile::tempdir().unwrap();
|
||||
let path = dir.path().join("nested").join("debug.log");
|
||||
assert!(!path.parent().unwrap().exists());
|
||||
|
||||
let layer = build_file_layer::<tracing_subscriber::Registry>(&path, default_file_filter());
|
||||
|
||||
assert!(layer.is_ok());
|
||||
assert!(path.parent().unwrap().exists());
|
||||
assert!(path.exists());
|
||||
}
|
||||
|
||||
#[test]
|
||||
fn build_file_layer_errors_when_open_fails() {
|
||||
// Opening an existing directory in append mode fails, exercising the Err path.
|
||||
let dir = tempfile::tempdir().unwrap();
|
||||
let layer =
|
||||
build_file_layer::<tracing_subscriber::Registry>(dir.path(), default_file_filter());
|
||||
assert!(layer.is_err());
|
||||
}
|
||||
|
||||
#[test]
|
||||
fn resolve_target_unset_is_none() {
|
||||
assert!(resolve_debug_target_inner(None, None, Path::new("/debug")).is_none());
|
||||
}
|
||||
|
||||
#[test]
|
||||
fn resolve_target_debug_log_disabled_is_none() {
|
||||
for v in ["0", "false", "off", "no", "", " "] {
|
||||
assert!(
|
||||
resolve_debug_target_inner(None, Some(OsStr::new(v)), Path::new("/debug"))
|
||||
.is_none(),
|
||||
"expected None for KIGI_DEBUG_LOG={v:?}"
|
||||
);
|
||||
}
|
||||
}
|
||||
|
||||
#[test]
|
||||
fn resolve_target_debug_log_enabled_is_per_session_dir() {
|
||||
for v in ["1", "true", "on", "yes"] {
|
||||
let target =
|
||||
resolve_debug_target_inner(None, Some(OsStr::new(v)), Path::new("/debug")).unwrap();
|
||||
assert_eq!(
|
||||
target,
|
||||
DebugTarget::PerSession {
|
||||
dir: PathBuf::from("/debug")
|
||||
},
|
||||
"expected PerSession for KIGI_DEBUG_LOG={v:?}"
|
||||
);
|
||||
}
|
||||
}
|
||||
|
||||
#[test]
|
||||
fn resolve_target_debug_log_custom_path_is_single_file() {
|
||||
let target = resolve_debug_target_inner(
|
||||
None,
|
||||
Some(OsStr::new("/tmp/custom.log")),
|
||||
Path::new("/debug"),
|
||||
)
|
||||
.unwrap();
|
||||
assert_eq!(
|
||||
target,
|
||||
DebugTarget::SingleFile {
|
||||
path: PathBuf::from("/tmp/custom.log"),
|
||||
src: DebugSource::GrokDebugLog,
|
||||
}
|
||||
);
|
||||
}
|
||||
|
||||
#[test]
|
||||
fn resolve_target_log_file_wins_over_debug_log() {
|
||||
let target = resolve_debug_target_inner(
|
||||
Some(OsStr::new("/tmp/explicit.log")),
|
||||
Some(OsStr::new("1")),
|
||||
Path::new("/debug"),
|
||||
)
|
||||
.unwrap();
|
||||
assert_eq!(
|
||||
target,
|
||||
DebugTarget::SingleFile {
|
||||
path: PathBuf::from("/tmp/explicit.log"),
|
||||
src: DebugSource::GrokLogFile,
|
||||
}
|
||||
);
|
||||
}
|
||||
|
||||
#[test]
|
||||
fn resolve_target_empty_log_file_falls_through_to_debug_log() {
|
||||
// Empty / whitespace KIGI_LOG_FILE is treated as unset (mirrors KIGI_DEBUG_LOG).
|
||||
for blank in ["", " "] {
|
||||
let target = resolve_debug_target_inner(
|
||||
Some(OsStr::new(blank)),
|
||||
Some(OsStr::new("1")),
|
||||
Path::new("/debug"),
|
||||
)
|
||||
.unwrap();
|
||||
assert_eq!(
|
||||
target,
|
||||
DebugTarget::PerSession {
|
||||
dir: PathBuf::from("/debug")
|
||||
}
|
||||
);
|
||||
}
|
||||
assert!(
|
||||
resolve_debug_target_inner(Some(OsStr::new("")), None, Path::new("/debug")).is_none()
|
||||
);
|
||||
}
|
||||
|
||||
#[cfg(unix)]
|
||||
#[test]
|
||||
fn resolve_target_non_utf8_debug_log_path_is_single_file() {
|
||||
use std::os::unix::ffi::OsStrExt;
|
||||
|
||||
// A non-UTF-8 KIGI_DEBUG_LOG value is a path, not a bool keyword, and its
|
||||
// bytes must round-trip (not be silently dropped).
|
||||
let raw = OsStr::from_bytes(b"/tmp/\xff/fire.txt");
|
||||
let target = resolve_debug_target_inner(None, Some(raw), Path::new("/debug")).unwrap();
|
||||
match target {
|
||||
DebugTarget::SingleFile { path, src } => {
|
||||
assert_eq!(src, DebugSource::GrokDebugLog);
|
||||
assert_eq!(path.as_os_str(), raw);
|
||||
}
|
||||
other => panic!("expected SingleFile for non-UTF-8 path, got {other:?}"),
|
||||
}
|
||||
}
|
||||
|
||||
#[test]
|
||||
fn firehose_directives_parse() {
|
||||
// Guard against the const rotting: every directive must parse strictly.
|
||||
for d in firehose_directives().split(',') {
|
||||
d.parse::<tracing_subscriber::filter::Directive>()
|
||||
.unwrap_or_else(|e| panic!("invalid directive {d:?}: {e}"));
|
||||
}
|
||||
}
|
||||
|
||||
#[test]
|
||||
fn firehose_directives_include_acp_update_targets() {
|
||||
let directives = firehose_directives();
|
||||
assert!(directives.contains(&format!("{ACP_UPDATE_TARGET}=debug")));
|
||||
assert!(!directives.contains(&format!("{ACP_UPDATE_PAYLOAD_TARGET}=debug")));
|
||||
}
|
||||
|
||||
#[test]
|
||||
fn sanitize_key_replaces_path_separators_and_dot_only() {
|
||||
assert_eq!(sanitize_key("01923-abcd-EF"), "01923-abcd-EF");
|
||||
assert_eq!(sanitize_key("../escape"), ".._escape");
|
||||
assert_eq!(sanitize_key("a/b\\c"), "a_b_c");
|
||||
// Dot-only / empty keys collapse to a safe constant.
|
||||
for dotty in ["", ".", "..", "..."] {
|
||||
assert_eq!(sanitize_key(dotty), "_", "expected '_' for {dotty:?}");
|
||||
}
|
||||
}
|
||||
|
||||
#[test]
|
||||
fn layer_routes_event_by_session_span() {
|
||||
use tracing_subscriber::layer::SubscriberExt as _;
|
||||
|
||||
let _lock = flush_test_lock();
|
||||
let dir = tempfile::tempdir().unwrap();
|
||||
let layer = RoutingLayer::new(dir.path().to_path_buf(), "agent".to_owned(), 4242);
|
||||
let subscriber = tracing_subscriber::registry().with(layer);
|
||||
|
||||
tracing::subscriber::with_default(subscriber, || {
|
||||
// `%` mirrors production's `info_span!("session", session_id = %...)`.
|
||||
tracing::info_span!("session", session_id = %"sess-xyz").in_scope(|| {
|
||||
tracing::info!(target: "kigi_shell", "inside session");
|
||||
});
|
||||
tracing::info!(target: "kigi_shell", "outside session");
|
||||
});
|
||||
crate::appender::flush_file_log_guards();
|
||||
|
||||
let session_file = std::fs::read_to_string(dir.path().join("sess-xyz.txt")).unwrap();
|
||||
assert!(
|
||||
session_file.contains("inside session"),
|
||||
"session file: {session_file:?}"
|
||||
);
|
||||
assert!(!session_file.contains("outside session"));
|
||||
|
||||
let fallback = std::fs::read_to_string(dir.path().join("agent-4242.txt")).unwrap();
|
||||
assert!(
|
||||
fallback.contains("outside session"),
|
||||
"fallback file: {fallback:?}"
|
||||
);
|
||||
assert!(!fallback.contains("inside session"));
|
||||
}
|
||||
|
||||
#[test]
|
||||
fn layer_routes_under_real_firehose_filter() {
|
||||
use tracing_subscriber::layer::SubscriberExt as _;
|
||||
|
||||
let _lock = flush_test_lock();
|
||||
let dir = tempfile::tempdir().unwrap();
|
||||
// Exactly the production wrapper: routing layer behind FIREHOSE_DIRECTIVES.
|
||||
// Pins the linchpin invariant — the `session` span (INFO, target
|
||||
// `kigi_log::session_ctx`) survives the real filter so
|
||||
// `event_scope` still finds it — at the unit level.
|
||||
let layer = RoutingLayer::new(dir.path().to_path_buf(), "agent".to_owned(), 7)
|
||||
.with_filter(firehose_filter());
|
||||
let subscriber = tracing_subscriber::registry().with(layer);
|
||||
|
||||
tracing::subscriber::with_default(subscriber, || {
|
||||
tracing::info_span!(
|
||||
target: "kigi_log::session_ctx",
|
||||
"session",
|
||||
session_id = %"sid-real"
|
||||
)
|
||||
.in_scope(|| {
|
||||
tracing::debug!(target: "kigi_shell", "filtered routing works");
|
||||
});
|
||||
});
|
||||
crate::appender::flush_file_log_guards();
|
||||
|
||||
let session_file = std::fs::read_to_string(dir.path().join("sid-real.txt")).unwrap();
|
||||
assert!(
|
||||
session_file.contains("filtered routing works"),
|
||||
"session file under real filter: {session_file:?}"
|
||||
);
|
||||
// Must route to the session file, NOT silently fall back to per-pid.
|
||||
assert!(
|
||||
!dir.path().join("agent-7.txt").exists(),
|
||||
"event must route to the session file, not the fallback"
|
||||
);
|
||||
}
|
||||
|
||||
#[test]
|
||||
fn layer_routes_two_sessions_to_distinct_files() {
|
||||
use tracing_subscriber::layer::SubscriberExt as _;
|
||||
|
||||
let _lock = flush_test_lock();
|
||||
let dir = tempfile::tempdir().unwrap();
|
||||
let layer = RoutingLayer::new(dir.path().to_path_buf(), "agent".to_owned(), 1);
|
||||
let subscriber = tracing_subscriber::registry().with(layer);
|
||||
|
||||
tracing::subscriber::with_default(subscriber, || {
|
||||
tracing::info_span!("session", session_id = %"sid-one").in_scope(|| {
|
||||
// Two events in one session also prove within-session accumulation.
|
||||
tracing::info!(target: "kigi_shell", "one first");
|
||||
tracing::info!(target: "kigi_shell", "one second");
|
||||
});
|
||||
tracing::info_span!("session", session_id = %"sid-two").in_scope(|| {
|
||||
tracing::info!(target: "kigi_shell", "two only");
|
||||
});
|
||||
});
|
||||
crate::appender::flush_file_log_guards();
|
||||
|
||||
let one = std::fs::read_to_string(dir.path().join("sid-one.txt")).unwrap();
|
||||
let two = std::fs::read_to_string(dir.path().join("sid-two.txt")).unwrap();
|
||||
assert!(
|
||||
one.contains("one first") && one.contains("one second") && !one.contains("two only"),
|
||||
"sid-one.txt: {one:?}"
|
||||
);
|
||||
assert!(
|
||||
two.contains("two only") && !two.contains("one first"),
|
||||
"sid-two.txt: {two:?}"
|
||||
);
|
||||
}
|
||||
|
||||
#[cfg(unix)]
|
||||
#[test]
|
||||
fn opening_session_sink_points_latest_symlink() {
|
||||
let _lock = flush_test_lock();
|
||||
let dir = tempfile::tempdir().unwrap();
|
||||
let layer = RoutingLayer::new(dir.path().to_path_buf(), "agent".to_owned(), 1);
|
||||
|
||||
layer.write_session("sess-1", b"x\n");
|
||||
let link = dir.path().join("latest.txt");
|
||||
assert_eq!(std::fs::read_link(&link).unwrap(), Path::new("sess-1.txt"));
|
||||
|
||||
// Opening a second session repoints latest.txt at it.
|
||||
layer.write_session("sess-2", b"y\n");
|
||||
assert_eq!(std::fs::read_link(&link).unwrap(), Path::new("sess-2.txt"));
|
||||
|
||||
crate::appender::flush_file_log_guards();
|
||||
}
|
||||
|
||||
#[test]
|
||||
fn prune_old_logs_removes_old_keeps_recent_and_spares_nonmatching_and_latest() {
|
||||
use std::time::{Duration, SystemTime};
|
||||
|
||||
let dir = tempfile::tempdir().unwrap();
|
||||
let now = SystemTime::now();
|
||||
let max_age = Duration::from_secs(7 * 24 * 60 * 60);
|
||||
|
||||
let old = std::fs::File::create(dir.path().join("old-session.txt")).unwrap();
|
||||
old.set_modified(now - Duration::from_secs(8 * 24 * 60 * 60))
|
||||
.unwrap();
|
||||
let recent = std::fs::File::create(dir.path().join("recent-session.txt")).unwrap();
|
||||
recent.set_modified(now).unwrap();
|
||||
// A non-.txt file must be left untouched even if it is old.
|
||||
let other = std::fs::File::create(dir.path().join("unified.jsonl")).unwrap();
|
||||
other
|
||||
.set_modified(now - Duration::from_secs(30 * 24 * 60 * 60))
|
||||
.unwrap();
|
||||
// An old `latest.txt` must be spared (harmless stale link / sentinel).
|
||||
let latest = std::fs::File::create(dir.path().join("latest.txt")).unwrap();
|
||||
latest
|
||||
.set_modified(now - Duration::from_secs(30 * 24 * 60 * 60))
|
||||
.unwrap();
|
||||
// Orphaned `latest.txt` swap temps follow the same age rule: old reaped,
|
||||
// recent spared. Regular files here so mtimes are settable cross-platform;
|
||||
// the symlink-specific path is covered by the Unix-gated test below.
|
||||
let old_tmp =
|
||||
std::fs::File::create(dir.path().join(".latest.old-session.txt.tmp")).unwrap();
|
||||
old_tmp
|
||||
.set_modified(now - Duration::from_secs(8 * 24 * 60 * 60))
|
||||
.unwrap();
|
||||
let recent_tmp =
|
||||
std::fs::File::create(dir.path().join(".latest.recent-session.txt.tmp")).unwrap();
|
||||
recent_tmp.set_modified(now).unwrap();
|
||||
|
||||
prune_old_logs(dir.path(), max_age);
|
||||
|
||||
assert!(!dir.path().join("old-session.txt").exists());
|
||||
assert!(dir.path().join("recent-session.txt").exists());
|
||||
assert!(dir.path().join("unified.jsonl").exists());
|
||||
assert!(dir.path().join("latest.txt").exists());
|
||||
assert!(!dir.path().join(".latest.old-session.txt.tmp").exists());
|
||||
assert!(dir.path().join(".latest.recent-session.txt.tmp").exists());
|
||||
}
|
||||
|
||||
#[cfg(unix)]
|
||||
#[test]
|
||||
fn prune_old_logs_reaps_dangling_orphaned_latest_tmp_symlink() {
|
||||
use std::time::{Duration, SystemTime};
|
||||
|
||||
// Models the real orphan: a crash between `update_latest_symlink`'s
|
||||
// create and rename leaves the temp symlink, and its target session file
|
||||
// may itself be pruned later — so the link is dangling. Literal name (not
|
||||
// the consts) so renaming the scheme can't silently strand orphans
|
||||
// created by already-shipped binaries.
|
||||
let dir = tempfile::tempdir().unwrap();
|
||||
let max_age = Duration::from_secs(7 * 24 * 60 * 60);
|
||||
// `filetime` ages the link itself; std's `set_modified` follows it (and a
|
||||
// dangling link can't even be opened).
|
||||
let old = filetime::FileTime::from_system_time(
|
||||
SystemTime::now() - Duration::from_secs(8 * 24 * 60 * 60),
|
||||
);
|
||||
|
||||
let tmp = dir.path().join(".latest.gone-session.txt.tmp");
|
||||
std::os::unix::fs::symlink("gone-session.txt", &tmp).unwrap();
|
||||
filetime::set_symlink_file_times(&tmp, old, old).unwrap();
|
||||
// A just-created (mid-swap) temp must be spared by age.
|
||||
let fresh_tmp = dir.path().join(".latest.live-session.txt.tmp");
|
||||
std::os::unix::fs::symlink("live-session.txt", &fresh_tmp).unwrap();
|
||||
// `latest.txt` must stay spared by name even as an old dangling symlink.
|
||||
let latest = dir.path().join("latest.txt");
|
||||
std::os::unix::fs::symlink("gone-session.txt", &latest).unwrap();
|
||||
filetime::set_symlink_file_times(&latest, old, old).unwrap();
|
||||
|
||||
prune_old_logs(dir.path(), max_age);
|
||||
|
||||
// `Path::exists` follows symlinks (false for dangling links either way),
|
||||
// so assert on the links themselves via `symlink_metadata`.
|
||||
assert!(
|
||||
std::fs::symlink_metadata(&tmp).is_err(),
|
||||
"old orphaned dangling temp symlink must be pruned"
|
||||
);
|
||||
assert!(
|
||||
std::fs::symlink_metadata(&fresh_tmp).is_ok(),
|
||||
"fresh mid-swap temp must be spared by age"
|
||||
);
|
||||
assert!(
|
||||
std::fs::symlink_metadata(&latest).is_ok(),
|
||||
"latest.txt must be spared"
|
||||
);
|
||||
}
|
||||
|
||||
#[cfg(unix)]
|
||||
#[test]
|
||||
fn update_latest_symlink_failed_rename_removes_temp() {
|
||||
// Sanity: prove the temp symlink is creatable here, so the helper's
|
||||
// symlink step must succeed and the post-call absence below can only
|
||||
// come from the rename-failure cleanup branch.
|
||||
let dir = tempfile::tempdir().unwrap();
|
||||
let tmp = dir.path().join(".latest.sess.txt.tmp");
|
||||
std::os::unix::fs::symlink("sess.txt", &tmp).unwrap();
|
||||
std::fs::remove_file(&tmp).unwrap();
|
||||
// Force the rename to fail: a non-empty directory at `latest.txt` makes
|
||||
// rename(2) of a non-directory over it error (EISDIR/ENOTEMPTY).
|
||||
let blocker = dir.path().join("latest.txt");
|
||||
std::fs::create_dir(&blocker).unwrap();
|
||||
std::fs::File::create(blocker.join("occupant.txt")).unwrap();
|
||||
|
||||
update_latest_symlink(dir.path(), &dir.path().join("sess.txt"));
|
||||
|
||||
assert!(
|
||||
std::fs::symlink_metadata(&tmp).is_err(),
|
||||
"failed swap must remove the temp symlink, not orphan it"
|
||||
);
|
||||
assert!(
|
||||
blocker.join("occupant.txt").exists(),
|
||||
"rename must have failed, leaving the blocker dir untouched"
|
||||
);
|
||||
}
|
||||
|
||||
#[test]
|
||||
fn prune_old_logs_spares_active_logs_regardless_of_count() {
|
||||
use std::time::{Duration, SystemTime};
|
||||
|
||||
// Guards the reported bug: a concurrent process's still-open (recently
|
||||
// written) log must never be unlinked, however many newer logs exist.
|
||||
let dir = tempfile::tempdir().unwrap();
|
||||
let now = SystemTime::now();
|
||||
for i in 0..25 {
|
||||
let f = std::fs::File::create(dir.path().join(format!("cli-{i}.txt"))).unwrap();
|
||||
f.set_modified(now).unwrap();
|
||||
}
|
||||
|
||||
prune_old_logs(dir.path(), Duration::from_secs(7 * 24 * 60 * 60));
|
||||
|
||||
let count = std::fs::read_dir(dir.path())
|
||||
.unwrap()
|
||||
.flatten()
|
||||
.filter(|e| e.file_name().to_str().is_some_and(|n| n.ends_with(".txt")))
|
||||
.count();
|
||||
assert_eq!(count, 25);
|
||||
}
|
||||
|
||||
#[test]
|
||||
fn prune_old_logs_missing_dir_is_noop() {
|
||||
// Best-effort: a nonexistent debug dir must not panic.
|
||||
prune_old_logs(
|
||||
Path::new("/no/such/grok/debug/dir"),
|
||||
std::time::Duration::from_secs(1),
|
||||
);
|
||||
}
|
||||
}
|
||||
@@ -0,0 +1,123 @@
|
||||
//! Hooks and plugins tracing target and optional file-based logging layer.
|
||||
//!
|
||||
//! A dedicated tracing target for hooks and plugins subsystems with an optional
|
||||
//! file logger that writes to `~/.kigi/logs/hooks.log`.
|
||||
//!
|
||||
//! ## When to use
|
||||
//!
|
||||
//! Use regular `tracing::info!` / `tracing::debug!` / `tracing::warn!` with
|
||||
//! targets `kigi_hooks` or `kigi_agent::plugins` at key lifecycle
|
||||
//! points — discovery, dispatch, execution, errors.
|
||||
//!
|
||||
//! ## Enabling
|
||||
//!
|
||||
//! ```bash
|
||||
//! KIGI_HOOKS_LOG=1 grok # enable, write to ~/.kigi/logs/hooks.log
|
||||
//! KIGI_HOOKS_LOG=/tmp/h.log grok # write to custom path
|
||||
//! KIGI_HOOKS_LOG=0 grok # explicitly disable
|
||||
//! tail -f ~/.kigi/logs/hooks.log # watch in another terminal
|
||||
//! ```
|
||||
|
||||
use std::fmt;
|
||||
use std::path::PathBuf;
|
||||
use std::sync::Mutex;
|
||||
use std::time::Instant;
|
||||
|
||||
use tracing::Subscriber;
|
||||
use tracing_subscriber::fmt::format::Writer;
|
||||
use tracing_subscriber::fmt::time::FormatTime;
|
||||
use tracing_subscriber::fmt::writer::BoxMakeWriter;
|
||||
use tracing_subscriber::layer::Layer;
|
||||
use tracing_subscriber::registry::LookupSpan;
|
||||
|
||||
use kigi_config::kigi_home;
|
||||
|
||||
const ENV_HOOKS_LOG: &str = "KIGI_HOOKS_LOG";
|
||||
|
||||
static LOG_GUARD: std::sync::OnceLock<Mutex<Option<tracing_appender::non_blocking::WorkerGuard>>> =
|
||||
std::sync::OnceLock::new();
|
||||
|
||||
#[derive(Clone)]
|
||||
struct UptimeTimer {
|
||||
epoch: Instant,
|
||||
}
|
||||
|
||||
impl UptimeTimer {
|
||||
fn new() -> Self {
|
||||
Self {
|
||||
epoch: Instant::now(),
|
||||
}
|
||||
}
|
||||
}
|
||||
|
||||
impl FormatTime for UptimeTimer {
|
||||
fn format_time(&self, w: &mut Writer<'_>) -> fmt::Result {
|
||||
let elapsed = self.epoch.elapsed();
|
||||
write!(w, "+{}.{:03}s", elapsed.as_secs(), elapsed.subsec_millis())
|
||||
}
|
||||
}
|
||||
|
||||
/// Build the hooks/plugins log layer.
|
||||
///
|
||||
/// Writes to `~/.kigi/logs/hooks.log` (or custom path via `KIGI_HOOKS_LOG`).
|
||||
/// Filters to hooks (`kigi_hooks`) and plugins (`kigi_agent::plugins`) targets.
|
||||
/// Set `KIGI_HOOKS_LOG=0` to disable, `KIGI_HOOKS_LOG=/path` to redirect.
|
||||
pub fn layer<S>() -> Option<impl Layer<S>>
|
||||
where
|
||||
S: Subscriber + for<'span> LookupSpan<'span>,
|
||||
{
|
||||
let path = resolve_log_path()?;
|
||||
|
||||
if let Some(parent) = path.parent() {
|
||||
let _ = std::fs::create_dir_all(parent);
|
||||
}
|
||||
|
||||
let file = match std::fs::OpenOptions::new()
|
||||
.create(true)
|
||||
.append(true)
|
||||
.open(&path)
|
||||
{
|
||||
Ok(f) => f,
|
||||
Err(e) => {
|
||||
tracing::warn!("[hooks-log] Failed to open {:?}: {}", path, e);
|
||||
return None;
|
||||
}
|
||||
};
|
||||
|
||||
let (non_blocking, guard) = tracing_appender::non_blocking(file);
|
||||
let guard_slot = LOG_GUARD.get_or_init(|| Mutex::new(None));
|
||||
if let Ok(mut slot) = guard_slot.lock() {
|
||||
*slot = Some(guard);
|
||||
}
|
||||
|
||||
// Filter for both hooks and plugins targets at debug level
|
||||
let filter =
|
||||
tracing_subscriber::filter::EnvFilter::new("kigi_hooks=debug,kigi_agent::plugins=debug");
|
||||
let fmt_layer = tracing_subscriber::fmt::layer()
|
||||
.with_target(true)
|
||||
.with_ansi(false)
|
||||
.with_thread_ids(true)
|
||||
.with_timer(UptimeTimer::new())
|
||||
.with_writer(BoxMakeWriter::new(non_blocking))
|
||||
.with_filter(filter);
|
||||
|
||||
tracing::info!(
|
||||
"[hooks-log] Hooks/plugins logging enabled: {}",
|
||||
path.display()
|
||||
);
|
||||
Some(fmt_layer)
|
||||
}
|
||||
|
||||
fn resolve_log_path() -> Option<PathBuf> {
|
||||
let default_path = || kigi_home().join("logs").join("hooks.log");
|
||||
let raw = match std::env::var(ENV_HOOKS_LOG) {
|
||||
Ok(val) => val,
|
||||
Err(_) => return None, // opt-in only
|
||||
};
|
||||
let raw = raw.trim();
|
||||
match raw {
|
||||
"" | "0" | "false" | "off" | "no" => None,
|
||||
"1" | "true" | "on" | "yes" => Some(default_path()),
|
||||
other => Some(PathBuf::from(other)),
|
||||
}
|
||||
}
|
||||
@@ -0,0 +1,616 @@
|
||||
use std::io::{self, BufRead};
|
||||
use std::marker::PhantomData;
|
||||
use std::path::PathBuf;
|
||||
use std::sync::{Mutex, OnceLock};
|
||||
use std::time::Instant;
|
||||
|
||||
use anyhow::{Result, anyhow};
|
||||
use chrono::{DateTime, FixedOffset};
|
||||
use serde_json::Value;
|
||||
use tracing::Subscriber;
|
||||
use tracing_chrome::{ChromeLayerBuilder, FlushGuard, TraceStyle};
|
||||
use tracing_subscriber::fmt::writer::BoxMakeWriter;
|
||||
use tracing_subscriber::layer::{Context, Layer};
|
||||
use tracing_subscriber::registry::LookupSpan;
|
||||
|
||||
use kigi_config::kigi_home;
|
||||
|
||||
const ENV_ENABLED: &str = "KIGI_INSTRUMENTATION";
|
||||
const ENV_LOG_PATH: &str = "KIGI_INSTRUMENTATION_LOG";
|
||||
const DEFAULT_LOG_DIR: &str = "logs";
|
||||
const DEFAULT_LOG_FILE: &str = "instrumentation.log";
|
||||
const DEFAULT_TRACE_FILE: &str = "instrumentation.trace.json";
|
||||
|
||||
pub const TARGET: &str = "kigi_instrumentation";
|
||||
|
||||
#[derive(Debug, Clone, Copy, PartialEq, Eq)]
|
||||
pub enum InstrumentationMode {
|
||||
Disabled,
|
||||
Log,
|
||||
Chrome,
|
||||
}
|
||||
|
||||
static INSTRUMENTATION_MODE: OnceLock<InstrumentationMode> = OnceLock::new();
|
||||
static LOG_GUARD: OnceLock<Mutex<Option<tracing_appender::non_blocking::WorkerGuard>>> =
|
||||
OnceLock::new();
|
||||
static CHROME_GUARD: OnceLock<Mutex<Option<FlushGuard>>> = OnceLock::new();
|
||||
|
||||
fn mode() -> InstrumentationMode {
|
||||
*INSTRUMENTATION_MODE.get_or_init(|| {
|
||||
let env_mode = match std::env::var(ENV_ENABLED) {
|
||||
Ok(v) => match v.trim().to_ascii_lowercase().as_str() {
|
||||
"1" | "true" | "on" | "enabled" | "log" | "json" | "jsonl" => {
|
||||
Some(InstrumentationMode::Log)
|
||||
}
|
||||
"chrome" | "trace" | "trace.json" => Some(InstrumentationMode::Chrome),
|
||||
"" | "0" | "false" | "off" | "disabled" | "none" => {
|
||||
Some(InstrumentationMode::Disabled)
|
||||
}
|
||||
_ => Some(InstrumentationMode::Log),
|
||||
},
|
||||
Err(_) => None,
|
||||
};
|
||||
|
||||
// Instrumentation is opt-in local profiling; absent the env var it is off.
|
||||
env_mode.unwrap_or(InstrumentationMode::Disabled)
|
||||
})
|
||||
}
|
||||
|
||||
pub fn current_mode() -> InstrumentationMode {
|
||||
mode()
|
||||
}
|
||||
|
||||
fn default_log_path() -> PathBuf {
|
||||
kigi_home().join(DEFAULT_LOG_DIR).join(DEFAULT_LOG_FILE)
|
||||
}
|
||||
|
||||
fn log_path_from_env() -> Option<PathBuf> {
|
||||
std::env::var(ENV_LOG_PATH)
|
||||
.ok()
|
||||
.map(|path| path.trim().to_string())
|
||||
.filter(|path| !path.is_empty())
|
||||
.map(PathBuf::from)
|
||||
}
|
||||
|
||||
fn default_output_path(mode: InstrumentationMode) -> PathBuf {
|
||||
let root = kigi_home().join(DEFAULT_LOG_DIR);
|
||||
match mode {
|
||||
InstrumentationMode::Chrome => root.join(DEFAULT_TRACE_FILE),
|
||||
InstrumentationMode::Log | InstrumentationMode::Disabled => root.join(DEFAULT_LOG_FILE),
|
||||
}
|
||||
}
|
||||
|
||||
/// A wrapper layer that filters events by target name.
|
||||
///
|
||||
/// This is used instead of `.with_filter()` because `Filtered<L, F, S>` layers
|
||||
/// require `FilterId` registration with the subscriber. When boxed as
|
||||
/// `Box<dyn Layer<S>>`, the type information needed for registration is lost,
|
||||
/// causing a panic: "a Filtered layer was used, but it had no FilterId".
|
||||
///
|
||||
/// This wrapper avoids that issue by implementing filtering in the `enabled()`
|
||||
/// method directly, without using the per-layer filter mechanism.
|
||||
pub struct TargetFilterLayer<L, S> {
|
||||
inner: L,
|
||||
target: &'static str,
|
||||
_subscriber: PhantomData<fn(S)>,
|
||||
}
|
||||
|
||||
impl<L, S> TargetFilterLayer<L, S> {
|
||||
pub fn new(inner: L, target: &'static str) -> Self {
|
||||
Self {
|
||||
inner,
|
||||
target,
|
||||
_subscriber: PhantomData,
|
||||
}
|
||||
}
|
||||
}
|
||||
|
||||
impl<L, S> Layer<S> for TargetFilterLayer<L, S>
|
||||
where
|
||||
L: Layer<S>,
|
||||
S: Subscriber + for<'span> LookupSpan<'span>,
|
||||
{
|
||||
fn enabled(&self, metadata: &tracing::Metadata<'_>, ctx: Context<'_, S>) -> bool {
|
||||
metadata.target() == self.target && self.inner.enabled(metadata, ctx)
|
||||
}
|
||||
|
||||
fn on_new_span(
|
||||
&self,
|
||||
attrs: &tracing::span::Attributes<'_>,
|
||||
id: &tracing::span::Id,
|
||||
ctx: Context<'_, S>,
|
||||
) {
|
||||
if attrs.metadata().target() == self.target {
|
||||
self.inner.on_new_span(attrs, id, ctx);
|
||||
}
|
||||
}
|
||||
|
||||
fn on_record(
|
||||
&self,
|
||||
span: &tracing::span::Id,
|
||||
values: &tracing::span::Record<'_>,
|
||||
ctx: Context<'_, S>,
|
||||
) {
|
||||
self.inner.on_record(span, values, ctx);
|
||||
}
|
||||
|
||||
fn on_follows_from(
|
||||
&self,
|
||||
span: &tracing::span::Id,
|
||||
follows: &tracing::span::Id,
|
||||
ctx: Context<'_, S>,
|
||||
) {
|
||||
self.inner.on_follows_from(span, follows, ctx);
|
||||
}
|
||||
|
||||
fn on_event(&self, event: &tracing::Event<'_>, ctx: Context<'_, S>) {
|
||||
if event.metadata().target() == self.target {
|
||||
self.inner.on_event(event, ctx);
|
||||
}
|
||||
}
|
||||
|
||||
fn on_enter(&self, id: &tracing::span::Id, ctx: Context<'_, S>) {
|
||||
self.inner.on_enter(id, ctx);
|
||||
}
|
||||
|
||||
fn on_exit(&self, id: &tracing::span::Id, ctx: Context<'_, S>) {
|
||||
self.inner.on_exit(id, ctx);
|
||||
}
|
||||
|
||||
fn on_close(&self, id: tracing::span::Id, ctx: Context<'_, S>) {
|
||||
self.inner.on_close(id, ctx);
|
||||
}
|
||||
}
|
||||
|
||||
/// A no-op layer that does nothing.
|
||||
/// Used when instrumentation is disabled to avoid any overhead.
|
||||
pub struct NoOpLayer<S>(PhantomData<fn(S)>);
|
||||
|
||||
impl<S> Default for NoOpLayer<S> {
|
||||
fn default() -> Self {
|
||||
Self(PhantomData)
|
||||
}
|
||||
}
|
||||
|
||||
impl<S> NoOpLayer<S> {
|
||||
pub fn new() -> Self {
|
||||
Self::default()
|
||||
}
|
||||
}
|
||||
|
||||
impl<S: Subscriber> Layer<S> for NoOpLayer<S> {
|
||||
// All methods use default implementations which do nothing
|
||||
}
|
||||
|
||||
fn resolve_output_path(mode: InstrumentationMode) -> Option<PathBuf> {
|
||||
if mode == InstrumentationMode::Disabled {
|
||||
return None;
|
||||
}
|
||||
|
||||
log_path_from_env().or_else(|| Some(default_output_path(mode)))
|
||||
}
|
||||
|
||||
fn resolve_log_path() -> Option<PathBuf> {
|
||||
if mode() != InstrumentationMode::Log {
|
||||
return None;
|
||||
}
|
||||
resolve_output_path(InstrumentationMode::Log)
|
||||
}
|
||||
|
||||
fn build_writer(path: Option<PathBuf>) -> BoxMakeWriter {
|
||||
let Some(path) = path else {
|
||||
return BoxMakeWriter::new(std::io::sink);
|
||||
};
|
||||
|
||||
if let Some(parent) = path.parent()
|
||||
&& let Err(err) = std::fs::create_dir_all(parent)
|
||||
{
|
||||
eprintln!(
|
||||
"Failed to create instrumentation log directory {:?}: {}",
|
||||
parent, err
|
||||
);
|
||||
return BoxMakeWriter::new(std::io::sink);
|
||||
}
|
||||
|
||||
let file = match std::fs::OpenOptions::new()
|
||||
.create(true)
|
||||
.append(true)
|
||||
.open(&path)
|
||||
{
|
||||
Ok(file) => file,
|
||||
Err(err) => {
|
||||
eprintln!(
|
||||
"Failed to open instrumentation log file {:?}: {}",
|
||||
path, err
|
||||
);
|
||||
return BoxMakeWriter::new(std::io::sink);
|
||||
}
|
||||
};
|
||||
|
||||
let (non_blocking, guard) = tracing_appender::non_blocking(file);
|
||||
let guard_slot = LOG_GUARD.get_or_init(|| Mutex::new(None));
|
||||
if let Ok(mut slot) = guard_slot.lock() {
|
||||
*slot = Some(guard);
|
||||
}
|
||||
BoxMakeWriter::new(non_blocking)
|
||||
}
|
||||
|
||||
fn build_log_layer<S>(mode: InstrumentationMode) -> Box<dyn Layer<S> + Send + Sync>
|
||||
where
|
||||
S: Subscriber + for<'span> LookupSpan<'span> + Send + Sync + 'static,
|
||||
{
|
||||
// When disabled, return a true no-op layer that does nothing.
|
||||
// This avoids any overhead and potential issues with complex layer types.
|
||||
if mode == InstrumentationMode::Disabled {
|
||||
return Box::new(NoOpLayer::new());
|
||||
}
|
||||
|
||||
let writer = build_writer(resolve_log_path());
|
||||
|
||||
// Use TargetFilterLayer instead of .with_filter() to avoid the FilterId
|
||||
// registration issue when the layer is boxed as Box<dyn Layer<S>>.
|
||||
let fmt_layer = tracing_subscriber::fmt::layer()
|
||||
.json()
|
||||
.with_current_span(false) // `spans` array already carries the full ancestor list
|
||||
.with_ansi(false)
|
||||
.with_timer(tracing_subscriber::fmt::time::UtcTime::rfc_3339())
|
||||
.with_thread_ids(true)
|
||||
.with_thread_names(true)
|
||||
.with_target(true)
|
||||
.with_writer(writer);
|
||||
|
||||
Box::new(TargetFilterLayer::new(fmt_layer, TARGET))
|
||||
}
|
||||
|
||||
fn build_chrome_layer<S>() -> Box<dyn Layer<S> + Send + Sync>
|
||||
where
|
||||
S: Subscriber + for<'span> LookupSpan<'span> + Send + Sync + 'static,
|
||||
{
|
||||
let Some(path) = resolve_output_path(InstrumentationMode::Chrome) else {
|
||||
return build_log_layer(InstrumentationMode::Disabled);
|
||||
};
|
||||
|
||||
if let Some(parent) = path.parent()
|
||||
&& let Err(err) = std::fs::create_dir_all(parent)
|
||||
{
|
||||
eprintln!(
|
||||
"Failed to create chrome trace directory {:?}: {}",
|
||||
parent, err
|
||||
);
|
||||
return build_log_layer(InstrumentationMode::Disabled);
|
||||
}
|
||||
|
||||
let file = match std::fs::OpenOptions::new()
|
||||
.create(true)
|
||||
.truncate(true)
|
||||
.write(true)
|
||||
.open(&path)
|
||||
{
|
||||
Ok(file) => file,
|
||||
Err(err) => {
|
||||
eprintln!("Failed to open chrome trace file {:?}: {}", path, err);
|
||||
return build_log_layer(InstrumentationMode::Disabled);
|
||||
}
|
||||
};
|
||||
|
||||
let (layer, guard) = ChromeLayerBuilder::<S>::new()
|
||||
.writer(file)
|
||||
.include_args(true)
|
||||
.trace_style(TraceStyle::Async)
|
||||
.build();
|
||||
|
||||
let guard_slot = CHROME_GUARD.get_or_init(|| Mutex::new(None));
|
||||
if let Ok(mut slot) = guard_slot.lock() {
|
||||
*slot = Some(guard);
|
||||
}
|
||||
|
||||
// Use TargetFilterLayer instead of .with_filter() to avoid the FilterId
|
||||
// registration issue when the layer is boxed as Box<dyn Layer<S>>.
|
||||
Box::new(TargetFilterLayer::new(layer, TARGET))
|
||||
}
|
||||
|
||||
pub fn layer<S>() -> Box<dyn Layer<S> + Send + Sync>
|
||||
where
|
||||
S: Subscriber + for<'span> LookupSpan<'span> + Send + Sync + 'static,
|
||||
{
|
||||
let mode = mode();
|
||||
match mode {
|
||||
InstrumentationMode::Chrome => build_chrome_layer(),
|
||||
InstrumentationMode::Log => build_log_layer(mode),
|
||||
InstrumentationMode::Disabled => build_log_layer(InstrumentationMode::Disabled),
|
||||
}
|
||||
}
|
||||
|
||||
/// Install a global panic hook that emits a structured tracing event before
|
||||
/// invoking the default hook. Call this once, early in `main`, after the
|
||||
/// tracing subscriber has been installed.
|
||||
pub fn install_panic_hook() {
|
||||
let default_hook = std::panic::take_hook();
|
||||
std::panic::set_hook(Box::new(move |info| {
|
||||
let message = if let Some(s) = info.payload().downcast_ref::<&str>() {
|
||||
s.to_string()
|
||||
} else if let Some(s) = info.payload().downcast_ref::<String>() {
|
||||
s.clone()
|
||||
} else {
|
||||
"unknown panic".to_string()
|
||||
};
|
||||
let location = info
|
||||
.location()
|
||||
.map(|l| format!("{}:{}:{}", l.file(), l.line(), l.column()));
|
||||
// `location` is the panic's source `file:line:col` (no user content);
|
||||
// path-scrubbed by the redact layer. Gives the panic counter a place
|
||||
// to point without exporting the message/stack.
|
||||
let err_span = tracing::info_span!(
|
||||
"internal_error",
|
||||
error_type = "panic",
|
||||
location = tracing::field::Empty,
|
||||
);
|
||||
if let Some(loc) = location.as_deref() {
|
||||
err_span.record("location", loc);
|
||||
}
|
||||
err_span.in_scope(|| {});
|
||||
tracing::error!(
|
||||
error_type = "panic",
|
||||
panic.message = %message,
|
||||
panic.location = ?location,
|
||||
"Process panicked"
|
||||
);
|
||||
default_hook(info);
|
||||
}));
|
||||
}
|
||||
|
||||
fn resolve_input_path(input: Option<PathBuf>) -> Result<PathBuf> {
|
||||
if let Some(path) = input {
|
||||
return Ok(path);
|
||||
}
|
||||
if let Some(path) = log_path_from_env() {
|
||||
return Ok(path);
|
||||
}
|
||||
Ok(default_log_path())
|
||||
}
|
||||
|
||||
#[derive(Debug, Clone, Default)]
|
||||
pub struct ChromeTraceOptions {
|
||||
pub input: Option<PathBuf>,
|
||||
pub output: Option<PathBuf>,
|
||||
}
|
||||
|
||||
pub fn generate_chrome_trace(options: ChromeTraceOptions) -> Result<PathBuf> {
|
||||
let input = resolve_input_path(options.input)?;
|
||||
let output = options
|
||||
.output
|
||||
.unwrap_or_else(|| input.with_extension("trace.json"));
|
||||
|
||||
let file = std::fs::File::open(&input)
|
||||
.map_err(|err| anyhow!("failed to open instrumentation log {:?}: {}", input, err))?;
|
||||
let reader = io::BufReader::new(file);
|
||||
|
||||
let mut events: Vec<Value> = Vec::new();
|
||||
let mut seen = 0usize;
|
||||
|
||||
for line in reader.lines() {
|
||||
let line = match line {
|
||||
Ok(line) => line,
|
||||
Err(_) => continue,
|
||||
};
|
||||
let value: Value = match serde_json::from_str(&line) {
|
||||
Ok(value) => value,
|
||||
Err(_) => continue,
|
||||
};
|
||||
|
||||
let target = value.get("target").and_then(Value::as_str);
|
||||
if target != Some(TARGET) {
|
||||
continue;
|
||||
}
|
||||
|
||||
let fields = match value.get("fields").and_then(Value::as_object) {
|
||||
Some(fields) => fields,
|
||||
None => continue,
|
||||
};
|
||||
|
||||
let event = fields.get("event").and_then(Value::as_str);
|
||||
if event != Some("timing") {
|
||||
continue;
|
||||
}
|
||||
|
||||
let name = match fields.get("name").and_then(Value::as_str) {
|
||||
Some(name) => name,
|
||||
None => continue,
|
||||
};
|
||||
|
||||
// Support both elapsed_us (new) and elapsed_ms (legacy) formats
|
||||
let dur_us = if let Some(us) = fields.get("elapsed_us").and_then(|v| v.as_u64()) {
|
||||
us
|
||||
} else if let Some(ms) = fields.get("elapsed_ms").and_then(|v| v.as_u64()) {
|
||||
ms.saturating_mul(1_000)
|
||||
} else {
|
||||
continue;
|
||||
};
|
||||
if dur_us == 0 {
|
||||
continue;
|
||||
}
|
||||
|
||||
let timestamp = value.get("timestamp").and_then(Value::as_str);
|
||||
let end_us = match timestamp.and_then(parse_timestamp_us) {
|
||||
Some(ts) => ts,
|
||||
None => continue,
|
||||
};
|
||||
let start_us = end_us.saturating_sub(dur_us as i64);
|
||||
|
||||
let mut args = serde_json::Map::new();
|
||||
args.insert("elapsed_us".to_string(), Value::Number(dur_us.into()));
|
||||
if let Some(extra) = fields.get("fields") {
|
||||
args.insert("fields".to_string(), extra.clone());
|
||||
}
|
||||
|
||||
let thread_name = value
|
||||
.get("thread_name")
|
||||
.or_else(|| value.get("threadName"))
|
||||
.and_then(Value::as_str);
|
||||
if let Some(name) = thread_name {
|
||||
args.insert("thread_name".to_string(), Value::String(name.to_string()));
|
||||
}
|
||||
|
||||
let thread_id = value
|
||||
.get("thread_id")
|
||||
.or_else(|| value.get("threadId"))
|
||||
.and_then(parse_thread_id)
|
||||
.unwrap_or(0);
|
||||
|
||||
let trace_event = serde_json::json!({
|
||||
"name": name,
|
||||
"cat": "instrumentation",
|
||||
"ph": "X",
|
||||
"ts": start_us,
|
||||
"dur": dur_us,
|
||||
"pid": 1,
|
||||
"tid": thread_id,
|
||||
"args": Value::Object(args),
|
||||
});
|
||||
|
||||
events.push(trace_event);
|
||||
seen += 1;
|
||||
}
|
||||
|
||||
if seen == 0 {
|
||||
return Err(anyhow!("no timing events found in {:?}", input));
|
||||
}
|
||||
|
||||
let trace = serde_json::json!({
|
||||
"displayTimeUnit": "ms",
|
||||
"traceEvents": events,
|
||||
});
|
||||
|
||||
let mut output_file = std::fs::File::create(&output)
|
||||
.map_err(|err| anyhow!("failed to create chrome trace {:?}: {}", output, err))?;
|
||||
serde_json::to_writer_pretty(&mut output_file, &trace)
|
||||
.map_err(|err| anyhow!("failed to write chrome trace: {}", err))?;
|
||||
|
||||
Ok(output)
|
||||
}
|
||||
|
||||
pub fn finalize() -> Result<()> {
|
||||
let mode = mode();
|
||||
if mode == InstrumentationMode::Disabled {
|
||||
return Ok(());
|
||||
}
|
||||
|
||||
drop_guard(LOG_GUARD.get());
|
||||
drop_guard(CHROME_GUARD.get());
|
||||
|
||||
Ok(())
|
||||
}
|
||||
|
||||
fn drop_guard<T>(guard: Option<&Mutex<Option<T>>>) {
|
||||
if let Some(lock) = guard
|
||||
&& let Ok(mut slot) = lock.lock()
|
||||
{
|
||||
let _ = slot.take();
|
||||
}
|
||||
}
|
||||
|
||||
pub struct InstrumentationFinalizer;
|
||||
|
||||
impl Drop for InstrumentationFinalizer {
|
||||
fn drop(&mut self) {
|
||||
let _ = finalize();
|
||||
}
|
||||
}
|
||||
|
||||
pub fn finalizer() -> InstrumentationFinalizer {
|
||||
InstrumentationFinalizer
|
||||
}
|
||||
|
||||
fn parse_timestamp_us(timestamp: &str) -> Option<i64> {
|
||||
let parsed: DateTime<FixedOffset> = DateTime::parse_from_rfc3339(timestamp).ok()?;
|
||||
Some(parsed.timestamp_micros())
|
||||
}
|
||||
|
||||
fn parse_thread_id(value: &Value) -> Option<i64> {
|
||||
match value {
|
||||
Value::Number(n) => n.as_i64(),
|
||||
Value::String(s) => s.parse::<i64>().ok(),
|
||||
_ => None,
|
||||
}
|
||||
}
|
||||
|
||||
pub struct InstrumentationTimer {
|
||||
name: &'static str,
|
||||
start: Instant,
|
||||
fields: Vec<(String, Value)>,
|
||||
mode: InstrumentationMode,
|
||||
_span_guard: Option<tracing::span::EnteredSpan>,
|
||||
}
|
||||
|
||||
impl InstrumentationTimer {
|
||||
pub fn new(name: &'static str) -> Self {
|
||||
Self {
|
||||
name,
|
||||
start: Instant::now(),
|
||||
fields: Vec::new(),
|
||||
mode: mode(),
|
||||
_span_guard: None,
|
||||
}
|
||||
}
|
||||
|
||||
pub fn new_with_span(
|
||||
name: &'static str,
|
||||
mode: InstrumentationMode,
|
||||
span_guard: Option<tracing::span::EnteredSpan>,
|
||||
) -> Self {
|
||||
Self {
|
||||
name,
|
||||
start: Instant::now(),
|
||||
fields: Vec::new(),
|
||||
mode,
|
||||
_span_guard: span_guard,
|
||||
}
|
||||
}
|
||||
|
||||
pub fn with_field(&mut self, key: impl Into<String>, value: impl Into<Value>) -> &mut Self {
|
||||
if self.mode != InstrumentationMode::Disabled && self.mode != InstrumentationMode::Chrome {
|
||||
self.fields.push((key.into(), value.into()));
|
||||
}
|
||||
self
|
||||
}
|
||||
}
|
||||
|
||||
impl Drop for InstrumentationTimer {
|
||||
fn drop(&mut self) {
|
||||
if self.mode == InstrumentationMode::Disabled {
|
||||
return;
|
||||
}
|
||||
if self.mode == InstrumentationMode::Chrome {
|
||||
let _ = self._span_guard.take();
|
||||
return;
|
||||
}
|
||||
let elapsed_us = self.start.elapsed().as_micros() as u64;
|
||||
if self.fields.is_empty() {
|
||||
tracing::info!(
|
||||
target: TARGET,
|
||||
event = "timing",
|
||||
name = self.name,
|
||||
elapsed_us = elapsed_us,
|
||||
);
|
||||
return;
|
||||
}
|
||||
|
||||
let mut map = serde_json::Map::new();
|
||||
for (key, value) in std::mem::take(&mut self.fields) {
|
||||
map.insert(key, value);
|
||||
}
|
||||
|
||||
let fields = Value::Object(map);
|
||||
tracing::info!(
|
||||
target: TARGET,
|
||||
event = "timing",
|
||||
name = self.name,
|
||||
elapsed_us = elapsed_us,
|
||||
fields = ?fields
|
||||
);
|
||||
}
|
||||
}
|
||||
|
||||
pub fn timer(name: &'static str) -> InstrumentationTimer {
|
||||
InstrumentationTimer::new(name)
|
||||
}
|
||||
@@ -0,0 +1,18 @@
|
||||
//! Local, zero-egress observability for Kigi sessions.
|
||||
//!
|
||||
//! Every sink in this crate writes to the local filesystem (under the Kigi
|
||||
//! home directory) and nothing else: the unified session log, the `--debug`
|
||||
//! firehose, subsystem file logs (memory, hooks, sampling), and the
|
||||
//! env-gated performance instrumentation. No module here opens a network
|
||||
//! connection — that property is the crate's contract.
|
||||
|
||||
mod appender;
|
||||
pub mod debug_log;
|
||||
pub mod hooks_log;
|
||||
pub mod instrumentation;
|
||||
pub mod memory_log;
|
||||
pub mod sampling_log;
|
||||
pub mod session_ctx;
|
||||
pub mod unified_log;
|
||||
|
||||
pub use session_ctx::with_session_ctx;
|
||||
@@ -0,0 +1,127 @@
|
||||
//! Memory system tracing target and optional file-based logging layer.
|
||||
//!
|
||||
//! Provides a dedicated tracing target (`xai_memory`) with an optional
|
||||
//! file logger that writes to `~/.kigi/logs/memory.log`.
|
||||
//!
|
||||
//! ## When to use
|
||||
//!
|
||||
//! Use `tracing::info!(target: memory_log::TARGET, ...)` at memory system
|
||||
//! lifecycle points — config resolution, storage init, flush, search, etc.
|
||||
//! These events are always emitted (zero cost when the layer is absent).
|
||||
//!
|
||||
//! ## Enabling (debug builds)
|
||||
//!
|
||||
//! ```bash
|
||||
//! # build with memory logging enabled, then:
|
||||
//! KIGI_MEMORY_LOG=0 grok # disable even when enabled
|
||||
//! tail -f ~/.kigi/logs/memory.log # watch in another terminal
|
||||
//! ```
|
||||
|
||||
/// Tracing target for all memory system operations.
|
||||
pub const TARGET: &str = "xai_memory";
|
||||
|
||||
#[cfg(feature = "memory-log")]
|
||||
mod inner {
|
||||
use std::fmt;
|
||||
use std::path::PathBuf;
|
||||
use std::sync::Mutex;
|
||||
use std::time::Instant;
|
||||
|
||||
use tracing::Subscriber;
|
||||
use tracing_subscriber::fmt::format::Writer;
|
||||
use tracing_subscriber::fmt::time::FormatTime;
|
||||
use tracing_subscriber::fmt::writer::BoxMakeWriter;
|
||||
use tracing_subscriber::layer::Layer;
|
||||
use tracing_subscriber::registry::LookupSpan;
|
||||
|
||||
use super::TARGET;
|
||||
use kigi_config::kigi_home;
|
||||
|
||||
const ENV_MEMORY_LOG: &str = "KIGI_MEMORY_LOG";
|
||||
|
||||
static LOG_GUARD: std::sync::OnceLock<
|
||||
Mutex<Option<tracing_appender::non_blocking::WorkerGuard>>,
|
||||
> = std::sync::OnceLock::new();
|
||||
|
||||
#[derive(Clone)]
|
||||
struct UptimeTimer {
|
||||
epoch: Instant,
|
||||
}
|
||||
|
||||
impl UptimeTimer {
|
||||
fn new() -> Self {
|
||||
Self {
|
||||
epoch: Instant::now(),
|
||||
}
|
||||
}
|
||||
}
|
||||
|
||||
impl FormatTime for UptimeTimer {
|
||||
fn format_time(&self, w: &mut Writer<'_>) -> fmt::Result {
|
||||
let elapsed = self.epoch.elapsed();
|
||||
write!(w, "+{}.{:03}s", elapsed.as_secs(), elapsed.subsec_millis())
|
||||
}
|
||||
}
|
||||
|
||||
/// Build the memory log layer.
|
||||
///
|
||||
/// Writes to `~/.kigi/logs/memory.log`. Filters to `xai_memory=trace`.
|
||||
/// Set `KIGI_MEMORY_LOG=0` to disable, `KIGI_MEMORY_LOG=/path` to redirect.
|
||||
pub fn layer<S>() -> Option<impl Layer<S>>
|
||||
where
|
||||
S: Subscriber + for<'span> LookupSpan<'span>,
|
||||
{
|
||||
let path = resolve_log_path()?;
|
||||
|
||||
if let Some(parent) = path.parent() {
|
||||
let _ = std::fs::create_dir_all(parent);
|
||||
}
|
||||
|
||||
let file = match std::fs::OpenOptions::new()
|
||||
.create(true)
|
||||
.append(true)
|
||||
.open(&path)
|
||||
{
|
||||
Ok(f) => f,
|
||||
Err(e) => {
|
||||
tracing::warn!("[memory-log] Failed to open {:?}: {}", path, e);
|
||||
return None;
|
||||
}
|
||||
};
|
||||
|
||||
let (non_blocking, guard) = tracing_appender::non_blocking(file);
|
||||
let guard_slot = LOG_GUARD.get_or_init(|| Mutex::new(None));
|
||||
if let Ok(mut slot) = guard_slot.lock() {
|
||||
*slot = Some(guard);
|
||||
}
|
||||
|
||||
let filter = tracing_subscriber::filter::EnvFilter::new(format!("{TARGET}=trace"));
|
||||
let fmt_layer = tracing_subscriber::fmt::layer()
|
||||
.with_target(true)
|
||||
.with_ansi(false)
|
||||
.with_thread_ids(true)
|
||||
.with_timer(UptimeTimer::new())
|
||||
.with_writer(BoxMakeWriter::new(non_blocking))
|
||||
.with_filter(filter);
|
||||
|
||||
tracing::info!("[memory-log] Memory logging enabled");
|
||||
Some(fmt_layer)
|
||||
}
|
||||
|
||||
fn resolve_log_path() -> Option<PathBuf> {
|
||||
let default_path = || kigi_home().join("logs").join("memory.log");
|
||||
let raw = match std::env::var(ENV_MEMORY_LOG) {
|
||||
Ok(val) => val,
|
||||
Err(_) => return Some(default_path()),
|
||||
};
|
||||
let raw = raw.trim();
|
||||
match raw {
|
||||
"" | "0" | "false" | "off" | "no" => None,
|
||||
"1" | "true" | "on" | "yes" => Some(default_path()),
|
||||
path => Some(PathBuf::from(path)),
|
||||
}
|
||||
}
|
||||
}
|
||||
|
||||
#[cfg(feature = "memory-log")]
|
||||
pub use inner::layer;
|
||||
@@ -0,0 +1,70 @@
|
||||
//! Tracing layer for `target: "sampling_log"` → `~/.kigi/logs/sampling.jsonl`.
|
||||
//! Enable with `--log-sampling` or `KIGI_LOG_SAMPLING=1`.
|
||||
|
||||
use std::sync::Mutex;
|
||||
|
||||
use tracing::Subscriber;
|
||||
use tracing_subscriber::fmt::writer::BoxMakeWriter;
|
||||
use tracing_subscriber::layer::Layer;
|
||||
use tracing_subscriber::registry::LookupSpan;
|
||||
|
||||
use kigi_config::kigi_home;
|
||||
|
||||
use crate::instrumentation::{NoOpLayer, TargetFilterLayer};
|
||||
|
||||
const ENV_VAR: &str = "KIGI_LOG_SAMPLING";
|
||||
const LOG_FILE: &str = "sampling.jsonl";
|
||||
const TARGET: &str = "sampling_log";
|
||||
|
||||
static GUARD: std::sync::OnceLock<Mutex<Option<tracing_appender::non_blocking::WorkerGuard>>> =
|
||||
std::sync::OnceLock::new();
|
||||
|
||||
pub fn layer<S>() -> Box<dyn Layer<S> + Send + Sync>
|
||||
where
|
||||
S: Subscriber + for<'span> LookupSpan<'span> + Send + Sync + 'static,
|
||||
{
|
||||
if !std::env::var(ENV_VAR).is_ok_and(|v| matches!(v.as_str(), "1" | "true" | "on")) {
|
||||
return Box::new(NoOpLayer::new());
|
||||
}
|
||||
|
||||
let path = kigi_home().join(crate::unified_log::LOG_DIR).join(LOG_FILE);
|
||||
|
||||
if let Some(parent) = path.parent()
|
||||
&& let Err(e) = std::fs::create_dir_all(parent)
|
||||
{
|
||||
tracing::warn!("failed to create sampling log dir: {e}");
|
||||
return Box::new(NoOpLayer::new());
|
||||
}
|
||||
|
||||
if crate::unified_log::file_size(&path) >= crate::unified_log::MAX_SIZE {
|
||||
crate::unified_log::trim_file(&path);
|
||||
}
|
||||
|
||||
let file = match std::fs::OpenOptions::new()
|
||||
.create(true)
|
||||
.append(true)
|
||||
.open(&path)
|
||||
{
|
||||
Ok(f) => f,
|
||||
Err(e) => {
|
||||
tracing::warn!("failed to open sampling log: {e}");
|
||||
return Box::new(NoOpLayer::new());
|
||||
}
|
||||
};
|
||||
|
||||
let (non_blocking, guard) = tracing_appender::non_blocking(file);
|
||||
let guard_slot = GUARD.get_or_init(|| Mutex::new(None));
|
||||
if let Ok(mut slot) = guard_slot.lock() {
|
||||
*slot = Some(guard);
|
||||
}
|
||||
|
||||
let fmt_layer = tracing_subscriber::fmt::layer()
|
||||
.json()
|
||||
.with_current_span(false) // `spans` array already carries the full ancestor list
|
||||
.with_ansi(false)
|
||||
.with_timer(tracing_subscriber::fmt::time::UtcTime::rfc_3339())
|
||||
.with_target(false)
|
||||
.with_writer(BoxMakeWriter::new(non_blocking));
|
||||
|
||||
Box::new(TargetFilterLayer::new(fmt_layer, TARGET))
|
||||
}
|
||||
@@ -0,0 +1,53 @@
|
||||
//! Ambient per-session tracing span for log routing.
|
||||
//!
|
||||
//! The `--debug` firehose router ([`crate::debug_log`]) fans events out to
|
||||
//! `~/.kigi/debug/<session_id>.txt` by finding the enclosing session span's
|
||||
//! `session_id` field. [`with_session_ctx`] installs that span for the
|
||||
//! duration of a session's work.
|
||||
|
||||
/// The `session_id` field name the debug-log firehose router keys on:
|
||||
/// `debug_log::SessionIdVisitor` stashes a `SessionId` extension on any span
|
||||
/// carrying this field — the span *name* is not load-bearing for routing. Shared
|
||||
/// so the `info_span!` here and the router in `debug_log` can't silently drift; a
|
||||
/// rename trips `session_span_exposes_router_field` below.
|
||||
pub(crate) const SESSION_ID_FIELD: &str = "session_id";
|
||||
|
||||
/// Build the per-session tracing span the firehose router routes by. The field
|
||||
/// name MUST be the literal `session_id` (tracing field names can't come from a
|
||||
/// const); the test below pins it against [`SESSION_ID_FIELD`].
|
||||
fn session_span(session_id: &str) -> tracing::Span {
|
||||
tracing::info_span!("session", session_id = %session_id)
|
||||
}
|
||||
|
||||
/// Run `fut` inside the per-session tracing span so the debug-log firehose
|
||||
/// routes its events to the session's file.
|
||||
pub async fn with_session_ctx<F: std::future::Future>(session_id: &str, fut: F) -> F::Output {
|
||||
use tracing::Instrument;
|
||||
fut.instrument(session_span(session_id)).await
|
||||
}
|
||||
|
||||
#[cfg(test)]
|
||||
mod tests {
|
||||
use super::*;
|
||||
|
||||
/// The debug-log firehose router (`debug_log`) finds the session span by its
|
||||
/// `session_id` field (not by name). That field name is a literal in
|
||||
/// `session_span` (tracing field names can't be a const), so pin it against the
|
||||
/// shared const here — a rename of either breaks this test instead of silently
|
||||
/// degrading routing to the per-pid fallback.
|
||||
#[test]
|
||||
fn session_span_exposes_router_field() {
|
||||
// A bare registry enables every callsite, so the span has live metadata.
|
||||
let subscriber = tracing_subscriber::registry();
|
||||
tracing::subscriber::with_default(subscriber, || {
|
||||
let span = session_span("test-id");
|
||||
let meta = span
|
||||
.metadata()
|
||||
.expect("session span must have metadata under an enabling subscriber");
|
||||
assert!(
|
||||
meta.fields().field(SESSION_ID_FIELD).is_some(),
|
||||
"session span must expose `{SESSION_ID_FIELD}` for debug-log routing",
|
||||
);
|
||||
});
|
||||
}
|
||||
}
|
||||
@@ -0,0 +1,505 @@
|
||||
//! Centralized unified log for cross-component session observability.
|
||||
//!
|
||||
//! Shell writes directly via [`emit()`]. Pager and desktop forward entries
|
||||
//! over ACP (`x.ai/log` notifications); shell receives them in
|
||||
//! [`ingest_client_entries()`] and writes on their behalf.
|
||||
|
||||
use std::fs::{self, File, OpenOptions};
|
||||
use std::io::Write;
|
||||
use std::path::PathBuf;
|
||||
use std::sync::{LazyLock, Mutex, OnceLock};
|
||||
|
||||
use chrono::Utc;
|
||||
use serde::{Deserialize, Serialize};
|
||||
|
||||
use kigi_config::kigi_home;
|
||||
|
||||
/// Binary version stamped into every log entry. Set once at startup via
|
||||
/// [`set_version()`]; entries emitted before that get `None`.
|
||||
static VERSION: OnceLock<String> = OnceLock::new();
|
||||
|
||||
/// Register the binary version (e.g. shell's `CARGO_PKG_VERSION`).
|
||||
/// Call once at startup; subsequent calls are no-ops.
|
||||
pub fn set_version(ver: &str) {
|
||||
let _ = VERSION.set(ver.to_owned());
|
||||
}
|
||||
|
||||
pub const LOG_DIR: &str = "logs";
|
||||
const LOG_FILE: &str = "unified.jsonl";
|
||||
pub const MAX_SIZE: u64 = 5 * 1024 * 1024; // 5 MB
|
||||
|
||||
/// ACP method name for unified log notifications.
|
||||
pub const LOG_METHOD: &str = "x.ai/log";
|
||||
|
||||
// ---------------------------------------------------------------------------
|
||||
// Log entry types
|
||||
// ---------------------------------------------------------------------------
|
||||
|
||||
/// Log level for a unified log entry.
|
||||
#[derive(Debug, Clone, Copy, PartialEq, Eq, strum::Display, Serialize, Deserialize)]
|
||||
#[strum(serialize_all = "lowercase")]
|
||||
#[serde(rename_all = "lowercase")]
|
||||
pub enum LogLevel {
|
||||
Error,
|
||||
Warn,
|
||||
Info,
|
||||
Debug,
|
||||
}
|
||||
|
||||
/// Component that produced a log entry.
|
||||
#[derive(Debug, Clone, Copy, PartialEq, Eq, strum::Display, Serialize, Deserialize)]
|
||||
pub enum LogSource {
|
||||
#[strum(serialize = "shell")]
|
||||
#[serde(rename = "shell")]
|
||||
Shell,
|
||||
#[strum(serialize = "grok-pager")]
|
||||
#[serde(rename = "grok-pager")]
|
||||
GrokPager,
|
||||
#[strum(serialize = "grok-desktop")]
|
||||
#[serde(rename = "grok-desktop")]
|
||||
GrokDesktop,
|
||||
}
|
||||
|
||||
/// A single unified log entry, written as one JSONL line.
|
||||
#[derive(Debug, Clone, Serialize, Deserialize)]
|
||||
pub struct LogEntry {
|
||||
/// RFC 3339 timestamp (millisecond precision, UTC).
|
||||
pub ts: String,
|
||||
/// Component that produced the entry.
|
||||
pub src: LogSource,
|
||||
/// OS process id of the producer. Critical for cross-process trace
|
||||
/// reconstruction because shell/pager/desktop all append to the same
|
||||
/// `unified.jsonl`, so multiple shell processes' lines interleave
|
||||
/// indistinguishably without it.
|
||||
///
|
||||
/// `Option<u32>` is for wire compatibility only -- shell, pager, and
|
||||
/// desktop all stamp `Some(std::process::id())` at emit time. A
|
||||
/// `None` here means the entry came from an older client/server that
|
||||
/// predates this field; current code never emits one.
|
||||
#[serde(skip_serializing_if = "Option::is_none")]
|
||||
pub pid: Option<u32>,
|
||||
/// Binary version (e.g. `"0.1.211"`). Stamped by [`set_version()`]
|
||||
/// at startup so stale zombie processes are identifiable in logs.
|
||||
/// `None` for entries from older binaries that predate this field.
|
||||
#[serde(skip_serializing_if = "Option::is_none")]
|
||||
pub ver: Option<String>,
|
||||
/// Log level.
|
||||
pub lvl: LogLevel,
|
||||
/// Session ID, if one exists.
|
||||
#[serde(skip_serializing_if = "Option::is_none")]
|
||||
pub sid: Option<String>,
|
||||
/// Human-readable message.
|
||||
pub msg: String,
|
||||
/// Structured context fields.
|
||||
#[serde(skip_serializing_if = "Option::is_none")]
|
||||
pub ctx: Option<serde_json::Value>,
|
||||
}
|
||||
|
||||
/// Wire format for the `x.ai/log` ACP notification params.
|
||||
#[derive(Debug, Clone, Serialize, Deserialize)]
|
||||
pub struct LogNotificationParams {
|
||||
/// Source component identifier.
|
||||
pub src: LogSource,
|
||||
pub entries: Vec<ClientLogEntry>,
|
||||
}
|
||||
|
||||
/// Entry as sent by a client (no `src` field -- shell stamps it).
|
||||
#[derive(Debug, Clone, Serialize, Deserialize)]
|
||||
pub struct ClientLogEntry {
|
||||
pub ts: String,
|
||||
/// Client process id. Stamped by the client when the entry is
|
||||
/// created; preserved through ACP forwarding so the on-disk log
|
||||
/// reflects the originating process.
|
||||
///
|
||||
/// Optional only for wire compatibility with clients that predate
|
||||
/// this field; in-tree clients always populate it.
|
||||
#[serde(skip_serializing_if = "Option::is_none")]
|
||||
pub pid: Option<u32>,
|
||||
/// Binary version. Optional for wire compatibility with older clients.
|
||||
#[serde(skip_serializing_if = "Option::is_none")]
|
||||
pub ver: Option<String>,
|
||||
pub lvl: LogLevel,
|
||||
#[serde(skip_serializing_if = "Option::is_none")]
|
||||
pub sid: Option<String>,
|
||||
pub msg: String,
|
||||
#[serde(skip_serializing_if = "Option::is_none")]
|
||||
pub ctx: Option<serde_json::Value>,
|
||||
}
|
||||
|
||||
// ---------------------------------------------------------------------------
|
||||
// Writer
|
||||
// ---------------------------------------------------------------------------
|
||||
|
||||
struct LogWriter {
|
||||
file: File,
|
||||
path: PathBuf,
|
||||
written: u64,
|
||||
}
|
||||
|
||||
static WRITER: LazyLock<Mutex<Option<LogWriter>>> = LazyLock::new(|| Mutex::new(open_writer()));
|
||||
|
||||
fn log_path() -> PathBuf {
|
||||
kigi_home().join(LOG_DIR).join(LOG_FILE)
|
||||
}
|
||||
|
||||
pub fn file_size(path: &std::path::Path) -> u64 {
|
||||
fs::metadata(path).map(|m| m.len()).unwrap_or(0)
|
||||
}
|
||||
|
||||
fn open_writer() -> Option<LogWriter> {
|
||||
let path = log_path();
|
||||
if let Some(parent) = path.parent()
|
||||
&& let Err(e) = fs::create_dir_all(parent)
|
||||
{
|
||||
tracing::warn!("[unified_log] failed to create log dir: {e}");
|
||||
return None;
|
||||
}
|
||||
|
||||
if file_size(&path) >= MAX_SIZE {
|
||||
trim_file(&path);
|
||||
}
|
||||
|
||||
match OpenOptions::new().create(true).append(true).open(&path) {
|
||||
Ok(file) => Some(LogWriter {
|
||||
written: file_size(&path),
|
||||
file,
|
||||
path,
|
||||
}),
|
||||
Err(e) => {
|
||||
tracing::warn!("[unified_log] failed to open log file: {e}");
|
||||
None
|
||||
}
|
||||
}
|
||||
}
|
||||
|
||||
fn write_lines(lines: &[u8]) {
|
||||
let Ok(mut guard) = WRITER.lock() else { return };
|
||||
let writer = match guard.as_mut() {
|
||||
Some(w) => w,
|
||||
None => return,
|
||||
};
|
||||
|
||||
let len = lines.len() as u64;
|
||||
if let Err(e) = writer.file.write_all(lines) {
|
||||
tracing::warn!("[unified_log] write failed: {e}");
|
||||
return;
|
||||
}
|
||||
writer.written += len;
|
||||
|
||||
// Trim under the lock to avoid a race where concurrent writers see stale
|
||||
// state between drop + re-acquire. Trim is fast (~2.5 MB read+write) and
|
||||
// this is a low-volume diagnostic log.
|
||||
if writer.written >= MAX_SIZE {
|
||||
let _ = writer.file.flush();
|
||||
trim_file(&writer.path);
|
||||
if let Ok(new_file) = OpenOptions::new()
|
||||
.create(true)
|
||||
.append(true)
|
||||
.open(&writer.path)
|
||||
{
|
||||
writer.file = new_file;
|
||||
writer.written = file_size(&writer.path);
|
||||
}
|
||||
}
|
||||
}
|
||||
|
||||
fn write_entry(entry: &LogEntry) {
|
||||
let Ok(mut line) = serde_json::to_vec(entry) else {
|
||||
return;
|
||||
};
|
||||
line.push(b'\n');
|
||||
write_lines(&line);
|
||||
}
|
||||
|
||||
/// Drop the oldest lines from the file, keeping roughly the last half.
|
||||
///
|
||||
/// Uses write-to-temp + rename so a crash mid-trim cannot lose the entire log.
|
||||
pub fn trim_file(path: &std::path::Path) {
|
||||
let Ok(data) = fs::read(path) else { return };
|
||||
let half = data.len() / 2;
|
||||
// Find the first newline after the halfway point so we don't split a line.
|
||||
let start = match data[half..].iter().position(|&b| b == b'\n') {
|
||||
Some(pos) => half + pos + 1,
|
||||
None => return,
|
||||
};
|
||||
let tmp = path.with_extension("jsonl.tmp");
|
||||
if fs::write(&tmp, &data[start..]).is_ok() {
|
||||
let _ = fs::rename(&tmp, path);
|
||||
}
|
||||
}
|
||||
|
||||
// ---------------------------------------------------------------------------
|
||||
// Public API
|
||||
// ---------------------------------------------------------------------------
|
||||
|
||||
/// Return a new timestamp string in the unified log format.
|
||||
fn now_ts() -> String {
|
||||
Utc::now().to_rfc3339_opts(chrono::SecondsFormat::Millis, true)
|
||||
}
|
||||
|
||||
/// Emit a log entry from shell itself.
|
||||
pub fn emit(lvl: LogLevel, msg: &str, sid: Option<&str>, ctx: Option<serde_json::Value>) {
|
||||
let entry = LogEntry {
|
||||
ts: now_ts(),
|
||||
src: LogSource::Shell,
|
||||
pid: Some(std::process::id()),
|
||||
ver: VERSION.get().cloned(),
|
||||
lvl,
|
||||
sid: sid.map(Into::into),
|
||||
msg: msg.into(),
|
||||
ctx,
|
||||
};
|
||||
write_entry(&entry);
|
||||
}
|
||||
|
||||
/// Ingest a batch of log entries from a client (pager or desktop).
|
||||
///
|
||||
/// Called by the `x.ai/log` notification handler. Entries from
|
||||
/// [`LogSource::Shell`] are rejected to prevent spoofing.
|
||||
pub fn ingest_client_entries(src: LogSource, entries: &[ClientLogEntry]) {
|
||||
if matches!(src, LogSource::Shell) || entries.is_empty() {
|
||||
return;
|
||||
}
|
||||
// Serialize all entries up front, then write in a single lock acquisition.
|
||||
let mut buf = Vec::new();
|
||||
for client_entry in entries {
|
||||
let entry = LogEntry {
|
||||
ts: client_entry.ts.clone(),
|
||||
src,
|
||||
pid: client_entry.pid,
|
||||
ver: client_entry.ver.clone(),
|
||||
lvl: client_entry.lvl,
|
||||
sid: client_entry.sid.clone(),
|
||||
msg: client_entry.msg.clone(),
|
||||
ctx: client_entry.ctx.clone(),
|
||||
};
|
||||
if let Ok(mut line) = serde_json::to_vec(&entry) {
|
||||
line.push(b'\n');
|
||||
buf.extend_from_slice(&line);
|
||||
}
|
||||
}
|
||||
if !buf.is_empty() {
|
||||
write_lines(&buf);
|
||||
}
|
||||
}
|
||||
|
||||
/// Convenience: emit an info-level entry from shell.
|
||||
pub fn info(msg: &str, sid: Option<&str>, ctx: Option<serde_json::Value>) {
|
||||
emit(LogLevel::Info, msg, sid, ctx);
|
||||
}
|
||||
|
||||
/// Convenience: emit a warn-level entry from shell.
|
||||
pub fn warn(msg: &str, sid: Option<&str>, ctx: Option<serde_json::Value>) {
|
||||
emit(LogLevel::Warn, msg, sid, ctx);
|
||||
}
|
||||
|
||||
/// Convenience: emit an error-level entry from shell.
|
||||
pub fn error(msg: &str, sid: Option<&str>, ctx: Option<serde_json::Value>) {
|
||||
emit(LogLevel::Error, msg, sid, ctx);
|
||||
}
|
||||
|
||||
/// Convenience: emit a debug-level entry from shell.
|
||||
pub fn debug(msg: &str, sid: Option<&str>, ctx: Option<serde_json::Value>) {
|
||||
emit(LogLevel::Debug, msg, sid, ctx);
|
||||
}
|
||||
|
||||
/// Read the current unified log file and return its contents.
|
||||
///
|
||||
/// Returns `None` if the log file doesn't exist or can't be read.
|
||||
/// Used by diagnostic uploads to capture the log state at a point in time.
|
||||
pub fn snapshot_log() -> Option<Vec<u8>> {
|
||||
let path = log_path();
|
||||
// Flush pending writes before reading.
|
||||
if let Ok(mut guard) = WRITER.lock()
|
||||
&& let Some(ref mut w) = *guard
|
||||
{
|
||||
let _ = w.file.flush();
|
||||
}
|
||||
// Lock released intentionally — snapshot is approximate.
|
||||
match fs::read(&path) {
|
||||
Ok(data) if !data.is_empty() => Some(data),
|
||||
_ => None,
|
||||
}
|
||||
}
|
||||
|
||||
/// Read the unified log and return only entries belonging to the given session.
|
||||
///
|
||||
/// Parses each JSONL line, keeps entries where `"sid"` matches `session_id`,
|
||||
/// and returns the filtered lines as JSONL bytes. Returns `None` if the log
|
||||
/// is empty or contains no entries for this session.
|
||||
pub fn snapshot_session_log(session_id: &str) -> Option<Vec<u8>> {
|
||||
let path = log_path();
|
||||
if let Ok(mut guard) = WRITER.lock()
|
||||
&& let Some(ref mut w) = *guard
|
||||
{
|
||||
let _ = w.file.flush();
|
||||
}
|
||||
let data = match fs::read(&path) {
|
||||
Ok(d) if !d.is_empty() => d,
|
||||
_ => return None,
|
||||
};
|
||||
let mut out = Vec::new();
|
||||
for line in data.split(|&b| b == b'\n') {
|
||||
if line.is_empty() {
|
||||
continue;
|
||||
}
|
||||
if let Ok(entry) = serde_json::from_slice::<serde_json::Value>(line)
|
||||
&& entry.get("sid").and_then(|v| v.as_str()) == Some(session_id)
|
||||
{
|
||||
out.extend_from_slice(line);
|
||||
out.push(b'\n');
|
||||
}
|
||||
}
|
||||
if out.is_empty() { None } else { Some(out) }
|
||||
}
|
||||
|
||||
#[cfg(test)]
|
||||
mod tests {
|
||||
use super::*;
|
||||
|
||||
#[test]
|
||||
fn log_entry_serializes_minimal() {
|
||||
let entry = LogEntry {
|
||||
ts: "2025-07-14T10:30:00.123Z".into(),
|
||||
src: LogSource::Shell,
|
||||
pid: None,
|
||||
ver: None,
|
||||
lvl: LogLevel::Info,
|
||||
sid: None,
|
||||
msg: "test".into(),
|
||||
ctx: None,
|
||||
};
|
||||
let json = serde_json::to_string(&entry).unwrap();
|
||||
assert!(!json.contains("sid"));
|
||||
assert!(!json.contains("ctx"));
|
||||
assert!(!json.contains("pid"));
|
||||
assert!(!json.contains("ver"));
|
||||
assert!(json.contains("\"src\":\"shell\""));
|
||||
}
|
||||
|
||||
#[test]
|
||||
fn log_entry_serializes_full() {
|
||||
let entry = LogEntry {
|
||||
ts: "2025-07-14T10:30:00.123Z".into(),
|
||||
src: LogSource::GrokPager,
|
||||
pid: Some(4242),
|
||||
ver: Some("0.1.211".into()),
|
||||
lvl: LogLevel::Warn,
|
||||
sid: Some("abc123".into()),
|
||||
msg: "connection lost".into(),
|
||||
ctx: Some(serde_json::json!({"retry": 3})),
|
||||
};
|
||||
let json = serde_json::to_string(&entry).unwrap();
|
||||
assert!(json.contains("\"sid\":\"abc123\""));
|
||||
assert!(json.contains("\"retry\":3"));
|
||||
assert!(json.contains("\"pid\":4242"));
|
||||
assert!(json.contains("\"ver\":\"0.1.211\""));
|
||||
}
|
||||
|
||||
#[test]
|
||||
fn client_entry_round_trip() {
|
||||
let wire = r#"{"ts":"2025-07-14T10:30:00.123Z","lvl":"info","msg":"hello"}"#;
|
||||
let entry: ClientLogEntry = serde_json::from_str(wire).unwrap();
|
||||
assert_eq!(entry.msg, "hello");
|
||||
assert!(entry.sid.is_none());
|
||||
assert!(entry.ctx.is_none());
|
||||
}
|
||||
|
||||
#[test]
|
||||
fn trim_file_keeps_recent_half() {
|
||||
let dir = tempfile::tempdir().unwrap();
|
||||
let path = dir.path().join("test.jsonl");
|
||||
let mut content = String::new();
|
||||
for i in 0..10 {
|
||||
content.push_str(&format!("line {i}\n"));
|
||||
}
|
||||
fs::write(&path, &content).unwrap();
|
||||
trim_file(&path);
|
||||
let result = fs::read_to_string(&path).unwrap();
|
||||
// Should keep roughly the second half, starting at a line boundary.
|
||||
assert!(!result.contains("line 0"));
|
||||
assert!(result.contains("line 9"));
|
||||
assert!(result.len() < content.len());
|
||||
// Every line should be complete (no partial lines).
|
||||
for line in result.lines() {
|
||||
assert!(line.starts_with("line "));
|
||||
}
|
||||
}
|
||||
|
||||
#[test]
|
||||
fn trim_file_no_newline_in_second_half_is_noop() {
|
||||
let dir = tempfile::tempdir().unwrap();
|
||||
let path = dir.path().join("test.jsonl");
|
||||
let content = "single-line-no-newline";
|
||||
fs::write(&path, content).unwrap();
|
||||
trim_file(&path);
|
||||
assert_eq!(fs::read_to_string(&path).unwrap(), content);
|
||||
}
|
||||
|
||||
#[test]
|
||||
fn trim_file_missing_file_is_noop() {
|
||||
let dir = tempfile::tempdir().unwrap();
|
||||
let path = dir.path().join("nonexistent.jsonl");
|
||||
trim_file(&path);
|
||||
assert!(!path.exists());
|
||||
}
|
||||
|
||||
#[test]
|
||||
fn ingest_rejects_shell_src() {
|
||||
ingest_client_entries(
|
||||
LogSource::Shell,
|
||||
&[ClientLogEntry {
|
||||
ts: "2025-01-01T00:00:00.000Z".into(),
|
||||
pid: None,
|
||||
ver: None,
|
||||
lvl: LogLevel::Info,
|
||||
sid: None,
|
||||
msg: "sneaky".into(),
|
||||
ctx: None,
|
||||
}],
|
||||
);
|
||||
}
|
||||
|
||||
#[test]
|
||||
fn unknown_src_rejected_at_deserialization() {
|
||||
for bad in &[
|
||||
r#"{"src":"evil","entries":[]}"#,
|
||||
r#"{"src":"","entries":[]}"#,
|
||||
r#"{"src":"GROK-PAGER","entries":[]}"#,
|
||||
] {
|
||||
assert!(serde_json::from_str::<LogNotificationParams>(bad).is_err());
|
||||
}
|
||||
}
|
||||
|
||||
#[test]
|
||||
fn notification_params_round_trip() {
|
||||
let params = LogNotificationParams {
|
||||
src: LogSource::GrokPager,
|
||||
entries: vec![
|
||||
ClientLogEntry {
|
||||
ts: "2025-07-14T10:30:00.123Z".into(),
|
||||
pid: Some(1234),
|
||||
ver: None,
|
||||
lvl: LogLevel::Info,
|
||||
sid: Some("s1".into()),
|
||||
msg: "first".into(),
|
||||
ctx: None,
|
||||
},
|
||||
ClientLogEntry {
|
||||
ts: "2025-07-14T10:30:00.456Z".into(),
|
||||
pid: Some(1234),
|
||||
ver: Some("0.1.211".into()),
|
||||
lvl: LogLevel::Error,
|
||||
sid: None,
|
||||
msg: "second".into(),
|
||||
ctx: Some(serde_json::json!({"code": 42})),
|
||||
},
|
||||
],
|
||||
};
|
||||
let json = serde_json::to_string(¶ms).unwrap();
|
||||
let parsed: LogNotificationParams = serde_json::from_str(&json).unwrap();
|
||||
assert_eq!(parsed.entries.len(), 2);
|
||||
assert_eq!(parsed.entries[0].msg, "first");
|
||||
assert_eq!(parsed.entries[1].msg, "second");
|
||||
}
|
||||
}
|
||||
Reference in New Issue
Block a user