Skip to content

Commit 0f3d3d3

Browse files
committed
fix(qwp): key poison-frame strikes on OK-level wire progress; pace NACK recycles
The poison-frame detector was dead in durable-ack mode: strikes were keyed on engine.ackedFsn()+1 and reset on ANY OK, but durable-mode OKs don't advance ackedFsn (trim waits for STATUS_DURABLE_ACK coverage). Every post-NACK recycle replays from the durable watermark, and the re-OKs of frames BEHIND the poisoned one laundered the strike count each cycle -- a deterministically-NACKing frame recycled the connection indefinitely, each cycle a full TCP+TLS+upgrade+window replay. Any terminal that did fire named ackedFsn+1: a frame the server had ACCEPTED at the OK level. Compounding it, connectLoop's backoff engages only after a FAILED connect attempt. A NACK against a healthy server reconnects instantly, so NACK-triggered recycles ran at server NACK rate with zero pacing (measured red: ~100k reconnects in 1.2s) -- design/qwp-nack-policy-v2.md promises capped backoff + jitter for RETRIABLE and the implementation didn't deliver it for this case. No data loss in any variant: bytes stay in SF. Fix: - Track highestOkFsn (OK-level acceptance, survives reconnects; runs ahead of durable trim). Strikes are keyed on the rejected frame's FSN (the NACK-named frame, or highestOkFsn+1 for a non-orderly close) and reset only on OK-level acceptance AT OR BEYOND the suspect -- replay re-OKs behind it no longer say anything about the poisoned bytes. - The poison terminal names the rejected frame; NACK-origin spans [fsn, fsn] (exact frame known), close-origin spans to publishedFsn. - RETRIABLE NACK recycles (post- and pre-send) go through failPaced: a deadline-looped park (immune to spurious wakeups / stale permits, responsive to close()) BEFORE the first connect attempt, sized initial-backoff x 2^(strikes-1) capped at max backoff, plus jitter. The escalation is the safety margin for transient same-frame rejections (e.g. sustained disk pressure), which now accumulate strikes in durable mode too: widening replay gaps give the condition time to clear before the threshold fires. RETRIABLE_OTHER stays immediate (rotation over backoff, byte 0x0C still reserved); transport failures keep the unpaced first attempt. Red-first: CursorWebSocketSendLoopPoisonFrameTest covers all four observables (detector fires despite replay re-OKs, terminal names the rejected FSN, close strikes key at the OK level, recycles paced against a healthy server). Doc updated -- its "Any ACK resets the counter" was the spec-level statement of the bug.
1 parent 64dd95b commit 0f3d3d3

4 files changed

Lines changed: 692 additions & 48 deletions

File tree

core/src/main/java/io/questdb/client/cutlass/qwp/client/sf/cursor/CursorWebSocketSendLoop.java

Lines changed: 152 additions & 40 deletions
Original file line numberDiff line numberDiff line change
@@ -259,17 +259,32 @@ public final class CursorWebSocketSendLoop implements QuietCloseable {
259259
// to -1 once trySendOne has caught up past it. Used to count replay
260260
// frames without a per-frame branch on the steady-state path.
261261
private long replayTargetFsn = -1L;
262-
// Poison-frame detector state (I/O thread only). poisonFsn is the head-of-line
263-
// FSN (ackedFsn+1) observed at the most recent server-active rejection (NACK,
264-
// or non-orderly close after at least one send on the connection);
265-
// poisonStrikes counts consecutive rejections at that same FSN with no ack
266-
// progress in between. Any ACK resets both. At maxHeadFrameRejections
267-
// strikes the frame is declared poisoned: the server (or an intermediary)
268-
// deterministically rejects these exact bytes, so replay cannot succeed and
269-
// the loop halts with a typed PROTOCOL_VIOLATION terminal instead of
270-
// reconnect-looping forever.
262+
// Poison-frame detector state (I/O thread only). poisonFsn is the FSN of the
263+
// frame implicated by the most recent server-active rejection: the NACK-named
264+
// frame, or the OK-level head-of-line frame (highestOkFsn+1) for a
265+
// non-orderly close after at least one send on the connection. poisonStrikes
266+
// counts consecutive rejections of that same FSN; an OK at-or-beyond
267+
// poisonFsn proves the rejection was not deterministic and resets both.
268+
// Progress is deliberately measured against highestOkFsn -- OK-level wire
269+
// progress -- and NOT against the engine's trim watermark: in durable-ack
270+
// mode ackedFsn advances only on STATUS_DURABLE_ACK coverage, so a
271+
// post-NACK recycle replays from the durable watermark and re-OKs frames
272+
// BEHIND the poisoned one; keying or resetting on trim would let those
273+
// re-OKs launder the strike count every cycle and a deterministically-
274+
// NACKing frame would recycle the connection forever. At
275+
// maxHeadFrameRejections strikes the frame is declared poisoned: the server
276+
// (or an intermediary) deterministically rejects these exact bytes, so
277+
// replay cannot succeed and the loop halts with a typed PROTOCOL_VIOLATION
278+
// terminal instead of reconnect-looping forever. Both fields deliberately
279+
// survive reconnects (swapClient) -- the detector spans connections.
271280
private long poisonFsn = -1L;
272281
private int poisonStrikes;
282+
// Highest FSN the server has acknowledged at the OK level (STATUS_OK),
283+
// across connections. In default mode this tracks the trim watermark
284+
// exactly; in durable-ack mode it runs AHEAD of ackedFsn, which waits for
285+
// STATUS_DURABLE_ACK coverage. I/O thread only; survives reconnects. Used
286+
// by the poison-frame detector to measure genuine acceptance progress.
287+
private long highestOkFsn = -1L;
273288
// Poison-frame detector threshold for this loop. Constructor-configured
274289
// (connect-string key max_frame_rejections); defaults to
275290
// DEFAULT_MAX_HEAD_FRAME_REJECTIONS.
@@ -972,7 +987,7 @@ private void applyDurableAck() {
972987
private void attemptInitialConnect() {
973988
connectLoop(new LineSenderException(
974989
"async initial connect deferred to I/O thread"),
975-
"initial connect");
990+
"initial connect", 0L);
976991
}
977992

978993
private void clearDurableAckTracking() {
@@ -995,8 +1010,10 @@ private void clearDurableAckTracking() {
9951010
* {@link #attemptInitialConnect()} for the async-initial-connect path
9961011
* (phase="initial connect"). The phase string only affects log lines
9971012
* and the {@link SenderError} message — control flow is identical.
1013+
* {@code paceFirstAttemptMillis} > 0 parks for that long (+jitter)
1014+
* before the first connect attempt — see {@link #failPaced}.
9981015
*/
999-
private void connectLoop(Throwable initial, String phase) {
1016+
private void connectLoop(Throwable initial, String phase, long paceFirstAttemptMillis) {
10001017
if (reconnectFactory == null || !running) {
10011018
recordFatal(initial);
10021019
return;
@@ -1016,6 +1033,22 @@ private void connectLoop(Throwable initial, String phase) {
10161033
// bounds only the blocking (non-lazy) initial connect in
10171034
// QwpWebSocketSender.buildAndConnect, never this background loop.
10181035
long backoffMillis = reconnectInitialBackoffMillis;
1036+
if (paceFirstAttemptMillis > 0 && running) {
1037+
// NACK-initiated recycle against a reachable server: pace the
1038+
// recycle with a backoff+jitter dose (sized by the caller --
1039+
// failPaced escalates it with consecutive same-frame strikes),
1040+
// or the recycle loop runs at server NACK rate. The dose is a
1041+
// hard pacing guarantee, so ride out spurious parkNanos returns
1042+
// and stale unpark permits with a deadline loop; close() flips
1043+
// running=false and unparks, exiting promptly.
1044+
long jitter = ThreadLocalRandom.current().nextLong(paceFirstAttemptMillis);
1045+
long deadlineNanos = System.nanoTime()
1046+
+ (paceFirstAttemptMillis + jitter) * 1_000_000L;
1047+
long remaining;
1048+
while (running && (remaining = deadlineNanos - System.nanoTime()) > 0) {
1049+
LockSupport.parkNanos(remaining);
1050+
}
1051+
}
10191052
int attempts = 0;
10201053
long lastLogNanos = 0L;
10211054
Throwable lastReconnectError = initial;
@@ -1212,37 +1245,48 @@ private void dispatchError(SenderError err) {
12121245

12131246
/**
12141247
* Poison-frame detector: record a server-active rejection (NACK, or non-orderly
1215-
* close after at least one send on this connection) at the current head-of-line
1216-
* frame. Returns true when the same head FSN has now been rejected
1248+
* close after at least one send on this connection) of {@code rejectedFsn} —
1249+
* the NACK-named frame, or the OK-level head-of-line frame for a close.
1250+
* Returns true when that same FSN has now been rejected
12171251
* {@code maxHeadFrameRejections} consecutive times (configurable; default
1218-
* {@link #DEFAULT_MAX_HEAD_FRAME_REJECTIONS}) with no ack progress in
1219-
* between — the frame is poisoned and replay is deterministic. I/O thread only.
1252+
* {@link #DEFAULT_MAX_HEAD_FRAME_REJECTIONS}) with no OK-level acceptance
1253+
* at or beyond it in between — the frame is poisoned and replay is
1254+
* deterministic. Strikes are keyed on the rejected frame itself, never on
1255+
* the engine's trim watermark: in durable-ack mode the trim watermark lags
1256+
* OK-level progress, and both the key and the reset must be immune to the
1257+
* replay re-OKs of frames behind the suspect. I/O thread only.
12201258
*/
1221-
private boolean recordHeadRejectionStrike() {
1222-
long head = engine.ackedFsn() + 1L;
1223-
if (head == poisonFsn) {
1259+
private boolean recordHeadRejectionStrike(long rejectedFsn) {
1260+
if (rejectedFsn == poisonFsn) {
12241261
poisonStrikes++;
12251262
} else {
1226-
poisonFsn = head;
1263+
poisonFsn = rejectedFsn;
12271264
poisonStrikes = 1;
12281265
}
12291266
return poisonStrikes >= maxHeadFrameRejections;
12301267
}
12311268

12321269
/**
12331270
* Escalate a poisoned frame to a typed terminal: the server (or an intermediary)
1234-
* has deterministically rejected the head-of-line frame
1235-
* {@code maxHeadFrameRejections} consecutive times with no ack progress, so
1271+
* has deterministically rejected the same frame {@code maxHeadFrameRejections}
1272+
* consecutive times with no OK-level acceptance at or beyond it, so
12361273
* replaying it cannot succeed and retrying would loop forever. recordFatal runs
12371274
* before dispatchError so the producer-observable terminal is latched before the
12381275
* user's handler is invoked. The rejected bytes remain in the SF log on disk —
12391276
* nothing is silently discarded.
12401277
*/
1241-
private void haltOnPoisonedFrame(String lastRejection) {
1242-
long fromFsn = engine.ackedFsn() + 1L;
1243-
long toFsn = Math.max(fromFsn, engine.publishedFsn());
1278+
private void haltOnPoisonedFrame(String lastRejection, long toFsnHint) {
1279+
// Name the frame the server actually rejected (the strike key), not
1280+
// ackedFsn+1: in durable-ack mode the trim watermark can sit on
1281+
// frames the server already ACCEPTED at the OK level, and pointing
1282+
// the operator at those bytes would misattribute the poison. The
1283+
// caller supplies the span end: a NACK names the exact frame, so the
1284+
// span is that single frame; a non-orderly close cannot single one
1285+
// out, so it spans to publishedFsn.
1286+
long fromFsn = poisonFsn;
1287+
long toFsn = Math.max(fromFsn, toFsnHint);
12441288
String msg = "frame at fsn=" + fromFsn + " rejected " + poisonStrikes
1245-
+ " consecutive times with no ack progress -- poisoned frame, replay cannot succeed (last: "
1289+
+ " consecutive times with no acceptance at or beyond it -- poisoned frame, replay cannot succeed (last: "
12461290
+ lastRejection + ')';
12471291
SenderError err = new SenderError(
12481292
SenderError.Category.PROTOCOL_VIOLATION,
@@ -1331,7 +1375,40 @@ private void enqueuePendingOk(long wireSeq) {
13311375
* (legacy behavior).
13321376
*/
13331377
private void fail(Throwable initial) {
1334-
connectLoop(initial, "reconnect");
1378+
connectLoop(initial, "reconnect", 0L);
1379+
}
1380+
1381+
/**
1382+
* Same recycle machinery as {@link #fail}, but parks for a backoff dose
1383+
* (+jitter) BEFORE the first connect attempt. Used for server-active
1384+
* RETRIABLE rejections (NACKs): the server is reachable — it just
1385+
* answered — so the first reconnect attempt will almost always succeed
1386+
* and connectLoop's failed-connect backoff never engages. This park is
1387+
* what delivers the "capped backoff + jitter" promise of
1388+
* design/qwp-nack-policy-v2.md for the RETRIABLE policy against a
1389+
* healthy server; transport failures keep the unpaced {@link #fail}
1390+
* (an immediate first reconnect attempt is desirable there).
1391+
* <p>
1392+
* The dose escalates with consecutive poison strikes against the same
1393+
* frame — initial backoff, doubling per strike, capped at the max
1394+
* backoff. Escalation matters beyond politeness: a TRANSIENT same-frame
1395+
* rejection (e.g. sustained disk pressure NACKing the head batch) now
1396+
* accumulates strikes toward the poison terminal even in durable-ack
1397+
* mode, and the widening gaps between replays are what give a transient
1398+
* condition time to clear before the threshold fires. A NACK sequence
1399+
* that IS making progress (different frame each time) resets strikes to
1400+
* 1 and keeps the dose at the initial backoff.
1401+
*/
1402+
private void failPaced(Throwable initial) {
1403+
long dose = reconnectInitialBackoffMillis;
1404+
if (dose > 0) {
1405+
int strikes = Math.max(poisonStrikes, 1);
1406+
dose <<= Math.min(strikes - 1, 6);
1407+
if (reconnectMaxBackoffMillis > 0 && dose > reconnectMaxBackoffMillis) {
1408+
dose = reconnectMaxBackoffMillis;
1409+
}
1410+
}
1411+
connectLoop(initial, "reconnect", dose);
13351412
}
13361413

13371414
/**
@@ -1786,10 +1863,23 @@ public void onBinaryMessage(long payloadPtr, int payloadLen) {
17861863
wireSeq, highestSent);
17871864
}
17881865
totalAcks.incrementAndGet();
1789-
// Any ACK on this connection means the server accepted the current
1790-
// head of the replay stream -- clear poison-frame suspicion.
1791-
poisonFsn = -1L;
1792-
poisonStrikes = 0;
1866+
long okFsn = fsnAtZero + capped;
1867+
if (okFsn > highestOkFsn) {
1868+
highestOkFsn = okFsn;
1869+
}
1870+
// Clear poison-frame suspicion only when OK-level progress
1871+
// reaches the suspected frame itself: acceptance at or beyond
1872+
// poisonFsn proves the earlier rejections were not
1873+
// deterministic. Re-OKs of frames BEHIND the suspect -- the
1874+
// norm in durable-ack mode, where every recycle replays from
1875+
// the durable trim watermark, which lags the OK level -- say
1876+
// nothing about the poisoned bytes and must not reset the
1877+
// count, or a deterministically-NACKing frame recycles the
1878+
// connection indefinitely.
1879+
if (poisonFsn != -1L && okFsn >= poisonFsn) {
1880+
poisonFsn = -1L;
1881+
poisonStrikes = 0;
1882+
}
17931883
if (durableAckMode) {
17941884
// Durable mode: stash the (wireSeq, table_seqTxns) tuple
17951885
// and wait for STATUS_DURABLE_ACK to release it. Empty
@@ -1848,9 +1938,11 @@ public void onClose(int code, String reason) {
18481938
// elsewhere, not a verdict on the bytes.
18491939
boolean orderly = code == WebSocketCloseCode.NORMAL_CLOSURE
18501940
|| code == WebSocketCloseCode.GOING_AWAY;
1851-
if (!orderly && nextWireSeq > 0 && recordHeadRejectionStrike()) {
1941+
if (!orderly && nextWireSeq > 0
1942+
&& recordHeadRejectionStrike(Math.max(engine.ackedFsn(), highestOkFsn) + 1L)) {
18521943
haltOnPoisonedFrame("ws-close[" + code + ' '
1853-
+ WebSocketCloseCode.describe(code) + "]: " + reason);
1944+
+ WebSocketCloseCode.describe(code) + "]: " + reason,
1945+
engine.publishedFsn());
18541946
return;
18551947
}
18561948
fail(new LineSenderException(
@@ -1896,11 +1988,18 @@ private void handlePreSendRejection(long wireSeq, byte status,
18961988
// so the rejection cannot implicate the head frame -- no poison
18971989
// strike. Surface for observability, then recycle the wire; the
18981990
// reconnect path replays from ackedFsn+1. No watermark advance --
1899-
// nothing is dropped.
1991+
// nothing is dropped. RETRIABLE is paced for the same reason as
1992+
// the post-send path: the server is reachable, so the recycle
1993+
// would otherwise run at its rejection rate.
19001994
dispatchError(err);
1901-
fail(new LineSenderException(
1995+
LineSenderException recycleCause = new LineSenderException(
19021996
"pre-send server rejection (" + category + "): "
1903-
+ response.getErrorMessage()));
1997+
+ response.getErrorMessage());
1998+
if (policy == SenderError.Policy.RETRIABLE) {
1999+
failPaced(recycleCause);
2000+
} else {
2001+
fail(recycleCause);
2002+
}
19042003
}
19052004

19062005
private void handleServerRejection(long wireSeq) {
@@ -1975,15 +2074,28 @@ private void handleServerRejection(long wireSeq) {
19752074
LOG.warn("server rejected wire seq {} (category={}, policy={}, status=0x{}) -- recycling connection, will replay from fsn {}",
19762075
wireSeq, category, policy, Integer.toHexString(status & 0xFF), engine.ackedFsn() + 1L);
19772076
dispatchError(err);
1978-
if (recordHeadRejectionStrike()) {
2077+
if (recordHeadRejectionStrike(fsn)) {
19792078
haltOnPoisonedFrame("server NACK status=0x"
1980-
+ Integer.toHexString(status & 0xFF) + " (" + category + "): "
1981-
+ response.getErrorMessage());
2079+
+ Integer.toHexString(status & 0xFF) + " (" + category + "): "
2080+
+ response.getErrorMessage(),
2081+
fsn);
19822082
return;
19832083
}
1984-
fail(new LineSenderException(
2084+
// RETRIABLE recycles are paced: the server is reachable and
2085+
// healthy (it just NACK'd a frame), so the reconnect will succeed
2086+
// immediately and connectLoop's failed-connect backoff never
2087+
// engages -- without pacing, a repeatedly-NACKing server drives
2088+
// full recycle cycles at its NACK rate. RETRIABLE_OTHER stays
2089+
// immediate: the node cannot serve writes at all, so rotating to
2090+
// another endpoint matters more than backing off.
2091+
LineSenderException recycleCause = new LineSenderException(
19852092
"server NACK (" + category + ", " + policy + "): "
1986-
+ response.getErrorMessage()));
2093+
+ response.getErrorMessage());
2094+
if (policy == SenderError.Policy.RETRIABLE) {
2095+
failPaced(recycleCause);
2096+
} else {
2097+
fail(recycleCause);
2098+
}
19872099
}
19882100
}
19892101
}

core/src/test/java/io/questdb/client/test/cutlass/qwp/client/sf/cursor/CursorWebSocketSendLoopJvmErrorTest.java

Lines changed: 2 additions & 2 deletions
Original file line numberDiff line numberDiff line change
@@ -86,10 +86,10 @@ public void testConnectLoopPropagatesJvmErrorAndLatchesTerminal() throws Excepti
8686
wireReconnectPlumbing(loop, attempts);
8787

8888
Method connectLoop = CursorWebSocketSendLoop.class.getDeclaredMethod(
89-
"connectLoop", Throwable.class, String.class);
89+
"connectLoop", Throwable.class, String.class, long.class);
9090
connectLoop.setAccessible(true);
9191
try {
92-
connectLoop.invoke(loop, new LineSenderException("initial wire failure"), "reconnect");
92+
connectLoop.invoke(loop, new LineSenderException("initial wire failure"), "reconnect", 0L);
9393
Assert.fail("a JVM Error must escape connectLoop, not be retried");
9494
} catch (InvocationTargetException ite) {
9595
Assert.assertTrue("expected LinkageError, got " + ite.getCause(),

0 commit comments

Comments
 (0)