Skip to content

Commit 264a56a

Browse files
authored
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>
1 parent bb445d3 commit 264a56a

2 files changed

Lines changed: 121 additions & 3 deletions

File tree

crates/buzz-audit/src/hash.rs

Lines changed: 96 additions & 1 deletion
Original file line numberDiff line numberDiff line change
@@ -1,3 +1,4 @@
1+
use chrono::{DateTime, SubsecRound, Utc};
12
use sha2::{Digest, Sha256};
23

34
use crate::entry::AuditEntry;
@@ -7,12 +8,34 @@ use crate::error::AuditError;
78
/// entry. Stored as `prev_hash = NULL`; hashed as all-zero bytes.
89
pub const GENESIS_HASH: [u8; 32] = [0u8; 32];
910

11+
/// Reduce a timestamp to the precision the audit store round-trips.
12+
///
13+
/// `audit_log.created_at` is `TIMESTAMPTZ`, which Postgres keeps at microsecond
14+
/// resolution. [`compute_hash`] covers `created_at.to_rfc3339()`, and that
15+
/// string's sub-second digit count follows the value (chrono emits 0, 3, 6 or 9
16+
/// digits), so a timestamp carrying nanoseconds hashes to a digest that can
17+
/// never be recomputed from the stored row — the entry is written with one
18+
/// preimage and verified against another.
19+
///
20+
/// Every `created_at` must therefore pass through here *before* it is hashed
21+
/// and stored, so the in-memory entry and the row are byte-identical.
22+
pub fn to_storage_precision(created_at: DateTime<Utc>) -> DateTime<Utc> {
23+
created_at.trunc_subsecs(6)
24+
}
25+
1026
/// SHA-256 over the entry's identity, chain, and context fields.
1127
///
1228
/// Field order is fixed — changing it invalidates all existing chains. The
1329
/// `community_id` is hashed first so chain identity carries the tenant: an entry
1430
/// cannot be lifted out of one community's chain and re-verified inside another.
1531
///
32+
/// `created_at` is normalized through [`to_storage_precision`] here rather than
33+
/// hashed as given. Write paths truncate before storing so the row matches the
34+
/// in-memory entry, but normalizing again at the single point that consumes the
35+
/// value means no future caller can reintroduce the write/read preimage split
36+
/// by forgetting to. Values already at storage precision are unaffected —
37+
/// truncation is idempotent — so this does not change any digest.
38+
///
1639
/// `detail` is serialized via [`canonical_json`] (sorted keys) so the hash is
1740
/// stable across machines and Rust versions. A serialization failure is a hard
1841
/// error, never silently hashed as empty.
@@ -21,7 +44,11 @@ pub fn compute_hash(entry: &AuditEntry) -> Result<[u8; 32], AuditError> {
2144
// Tenant binding: community_id leads the hash.
2245
hasher.update(entry.community_id.as_bytes());
2346
hasher.update(entry.seq.to_be_bytes());
24-
hasher.update(entry.created_at.to_rfc3339().as_bytes());
47+
hasher.update(
48+
to_storage_precision(entry.created_at)
49+
.to_rfc3339()
50+
.as_bytes(),
51+
);
2552
hasher.update(entry.action.as_str().as_bytes());
2653
match &entry.actor_pubkey {
2754
Some(pk) => {
@@ -111,13 +138,81 @@ mod tests {
111138
}
112139
}
113140

141+
/// A wall-clock instant carrying sub-microsecond digits, like `Utc::now()`
142+
/// returns on Linux (`clock_gettime`, nanosecond resolution).
143+
fn nanosecond_instant() -> chrono::DateTime<Utc> {
144+
chrono::DateTime::from_timestamp_nanos(1_700_000_000_123_456_789)
145+
}
146+
147+
/// What Postgres hands back for a `TIMESTAMPTZ`: microsecond resolution.
148+
fn after_database_round_trip(ts: chrono::DateTime<Utc>) -> chrono::DateTime<Utc> {
149+
ts.trunc_subsecs(6)
150+
}
151+
114152
#[test]
115153
fn deterministic() {
116154
let entry = sample_entry();
117155
assert_eq!(compute_hash(&entry).unwrap(), compute_hash(&entry).unwrap());
118156
assert_eq!(compute_hash(&entry).unwrap().len(), 32);
119157
}
120158

159+
#[test]
160+
fn storage_precision_drops_sub_microsecond_digits() {
161+
let stored = to_storage_precision(nanosecond_instant());
162+
assert_eq!(stored.timestamp_subsec_nanos(), 123_456_000);
163+
// Idempotent, so a stored value re-read from Postgres is unchanged.
164+
assert_eq!(stored, after_database_round_trip(stored));
165+
}
166+
167+
#[test]
168+
fn rfc3339_sub_second_width_follows_the_value() {
169+
// The underlying trap, pinned on the preimage rather than the digest:
170+
// chrono emits 0/3/6/9 fractional digits depending on the value, so a
171+
// nanosecond timestamp and its microsecond truncation are *different
172+
// strings*. Hashing the untruncated value therefore produces a digest
173+
// that cannot be recomputed from the stored row — which is what made
174+
// every entry fail `verify_chain` with `HashMismatch`.
175+
let ns = nanosecond_instant();
176+
assert_eq!(ns.to_rfc3339(), "2023-11-14T22:13:20.123456789+00:00");
177+
assert_eq!(
178+
after_database_round_trip(ns).to_rfc3339(),
179+
"2023-11-14T22:13:20.123456+00:00"
180+
);
181+
assert_ne!(ns.to_rfc3339(), after_database_round_trip(ns).to_rfc3339());
182+
}
183+
184+
#[test]
185+
fn compute_hash_normalizes_sub_microsecond_timestamps() {
186+
// The enforcement point: even handed an untruncated `created_at`,
187+
// `compute_hash` digests the storage-precision value, so a write path
188+
// that forgot to truncate cannot split the write/read preimage.
189+
let ns = nanosecond_instant();
190+
let mut written = sample_entry();
191+
written.created_at = ns;
192+
let mut read_back = sample_entry();
193+
read_back.created_at = after_database_round_trip(ns);
194+
195+
assert_eq!(
196+
compute_hash(&written).unwrap(),
197+
compute_hash(&read_back).unwrap()
198+
);
199+
}
200+
201+
#[test]
202+
fn storage_precision_timestamps_survive_a_database_round_trip() {
203+
// The invariant the write path must hold: hash what will be stored, so
204+
// recomputing from the row reproduces the digest.
205+
let mut written = sample_entry();
206+
written.created_at = to_storage_precision(nanosecond_instant());
207+
let mut read_back = written.clone();
208+
read_back.created_at = after_database_round_trip(read_back.created_at);
209+
210+
assert_eq!(
211+
compute_hash(&written).unwrap(),
212+
compute_hash(&read_back).unwrap()
213+
);
214+
}
215+
121216
#[test]
122217
fn community_id_is_part_of_identity() {
123218
// The whole point: the same logical entry in two communities hashes

crates/buzz-audit/src/service.rs

Lines changed: 25 additions & 2 deletions
Original file line numberDiff line numberDiff line change
@@ -10,9 +10,18 @@ use crate::{
1010
action::AuditAction,
1111
entry::{AuditEntry, NewAuditEntry},
1212
error::AuditError,
13-
hash::compute_hash,
13+
hash::{compute_hash, to_storage_precision},
1414
};
1515

16+
/// The `created_at` stamped on a new entry.
17+
///
18+
/// Reduced to the precision Postgres round-trips before it is hashed — see
19+
/// [`to_storage_precision`]. Split out from [`AuditService::log_inner`] so the
20+
/// invariant is testable without a database.
21+
fn log_timestamp() -> DateTime<Utc> {
22+
to_storage_precision(Utc::now())
23+
}
24+
1625
/// Per-community advisory lock key. Derived in Postgres from the community UUID
1726
/// so two communities never serialize each other's audit writes (which would be
1827
/// both a throughput bottleneck and a cross-tenant timing oracle). The lock is
@@ -100,7 +109,7 @@ impl AuditService {
100109
};
101110
let seq = prev_seq + 1;
102111

103-
let created_at: DateTime<Utc> = Utc::now();
112+
let created_at: DateTime<Utc> = log_timestamp();
104113

105114
let mut audit_entry = AuditEntry {
106115
community_id,
@@ -251,6 +260,7 @@ mod tests {
251260
use super::*;
252261
use crate::action::AuditAction;
253262
use crate::entry::NewAuditEntry;
263+
use chrono::SubsecRound;
254264
use std::sync::OnceLock;
255265
use tokio::sync::Mutex;
256266
use uuid::Uuid;
@@ -268,6 +278,19 @@ mod tests {
268278
PgPool::connect(&url).await.ok()
269279
}
270280

281+
/// Runs without Postgres, so a regression here is caught by `just
282+
/// test-unit` rather than only by the `#[ignore]` chain tests below.
283+
#[test]
284+
fn log_timestamp_carries_no_sub_microsecond_digits() {
285+
let ts = log_timestamp();
286+
assert_eq!(
287+
ts,
288+
ts.trunc_subsecs(6),
289+
"created_at is hashed and then stored in a TIMESTAMPTZ column; \
290+
sub-microsecond digits make every entry fail verify_chain"
291+
);
292+
}
293+
271294
/// A `community_id` known to exist in `communities` (FK target). Inserts a
272295
/// throwaway community row with a unique host and returns its id.
273296
async fn make_community(pool: &PgPool) -> Uuid {

0 commit comments

Comments
 (0)