Skip to content

Commit f38de3a

Browse files
LEGLINK-186: Stop stamping a retry due-time on dead-lettered records
The backoff timestamp is a due-time the -Retry listener waits on, so it is a promise that the record will be delivered again. It was stamped before the routing decision was known, so every dead letter carried one - a delivery that was never scheduled. Poison landed on -Error advertising a retry ~20s in the future that nothing would ever perform. Stamping is now split by what each header means: attempts history - how many times the record ran. Stamped unconditionally, survives onto the dead letter. backoff-timestamp a promise - stamped only when the decision is RETRY. The remove() before the conditional is load-bearing. An exhausted record arrives carrying the due-time from its previous retry hop, so declining to stamp a new one is not enough; the stale one has to be cleared or it rides onto the DLT looking current. No routing or timing change: the due-time is computed identically for the RETRY case, and the other three decisions never used it. Nothing reads these headers off -Error today - the DLT listener was suppressed earlier in this branch - which is why this was invisible. It matters for the dead-letter replay capability we want: replay tooling reading -Error would otherwise find attempts=1 and a pending due-time on records that are finished. Renamed RetryTopicRecovererLoggingTest -> RetryTopicRecovererDecisionTest; it now covers the topic, the log line and the headers, i.e. everything derived from the Decision. Five header tests added, three of which failed before this change. The two that already passed guard the other direction: a retried record must still carry a future due-time, and a dead letter must still record its attempt count. Tests: shared 12, measureeval 130, validation 153, 0 failures. Verified live on a rebuilt image, EvaluationRequested ladder: 18:26:54.091 Retry attempt 1/4 [EvaluationRequested] 18:27:14.095 Retry attempt 2/4 [EvaluationRequested-Retry] +20.004s 18:28:14.098 Retry attempt 3/4 [EvaluationRequested-Retry] +60.003s 18:30:14.101 Max retry attempts (4) reached. Routing to DLT +120.003s Every interval within 4ms of PT20S/PT60S/PT120S, matching the runs from before this change. That final hop is the case this fix targets: the record had genuinely retried three times, so it arrived carrying the due-time its previous hop stamped, and that stale value had to be cleared rather than merely not re-stamped. Claude-Session: https://claude.ai/code/session_01AZubeEYCKfAmDCcgVTr18G
1 parent 62857e1 commit f38de3a

2 files changed

Lines changed: 102 additions & 16 deletions

File tree

Java/measureeval/src/test/java/com/lantanagroup/link/measureeval/configs/RetryTopicRecovererLoggingTest.java renamed to Java/measureeval/src/test/java/com/lantanagroup/link/measureeval/configs/RetryTopicRecovererDecisionTest.java

Lines changed: 87 additions & 12 deletions
Original file line numberDiff line numberDiff line change
@@ -12,6 +12,7 @@
1212
import org.apache.kafka.clients.producer.ProducerRecord;
1313
import org.apache.kafka.common.Node;
1414
import org.apache.kafka.common.PartitionInfo;
15+
import org.apache.kafka.common.header.Header;
1516
import org.junit.jupiter.api.AfterEach;
1617
import org.junit.jupiter.api.BeforeEach;
1718
import org.junit.jupiter.api.Test;
@@ -20,6 +21,7 @@
2021
import org.springframework.kafka.core.KafkaTemplate;
2122
import org.springframework.kafka.retrytopic.RetryTopicHeaders;
2223

24+
import java.math.BigInteger;
2325
import java.nio.ByteBuffer;
2426
import java.time.Duration;
2527
import java.util.Collections;
@@ -32,18 +34,18 @@
3234
import static org.mockito.Mockito.*;
3335

3436
/**
35-
* The recoverer's log line must describe what actually happened to the record.
37+
* Everything the recoverer derives from its routing decision — the topic, the log line, and the retry
38+
* headers — must agree with each other.
3639
*
37-
* <p>{@link RetryTopicRecoverer} emits the log, but the destination is chosen by the resolver built in
38-
* {@link RetryTopicRecovererFactory}, which considers three reasons to dead-letter: retries disabled,
39-
* poison exception, attempts exhausted. A log derived from only one of those three reports a retry that
40-
* never happens for the other two — the record is already on {@code -Error} while the log says
41-
* "Retry attempt 1/N", and no dead-letter line is ever emitted.</p>
40+
* <p>{@link RetryTopicRecoverer} emits the log and stamps the headers, but the destination is chosen by
41+
* the resolver built in {@link RetryTopicRecovererFactory}, which considers three reasons to
42+
* dead-letter: retries disabled, poison exception, attempts exhausted. Anything derived from only one of
43+
* those three describes a retry that never happens for the other two.</p>
4244
*
43-
* <p>These tests drive the real production wiring and assert the log against the topic the record was
44-
* actually published to, so the two can never drift apart again.</p>
45+
* <p>These tests drive the real production wiring and assert the log and the published headers against
46+
* the topic the record actually went to, so the three can never drift apart again.</p>
4547
*/
46-
class RetryTopicRecovererLoggingTest {
48+
class RetryTopicRecovererDecisionTest {
4749

4850
private static final String RETRY_TOPIC = "ResourcesNormalized-Retry";
4951
private static final String ERROR_TOPIC = "ResourcesNormalized-Error";
@@ -69,11 +71,19 @@ void detachAppender() {
6971
recovererLogger.setLevel(originalLevel);
7072
}
7173

72-
/** What the recoverer did with a record: where it went, and what it said about it. */
73-
private record Outcome(String topic, ILoggingEvent log) {
74+
/** What the recoverer did with a record: what it published, and what it said about it. */
75+
private record Outcome(ProducerRecord<Object, Object> published, ILoggingEvent log) {
76+
String topic() {
77+
return published.topic();
78+
}
79+
7480
String message() {
7581
return log.getFormattedMessage();
7682
}
83+
84+
Header header(String name) {
85+
return published.headers().lastHeader(name);
86+
}
7787
}
7888

7989
private static ConsumerRecord<String, String> record() {
@@ -116,7 +126,7 @@ private Outcome run(KafkaRetryConfig config, ConsumerRecord<String, String> reco
116126

117127
assertEquals(1, appender.list.size(),
118128
"recoverer must emit exactly one log line per failure, got: " + appender.list);
119-
return new Outcome(captor.getValue().topic(), appender.list.get(0));
129+
return new Outcome(captor.getValue(), appender.list.get(0));
120130
}
121131

122132
@Test
@@ -163,4 +173,69 @@ void transientFailure_withAttemptsRemaining_isLoggedAsARetry() {
163173
assertTrue(outcome.message().contains("Retry attempt"),
164174
"record was retried but not logged as a retry: " + outcome.message());
165175
}
176+
177+
// ---- Backoff-timestamp header. It is a due-time: "do not deliver before this instant", read by the
178+
// backoff-aware -Retry listener. A record going to -Error will never be delivered again, so a
179+
// due-time on it describes a retry that was never scheduled. Nothing reads it there today, which
180+
// is exactly why it is worth pinning: dead-letter replay tooling would find headers implying a
181+
// pending retry on records that are finished.
182+
183+
@Test
184+
void retriedRecord_carriesBackoffDueTime() {
185+
Outcome outcome = run(retryConfig(3, false), record(), new RuntimeException("transient boom"));
186+
187+
assertEquals(RETRY_TOPIC, outcome.topic(), "precondition: transient failure must route to -Retry");
188+
Header backoff = outcome.header(RetryTopicHeaders.DEFAULT_HEADER_BACKOFF_TIMESTAMP);
189+
assertNotNull(backoff, "a record that will be retried must carry the due-time the listener waits on");
190+
assertTrue(new BigInteger(backoff.value()).longValue() >= System.currentTimeMillis() - 1_000L,
191+
"due-time must be in the future, not a stale instant");
192+
}
193+
194+
@Test
195+
void poisonRecord_carriesNoBackoffDueTime() {
196+
Outcome outcome = run(retryConfig(3, false), record(), new ValidationException("Query Type is null."));
197+
198+
assertEquals(ERROR_TOPIC, outcome.topic(), "precondition: poison must route to -Error");
199+
assertNull(outcome.header(RetryTopicHeaders.DEFAULT_HEADER_BACKOFF_TIMESTAMP),
200+
"a dead-lettered record must not advertise a due-time for a retry that will never happen");
201+
}
202+
203+
@Test
204+
void exhaustedRecord_carriesNoBackoffDueTime() {
205+
ConsumerRecord<String, String> record = record();
206+
stampAttempts(record, 2);
207+
208+
Outcome outcome = run(retryConfig(3, false), record, new RuntimeException("still failing"));
209+
210+
assertEquals(ERROR_TOPIC, outcome.topic(), "precondition: exhausted attempts must route to -Error");
211+
assertNull(outcome.header(RetryTopicHeaders.DEFAULT_HEADER_BACKOFF_TIMESTAMP),
212+
"a dead-lettered record must not advertise a due-time for a retry that will never happen");
213+
}
214+
215+
@Test
216+
void exhaustedRecord_dropsTheDueTimeLeftByItsPreviousRetry() {
217+
// The realistic path: this record retried before, so it arrives carrying the due-time stamped on
218+
// the last hop. Not stamping a new one is not enough — the stale one must be cleared.
219+
ConsumerRecord<String, String> record = record();
220+
stampAttempts(record, 2);
221+
record.headers().add(RetryTopicHeaders.DEFAULT_HEADER_BACKOFF_TIMESTAMP,
222+
BigInteger.valueOf(System.currentTimeMillis() + 60_000L).toByteArray());
223+
224+
Outcome outcome = run(retryConfig(3, false), record, new RuntimeException("still failing"));
225+
226+
assertEquals(ERROR_TOPIC, outcome.topic(), "precondition: exhausted attempts must route to -Error");
227+
assertNull(outcome.header(RetryTopicHeaders.DEFAULT_HEADER_BACKOFF_TIMESTAMP),
228+
"the due-time from the previous retry must be removed, not carried onto the dead letter");
229+
}
230+
231+
@Test
232+
void deadLetteredRecord_stillRecordsHowManyAttemptsItGot() {
233+
// attempts is history, not a promise — it stays, so a dead letter says how many times it ran.
234+
Outcome outcome = run(retryConfig(3, false), record(), new ValidationException("Query Type is null."));
235+
236+
Header attempts = outcome.header(RetryTopicHeaders.DEFAULT_HEADER_ATTEMPTS);
237+
assertNotNull(attempts, "attempts must survive onto the dead letter");
238+
assertEquals(1, ByteBuffer.wrap(attempts.value()).getInt(),
239+
"poison failed once and was never retried, so it must record exactly one attempt");
240+
}
166241
}

Java/shared/src/main/java/com/lantanagroup/link/shared/kafka/RetryTopicRecoverer.java

Lines changed: 15 additions & 4 deletions
Original file line numberDiff line numberDiff line change
@@ -71,21 +71,32 @@ public RetryTopicRecoverer(int maxAttempts, IntToLongFunction backoffMsForAttemp
7171
public void accept(ConsumerRecord<?, ?> record, Exception exception) {
7272
Headers headers = record.headers();
7373

74+
// attempts is history: it records how many times the record ran, so it is stamped
75+
// unconditionally and survives onto a dead letter.
7476
int attempt = currentAttempts(headers) + 1;
7577
headers.remove(RetryTopicHeaders.DEFAULT_HEADER_ATTEMPTS);
7678
headers.add(RetryTopicHeaders.DEFAULT_HEADER_ATTEMPTS, ByteBuffer.allocate(4).putInt(attempt).array());
7779

78-
long newBackoff = System.currentTimeMillis() + backoffMsForAttempt.applyAsLong(attempt);
79-
headers.remove(RetryTopicHeaders.DEFAULT_HEADER_BACKOFF_TIMESTAMP);
80-
headers.add(RetryTopicHeaders.DEFAULT_HEADER_BACKOFF_TIMESTAMP, BigInteger.valueOf(newBackoff).toByteArray());
8180
if (headers.lastHeader(RetryTopicHeaders.DEFAULT_HEADER_ORIGINAL_TIMESTAMP) == null) {
8281
headers.add(RetryTopicHeaders.DEFAULT_HEADER_ORIGINAL_TIMESTAMP, BigInteger.valueOf(record.timestamp()).toByteArray());
8382
}
8483

8584
// Exception headers are stamped by the DeadLetterPublishingRecoverer delegate on publish.
8685
// Evaluated here, after the attempts header is stamped, so this sees the same count the
8786
// delegate's destination resolver will read a moment later.
88-
switch (decide.apply(record, exception)) {
87+
Decision decision = decide.apply(record, exception);
88+
89+
// The backoff timestamp is a due-time the -Retry listener waits on, so it is a promise that the
90+
// record will be delivered again. Stamp it only when that is true. A dead letter is never
91+
// redelivered, so a due-time on it describes a retry that was never scheduled — clear the one a
92+
// previous hop left rather than carrying it onto the DLT.
93+
headers.remove(RetryTopicHeaders.DEFAULT_HEADER_BACKOFF_TIMESTAMP);
94+
if (decision == Decision.RETRY) {
95+
long dueAt = System.currentTimeMillis() + backoffMsForAttempt.applyAsLong(attempt);
96+
headers.add(RetryTopicHeaders.DEFAULT_HEADER_BACKOFF_TIMESTAMP, BigInteger.valueOf(dueAt).toByteArray());
97+
}
98+
99+
switch (decision) {
89100
case RETRY -> logger.info("Retry attempt {}/{} for topic [{}].",
90101
attempt, maxAttempts, record.topic());
91102
case DLT_EXHAUSTED -> logger.warn("Max retry attempts ({}) reached for topic [{}]. Routing to DLT.",

0 commit comments

Comments
 (0)