Skip to main content

gunnar_core/
observe.rs

1//! **What an operator can see**: the `tracing` targets, the request id, and
2//! the server's counters.
3//!
4//! # The measurement this module answers
5//!
6//! 58 `tracing::` call sites in 27182 lines of code, no `span!`, no
7//! `#[instrument]`, no request id, no timing and no counters. Closing the gRPC
8//! audit hole moved the worst of that distribution and none of the total.
9//! At forge scale an operator has minutes to answer *which connection, which
10//! principal, which repository, how long did it take, how many failed, is the
11//! queue growing*. None of it was answerable from gunnar's output at all.
12//!
13//! # One vocabulary, not one per crate
14//!
15//! [`TARGET_AUDIT`] already existed, in `gunnar_grpc::auth`. Everything added
16//! since is a **sibling of it**, defined here once, so `RUST_LOG` selects a
17//! *subsystem* rather than a crate name that happens to hold the call site:
18//!
19//! | target | what is on it |
20//! |---|---|
21//! | [`TARGET_AUDIT`] | control-plane mutations: who called what, and the decision |
22//! | [`TARGET_SSH`] | the connection: accept, publickey, exec dispatch, every refusal |
23//! | [`TARGET_GIT`] | transfers: upload-pack, receive-pack, objects, packs, bytes |
24//! | [`TARGET_POLICY`] | the push gate: which gate refused which reference |
25//! | [`TARGET_STORE`] | ref transactions, compare-and-swap contention, repack |
26//! | [`TARGET_METRICS`] | the counters: the heartbeat, and the scrape endpoint |
27//! | [`TARGET_LFS`] | large-file transfers: the session, its verbs, its refusals |
28//! | [`TARGET_ARCHIVE`] | archiving a repository off the box and back in |
29//! | [`TARGET_REPLICATION`] | replication to a standby: shipped, lagging, refused |
30//! | [`TARGET_SPACE`] | disk headroom: what a write may take, and the refusals when it is short |
31//! | [`TARGET_REPAIR`] | the repair plane: the boot check, the pull channel, the recharges they run |
32//! | [`TARGET_LIVE`] | the live update: a version staged, the re-exec, the trial and its roll back |
33//! | [`TARGET_ACTIVITY`] | a principal's last sign-in and last operation: a stamp that could not be kept |
34//! | [`TARGET_HEIMDALL`] | the Heimdall pack gate: on, or asked for and not started (ALERT) |
35//!
36//! ```text
37//!   RUST_LOG=warn,gunnar::audit=info,gunnar::git=info   # the two an operator watches
38//!   RUST_LOG=gunnar::ssh=debug                          # one connection, in detail
39//! ```
40//!
41//! `gunnar-grpc` cannot link this crate (it is expressed in `gunnar-proto`
42//! terms and deliberately has no `gunnar-core` edge), so it keeps its own
43//! `AUDIT_TARGET` **string**. That is the one place a constant is stated twice,
44//! and it is not left to a comment: `gunnar-cli` links both crates and
45//! `the_audit_target_is_the_same_string_in_both_crates` asserts they are equal.
46//!
47//! # Levels
48//!
49//! `info` is the production default and must stay legible: one line per
50//! connection authenticated, one per transfer served with its applied outputs,
51//! one per reference moved, and every refusal at `warn`. `debug` is the
52//! diagnostic tier: per-frame detail, environment requests, CAS retries. A
53//! server that has to run at `trace` to be legible has failed.
54//!
55//! # Cost
56//!
57//! [`RequestId`] is a `u64` that formats itself; it never allocates and never
58//! touches a lock. [`ServerMetrics`] is a flat block of [`AtomicU64`] read and
59//! written with [`Ordering::Relaxed`]. **No mutex is taken to record a
60//! counter**, because a signal that costs a lock is paid for by the thing it is
61//! measuring. `tracing`'s macros evaluate their field expressions only inside
62//! the `enabled!` branch, so a line that will not be emitted allocates nothing
63//! even where the field is a `String`.
64
65use std::sync::atomic::{AtomicU64, Ordering};
66use std::sync::OnceLock;
67
68// ───────────────────────────────────────────────────────────────────────────
69// Targets
70// ───────────────────────────────────────────────────────────────────────────
71
72/// Control-plane mutations: who called what, over which credential, and what
73/// was decided. Written by `gunnar-grpc`, which states the same literal
74/// because it cannot link this crate. See the module docs.
75pub const TARGET_AUDIT: &str = "gunnar::audit";
76
77/// The SSH connection: accepted, authenticated, dispatched, refused.
78pub const TARGET_SSH: &str = "gunnar::ssh";
79
80/// Git transfers: `upload-pack`, `receive-pack`, and their applied outputs.
81pub const TARGET_GIT: &str = "gunnar::git";
82
83/// The push gate: which gate refused which reference, and why.
84pub const TARGET_POLICY: &str = "gunnar::policy";
85
86/// Storage: ref transactions, compare-and-swap contention, repack.
87pub const TARGET_STORE: &str = "gunnar::store";
88
89/// The counter heartbeat, and the scrape endpoint.
90pub const TARGET_METRICS: &str = "gunnar::metrics";
91
92/// Large-file transfers: the LFS session, its verbs, and every refusal.
93///
94/// Added 2026-08-05, and it did not replace nothing. `gunnar-lfs` was emitting
95/// on **`"gunnar.lfs"`** — a dot, not a `::` — at five call sites, and
96/// the old znippy engine crate, `gunnar-cli`'s znippy-engine arm and `gunnar-znippy` were
97/// emitting on `"gunnar.store"` at twelve more. `RUST_LOG=gunnar::lfs=debug`
98/// selected none of them; neither did `gunnar::store=info`, which this
99/// module's own table tells an operator to use. Seventeen lines that could be
100/// written and never read.
101///
102/// That is exactly the failure [`TARGETS`] was written to prevent, and
103/// [`TARGETS`] could not see it: it checked the constants in its own list and
104/// no call site ever passes through it. The guard that can is
105/// `every_tracing_target_in_the_shipped_source_is_one_of_ours` in `gunnar-cli`'s
106/// `tests/observability.rs`, which reads the source of every shipped crate.
107pub const TARGET_LFS: &str = "gunnar::lfs";
108
109/// Archiving a repository out of the box and back in (`Repos.ArchiveOut`).
110///
111/// `repo.archive_out` when a repository is written to its archive,
112/// `repo.archive_out_failed` when that write does not land.
113///
114/// Emitted by `gunnar-grpc`'s `service::repos` and undeclared until the two
115/// halves of this repository were merged (2026-08-31) — so
116/// `gunnar_core::observe::log_filter`, the filter a deployment installs,
117/// selected neither of its two call sites. The same defect [`TARGET_LFS`]
118/// documents, found by the guard that exists for it.
119///
120/// Undeclared is not harmless here: an archive-out that FAILS is the one event
121/// an operator has to see, so the failure of the very thing that protects the
122/// objects was the least visible line gunnar emitted.
123pub const TARGET_ARCHIVE: &str = "gunnar::archive";
124
125/// Replication to a standby: what was shipped, what lagged, what
126/// refused.
127///
128/// `replication.never_synced`, `replication.stale`, `replication.recovered`.
129///
130/// Emitted by `gunnar-server`'s `replication_view` and undeclared until
131/// 2026-08-31, alongside [`TARGET_ARCHIVE`] and for the same reason. It is the
132/// worst of the three to have had dark: a standby that receives nothing looks
133/// exactly like a standby with nothing to receive, and the lines that tell them
134/// apart were written into a filter that did not select them — so a mirror
135/// could quietly stop being a mirror.
136pub const TARGET_REPLICATION: &str = "gunnar::replication";
137/// The process's own limits: the descriptor budget PID 1 raised, and the WARN
138/// row when it could not raise it far enough.
139///
140/// Added 2026-08-30 for a defect of exactly the shape [`TARGET_LFS`]
141/// documents: `crate::limits` shipped emitting on `"gunnar::limits"`
142/// at two call sites, and no documented filter selected either of them. One of
143/// the two is the `!WARN limits.nofile.low` row the dashboard guide tells an
144/// operator to watch for.
145pub const TARGET_LIMITS: &str = "gunnar::limits";
146
147/// The object index: a reader's own scan of a pending pack, and the memory
148/// watchdog's pause and spill.
149///
150/// Emitted by the znippy git plugin, which cannot link this crate and states
151/// the literal, and rendered by the dashboard as `index paused: …` /
152/// `index.spilled`. Undeclared until 2026-08-30, so
153/// `gunnar_core::observe::log_filter` — the filter a deployment installs —
154/// selected none of it, which is exactly the memory-pressure story an operator
155/// needs when a box collapses under sustained create load.
156pub const TARGET_INDEX: &str = "gunnar::index";
157
158/// Plan enforcement (the `metered` build): a fact accepted or refused at
159/// `Entitlement.Set`, a push refused for a suspended namespace, a cap applied.
160/// Emitted by `gunnar-server::entitlement`; absent from a community binary,
161/// declared here regardless so the filter and the probes name it.
162pub const TARGET_ENTITLEMENT: &str = "gunnar::entitlement";
163/// The twin following a primary's transaction log (`gunnar-server::twin`).
164pub const TARGET_TWIN: &str = "gunnar::twin";
165/// Disk space: the headroom a write is admitted against, the space a push may
166/// take, and the refusals when the volume is short (`gunnar-ssh::space`,
167/// `gunnar-ssh::headroom`). Emitted since 5.x but undeclared until 2026-10-10
168/// (stinky row 22), so the installed filter selected none of it.
169pub const TARGET_SPACE: &str = "gunnar::space";
170
171/// The repair plane: the boot check's findings, the pull channel's word, and
172/// the recharges they run (`gunnar-server::serve`, 5.4 resilience).
173pub const TARGET_REPAIR: &str = "gunnar::repair";
174
175/// The live update: a version staged, the graceful stop and re-exec, the trial
176/// and a roll back.
177///
178/// Emitted by `gunnar-server::live_update` since the live update landed
179/// (2026-10-12) and undeclared until 2026-10-14 — so the filter a deployment
180/// installs selected none of its call sites. The defect [`TARGET_LFS`]
181/// documents, found by the guard that exists for it.
182pub const TARGET_LIVE: &str = "gunnar::live";
183
184/// A principal's activity stamps: last sign-in and last operation, kept in the
185/// control redb and on the twin (`gunnar-core::activity`). A stamp that could
186/// not be read or written is a warning here.
187///
188/// Emitted since the admin's Principals list (89818d10, merged in cd07bc2f,
189/// 2026-10-21) and undeclared until 2026-10-25 (ODEN-CI round 2), so the filter
190/// a deployment installs selected none of it.
191pub const TARGET_ACTIVITY: &str = "gunnar::activity";
192
193/// The Heimdall pack gate (`gunnar-server`'s `heimdall` feature): whether the gate is on,
194/// and the ALERT when it was asked for and could not start (every fetched or pushed pack
195/// is then refused).
196///
197/// Emitted since the gate (1a886b4a, 2026-11-03) on a literal `gunnar::heimdall` that no
198/// documented filter selected; declared here by lane gun-rel the same day.
199pub const TARGET_HEIMDALL: &str = "gunnar::heimdall";
200
201/// Every target gunnar emits on, so a filter, a document or a test can
202/// enumerate them rather than guess.
203///
204/// A test asserts this list is exactly the constants above and that each is a
205/// `gunnar::` sibling. A target invented at one call site and spelled slightly
206/// differently is invisible to every filter written for the others, which is
207/// the failure this constant exists to prevent.
208pub const TARGETS: &[&str] = &[
209    TARGET_AUDIT,
210    TARGET_SSH,
211    TARGET_GIT,
212    TARGET_POLICY,
213    TARGET_STORE,
214    TARGET_METRICS,
215    TARGET_LFS,
216    TARGET_ARCHIVE,
217    TARGET_REPLICATION,
218    TARGET_LIMITS,
219    TARGET_INDEX,
220    TARGET_ENTITLEMENT,
221    TARGET_TWIN,
222    TARGET_SPACE,
223    TARGET_REPAIR,
224    TARGET_LIVE,
225    TARGET_ACTIVITY,
226    TARGET_HEIMDALL,
227];
228
229/// A `RUST_LOG` directive list: `base` for everything gunnar did not write, and
230/// `gunnar` for every one of [`TARGETS`].
231///
232/// **Built FROM [`TARGETS`], never written out beside it.** The table in this
233/// module's docs is prose and a reader can copy it wrong; a filter that a
234/// deployment installs must not be able to fall behind the list (one implementation). The
235/// 2026-08-05 `"gunnar.lfs"` finding is what a hand-written filter costs:
236/// seventeen call sites no documented filter selected, and nothing failed.
237///
238/// The two levels are separate arguments because they answer different
239/// questions. `base` is how much `russh`, `h2` and `gix` an operator wants to
240/// wade through; `gunnar` is how much of gunnar's own story they want. A single
241/// level cannot say "everything gunnar does, and nothing else at that volume".
242pub fn log_filter(base: &str, gunnar: &str) -> String {
243    let mut spec = String::with_capacity(base.len() + TARGETS.len() * 24);
244    spec.push_str(base);
245    for target in TARGETS {
246        spec.push(',');
247        spec.push_str(target);
248        spec.push('=');
249        spec.push_str(gunnar);
250    }
251    spec
252}
253
254/// Everything outside gunnar, in the filter a service is installed with.
255///
256/// `info` and not `warn`: the lines that say a listener bound, a host key was
257/// loaded and a runtime started come from gunnar at `info` too, and an operator
258/// reading a journal from the top wants the boot to be legible.
259pub const SERVICE_LOG_BASE: &str = "info";
260
261/// gunnar's own targets, in the filter a service is installed with.
262///
263/// `debug` rather than `info`, deliberately. A service is watched when
264/// something is being commissioned or has gone wrong, and the rungs above
265/// `info` in gunnar are per-frame protocol detail on gunnar's OWN targets only
266/// — `base` stays at `info`, so this does not drag `russh`, `h2` and `gix`
267/// debug into the journal with it. Turn it down with `--log-filter`, or move it
268/// live with `SIGUSR1` (`gunnar_cli::logging`).
269pub const SERVICE_LOG_GUNNAR: &str = "debug";
270
271/// **The `RUST_LOG` a `gunnar service install` bakes into the unit.**
272///
273/// One function, so the unit, the documentation and the test that proves the
274/// filter selects gunnar's lines all read the same string.
275pub fn service_log_filter() -> String {
276    log_filter(SERVICE_LOG_BASE, SERVICE_LOG_GUNNAR)
277}
278
279// ───────────────────────────────────────────────────────────────────────────
280// The request id
281// ───────────────────────────────────────────────────────────────────────────
282
283/// A per-connection (or per-request) identifier, carried as a span field so
284/// every line emitted underneath is attributable without repeating it.
285///
286/// # Why not a UUID
287///
288/// A UUID costs a dependency, 16 bytes and a formatting allocation to say
289/// something a 64-bit integer already says. This is a **process seed** in the
290/// high 32 bits and a monotonic counter in the low 32, rendered as 16 hex
291/// digits. Two ids from the same process never collide; two ids from different
292/// runs of the same server collide only if both start within the same
293/// microsecond *and* reach the same counter value, which is not a property a
294/// log correlation needs.
295///
296/// It is `Copy`, it is one `fetch_add(Relaxed)` to mint, and its `Display`
297/// writes into the formatter without allocating.
298#[derive(Debug, Clone, Copy, PartialEq, Eq, PartialOrd, Ord, Hash)]
299pub struct RequestId(u64);
300
301static NEXT_REQUEST_ID: AtomicU64 = AtomicU64::new(1);
302
303/// The high half: distinct per process, so two servers' logs merged into one
304/// stream do not appear to share connections.
305fn process_seed() -> u64 {
306    static SEED: OnceLock<u64> = OnceLock::new();
307    *SEED.get_or_init(|| {
308        let nanos = std::time::SystemTime::now()
309            .duration_since(std::time::UNIX_EPOCH)
310            .map(|d| d.as_nanos() as u64)
311            .unwrap_or(0);
312        // Mix the pid in so two processes started in the same nanosecond bucket
313        // still differ. `id()` is a `u32` and free.
314        (nanos ^ ((std::process::id() as u64) << 40)) & 0xffff_ffff
315    })
316}
317
318impl RequestId {
319    /// Mint the next id. One relaxed atomic increment; never blocks.
320    pub fn next() -> RequestId {
321        let n = NEXT_REQUEST_ID.fetch_add(1, Ordering::Relaxed);
322        RequestId((process_seed() << 32) | (n & 0xffff_ffff))
323    }
324
325    /// The raw value, for a caller that wants to store it as a number.
326    pub fn get(&self) -> u64 {
327        self.0
328    }
329}
330
331impl std::fmt::Display for RequestId {
332    fn fmt(&self, f: &mut std::fmt::Formatter<'_>) -> std::fmt::Result {
333        write!(f, "{:016x}", self.0)
334    }
335}
336
337// ───────────────────────────────────────────────────────────────────────────
338// The counters
339// ───────────────────────────────────────────────────────────────────────────
340
341/// Everything an operator watches, as one flat block of atomics.
342///
343/// Held behind an `Arc` and shared by the SSH listener and the git transport,
344/// which is what makes "connections refused" and "pushes rejected" numbers
345/// about the **same server** rather than two crates' private tallies.
346///
347/// Every method is one `fetch_add(Relaxed)`. There is no lock anywhere in this
348/// type, and [`ServerMetrics::snapshot`] reads the fields independently rather
349/// than under a barrier: these are a signal, and a signal read atomically
350/// across eighteen fields would cost more than it tells anyone.
351#[derive(Debug, Default)]
352pub struct ServerMetrics {
353    connections_opened: AtomicU64,
354    connections_accepted: AtomicU64,
355    connections_anonymous: AtomicU64,
356    connections_refused: AtomicU64,
357    auth_faults: AtomicU64,
358    exec_refused: AtomicU64,
359    transfers_started: AtomicU64,
360    transfers_in_flight: AtomicU64,
361    transfers_failed: AtomicU64,
362    transfers_idle_closed: AtomicU64,
363    packs_served: AtomicU64,
364    objects_sent: AtomicU64,
365    bytes_out: AtomicU64,
366    bytes_in: AtomicU64,
367    pushes_accepted: AtomicU64,
368    pushes_rejected: AtomicU64,
369    refs_updated: AtomicU64,
370    refs_deleted: AtomicU64,
371    refs_rejected: AtomicU64,
372    gate_refusals: AtomicU64,
373    usage_reconcile_missed: AtomicU64,
374}
375
376/// A reading of [`ServerMetrics`], taken at one moment.
377#[derive(Debug, Clone, Copy, PartialEq, Eq, Default)]
378pub struct MetricsSnapshot {
379    /// TCP connections russh handed to gunnar.
380    pub connections_opened: u64,
381    /// Connections whose offered key named a principal.
382    pub connections_accepted: u64,
383    /// Connections admitted with **no key at all**, served as the
384    /// anonymous principal, which can only ever read a public repository.
385    ///
386    /// Counted separately from [`MetricsSnapshot::connections_accepted`] rather
387    /// than folded into it: "how much of my traffic is strangers" is the first
388    /// question an operator asks after making anything public, and a total that
389    /// mixed the two could not answer it.
390    pub connections_anonymous: u64,
391    /// Connections whose offered key named nobody. **Not** the same as
392    /// [`MetricsSnapshot::auth_faults`].
393    pub connections_refused: u64,
394    /// Connections refused because the identity table could not be *read*. A
395    /// storage fault looks exactly like an empty table from the client's side,
396    /// and an operator must be able to tell them apart.
397    pub auth_faults: u64,
398    /// Exec requests refused or denied after authentication: a non-git
399    /// command, an unknown repository, a missing grant.
400    pub exec_refused: u64,
401    /// Transfers admitted and begun.
402    pub transfers_started: u64,
403    /// Transfers running right now. A **gauge**, not a total.
404    pub transfers_in_flight: u64,
405    /// Transfers that ended with a protocol or storage error.
406    pub transfers_failed: u64,
407    /// Transfers closed because no bytes moved while they waited on the client
408    /// (GUN-SSH-SLOT-HANG, `--transfer-idle-secs`): each gave its slot back.
409    pub transfers_idle_closed: u64,
410    /// `upload-pack` sessions that sent a packfile.
411    pub packs_served: u64,
412    /// Objects written into those packs.
413    pub objects_sent: u64,
414    /// Bytes gunnar wrote to git clients, counted at the wire.
415    pub bytes_out: u64,
416    /// Bytes gunnar read from git clients, counted at the wire.
417    pub bytes_in: u64,
418    /// Pushes in which every reference landed.
419    pub pushes_accepted: u64,
420    /// Pushes in which at least one reference was refused.
421    pub pushes_rejected: u64,
422    /// References moved.
423    pub refs_updated: u64,
424    /// References deleted.
425    pub refs_deleted: u64,
426    /// Reference updates refused, for any reason.
427    pub refs_rejected: u64,
428    /// Reference updates refused **by a named policy gate**. A subset of
429    /// [`MetricsSnapshot::refs_rejected`], which also counts connectivity
430    /// failures and the collateral refusals of an `--atomic` push.
431    pub gate_refusals: u64,
432    /// Ticks of the usage ledger's reconcile pass that could not run (the
433    /// catalog could not be read, so nothing was re-measured). Counted, warned
434    /// and published rather than dropped (A28 M17): a pass that silently skips
435    /// is a ledger that silently goes stale.
436    pub usage_reconcile_missed: u64,
437}
438
439// **Every field above is written by real code.** A counter nothing increments
440// reads as "this never happens" and is worse than no counter at all. `repacks`
441// was in this struct for exactly one revision before it came out again, because
442// `gunnar gc` runs in a separate process that has no `ServerMetrics` to write
443// to. `a_real_clone_and_push_move_the_counters` in `gunnar-cli` pins the ones a
444// transfer touches; the rest have a red-first proof in their own crate.
445
446/// What a number **means to a reader**: a total that only climbs, or a level
447/// that moves both ways.
448///
449/// One field in this type is a gauge — [`MetricsSnapshot::transfers_in_flight`]
450/// — and it is the whole reason the distinction is carried rather than assumed.
451/// A scraper told everything is a counter charts a busy server's concurrency as
452/// a *rate of transfers per second*, which is a different number with a
453/// plausible shape, and the operator reading it has no way to know.
454#[derive(Debug, Clone, Copy, PartialEq, Eq)]
455pub enum MetricKind {
456    /// Monotonic since start-up. A reader takes its rate.
457    Counter,
458    /// A level, read as it stands.
459    Gauge,
460}
461
462impl MetricKind {
463    /// The word the exposition format's `# TYPE` line uses.
464    pub fn as_str(self) -> &'static str {
465        match self {
466            MetricKind::Counter => "counter",
467            MetricKind::Gauge => "gauge",
468        }
469    }
470}
471
472/// The kind word in the [`counters!`] table, as a value.
473///
474/// Two arms and no fallback, deliberately: a counter declared `guage` — or
475/// declared with no kind at all — **fails to compile**. The alternative is a
476/// default, and a default here would silently publish the next gauge as a
477/// counter, which is the one error in this file that produces a plausible
478/// wrong number instead of an obvious one.
479macro_rules! metric_kind {
480    (counter) => {
481        MetricKind::Counter
482    };
483    (gauge) => {
484        MetricKind::Gauge
485    };
486}
487
488macro_rules! counters {
489    ($($kind:ident $field:ident => $add:ident),* $(,)?) => {
490        impl ServerMetrics {
491            $(
492                #[doc = concat!("Add `n` to `", stringify!($field), "`.")]
493                pub fn $add(&self, n: u64) {
494                    self.$field.fetch_add(n, Ordering::Relaxed);
495                }
496            )*
497
498            /// Read every counter.
499            pub fn snapshot(&self) -> MetricsSnapshot {
500                MetricsSnapshot {
501                    $($field: self.$field.load(Ordering::Relaxed),)*
502                }
503            }
504        }
505
506        impl MetricsSnapshot {
507            /// Every counter as `(name, kind, value)`, in declaration order.
508            ///
509            /// Generated by the same macro arm that declares the fields, so a
510            /// counter added to [`ServerMetrics`] appears here — and therefore
511            /// on the scrape endpoint — **without anyone remembering to add
512            /// it**. The alternative was a second hand-written list of nineteen
513            /// names, and the counter left out of it would be the one nobody
514            /// could see.
515            ///
516            /// That is not a hypothetical. The heartbeat *was* such a list, and
517            /// it carried eighteen of the nineteen: `connections_anonymous` —
518            /// written by both transports, and the answer to *how much of my
519            /// traffic is strangers* — never appeared in a single line gunnar
520            /// ever printed. See [`MetricsSnapshot::emit_heartbeat`].
521            pub fn fields(&self) -> Vec<(&'static str, MetricKind, u64)> {
522                vec![$((stringify!($field), metric_kind!($kind), self.$field),)*]
523            }
524
525            /// The heartbeat line: one `info` on [`TARGET_METRICS`] naming every
526            /// counter.
527            ///
528            /// Here, and generated, for the reason above: this used to be a
529            /// hand-written `tracing::info!` in `gunnar-cli` listing eighteen of
530            /// the nineteen fields. Expanding from the declaration is the only
531            /// version of it that cannot fall behind (one implementation), and it puts the
532            /// log line and [`MetricsSnapshot::fields`] — the log and the wire —
533            /// on one source of truth rather than two that agree today.
534            ///
535            /// Structured fields and not a rendered string, unchanged from what
536            /// it replaced: `bytes_out=` has to stay greppable in the server's
537            /// stderr, and a JSON subscriber has to still see nineteen typed
538            /// numbers rather than one blob.
539            pub fn emit_heartbeat(&self) {
540                tracing::info!(
541                    target: TARGET_METRICS,
542                    event = "metrics",
543                    $($field = self.$field,)*
544                    "gunnar"
545                );
546            }
547        }
548    };
549}
550
551counters! {
552    counter connections_opened => add_connections_opened,
553    counter connections_accepted => add_connections_accepted,
554    counter connections_anonymous => add_connections_anonymous,
555    counter connections_refused => add_connections_refused,
556    counter auth_faults => add_auth_faults,
557    counter exec_refused => add_exec_refused,
558    counter transfers_started => add_transfers_started,
559    gauge   transfers_in_flight => add_transfers_in_flight,
560    counter transfers_failed => add_transfers_failed,
561    counter transfers_idle_closed => add_transfers_idle_closed,
562    counter packs_served => add_packs_served,
563    counter objects_sent => add_objects_sent,
564    counter bytes_out => add_bytes_out,
565    counter bytes_in => add_bytes_in,
566    counter pushes_accepted => add_pushes_accepted,
567    counter pushes_rejected => add_pushes_rejected,
568    counter refs_updated => add_refs_updated,
569    counter refs_deleted => add_refs_deleted,
570    counter refs_rejected => add_refs_rejected,
571    counter gate_refusals => add_gate_refusals,
572    counter usage_reconcile_missed => add_usage_reconcile_missed,
573}
574
575impl ServerMetrics {
576    /// A fresh set of counters, all zero.
577    pub fn new() -> ServerMetrics {
578        ServerMetrics::default()
579    }
580
581    /// A transfer began. Returns a guard whose [`Drop`] decrements
582    /// `transfers_in_flight`, so the gauge cannot be leaked by an error path
583    /// that forgot to close it, the failure mode that turns a working gauge
584    /// into a server that appears permanently busy.
585    pub fn transfer_started(self: &std::sync::Arc<Self>) -> InFlightGuard {
586        self.transfers_started.fetch_add(1, Ordering::Relaxed);
587        self.transfers_in_flight.fetch_add(1, Ordering::Relaxed);
588        InFlightGuard {
589            metrics: std::sync::Arc::clone(self),
590        }
591    }
592}
593
594/// A held `transfers_in_flight` slot. Released by [`Drop`], never by a call.
595#[derive(Debug)]
596pub struct InFlightGuard {
597    metrics: std::sync::Arc<ServerMetrics>,
598}
599
600impl Drop for InFlightGuard {
601    fn drop(&mut self) {
602        self.metrics
603            .transfers_in_flight
604            .fetch_sub(1, Ordering::Relaxed);
605    }
606}
607
608impl MetricsSnapshot {
609    /// Has anything at all been served? Used by the heartbeat to stay quiet on
610    /// an idle server without going quiet on a busy one.
611    pub fn is_zero(&self) -> bool {
612        *self == MetricsSnapshot::default()
613    }
614}
615
616// ───────────────────────────────────────────────────────────────────────────
617// The scrape body
618// ───────────────────────────────────────────────────────────────────────────
619
620/// What every exposed name starts with, so one `gunnar_` selector reaches all
621/// of them and nothing gunnar publishes can collide with a neighbour's series.
622pub const SCRAPE_PREFIX: &str = "gunnar_";
623
624/// The `Content-Type` a Prometheus-compatible scraper expects. Stated once
625/// here, beside the renderer that decides the format, rather than in the
626/// listener that merely writes the header.
627pub const SCRAPE_CONTENT_TYPE: &str = "text/plain; version=0.0.4; charset=utf-8";
628
629impl MetricsSnapshot {
630    /// This reading in the Prometheus text exposition format.
631    ///
632    /// ```text
633    /// # TYPE gunnar_bytes_out counter
634    /// gunnar_bytes_out 4096
635    /// # TYPE gunnar_transfers_in_flight gauge
636    /// gunnar_transfers_in_flight 1
637    /// ```
638    ///
639    /// # Why the names are not suffixed `_total`
640    ///
641    /// Prometheus convention would call the first one `gunnar_bytes_out_total`.
642    /// It is a convention and not a requirement — `# TYPE` is what actually
643    /// carries the semantics, and this renderer emits it for every series — and
644    /// paying it would mean **one counter with two names**: `bytes_out=` in the
645    /// log and `gunnar_bytes_out_total` on the wire. The module's opening
646    /// section argues for one vocabulary across the whole server, and an
647    /// operator who greps the heartbeat and then greps the endpoint for the
648    /// same string is exactly who that section is for. The prefix is worth its
649    /// cost because it prevents collision; the suffix buys a lint.
650    ///
651    /// # Why there is no `# HELP`
652    ///
653    /// Every one of these fields is documented on [`MetricsSnapshot`], and a
654    /// `HELP` line would be a second copy of that prose, in a macro table,
655    /// diverging from the first (one implementation). `# TYPE` is the part a scraper reads.
656    ///
657    /// # Why this is here and not in the listener
658    ///
659    /// It is pure — a `&self` to a `String`, no clock, no I/O, no socket — so
660    /// the format can be asserted without binding a port, and the listener that
661    /// serves it stays a listener. It also means `gunnar-core` gained no
662    /// dependency for the endpoint: the HTTP is somebody else's problem.
663    pub fn render_prometheus(&self) -> String {
664        let mut out = String::with_capacity(self.fields().len() * 64);
665        for (name, kind, value) in self.fields() {
666            out.push_str("# TYPE ");
667            out.push_str(SCRAPE_PREFIX);
668            out.push_str(name);
669            out.push(' ');
670            out.push_str(kind.as_str());
671            out.push('\n');
672            out.push_str(SCRAPE_PREFIX);
673            out.push_str(name);
674            out.push(' ');
675            {
676                use std::fmt::Write as _;
677                // Writing into the buffer rather than `format!`-ing nineteen
678                // little `String`s and dropping each one. `write!` to a
679                // `String` is infallible; the `Result` is discarded for that
680                // reason and not because a failure would be tolerable.
681                let _ = write!(out, "{value}");
682            }
683            out.push('\n');
684        }
685        out
686    }
687}
688
689#[cfg(test)]
690mod tests {
691    use super::*;
692    use std::sync::Arc;
693
694    #[test]
695    fn every_target_is_a_gunnar_sibling_and_the_list_is_complete() {
696        // The scheme, asserted rather than described: one prefix, one `::`
697        // separator, no crate names. A target invented at a call site and
698        // spelled `gunnar_ssh` would be invisible to every filter written for
699        // the others.
700        for target in TARGETS {
701            assert!(
702                target.starts_with("gunnar::"),
703                "{target} is not a sibling of {TARGET_AUDIT}"
704            );
705            assert_eq!(
706                target.matches("::").count(),
707                1,
708                "{target} is not one level deep"
709            );
710        }
711        let mut sorted = TARGETS.to_vec();
712        sorted.sort_unstable();
713        sorted.dedup();
714        assert_eq!(sorted.len(), TARGETS.len(), "TARGETS holds a duplicate");
715        assert!(TARGETS.contains(&TARGET_AUDIT));
716    }
717
718    /// The filter must name **every** target, and it must be derived rather
719    /// than restated — that is the whole reason it is a function.
720    ///
721    /// The identity-value guard is the second half: a filter of `"trace"` would
722    /// select every line in this process and satisfy any test that only asked
723    /// "does gunnar's output appear". So this asserts the filter is a LIST that
724    /// names each target with the gunnar level, and that the base level is
725    /// still in it and is NOT that level. `tests/observability.rs` in
726    /// `gunnar-cli` then asserts the string actually decides events that way.
727    #[test]
728    fn the_service_filter_is_derived_from_the_target_list() {
729        let filter = service_log_filter();
730        for target in TARGETS {
731            let directive = format!("{target}={SERVICE_LOG_GUNNAR}");
732            assert!(
733                filter.contains(&directive),
734                "{directive} is missing from {filter}: a target added to TARGETS did not \
735                 reach the filter a service is installed with"
736            );
737        }
738        assert!(
739            filter.starts_with(SERVICE_LOG_BASE),
740            "the filter must open with the base level: {filter}"
741        );
742        assert_ne!(
743            SERVICE_LOG_BASE, SERVICE_LOG_GUNNAR,
744            "with one level for both, this filter says nothing a bare level does not, and \
745             the test above cannot tell a derived filter from a blanket one"
746        );
747        assert_eq!(
748            filter.matches(',').count(),
749            TARGETS.len(),
750            "the filter holds a directive that is not one of ours: {filter}"
751        );
752    }
753
754    #[test]
755    fn request_ids_do_not_repeat() {
756        let a = RequestId::next();
757        let b = RequestId::next();
758        assert_ne!(a, b, "two ids from the same process collided");
759        assert_ne!(
760            a.to_string(),
761            b.to_string(),
762            "two ids RENDERED the same, which is what a log correlation sees"
763        );
764        assert_eq!(a.to_string().len(), 16, "the id must be fixed-width");
765        assert!(
766            a.to_string().chars().all(|c| c.is_ascii_hexdigit()),
767            "the id must be greppable"
768        );
769        // …and the seed half is stable within a process, so a human can spot
770        // two connections belonging to the same server at a glance.
771        assert_eq!(a.get() >> 32, b.get() >> 32);
772    }
773
774    #[test]
775    fn a_counter_moves_and_the_gauge_comes_back_down() {
776        let metrics = Arc::new(ServerMetrics::new());
777        let before = metrics.snapshot();
778        assert!(before.is_zero(), "a fresh set of counters must read zero");
779
780        metrics.add_bytes_out(4096);
781        metrics.add_objects_sent(7);
782        let guard = metrics.transfer_started();
783        let during = metrics.snapshot();
784        assert_eq!(during.bytes_out - before.bytes_out, 4096);
785        assert_eq!(during.objects_sent - before.objects_sent, 7);
786        assert_eq!(during.transfers_started, 1);
787        assert_eq!(during.transfers_in_flight, 1, "the gauge must be up");
788
789        drop(guard);
790        let after = metrics.snapshot();
791        assert_eq!(
792            after.transfers_in_flight, 0,
793            "the in-flight gauge leaked; a server that never comes back to zero \
794             reads as permanently saturated"
795        );
796        assert_eq!(
797            after.transfers_started, 1,
798            "the total is a total, not a gauge"
799        );
800    }
801
802    /// The guard that would have caught `connections_anonymous`.
803    ///
804    /// It names its own subject: **every field of [`MetricsSnapshot`] must be
805    /// reachable through [`MetricsSnapshot::fields`]**, counted against the
806    /// struct itself and not against a list this test also keeps. A second list
807    /// here would be the same defect one layer up — the one the endpoint would
808    /// then be missing a counter from, silently.
809    ///
810    /// It is counted from `Debug`, which the compiler derives from the struct
811    /// definition, so adding a field to `MetricsSnapshot` and forgetting the
812    /// `counters!` table makes this fail without anyone touching this file.
813    #[test]
814    fn every_field_of_the_snapshot_is_published() {
815        let snapshot = MetricsSnapshot::default();
816        let published: Vec<&str> = snapshot.fields().iter().map(|(name, _, _)| *name).collect();
817
818        // `MetricsSnapshot { connections_opened: 0, connections_accepted: 0, … }`
819        let debug = format!("{snapshot:?}");
820        let declared: Vec<String> = debug
821            .trim_start_matches("MetricsSnapshot {")
822            .trim_end_matches('}')
823            .split(',')
824            .filter_map(|pair| pair.split_once(':'))
825            .map(|(name, _)| name.trim().to_owned())
826            .collect();
827        assert_eq!(
828            declared.len(),
829            21,
830            "the Debug parse found {} fields, not the 21 this struct has, so this guard is \
831             reading nothing and would pass against an empty `fields()`: {debug}",
832            declared.len()
833        );
834
835        for field in &declared {
836            assert!(
837                published.contains(&field.as_str()),
838                "`{field}` is a counter of this server that NOTHING publishes: not the \
839                 heartbeat, not the scrape endpoint. That is exactly how \
840                 `connections_anonymous` stayed invisible."
841            );
842        }
843        assert_eq!(
844            published.len(),
845            declared.len(),
846            "fields() publishes {} names for {} struct fields",
847            published.len(),
848            declared.len()
849        );
850    }
851
852    /// The scrape body, asserted as **text a scraper parses**, not as a call
853    /// that returned.
854    #[test]
855    fn the_scrape_body_names_every_counter_with_its_kind_and_value() {
856        let metrics = Arc::new(ServerMetrics::new());
857        metrics.add_bytes_out(4096);
858        metrics.add_connections_anonymous(3);
859        let _guard = metrics.transfer_started();
860        let body = metrics.snapshot().render_prometheus();
861
862        // The value, not merely the name: a renderer that printed every series
863        // as 0 would satisfy a name-only assertion, and 0 is what a broken
864        // counter also looks like.
865        assert!(
866            body.contains("\ngunnar_bytes_out 4096\n"),
867            "the applied value is not in the body:\n{body}"
868        );
869        assert!(
870            body.contains("\ngunnar_connections_anonymous 3\n"),
871            "the counter no line ever carried is still not carried:\n{body}"
872        );
873        // Kind, and the one that matters: a scraper told the gauge is a counter
874        // charts concurrency as a rate.
875        assert!(
876            body.contains("# TYPE gunnar_transfers_in_flight gauge\n"),
877            "the in-flight gauge is not typed as a gauge:\n{body}"
878        );
879        assert!(
880            body.contains("# TYPE gunnar_bytes_out counter\n"),
881            "a total is not typed as a counter:\n{body}"
882        );
883        // Every series is prefixed and every series is typed, checked over the
884        // whole body rather than over the four names above.
885        let mut samples = 0;
886        for line in body.lines() {
887            if let Some(spec) = line.strip_prefix("# TYPE ") {
888                let (name, kind) = spec.split_once(' ').expect("a TYPE line is `name kind`");
889                assert!(name.starts_with(SCRAPE_PREFIX), "{name} is unprefixed");
890                assert!(kind == "counter" || kind == "gauge", "{kind} is not a kind");
891                continue;
892            }
893            assert!(line.starts_with(SCRAPE_PREFIX), "stray line: {line:?}");
894            let (name, value) = line.split_once(' ').expect("a sample is `name value`");
895            value
896                .parse::<u64>()
897                .unwrap_or_else(|_| panic!("{name} rendered {value:?}, which is not a number"));
898            assert!(
899                body.contains(&format!("# TYPE {name} ")),
900                "{name} is a sample with no TYPE line"
901            );
902            samples += 1;
903        }
904        assert_eq!(
905            samples,
906            metrics.snapshot().fields().len(),
907            "the body carries {samples} samples for {} counters",
908            metrics.snapshot().fields().len()
909        );
910    }
911
912    #[test]
913    fn counters_survive_concurrent_writers() {
914        // Relaxed ordering is still atomic. If any of this were a `+= 1` on a
915        // plain integer the total would come out short.
916        let metrics = Arc::new(ServerMetrics::new());
917        let mut threads = Vec::new();
918        for _ in 0..8 {
919            let metrics = Arc::clone(&metrics);
920            threads.push(std::thread::spawn(move || {
921                for _ in 0..1000 {
922                    metrics.add_bytes_out(1);
923                    let _guard = metrics.transfer_started();
924                }
925            }));
926        }
927        for t in threads {
928            t.join().expect("a counting thread");
929        }
930        let snapshot = metrics.snapshot();
931        assert_eq!(snapshot.bytes_out, 8000);
932        assert_eq!(snapshot.transfers_started, 8000);
933        assert_eq!(snapshot.transfers_in_flight, 0);
934    }
935}