Onur Kesim

Posted on Aug 11

Your Test Went Red. Can You Read It?

#postgres #testing #sql #debugging

Thesis: A gate being green is not enough. When it turns red, it must be readable—and the guard that makes it readable must stand where it cannot disappear.

To test my assertion, I deleted SKIP LOCKED from an outbox claiming query in my side project's sync layer, leaving a plain FOR UPDATE.

The test turned red in about six seconds, throwing an exception with a distinct Postgres error code: 55P03 (lock_not_available). The gate bit me immediately. But it only bit because of a single decision I had made earlier: setting -c lock_timeout=5000 directly in the database connection string.

My repository code (OutboxClaimStore.cs) had a client timeout of 10 seconds configured (CommandTimeout = 10; Npgsql's default is 30). Had lock_timeout been missing, removing SKIP LOCKED wouldn't have hung the runner forever, but it would have hit that 10-second client cutoff. Npgsql would not have handed me a lock error either. On command timeout it sends a real Postgres CancelRequest on a side connection; the server aborts the statement with 57014 query_canceled — and Npgsql then throws that PostgresException away, replacing it with NpgsqlException: Exception while reading from stream, inner TimeoutException: Timeout during reading attempt. Even the code it did get would only have said "somebody cancelled me," never "I was waiting for a row lock."

By enforcing lock_timeout at the database level, Postgres explicitly told me why it stopped: SQLSTATE 55P03 (lock_not_available).

This is the story of that setting and why where you put your guards determines whether you actually have them.

Unless stated otherwise, every timing in this article comes from a single scripted run against PostgreSQL 16.13 (Ubuntu) on 5 August 2026. Configuration values such as CommandTimeout and lock_timeout are quoted from the source file rather than measured, and the mutant-8 result comes from a separate dotnet test run the same day, whose runtime versions I did not record.

§1 — The Same Session Proves Nothing

If two dispatcher instances share a single database session, testing a SKIP LOCKED clause measures nothing.

In my outbox implementation, OutboxClaimStore opens a separate NpgsqlConnection per call — and because the test holds a third connection open across the pump, the pool is forced to hand out a genuinely different backend session. The comment in OutboxClaimStore.cs records why the dispatcher never shares a session:

"a session always 'sees' its own uncommitted locks"

To demonstrate this, I ran experiment M1, executing a lease-based UPDATE query twice in a row within a single session (reassembled from the repro script's output):

           run           |            claimed
-------------------------+-------------------------------
 A1  SKIP LOCKED present | 1,2,3,4,5,6,7,8,9,10
 A2  SKIP LOCKED present | 11,12,13,14,15,16,17,18,19,20
 B1  SKIP LOCKED REMOVED | 1,2,3,4,5,6,7,8,9,10
 B2  SKIP LOCKED REMOVED | 11,12,13,14,15,16,17,18,19,20

A1 matched B1, and A2 matched B2. Deleting SKIP LOCKED inside a single session changed absolutely nothing.

The mechanism here is worth clarifying: the reason sequential calls in a single session return distinct items isn't strictly that the session sees its own locks. Rather, the claim query bumps attempts and — more to the point — pushes available_at into the future. The candidate filter is available_at <= @now, so it is that second write, not the lock, that removes the row from the next query's candidate pool.

If you test your outbox claiming queries inside a single session, your test suite will remain green even if concurrent locking is completely broken.

§2 — An Anonymous Timeout Is Not an Error

Removing SKIP LOCKED breaks concurrency logic, and your test should fail. But how it fails dictates whether you can diagnose the issue.

Without a configured database timeout, Postgres waits for a locked row until the holding transaction ends. The test hangs until an external shell script terminates it (all runs below: PostgreSQL 16.13, measured 5 August 2026):

M3 exit_code=124  (124 = killed by the ceiling)  wall_ms=8014

Exit code 124 came from the Linux shell timeout command, not Npgsql or Postgres. The database emitted no logs and no SQLSTATE. The value 8,014 ms is not an execution measurement—it is an artificial ceiling enforced by the shell script.

Relying on a client-side timeout (CommandTimeout = 10; Npgsql defaults to 30) cuts the wait at ten seconds, but what surfaces is a stream-read timeout, not a lock error.

With lock_timeout set to 5 s for that session in test run M4, the failure mode changes entirely:

ERROR:  canceling statement due to lock timeout
M4 exit_code=1  elapsed_ms=5044

A separate run (M6) with VERBOSE error reporting confirms the code:

ERROR:  55P03: canceling statement due to lock timeout

Comparing these runs highlights the key differences:

M2 vs M3: With SKIP LOCKED present (M2), the whole psql invocation — process start, connect, query, exit — took 42 ms in that run. Without it (M3), the query blocked until the shell ceiling cut it off at 8,014 ms.
M3 vs M4: In M3, the shell script killed the process silently at 8 seconds. In M4, with a session-level lock_timeout of 5 s, Postgres aborted the statement at 5,044 ms and raised 55P03. M7, below, is the run that separates a session SET from a startup option.

In my mutation-test log for mutant-8 (where SKIP LOCKED was dropped, leaving a plain FOR UPDATE), Npgsql threw 55P03 out of OutboxClaimStore.ClaimAsync; PumpOnceAsync propagated it instead of swallowing it, so the test died on a named exception at the first pump — six seconds in, with the 120-second hang detector never firing.

Two things worth pinning down:

Row order matters: Lock contention surfaces when locked rows sit at the head of the ORDER BY clause. If enough unlocked candidate rows precede the locked ones to satisfy the query's LIMIT, Postgres fills the limit and returns without blocking.
Why the setting belongs in the connection string: with -c lock_timeout=5000, a worker opening a connection with that string aborts within 5 seconds of hitting row contention instead of holding its connection open indefinitely. That is a real trade-off, not a free win — if your workload would rather wait than fail, scope the guard to your test data source.

A fair question at this point: why not FOR UPDATE NOWAIT? I did not measure it — the repro script never runs it — so everything I say about it here is definitional rather than measured: NOWAIT reports the same 55P03 condition without waiting at all, and needs no GUC and no placement rule to get wrong, while lock_timeout bounds how long the wait may last. Whether that bound is worth having depends on a consumer I did not test here. What I did measure is that one setting produced the readable failure.

§3 — The Guard That Vanishes in Silence

The critical question is not just whether to set lock_timeout, but where to set it.

If you configure lock_timeout inside your application using a session-level statement (SET lock_timeout = '5s'), you are placing your guard on mutable session state. A pooled connection is typically handed back after a reset such as DISCARD ALL or RESET ALL, so the next check-out starts clean.

In Postgres, RESET ALL restores every session GUC to its default value, and the docs define that precisely: "the value that the parameter would have had, if no SET had ever been issued for it in the current session." The sources it can come from are listed explicitly — a compiled-in default, postgresql.conf, command-line options, or per-database/per-user settings. That list is the whole trick: a SET is not on it, and a startup option is.

In Postgres, a lock_timeout value of 0 does not mean zero milliseconds. It means disabled (wait indefinitely).

When you pass -c lock_timeout=5000 as a connection string option (Npgsql writes the startup packet itself and puts this in the same options startup parameter libpq would send), that setting becomes the session's startup value. When the pooler issues RESET ALL, Postgres resets lock_timeout back to 5000.

To measure the direct effect of DISCARD ALL on session GUCs versus startup options, I ran experiment M7 on PostgreSQL 16.13 (Ubuntu 16.13-0ubuntu0.24.04.1). Both runs use psql — one with a session SET, one with PGOPTIONS — and the table below is reassembled from four separate SHOW lock_timeout outputs, not copied from one terminal:

-- (a) Guard set via a session-level SET statement:
 lock_timeout before DISCARD ALL | lock_timeout after DISCARD ALL
---------------------------------+---------------------------------
 5s                              | 0

-- (b) Guard supplied as a startup option (PGOPTIONS='-c lock_timeout=5000'):
 lock_timeout before DISCARD ALL | lock_timeout after DISCARD ALL
---------------------------------+---------------------------------
 5s                              | 5s

When set via SET, the guard vanished on connection reset. When supplied as a connection startup option, it survived.

A session-level guard disappears without throwing an error or printing a warning. Your readable 55P03 error silently degrades back into a hanging query.

One alternative deserves naming: SET LOCAL lock_timeout = '5s' at the start of the claim transaction. It dies with the transaction, so a pool reset cannot pull it out from under you either. It costs a statement per transaction and has to be remembered at every call site; the connection string costs nothing and cannot be forgotten.

A practical testing note: When verifying this with psql, running psql -c "...; DISCARD ALL; ..." failed with ERROR: DISCARD ALL cannot run inside a transaction block. This occurs because a multi-statement string in a single -c is sent as one request, and the server runs it as one implicit transaction. Separate -c flags are separate requests, so DISCARD ALL gets a transaction of its own.

Boundary condition: This experiment measures the behavior of Postgres session reset commands (DISCARD ALL / RESET ALL). How external connection proxies operating in transaction or statement pooling modes (such as PgBouncer) handle client startup options depends on proxy configuration, which is a separate operational layer.

§4 — Two Kinds of Silent Zero

When a claiming query returns zero rows, that zero can indicate two different things: either there is no work to do, or a configuration defect is hiding your data.

This trap was designed out of the project before it could bite. The initial database migration (migration_20260718_InitialSync.cs) defined a default value on the outbox table:

defaultValueSql: "now()"

The dispatcher runs against a frozen, simulated test clock, while now() generates timestamps from the database server's own clock. A row born that way sits "in the future" relative to the dispatcher's fake clock, so the filter available_at <= @now is false and the query returns zero rows.

The next migration removed that default, and its comment records why:

"available_at's DB default was now() … a row born under the DB clock while the dispatcher runs under a test's fake clock would never satisfy available_at <= @now, so the default must go."
— migration_20260719_DispatcherIndexes.cs

To visualize how this failure manifests, consider schematic model M5 (schematic — reproduced by the repro script, not captured from a failing run):

      reader_clock      | unsent_rows | claimable_rows
------------------------+-------------+----------------
 2026-08-05 18:00:00+03 |          25 |              0

There are 25 unsent records in the outbox, but the dispatcher reads 0 claimable items.

No exception is raised, and no SQLSTATE is generated. Downstream test assertions fail when expecting processed records, making it look like the message consumer failed when the actual issue was an upstream time mismatch.

§5 — The Rules

If you rely on SQL locking or queue claiming, keep two rules in mind:

Make your red tests readable. Do not rely on generic client command timeouts or shell execution ceilings to catch blocked queries. Use database-level lock_timeout settings so lock contention fails with explicit SQLSTATE codes like 55P03. One ordering constraint makes or breaks this: lock_timeout must sit strictly below your client cutoff. Npgsql's CommandTimeout defaults to 30 seconds, so a 30-second lock_timeout is a coin flip and a larger one is dead code.
Put your guards where they cannot disappear. Session-level SET commands can be wiped out when connection pools issue RESET ALL or DISCARD ALL. Configure your session safeguards as startup connection options (-c lock_timeout=5000) so they survive connection recycling.

(A third rule applies: if you delete the query clause you are testing and your test suite stays green, you do not have a test. But verifying test validity by breaking queries is a topic for another time.)

A gate that fails illegibly is a gate you will disable the first time it goes red on a Friday.