Skip to content

Commit d2bc8be

Browse files
thiagohoraclaude
andcommitted
[OPIK-8240] [BE] fix: split provider-error retryability by status, resume XAUTOCLAIM from its cursor
Two independent defects that each leave a permanently failing online-scoring message cycling instead of retiring it. 1. A permanent provider 4xx was retried as if transient. ChatCompletionService.scoreTrace answered every unmappable provider failure with a blanket InternalServerErrorException, which sits outside BaseRedisSubscriber.NON_RETRYABLE_EXCEPTIONS -- so a request that can never succeed was replayed maxRetries times, once per pendingMessageDuration. The real status was available the whole time on the HttpException in the cause chain; it went unread because the existing recovery path classifies by family, and mapping all of 4xx to ClientErrorException would drop transient 408/429 after one attempt. Hence the blanket 500. Classify by status code instead: 400/401/403 and the rest of 4xx are permanent, 408/425/429 and all 5xx stay retryable. scoreTrace gets its own mapping so create() and the streaming handler keep returning the provider's status verbatim to HTTP callers. This also closes a pre-existing over-eager drop on the parseable branch, where a JSON-parseable 429 already became ClientErrorException and was dropped after one attempt. 2. XAUTOCLAIM never scanned past the first ~100 pending entries. claimPendingMessages passed StreamMessageId.MIN as the scan start every call and discarded the cursor Redis returns. Redis caps each XAUTOCLAIM at COUNT * 10 PEL entries *examined*, so at consumerBatchSize=10 a call inspects only the first 100 -- and restarting at MIN means nothing past that window is ever examined. Any backlog above ~100 grows a permanently unreachable tail, whatever the retry or decode behaviour downstream. Carry getNextId() forward, resetting to MIN on Redis's 0-0 end-of-pass reply so the oldest-first bias is preserved. A failed scan deliberately does not advance the cursor, so its window is retried rather than skipped. The end-of-pass sentinel is compared numerically, not against StreamMessageId.MIN/.ALL: those are wire sentinels serializing to "-" and "0", and neither is equals() to the StreamMessageId(0, 0) Redisson parses 0-0 into (verified against redisson 4.7.0), so matching on the constants would never fire and the scan would park at the end of the PEL. Tests: 132 green across the affected suites. Both fixes mutation-checked -- collapsing the status split to the whole 4xx family fails 5 tests, removing it entirely fails 7; reverting the cursor to always-MIN fails 3. Co-Authored-By: Claude Opus 5 (1M context) <noreply@anthropic.com>
1 parent 867d65e commit d2bc8be

5 files changed

Lines changed: 431 additions & 24 deletions

File tree

apps/opik-backend/src/main/java/com/comet/opik/api/resources/v1/events/BaseRedisSubscriber.java

Lines changed: 57 additions & 2 deletions
Original file line numberDiff line numberDiff line change
@@ -124,6 +124,27 @@ public abstract class BaseRedisSubscriber<M> implements Managed {
124124
private final LongHistogram listPendingTime;
125125
private final LongCounter unexpectedErrors;
126126

127+
/**
128+
* Resume point for the next {@code XAUTOCLAIM} scan.
129+
*
130+
* <p>Redis caps each {@code XAUTOCLAIM} at {@code COUNT * 10} PEL entries <em>examined</em> (not
131+
* claimed), so with the default {@code consumerBatchSize} of 10 a single call only ever inspects the
132+
* first 100 entries of the pending list. Restarting every scan at {@link StreamMessageId#MIN} —
133+
* which this class used to do, discarding the cursor Redis hands back — means anything past that
134+
* first window is never examined at all: a backlog above ~100 entries develops a permanently
135+
* unreachable tail, whatever the retry or decode behaviour further down. Carrying the returned
136+
* cursor forward walks the whole PEL instead, a window at a time.
137+
*
138+
* <p>Redis returns {@code 0-0} once a pass has covered the entire pending list; that resets this
139+
* back to {@link StreamMessageId#MIN} so the next pass starts over from the oldest entry, keeping
140+
* the oldest-first bias the original code intended.
141+
*
142+
* <p>Volatile rather than synchronized: {@code concatMap} in {@link #setupStreamListener()} already
143+
* serializes claim calls, so this is only ever written by one claim at a time; volatile just
144+
* publishes that write to whichever scheduler thread runs the next one.
145+
*/
146+
private volatile StreamMessageId claimCursor = StreamMessageId.MIN;
147+
127148
private volatile RStreamReactive<String, M> stream;
128149
private volatile Disposable streamSubscription;
129150
private volatile Scheduler timerScheduler;
@@ -387,11 +408,11 @@ private Mono<Map<StreamMessageId, Map<String, M>>> claimPendingMessages() {
387408
consumerId,
388409
config.getPendingMessageDuration().toJavaDuration().toMillis(),
389410
TimeUnit.MILLISECONDS,
390-
StreamMessageId.MIN, // Start from the beginning of pending list
411+
claimCursor, // Resume where the previous scan stopped; see claimCursor
391412
config.getConsumerBatchSize())
392413
.subscribeOn(consumerScheduler)
393414
.filter(Objects::nonNull)
394-
.map(AutoClaimResult::getMessages)
415+
.map(this::advanceCursorAndExtractMessages)
395416
.filter(Objects::nonNull)
396417
.doOnSuccess(claimedMessages -> {
397418
claimedMessages = Objects.requireNonNullElse(claimedMessages, Map.of());
@@ -401,14 +422,48 @@ private Mono<Map<StreamMessageId, Map<String, M>>> claimPendingMessages() {
401422
.onErrorResume(throwable -> {
402423
claimErrors.add(1);
403424
log.error("Error claiming pending messages", throwable);
425+
// A failed scan leaves the cursor where it was, so the next attempt retries the same
426+
// window rather than skipping it. Except on NOGROUP: the group is being recreated, so
427+
// any cursor into the old group's PEL is meaningless.
404428
if (isNoGroupError(throwable)) {
429+
claimCursor = StreamMessageId.MIN;
405430
return recoverFromNoGroup();
406431
}
407432
return Mono.just(Map.of());
408433
})
409434
.doFinally(signalType -> claimTime.record(System.currentTimeMillis() - startMillis));
410435
}
411436

437+
/**
438+
* Advances {@link #claimCursor} to where Redis says the next scan should resume, then returns the
439+
* batch this scan actually claimed.
440+
*
441+
* <p>A {@code null} or {@code 0-0} next-id means the pass reached the end of the pending list, so the
442+
* cursor goes back to {@link StreamMessageId#MIN} and the following pass starts from the oldest entry
443+
* again.
444+
*/
445+
private Map<StreamMessageId, Map<String, M>> advanceCursorAndExtractMessages(AutoClaimResult<String, M> result) {
446+
claimCursor = nextCursor(result.getNextId());
447+
return result.getMessages();
448+
}
449+
450+
/**
451+
* The cursor to use for the next scan, given the next-id Redis returned.
452+
*
453+
* <p>Compared numerically rather than against {@link StreamMessageId#MIN} / {@link StreamMessageId#ALL}:
454+
* those are wire sentinels that serialize to {@code -} and {@code 0}, and neither is
455+
* {@code equals()} to the {@code StreamMessageId(0, 0)} that Redisson parses Redis's literal
456+
* {@code 0-0} end-of-pass reply into. Matching on the constants would therefore never fire, and the
457+
* scan would run off the end of the PEL and stay there instead of wrapping.
458+
*/
459+
// Package-private for unit tests.
460+
static StreamMessageId nextCursor(StreamMessageId nextId) {
461+
if (nextId == null || (nextId.getId0() == 0 && nextId.getId1() == 0)) {
462+
return StreamMessageId.MIN;
463+
}
464+
return nextId;
465+
}
466+
412467
private Mono<Map<StreamMessageId, Map<String, M>>> readMessages() {
413468
var startMillis = System.currentTimeMillis();
414469
var streamReadGroupArgs = StreamReadGroupArgs.neverDelivered()

apps/opik-backend/src/main/java/com/comet/opik/domain/llm/ChatCompletionService.java

Lines changed: 54 additions & 8 deletions
Original file line numberDiff line numberDiff line change
@@ -36,6 +36,7 @@
3636
import java.nio.channels.ClosedChannelException;
3737
import java.util.List;
3838
import java.util.Optional;
39+
import java.util.Set;
3940
import java.util.concurrent.Callable;
4041
import java.util.function.Consumer;
4142

@@ -147,16 +148,32 @@ public ChatResponse scoreTrace(@NonNull ChatRequest chatRequest,
147148

148149
Optional<ErrorMessage> providerError = provider.getLlmProviderError(runtimeException);
149150

150-
providerError
151-
.ifPresent(llmProviderError -> failHandlingLLMProviderError(runtimeException, llmProviderError));
151+
// Deliberately NOT failHandlingLLMProviderError here, unlike create() and the streaming handler.
152+
// Those two answer an HTTP caller, so they want the provider's status verbatim - a 429 upstream
153+
// should be a 429 downstream. This method answers the online-scoring subscribers instead, where
154+
// the thrown type decides retryability: BaseRedisSubscriber.NON_RETRYABLE_EXCEPTIONS matches on
155+
// ClientErrorException, so the whole 4xx family would be dropped on the first failure - taking
156+
// genuinely transient 408s and 429s with it. Route through the retryability split instead, which
157+
// separates "this request can never succeed" from "try again later" inside that family.
158+
int status = providerError.map(ErrorMessage::getCode)
159+
.filter(ChatCompletionService::isErrorStatus)
160+
.or(() -> findProviderHttpStatus(runtimeException))
161+
.orElse(Response.Status.INTERNAL_SERVER_ERROR.getStatusCode());
152162

153-
// No failIfProviderReportedHttpStatus here, unlike create() and the streaming handler. This method is
154-
// called only by the online-scoring subscribers, never from a resource, so a recovered status reaches no
155-
// HTTP client — while BaseRedisSubscriber.NON_RETRYABLE_EXCEPTIONS lists ClientErrorException, so turning
156-
// a rate limit into a 429 or a provider timeout into a 408 would make the subscriber ack and drop the
157-
// evaluation instead of honouring onlineScoring.maxRetries. Both are RetriableException upstream, so the
158-
// blanket 500 is what keeps them retryable.
159163
log.warn(UNEXPECTED_ERROR_CALLING_LLM_PROVIDER, runtimeException);
164+
165+
if (isPermanentFailure(status)) {
166+
// Non-retryable: the subscriber acks and removes on the first delivery instead of burning
167+
// maxRetries x pendingMessageDuration on a request whose outcome cannot change. This is the
168+
// OPIK-8193 case - a provider rejecting an oversized/invalid request rejects every retry of
169+
// it identically.
170+
throw new ClientErrorException(buildDetailedErrorMessage(runtimeException), status,
171+
runtimeException);
172+
}
173+
// Everything else stays a blanket 500 so it lands outside NON_RETRYABLE_EXCEPTIONS and honours
174+
// onlineScoring.maxRetries. Note this keeps transient 4xx (408/429) retryable even though their
175+
// real status is a client error, which is exactly the distinction ClientErrorException cannot
176+
// express on its own.
160177
throw new InternalServerErrorException(buildDetailedErrorMessage(runtimeException), runtimeException);
161178
} finally {
162179
// Close the Vertex client (reused across retries) to release its GAX threads; other providers self-reclaim.
@@ -292,6 +309,35 @@ private static boolean isErrorStatus(int status) {
292309
return family == Response.Status.Family.CLIENT_ERROR || family == Response.Status.Family.SERVER_ERROR;
293310
}
294311

312+
/**
313+
* Statuses in the 4xx family that a retry could still clear, so they must NOT be treated as permanent.
314+
*
315+
* <p>{@code 408 Request Timeout}, {@code 425 Too Early} and {@code 429 Too Many Requests} all say
316+
* "not now", not "not ever" - langchain4j models the latter two as {@code RetriableException} upstream.
317+
* They sit in the client-error family purely by HTTP numbering, which is why family alone is too blunt
318+
* a discriminator for retryability.
319+
*/
320+
private static final Set<Integer> TRANSIENT_CLIENT_ERRORS = Set.of(
321+
Response.Status.REQUEST_TIMEOUT.getStatusCode(),
322+
425, // Too Early - no jakarta.ws.rs.core.Response.Status constant
323+
429); // Too Many Requests - no jakarta.ws.rs.core.Response.Status constant
324+
325+
/**
326+
* Whether a provider status means "this exact request can never succeed", so the caller should give up
327+
* rather than retry.
328+
*
329+
* <p>True only for the client-error family minus {@link #TRANSIENT_CLIENT_ERRORS}: a malformed,
330+
* oversized, unauthorised or forbidden request is rejected identically however many times it is
331+
* replayed. Server errors are excluded - a 5xx is the provider having a bad moment, and that is the
332+
* textbook retry case. An unrecognised status is treated as retryable, matching
333+
* {@code BaseRedisSubscriber}'s own "unknown defaults to retryable for safety" stance.
334+
*/
335+
// Package-private for unit tests.
336+
static boolean isPermanentFailure(int status) {
337+
return familyOf(status) == Response.Status.Family.CLIENT_ERROR
338+
&& !TRANSIENT_CLIENT_ERRORS.contains(status);
339+
}
340+
295341
/**
296342
* The status langchain4j's own exception types stand for, used for providers whose clients raise them without an
297343
* {@link HttpException} in the chain. {@code ContentFilteredException} is covered by its
Lines changed: 44 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -0,0 +1,44 @@
1+
package com.comet.opik.api.resources.v1.events;
2+
3+
import org.junit.jupiter.api.DisplayName;
4+
import org.junit.jupiter.api.Test;
5+
import org.redisson.api.stream.StreamMessageId;
6+
7+
import static org.assertj.core.api.Assertions.assertThat;
8+
9+
/**
10+
* Pure-function coverage for {@link BaseRedisSubscriber#nextCursor(StreamMessageId)}, the mapping that
11+
* decides where the next {@code XAUTOCLAIM} scan resumes (OPIK-8193).
12+
*
13+
* <p>Separate from {@link BaseRedisSubscriberUnitTest} because these need no Redis mocks at all, and
14+
* living under that class's Mockito setup would trip strict stubbing.
15+
*/
16+
@DisplayName("BaseRedisSubscriber claim-cursor mapping")
17+
class BaseRedisSubscriberCursorTest {
18+
19+
@Test
20+
@DisplayName("Redis's 0-0 end-of-pass reply wraps back to the start of the pending list")
21+
void endOfPassWrapsToStart() {
22+
// Compared numerically on purpose. StreamMessageId.MIN and .ALL are wire sentinels that serialize
23+
// to "-" and "0", and NEITHER is equals() to the StreamMessageId(0, 0) that Redisson parses Redis's
24+
// literal 0-0 into -- verified against redisson 4.7.0. Matching on the constants would therefore
25+
// never fire, the cursor would stick at the end of the PEL, and the scan would stop finding
26+
// anything at all: strictly worse than the always-MIN behaviour this replaces.
27+
assertThat(BaseRedisSubscriber.nextCursor(new StreamMessageId(0, 0))).isEqualTo(StreamMessageId.MIN);
28+
}
29+
30+
@Test
31+
@DisplayName("A missing next-id is treated as end-of-pass rather than propagating a null")
32+
void nullNextIdWrapsToStart() {
33+
assertThat(BaseRedisSubscriber.nextCursor(null)).isEqualTo(StreamMessageId.MIN);
34+
}
35+
36+
@Test
37+
@DisplayName("A mid-scan position is carried forward unchanged, which is what walks past the first window")
38+
void midScanPositionIsCarriedForward() {
39+
// Redis caps each XAUTOCLAIM at COUNT * 10 entries EXAMINED, so without carrying this forward the
40+
// scan only ever sees the first ~100 pending entries and anything behind them is never reclaimed.
41+
var midScan = new StreamMessageId(1787891543627L, 0);
42+
assertThat(BaseRedisSubscriber.nextCursor(midScan)).isSameAs(midScan);
43+
}
44+
}

apps/opik-backend/src/test/java/com/comet/opik/api/resources/v1/events/BaseRedisSubscriberUnitTest.java

Lines changed: 123 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -604,6 +604,129 @@ void shouldHandleRemoveConsumerTimeoutOnStop() {
604604
}
605605
}
606606

607+
/**
608+
* OPIK-8193. Redis caps each {@code XAUTOCLAIM} at {@code COUNT * 10} PEL entries <em>examined</em>,
609+
* so a scan that always restarts at {@link StreamMessageId#MIN} only ever inspects the first ~100
610+
* pending entries. A backlog above that grows a tail nothing ever reclaims: verified against a real
611+
* Redis, entries beyond the window sat at delivery-count 1 for weeks while the head cycled. These
612+
* tests pin the cursor being carried forward, which is what walks the rest of the PEL.
613+
*/
614+
@Nested
615+
class ClaimCursorTests {
616+
617+
@BeforeEach
618+
void setUp() {
619+
whenCreateGroupReturnEmpty();
620+
whenRemoveConsumerReturn();
621+
}
622+
623+
@Test
624+
void shouldResumeTheNextScanFromTheReturnedCursor() {
625+
var fastConfig = CONFIG.toBuilder().claimIntervalRatio(2).build();
626+
var subscriber = trackSubscriber(TestRedisSubscriber.createSubscriber(fastConfig, redissonClient));
627+
var starts = new CopyOnWriteArrayList<StreamMessageId>();
628+
// Never returns 0-0, so a correct implementation keeps walking forward and a regressed one
629+
// (restarting at MIN) is immediately visible in the captured start arguments.
630+
var cursor = new AtomicInteger();
631+
when(stream.autoClaim(
632+
eq(fastConfig.getConsumerGroupName()),
633+
anyString(),
634+
eq(fastConfig.getPendingMessageDuration().toJavaDuration().toMillis()),
635+
eq(TimeUnit.MILLISECONDS),
636+
any(StreamMessageId.class),
637+
eq(fastConfig.getConsumerBatchSize())))
638+
.thenAnswer(invocation -> {
639+
starts.add(invocation.getArgument(4));
640+
return Mono.just(new AutoClaimResult<>(
641+
new StreamMessageId(100L + cursor.incrementAndGet(), 0),
642+
Map.of(),
643+
List.of()));
644+
});
645+
whenReadGroupReturnMessages();
646+
whenAckReturn();
647+
whenRemoveReturn();
648+
649+
subscriber.start();
650+
651+
await().atMost(AWAIT_TIMEOUT_SECONDS, TimeUnit.SECONDS).until(() -> starts.size() >= 3);
652+
653+
// First scan starts at the beginning; every later scan resumes where the previous one stopped.
654+
assertThat(starts.get(0)).isEqualTo(StreamMessageId.MIN);
655+
assertThat(starts.get(1)).isEqualTo(new StreamMessageId(101L, 0));
656+
assertThat(starts.get(2)).isEqualTo(new StreamMessageId(102L, 0));
657+
}
658+
659+
@Test
660+
void shouldWrapBackToTheStartAfterAFullPass() {
661+
var fastConfig = CONFIG.toBuilder().claimIntervalRatio(2).build();
662+
var subscriber = trackSubscriber(TestRedisSubscriber.createSubscriber(fastConfig, redissonClient));
663+
var starts = new CopyOnWriteArrayList<StreamMessageId>();
664+
var calls = new AtomicInteger();
665+
when(stream.autoClaim(
666+
eq(fastConfig.getConsumerGroupName()),
667+
anyString(),
668+
eq(fastConfig.getPendingMessageDuration().toJavaDuration().toMillis()),
669+
eq(TimeUnit.MILLISECONDS),
670+
any(StreamMessageId.class),
671+
eq(fastConfig.getConsumerBatchSize())))
672+
.thenAnswer(invocation -> {
673+
starts.add(invocation.getArgument(4));
674+
// Advance once, then report the pass complete.
675+
var nextId = calls.incrementAndGet() == 1
676+
? new StreamMessageId(500L, 0)
677+
: new StreamMessageId(0, 0);
678+
return Mono.just(new AutoClaimResult<>(nextId, Map.of(), List.of()));
679+
});
680+
whenReadGroupReturnMessages();
681+
whenAckReturn();
682+
whenRemoveReturn();
683+
684+
subscriber.start();
685+
686+
await().atMost(AWAIT_TIMEOUT_SECONDS, TimeUnit.SECONDS).until(() -> starts.size() >= 3);
687+
688+
assertThat(starts.get(0)).isEqualTo(StreamMessageId.MIN);
689+
assertThat(starts.get(1)).isEqualTo(new StreamMessageId(500L, 0));
690+
// 0-0 came back, so the oldest-first bias is restored rather than the scan parking at the end.
691+
assertThat(starts.get(2)).isEqualTo(StreamMessageId.MIN);
692+
}
693+
694+
@Test
695+
void shouldRetryTheSameWindowAfterAFailedScan() {
696+
var fastConfig = CONFIG.toBuilder().claimIntervalRatio(2).build();
697+
var subscriber = trackSubscriber(TestRedisSubscriber.createSubscriber(fastConfig, redissonClient));
698+
var starts = new CopyOnWriteArrayList<StreamMessageId>();
699+
var calls = new AtomicInteger();
700+
when(stream.autoClaim(
701+
eq(fastConfig.getConsumerGroupName()),
702+
anyString(),
703+
eq(fastConfig.getPendingMessageDuration().toJavaDuration().toMillis()),
704+
eq(TimeUnit.MILLISECONDS),
705+
any(StreamMessageId.class),
706+
eq(fastConfig.getConsumerBatchSize())))
707+
.thenAnswer(invocation -> {
708+
starts.add(invocation.getArgument(4));
709+
if (calls.incrementAndGet() == 1) {
710+
return Mono.just(new AutoClaimResult<>(
711+
new StreamMessageId(700L, 0), Map.of(), List.of()));
712+
}
713+
// A failed scan must not advance the cursor, or the window it covered would be
714+
// skipped entirely and its entries left unreachable until the next full wrap.
715+
return Mono.error(new RuntimeException("Redis autoClaim error"));
716+
});
717+
whenReadGroupReturnMessages();
718+
whenAckReturn();
719+
whenRemoveReturn();
720+
721+
subscriber.start();
722+
723+
await().atMost(AWAIT_TIMEOUT_SECONDS, TimeUnit.SECONDS).until(() -> starts.size() >= 3);
724+
725+
assertThat(starts.get(1)).isEqualTo(new StreamMessageId(700L, 0));
726+
assertThat(starts.get(2)).isEqualTo(new StreamMessageId(700L, 0));
727+
}
728+
}
729+
607730
private TestRedisSubscriber trackSubscriber(TestRedisSubscriber subscriber) {
608731
subscribers.add(subscriber);
609732
return subscriber;

0 commit comments

Comments
 (0)