Plan: Audit-Events Hash-Chain Verification Tests

On this page

Status

Step Description Status

1

Unit test: append 5 events via insert_audit_event, call verify_chain, assert all verified

Done (2026-04-19)

2

Unit test: insert 5 events, UPDATE one event’s event_type, call verify_chain, assert Errrow_id, reason identifies the tampered row

Done (2026-04-19)

3

Unit test: spawn N concurrent insert_audit_event tasks, then verify_chain. Corrects the misleadingly-Complete concurrency row in test-coverage-phase2.adoc

Done (2026-04-19)

4

test-coverage-phase2.adoc status fix

Done (2026-04-19)

5

FTI hash-chain extension — Phase B (issue #311)

Done (2026-04-25) — landed in two MRs against ADR-014. MR !122 (chain mechanics): schema migrations on canopy-tanf + canopy-medicaid (live + archive tables); compute_fti_event_hash + verify_fti_chain in crates/canopy-common/src/fti_audit.rs; PostgresFtiAuditLogger::log_access and fti_audited rewritten with pg_advisory_xact_lock(2) + canonical timestamp + clock_timestamp() ordering; 3 chain tests in services/canopy-tanf/tests/fti_audit_hash_chain_test.rs mirror the audit_events triple. MR !123 (operational layer): daily services/canopy-security/src/jobs/fti_chain_verify.rs job; GET /v1/security/fti/chain-status?service=… returns 200 / 404 / 503 per ADR-014 §7; POST /v1/security/fti/chain-verify for synchronous re-verify (incident response); fti.audit_chain.verified and fti.audit_chain.breach_detected events published on canopy.events with no FTI fields in payload; fti_chain_verifications audit table records every run.

6

Fix pre-existing timestamp-precision bug in compute_event_hash (discovered during Step 1)

Done (see Errata)

7

Fix pre-existing advisory-lock ordering bug in insert_audit_event (discovered during Step 3, tracked as #312 and closed)

Done (see Errata)

Branch: test/audit-events-hash-chain-tests
Labels: type::test, priority::high, program::infrastructure, service::security, compliance::irs-pub-1075-audit, workflow::ready

Context

ADR-004 requires two separate audit logs:

  • audit_events in canopy-security — the centralised wildcard-subscriber log of every cross-service event. Has a SHA-256 hash chain on previous_hash/event_hash columns added by services/canopy-security/migrations/20260402000001_add_hash_chain.sql. Writes are serialised by pg_advisory_xact_lock(1) in services/canopy-security/src/store/mod.rs line 37. Verified by verify_chain at line 85. Surfaced at GET /v1/security/verify-chain and canopy security verify-chain.

  • fti_audit_log in canopy-tanf and canopy-medicaid — separate per-program FTI-specific access logs required by IRS Pub 1075 §4 and ADR-004 §"FTI audit". Columns: id, accessed_by, accessed_at, purpose_code, data_elements_accessed, originating_system, action, resource_type, resource_id, request_id, ip_address, success, created_at. No hash-chain columns, no chain verification, no advisory lock. ADR-004 does not currently require hash-chain integrity on FTI logs — only separation, retention, access control, and FTI field scrubbing.

The 2026-04-18 security audit found:

FTI Audit Logging — ✅ PASS (Comprehensive). Hash chain columns present in services/canopy-security/migrations/20260402000001_add_hash_chain.sql, PostgresFtiAuditLogger writes them on insert.

Gap: No test exists that appends N events, recomputes the chain end-to-end, and asserts integrity. A refactor that silently stopped populating the hash columns would not be caught by current tests.

The auditor was looking at audit_events (which does have hash chain) and noted the test-coverage gap. The original version of this plan misread the finding and pivoted to extending the hash chain to fti_audit_log — conflating two distinct audit logs. Errata below.

The actual gap:

  • Missing: an append-N-verify-full-chain test with a controlled event sequence.

  • Missing: a tamper-detection test that mutates a row and asserts verify_chain identifies the right row.

  • Misleadingly complete: docs/modules/ROOT/pages/plans/test-coverage-phase2.adoc lines 17, 18, 90, 155 claim a chain concurrency test is "Complete", but the referenced test events_have_sequential_hash_chain at services/canopy-security/tests/security_test.rs line 139 only checks for duplicate previous_hash in events that already exist — it does not spawn concurrent inserts.

Scope

In scope:

  • Three new unit tests in services/canopy-security/src/store/mod.rs (alongside the existing 3 hash-function unit tests — keeps test and impl co-located).

  • Status-row fix in test-coverage-phase2.adoc.

  • Errata and Potential Improvements recording the original plan’s conflation and the FTI-chain extension as a separable future plan.

Out of scope (moved to Potential Improvements / separate plan):

  • Adding hash-chain columns to fti_audit_log tables in canopy-tanf and canopy-medicaid.

  • Modifying PostgresFtiAuditLogger::log_access to compute and write a chain.

  • A per-program chain verification fn.

  • Scheduled chain verification job across both services.

  • GET /v1/security/fti/chain-status endpoint.

These deliverables make up a real security feature that deserves an ADR amendment — see Errata.

Dependencies

  • services/canopy-security/src/store/mod.rs — insert_audit_event (line 30), compute_event_hash (line 15), verify_chain (line 85), advisory-lock wiring (line 37).

  • services/canopy-security/migrations/20260402000001_add_hash_chain.sql — schema.

  • services/canopy-security/src/event_parsing.rs — ParsedAuditEvent (the argument type for insert_audit_event).

Design

Test harness

All three tests live in the existing #[cfg(test)] mod tests at the bottom of store/mod.rs. They use the same canopy-eligibility-style devstack pattern: guard on canopy_test_lib::infrastructure_available, connect to canopy_security database on the shared postgres port, TRUNCATE audit_events at test start (the chain is a shared resource — co-mingling with existing events makes tamper-detection assertions noisy).

async fn test_pool() -> Option<sqlx::PgPool> {
    if !canopy_test_lib::infrastructure_available().await {
        return None;
    }
    let port = std::env::var("CANOPY_PORT_POSTGRES_5432")
        .ok().and_then(|p| p.parse::<u16>().ok()).unwrap_or(5432);
    let url = format!("postgres://canopy:canopy@localhost:{port}/canopy_security");
    let pool = sqlx::PgPool::connect(&url).await.ok()?;
    sqlx::query("TRUNCATE audit_events").execute(&pool).await.ok()?;
    Some(pool)
}

fn sample_parsed_event(event_type: &str) -> ParsedAuditEvent {
    ParsedAuditEvent {
        event_id: EventEnvelopeId::new(),
        event_type: event_type.into(),
        source_service: "test".into(),
        action: "read".into(),
        resource_type: "test".into(),
        resource_id: None,
        user_id: None,
        user_role: None,
        ip_address: None,
        metadata: serde_json::json!({}),
        event_timestamp: chrono::Utc::now(),
    }
}

Step 1 — append-N-verify

#[tokio::test]
async fn chain_verifies_after_five_sequential_inserts() {
    let Some(pool) = test_pool().await else { return };

    for i in 0..5 {
        insert_audit_event(&pool, &sample_parsed_event(&format!("test.seq.{i}")))
            .await
            .expect("insert");
    }

    match verify_chain(&pool).await.expect("verify query") {
        Ok(count) => assert_eq!(count, 5, "expected 5 verified events"),
        Err((id, reason)) => panic!("unexpected chain break at {id}: {reason}"),
    }
}

Step 2 — tamper detection

#[tokio::test]
async fn chain_breaks_at_tampered_row() {
    let Some(pool) = test_pool().await else { return };

    // Insert 5 events, capture the third's id.
    let mut ids = Vec::new();
    for i in 0..5 {
        let ev = sample_parsed_event(&format!("test.tamper.{i}"));
        insert_audit_event(&pool, &ev).await.expect("insert");
        // `insert_audit_event` doesn't return the row id; re-query by event_id.
        let id: uuid::Uuid = sqlx::query_scalar("SELECT id FROM audit_events WHERE event_id = $1")
            .bind(ev.event_id)
            .fetch_one(&pool).await.expect("lookup");
        ids.push(id);
    }
    let target = ids[2];

    sqlx::query("UPDATE audit_events SET event_type = 'tampered' WHERE id = $1")
        .bind(target)
        .execute(&pool).await.expect("tamper");

    match verify_chain(&pool).await.expect("verify query") {
        Ok(n) => panic!("chain reported {n} valid — tampered row went undetected"),
        Err((break_id, reason)) => {
            assert_eq!(break_id.as_uuid(), &target, "chain broke at wrong row: {reason}");
            assert!(reason.contains("hash mismatch"), "unexpected break reason: {reason}");
        }
    }
}

Step 3 — concurrent inserts

#[tokio::test]
async fn chain_stays_valid_under_concurrent_inserts() {
    let Some(pool) = test_pool().await else { return };

    let tasks: Vec<_> = (0..10).map(|i| {
        let pool = pool.clone();
        tokio::spawn(async move {
            insert_audit_event(&pool, &sample_parsed_event(&format!("test.conc.{i}")))
                .await
        })
    }).collect();

    for t in tasks {
        t.await.expect("task panic").expect("insert");
    }

    match verify_chain(&pool).await.expect("verify query") {
        Ok(count) => assert_eq!(count, 10, "all 10 concurrent inserts should chain cleanly"),
        Err((id, reason)) => panic!("chain broke at {id}: {reason} — advisory lock regression?"),
    }
}

The advisory lock (pg_advisory_xact_lock(1) at line 37) is what makes this test pass. Without the lock, two tasks that fetch the same previous_hash would produce forked events with identical previous_hash values — verify_chain would catch the fork because exactly one of the two would match expected_previous.

Errata

Original plan’s scope was mis-scoped

The plan was originally titled "FTI Audit Hash-Chain Verification Test" and proposed:

  1. Extracting a verify_hash_chain() helper into canopy-common::fti_audit

  2. Adding per-service hash-chain tests against canopy-tanf and canopy-medicaid’s `fti_audit_log

  3. A scheduled job that verifies the FTI chain daily

  4. An auditor endpoint GET /v1/security/fti/chain-status

Those steps assume the FTI audit log has a hash chain. It does not. PostgresFtiAuditLogger::log_access at crates/canopy-common/src/fti_audit.rs line 225 inserts 12 columns, none of them hash-related; the fti_audit_log migrations in canopy-tanf (20260325000001_create_fti_audit_log.sql) and canopy-medicaid (20260326000001_create_fti_audit_log.sql) have no hash columns.

The 2026-04-18 audit finding that drove the original plan was correctly identifying a test-coverage gap against audit_events in canopy-security (which does have a hash chain), not a missing FTI chain. The FTI scope was the plan author’s extrapolation, not the auditor’s ask.

Why the FTI extension isn’t the right scope for one MR

Extending hash-chain integrity to FTI audit logs is a real security feature with several design decisions deferred by the original plan’s terseness:

  • What is hashed? audit_events hashes (previous_hash, event_id, event_type, timestamp) — body is not included. FTI audit rows have no obvious event_id; the row’s own id is the natural substitute, but what about accessed_by, purpose_code, data_elements_accessed? Including them makes the chain strictly more tamper-evident; excluding them keeps the implementation simple. An ADR should settle this.

  • Advisory lock scope. FTI audit writes today happen inline with program-service DB transactions. Introducing pg_advisory_xact_lock(N) per service serialises every FTI write; this may conflict with high-volume program-service workloads in production. An ADR should settle the serialization strategy (per-service lock ID? separate write worker?).

  • Archive / retention interaction. archive_expired_records at crates/canopy-common/src/fti_audit.rs line 406 moves rows to fti_audit_log_archive. If we chain the live table, archiving breaks the chain across the archive boundary unless the archive is also chained (and audit_events_archive precedent suggests it should be — see services/canopy-security/migrations/20260409000000_align_archive_hash_columns.sql).

  • Failure mode. When verify_chain fails on a production FTI log, is that a 500 from the audit endpoint, an alert, or an auditor-only signal? This is a Pub 1075 §9 reporting question, not just a test question.

  • ADR-004 amendment. ADR-004 explicitly requires "independent FTI audit logging that satisfies IRS Pub 1075 §4" but does not mandate hash-chain integrity. Adding it changes what operators must implement to comply — an ADR amendment is the right vehicle.

Tracked as Phase B: issue #311. The original plan’s Step 1/3/6/7 sketches are preserved below under == Potential Improvements as the starting point for Phase B.

Two pre-existing bugs discovered and fixed during test implementation

Writing the end-to-end chain tests immediately surfaced two bugs in the production hash-chain path that had been latent since the original P1 #281 advisory-lock fix. Both were fixed in this same MR (the app isn’t live; deferring real bugs past the MR that uncovers them is deferred risk, not saved scope).

Bug 6: compute_event_hash timestamp-precision drift

compute_event_hash hashed timestamp.to_rfc3339(). chrono::DateTime::to_rfc3339 picks fractional-second precision dynamically — it includes nanoseconds when the input has them, strips trailing zeros otherwise. At INSERT time the timestamp comes from chrono::Utc::now() (nanosecond precision). Postgres TIMESTAMPTZ stores microseconds, so the round-trip at VERIFY time loses nanoseconds. The two to_rfc3339() calls produced different strings for the same logical timestamp — insert-time hash ≠ verify-time hash.

Fix: hash a canonical fixed-width %Y-%m-%dT%H:%M:%S%.6f+00:00 format (6-digit fractional-second, always). Identical strings at insert and verify regardless of sub-microsecond input.

The chain_verifies_after_five_sequential_inserts test fails without this fix.

Bug 7: insert_audit_event used transaction-start timestamps for chain ordering

insert_audit_event serialises concurrent inserts with pg_advisory_xact_lock(1), then runs SELECT event_hash FROM audit_events ORDER BY created_at DESC LIMIT 1 to pick the previous row. created_at defaulted to now(), which in Postgres is transaction_timestamp() — set at BEGIN, not at INSERT.

Under concurrency, N tokio tasks call pool.begin() at near-identical wall-clock times. Each task’s transaction_timestamp is fixed at that moment. Tasks then acquire the advisory lock in some order determined by tokio-scheduler + Postgres lock-queue — not by transaction-start order. Each INSERT writes created_at = transaction_timestamp of its own transaction. Result: created_at reflects tx-start order, not insert order.

The SELECT ORDER BY created_at DESC LIMIT 1 then returns whichever committed row has the latest tx-start time — not the row that most-recently committed. Multiple concurrent tasks end up chaining from the same predecessor. Fork.

Concrete trace from a failing 10-task run, recorded in issue #312:

  • task 9 tx_start = 762.516103 (latest)

  • task 1 tx_start = 762.515471

  • task 2 tx_start = 762.516032

  • task 4 tx_start = 762.516040

  • task 5 tx_start = 762.516048

Lock acquisition order was …, 9, 1, 2, 4, 5, …. Task 1 chained from task 9 correctly. Task 2’s SELECT returned task 9 (higher created_at than task 1) instead of the actually-just-committed task 1. Tasks 4 and 5 likewise saw task 9 as "latest". All four chained from task 9 → fork.

Fix: in the INSERT statement, write created_at = clock_timestamp() (wall-clock at INSERT execution, inside the advisory-locked critical section) explicitly rather than relying on the column’s now() default. clock_timestamp() is strictly increasing across serialised inserts, so ORDER BY created_at DESC LIMIT 1 now returns the actually-most-recently- inserted row. No schema migration; the column definition stays TIMESTAMPTZ NOT NULL DEFAULT now() for any other writer that doesn’t override it (none today on the chain path).

The concurrent_inserts_do_not_fork_chain test fails without this fix.

Tracked as issue #312; closed by this MR with the root-cause write-up.

Steps

Step 1 — append-N-verify test

Files: services/canopy-security/src/store/mod.rs test module.

Write chain_verifies_after_five_sequential_inserts per Design. One new test. Must skip cleanly when devstack is down.

Step 2 — tamper-detection test

Files: same module.

Write chain_breaks_at_tampered_row per Design. One new test. Target the middle row (row 3 of 5) so the assertion is unambiguous about which row broke.

Step 3 — concurrency test

Files: same module.

Write chain_stays_valid_under_concurrent_inserts per Design. One new test. 10 concurrent inserts against the same pool.

Step 4 — plan sync

Files: docs/modules/ROOT/pages/plans/test-coverage-phase2.adoc.

Update the audit-hash-chain concurrency row to reflect that coverage was added here (not in the earlier test that only checks for duplicate previous_hash). Replace any "Complete" claim with "Complete (verified by this plan)".

Step 5 — file Phase B issue

File a GitLab issue titled "FTI audit log hash-chain extension (Phase B)" with labels type::security, priority::medium, compliance::irs-pub-1075-audit, workflow::needs-spec. Body carries forward the original plan’s Steps 1/3/6/7 sketch as "Starting point" and notes the open design questions under Errata as acceptance criteria.

Files Touched

File Change

services/canopy-security/src/store/mod.rs

3 new unit tests in existing test module

docs/modules/ROOT/pages/plans/test-coverage-phase2.adoc

Status row correction

docs/modules/ROOT/pages/plans/fti-audit-hash-chain-test.adoc

Full rewrite (this file) — rescope + errata + potential improvements

CHANGELOG.adoc

Entry under == Unreleased

Deferred (Phase B issue):

  • services/canopy-tanf/migrations/ — new migration adding previous_hash/event_hash to fti_audit_log

  • services/canopy-medicaid/migrations/ — same

  • crates/canopy-common/src/fti_audit.rs — update log_access + add verify_chain helper

  • services/canopy-security/src/jobs/fti_chain_verify.rs — scheduled job

  • services/canopy-security/src/api/fti.rs — per-service chain-status endpoint

Verification

  1. cargo nextest run -p canopy-security — 3 new tests pass (6 total under store::tests)

  2. Deliberately break insert_audit_event (e.g., write a constant hash instead of computing one) — the append-N-verify test fails loudly

  3. Deliberately weaken verify_chain (e.g., skip the recomputed-hash assertion) — the tamper-detection test fails loudly

  4. Deliberately remove pg_advisory_xact_lock(1) — the concurrency test fails under real load; also fails deterministically when 10 tasks race

  5. cargo xtask validate — full pre-push battery green

Resolved by Phase B (#311 closed 2026-04-26)

Phase B’s full sketch — preserved here as historical record — was implemented end-to-end and shipped under #311 with ADR-014 ratified alongside. Each bullet now points at its landing site:

  • FTI hash-chain columns — landed via services/canopy-tanf/migrations/20260425000000_add_fti_audit_hash_chain.sql and the canopy-medicaid sibling migration; both add previous_hash and event_hash to fti_audit_log (and fti_audit_log_archive to extend the chain across the archive boundary).

  • FTI logger writes chain — PostgresFtiAuditLogger::log_access in crates/canopy-common/src/fti_audit.rs now computes the chain hash with pg_advisory_xact_lock(2) per-database serialisation and the canonical %Y-%m-%dT%H:%M:%S%.6f+00:00 timestamp format (matches the audit_events chain Bug 6/7 fixes that became part of ADR-014).

  • Shared verify_fti_chain helper — crates/canopy-common::fti_audit::verify_fti_chain.

  • Scheduled job + breach event — canopy-security background job emits fti.audit_chain.verified and fti.audit_chain.breach_detected; the latter forces 503 from GET /v1/security/fti/chain-status per Pub 1075 §9.

  • Auditor endpoint — GET /v1/security/fti/chain-status shipped on canopy-security.

  • Archive chaining — chain extends across fti_audit_log_archive per ADR-014.

  • ADR amendment — ADR-014 ratifies the design and amends ADR-004 §"FTI audit" to require chain integrity.

Documentation Updates

  • .claude/docs/services.md — canopy-security chain verification section should cite these tests

  • CHANGELOG.adoc — entry under == Unreleased

Status (2026-04-24 audit correction): Phase A (the scope of this plan — three end-to-end tests over audit_events) is Done (Steps 1-4, 6, 7 marked Done 2026-04-19; see Status table above). Step 5 was a meta-step that filed the Phase B follow-up issue.

Tracked follow-ups:

  • Phase B — FTI hash-chain extension to fti_audit_log in canopy-tanf and canopy-medicaid. Tracked as #311. Phase B’s design questions (hash inputs, advisory-lock scope, archive boundary, breach-reporting pathway, ADR-004 amendment) are settled in ADR-014; implementation lands against #311.

  • #317 — closed 2026-04-24 as a duplicate of #311 (audit miscategorised the plan as "entire plan unimplemented"; only Phase B remained).

Edit this page · default