Async daemon can advance projection progress past committed events during concurrent appends

[gschuager]

I found this while working on a bulk import feature for my application. During the import, I noticed that an async projection could report as caught up even though some committed events had not been projected.

I used an agent to help isolate the behavior into a smaller reproduction. My current understanding is that this can happen when concurrent appends reserve event sequence numbers ahead of rows becoming visible in mt_events. The async daemon can load a page with a high-water/page ceiling that crosses one of those temporarily invisible events. If the event commits after the page query but before progression is recorded, projection progress may advance past that seq_id, causing the event to be silently skipped.

The regression test is intended to model that race by delaying one event insert while allowing later events to commit, then checking that the daemon/page loader does not advance past the missing committed event.

I split the work into two commits in my fork at https://github.com/gschuager/marten/tree/projection-skip:

• the first commit adds the reproduction/regression coverage
• the second commit contains the agent-proposed fix

I do not fully understand all the implications of the proposed solution, but I validated it against my application’s bulk import scenario and it did resolve the projection skip I was seeing. I’m sharing it as a starting point and would be happy to help however I can with further investigation or refinement.

Expected Behavior

If projection progress advances to sequence N, every matching committed event with seq_id <= N should have either been projected, explicitly skipped/dead-lettered, or covered by a recorded high-water skip.

Actual Behavior

Under concurrent append/import load, the daemon can advance projection progress past a matching committed event that was not included in the loaded page, causing that event to be missed by the async projection.

BTW, I also worked on a similar issue in https://github.com/Eventuous/eventuous and ended up adding some gap handling timeouts there Eventuous/eventuous#424

[jeremydmiller]

@gschuager Before I even think about doing anything about this, have you:

1. Simply paused the async daemon which you can do at will
2. Used Marten's own bulk insert functionality for events instead of trying to roll your own
3. Used QuickAppend to avoid having really any gaps in the sequence
4. Just upped the timeout on stale async daemon high water detection

And I wouldn't think that Marten's model is similar enough to Eventuous + KurrentDb to really apply, but I could be wrong.

And lastly, what version of Marten?

[jeremydmiller]

Yeah, use this: https://martendb.io/events/bulk-appending.html#bulk-appending-events. Not willing to look at this until you try our official event importing:)

[gschuager]

Thank you.

I don’t want to pause the async daemon for this use case because this is part of normal application behavior: users should be able to import people from a CSV file while the application is running.

Let me explain the real use case in a simplified way. People are event-sourced aggregates in my application. They can be created or updated normally through the app, and those events trigger eligibility evaluation logic via Wolverine event subscriptions. When a person is evaluated as eligible, new aggregates/streams may be created.

I want the import procedure to reuse that same application logic rather than having a separate path that generates a different set of events for bulk insertion. Also, unless I’m misunderstanding the API, Marten’s event bulk append feature does not seem intended for appending events to existing streams, which I need for updates during the import.

It was while working through this import scenario that I found the behavior described above.

My plan is to eventually batch the import once I have everything working correctly, but I’m hesitant to move forward while it seems possible for some events to not be projected at all without any warning or notification ... that can lead to incorrect information being shown to users, and potentially to new incorrect events being appended based on stale/incorrect read-side state.

To answer the other questions:

• I’m already using Quick append mode.
• I also tried setting opts.Projections.StaleSequenceThreshold = 10.Minutes(), which is much longer than the whole import process takes, but I still see the issue.
• I tested this with Marten 9.15.2.
• In my fork, the reproduction is on top of current master: https://github.com/gschuager/marten/tree/projection-skip

[jeremydmiller]

@gschuager You're using the tool very differently than anyone else has before. Feel very free to engage us at sales@jasperfx.net for formal support or consulting to work through what is a very unusual usage nobody else has tried before.

[jeremydmiller]

Opened #4964 to track the page-loader / observability half of this separately.

Confirmed deterministically (advisory-lock + pg_sleep trigger to hold one event row invisible while later events commit): EventLoader.LoadAsync returns a partial page whose ceiling advances to the high-water mark over the committed-but-invisible event (persisted=12, projected=11, missing=[9], page.ceiling=12), for both Rich and QuickWithServerTimestamps. The culprit is EventPage.CalculateCeiling jumping a short page straight to highWaterMark.

Notably this skip is silent — it records nothing in mt_high_water_skips, sets no is_skipped, emits no daemon.skipping metric, and writes no log line. The only skip that is logged/tracked today is the deliberate stale-gap DetectInSafeZone skip. #4964 captures the confirmed page-loader behavior, the observability gap, and the open design questions (conservative partial-page ceiling vs. high-water gap-safety under the detect-then-load race). Repro adapted from your projection-skip branch.

[gschuager]

Hey Jeremy, thanks for looking into this.
I wanted to let you know that I just tested version 9.16.0 and I still see events being silently skipped in projections, both in my real app and in the repro branch using the trigger (I rebased it and left out GapDetector changes).
If it is useful, I can look into isolating the issue without using the trigger technique, but for sure it will involve hammering the event store with load.

[jeremydmiller]

Sorry I didn't get back to you. Yes, I confirmed that the event skipping happened in your case and that the logging was skipped in your very particular case. It's an edge case (very heavy load and slow transactions at the very beginning of an event store sequence) that nobody has ever run across or noticed before.

Regardless, I think your focus needs to shift to finding ways to segment the work to speed up transactions, or increase the buffer time.

And I'm going to very strongly recommend you do more with integration testing to be able to drive this issue outside of manual UI testing.

And both of those are things that JasperFx can help our clients do.

And regardless, this would of course be much easier for me to address if we had your actual system and preferably a load testing harness that did your file import as a way to reproduce and know when it's actually fixed.

[gschuager]

I understand your advice, and for sure we’ll invest in those topics.

Meanwhile, I’d like to better understand whether the advisory-lock + pg_sleep test is a valid one, and whether Marten is expected to pass that test, or at least fail visibly instead of silently skipping an event.

Since #4964/#4972 confirmed part of the issue, I expected 9.16.0 to resolve what I’m seeing. But it didn’t in my app, and it also didn’t in the repro branch, so I’m wondering if I may be testing this incorrectly, if #4972 fixed only one part of the issue, or if my expectation of the guarantee is wrong.

Also, I wanted to clarify that in my application tests I didn’t see any long-lasting transactions, only around 200ms max. What I do see is continuous concurrent load. The trigger-based test holds one insert longer only to make that visibility-gap race deterministic.

[gschuager]

I just saw your last comment ... I will try to reproduce the silent skip in isolation without the advisory-lock + pg_sleep technique.

[jeremydmiller]

And there's going to be a 9.16.1 later today with more steps to address this issue, this time digging into more postgres internals to observe the presence of ongoing transactions

[jeremydmiller]

Root cause: how a gap-crossing high-water mark reaches the loader silently

The page loader (EventPage.CalculateCeiling) never exceeds the high-water mark it is handed — on a partial page it advances to it. So for a silent skip to happen, the high-water mark itself must already cross a committed-but-invisible event, and it must get there through the Normal detection path (which records nothing), not the SafeZone/stale skip (which writes mt_high_water_skips and logs). Tracing HighWaterDetector.findCurrentMark → GapDetector, there is a blind spot that does exactly this.

GapDetector query (per Start = SafeStartMark):

-- (1) first interior gap at/after Start
select seq_id
from (select seq_id, lead(seq_id) over (order by seq_id) as no
      from mt_events where seq_id >= :start) ct
where no is not null and no - seq_id > 1
LIMIT 1;
-- (2) fallback when (1) finds nothing
select max(seq_id) from mt_events where seq_id >= :start;

Query (1) only compares consecutive visible rows, and lead(last row) = NULL is dropped by where no is not null. So it can only see a gap that sits between two visible rows.

Case A — start event present, interior gap (the reproduction's data): committed [1..8, 10, 11, 12], seq 9 invisible, Start = 8 (or 0).

• window >= 8 = [8,10,11,12]; lead(8)=10, 10-8=2>1 → returns 8. Correct — holds before the gap. This is why the real daemon does not skip on the repro's own data, and why the isolated loader test had to feed max(seq_id) directly.

Case B — start lands in/just below a gap, first visible rows internally contiguous (the silent skip): committed above start = [10, 11, 12] while 9 (and the row at Start itself) are missing/invisible, Start = 8.

• window >= 8 = [10,11,12]; lead(10)=11 (d=1), lead(11)=12 (d=1), lead(12)=NULL (excluded) → query (1) returns nothing → fallback (2) max = 12.
• GapDetector returns 12, crossing the invisible event 9. calculateHighWaterMark sees HasChanged and takes the Normal branch → MarkHighWaterMarkInDatabaseAsync(12): no mt_high_water_skips row, no is_skipped, no daemon.skipping metric, no log line. The projection then loads a partial page over (floor, 12] (9 still not returned), and CalculateCeiling sets the ceiling to the high water 12, sealing the skip. Completely silent.

How Start (SafeStartMark) ends up inside a gap — two plausible routes, both real under concurrent-append / import load:

1. The stale-gap safe-zone advance parks the mark on a boundary that need not be an actual event: DetectInSafeZone can set SafeStartMark = CurrentMark = HighestSequence - 32 (the Make the "high water detection" robust for SEQUENCE hiccups #3865 "-32" guard). If that boundary falls in a hole, the next Normal detection starts its window inside the gap.
2. Rolled-back appends leave permanent mt_events_sequence holes (a nextval with no committed row), so seq_id >= Start can begin at a value above Start + 1.

This matches the fix on gschuager/marten@projection-skip: the GapDetector change adds select min(seq_id) from mt_events where seq_id > :start and if (firstVisible > Start + 1) return Start; — i.e., detect the leading gap that query (1)'s consecutive-visible-rows logic cannot, and hold at Start instead of falling back to max. The EventLoader change adds a second, defense-in-depth guard (tryApplyUnrecordedGapCeilingAsync / containsNewlyVisibleMatchingEventsAsync) so a partial page will not advance its ceiling over an unrecorded gap or a newly-visible in-range event even if a gap-crossing mark still reaches it.

Takeaways for where to fix:

• High-water gap-safety (Marten): close the GapDetector leading-gap/trailing-NULL blind spot so the Normal mark never crosses an invisible event.
• Defense in depth (JasperFx.Events): on a partial page, CalculateCeiling should not blindly leap to the high-water mark over a range it did not fully load (tension: a legitimately-short final page must still reach the high water, so a naive cap would stall the tail).
• Observability: any progression advance that jumps an unloaded in-range sequence should leave a trace (log / mt_high_water_skips / metric) even when believed safe — today only the deliberate SafeZone skip is recorded, so this class of skip is invisible in the field.

[jeremydmiller]

Follow-up: full audit of every path that can cross an outstanding sequence — 4 confirmed mechanisms on 9.16.0

@gschuager you're right, and thank you for pushing back with the 9.16.0 re-test. I went back through the whole high-water detection surface hunting specifically for ways the mark can advance over a sequence number that is reserved by a still-running transaction ("outstanding" — will commit later, unlike a rolled-back hole). There are four distinct mechanisms, and I reproduced all four deterministically against 9.16.0 (open-transaction holds + statement-boundary widening, no load-dependent flakiness).

1. GapDetector per-statement snapshot skew — Normal path, silent, threshold-independent. The detector's command is three statements in one batch: leading-gap probe, interior-gap window query, max(seq_id) fallback. Under READ COMMITTED each statement takes its own snapshot, so commits landing between statements defeat the gap checks. Two proven flavors: (a) when detection Start sits on a hole and the probe's snapshot sees nothing above it, the #4964 hold never engages (it requires a non-null probe); rows committing before the interior query then look contiguous and the fallback crosses the still-open sequence. (b) With Start on a real row and an empty tail, rows committing between the interior query and the max() statement do the same. The real-world window is the millisecond-scale statement execution time, retried at every 250ms poll — under import-level commit rates this fires. This is the mechanism that doesn't care about StaleSequenceThreshold at all, and my best explanation for what you're still seeing with the 10-minute setting. Fix: collapse to a single statement (single snapshot) — cheap, Marten-only.

2. CheckNowAsync → DetectInSafeZone with zero staleness gating. Projection rebuilds, PrepareForRebuildsAsync, and daemon catch-up all invoke the safe-zone (skipping) detection unconditionally, and loop until the mark reaches the reserved sequence last_value. Verified: with seq 9 held open and 10–12 committed, Detect() correctly holds at 8, but DetectInSafeZone marks 12 — so any rebuild or forced catch-up while an import is running mows through in-flight gaps by design.

3. The stale fallback teleports into pure reservations. When the mark is stale and nothing above it is committed yet, detection jumps to HighestSequence - 32 where HighestSequence is the reserved last_value — and the gate for that branch measures staleness against mt_event_progression.last_updated, which on an idle store is hours old, so it passes instantly. Verified: idle-for-an-hour store + 5,000 reserved-but-uncommitted sequence numbers → mark teleports from 8 to 4,977 across nothing but in-flight reservations. The only log line on that route is the misleading "was not able to determine a safe harbor sequence, will try again soon". This is the "no activity → sudden crush with slow first transactions" cold-start scenario in its purest form.

4. The deliberate stale skip can't tell "slow" from "rolled back". The 3s-default threshold skip is wall-clock only; at cold start the mark pins at 0 on the first in-flight event, and the skip then lands past every outstanding sequence below the first visible gap edge. Your trigger repro's daemon-level test races exactly this (2s hold vs. the 3s threshold).

The interesting part: Postgres can prove a gap dead — no wall-clock guessing needed

An in-flight append holds a granted RowExclusiveLock on mt_events in pg_locks (fully visible to all roles, no redaction — verified), and open write transactions are enumerable via pg_snapshot_xip(pg_current_snapshot()) (no privileges needed) plus pg_stat_activity.xact_start (full detail same-role or with pg_read_all_stats). So instead of "skip after N seconds", detection can hold while there is evidence a reserver may still be alive, and treat a gap as permanently dead only when no candidate transaction from before the gap was first observed remains — which also means genuinely dead holes (rollbacks) can be skipped without waiting out an arbitrary threshold.

Plan

Reproductions first — the four scenarios above are being turned into permanent Bug_4953_* regressions — then, in order: (1) single-snapshot GapDetector (closes mechanism 1), (2) in-flight-evidence gating before any safe-zone skip, with the stale gate keyed off when the gap was first observed rather than last_updated, plus Warning-level logging + mt_high_water_skips for every crossing advance (closes 3 and 4), (3) catch-up/rebuild loops re-targeted to committed height instead of reserved last_value (closes 2, lands in JasperFx.Events), (4) same treatment for the per-tenant path.

Your instinct in the fork was right — the GapDetector/loader area was the right neighborhood; the leading-gap fix in 9.16.0 closed the static case but not the snapshot-skew or safe-zone routes. I'll follow up here as the fixes land.

[jeremydmiller]

Fixes are up: PR #4977 + JasperFx.Events 2.29.1

Following up on the four mechanisms above — the full fix set is now in review as #4977, with the daemon-coordination half already published in JasperFx.Events 2.29.1. What changed, mechanism by mechanism:

1. Snapshot skew (the silent, threshold-independent one): GapDetector and the statistics reading are now each a single SQL statement, so the leading-gap probe, interior-gap check, and max(seq_id) fallback always see one consistent snapshot. The mid-command race that let the Normal path leap an in-flight sequence is structurally impossible now.
2. Rebuild/catch-up skipping: CheckNowAsync no longer loops the skipping detection toward the reserved sequence last_value — it targets the highest committed sequence (new detector contract in 2.29.1, Marten supplies max(seq_id)), so a rebuild or forced catch-up during your import now waits for in-flight appends to land instead of mowing past them.
3. • 4. Stale skipping now requires proof of death, not a wall clock. Before any gap skip, detection checks PostgreSQL itself for evidence that a transaction which could still fill the gap is alive — write locks on mt_events held by transactions from before the gap was first observed (pg_locks), open transactions from before that observation (pg_stat_activity), and in-progress write transaction ids from the snapshot recorded at observation (pg_current_snapshot). Any evidence ⇒ the daemon holds: a slow append gets waited out, no matter how long it takes — by default Marten will now never knowingly skip past a live appender. Only a gap with no possible living reserver (i.e. the appends genuinely rolled back) is skipped, after the stale threshold measured from when that specific gap was first seen — and every skip now logs its exact sequence range at Warning, so nothing in this area is silent anymore. The old HighestSequence - 32 teleport is gone from this path entirely.

For your import scenario specifically: the trigger-style reproduction (first event of the store held in-flight while later events commit) is now a permanent regression test in the daemon suite, both as a detector-level test and end-to-end — daemon running, rebuild during the in-flight append — and both require every committed event to be projected with zero skips.

Two knobs, should you ever want different trade-offs: Projections.UseTransactionEvidenceForGapSkipping = false restores the previous wall-clock behavior, and Projections.SkipStaleGapsDespiteLiveTransactionsAfter can cap the hold if you'd rather guarantee projection progress over waiting out a leaked idle-in-transaction session (we recommend PostgreSQL's own idle_in_transaction_session_timeout as the backstop instead).

This will ship in the next Marten release once #4977 lands. I'd appreciate you re-running both your repro branch and the real bulk-import flow against it when it's out.

[jeremydmiller]

Marten 9.16.1 is out with the full fix set described above: https://github.com/JasperFx/marten/releases/tag/V9.16.1 (on nuget.org now, alongside JasperFx.Events 2.29.1).

@gschuager when you get a chance, please re-run both your projection-skip repro branch (the trigger technique) and your real bulk-import flow against 9.16.1 — with the transaction-evidence gating on by default, the daemon should now hold for your in-flight appends rather than skipping them, and any skip that ever does happen (genuinely rolled-back appends only) will be logged at Warning with its exact sequence range. If you still see a missing event after this, that's something new and I want to know about it here.

[gschuager]

I just ran the tests in my fork against 9.16.1, as well as my real bulk-import use case a couple of times, and I can confirm that both completed successfully with no missing projected events.

Thank you very much for looking into this and for the quick turnaround.

[jeremydmiller]

Good deal. Thanks for letting me know!