vcon_server/
audit.rs

1//! The audit log: one record per request, written in the same transaction
2//! as the change it describes. A record holds no vCon content, no token
3//! and no client address.
4
5use std::io::{self, Write};
6
7use rusqlite::{Connection, params};
8use serde_json::json;
9use time::OffsetDateTime;
10use time::format_description::well_known::Rfc3339;
11
12use crate::ids::{KeyId, VersionId};
13use crate::query::{self, BadQuery};
14
15/// The audit table, part of every catalog that holds a log.
16pub const SCHEMA: &str = "
17CREATE TABLE audit (
18    seq INTEGER PRIMARY KEY AUTOINCREMENT,
19    at TEXT NOT NULL,
20    actor TEXT NOT NULL,
21    action TEXT NOT NULL,
22    target TEXT,
23    version TEXT,
24    status INTEGER NOT NULL,
25    count INTEGER NOT NULL
26);
27CREATE INDEX audit_counted ON audit (actor, action, status, at);
28";
29
30/// Who made a request.
31#[derive(Debug, Clone, Copy, PartialEq, Eq)]
32pub enum Actor {
33    /// A caller's key.
34    Key(KeyId),
35    /// The purge sweep.
36    Sweep,
37    /// A command run on the host.
38    Cli,
39    /// A caller with no known key: its token did not parse, or names a key
40    /// id the key table does not hold.
41    Unparsed,
42}
43
44/// What a request asked for. A refused request records what it asked for.
45#[derive(Debug, Clone, Copy, PartialEq, Eq)]
46pub enum Action {
47    Create,
48    Replace,
49    Read,
50    Delete,
51    Purge,
52    LegalRead,
53    LegalVersions,
54    Restore,
55    Hold,
56    Release,
57    KeyCreate,
58    KeyRevoke,
59    KeyList,
60    KeyInfo,
61    Retention,
62    Health,
63    AuthFailed,
64    TenantCreate,
65    TenantList,
66    TenantRetention,
67    TenantRemove,
68    RekeyMaster,
69    RekeyTenant,
70    List,
71    AuditRead,
72    Openapi,
73    Backup,
74    /// A request to the MCP server, counted (`count`), not recorded.
75    Mcp,
76}
77
78impl Action {
79    /// The name written in the log.
80    pub fn as_str(self) -> &'static str {
81        match self {
82            Action::Create => "create",
83            Action::Replace => "replace",
84            Action::Read => "read",
85            Action::Delete => "delete",
86            Action::Purge => "purge",
87            Action::LegalRead => "legal_read",
88            Action::LegalVersions => "legal_versions",
89            Action::Restore => "restore",
90            Action::Hold => "hold",
91            Action::Release => "release",
92            Action::KeyCreate => "key_create",
93            Action::KeyRevoke => "key_revoke",
94            Action::KeyList => "key_list",
95            Action::KeyInfo => "key_info",
96            Action::Retention => "retention",
97            Action::Health => "health",
98            Action::AuthFailed => "auth_failed",
99            Action::TenantCreate => "tenant_create",
100            Action::TenantList => "tenant_list",
101            Action::TenantRetention => "tenant_retention",
102            Action::TenantRemove => "tenant_remove",
103            Action::RekeyMaster => "rekey_master",
104            Action::RekeyTenant => "rekey_tenant",
105            Action::List => "list",
106            Action::AuditRead => "audit_read",
107            Action::Openapi => "openapi",
108            Action::Backup => "backup",
109            Action::Mcp => "mcp",
110        }
111    }
112}
113
114/// One request, as recorded.
115#[derive(Debug, Clone, PartialEq, Eq)]
116pub struct Entry {
117    pub actor: Actor,
118    pub action: Action,
119    /// The vCon's uuid, or the tenant or key id for an admin action.
120    pub target: Option<String>,
121    /// The version written, read or purged, if there is one.
122    pub version: Option<VersionId>,
123    /// The HTTP status answered, or the command's result.
124    pub status: u16,
125}
126
127/// Why a record could not be written or exported.
128#[derive(Debug)]
129pub enum AuditError {
130    Sqlite(rusqlite::Error),
131    Write(io::Error),
132}
133
134impl From<rusqlite::Error> for AuditError {
135    fn from(e: rusqlite::Error) -> AuditError {
136        AuditError::Sqlite(e)
137    }
138}
139
140impl Actor {
141    /// The name written in the log: the key id, `sweep`, `cli`, or empty.
142    fn name(self) -> String {
143        match self {
144            Actor::Key(id) => id.to_string(),
145            Actor::Sweep => "sweep".to_owned(),
146            Actor::Cli => "cli".to_owned(),
147            Actor::Unparsed => String::new(),
148        }
149    }
150}
151
152/// `now` in RFC 3339, in UTC.
153fn rfc3339(now: OffsetDateTime) -> String {
154    now.to_offset(time::UtcOffset::UTC)
155        .format(&Rfc3339)
156        .expect("every UTC time from the clock formats")
157}
158
159/// Appends one record, at `now`, in `tx`.
160pub fn record(tx: &Connection, entry: &Entry, now: OffsetDateTime) -> Result<(), AuditError> {
161    tx.execute(
162        "INSERT INTO audit (at, actor, action, target, version, status, count)
163         VALUES (?1, ?2, ?3, ?4, ?5, ?6, 1)",
164        params![
165            rfc3339(now),
166            entry.actor.name(),
167            entry.action.as_str(),
168            entry.target,
169            entry.version.map(|v| v.to_string()),
170            entry.status,
171        ],
172    )?;
173    Ok(())
174}
175
176/// Adds one to the record for this actor, action and status in the minute
177/// of `now`, making it if needed. For requests that could otherwise grow a
178/// log one row each: failed authentications and health checks.
179pub fn count(tx: &Connection, entry: &Entry, now: OffsetDateTime) -> Result<(), AuditError> {
180    let minute = now
181        .to_offset(time::UtcOffset::UTC)
182        .replace_second(0)
183        .and_then(|t| t.replace_nanosecond(0))
184        .expect("0 is a valid second and nanosecond");
185    let fields = params![
186        rfc3339(minute),
187        entry.actor.name(),
188        entry.action.as_str(),
189        entry.target,
190        entry.version.map(|v| v.to_string()),
191        entry.status,
192    ];
193    let added = tx.execute(
194        "UPDATE audit SET count = count + 1
195         WHERE at = ?1 AND actor = ?2 AND action = ?3 AND target IS ?4 AND version IS ?5
196           AND status = ?6",
197        fields,
198    )?;
199    if added == 0 {
200        tx.execute(
201            "INSERT INTO audit (at, actor, action, target, version, status, count)
202             VALUES (?1, ?2, ?3, ?4, ?5, ?6, 1)",
203            fields,
204        )?;
205    }
206    Ok(())
207}
208
209/// Writes every record after `since` as JSON lines, oldest first.
210pub fn export(log: &Connection, since: Option<i64>, out: &mut dyn Write) -> Result<(), AuditError> {
211    // SQLite reads a negative limit as none.
212    lines(log, since.unwrap_or(0), -1, out)
213}
214
215/// Writes at most `limit` records after `after` as JSON lines, oldest
216/// first: the one rendering both `export` and `page` write.
217fn lines(log: &Connection, after: i64, limit: i64, out: &mut dyn Write) -> Result<(), AuditError> {
218    let mut rows = log.prepare(
219        "SELECT seq, at, actor, action, target, version, status, count
220         FROM audit WHERE seq > ?1 ORDER BY seq LIMIT ?2",
221    )?;
222    let mut rows = rows.query(params![after, limit])?;
223    while let Some(row) = rows.next()? {
224        let record = json!({
225            "seq": row.get::<_, i64>(0)?,
226            "at": row.get::<_, String>(1)?,
227            "actor": row.get::<_, String>(2)?,
228            "action": row.get::<_, String>(3)?,
229            "target": row.get::<_, Option<String>>(4)?,
230            "version": row.get::<_, Option<String>>(5)?,
231            "status": row.get::<_, u16>(6)?,
232            "count": row.get::<_, i64>(7)?,
233        });
234        writeln!(out, "{record}").map_err(AuditError::Write)?;
235    }
236    Ok(())
237}
238
239/// What an audit read asks for: at most `limit` records after the seq
240/// `after`, oldest first.
241#[derive(Debug, Clone, Copy, PartialEq, Eq)]
242pub struct AuditQuery {
243    pub after: i64,
244    pub limit: u32,
245}
246
247impl AuditQuery {
248    pub const DEFAULT_LIMIT: u32 = 1000;
249    pub const MAX_LIMIT: u32 = 10000;
250
251    /// An audit query from its parameters' values, the one rule for them
252    /// wherever they come from: `after` a seq (0, the default, is the
253    /// start of the log), `limit` 1 to `MAX_LIMIT`.
254    pub fn new(after: Option<u64>, limit: Option<u64>) -> Result<AuditQuery, BadQuery> {
255        let after = after
256            .map(|n| i64::try_from(n).map_err(|_| BadQuery))
257            .transpose()?
258            .unwrap_or(0);
259        let limit = match limit {
260            None => AuditQuery::DEFAULT_LIMIT,
261            Some(n) => u32::try_from(n)
262                .ok()
263                .filter(|n| (1..=AuditQuery::MAX_LIMIT).contains(n))
264                .ok_or(BadQuery)?,
265        };
266        Ok(AuditQuery { after, limit })
267    }
268
269    /// An audit query from an HTTP query string, which may name `after` and
270    /// `limit`, each at most once.
271    pub fn from_query(text: Option<&str>) -> Result<AuditQuery, BadQuery> {
272        let read = query::pairs(text, &["after", "limit"])?;
273        let number = |name| {
274            read.get(name)
275                .map(|n: &String| n.parse::<u64>().map_err(|_| BadQuery))
276                .transpose()
277        };
278        AuditQuery::new(number("after")?, number("limit")?)
279    }
280}
281
282/// Writes at most `query.limit` records after `query.after` as JSON lines,
283/// oldest first: the first lines `export` writes from the same place.
284pub fn page(log: &Connection, query: &AuditQuery, out: &mut dyn Write) -> Result<(), AuditError> {
285    lines(log, query.after, i64::from(query.limit), out)
286}
287
288/// Reading a log back, for tests.
289#[cfg(test)]
290pub(crate) mod testing {
291    use rusqlite::Connection;
292    use serde_json::Value;
293
294    /// The records `export` writes after `since`, parsed.
295    pub(crate) fn exported(log: &Connection, since: Option<i64>) -> Vec<Value> {
296        let mut out = Vec::new();
297        super::export(log, since, &mut out).expect("export");
298        String::from_utf8(out)
299            .expect("UTF-8")
300            .lines()
301            .map(|line| serde_json::from_str(line).expect("one JSON object per line"))
302            .collect()
303    }
304}
305
306#[cfg(test)]
307mod tests {
308    use serde_json::{Value, json};
309    use time::macros::datetime;
310
311    use super::testing::exported;
312    use super::*;
313    use crate::catalog;
314    use crate::envelope::Key;
315
316    struct Log {
317        _dir: tempfile::TempDir,
318        conn: Connection,
319    }
320
321    fn log() -> Log {
322        let dir = tempfile::tempdir().expect("temp dir");
323        let key = Key::generate().expect("key");
324        let conn = catalog::open(&dir.path().join("catalog.sqlite"), &key, SCHEMA).expect("opens");
325        Log { _dir: dir, conn }
326    }
327
328    fn read_by(key: KeyId, status: u16) -> Entry {
329        Entry {
330            actor: Actor::Key(key),
331            action: Action::Read,
332            target: Some("01a07da8-c2bb-83e5-b9a2-279e0d16bc46".into()),
333            version: Some(VersionId([0x22; 16])),
334            status,
335        }
336    }
337
338    #[test]
339    fn records_are_written_and_exported_back() {
340        let mut log = log();
341        let key = Key::generate().expect("key").id();
342        let tx = log.conn.transaction().expect("tx");
343        record(
344            &tx,
345            &read_by(key, 200),
346            datetime!(2026-10-23 12:34:56.789 UTC),
347        )
348        .expect("record");
349        let purge = Entry {
350            actor: Actor::Sweep,
351            action: Action::Purge,
352            target: Some("01a07da8-c2bb-83e5-b9a2-279e0d16bc46".into()),
353            version: None,
354            status: 200,
355        };
356        record(&tx, &purge, datetime!(2026-10-23 12:35:00 UTC)).expect("record");
357        tx.commit().expect("commit");
358        assert_eq!(
359            exported(&log.conn, None),
360            [
361                json!({"seq": 1, "at": "2026-10-23T12:34:56.789Z", "actor": key.to_string(),
362                       "action": "read", "target": "01a07da8-c2bb-83e5-b9a2-279e0d16bc46",
363                       "version": "22".repeat(16), "status": 200, "count": 1}),
364                json!({"seq": 2, "at": "2026-10-23T12:35:00Z", "actor": "sweep",
365                       "action": "purge", "target": "01a07da8-c2bb-83e5-b9a2-279e0d16bc46",
366                       "version": null, "status": 200, "count": 1}),
367            ]
368        );
369        assert_eq!(
370            exported(&log.conn, Some(1)).len(),
371            1,
372            "only records after seq 1"
373        );
374        assert_eq!(exported(&log.conn, Some(2)).len(), 0);
375    }
376
377    #[test]
378    fn times_are_written_in_utc() {
379        let mut log = log();
380        let key = Key::generate().expect("key").id();
381        let tx = log.conn.transaction().expect("tx");
382        record(
383            &tx,
384            &read_by(key, 200),
385            datetime!(2026-10-23 14:34:56 +02:00),
386        )
387        .expect("record");
388        tx.commit().expect("commit");
389        assert_eq!(exported(&log.conn, None)[0]["at"], "2026-10-23T12:34:56Z");
390    }
391
392    #[test]
393    fn counted_records_hold_one_row_per_actor_action_status_and_minute() {
394        let mut log = log();
395        let health = |status| Entry {
396            actor: Actor::Unparsed,
397            action: Action::Health,
398            target: None,
399            version: None,
400            status,
401        };
402        let tx = log.conn.transaction().expect("tx");
403        for second in [0, 30, 59] {
404            let now = datetime!(2026-10-23 12:34:00 UTC) + time::Duration::seconds(second);
405            count(&tx, &health(200), now).expect("count");
406        }
407        count(&tx, &health(200), datetime!(2026-10-23 12:35:00 UTC)).expect("next minute");
408        count(&tx, &health(503), datetime!(2026-10-23 12:34:10 UTC)).expect("other status");
409        // Same actor, status and minute as the 503 health record above,
410        // so only the action keeps the two apart.
411        let failed = Entry {
412            action: Action::AuthFailed,
413            ..health(503)
414        };
415        count(&tx, &failed, datetime!(2026-10-23 12:34:20 UTC)).expect("other action");
416        let cli = Entry {
417            actor: Actor::Cli,
418            ..health(200)
419        };
420        count(&tx, &cli, datetime!(2026-10-23 12:34:40 UTC)).expect("other actor");
421        tx.commit().expect("commit");
422        let rows: Vec<(String, String, String, u64, u64)> = exported(&log.conn, None)
423            .iter()
424            .map(|r| {
425                (
426                    r["at"].as_str().expect("at").to_owned(),
427                    r["actor"].as_str().expect("actor").to_owned(),
428                    r["action"].as_str().expect("action").to_owned(),
429                    r["status"].as_u64().expect("status"),
430                    r["count"].as_u64().expect("count"),
431                )
432            })
433            .collect();
434        let row = |at: &str, actor: &str, action: &str, status, count| {
435            (
436                at.to_owned(),
437                actor.to_owned(),
438                action.to_owned(),
439                status,
440                count,
441            )
442        };
443        assert_eq!(
444            rows,
445            [
446                row("2026-10-23T12:34:00Z", "", "health", 200, 3),
447                row("2026-10-23T12:35:00Z", "", "health", 200, 1),
448                row("2026-10-23T12:34:00Z", "", "health", 503, 1),
449                row("2026-10-23T12:34:00Z", "", "auth_failed", 503, 1),
450                row("2026-10-23T12:34:00Z", "cli", "health", 200, 1),
451            ]
452        );
453    }
454
455    #[test]
456    fn a_record_in_a_transaction_that_does_not_commit_is_not_kept() {
457        let mut log = log();
458        let tx = log.conn.transaction().expect("tx");
459        let key = Key::generate().expect("key").id();
460        record(&tx, &read_by(key, 200), datetime!(2026-10-23 12:00:00 UTC)).expect("record");
461        drop(tx);
462        assert_eq!(exported(&log.conn, None), Vec::<Value>::new());
463    }
464
465    #[test]
466    fn every_action_has_its_name_in_the_log() {
467        // The name each action has in the logs, which exports and the audit
468        // routes give to operators. The match has no catch-all arm, so a
469        // new action fails to compile here until its name is written down.
470        let named = |action: Action| match action {
471            Action::Create => "create",
472            Action::Replace => "replace",
473            Action::Read => "read",
474            Action::Delete => "delete",
475            Action::Purge => "purge",
476            Action::LegalRead => "legal_read",
477            Action::LegalVersions => "legal_versions",
478            Action::Restore => "restore",
479            Action::Hold => "hold",
480            Action::Release => "release",
481            Action::KeyCreate => "key_create",
482            Action::KeyRevoke => "key_revoke",
483            Action::KeyList => "key_list",
484            Action::KeyInfo => "key_info",
485            Action::Retention => "retention",
486            Action::Health => "health",
487            Action::AuthFailed => "auth_failed",
488            Action::TenantCreate => "tenant_create",
489            Action::TenantList => "tenant_list",
490            Action::TenantRetention => "tenant_retention",
491            Action::TenantRemove => "tenant_remove",
492            Action::RekeyMaster => "rekey_master",
493            Action::RekeyTenant => "rekey_tenant",
494            Action::List => "list",
495            Action::AuditRead => "audit_read",
496            Action::Openapi => "openapi",
497            Action::Backup => "backup",
498            Action::Mcp => "mcp",
499        };
500        let every = [
501            Action::Create,
502            Action::Replace,
503            Action::Read,
504            Action::Delete,
505            Action::Purge,
506            Action::LegalRead,
507            Action::LegalVersions,
508            Action::Restore,
509            Action::Hold,
510            Action::Release,
511            Action::KeyCreate,
512            Action::KeyRevoke,
513            Action::KeyList,
514            Action::KeyInfo,
515            Action::Retention,
516            Action::Health,
517            Action::AuthFailed,
518            Action::TenantCreate,
519            Action::TenantList,
520            Action::TenantRetention,
521            Action::TenantRemove,
522            Action::RekeyMaster,
523            Action::RekeyTenant,
524            Action::List,
525            Action::AuditRead,
526            Action::Openapi,
527            Action::Backup,
528            Action::Mcp,
529        ];
530        let mut seen = std::collections::BTreeSet::new();
531        for action in every {
532            assert_eq!(action.as_str(), named(action), "{action:?}");
533            assert!(
534                seen.insert(action.as_str()),
535                "{action:?}: a name of its own"
536            );
537        }
538    }
539
540    /// Five read records, at whole seconds.
541    fn five(log: &mut Log) {
542        let key = Key::generate().expect("key").id();
543        let tx = log.conn.transaction().expect("tx");
544        for second in 0..5 {
545            let now = datetime!(2026-10-23 12:00:00 UTC) + time::Duration::seconds(second);
546            record(&tx, &read_by(key, 200), now).expect("record");
547        }
548        tx.commit().expect("commit");
549    }
550
551    fn exported_text(log: &Connection, since: Option<i64>) -> String {
552        let mut out = Vec::new();
553        export(log, since, &mut out).expect("export");
554        String::from_utf8(out).expect("UTF-8")
555    }
556
557    fn paged(log: &Connection, after: i64, limit: u32) -> String {
558        let mut out = Vec::new();
559        page(log, &AuditQuery { after, limit }, &mut out).expect("page");
560        String::from_utf8(out).expect("UTF-8")
561    }
562
563    #[test]
564    fn a_page_is_the_first_lines_export_writes_from_the_same_place() {
565        let mut log = log();
566        five(&mut log);
567        for after in 0..=6 {
568            let lines: Vec<String> = exported_text(&log.conn, Some(after))
569                .lines()
570                .map(|l| format!("{l}\n"))
571                .collect();
572            for limit in 1..=6 {
573                let take = lines.len().min(usize::try_from(limit).expect("small"));
574                assert_eq!(
575                    paged(&log.conn, after, limit),
576                    lines[..take].concat(),
577                    "after {after}, limit {limit}"
578                );
579            }
580        }
581        assert_eq!(paged(&log.conn, 0, 10), exported_text(&log.conn, None));
582    }
583
584    #[test]
585    fn an_audit_query_takes_a_seq_and_a_limit_of_1_to_10000() {
586        let q = |after, limit| AuditQuery { after, limit };
587        assert_eq!(AuditQuery::new(None, None), Ok(q(0, 1000)));
588        assert_eq!(AuditQuery::new(Some(7), Some(1)), Ok(q(7, 1)));
589        assert_eq!(AuditQuery::new(None, Some(10000)), Ok(q(0, 10000)));
590        assert_eq!(
591            AuditQuery::new(Some(i64::MAX as u64), None),
592            Ok(q(i64::MAX, 1000))
593        );
594        for (after, limit) in [
595            (None, Some(0)),
596            (None, Some(10001)),
597            (None, Some(u64::MAX)),
598            (Some(i64::MAX as u64 + 1), None),
599        ] {
600            assert_eq!(
601                AuditQuery::new(after, limit),
602                Err(BadQuery),
603                "{after:?} {limit:?}"
604            );
605        }
606        assert_eq!(AuditQuery::from_query(None), Ok(q(0, 1000)));
607        assert_eq!(
608            AuditQuery::from_query(Some("after=12&limit=3")),
609            Ok(q(12, 3))
610        );
611        for bad in [
612            "after=-1",
613            "after=x",
614            "after=",
615            "limit=0",
616            "limit=1&limit=1",
617            "since=3",
618            "after=1.0",
619        ] {
620            assert_eq!(AuditQuery::from_query(Some(bad)), Err(BadQuery), "{bad}");
621        }
622    }
623}
vcon_server/audit.rs

vcon_server/
audit.rs
