[OPIK-8202] [BE] fix: harden ClickHouseAppender against dropped user logs - #8126
[OPIK-8202] [BE] fix: harden ClickHouseAppender against dropped user logs#8126JetoPistola wants to merge 2 commits into
Conversation
…logs Investigating the intermittent Integration Group 14 failures in AutomationRuleEvaluatorsResourceTest surfaced two ways the appender can lose user-facing log rows outright. Both are fixed here. flushLogs drains the batch out of the queue before inserting, so any failure past that point loses those events: - a failed insert was only logged, never retried or re-queued - a throw escaping flushLogs cancelled the scheduleAtFixedRate task permanently, silently stopping log persistence for the rest of the JVM's life Retry the insert, re-queue the batch when the retries are exhausted (including on a synchronous throw), and keep the periodic flush alive across failures. The two new unit tests fail without these changes and pass with them; they need no containers. The awaits in AutomationRuleEvaluatorsResourceTest now state their timeout explicitly instead of inheriting Awaitility's implicit 10s default. This is a readability change, not a fix: the flush interval is 500ms, and the failing tests still fail with a 30s wait, so the rows are not merely late. This does NOT confirm a fix for the OPIK-8202 flake. Locally the affected tests fail on unmodified main and still fail with these changes, at rates too close to distinguish over three runs each. Local runs are also a poor proxy here -- they fail far more often than CI does, so something environmental may be involved. The root cause of the flake is still unidentified: in failing runs the log write path reports no errors, and the sampler scores the rule the test expects it to skip, so the awaited row is never produced rather than lost. Co-Authored-By: Claude Opus 5 (1M context) <noreply@anthropic.com>
⏱️ pre-commit per-hook timing
⏭️ 42 skipped (no matching files changed)
|
Python SDK E2E Tests Results (Python 3.10)296 tests 288 ✅ 5m 3s ⏱️ Results for commit a360c1d. ♻️ This comment has been updated with latest results. |
Review feedback on the retry path. A synchronous throw from saveAll means the batch is rejected before any I/O -- an event missing workspace_id or rule_id throws IllegalStateException out of the DAO. Requeueing such a batch made every later flush throw identically, so the appender would spin on a poison batch forever. Drop it instead, and keep requeueing only for errors signalled through the returned Mono, which are the genuinely transient ones. Also hoist the fixed Retry.backoff policy into a constant rather than building one per flushed batch, and assert the retry attempt count in the transient test -- it previously passed on requeue-then-reflush alone, so it did not actually pin Retry.backoff. Co-Authored-By: Claude Opus 5 (1M context) <noreply@anthropic.com>
Backend Tests - Integration Group 14 43 files 43 suites 4m 11s ⏱️ For more details on these errors, see this check. Results for commit a360c1d. |
|
|
||
| private static final long INSERT_RETRY_ATTEMPTS = 3; | ||
| private static final Duration INSERT_RETRY_MIN_BACKOFF = Duration.ofMillis(100); | ||
| private static final Retry INSERT_RETRY = Retry.backoff(INSERT_RETRY_ATTEMPTS, INSERT_RETRY_MIN_BACKOFF); |
There was a problem hiding this comment.
Hardcoded retry policy blocks operational tuning
ClickHouseAppender hardcodes Retry.backoff(INSERT_RETRY_ATTEMPTS, INSERT_RETRY_MIN_BACKOFF), so operators cannot tune or disable ClickHouse insert retries at runtime — should we move these values into a validated typed configuration block with YAML defaults and environment overrides, then build the policy from that shared configuration?
Want Baz to fix this for you? Activate Fixer
Other fix methods
Prompt for AI Agents
Before applying, verify this suggestion against the current code. In
`apps/opik-backend/src/main/java/com/comet/opik/infrastructure/log/ClickHouseAppender.java`
around line 33, the ClickHouse insert retry policy is hardcoded in the `INSERT_RETRY`
field, preventing operators from tuning or disabling retries at runtime. Add a validated
typed configuration block with YAML defaults and environment-variable overrides for
retry attempts and backoff, and construct the appender’s retry policy from that shared
configuration instead of hardcoded constants. Update the wiring and any relevant
configuration documentation or tests to verify the defaults, overrides, and
disabled-retry behavior.
| // A synchronous throw from saveAll means the batch itself is rejected before | ||
| // any I/O (e.g. an event missing workspace_id or rule_id). Requeueing would | ||
| // fail identically on every later flush, so drop it instead of looping. | ||
| log.error("Dropping '{}' logs rejected before insert", events.size(), e); |
There was a problem hiding this comment.
Expected log drops pollute ERROR telemetry
Handled validation failures such as missing workspace_id or rule_id go through log.error(..., e), so expected rejected batches produce ERROR telemetry and stack traces that obscure failures needing investigation — should we log them at WARN with concise bounded context and omit the throwable unless the failure is unexpected?
Want Baz to fix this for you? Activate Fixer
Other fix methods
Prompt for AI Agents
Before applying, verify this suggestion against the current code. In
`apps/opik-backend/src/main/java/com/comet/opik/infrastructure/log/ClickHouseAppender.java`
around lines 120-123, update the synchronous `saveAll` rejection handling in
`flushLogs()` so expected validation failures are logged at `WARN`, not `ERROR`. Use
concise bounded context such as the affected table and event count, and omit the
throwable to avoid routine stack traces; preserve throwable logging only for genuinely
unexpected failures if the surrounding exception handling can distinguish them.
| @Test | ||
| @DisplayName("when the batch is rejected before insert, then it is dropped rather than requeued") | ||
| void whenBatchRejectedBeforeInsert__thenItIsDroppedRatherThanRequeued() { | ||
| var attempts = new AtomicInteger(); | ||
|
|
||
| // A synchronous throw means the batch is malformed (e.g. missing workspace_id), so it would | ||
| // fail identically forever. Requeueing it would spin the flush thread on a poison batch. | ||
| startAppender(events -> { | ||
| attempts.incrementAndGet(); | ||
| throw new IllegalStateException("workspace_id is not set"); | ||
| }); | ||
|
|
There was a problem hiding this comment.
Exhausted retries can silently lose logs
The new coverage never exhausts INSERT_RETRY, so a regression could still drop batches after all attempts fail while the other retry paths pass. According to the PR description, should we add a deterministic test that fails every attempt, asserts the batch is requeued, then allows a later flush to persist it and verifies the attempt count?
Want Baz to fix this for you? Activate Fixer
Other fix methods
Prompt for AI Agents
Before applying, verify this suggestion against the current code. In
apps/opik-backend/src/test/java/com/comet/opik/infrastructure/log/ClickHouseAppenderTest.java
around lines 66-86, add a deterministic test covering exhaustion of INSERT_RETRY rather
than only the synchronous-rejection path. Make every insert attempt fail through the
configured retry limit, assert the expected retry attempt count, then allow the
subsequent flush to succeed and verify that the requeued batch is persisted with the
final expected total attempt count. Keep the existing poison-batch test and use
synchronization/await conditions so the test does not depend on timing.
Details
Hardens
ClickHouseAppenderagainst two ways it can silently lose user-facing log rows. Both were found while investigating the intermittentIntegration Group 14failures inAutomationRuleEvaluatorsResourceTest, but neither is confirmed to be the cause of that flake — see the caveat below.flushLogsdrains the batch out of the queue before inserting, so any failure past that point loses those events:flushLogspermanently cancelled thescheduleAtFixedRatetask, silently stopping user-log persistence for the rest of the JVM's life.This retries the insert, re-queues the batch when retries are exhausted (including on a synchronous throw), and keeps the periodic flush alive across failures. In production the second bug would end evaluator-log persistence until the next restart, so it is worth fixing on its own merits.
Caveat — this does not confirm a fix for the flake. Locally the affected tests fail on unmodified
mainand still fail with these changes, at rates too close to distinguish over three full-class runs each (3/3 vs 2/3). Local runs are also a poor proxy: they fail far more often than CI does, so something environmental may be involved. The root cause is still unidentified — in failing runs the log write path reports no errors, and the sampler scores the rule the test expects it to skip, so the awaited row is never produced rather than lost. Opening as a draft to get CI signal on the real environment.The awaits in
AutomationRuleEvaluatorsResourceTestnow state their timeout explicitly instead of inheriting Awaitility's implicit 10s default. This is a readability change, not a fix: the flush interval is 500ms and the failing tests still fail with a 30s wait, so the rows are not merely late.Change checklist
Issues
AI-WATERMARK
AI-WATERMARK: yes
Testing
Commands run, from
apps/opik-backend:mvn -o compile -DskipTests— passesmvn -o spotless:check— passesmvn -o test -Dtest='ClickHouseAppenderTest'— passes (2/2)The two new unit tests in
ClickHouseAppenderTestare the meaningful coverage here: they fail on unmodifiedmainand pass with this change, and need no containers.whenInsertFailsTransiently__thenEventsAreRetriedAndPersisted— fails a first insert attempt, asserts the events still land.whenFlushThrows__thenSubsequentFlushesStillRun— throws inside a flush, asserts later flushes still run (pins the killed-scheduler bug).Integration runs of
AutomationRuleEvaluatorsResourceTest(Testcontainers: ClickHouse, MySQL, Redis + in-process Dropwizard + WireMock), three consecutive full-class runs each, locally on macOS/Apple Silicon:main: 3/3 runs failedSame failure mode either way (
AwaitilityConditionTimeout,Expected size: 1 but was: 0), landing on a different test each run. That difference is not significant at n=3 — this branch is not demonstrated to fix the flake, which is why this is a draft. Local reproduction is also much more frequent than CI's, so the local failures may be partly environmental.Not run: the full backend suite, and any verification that this changes flake rate in CI — that is what the draft is for.
Documentation
N/A — internal robustness fix with no user-facing or API surface change.