I Built an Audit Log Three Times. The First Two Lied to Me.

Over the last couple of years I've built a few systems where somebody,
eventually, asks "who changed this?" An online exam platform where teachers
grade students. An attendance platform where managers approve overtime and
the numbers go to payroll. In both, a wrong answer to that question costs
someone money or a grade.

An audit log is supposed to be the answer. It's the table that records who did
what, to what, and when, so that six months later you can open it and know.
Simple idea. I got it wrong twice before I got it right, and the two wrong
versions both looked fine until the day someone actually needed them.

The story comes first, because the mistakes are what explain the rules. The
rules come after, as eight decisions you can make for any project.

---

Version one: add a table when a feature needs it

The first system was the exam platform. I didn't sit down and design an audit
log. Each time a feature needed some history, I added a table for it.

So there was a table for admin actions, like suspending a school. There was a
table for subscription changes, which stored the old and new values. There was
a table that logged every request made with an API key. And there was a table
for what students did during an exam: switching tabs, going offline, that kind
of thing.

What was good about it: each table did its one job. The subscription one could
actually show you what a plan looked like before and after a change. The exam
activity one drove a real feature, auto-submitting a student after too many
violations. For the people using those two features, it worked.

Where it went wrong is everything in between. The admin actions table had
columns for IP address and browser, and the admin page showed them, but every
row said -. Nobody had ever passed a value in. I had constants defined for
login and logout events, which made the code look like login was audited. It
wasn't. Nothing used them.

Worse, the things teachers actually asked about were not in any table. Editing
an exam. Extending a deadline. Changing a student's grade. Those just updated
the row and moved on. The first time a teacher asked me "who changed this
grade?", I opened my audit page, saw a row for a school being suspended last
month with - for the IP, and nothing at all about the grade.

Four tables, and not one of them could answer the question I was being asked.
Each table answered the question of whoever wrote it that week. Nobody had
decided which questions mattered.

Version two: one table, one function

The next system was the attendance platform, and I started cleaner. One
audit_log table. One function, Record(ctx, entry), that every handler
calls. The actor is read from the request context instead of being passed in,
so no code path can claim to be someone else. Actions are typed constants
instead of free strings.

What was good: for the first time there was one place to look. If an admin
renamed a department or deactivated a job title, there was a line, with the
right actor, every time. Adding a new audited action was one constant and one
Record call.

Where it went wrong is subtler. Record was best-effort. The change commits
first, then the audit line is written separately, and if the audit write fails
it logs a warning and moves on. For "department renamed", that's fine. Losing
one of those lines is a gap nobody will ever notice.

But this system feeds payroll. If a user grants themselves the right to approve
overtime, approves their own, and the audit insert happens to fail because a
deploy was restarting the database at that moment, there is no line. The money
goes out. The log has a hole in the one place a hole can't be.

I had decided a single failure behavior for the whole system. It was right for
most actions and wrong for the ones that mattered most.

Version three: decide what can fail, per action

The fix was not a bigger table or a smarter function. It was one question,
asked about every action: if the audit write fails, should the action still
happen?

For renaming a department, yes. For granting a role, no. If the line can't be
written, the role shouldn't be granted either. That split turned out to be the
whole design.

I grouped the actions into families, and the family decides two things: whether
the audit line is written inside the same database transaction as the change,
and whether a cleanup job is ever allowed to delete it. I ended up with seven:

Family	What it covers	Same transaction?	Retention may delete?
authority	roles, grants, memberships, policy, approval chains	yes	never
access	reading someone else's sensitive data	yes	after N days
identity	account lifecycle, failed logins	no	failed logins only
masterdata	renames, deactivations	no	never
decision	pointer to a reasoned-trail row	no	never
integration	API keys, webhooks	no	never
export	a file leaving the system	no	never

The rest of this section is how that table turns into code. The examples are
Go with Postgres, but nothing here depends on the language.

Where the audit call lives

The first question I had was where to put it. Middleware, so every request is
covered for free? Or one explicit line in each handler?

I tried middleware first, and it can't do the job alone. Middleware knows the
route and the request body. It doesn't know that POST /roles was "role
admin granted to user 42", it doesn't know what the row looked like before,
and it can't tell a no-op save from a real change. An audit line built from
middleware says what was called, not what happened.

So the design is three layers, and each one knows exactly one thing.

Middleware knows who. It reads the session or token (the reference below
just reads headers) and stamps the actor and the request id on the context.
That's all it does:

func WithActor(next http.Handler) http.Handler {
    return http.HandlerFunc(func(w http.ResponseWriter, r *http.Request) {
        ctx := r.Context()
        if uid := r.Header.Get("X-User-Id"); uid != "" {
            ctx = audit.WithActor(ctx, audit.User(uid))
        }
        // ... the tenant, the same way
        rid := r.Header.Get("X-Request-Id")
        if rid == "" {
            rid = newRequestID() // 16 random bytes, hex
        }
        w.Header().Set("X-Request-Id", rid)
        ctx = audit.WithRequestID(ctx, rid)
        next.ServeHTTP(w, r.WithContext(ctx))
    })
}

The handler knows what. One line, naming the action and the target. It
never names the actor, because the actor is already on the context:

func (h *Roles) Grant(w http.ResponseWriter, r *http.Request) {
    ctx := audit.Attach(r.Context(), audit.Entry{
        Action:  audit.RoleGranted,
        Subject: req.UserID,
        Target:  req.RoleID,
    })
    if err := h.Store.GrantRole(ctx, req.UserID, req.RoleID); err != nil {
        // ...
    }
}

The store knows when it's safe to write. That's the next part.

Same transaction: no line, no change

audit.Attach doesn't write anything. It puts the entry on the context and
returns. The storage layer picks it up when it commits, because every write in
the store goes through one wrapper:

func (s *Store) InTx(ctx context.Context, fn func(pgx.Tx) error) error {
    tx, err := s.pool.Begin(ctx)
    if err != nil {
        return err
    }
    defer tx.Rollback(ctx)
    if err := fn(tx); err != nil {
        return err
    }
    return s.commitWithAudit(ctx, tx)
}

And commitWithAudit is where the promise is kept. It writes the line inside
the open transaction, then commits. If the line can't be written, the change
is rolled back with it:

func (s *Store) commitWithAudit(ctx context.Context, tx pgx.Tx) error {
    p := audit.PendingFrom(ctx) // captured once: once taken, PendingFrom returns nil
    line, err := recordIn(ctx, tx, p)
    if err != nil {
        return err // rolls the change back: no line, no change
    }
    if err := tx.Commit(ctx); err != nil {
        if line != nil {
            p.Release()
        }
        return err
    }
    if line != nil {
        audit.Mirror(s.log, *line) // decision 8, further down
    }
    return nil
}

recordIn has one subtlety worth showing. The entry is attached early, before
the service runs, and a service might open a read-only transaction first (to
load the current state) before the one that writes. The line must land in the
writing transaction, not the reading one. Postgres can tell you whether the
current transaction has written anything. Reads of sensitive data have no
write to probe for, so an access entry is written on the first transaction
that carries it:

func recordIn(ctx context.Context, tx pgx.Tx, p *audit.Pending) (*audit.Line, error) {
    if p == nil {
        return nil, nil
    }
    var wrote bool
    if err := tx.QueryRow(ctx, `SELECT pg_current_xact_id_if_assigned() IS NOT NULL`).Scan(&wrote); err != nil {
        return nil, err
    }
    fam, _ := p.Entry.Action.Family()
    if (!wrote && fam != audit.Access) || !p.Take() { // not this tx, or already written once
        return nil, nil
    }
    line, err := audit.Resolve(ctx, p.Entry) // stamps actor, tenant, request id, time
    if err == nil {
        line.ID, err = insertLine(ctx, tx, line)
    }
    if err != nil {
        p.Release() // give the claim back
        return nil, err
    }
    return &line, nil
}

p.Take() is an atomic flag so the entry is written exactly once even if two
transactions under the same context both qualify. If the write fails, or the
commit after it fails, the claim is released, so a retry under the same
context still writes the line.

Different transaction: best-effort, and refuse the rest

For the five best-effort families, the handler calls Record instead of
Attach, after the change has committed:

func (h *Departments) Rename(w http.ResponseWriter, r *http.Request) {
    ctx := r.Context()
    before, err := h.Store.GetDepartment(ctx, req.ID)
    // ...
    after, err := h.Store.RenameDepartment(ctx, req.ID, req.Name)
    // ...
    if change := audit.Diff(before, after); change != nil {
        h.Audit.Record(ctx, audit.Entry{
            Action:   audit.DepartmentRenamed,
            Target:   req.ID,
            Metadata: change,
        })
    }
}

Record opens its own short transaction, inserts, and if that fails it logs a
warning with the action name and moves on. The handler doesn't check its
result, on purpose: there is nothing useful a handler can do about a lost
best-effort line. The read and the write are two separate transactions, so a
rename that lands in between can make before stale, and for best-effort
masterdata I accept that.

The one thing Record does strictly is refuse the transactional families:

func (s *Service) Record(ctx context.Context, e Entry) {
    ctx = context.WithoutCancel(ctx) // a client hanging up must not drop the line
    fam, ok := e.Action.Family()
    if !ok || fam.Transactional() {
        s.log.ErrorContext(ctx, "audit: programmer error: Record refused",
            "action", e.Action, "known", ok, "transactional", ok && fam.Transactional())
        return
    }
    line, err := Resolve(ctx, e)
    if err != nil {
        s.log.ErrorContext(ctx, "audit: programmer error", "action", e.Action, "err", err)
        return
    }
    if err := s.store.Insert(ctx, line); err != nil {
        s.log.WarnContext(ctx, "audit: line dropped", "action", e.Action, "err", err)
        return
    }
    Mirror(s.log, line)
}

So you can't write a role grant the lazy way by accident. If a handler calls
Record with an authority action, it's an error in the log, loud enough to
see, not a silent downgrade.

Retention: decided with the schema, not after

The family also answers how long a line lives. Most families are kept
forever; the volume is small because they record decisions, not traffic. The
access family (someone viewed someone else's file) is the exception. It's
the highest-volume family and the least interesting after a year, so it's the
only one a cleanup job may touch, and that job writes its own line in the same
transaction as the delete:

func (s *Store) PruneAccess(ctx context.Context, tenant string, days int) (int64, error) {
    if days < MinRetentionDays {
        return 0, ErrRetentionTooShort
    }
    ctx = audit.WithActor(ctx, audit.System("retention"))
    ctx = audit.WithTenant(ctx, tenant)
    var deleted int64
    var line audit.Line
    err := s.InTx(ctx, func(tx pgx.Tx) error {
        tag, err := tx.Exec(ctx, `DELETE FROM audit_log WHERE tenant_id = $1
               AND (family = $2 OR action = $3)
               AND created_at < now() - make_interval(days => $4)`,
            tenant, string(audit.Access), string(audit.LoginFailed), days)
        if err != nil || tag.RowsAffected() == 0 {
            return err
        }
        deleted = tag.RowsAffected()
        line, err = audit.Resolve(ctx, audit.Entry{Action: audit.Pruned, Metadata: map[string]any{"deleted": deleted}})
        // ... insertLine(ctx, tx, line): the line commits with the delete, or neither does
        return err
    })
    // ... on error return 0, err; otherwise audit.Mirror(s.log, line) and return deleted, nil
}

The retention window is a tenant setting with a floor, so a config change
can't quietly make it zero. I cut the insert and the mirror from the snippet;
they are the same two steps as in commitWithAudit, write inside the
transaction, mirror after the commit.

What was good, and what's still wrong

The payroll hole is closed, and it's closed by the database, not by me
remembering. The handler's job shrank to one line. And going through every
action to assign a family forced me to ask what each one was for, which is how
I found the ones I had never audited.

What's still wrong, honestly: the table says "append-only" in a comment and
nothing enforces it. There is no test that catches a new route with no audit
line. The request id lives in the log output but not in the table. I'll come
back to each of those below, because they're on the list.

The eight decisions

That's the story. This is the method. Each decision constrains the next, so
make them in this order.

1. What can fail

Per action, not per system, as shown above. Write the Transactional()
function first; everything else hangs off it.

2. Who did it

The actor comes from the auth context. The caller never passes it. Jobs are
system:<job-name>. A context nobody stamped is system:unattributed, never
NULL. Failed logins are anonymous:<ip>.

The test for this one is a grep. If any call to the audit writer passes an
actor id, version one is creeping back.

3. What the vocabulary is

A closed, typed list of actions in one file, each mapped to a family, and the
writer refuses anything not on it. That file is the design review: if you
can't name the action, you don't know what you're auditing.

4. What is stored

Updates store changed keys only, as {field: {before, after}}. Empty diff,
no line. Set changes store added and removed ids. Reads of sensitive data
store the field names, never the values, because the audit log must not become
a second copy of the thing it protects. No secrets, ever.

Decisions with a reason (an override, an approval, a forced submission) don't
go in metadata. They get their own append-only table with actor_id,
reason, and CHECK (reason <> ''). The audit log stores a pointer. A reason
is a business decision, not audit metadata, and the database should refuse the
decision without one.

5. Who can change the log

Nobody, and the database enforces it:

REVOKE UPDATE, DELETE ON audit_log FROM app_role;

My first two versions both have a comment in the migration saying
"append-only". Neither has the REVOKE. A comment is not a permission. It's one
migration, and I still owe it to the current project.

If your service connects as the table owner, REVOKE can't bind it. Use a
BEFORE UPDATE OR DELETE trigger that raises, with a SET LOCAL setting as
the escape hatch for the retention job.

6. How completeness is known

A test that walks every mutating route and fails unless it's audited or
explicitly listed as not audited, with a reason. auditOps maps a route name
to the action it writes; notAudited maps a route name to the reason it
writes nothing:

for _, r := range Mutating(routes) {
    if _, ok := auditOps[r.Name]; ok {
        continue
    }
    if _, ok := notAudited[r.Name]; !ok {
        t.Errorf("%s writes no audit line and is not in notAudited", r.Name)
    }
}

This would have caught the unused login constants in version one. A doc that
lists "the audited routes" drifts the week after you write it. A test doesn't.
The real test also fails the other way round, on a name in auditOps or
notAudited that no longer matches any route.

7. When it dies

Retention per family, written the same day as the table, with a floor the
config can't go under; the prune job is shown above. Estimate the volume
before you reach for partitioning. Mine came out small enough that
partitioning would have been complexity for nothing.

8. Where the second copy is

Every committed line also goes to stdout as one JSON log line, same struct as
the row. The container log driver keeps it outside the database. Edit the
table, and the two copies disagree. That is the only tamper-evidence a plain
Postgres table gives you, and it's cheap.

request_id is a column on the row and a field on the log line, so an audit
line can be joined to the access log and to application errors.

When not to do this

Not everything that records an event is an audit trail. A user activity
stream (tab switches, offline events, clicks that drive a feature) is high
volume, and losing a row is fine. It belongs in its own table, with its own
retention, and should never share the audit table's guarantees. Same for
one-row-per-request API logs. That's an access log, and it belongs in
structured logging, not a table nobody reads.

The transactional path costs one extra probe query per commit and turns an
audit failure into a 500. That's the right trade for a role grant. It's the
wrong trade for a high-volume event stream.

And this method gets you to tamper-evident, not tamper-proof. If a regulator
needs the second one, a Postgres table is not the answer. That's WORM storage
and a hash chain, and a different post.

What I learned

The audit log is the one table where "we'll add it later" is a lie, because
later is when you need the rows that don't exist. Decide what can fail before
you write the schema. Take the actor from the context so nobody can forge a
row. Make "append-only" a REVOKE, not a comment. Write the retention rule the
same day as the CREATE TABLE. And write the test that fails when someone adds
a route and forgets, because someone will, and that someone is usually me.

---

The checklist

If you build one, build this, in this order. I'm applying it to every project
I own, and it's written so I can paste it into a prompt and get the same
eight decisions back whether the project is Go or Laravel.

1. Every action belongs to a family. The family decides: same transaction or best-effort, and whether retention may ever delete it.
2. The actor comes from the auth context. The caller never passes it. Jobs are system:<name>, unknown is system:unattributed, never NULL.
3. Actions are a closed, typed list in one file. The writer refuses anything not on it.
4. Updates store changed keys only. Reads store field names, never values. Decisions with a reason get their own append-only table with a CHECK.
5. REVOKE UPDATE, DELETE on the audit table from the app role. A comment is not a permission.
6. A test that fails when a mutating route is neither audited nor explicitly listed as not audited.
7. Retention per family, written the same day as the table, with a floor.
8. Every line mirrored to stdout, with request_id on both the row and the log line.

Further reading:

• Postgres docs on pg_current_xact_id_if_assigned(), the probe that makes attaching the entry early safe.
• Row-level security in Postgres, if the audit table is multi-tenant.

One question, if you have an audit log in production: which of your audit
writes are allowed to fail, and did you decide that, or did it just happen?

Comments

[ANP2 Network]

p.Take() gives exactly-once inside a request context, which means the unit being deduplicated is the request, while the intent can still repeat. A client retrying a role grant after a timeout arrives on a fresh context, so the atomic flag never sees the first attempt, and because the middleware mints a new 16-byte id whenever X-Request-Id is absent, the two attempts are not joinable afterwards either. Two authority rows survive, in the one family retention may never delete, with nothing on either row separating "granted twice" from "asked twice".

pg_current_xact_id_if_assigned() IS NOT NULL answers whether the transaction acquired an xid, which is a different question from whether the state moved. The rename handler already encodes the stricter rule, since an empty audit.Diff writes no line at all. Attach has no equivalent, so re-granting a role that is already held can still leave a permanent authority row, and the family you cannot prune is the one collecting the no-ops. Carrying the empty-diff suppression into commitWithAudit would close that, with access exempt because a read has no before state to compare.

On the first one: would you accept deriving the identity of a line from action + subject + target + actor + an intent key supplied by the caller, under a unique constraint, so that repeated intent collides instead of appending?