Skip to content

MODPUBSUB-354 Fix silent event delivery stalls - #318

Closed
shelleydoljack wants to merge 1 commit into
folio-org:masterfrom
shelleydoljack:MODPUBSUB-354-fix-event-delivery-timeouts
Closed

shelleydoljack wants to merge 1 commit into
folio-org:masterfrom
shelleydoljack:MODPUBSUB-354-fix-event-delivery-timeouts

Conversation

@shelleydoljack

Copy link
Copy Markdown

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 a
production 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=true advances offsets on consumption rather than on
successful delivery. The ticket has the full detection story.

The affected code is unchanged between 2.16.x, 2.17.0 and current master.

  1. RestUtil set the WebClient idle timeout to 2000 in a field Vert.x reads as seconds
    (TCPSSLOptions.DEFAULT_IDLE_TIMEOUT_TIME_UNIT), so the intended 2-second timeout was
    ~33 minutes.
  2. The WebClient used default pool settings — DEFAULT_MAX_POOL_SIZE 5 and
    DEFAULT_MAX_WAIT_QUEUE_SIZE -1 (unbounded, untimed) — so five stuck requests blocked
    all outbound HTTP including the system-user login.
  3. getEventReceivedHandler discarded the future returned by deliverEvent, so every failure
    before the POST wrote no audit row and logged nothing.
  4. retryDelivery was reachable only from the delivery-response handler, so failures before
    the first POST were never retried.
  5. An empty x-okapi-token was sent, which a sidecar reads as absent, forcing a redundant
    system-user token fetch on every outbound call.

Approach

Timeouts (RestUtil). Request timeouts are now set per request, in milliseconds, where
there is no unit ambiguity: idleTimeout bounds a stalled exchange and connectTimeout bounds
waiting for a pooled connection (per HttpRequest#connectTimeout, that is the pool-acquisition
deadline, not the TCP connect timeout). The connection-level setIdleTimeout is kept but now
sets setIdleTimeoutUnit(SECONDS) explicitly so the unit is stated at the call site.

Pool (RestUtil). Vert.x 5 moved pool configuration out of WebClientOptions into
PoolOptions, so this uses the three-argument WebClient.create. The per-host limit is raised
to 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 Vertx instance alone silently applied the first caller's timeout to every
subsequent caller.

Discarded future (KafkaConsumerServiceImpl). The delivery future is now consumed, and
failures are logged and audited as REJECTED. This required changing the inner composition to
Future.join(...).otherwiseEmpty(): per-subscriber rejections are already audited and retried
by the delivery handler, and must not also surface as an event-level failure or cancel delivery
to the remaining subscribers.

Retry path (KafkaConsumerServiceImpl). deliverEvent now retries the whole attempt when
it fails before any subscriber has been contacted. Because otherwiseEmpty absorbs POST
failures, only genuinely pre-dispatch failures reach the recover branch, so there is no risk
of duplicate deliveries. retryDelivery had the same discarded-future bug on its own token
fetch; 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 sent
empty. 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
remove would miss X-Okapi-Token; and the map is now a copy, because the previous code
mutated params.getHeaders() in place and those OkapiConnectionParams are cached per tenant
and reused for every event.

New environment variables (pubsub.delivery.retry.delay.ms and pubsub.http.*) are documented
in 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

  • Requesting a backport to b2.16 for a Sunflower CSP. Sunflower ships mod-pubsub
    2.16.3, which is where we hit this in production, and b2.16 is at 2.16.4-SNAPSHOT.
    Master is not an option for us: it pins folio-kafka-wrapper 4.1.0-SNAPSHOT, which has
    not 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) and
    connectTimeout(long), WebClientOptions.setIdleTimeoutUnit, Future.join(List),
    recover, otherwiseEmpty, and the same pool defaults (DEFAULT_MAX_POOL_SIZE 5,
    DEFAULT_MAX_WAIT_QUEUE_SIZE -1). The only API difference is that Vert.x 4 configures
    the pool via WebClientOptions.setMaxPoolSize/setMaxWaitQueueSize instead of
    PoolOptions, so the 2.16 version of getWebClient is actually simpler.
  • Response timeout default is 60s where the effective value was ~33 minutes. If any
    subscriber legitimately holds a callback open longer than 60 seconds, it needs
    pubsub.http.response.timeout.ms raised. Reviewers who know the slowest subscriber
    callback in practice — data-import is the likely candidate — please confirm 60s is safe
    or suggest a better default.
  • Retries now wait 1s (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.
  • No integration-level coverage in my local run. The org.folio.rest.impl.* tests fail
    on my machine with Could not find a valid Docker environment, identically on unmodified
    master, 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 setIdleTimeout in a unit held
in a separate property (setIdleTimeoutUnit, defaulting to seconds), while the adjacent
setConnectTimeout is unconditionally milliseconds. Two timeout setters side by side, in
different 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 unit
argument, 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_UNIT is SECONDS.
  • PoolOptions.DEFAULT_MAX_POOL_SIZE is 5; DEFAULT_MAX_WAIT_QUEUE_SIZE is -1.
  • Pool settings moved from WebClientOptions to io.vertx.core.http.PoolOptions;
    WebClientOptions.setMaxPoolSize no longer exists.
  • HttpRequest.connectTimeout(long) is the pool-acquisition deadline, explicitly not the TCP
    connect timeout, which makes it the right guard for an exhausted pool.

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>
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment

Labels

None yet

Projects

None yet

Development

Successfully merging this pull request may close these issues.

1 participant