unknown action of type <char> exception-replay crash still reproducible on main (possible regression/incomplete fix of #40)

[mrayva]

Summary

unknown action of type <char> crashes are still reproducible on current main (reports as Spock 6.0.0), under spock.exception_behaviour = transdiscard (the default), when an update_missing conflict occurs (one node deletes a row while the other concurrently updates it). This looks like the same failure reported in #40, which a maintainer said was resolved in 5.0.0 via #42's replay-queue rewrite (ApplyReplayContext / apply_replay_queue_*) — but I can reproduce the identical symptom against that current implementation.

Reproduction

Two-node bidirectional Spock cluster (reproduced against an OrioleDB table; see note on heap tables below). With both subscriptions active, fire a genuinely concurrent UPDATE (node1) / DELETE (node2) on the same row:

-- node1
UPDATE items SET name='updated-by-node1' WHERE id=700;
-- node2, committed close enough in time to race node1's replicated change
DELETE FROM items WHERE id=700;

Observed apply-worker log on the node receiving the now-missing row's UPDATE:

LOG:  spock_apply_heap_update() retried 5 times
LOG:  SPOCK: caught initial exception - logical replication did not find row to be updated in replication target relation (public.items)
LOG:  SPOCK sub_x_y: error during exception handling: SPOCK sub_x_y: unknown action of type o
LOG:  SPOCK sub_x_y: exiting to allow worker restart
ERROR:  SPOCK sub_x_y: unknown action of type o
CONTEXT:  apply (unknown action) in commit before 0/1D650DE, xid 64 committed at ... (action #2) from node replorigin ...
LOG:  apply worker [...] exiting with error

The garbage action byte is not stable across runs — I observed both 'o' (0x6F) and 'B' (0x42, which is otherwise a valid action letter — BEGIN) in different runs, which points at reading stale/reused memory in the replay path rather than a fixed off-by-one. After the worker restarts and reprocesses the same LSN, it takes a different branch entirely and discards the transaction outright:

LOG:  SPOCK sub_x_y: Transaction discarded in TRANSDISCARD mode at LSN ... Initial error: logical replication did not find row to be updated ...

— i.e. the UPDATE is never applied on that node, and the two nodes are left permanently diverged for that row (the "losing" node keeps its own local delete instead of picking up the winning node's update).

Note on OrioleDB vs. heap tables

I could reliably reproduce this against an OrioleDB table, but the identical test against a plain heap-table Spock cluster (same topology, same conflict pattern) did not crash — it went straight to a clean Transaction discarded in TRANSDISCARD mode. The one consistent difference in the logs is that the OrioleDB run always shows spock_apply_heap_update() retried 5 times (i.e. FindReplTupleInLocalRel()'s wait_for_previous_transaction() retry loop runs to exhaustion before concluding the row is genuinely missing) immediately before the crash, whereas the heap-table run has no such retry line. My working hypothesis is that OrioleDB's slower/different local-tuple-visibility characteristics widen a narrow, pre-existing race in the replay-queue lifecycle (around ApplyReplayContext / apply_replay_queue_reset() / the transition into use_try_block replay via goto stream_replay) that's rarely hit against heap tables' near-instant missing-row detection. I have not fully root-caused the race itself — I looked at apply_replay_queue_append_entry() / apply_replay_queue_next_entry() / apply_replay_queue_start_replay() without finding an obvious bug in isolation, so the corruption is likely coming from a memory-context lifetime issue (MemoryContextReset(MessageContext) / MemoryContextReset(ApplyOperationContext) around the "caught initial exception" handling in apply_work(), or ApplyReplayContext being reset while still referenced) rather than the append/read logic itself.

Why I think this is worth a fresh look rather than assuming #40 covers it

• Replication failing to delete a non existing row #40's fix (Queue stream messages to replay on exception #42) replaced tearing-down-and-reconnecting-the-replication-connection with an in-memory (or spilled-to-disk) replay queue specifically to avoid this class of bug.
• This reproduction is against main, well after that fix landed, using the same exception_behaviour=transdiscard / update_missing scenario as Replication failing to delete a non existing row #40.
• It's timing-sensitive (needs a real retry loop to manifest reliably in my testing), which would explain why it might not show up in fast unit/TAP tests against heap tables even if the underlying race is general-purpose and not OrioleDB-specific in principle.

Environment

• Spock built from main (reports as version 6.0.0)
• PostgreSQL 18.6
• Reproduced with OrioleDB tables (orioledb.so + spock.so both in shared_preload_libraries); not reproduced (in limited testing) against heap tables under the same scenario
• spock.exception_behaviour = transdiscard (default)

Related

• Replication failing to delete a non existing row #40 — same unknown action + update_missing/transdiscard symptom, on Spock 4.0.10, said to be resolved in 5.0.0.
• Queue stream messages to replay on exception #42 — the replay-queue rewrite that resolved Replication failing to delete a non existing row #40; this report reproduces the same symptom against that implementation.
• SUB_DISABLE can skip a retransmitted transaction after provider disconnect #520 — a different bug in the same exception-marker/replay-state subsystem (stale commit_lsn marker after a connection-class failure), fixed after 5.0.10.
• exception log claims "discarded" for operations that replayed OK #535 — still-open, same subsystem: exception log misleadingly reports "discarded" for operations that in fact replayed and applied successfully.

I don't have a fix for this one — happy to help narrow it down further (e.g. with a debug build and gdb) if that'd be useful, but wanted to get it filed with what I have so far.

[mrayva]

Update: crash reproduction attempts, and a clarification on scope

I spent more time trying to pin down the exact corruption (per my offer above), and want to share what I found — it refines the picture somewhat.

Reproduction of the crash itself: much harder than it first looked

I tried to catch this with gdb first (conditional breakpoint on the action-dispatch switch, both live-attach and a debug build with -O0 -g), then rebuilt with AddressSanitizer to catch the corruption at the write site instead of the read site. Across roughly 140 additional trigger attempts, spanning:

• ASan (-fsanitize=address -O1)
• ASan with quarantine_size_mb=0 (to make the allocator behave closer to native malloc/free timing)
• Plain -O1, no sanitizer
• Plain -O2, no sanitizer — i.e. matching the exact build that reproduced the crash reliably earlier
• A full clean restart of both nodes
• Artificial CPU contention (20 busy-loop processes pinning all cores, to widen scheduling jitter)

the unknown action of type <char> crash did not reproduce even once. This is despite it reproducing on essentially every attempt in my original testing a few hours earlier, on what should be equivalent code and build flags. My best honest read is that whatever narrow timing condition let it fire originally depended on some transient state (accumulated WAL position, a specific worker-generation count, or similar) that I haven't been able to reconstruct, rather than something a sanitizer or CPU load could reliably re-expose. I don't have a root cause, and at this point I don't think further sanitizer/gdb attempts are a good use of time without a fundamentally different approach (e.g. instrumenting the suspect memory regions directly with canary values, or a long unattended fuzzing run).

The divergence itself is independent of the crash, and reproduces 100% of the time

This is the more useful finding. While chasing the crash, I ran the same concurrent UPDATE(node1)/DELETE(node2) scenario dozens more times without it ever crashing, and in every single one the transaction was still silently discarded via TRANSDISCARD, and the two nodes still ended up diverged (node1 keeps its update, node2 keeps its delete). So the crash was never the cause of the divergence — they're two separate things that happen to be triggerable by the same scenario:

• The divergence happens because transdiscard mode unconditionally discards any update_missing transaction rather than attempting any timestamp/tiebreak resolution against it — this looks like it may be closer to an inherent design tradeoff of that mode (avoid a crash-loop, accept a lost transaction) than a pure bug, similar in spirit to what Replication failing to delete a non existing row #40 originally described before the mode existed.
• The crash (unknown action of type <char>, corrupted/varying garbage byte) is a genuinely separate defect in the replay path, but is apparently much rarer/more timing-sensitive than it first appeared, and I no longer have a reliable repro for it.

Given that, this issue is probably better read as two things rather than one: (1) whether transdiscard unconditionally favoring "whoever deleted the row" for update_missing conflicts (rather than a timestamp/tiebreak decision, the way update_update/insert_exists already do) is intended behavior or worth revisiting, and (2) the crash itself, which I'd flag as lower-confidence/lower-priority now given I can no longer reproduce it on demand — happy to have this issue stay open for (1) even if (2) can't be pinned down further from my side.

[mrayva]

Update: found a 100%-reliable reproduction, and a concrete lead on the root cause

Following up on my earlier comment (which said the crash had become hard to reproduce even under ASan) — I found the missing ingredient, and used it to get much further on the actual root cause.

The missing ingredient: the exception-replay queue has to spill to disk

Every reproduction attempt I'd tried before used small, single-row transactions — nowhere near spock.exception_replay_queue_size (default 4MB). Once a transaction is large enough to actually spill to disk, hitting an update_missing conflict during it crashes the apply worker with unknown action of type <char> every single time (reproduced independently multiple times, 100% hit rate).

Reproduction recipe (3-node vanilla PG18 + Spock cluster, no OrioleDB involved):

1. Lower spock.exception_replay_queue_size to force spilling quickly (e.g. 1MB).
2. Fully isolate one node (disable all its subscriptions, both directions) so a local write on it doesn't propagate anywhere.
3. Delete one row on the isolated node.
4. On a different node (which still has that row), run one large single-statement UPDATE touching tens of thousands of rows, including the deleted one (60,000 rows was plenty to spill and trigger it every time).
5. Re-enable only the isolated node's inbound subscription from the node that ran the UPDATE, forcing it to replay that large transaction fresh.
6. The apply worker crashes with unknown action of type <char> immediately after spock_apply_heap_update() retried 5 times → caught initial exception → replay queue start: ... spill file=active (spill_count=N).

Root cause: this is a read bug, not a write bug — evidence attached

I injected a temporary raise(SIGSTOP) right where the garbage action byte gets read (gated so it only fires on the exact corruption condition — normal replay traffic passes through untouched), which let me freeze the apply worker at the exact moment of corruption and attach gdb without racing timing.

The crash happens on the very first read from the spill file (spill_read=0). At that exact paused moment, I read the raw spill file bytes directly off disk via /proc/<pid>/fd/<N> — bypassing Spock/Postgres entirely. The on-disk data at offset 0 is completely correct: valid 4-byte length prefix (74), the expected 'w' tag, real LSNs, and a readable row payload ("row14309-updated"). But apply_replay_spill_read_entry()'s BufFileRead() call returned a different length (len=600) with garbage content that looks like leftover text from the replication connection's START_REPLICATION handshake negotiation (readable substrings like max_proto_version). That bogus length doesn't correspond to any real entry boundary elsewhere in the file either — I checked by scanning for a matching length-prefix.

Since the on-disk bytes are provably correct and what comes back from the read call is provably wrong, the bug has to be in the read path, not the write path. The most likely spot: apply_replay_queue_start_replay() calls BufFileSeek(apply_replay_spill_file, 0, 0, SEEK_SET) to rewind the file before replaying, and the very next BufFileRead() (inside apply_replay_spill_read_entry()) appears to return stale, previously-buffered content rather than genuinely re-reading from the sought position — consistent with a buffer-invalidation gap around that seek, specific to this write-then-seek-then-read usage pattern on an interXact temp BufFile. I didn't trace all the way into buffile.c to confirm the exact internal mechanism, but the evidence above should make that tractable for someone with more context on BufFile's internals than I have.

Summary for whoever picks this up

• Reliable repro recipe above — should turn this from "can't pin down" into a quick confirm.
• Look at apply_replay_queue_start_replay()'s BufFileSeek() call and the first BufFileRead() in apply_replay_spill_read_entry() right after it.
• The bug is in the read side of the spill mechanism, not the write side — confirmed by comparing actual on-disk bytes against what the read call returned, at the exact moment of failure.

Happy to share the exact patch I used for the temporary debug instrumentation if useful for reproducing this on your end.

[mrayva]

Correction to my previous comment — the BufFileSeek lead was wrong (or at least the wrong layer)

I want to walk back the root-cause claim in my last comment here. I pushed further and the evidence now points somewhere else entirely.

What I did

Added source-level checkpoint logging (not just gdb spot-checks this time) at three points in the exception-replay lifecycle in spock_apply.c:

1. apply_replay_entry_create() — right when the buffer is first wrapped into a queue entry, straight from PQgetCopyData().
2. apply_replay_queue_start_replay() returning — right after the exception is caught and replay is about to begin.
3. apply_replay_queue_next_entry() returning the head entry — right before it's handed to replication_handler().

At each point I logged the first 4 bytes of the buffer and the specific byte at offset 33 (the actual action-byte position for this message — the byte that later reads as garbage).

I also tried gdb hardware watchpoints on the corrupted byte's address four separate times (different reproduction runs, verified correct addresses each time via print). None of them ever fired, despite the corruption reliably happening in every un-watched control run of the same scenario. I now believe hardware watchpoints simply don't function in the sandboxed environment I'm working in (likely restricted ptrace/debug-register passthrough) — worth knowing if anyone else tries to reproduce this with gdb watch and gets the same non-result; it doesn't mean the memory isn't being touched, the tooling just isn't seeing it.

What the checkpoint logging showed

The byte at offset 33 is already wrong at checkpoint 1 — i.e. at the moment apply_replay_entry_create() first receives the buffer from PQgetCopyData(), before any Spock replay-queue code (in-memory list, spill file, BufFileSeek, anything) has touched it.

Why this matters

This means the bug is not in Spock's exception-replay memory management, which is what my previous comment (and the BufFileSeek/spill-file hypothesis) pointed at. The wrong byte is present in the raw data as delivered by libpq's PQgetCopyData(), on the very first read. That points at:

• what the provider's walsender / spock_output plugin actually put on the wire for this message, or
• something in libpq's copy-data delivery / buffering.

Both are a different part of the codebase than spock_apply.c's replay queue, and outside what I was able to dig into this round.

Where this leaves things

• The reproduction recipe from my earlier comment (large spilling transaction + update_missing conflict) still reliably reproduces the crash — that part holds up.
• The specific mechanism I proposed (BufFileSeek returning stale buffered content) does not hold up — the corruption predates that code path entirely.
• I don't have a further root cause to offer beyond "look at what's sent for this message on the provider side / how libpq delivers it" — that's genuinely a different investigation (walsender/output-plugin/libpq territory) that I haven't done.

Sorry for the churn — wanted to correct this before it sent anyone down the wrong path. Happy to help narrow the wire-protocol side further if useful, just wanted to get the correction out first.

[mrayva]

Root cause found and fixed — this supersedes both of my previous comments here

Sorry for the churn on this thread — the BufFileSeek lead and its correction were both off-track. Kept digging (this time with a shared-memory ring buffer capturing the raw wire bytes at both ingestion (PQgetCopyData()) and replay (apply_replay_queue_next_entry()) time, tagged with a correlating id so the same message's bytes could be diffed at both points) and this time got a definitive answer.

Root cause

apply_replay_head/apply_replay_tail (the exception-replay queue) is only ever cleared in handle_commit(). The one-time 'S' STARTUP message sent at connection setup flows through the exact same queue_append path as transactional messages, so it becomes the head of that list the instant it's received — before any transaction has even begun. Neither handle_begin() nor handle_startup() ever clears it.

If the very first transaction a freshly-connected worker processes hits an exception requiring replay, apply_replay_queue_start_replay() sets apply_replay_next = apply_replay_head — which is still that stale STARTUP entry, not the transaction's own BEGIN.

Replaying it hits a second, compounding issue: the generic per-message pre-processing in apply_work()'s main loop decides whether to consume an 8-byte remote_insert_lsn field based on the currently negotiated protocol version (spock_apply_get_proto_version() >= 5). The STARTUP message's wire format deliberately never includes that field — see the comment on write_startup_message() in spock_proto_native.c: version negotiation hasn't happened yet when STARTUP is first sent/parsed. But by the time the stale entry gets replayed, the version has already been negotiated to 5 (STARTUP's own job), so that check now wrongly fires and consumes 8 bytes that aren't there — shifting every subsequent read 8 bytes into the STARTUP message's own parameter text. "max_proto_version" is always the first parameter sent, so the misaligned read lands on the same character every time: 'o' — matching the crash signature in every report on this issue.

Confirmed directly, not just by code reading: the entry returned by apply_replay_queue_next_entry() at the moment of the crash was byte-for-byte identical to that worker's own STARTUP message from earlier in the same connection — not corrupted data, the wrong message.

This also explains why the crash looked like a flaky race for so long (including my own ~140 failed ASan repro attempts mentioned upthread): it isn't one. It's a deterministic bug gated on exactly one precondition — the exception-triggering transaction is the first one this connection processes. Anything that shifted timing enough to let some other transaction go first (and reset the queue via a normal commit) made the bug disappear, mimicking a race without being one. That's also why the 100%-reliable repro I posted earlier works: it deliberately isolates a node then reconnects it right before the failing transaction, guaranteeing that transaction is the first one replayed.

The fix

A deferred-reset flag (apply_replay_queue_reset_pending), set at the end of handle_startup() once negotiation completes, consumed in the main loop right after replication_handler() returns and any need_free bookkeeping for that message is done — never inside handle_startup() itself, since resetting there would free the entry's buffer while the caller's msg/entry still alias it for the rest of that loop iteration. This guarantees the replay queue is provably empty before any real transaction begins.

Validation

Reproduced the crash 3/3 times with the isolate-then-reconnect recipe from my earlier comment. With the fix: 2/2 clean runs (exception caught, replay completed, transaction discarded via TRANSDISCARD, no crash) — including one run against a fully clean production build with zero debug instrumentation. Also ran a full regression pass (hard-crash recovery, extended-outage/WAL-retention, 3-node network partition, bulk transaction, no-PK-table replica-identity checks) with no behavior change to normal replication.

Fix branch

https://github.com/mrayva/spock/tree/fix/exception-replay-stale-startup-message — single commit, full detail in the commit message. Happy to open a PR against main if that's useful, or if maintainers would rather take the fix a different way given the code's likely evolved since I started digging into this.