PostgreSQLのnow()は同一tx内で同じ値、監査ログhash chainが誤検知した

結論

監査ログのhash chainは(occurred_at, id)昇順で連鎖させる設計だったが、occurred_atの既定値がnow()だったため、同一トランザクション内で書かれた複数の監査行が全く同じoccurred_atを持ってしまい、並び順のtie-breakが実質ランダムなid（uuid）で決まっていた。結果、挿入順と並び順がズレ、改竄が一件も起きていない正当な連鎖を検証関数が「改竄」と誤検知した。

• PostgreSQLのnow()（transaction_timestamp()の別名）はトランザクション開始時刻を返す。同一トランザクション内でどの文から呼んでも同じ値
• 1トランザクションで監査行を2行以上書く処理があると、その2行のoccurred_atは同一になる
• 連鎖の並び順は(occurred_at, id)昇順なので、occurred_atが同じ行同士はid（gen_random_uuid()）の大小で並ぶ。これは挿入順と無関係
• occurred_atの既定をclock_timestamp()（呼ばれた瞬間の実時刻）に変えることで、同一トランザクション内でも文ごとに値が進み、並び順が挿入順と一致するようにした

症状

監査ログテーブルaudit_logは、改竄検知のためのhash chainを持つ。各行は直前行のrow_hashをprev_hashとして保持し、row_hashはそれ自身を含むpayloadのSHA-256で計算される。「直前行」が何を指すかは(occurred_at, id)昇順で決める設計になっていた。

occurred_atカラムの既定値は次のようになっていた。

occurredAt: timestamp("occurred_at", { withTimezone: true, mode: "date" })
  .notNull()
  .default(sql`now()`),

PostgreSQLのnow()はtransaction_timestamp()の別名で、トランザクションが開始した時刻を返す。同じトランザクションの中でnow()を何度呼んでも、値は変わらない。

通常のINSERT（1トランザクションにつき監査行1つ）であれば、各トランザクションの開始時刻は異なるため問題にならない。ところが「コンテンツの再公開」のように、1つのトランザクションの中で複数の監査行を書く処理がある。旧公開を無効化したことを記録する監査行と、新公開を記録する監査行の2つを、同じトランザクションでまとめて書くような操作だ。

この2行はoccurred_atが完全に同一になる。連鎖の並び順を決める(occurred_at, id)の比較では、occurred_atが同値なので次にidで比較される。idはgen_random_uuid()で生成されるランダムな値のため、2行のうちどちらが先に並ぶかは挿入順と無関係に決まる。

挿入時のトリガは「直前行」として(occurred_at, id)順で見た直前の行からrow_hashを引いてprev_hashに詰める。だが実際に先に挿入されたのがどちらかはoccurred_atだけでは分からないため、トリガが選ぶ「直前行」と、検証関数audit_log_verify_chain()が走査で期待する「直前行」がズレることがある。改竄が一件も起きていないにもかかわらず、検証関数は連鎖の不整合（改竄の疑い）を報告していた。

原因

設計時点での前提は「1トランザクション＝1監査行」だった。その前提のもとではoccurred_atにnow()を使うのは自然な選択で、トランザクションの開始時刻がそのまま一意なタイムスタンプになる。

しかし実際のアプリケーションコードには、1トランザクションで2行以上の監査行を書く経路が存在した。この経路自体は「関連する2つの操作をまとめて記録する」という意味で正当であり、禁止すべきものではない。問題はタイムスタンプ関数の選び方が「1トランザクション1行」という前提にだけ最適化されていて、「1トランザクション複数行」のケースで並び順の一意性を保証できなくなる点に誰も気づいていなかったことだ。

now()とclock_timestamp()はどちらも「現在時刻を返す関数」という説明だけを見ると区別がつきにくい。違いはトランザクション内で何度呼んでも値が変わらないか、呼ぶたびに進むかという一点に尽きる。hash chainのように「挿入順を一意なタイムスタンプで表現したい」用途では、この違いが並び順の正しさを直接左右する。

直す

occurred_atの既定値をnow()からclock_timestamp()に変更した。

occurredAt: timestamp("occurred_at", { withTimezone: true, mode: "date" })
  .notNull()
  .default(sql`clock_timestamp()`),

migrationは次の1行だけ。

ALTER TABLE "audit_log" ALTER COLUMN "occurred_at" SET DEFAULT clock_timestamp();

clock_timestamp()は呼ばれた瞬間の実際の時刻を返すため、同一トランザクション内で複数回評価されても、評価された文ごとに値が進む。同じトランザクションで2行の監査行をINSERTしても、2つのoccurred_atは（マイクロ秒単位の差であっても）distinctになり、(occurred_at, id)昇順の並びが挿入順と一致するようになる。

このmigrationは既存行には影響しない。変更したのはカラムの**既定値（DEFAULT）**だけで、カラムの型や制約は変わらないため、PostgreSQLはテーブル書き換え（table rewrite）を行わない。既存行のoccurred_atはそのままで、以後に新しく挿入される行だけが新しい既定値を使う。

再発しにくい形

now()（transaction_timestamp()）とclock_timestamp()は、どちらも「現在時刻」という説明だけでは区別がつかない。1トランザクションで複数回評価される可能性があるカラムの既定値を選ぶときは、この2つのどちらで実装されているかを明示的に確認する必要がある。

とくに「挿入順を一意なタイムスタンプで表現する」目的でタイムスタンプを使う場合、前提にしている粒度（トランザクション単位か、文単位か）とアプリケーション側の実際の書き込み方（1トランザクション1行か、複数行か）が一致しているかを、設計時点で突き合わせておく必要がある。今回のケースでは、この前提のズレはテスト（describe.skipで守られたaudit_log: hash chain integrity）の対象にすら入っていなかった。「複数行を同一トランザクションで書くケース」を明示的にテストに加えたことで、同種の問題が再発しても検知できる形になった。