Audit Logging

The previous two lessons measured two configuration decisions, and both left a question open: who, and when. The application’s own logs write the request and the error; they do not write which staff member waived which member’s penalty. The audit log fills this gap, and it is separated by purpose from the audit trail in the Case Studies course: there, the trail was a data-structure decision for reconstructing state; here, the log is kept to show, after the fact, who was responsible for a decision, and so it must not have been altered itself.

Traceability is measured with four questions. Which events are logged — how many of the system’s decision points are written. Can the log prove it has not been altered afterward. What does the log itself carry. And how long is it kept. All four are configuration decisions, and the system raises no error when they are set wrong.

Decision Points

AS16 — the loan system has twelve decision points, and their daily volumes sit in the table below; the total is 3,012 events. AS17 — every record carries four fields: kind, actor, target, result. The store sits on node:sqlite, and every record’s digest also covers the previous one’s.

// log.mjs — the audit log store: decision points, hash chain, verification
import { createHash } from 'node:crypto';
import { DatabaseSync } from 'node:sqlite';

export const SEED = 4231;
let state = SEED;
const rand = () => (state = (state * 1103515245 + 12345) % 2147483648) / 2147483648;
const pick = (n) => Math.floor(rand() * n);

// Decision points: [kind, daily count, changes state?, actor class, target class]
export const KINDS = [
  ['LOGIN', 1200, false, 'member', 'self'], ['LOGIN_REJECTED', 60, false, 'member', 'self'],
  ['VIEW', 900, false, 'staff', 'member'], ['LOAN', 400, true, 'member', 'catalog'],
  ['RETURN', 380, true, 'member', 'catalog'], ['CATALOG_EDIT', 45, true, 'staff', 'catalog'],
  ['PENALTY_WAIVE', 12, true, 'staff', 'member'], ['EXPORT', 4, false, 'staff', 'member'],
  ['ROLE_CHANGE', 5, true, 'staff', 'member'], ['MEMBER_DELETE', 3, true, 'staff', 'member'],
  ['ROLLOUT', 2, true, 'staff', 'system'], ['ROTATION', 1, true, 'staff', 'system'],
];
export const MEMBERS = 40, STAFF = 6, CATALOG_SIZE = 60;

export function generateDay() {
  const events = [];
  for (const [kind, count, writes, actorClass, targetClass] of KINDS) {
    for (let i = 0; i < count; i++) {
      const actor = actorClass === 'member' ? `U-${1 + pick(MEMBERS)}` : `G-${1 + pick(STAFF)}`;
      const target = targetClass === 'self' ? actor
        : targetClass === 'member' ? `U-${1 + pick(MEMBERS)}`
          : targetClass === 'catalog' ? `K-${800 + pick(CATALOG_SIZE)}` : 'system';
      events.push({ kind, actor, target, writes, seq: rand(), result: kind === 'LOGIN_REJECTED' ? 'reject' : 'accept' });
    }
  }
  return events.sort((a, b) => a.seq - b.seq);
}

// Hash chain: every record's digest also covers the previous one's digest.
export const digest = (seq, previous, body) =>
  createHash('sha256').update(`${seq}|${previous}|${body}`).digest('hex').slice(0, 16);

export function openLog(events, alias = null) {
  const db = new DatabaseSync(':memory:');
  db.exec('create table log (seq integer primary key, kind text, actor text, target text, result text, body text, digest text)');
  const insert = db.prepare('insert into log values (?, ?, ?, ?, ?, ?, ?)');
  let previous = 'start';
  events.forEach((o, i) => {
    const [actor, target] = alias ? [alias(o.actor), alias(o.target)] : [o.actor, o.target];
    const body = JSON.stringify({ kind: o.kind, actor, target, result: o.result });
    previous = digest(i + 1, previous, body);
    insert.run(i + 1, o.kind, actor, target, o.result, body, previous);
  });
  return db;
}

// Verification walks the chain from the start; returns the seq of the first mismatch, else 0.
export function verify(db) {
  let previous = 'start';
  for (const k of db.prepare('select * from log order by seq').all()) {
    previous = digest(k.seq, previous, k.body);
    if (previous !== k.digest) return k.seq;
  }
  return 0;
}

Three Logging Policies

There are three common ways to choose which events to log, and all three look defensible: writing only the operations that change state, writing only rejected authorization requests, writing every decision point. The way to measure the difference between them is not volume but how many questions can be answered. The run below asks eight accountability questions against all three logs as real queries; the questions’ targets are read from the log itself.

// measurement.mjs — three log policies, what the chain catches and what it does not, the log's own privacy
import { createHash } from 'node:crypto';
import { generateDay, openLog, verify, digest, KINDS, SEED } from './log.mjs';

const events = generateDay();
const full = openLog(events);
const one = (s) => full.prepare(s).get();
const penaltyMember = one("select target from log where kind='PENALTY_WAIVE'").target;
const deletedMember = one("select target from log where kind='MEMBER_DELETE'").target;
const catalogItem = one("select target from log where kind='CATALOG_EDIT'").target;
const topViewer = one("select actor from log where kind='VIEW' group by actor order by count(*) desc").actor;

const questions = [
  [`who waived ${penaltyMember}'s penalty`, `select actor from log where kind='PENALTY_WAIVE' and target='${penaltyMember}'`],
  [`how many distinct members did ${topViewer} view`, `select distinct target from log where kind='VIEW' and actor='${topViewer}'`],
  [`who edited ${catalogItem}'s record`, `select actor from log where kind='CATALOG_EDIT' and target='${catalogItem}'`],
  ['which account had more than four failed logins', "select target from log where kind='LOGIN_REJECTED' group by target having count(*) > 4"],
  ['who rotated the signing key', "select actor from log where kind='ROTATION'"],
  ['who started the rollout', "select actor from log where kind='ROLLOUT'"],
  [`who accessed ${penaltyMember}'s data`, `select distinct actor from log where target='${penaltyMember}' and kind in ('VIEW','EXPORT')`],
  [`who accessed deleted member ${deletedMember}'s record`, `select distinct actor from log where target='${deletedMember}' and kind='VIEW'`],
];

const policies = {
  'writes only': (o) => o.writes,
  'rejects only': (o) => o.result === 'reject',
  'all decisions': () => true,
};

const s = (x, n) => String(x).padStart(n);
console.log(`seed ${SEED}: ${KINDS.length} decision points, ${events.length} events/day`);
console.log(`${'policy'.padEnd(20)}${s('records', 8)}${s('bytes', 8)}${s('answered', 17)}${s('unanswered', 18)}`);
const answer = {};
for (const [name, filter] of Object.entries(policies)) {
  const db = openLog(events.filter(filter));
  const bytes = db.prepare('select sum(length(body)) as b, count(*) as n from log').get();
  answer[name] = questions.map(([, sql]) => db.prepare(sql).all().length > 0);
  const count = answer[name].filter(Boolean).length;
  console.log(`${name.padEnd(20)}${s(bytes.n, 8)}${s(bytes.b, 8)}${s(`${count}/8`, 17)}`
    + `${s(answer[name].map((v, i) => (v ? '' : i + 1)).filter(Boolean).join(',') || '-', 18)}`);
}
console.log(questions.map(([name], i) => `  ${i + 1}. ${name}`).join('\n'));

// Chain: change the body, refresh the digest too, truncate the tail.
const corrupted = openLog(events);
const victim = 500;
const old = corrupted.prepare('select body, digest from log where seq=?').get(victim);
const updated = old.body.replace('"result":"accept"', '"result":"reject"');
corrupted.prepare('update log set body=? where seq=?').run(updated, victim);
console.log(`\nverification while the chain is clean: ${verify(full)}`);
console.log(`record ${victim}'s body was changed -> first mismatch at seq ${verify(corrupted)}`);
const previous = corrupted.prepare('select digest from log where seq=?').get(victim - 1).digest;
corrupted.prepare('update log set digest=? where seq=?').run(digest(victim, previous, updated), victim);
console.log(`digest refreshed too -> first mismatch at seq ${verify(corrupted)}`);

const truncated = openLog(events);
truncated.prepare('delete from log where seq > ?').run(events.length - 25);
console.log(`last 25 records deleted -> verification ${verify(truncated)} (0 = no mismatch)`);
for (const anchor of [Infinity, 500, 100, 10]) {
  const silent = anchor === Infinity ? events.length : events.length % anchor;
  const label = anchor === Infinity ? 'no anchor      ' : `anchor every ${s(anchor, 3)}`;
  console.log(`${label} -> ${s(silent, 4)} records can be silently deleted in this run, worst case ${anchor === Infinity ? silent : anchor - 1}`);
}

// The log's own privacy.
const personal = full.prepare("select count(*) as n from log where actor like 'U-%' or target like 'U-%'").get().n;
const history = full.prepare("select actor, count(*) as n from log where kind='LOAN' group by actor order by n desc").all();
const salted = (salt) => (d) => (d.startsWith('U-') ? `T-${createHash('sha256').update(salt + d).digest('hex').slice(0, 8)}` : d);
const pseudonymous = openLog(events, salted('period-1'));
const pseudonymousHistory = pseudonymous.prepare("select actor, count(*) as n from log where kind='LOAN' group by actor order by n desc").all();
const period2 = new Set(history.map((g) => salted('period-2')(g.actor)));
const shared = pseudonymousHistory.filter((g) => period2.has(g.actor)).length;
console.log(`\nrecords identifying a person: ${personal}/${events.length} (${(100 * personal / events.length).toFixed(1)}%)`);
console.log(`members whose loan history can be built: with open identity ${history.length}, longest list ${history[0].n} records`);
console.log(`same measure on the pseudonymous log: ${pseudonymousHistory.length} members, longest list ${pseudonymousHistory[0].n} records`);
console.log(`shared pseudonym across two periods when the period salt changes: ${shared}`);

const bytes = full.prepare('select sum(length(body)) as b from log').get().b;
for (const day of [30, 180, 3650]) {
  console.log(`retention ${s(day, 4)} days -> ${s(events.length * day, 9)} records, `
    + `${s((bytes * day / 1048576).toFixed(1), 7)} MiB, person-days ${history.length * day}`);
}

seed 4231: 12 decision points, 3012 events/day
policy               records   bytes         answered        unanswered
writes only              848   56159              4/8           2,4,7,8
rejects only              60    4412              1/8     1,2,3,5,6,7,8
all decisions           3012  194726              8/8                 -
  1. who waived U-12's penalty
  2. how many distinct members did G-1 view
  3. who edited K-834's record
  4. which account had more than four failed logins
  5. who rotated the signing key
  6. who started the rollout
  7. who accessed U-12's data
  8. who accessed deleted member U-27's record

verification while the chain is clean: 0
record 500's body was changed -> first mismatch at seq 500
digest refreshed too -> first mismatch at seq 501
last 25 records deleted -> verification 0 (0 = no mismatch)
no anchor       -> 3012 records can be silently deleted in this run, worst case 3012
anchor every 500 ->   12 records can be silently deleted in this run, worst case 499
anchor every 100 ->   12 records can be silently deleted in this run, worst case 99
anchor every  10 ->    2 records can be silently deleted in this run, worst case 9

records identifying a person: 2964/3012 (98.4%)
members whose loan history can be built: with open identity 40, longest list 18 records
same measure on the pseudonymous log: 40 members, longest list 18 records
shared pseudonym across two periods when the period salt changes: 0
retention   30 days ->     90360 records,     5.6 MiB, person-days 1200
retention  180 days ->    542160 records,    33.4 MiB, person-days 7200
retention 3650 days ->  10993800 records,   677.8 MiB, person-days 146000

The Answer to Eight Questions

The policy that logs only writes keeps 848 of the daily 3,012 events and answers four of eight questions. The four left unanswered are all the same class: each asks about a read. How many members’ records a staff member viewed, who accessed a member’s data, who viewed a deleted member’s record before deletion — none of these change state, so none is written. Asked about the traceability of access to personal data, this policy is structurally unable to answer, and nothing in its configuration flags that.

The policy logging only rejected requests is cheapest at 60 records and answers one of eight — only the question on failed logins. Its silent assumption is that abuse shows up in rejected requests. Yet a staff member with authorization viewing nine hundred records is never rejected, and never appears in this log at all.

Logging every decision point gives eight of eight, at roughly three and a half times the volume (194,726 bytes against 56,159 here). Where the difference comes from matters: 2,100 of the 3,012 events are logins and views — the expensive part of traceability is exactly what the writes-only policy skips. Counting decision points thus comes before any argument about volume — which questions can be answered is set by which events are written.

What the Chain Does Not Catch

If a log is kept to show accountability, it must be able to show it has not been altered afterward. The hash chain provides this only in part. When the result field in record 500’s body is changed from accept to reject, verification stops at exactly that point. If whoever changed it also recomputes that record’s digest, the mismatch shifts to the next record (501): because every digest covers the one before it, fixing a single record requires rewriting every record after it.

Cutting the tail is different. When the last twenty-five records are deleted, verification returns zero — no mismatch at all. The remaining chain is intact, because the chain shows only its own internal consistency; it does not know how many records ought to exist. The only way to know a record was deleted is to write the chain’s digest at some point outside the log, under a separate responsibility. The anchor period measures this gap: no anchor lets all 3,012 of the day’s records be silently deleted; an anchor every five hundred caps the worst case at 499; every ten, at 9. The wrong configuration here is the record’s absence, and an absent record breaks no verification.

The Log’s Own Risk

98.4% of this day’s records identify a person. An audit log, by definition, writes who did what; the moment it is collected, it becomes the system’s densest set of personal data. From the loan records, the full reading history of all forty members can be built, with the longest list at eighteen records. In a library system, this is the list of what members have read, and it keeps standing in the audit log even after it has been deleted from the loan service’s own database following a return.

Pseudonymizing the member ID with a salted hash changes this measure not at all: still forty members, still an eighteen-record longest list. A pseudonym hides identity, not the link; the same pseudonym keeps tying all of one person’s records together. The only setting that breaks the link is changing the salt per period, and its measure is in the last line: the two periods share zero pseudonyms. The cost sits there too — once the period salt is discarded, the seventh question cannot be asked of past periods, because the member’s pseudonym for that period can no longer be recomputed.

Retention is the last setting, and it grows two measures at once. Thirty days comes to 5.6 MiB and 1,200 person-days; ten years comes to 677.8 MiB and 146,000 person-days. The volume side is cheap — even ten years of log stays under a gigabyte, so extending retention raises no alarm anywhere. What grows is the other half of the cost: an audit log kept for ten years is a data set holding ten years of reading history in one place, and when it leaks, what leaks is not a list of requests but a list of people.

Summary

• The audit log is separated by purpose from the audit trail: the trail reconstructs state, the log shows a decision’s accountable party, and so must also prove its own immutability.
• Logging only writes left four of eight questions unanswered, and every unanswered one asked about a read; logging only rejected requests answered one of eight.
• Logging every decision point gave eight of eight and multiplied volume roughly three and a half times; the entire difference comes from login and view records.
• The hash chain caught a body change at seq 500, a change with a refreshed digest at seq 501; it never caught the deletion of the last twenty-five records. The anchor period is the measure of this silent gap: 3,012 with no anchor, worst case 499 with an anchor every five hundred.
• 98.4% of records identify a person, and the full reading history of all forty members can be built; pseudonymization did not change this number, only a per-period salt zeroed the link between two periods.
• Extending retention to ten years comes to 677.8 MiB and 146,000 person-days; the volume is too small to raise an alarm, and person-days is the real cost of the retention decision.

Next Step

The audit log asks afterward and answers well, but it stops nothing. This day’s log holds twelve hundred logins, sixty failed logins, and nine hundred views; the log writes who they came from, not that someone should not reach that count. In a forty-member system, sixty failed logins piling onto a single account and sixty spread across forty accounts produce the same log volume, and the two are entirely different things. The next lesson takes on this distinction: who the limit is applied to, how the response itself gives away whether an account exists, and how long lockout keeps the legitimate account out.