MODPUBSUB-354 Fix silent event delivery stalls - #318
Closed
shelleydoljack wants to merge 1 commit into
Closed
shelleydoljack wants to merge 1 commit into
shelleydoljack wants to merge 1 commit into
Conversation
Five defects in the outbound delivery path combined so that a slow subscriber could stall all event delivery, and so that failures before the first request to a subscriber left no trace. Found after a 41-hour silent outage of LOG_RECORD events in production, detected only when a user reported one missing checkout. The WebClient idle timeout was set to 2000 in a field Vert.x reads as seconds, making the intended 2s timeout ~33 minutes. Request timeouts are now set per request in milliseconds, where Vert.x takes no unit argument, and the connection-level setter states its unit explicitly. The client used default pool settings, so five stuck requests exhausted the pool and blocked all outbound HTTP including the system user login, while further requests queued without limit or timeout. Pool config moves to PoolOptions with a larger pool and a bounded wait queue, and requests now time out waiting for a connection. The client cache key includes the connect timeout, which previously applied the first caller's value to every later caller. The future returned by deliverEvent was discarded, so failures before the POST wrote no audit row and logged nothing. It is now consumed, logged and audited as REJECTED. Those failures are also retried, which previously only happened for failures reported by a subscriber, and retries now wait between attempts rather than spending the whole retry budget inside one outage. An empty x-okapi-token is no longer sent, as an empty token is not read as an absent one and forced a redundant system user token fetch on every call. Outbound headers are built case-insensitively into a copy, since OkapiConnectionParams are cached per tenant and were being mutated in place. Co-Authored-By: Claude Opus 5 (1M context) <noreply@anthropic.com>
This file contains hidden or bidirectional Unicode text that may be interpreted or compiled differently than what appears below. To review, open the file in an editor that reveals hidden Unicode characters.
Learn more about bidirectional Unicode characters
Sign up for free
to join this conversation on GitHub.
Already have an account?
Sign in to comment
Add this suggestion to a batch that can be applied as a single commit.This suggestion is invalid because no changes were made to the code.Suggestions cannot be applied while the pull request is closed.Suggestions cannot be applied while viewing a subset of changes.Only one suggestion per line can be applied in a batch.Add this suggestion to a batch that can be applied as a single commit.Applying suggestions on deleted lines is not supported.You must change the existing code in this line in order to create a valid suggestion.Outdated suggestions cannot be applied.This suggestion has been applied or marked resolved.Suggestions cannot be applied from pending reviews.Suggestions cannot be applied on multi-line comments.Suggestions cannot be applied while the pull request is queued to merge.Suggestion cannot be applied right now. Please check back later.
Purpose
Fixes MODPUBSUB-354.
Five defects in the outbound event-delivery path combine so that a slow or unresponsive
subscriber can stall all event delivery, and so that failures occurring before the first
request to a subscriber leave no log line and no audit record. Individually each is minor;
together they make the failure mode invisible.
These were found after a 41-hour silent outage of circulation log (
LOG_RECORD) events in aproduction Eureka deployment, detected only when a user reported one missing checkout. No
routine health signal shows anything during the outage — in particular Kafka consumer lag
cannot, because
enable.auto.commit=trueadvances offsets on consumption rather than onsuccessful delivery. The ticket has the full detection story.
The affected code is unchanged between 2.16.x, 2.17.0 and current
master.RestUtilset theWebClientidle timeout to2000in a field Vert.x reads as seconds(
TCPSSLOptions.DEFAULT_IDLE_TIMEOUT_TIME_UNIT), so the intended 2-second timeout was~33 minutes.
WebClientused default pool settings —DEFAULT_MAX_POOL_SIZE5 andDEFAULT_MAX_WAIT_QUEUE_SIZE-1(unbounded, untimed) — so five stuck requests blockedall outbound HTTP including the system-user login.
getEventReceivedHandlerdiscarded the future returned bydeliverEvent, so every failurebefore the POST wrote no audit row and logged nothing.
retryDeliverywas reachable only from the delivery-response handler, so failures beforethe first POST were never retried.
x-okapi-tokenwas sent, which a sidecar reads as absent, forcing a redundantsystem-user token fetch on every outbound call.
Approach
Timeouts (
RestUtil). Request timeouts are now set per request, in milliseconds, wherethere is no unit ambiguity:
idleTimeoutbounds a stalled exchange andconnectTimeoutboundswaiting for a pooled connection (per
HttpRequest#connectTimeout, that is the pool-acquisitiondeadline, not the TCP connect timeout). The connection-level
setIdleTimeoutis kept but nowsets
setIdleTimeoutUnit(SECONDS)explicitly so the unit is stated at the call site.Pool (
RestUtil). Vert.x 5 moved pool configuration out ofWebClientOptionsintoPoolOptions, so this uses the three-argumentWebClient.create. The per-host limit is raisedto 100 and the wait queue bounded at 1000, so a saturated pool fails fast — and audibly —
instead of parking requests forever. The client cache key now includes the connect timeout;
keying on the
Vertxinstance alone silently applied the first caller's timeout to everysubsequent caller.
Discarded future (
KafkaConsumerServiceImpl). The delivery future is now consumed, andfailures are logged and audited as
REJECTED. This required changing the inner composition toFuture.join(...).otherwiseEmpty(): per-subscriber rejections are already audited and retriedby the delivery handler, and must not also surface as an event-level failure or cancel delivery
to the remaining subscribers.
Retry path (
KafkaConsumerServiceImpl).deliverEventnow retries the whole attempt whenit fails before any subscriber has been contacted. Because
otherwiseEmptyabsorbs POSTfailures, only genuinely pre-dispatch failures reach the
recoverbranch, so there is no riskof duplicate deliveries.
retryDeliveryhad the same discarded-future bug on its own tokenfetch; that failure is now audited too. Retries also wait between attempts rather than firing
immediately, so the retry budget is not spent inside a single outage.
Token header (
RestUtil). The header is omitted when the token is blank rather than sentempty. Two related problems surfaced while making this change: the header map is now keyed
case-insensitively, because inbound Okapi headers do not agree on casing and a lowercase
removewould missX-Okapi-Token; and the map is now a copy, because the previous codemutated
params.getHeaders()in place and thoseOkapiConnectionParamsare cached per tenantand reused for every event.
New environment variables (
pubsub.delivery.retry.delay.msandpubsub.http.*) are documentedin the README. All defaults apply when unset.
Deployment risk. The module descriptor is untouched — no interface version changes on either
the provides or requires side, and no new permissions — and there are no database schema
changes, so the upgrade is reversible. The behaviour changes are confined to the two TODOs
below.
TODOS and Open Questions
b2.16for a Sunflower CSP. Sunflower ships mod-pubsub2.16.3, which is where we hit this in production, and
b2.16is at 2.16.4-SNAPSHOT.Master is not an option for us: it pins
folio-kafka-wrapper 4.1.0-SNAPSHOT, which hasnot been released (latest release is 4.0.0), and 2.17+ is Trillium-era. The backport
looks cheap — I verified against the Vert.x 4.5.23 jars that everything this change
relies on already exists there:
HttpRequest.idleTimeout(long)andconnectTimeout(long),WebClientOptions.setIdleTimeoutUnit,Future.join(List),recover,otherwiseEmpty, and the same pool defaults (DEFAULT_MAX_POOL_SIZE5,DEFAULT_MAX_WAIT_QUEUE_SIZE-1). The only API difference is that Vert.x 4 configuresthe pool via
WebClientOptions.setMaxPoolSize/setMaxWaitQueueSizeinstead ofPoolOptions, so the 2.16 version ofgetWebClientis actually simpler.subscriber legitimately holds a callback open longer than 60 seconds, it needs
pubsub.http.response.timeout.msraised. Reviewers who know the slowest subscribercallback in practice — data-import is the likely candidate — please confirm 60s is safe
or suggest a better default.
pubsub.delivery.retry.delay.ms) instead of firing immediately.This is a deliberate behaviour change; happy to drop it to 0 to keep the previous timing
if preferred.
org.folio.rest.impl.*tests failon my machine with
Could not find a valid Docker environment, identically on unmodifiedmaster, so it is an environment problem rather than a regression. The 50 unit tests pass.Please confirm CI is green.
Learning
The root cause of the timeout defect is that Vert.x expresses
setIdleTimeoutin a unit heldin a separate property (
setIdleTimeoutUnit, defaulting to seconds), while the adjacentsetConnectTimeoutis unconditionally milliseconds. Two timeout setters side by side, indifferent units, with the unit for one of them stored elsewhere. The fix leans on the
HttpRequest-level timeouts instead, which are documented as milliseconds and take no unitargument, and states the unit explicitly wherever the options-level setter is still used.
Relevant Vert.x 5 API notes, verified against the 5.0.12 jars rather than the 4.x docs:
io.vertx.core.net.TCPSSLOptions.DEFAULT_IDLE_TIMEOUT_TIME_UNITisSECONDS.PoolOptions.DEFAULT_MAX_POOL_SIZEis 5;DEFAULT_MAX_WAIT_QUEUE_SIZEis-1.WebClientOptionstoio.vertx.core.http.PoolOptions;WebClientOptions.setMaxPoolSizeno longer exists.HttpRequest.connectTimeout(long)is the pool-acquisition deadline, explicitly not the TCPconnect timeout, which makes it the right guard for an exhausted pool.