Repository navigation
fix(core)!: back off exponentially between retries instead of retrying on every poll (#131) - #146
Conversation
rawo
left a comment
There was a problem hiding this comment.
Reviewed the #146 diff only (on top of #145/#144). The approach is sound: claiming by due time, with an index that stops at now, fixes the dead-lettering and the head-of-line problem.
What I verified. I ran the claim queries against throwaway containers (PostgreSQL 16 and MySQL 8.0.46; 300k/200k rows, 10% PENDING, 80% of those not yet due):
- PostgreSQL, generic prepared plan (
plan_cache_mode = force_generic_plan), both the 1-type and 2-type IN forms:Limit -> LockRows -> Index Scan using idx_okapi_outbox_pending_delivery_next_attempt_id, withIndex Cond: delivery_type = ANY(...) AND next_attempt_at <= $3. No Sort node, about 5 buffers. - MySQL with
FORCE INDEX:type: range,Using index condition, no filesort. EXPLAIN ANALYZE shows one bounded range per route:(status='PENDING' AND delivery_type='http' AND NULL < next_attempt_at <= now) OR (... 'kafka' ...).
So the index claims in the description hold on both databases. The PG fast-default claim also holds: CURRENT_TIMESTAMP is STABLE, not volatile, so PG 11+ stores it in attmissingval.
The inline comments cover the specific issues. Cross-cutting ones:
-
should-fix, tests don't prove the migration/rolling-deploy claims. The PR description says the Postgres rolling-deploy test "inserts 1.x-style rows without the column after 004, and they are claimed".
PostgresTimestamptzMigrationTestdoes insert after the fullmigrate(url), but it asserts with the legacystore.claimPending(10), which ignoresnext_attempt_at. If the DEFAULT were missing or wrong, the test would still pass. Nothing tests:- the 004 backfill: pre-existing
PENDINGrows getnext_attempt_at = created_atand keep their order under the route-aware claim; - the MySQL
NULL→created_atfallback intoOutboxEntry; - that a 1.x-style insert after 004 is returned by
claimPending(types, limit, Instant.now()).
Suggest switching those assertions to the route-aware claim and adding a pre-004
PENDINGrow to both migration tests. - the 004 backfill: pre-existing
-
nit, no Spring test for the four new properties. Nothing checks binding (e.g.
okapi.processor.initial-backoff=1sreaching theRetryPolicy) or that an invalid value fails startup with the property name.OutboxProcessorAutoConfigurationTestalready has the setup for this. -
question, clock sources. The description says "
nowcomes from the processor'sClock... so database clock skew doesn't matter". That is true for retries. A new row's due time, though, iscreatedAtfrom the publishing instance's clock. On PG, a row inserted by 1.x during the rolling window gets the DB'sCURRENT_TIMESTAMP. So skew between a publisher (or the DB) and a processor now delays brand-new messages by that skew: a publisher 30 s ahead means its messages wait about 30 s. Before this PR, skew only affected ordering. With NTP this is small. Is it worth a sentence in README's ordering/guarantees section, or using<= now + small tolerance? Not blocking.
| is DeliveryResult.RetriableFailure -> | ||
| if (retryPolicy.shouldRetry(entry.retries)) { | ||
| entry.retry(now, result.error) | ||
| entry.retry(now, result.error, nextAttemptAt = now + retryPolicy.backoff(entry.retries + 1)) |
There was a problem hiding this comment.
should-fix: the backoff is measured from before delivery, so a slow failure uses up most or all of it.
In processBatch, now is read before deliverer.deliverBatch(entries) (line 34), so nextAttemptAt = batchStart + backoff. A slow failure is the typical shape of a real outage. For example, HttpMessageDeliverer has a 30 s exchange timeout and a 10 s connect timeout.
- The 10 s and 20 s backoffs (with jitter, 8 to 20 s) have already passed by the time
updateAfterProcessingBatchcommits. - Those entries are claimed again on the very next tick.
- During an outage with timeouts, the first two retries are still back-to-back, which is the behaviour No retry backoff: default config dead-letters every pending message after ~6s of downstream outage #131 reports.
The single-entry process() path reads the clock after deliver(), so the two paths also disagree.
Suggestion: in processBatch, take a second clock.instant() after deliverBatch returns and use it as the base for nextAttemptAt. lastAttempt/updatedAt can keep the start time if that is intended. A unit test with a clock that advances inside deliverBatch would pin this down.
|
|
||
| ALTER TABLE okapi_outbox ADD COLUMN IF NOT EXISTS next_attempt_at TIMESTAMPTZ NOT NULL DEFAULT CURRENT_TIMESTAMP; | ||
|
|
||
| UPDATE okapi_outbox SET next_attempt_at = created_at WHERE status = 'PENDING'; |
There was a problem hiding this comment.
should-fix: the backfill runs while the table's ACCESS EXCLUSIVE lock is held.
The ALTER TABLE on line 13 takes ACCESS EXCLUSIVE, and PostgreSQL holds it until the changeset's transaction commits. This UPDATE runs in the same transaction, so the lock covers the whole backfill, not a "brief" moment as line 10 and UPGRADING.md say. Every publish(), and every read of okapi_outbox (1.x workers, lag metrics), waits until all PENDING rows are rewritten. The PENDING backlog is largest right after an outage, which is exactly when people are likely to upgrade for this fix, and every PENDING row gets a new tuple plus index entries.
Suggestion: move the UPDATE into its own changeset (e.g. outbox:004-backfill) after the column add.
- In its own transaction it takes only row locks, so
publish()(inserts) is not blocked, and 1.xSKIP LOCKEDclaims just skip rows the backfill is touching. - It stays idempotent on re-run.
- Optionally, batch it by id range for very large backlogs.
- Then fix the comment on line 10 and the UPGRADING wording.
| SET @okapi_previous_lock_wait_timeout = @@session.lock_wait_timeout; | ||
| SET SESSION lock_wait_timeout = 30; | ||
|
|
||
| ALTER TABLE okapi_outbox ADD COLUMN next_attempt_at DATETIME(6) NULL; |
There was a problem hiding this comment.
should-fix: the changeset cannot be re-run after a partial failure.
MySQL DDL commits implicitly, so the steps in this changeset are not atomic.
- Suppose the
ADD INDEX(line 18) orDROP INDEX(line 22) fails. The likeliest cause is the 30 slock_wait_timeoutadded here: theINPLACEbuild needs a brief exclusive MDL and waits behind any open transaction on the table. - By then the column already exists and the backfill is committed, but Liquibase has not recorded
outbox:004. - On the next start this line fails with
Duplicate column name 'next_attempt_at', and every start fails after that until someone fixes the schema by hand.
The comment in 003 says a timeout means "the migration fails and runs again on the next start". That holds for 003 (a single statement) but not for this changeset. MySQL has no ADD COLUMN IF NOT EXISTS.
Suggestion: split this into one changeset per DDL statement (column, backfill, add index, drop index), each with a Liquibase precondition, for example:
--precondition-sql-check expectedResult:0 SELECT COUNT(*) FROM information_schema.columns WHERE table_schema = DATABASE() AND table_name = 'okapi_outbox' AND column_name = 'next_attempt_at'- an
onFail:MARK_RANprecondition oninformation_schema.statisticsfor the two index statements.
Minor: as in 003, lock_wait_timeout is only restored on success. The 003 comment documents that; this file doesn't.
|
|
||
| ALTER TABLE okapi_outbox ADD COLUMN next_attempt_at DATETIME(6) NULL; | ||
|
|
||
| UPDATE okapi_outbox SET next_attempt_at = created_at WHERE status = 'PENDING'; |
There was a problem hiding this comment.
should-fix: a manually requeued pre-004 FAILED row can never be claimed on MySQL.
Only PENDING rows are backfilled, so FAILED (and DELIVERED) rows written before 004 keep next_attempt_at = NULL. There is no requeue API yet: it is deferred to a follow-up, and README says an upgrade does not retry existing FAILED rows. The usual workaround is therefore UPDATE okapi_outbox SET status = 'PENDING', retries = 0 WHERE ....
- On PostgreSQL that works, because those rows got the column default.
- On MySQL
next_attempt_at <= ?is never true forNULL, so the row staysPENDINGforever. toOutboxEntry's?: created_atfallback hides this, and nothing logs it.
Suggestion: backfill WHERE status IN ('PENDING', 'FAILED'). FAILED rows are usually few, and DELIVERED rows get purged, so the extra cost is small. Alternatively, or as well, add an UPGRADING note that a manual requeue must also set next_attempt_at. The same advice would be useful generally, for example SET next_attempt_at = CURRENT_TIMESTAMP(6) on MySQL (UTC session), since requeued rows keep their old due time.
| - **PostgreSQL:** [001](okapi-postgres/src/main/resources/com/softwaremill/okapi/db/postgres/001__create_okapi_outbox_table.sql) table and initial indexes, [002](okapi-postgres/src/main/resources/com/softwaremill/okapi/db/postgres/002__route_aware_claim_index.sql) route-aware claim index, [003](okapi-postgres/src/main/resources/com/softwaremill/okapi/db/postgres/003__timestamptz_columns.sql) `TIMESTAMPTZ` timestamp columns, [004](okapi-postgres/src/main/resources/com/softwaremill/okapi/db/postgres/004__retry_backoff.sql) retry backoff column and claim index (its second changeset must run outside a transaction) | ||
| - **MySQL:** [001](okapi-mysql/src/main/resources/com/softwaremill/okapi/db/mysql/001__create_okapi_outbox_table.sql) table and initial indexes, [002](okapi-mysql/src/main/resources/com/softwaremill/okapi/db/mysql/002__route_aware_claim_index.sql) route-aware claim index, [003](okapi-mysql/src/main/resources/com/softwaremill/okapi/db/mysql/003__datetime_columns.sql) `DATETIME(6)` timestamp columns, [004](okapi-mysql/src/main/resources/com/softwaremill/okapi/db/mysql/004__retry_backoff.sql) retry backoff column and claim index | ||
|
|
||
| For an existing installation, apply `002` before starting updated workers. MySQL claims explicitly select the new index and fail if it is missing. PostgreSQL's `002` uses `CREATE INDEX CONCURRENTLY`, so run it outside a transaction when using another migration tool. The bundled Liquibase changelog handles this automatically. `CREATE INDEX CONCURRENTLY` waits for every transaction in the database that started before it, not only those on `okapi_outbox`, so long-running transactions (including old workers delivering a claimed batch) delay it, and with Liquibase they delay application startup while the changelog lock is held. Run it when no long transactions are open, or apply it ahead of the rollout. |
There was a problem hiding this comment.
should-fix (docs): this paragraph is now stale.
It still says to apply 002 before starting updated workers and that MySQL claims use "the new index". After this PR:
MysqlOutboxStoreusesFORCE INDEX (idx_okapi_outbox_status_delivery_next_attempt_id)and needs thenext_attempt_atcolumn, so 004 must be applied before updated workers start, or every claim fails.- PostgreSQL's 004 claim-index changeset is also
CREATE INDEX CONCURRENTLYwith the same caveats about waiting for transactions.
Suggest: "apply all migrations up to 004 ...", and mention that the CONCURRENTLY caveats apply to both 002 and 004.
| fun backoff(retry: Int, random: RandomGenerator = ThreadLocalRandom.current()): Duration { | ||
| require(retry >= 1) { "retry must be >= 1, got: $retry" } | ||
| val maxMillis = maxBackoff.toMillis().toDouble() | ||
| val exponential = initialBackoff.toMillis() * Math.pow(backoffMultiplier, (retry - 1).toDouble()) |
There was a problem hiding this comment.
nit: two edge cases in backoff().
toMillis()truncates, so a sub-millisecondinitialBackoffsilently becomes 0.- More importantly,
maxBackoffhas no upper bound.Duration.toMillis()throwsArithmeticExceptionabove about 292M years. A very largemaxBackoff(e.g. from a typo in a Spring property) passes validation, thenbackoff()throws insideprocessBatchon the first retriable failure. The batch transaction rolls back and the same entries fail again every tick.now + backoffcan also overflowInstantor exceed the DB column range well before that.
Suggest validating maxBackoff against a sane bound in init, e.g. <= Duration.ofDays(365), or clamping. Also, backoffMultiplier = +Infinity passes >= 1.0, and with initialBackoff = 0 it gives 0 * Inf = NaN. That happens to come out as 0 ms, but require(backoffMultiplier.isFinite()) would be cleaner.
| * When a `PENDING` entry becomes eligible for its next delivery attempt (issue #131): [createdAt] | ||
| * for a new entry, later after a retriable failure. Only meaningful while the entry is `PENDING`. | ||
| */ | ||
| val nextAttemptAt: Instant = createdAt, |
There was a problem hiding this comment.
nit (API docs): Java callers lose the 11-argument constructor.
OutboxEntry's constructor has no @JvmOverloads, so the 11-argument JVM constructor is gone and Java callers of new OutboxEntry(...) get a compile error. The CHANGELOG only says Kotlin copy/default-argument callers must recompile. Either add @JvmOverloads constructor here, as RetryPolicy and OutboxProcessorProperties have, or mention Java constructor callers in the CHANGELOG.
|
Addressed the review in 56b79f1:
I also hit and fixed a Liquibase 5 parse error: a comment line starting
|
d105443 to
d4b16d2
Compare
56b79f1 to
6dd54d9
Compare
…g on every poll (#131) A retriable failure was retried on the next tick, so with the defaults an entry was terminally FAILED after ~6 s of downstream outage, and failing rows, always the oldest, were re-claimed first every tick. Entries now carry nextAttemptAt (column next_attempt_at, changeset 004); a retriable failure sets it RetryPolicy's backoff ahead (default 10 s doubling, capped at 10 min, 20% jitter), and the route-aware claim takes only due rows, walking (delivery_type, next_attempt_at, id) up to the processor clock's now through a new index that replaces 002's. BREAKING CHANGE: RetryPolicy, OutboxEntry and OutboxProcessorProperties gained parameters; RouteAwareOutboxStore.claimPending takes `now`; migration 004 adds a column and replaces the claim index; retries are no longer immediate by default. Co-Authored-By: Claude Opus 5.5 (1M context) <noreply@anthropic.com>
- Count a batch retry's backoff from when delivery ended, as process() already did, so slow failures (timeouts) do not eat into it. - Postgres 004: backfill in its own changeset so ADD COLUMN holds ACCESS EXCLUSIVE only briefly. - MySQL 004: one changeset per DDL step with preconditions, so a migration that stopped half-way (MySQL commits each DDL) resumes; backfill FAILED rows too so a manual requeue is claimable. - RetryPolicy: compute in nanoseconds, cap maxBackoff at 365 days, require a finite multiplier; same checks on the Spring properties. OutboxEntry constructor is @jvmoverloads for Java callers. - Docs: all migrations up to 004 before updated workers, clock-skew note, manual requeue recipe. - Tests: migration tests claim through the route-aware claim (backfill, 1.x insert default, FAILED requeue), batch backoff timing, sub-ms backoff, Spring property binding and validation. Co-Authored-By: Claude Opus 5.5 (1M context) <noreply@anthropic.com>
6dd54d9 to
5f14966
Compare
… commits (#137) (#147) Closes #137. Part of the 2.0.0 breaking-change set. > Independent of the stacked schema PRs (#144 → #145 → #146), so it is based on `main`. It adds the same "From 1.x to 2.0.0" heading to `UPGRADING.md` as #144, which will be a trivial merge conflict for whichever lands second. ## Problem `OutboxProcessor.processNext` called `listener.onEntryProcessed` / `onBatchProcessed` right after `store.updateAfterProcessingBatch`, **inside the scheduler's transaction, before it commits**. When the commit then failed (connection loss, serialization failure, timeout): - The rows rolled back to `PENDING`. - `okapi.entries.delivered` and `okapi.entries.failed` had already been incremented, and they were incremented again on redelivery. - A custom listener could act on state that was never persisted. ## Fix - `OutboxProcessor.processBatch(limit)` claims, delivers and persists, then returns a `ProcessedBatch` without notifying anyone. - `OutboxProcessor.publishEvents(batch)` emits the entry events and then the batch event. - `OutboxScheduler` runs `processBatch` inside `runInTransaction` and `publishEvents` after it returns. Under the scheduler, events therefore describe committed state, and a batch whose commit fails emits nothing. - `processNext(limit)` keeps its signature and still notifies at once (`processBatch` + `publishEvents`), for callers that drive the processor themselves. Its KDoc says that inside a transaction those events come before the commit. - `onBatchProcessed`'s duration, and therefore `okapi.batch.duration`, now runs until the commit. - **Docs:** the KDoc of `OutboxProcessor`, `OutboxProcessorListener` and `OutboxScheduler`; the README metrics table and listener paragraph; a CHANGELOG entry under *Changed (BREAKING)*; an UPGRADING section. ## Breaking - **Listener timing:** under the scheduler, callbacks run after the commit, outside the processing transaction, and are skipped when the commit fails. A listener that relied on joining that transaction can't any more. - **Batch timer:** `okapi.batch.duration` includes the commit. ## Tests - `ListenerAfterCommitTest` (unit): - `processBatch` doesn't notify, and `publishEvents` does; - `processNext` still notifies at once; - the scheduler emits events only after the runner's "commit"; - a runner whose commit throws leads to no events over several ticks. - `ListenerAfterCommitEndToEndTest` (Postgres): the listener queries the row's status from a separate connection inside `onEntryProcessed` and must see `DELIVERED`, which proves the commit already happened. - **The test was checked against the fix:** with the old scheduler it fails with `expected:<DELIVERED> but was:<PENDING>`. - `./gradlew ktlintCheck test` passes locally. 🤖 Generated with [Claude Code](https://claude.com/claude-code) --------- Co-authored-by: Claude Opus 5.5 (1M context) <noreply@anthropic.com>
Closes #131. Part of the 2.0.0 breaking-change set (labelled
criticaltoo).Problem
A retriable failure was retried on the very next poll. With the defaults (
interval1s,max-retries5), an entry was attempted 6 times in about 6 s and then markedFAILED, which is terminal. So:Fix
next_attempt_at/OutboxEntry.nextAttemptAt: when aPENDINGentry is next due.createPendingsets it tocreatedAt.now + RetryPolicy.backoff(retryNumber).RetryPolicygainsinitialBackoff(10s),backoffMultiplier(2.0),maxBackoff(10m) andjitter(0.2), all defaulted and@JvmOverloads, plusbackoff(retry, random).initial × multiplier^(n-1), capped, then shortened by up tojitterat random.RouteAwareOutboxStore.claimPending(types, limit, now)returns only rows withnext_attempt_at <= now, ordered by(delivery_type, next_attempt_at, id).nowcomes from the processor'sClock, the same clock that computed the backoff, so database clock skew doesn't matter.now. Entries still backing off are never scanned or locked, however large the outage backlog.004__retry_backoff(both databases) adds the column, backfillsPENDINGrows withcreated_at, and replaces 002's claim index.NOT NULL DEFAULT CURRENT_TIMESTAMP, so rows that 1.x instances insert during a rolling deploy stay claimable. This works without a table rewrite on PG 11+. The index goes in a separaterunInTransaction:falsechangeset withCREATE INDEX CONCURRENTLY, dropping any invalid leftover first.INSTANTadd on 8.0.12+),lock_wait_timeoutis bounded, and the index is added and droppedINPLACE, LOCK=NONE. 1.x instances are already required to be stopped by fix(mysql)!: store timestamps as UTC DATETIME(6) so the outbox survives 2038 (#138) #144, so the column needs no default.okapi.processor.initial-backoff,backoff-multiplier,max-backoffandbackoff-jitterproperties, validated at startup, with configuration metadata.Breaking
RetryPolicy,OutboxEntryandOutboxProcessorPropertiesgained parameters, so Kotlincopy/default-argument callers must be recompiled.RouteAwareOutboxStore.claimPendingtakesnow. That interface is new in 2.0, so no released API changes there.Out of scope
The issue also suggests these. Both are additive, so they can ship in a minor release, and I'll open follow-ups:
requeueFailedAPI or Actuator endpoint;Tests
RetryPolicyTest:nextAttemptAt.RouteAwareOutboxProcessorTest: the processor passes its clock'snowto the claim.updateAfterProcessingBatchpersistsnextAttemptAt;HttpEndToEndTest,ObservabilityEndToEndTest) now use an explicit zero-backoff policy../gradlew ktlintCheck testpasses locally, andcompileJmhKotlincompiles.🤖 Generated with Claude Code