Files
buzz/crates/buzz-audit/src/service.rs
T
Shani SinghandGitHub 264a56a226 fix(audit): hash created_at at the precision Postgres stores (#2638)
Fixes #2637 — full analysis and reproduction there.

## Problem

Audit entries are stamped and hashed with `Utc::now()` (nanoseconds),
then stored in a `TIMESTAMPTZ` column (microseconds). `compute_hash`
covers `created_at.to_rfc3339()`, and chrono emits 0/3/6/**9**
fractional digits depending on the value — so the digest written at
`service.rs:103` is computed over `…T12:00:00.123456789+00:00` while
`verify_chain` recomputes over the `…T12:00:00.123456+00:00` that
Postgres hands back.

Every hash chain backed by a real database therefore fails verification
at its first entry, on untampered data. That is not just a broken
feature — it means a genuinely forged row is indistinguishable from the
permanent baseline failure, so `HashMismatch` carries no signal.

It is invisible in CI because all six chain tests are `#[ignore =
"requires Postgres"]`, and the in-process `hash.rs` tests use a fixture
timestamp of `2026-01-01T00:00:00Z` — zero sub-seconds, the one value
where the bug cannot appear.

## Solution

Reduce `created_at` to the stored precision *before* hashing, so the
in-memory entry and the row are byte-identical:

```rust
pub fn to_storage_precision(created_at: DateTime<Utc>) -> DateTime<Utc> {
    created_at.trunc_subsecs(6)
}
```

`log_inner` is the only place that assigns `created_at` — every caller
goes through `NewAuditEntry`, which carries no timestamp — so this is a
single choke point. It is wrapped in a `log_timestamp()` helper purely
so the invariant is assertable without a database.

I chose truncation at the write path over the alternative (hashing a
precision-independent encoding such as
`timestamp_micros().to_be_bytes()`). Both fix the mismatch, but
truncating keeps the existing hash preimage format and gives the
stronger invariant: the `AuditEntry` returned from `log()` is now
exactly what a later read returns.

Truncation matches what actually happens on the wire — sqlx encodes
`DateTime<Utc>` as microseconds since the Postgres epoch, truncating —
so the value hashed is the value stored.

## Validation

Toolchain note: built on Windows with the `x86_64-pc-windows-gnu`
toolchain (no MSVC linker locally).

**Before**, against Postgres 17 with `migrations/*` applied:

```
$ cargo test -p buzz-audit --lib -- --ignored --test-threads=1

test service::tests::chain_links_within_one_community ... FAILED
test service::tests::chains_are_independent_per_community ... FAILED
test service::tests::community_chain_starts_at_seq_1_with_null_prev ... ok
test service::tests::cross_community_row_does_not_verify ... ok
test service::tests::verify_detects_tampering_within_a_community ... FAILED
test service::tests::verify_empty_range_is_false ... ok

test result: FAILED. 3 passed; 3 failed
```

with `HashMismatch { seq: 2 }` / `HashMismatch { seq: 1 }` on untampered
chains.

**After**, same database:

```
test result: ok. 6 passed; 0 failed
```

`verify_detects_tampering_within_a_community` is the one to look at: it
asserts `HashMismatch` lands on the *tampered* entry's `seq`. It was
failing because verification already blew up on an earlier untampered
row — so the assertion proving tamper detection works had never actually
been exercised. It passes now.

Also:
- `cargo test -p buzz-audit --lib` (no Postgres) — 12 passed, 0 failed.
- `cargo clippy -p buzz-audit --all-targets -- -D warnings` — clean.
- `cargo fmt -p buzz-audit -- --check` — clean.

## New tests

Three in `hash.rs`, none needing Postgres:

- `storage_precision_drops_sub_microsecond_digits` — the helper's
contract, and that it is idempotent so a re-read value is unchanged.
- `nanosecond_timestamps_cannot_survive_a_database_round_trip` — asserts
the digests **differ**. This is the trap itself, written down so the
next person changing the hash preimage sees why the precision reduction
is load-bearing.
- `storage_precision_timestamps_survive_a_database_round_trip` — the
invariant the write path must hold.

Plus `log_timestamp_carries_no_sub_microsecond_digits` in `service.rs`,
deliberately **not** `#[ignore]`d, so a regression on the write path is
caught by `just test-unit` instead of only by Postgres-gated tests that
normally never run.

## Compatibility

Rows written before this stay unverifiable — they always were — so there
is no migration. An operator relying on an existing chain has to
re-anchor.

## Relationship to #2620

#2620 proposes a shared `verify_entries` walk (anchoring, seq
contiguity, tail-truncation detection) plus a `buzz-admin audit verify`
command. Its Postgres-free unit tests build entries in memory and would
pass regardless, but its `#[ignore]` Postgres tests and the operator
command itself would fail on every real chain until this lands. Worth
taking this first so that work has a verifiable baseline — the two
changes don't overlap in code.

---------

Signed-off-by: Shani Singh <teamdeveloperworld@gmail.com>
2026-07-24 19:28:39 -04:00

528 lines
18 KiB
Rust

use chrono::{DateTime, Utc};
use futures_util::FutureExt as _;
use sqlx::{Acquire, PgPool, Row};
use tracing::{debug, instrument, warn};
use uuid::Uuid;
use buzz_core::CommunityId;
use crate::{
action::AuditAction,
entry::{AuditEntry, NewAuditEntry},
error::AuditError,
hash::{compute_hash, to_storage_precision},
};
/// The `created_at` stamped on a new entry.
///
/// Reduced to the precision Postgres round-trips before it is hashed — see
/// [`to_storage_precision`]. Split out from [`AuditService::log_inner`] so the
/// invariant is testable without a database.
fn log_timestamp() -> DateTime<Utc> {
to_storage_precision(Utc::now())
}
/// Per-community advisory lock key. Derived in Postgres from the community UUID
/// so two communities never serialize each other's audit writes (which would be
/// both a throughput bottleneck and a cross-tenant timing oracle). The lock is
/// taken with `pg_advisory_lock(hashtextextended(...))` — see [`AuditService::log`].
const AUDIT_LOCK_NAMESPACE: &str = "buzz_audit:";
/// Append-only, per-community hash-chain audit log backed by Postgres.
///
/// Each community has an independent chain keyed `(community_id, seq)`. Writes
/// for one community are serialized by a per-community advisory lock so the chain
/// stays consistent across relay processes; different communities proceed in
/// parallel.
pub struct AuditService {
pool: PgPool,
}
impl AuditService {
/// Creates a new `AuditService` using the given connection pool.
pub fn new(pool: PgPool) -> Self {
Self { pool }
}
/// Append a new entry to the calling community's chain.
///
/// Serialized per-community via `pg_advisory_lock`. Postgres advisory locks
/// are session-scoped, so we acquire before the transaction and release
/// after commit (or on any error path).
#[instrument(skip(self, entry), fields(action = %entry.action))]
pub async fn log(&self, entry: NewAuditEntry) -> Result<AuditEntry, AuditError> {
let mut conn = self.pool.acquire().await?;
// Per-community advisory lock: hash the namespaced community id to an
// i64 lock key inside Postgres. Communities lock independently.
let lock_key = format!("{AUDIT_LOCK_NAMESPACE}{}", entry.community_id);
sqlx::query("SELECT pg_advisory_lock(hashtextextended($1, 0))")
.bind(&lock_key)
.execute(&mut *conn)
.await?;
// Run the chain append and release the lock regardless of outcome.
// catch_unwind so a panic still releases the lock before the connection
// returns to the pool.
let result = std::panic::AssertUnwindSafe(self.log_inner(&mut conn, entry))
.catch_unwind()
.await;
let _ = sqlx::query("SELECT pg_advisory_unlock(hashtextextended($1, 0))")
.bind(&lock_key)
.execute(&mut *conn)
.await;
match result {
Ok(inner_result) => inner_result,
Err(panic_payload) => std::panic::resume_unwind(panic_payload),
}
}
async fn log_inner(
&self,
conn: &mut sqlx::pool::PoolConnection<sqlx::Postgres>,
entry: NewAuditEntry,
) -> Result<AuditEntry, AuditError> {
let mut tx = conn.begin().await?;
// The stored row keys on the raw UUID; the typed `CommunityId` on the
// input is the provenance fence, dereferenced here at the DB boundary.
let community_id = *entry.community_id.as_uuid();
// Head of THIS community's chain — scoped by community_id.
let head = sqlx::query(
"SELECT seq, hash FROM audit_log
WHERE community_id = $1
ORDER BY seq DESC LIMIT 1",
)
.bind(community_id)
.fetch_optional(&mut *tx)
.await?;
let (prev_seq, prev_hash): (i64, Option<Vec<u8>>) = match head {
Some(row) => (
row.get::<i64, _>("seq"),
Some(row.get::<Vec<u8>, _>("hash")),
),
None => (0, None), // community's first entry
};
let seq = prev_seq + 1;
let created_at: DateTime<Utc> = log_timestamp();
let mut audit_entry = AuditEntry {
community_id,
seq,
hash: Vec::new(),
prev_hash,
action: entry.action,
actor_pubkey: entry.actor_pubkey,
object_id: entry.object_id,
detail: entry.detail,
created_at,
};
audit_entry.hash = compute_hash(&audit_entry)?.to_vec();
debug!(seq, "writing audit entry");
sqlx::query(
r#"
INSERT INTO audit_log
(community_id, seq, hash, prev_hash, action, actor_pubkey, object_id, detail, created_at)
VALUES ($1, $2, $3, $4, $5, $6, $7, $8, $9)
"#,
)
.bind(audit_entry.community_id)
.bind(audit_entry.seq)
.bind(&audit_entry.hash)
.bind(audit_entry.prev_hash.as_deref())
.bind(audit_entry.action.as_str())
.bind(audit_entry.actor_pubkey.as_deref())
.bind(audit_entry.object_id.as_deref())
.bind(&audit_entry.detail)
.bind(audit_entry.created_at)
.execute(&mut *tx)
.await?;
tx.commit().await?;
Ok(audit_entry)
}
/// Verify the hash chain for one community over `[from_seq, to_seq]`.
///
/// Reads exactly that community's chain — it can never observe another
/// community's entries or head. Returns `Ok(false)` if the range is empty,
/// `Ok(true)` if the segment is internally consistent.
#[instrument(skip(self))]
pub async fn verify_chain(
&self,
community: CommunityId,
from_seq: i64,
to_seq: i64,
) -> Result<bool, AuditError> {
let rows = sqlx::query(
r#"
SELECT community_id, seq, hash, prev_hash, action, actor_pubkey,
object_id, detail, created_at
FROM audit_log
WHERE community_id = $1 AND seq BETWEEN $2 AND $3
ORDER BY seq ASC
"#,
)
.bind(community.as_uuid())
.bind(from_seq)
.bind(to_seq)
.fetch_all(&self.pool)
.await?;
if rows.is_empty() {
return Ok(false);
}
let mut expected_prev: Option<Vec<u8>> = None;
for row in &rows {
let entry = row_to_audit_entry(row)?;
if let Some(ref expected) = expected_prev {
// The previous entry's hash must equal this entry's prev_hash.
if entry.prev_hash.as_deref() != Some(expected.as_slice()) {
return Err(AuditError::ChainViolation { seq: entry.seq });
}
}
let computed = compute_hash(&entry)?;
if computed.as_slice() != entry.hash.as_slice() {
return Err(AuditError::HashMismatch { seq: entry.seq });
}
expected_prev = Some(entry.hash);
}
Ok(true)
}
/// Returns up to `limit` entries from one community's chain starting at
/// `from_seq`, ordered by sequence number. Scoped to `community` — never
/// returns another community's rows.
#[instrument(skip(self))]
pub async fn get_entries(
&self,
community: CommunityId,
from_seq: i64,
limit: i64,
) -> Result<Vec<AuditEntry>, AuditError> {
let rows = sqlx::query(
r#"
SELECT community_id, seq, hash, prev_hash, action, actor_pubkey,
object_id, detail, created_at
FROM audit_log
WHERE community_id = $1 AND seq >= $2
ORDER BY seq ASC
LIMIT $3
"#,
)
.bind(community.as_uuid())
.bind(from_seq)
.bind(limit)
.fetch_all(&self.pool)
.await?;
rows.iter().map(row_to_audit_entry).collect()
}
}
fn row_to_audit_entry(row: &sqlx::postgres::PgRow) -> Result<AuditEntry, AuditError> {
let action_str: String = row.get("action");
let action: AuditAction = action_str.parse().map_err(|_| {
warn!("unknown action in audit log");
AuditError::UnknownAction
})?;
Ok(AuditEntry {
community_id: row.get::<Uuid, _>("community_id"),
seq: row.get("seq"),
hash: row.get("hash"),
prev_hash: row.get("prev_hash"),
action,
actor_pubkey: row.get("actor_pubkey"),
object_id: row.get("object_id"),
detail: row.get("detail"),
created_at: row.get("created_at"),
})
}
#[cfg(test)]
mod tests {
use super::*;
use crate::action::AuditAction;
use crate::entry::NewAuditEntry;
use chrono::SubsecRound;
use std::sync::OnceLock;
use tokio::sync::Mutex;
use uuid::Uuid;
// The per-community advisory lock means different communities don't contend,
// but tests share one table; serialize them so seq assertions are stable.
static DB_LOCK: OnceLock<Mutex<()>> = OnceLock::new();
fn db_lock() -> &'static Mutex<()> {
DB_LOCK.get_or_init(|| Mutex::new(()))
}
async fn test_pool() -> Option<PgPool> {
let url = std::env::var("DATABASE_URL")
.unwrap_or_else(|_| "postgres://buzz:buzz_dev@localhost:5432/buzz".into());
PgPool::connect(&url).await.ok()
}
/// Runs without Postgres, so a regression here is caught by `just
/// test-unit` rather than only by the `#[ignore]` chain tests below.
#[test]
fn log_timestamp_carries_no_sub_microsecond_digits() {
let ts = log_timestamp();
assert_eq!(
ts,
ts.trunc_subsecs(6),
"created_at is hashed and then stored in a TIMESTAMPTZ column; \
sub-microsecond digits make every entry fail verify_chain"
);
}
/// A `community_id` known to exist in `communities` (FK target). Inserts a
/// throwaway community row with a unique host and returns its id.
async fn make_community(pool: &PgPool) -> Uuid {
let id = Uuid::new_v4();
let host = format!("test-{id}.example");
sqlx::query("INSERT INTO communities (id, host) VALUES ($1, $2)")
.bind(id)
.bind(host)
.execute(pool)
.await
.expect("insert test community");
id
}
fn new_entry(community_id: Uuid, action: AuditAction) -> NewAuditEntry {
NewAuditEntry {
community_id: CommunityId::from_uuid(community_id),
action,
actor_pubkey: Some(vec![0xab; 32]),
object_id: Some(format!("obj_{}", Uuid::new_v4())),
detail: serde_json::json!({"test": true}),
}
}
#[tokio::test]
#[ignore = "requires Postgres"]
async fn community_chain_starts_at_seq_1_with_null_prev() {
let _g = db_lock().lock().await;
let Some(pool) = test_pool().await else {
return;
};
let svc = AuditService::new(pool.clone());
let c = make_community(&pool).await;
let e = svc
.log(new_entry(c, AuditAction::EventCreated))
.await
.unwrap();
assert_eq!(e.seq, 1, "first entry in a community starts at seq 1");
assert!(e.prev_hash.is_none(), "genesis entry has NULL prev_hash");
assert_eq!(e.hash.len(), 32);
assert_eq!(e.community_id, c);
}
#[tokio::test]
#[ignore = "requires Postgres"]
async fn chain_links_within_one_community() {
let _g = db_lock().lock().await;
let Some(pool) = test_pool().await else {
return;
};
let svc = AuditService::new(pool.clone());
let c = make_community(&pool).await;
let e1 = svc
.log(new_entry(c, AuditAction::EventCreated))
.await
.unwrap();
let e2 = svc
.log(new_entry(c, AuditAction::ChannelCreated))
.await
.unwrap();
let e3 = svc
.log(new_entry(c, AuditAction::MemberAdded))
.await
.unwrap();
assert_eq!(e1.seq, 1);
assert_eq!(e2.seq, 2);
assert_eq!(e3.seq, 3);
assert!(e1.prev_hash.is_none());
assert_eq!(e2.prev_hash.as_deref(), Some(e1.hash.as_slice()));
assert_eq!(e3.prev_hash.as_deref(), Some(e2.hash.as_slice()));
assert!(svc
.verify_chain(CommunityId::from_uuid(c), 1, 3)
.await
.unwrap());
}
/// THE isolation property: two communities keep independent chains. Each
/// starts at seq 1; interleaving writes does not link them; verifying one
/// never traverses the other.
#[tokio::test]
#[ignore = "requires Postgres"]
async fn chains_are_independent_per_community() {
let _g = db_lock().lock().await;
let Some(pool) = test_pool().await else {
return;
};
let svc = AuditService::new(pool.clone());
let a = make_community(&pool).await;
let b = make_community(&pool).await;
// Interleave A and B writes.
let a1 = svc
.log(new_entry(a, AuditAction::EventCreated))
.await
.unwrap();
let b1 = svc
.log(new_entry(b, AuditAction::EventCreated))
.await
.unwrap();
let a2 = svc
.log(new_entry(a, AuditAction::ChannelCreated))
.await
.unwrap();
let b2 = svc
.log(new_entry(b, AuditAction::ChannelCreated))
.await
.unwrap();
// Each community's seq is independent and starts at 1.
assert_eq!((a1.seq, a2.seq), (1, 2));
assert_eq!((b1.seq, b2.seq), (1, 2));
// A's chain links only within A; B's only within B. A2 must NOT chain to
// B1 even though B1 was written between A1 and A2.
assert_eq!(a2.prev_hash.as_deref(), Some(a1.hash.as_slice()));
assert_eq!(b2.prev_hash.as_deref(), Some(b1.hash.as_slice()));
assert_ne!(a2.prev_hash, b1.prev_hash);
// Verifying A's chain traverses only A; same for B.
assert!(svc
.verify_chain(CommunityId::from_uuid(a), 1, 2)
.await
.unwrap());
assert!(svc
.verify_chain(CommunityId::from_uuid(b), 1, 2)
.await
.unwrap());
// get_entries scoped to A returns only A's rows.
let a_rows = svc
.get_entries(CommunityId::from_uuid(a), 1, 100)
.await
.unwrap();
assert!(
a_rows.iter().all(|e| e.community_id == a),
"A read leaked another community"
);
assert_eq!(a_rows.len(), 2);
}
#[tokio::test]
#[ignore = "requires Postgres"]
async fn verify_detects_tampering_within_a_community() {
let _g = db_lock().lock().await;
let Some(pool) = test_pool().await else {
return;
};
let svc = AuditService::new(pool.clone());
let c = make_community(&pool).await;
svc.log(new_entry(c, AuditAction::EventCreated))
.await
.unwrap();
let e2 = svc
.log(new_entry(c, AuditAction::EventDeleted))
.await
.unwrap();
svc.log(new_entry(c, AuditAction::ChannelDeleted))
.await
.unwrap();
// Tamper with e2's stored actor_pubkey.
let tampered: Vec<u8> = vec![0xff; 32];
sqlx::query("UPDATE audit_log SET actor_pubkey = $1 WHERE community_id = $2 AND seq = $3")
.bind(tampered)
.bind(c)
.bind(e2.seq)
.execute(&pool)
.await
.unwrap();
let r = svc.verify_chain(CommunityId::from_uuid(c), 1, 3).await;
assert!(matches!(r, Err(AuditError::HashMismatch { seq }) if seq == e2.seq));
}
/// A row forged with another community's id cannot pass verification against
/// the chain it was stamped for, because community_id is hashed in. (Models
/// "a row can't be replayed across chains and still verify".)
#[tokio::test]
#[ignore = "requires Postgres"]
async fn cross_community_row_does_not_verify() {
let _g = db_lock().lock().await;
let Some(pool) = test_pool().await else {
return;
};
let svc = AuditService::new(pool.clone());
let a = make_community(&pool).await;
let b = make_community(&pool).await;
let a1 = svc
.log(new_entry(a, AuditAction::EventCreated))
.await
.unwrap();
// Forge: copy A's seq-1 row's hash into B's chain at seq 1.
sqlx::query(
"INSERT INTO audit_log (community_id, seq, hash, prev_hash, action, actor_pubkey, object_id, detail, created_at)
VALUES ($1, 1, $2, NULL, $3, $4, $5, $6, NOW())",
)
.bind(b)
.bind(&a1.hash) // A's hash, which was computed over community_id = A
.bind(a1.action.as_str())
.bind(a1.actor_pubkey.as_deref())
.bind(a1.object_id.as_deref())
.bind(&a1.detail)
.execute(&pool)
.await
.unwrap();
// Verifying B's chain recomputes the hash with community_id = B, which
// won't match A's stored hash → HashMismatch. The forge is rejected.
let r = svc.verify_chain(CommunityId::from_uuid(b), 1, 1).await;
assert!(matches!(r, Err(AuditError::HashMismatch { seq: 1 })));
}
#[tokio::test]
#[ignore = "requires Postgres"]
async fn verify_empty_range_is_false() {
let _g = db_lock().lock().await;
let Some(pool) = test_pool().await else {
return;
};
let svc = AuditService::new(pool.clone());
let c = make_community(&pool).await;
// No entries for this fresh community.
assert!(!svc
.verify_chain(CommunityId::from_uuid(c), 1, 100)
.await
.unwrap());
}
}