fix(clustering): surface silent cache-transport failures and make rewire retryable (#36803) - #36864
Conversation
|
Claude finished @dsolistorres's task in 4m 2s —— View job PR Review — complete
I reviewed the full diff and traced the runtime paths the new counters depend on. No blocking issues found — the change is correct and unusually well tested. Details below. Verifications performed
Notes (non-blocking, no action required)
No issues found. |
Cache invalidations were dropped with no log, no metric and no health signal when the pub/sub cache transport was not initialized, and a failing cluster rewire was logged and forgotten while KNOWN_SERVERS was updated as if it had succeeded (issue #36544 incident). - PubSubCacheTransport.send(): count dropped invalidations and WARN, rate-limited (CACHE_TRANSPORT_DROP_WARN_INTERVAL_MILLIS, default 30s) - PubSubCacheTransport.init(): idempotent - a rewire on a healthy transport no longer tears down/rebuilds the pub/sub listener - ClusterFactory.addMeToCacheIfNeeded(): report success/failure; only update KNOWN_SERVERS on success so failed rewires are retried; track consecutive failures in a counter exposed via getRewireFailures() - New cache-transport health check (MONITOR_MODE by default so it never fails readiness unless an operator opts in via health.check.cache-transport.mode=PRODUCTION - avoids cold-start deadlock) - Micrometer gauges: dotcms.cache.transport.invalidations.dropped, dotcms.cache.transport.initialized, dotcms.cache.transport.rewire.failures Fixes #36803 Co-Authored-By: Claude Fable 5 <noreply@anthropic.com> Claude-Session: https://claude.ai/code/session_01XFuXwYdNsb7irpMEeSGTyj
…ng (#36803) Review follow-ups on the transport health check and metrics. CacheMetrics had no NullTransport guard, so a node with no real transport published transport.initialized=0 -- NullTransport.isInitialized() is false once it has been shut down -- and alerted as if it were dropping invalidations, while CacheTransportHealthCheck reported the same node healthy. Both now agree via a single activeTransport() helper. Both call sites resolved the transport by casting getImplementationObject() to ChainableCacheAdministratorImpl. getTransport() is on the DotCacheAdministrator interface and CommitListenerCacheWrapper delegates it, whereas the cast throws ClassCastException for any other administrator (NullCacheAdministrator.getImplementationObject() returns itself, which is the unit-test path) -- swallowed into a null that happened to produce the right answer. Both now use the interface method, as ClusterResource does. The cast in addMeToCacheIfNeeded stays: setCluster()/testCluster() are not on the interface. A single rewire failure no longer reports DOWN. testCluster() can throw on a momentary database hiccup while the transport stays initialized and invalidations keep flowing, so the check now tolerates health.check.cache-transport.rewire-failure-threshold (default 3) consecutive failures and always reports the count. rewireClusterIfNeeded() now retries whenever REWIRE_FAILURES > 0. The membership comparison alone only fires when the alive-server set changes, so a failure followed by membership settling back to KNOWN_SERVERS was never retried -- the counter could never return to zero and the check would report DOWN indefinitely. performCheck() and buildStructuredData() shared one immutable snapshot instead of each resolving the transport and re-reading the counters. Two independent reads let one health response contradict itself: a message saying the transport is initialized next to structured data saying it is not. Refs: #36803 Co-Authored-By: Claude Opus 5 (1M context) <noreply@anthropic.com>
The PR instrumented only the pre-init drop path. A transport that initialized successfully and then started failing every publish stayed completely invisible: no drops recorded, isInitialized() still true, rewireFailures 0, health check green, other nodes serving stale content. Every provider signals a failed send by returning false rather than throwing -- JDBCPubSubImpl (the default) and PostgresPubSubImpl on an exception or an execute() that returns false, RedisPubSubImpl when stopped -- and PubSubCacheTransport.send() discarded that boolean. Checking it in send() is necessary but not sufficient. DOT_PUBSUB_USE_QUEUE defaults to true, so the provider is normally a QueuingPubSubWrapper whose publish() returns true immediately and completes the real send on a submitter thread, discarding the result. In that configuration send() would read true 100% of the time. So the wrapper now records the outcome of the task it submits, and PubSubCacheTransport sums its own synchronous failures with the provider-reported ones -- exactly one of the two counts any given attempt, so nothing is double counted. Counted per topic, because one provider instance is shared by every topic in the JVM (cache invalidation, OSGi restart, cluster management) and a JVM-wide total could not be attributed to the cache transport. Exposed as CacheTransport.getFailedMessages(), the new dotcms.cache.transport.invalidations.failed gauge, and failedInvalidations in the health check's structured data. Kept distinct from getDroppedMessages() because the two mean different things operationally: dropped is "the transport is down", failed is "the transport believes it is up but sends are erroring". Failed invalidations deliberately do not make the health check unhealthy on their own. The count is cumulative and never resets, so alarming on "greater than zero" would pin a node DOWN forever after one transient error -- the same false-positive class fixed for rewire failures in the previous commit. Alert on the gauge's rate of increase instead. Known gap: RedisStreamsPubSubImpl always returns true (fire-and-forget async xadd), so it reports no failures. Left as-is. Refs: #36803 Co-Authored-By: Claude Opus 5 (1M context) <noreply@anthropic.com>
…ailures (#36803) A node necessarily drops cache invalidations before its transport comes up: caches are invalidated by startup tasks and the starter import long before ClusterFactory wires the cluster and calls PubSubCacheTransport.init(). A first boot against an empty database was measured at ~2,800 of them, and the cumulative counter carried that burst for the life of the node. Two consequences, both of which would land on operators the moment this ships: - getDroppedMessages() reported thousands on a perfectly healthy node, so the counter was useless as an alerting signal -- the exact thing this issue exists to provide. - CacheTransportHealthCheck reported the transport uninitialized for the few seconds between the first poll and cluster wiring. deriveOverallStatus() propagates any DEGRADED component to the overall status, so every pod start would have shown a DEGRADED /dotmgt/health payload. Measured on a local two-node cluster: an 11s window on a fresh boot, 3s on a populated database. Drops from before the first successful init are now retired into a separate startupDroppedMessages counter, and the health check treats a never-yet- initialized transport as still starting up for a configurable grace period (health.check.cache-transport.initialization-grace-period-seconds, default 120). Retiring is deliberately first-init-only. A transport that came up, went down, lost invalidations and recovered has lost real ones; retiring on every re-init would launder genuine loss into the benign startup bucket. Equally, the grace period ends for good once the check has seen an initialized transport -- losing one that had been working is a regression, not a node still booting, and is reported immediately. The transport.initialized gauge is left raw, with no grace period: a gauge states the current fact and alert rules add the duration clause. Noted in the metric description. Refs: #36803
) The review flagged the health check as the largest new file in the PR with no unit coverage, which was fair: its decision logic is the "surface the silent failure" behaviour this issue is about, and nothing pinned it. Ten cases against statically mocked CacheLocator and ClusterFactory, in the style of VelocityHealthCheckTest: - NullTransport reports UP, with the per-transport fields omitted rather than reported as misleading zeros - an unresolvable cache layer reports UP instead of throwing out of the probe - a never-initialized transport reports UP inside the startup grace period and DOWN past it - a transport lost after having been initialized reports DOWN immediately, even with a long grace period configured - rewire failures below the threshold report UP, at the threshold report DOWN - structured data carries every counter monitoring consumes, with startup drops separate from operational ones - the default mode stays MONITOR_MODE and converts DOWN to DEGRADED, pinning the property that keeps a broken transport from draining a node that can still serve traffic - the check is never a liveness check Writing these caught a real defect in the preceding commit: retireStartupDrops() ran on every init, so a transport that went down, lost invalidations and recovered would have had that genuine loss moved into the startup bucket. Fixed there before this commit; test_drops_after_first_init_are_not_retired_by_a_later_init holds the line. Refs: #36803
Review follow-up. init() guarded with a check-then-act -- read initialized, then set it several statements later -- so two threads could both see false and each run start() + subscribe(), double-subscribing the listener. That is the opposite of the churn the idempotent init() was added to remove. Not reachable through today's call graph: init() is reached only via ChainableCacheAdministratorImpl.setCluster() <- addMeToCacheIfNeeded() <- rewireCluster() <- ClusterFactory.rewireClusterIfNeeded(), each with exactly one call site, and the last is static synchronized. Every entry point (ServerHeartbeatJob, FreeServerFromClusterJob, ClusterFactory.initialize() from LicenseManager and the two startup tasks) funnels through that monitor. The verification the reviewer asked for, recorded here because the guarantee is not local to this class: rewireCluster() is public static and not itself synchronized, so a future caller could bypass the lock that makes the race unreachable today. init() and shutdown() are now synchronized. init() runs once per cluster rewire, so the monitor costs nothing. shutdown() shares it because a shutdown landing between init()'s subscribe() and its initialized.set(true) would stop the provider and then be overwritten back to initialized, leaving a transport that reports itself up with nothing listening. Deliberately NOT the compareAndSet form suggested in review (`if (!initialized.compareAndSet(false, true)) return;` with the work after it). Claiming the flag up front means a thrown start() stays flagged as initialized: isInitialized() reports true, shouldReinit() reports false, setCluster() never retries, and the new health check reports a healthy transport that never subscribed -- reintroducing the exact silent failure this issue removes. The flag stays set only after start() and subscribe() return. Two tests, both verified to fail without the change: - test_concurrent_init_starts_and_subscribes_exactly_once: 16 threads released together must produce one start() and one subscribe(). Fails 3/3 runs without the synchronization (observed 3 starts). - test_failed_init_leaves_the_transport_retryable: a throwing start() leaves isInitialized() false and shouldReinit() true, and the next rewire succeeds. This is the test that would fail under the compareAndSet-first form. Refs: #36803
Review follow-up. Writes into QueuingPubSubWrapper.failedByTopic and reads out of it arrive by routes that disagree on case: - recordFailure() keys on the event's topic, which DotPubSubEvent.Builder.withTopic has already lowercased (DotPubSubEvent.java:216) - PubSubCacheTransport.getFailedMessages() looks up this.topic.getTopic(), which is a bare String.valueOf(getKey()) with no normalization (DotPubSubTopic.java:26) They match today only because every current topic key is already lowercase (CacheTransportTopic.CACHE_TOPIC is "dotcache_topic"). A future key with one uppercase character would make the lookup miss silently, and getFailedPublishCount() would report zero failures while cluster invalidations were being lost -- the same class of blind spot this issue exists to remove. Normalized on both sides inside the wrapper, which owns the map, rather than with a .toLowerCase() at the single call site as suggested in review: that would leave every caller needing to know the wrapper's internal key convention, and would fix only the cache topic rather than any future one. DotPubSubProvider documents that the key is matched case-insensitively so other implementations follow suit. test_failure_lookup_is_case_insensitive records a failure through a mixed-case topic and reads it back three ways. Verified to fail without the fix, with exactly the silent under-report described above: AssertionError: and still found when the caller passes the un-normalized topic key expected:<1> but was:<0> Currently a latent fragility, not a live defect. Refs: #36803
Review follow-up: the rewire-retry logic was the least-protected behavioural change in this PR. Only the health check's consumption of REWIRE_FAILURES was tested, not the producer -- and the retry clause is what guarantees a failed cache-transport init keeps being retried, so a regression there would silently restore the "logged and forgotten" failure #36803 targets. It also could not be exercised on the live cluster: ServerHeartbeatJob.execute() calls LicenseUtil.updateLicenseHeartbeat() before rewireClusterIfNeeded(), and that throws when the database is down, so REWIRE_FAILURES can only move while the database is healthy and setCluster()/testCluster() fails -- a window that resisted local reproduction. The decision was an inline condition behind clusterReady(), isEnterprise() and two APILocator calls, so it is extracted into a pure, package-private shouldRewire(aliveServers, knownServers, currentServer, pendingFailures). Behaviour is unchanged; the rationale that was a comment on the condition is now the method's javadoc. Five cases, including the one that motivated the clause: a pending failure forces a retry even when membership has settled back to the stale KNOWN_SERVERS, where the membership comparison alone reports "nothing changed". That test asserts its own precondition first, so it cannot pass for the wrong reason, and it was verified to fail when the pendingFailures clause is removed. Also replaces the raw Collections.EMPTY_LIST on KNOWN_SERVERS with Collections.emptyList() while in this file. Refs: #36803
fb8db88 to
24108d7
Compare
Review follow-upsMoved out of the PR description to keep it readable. Seven commits added after review; full rationale in each commit message. Seven commits added after review. Details in the commit messages.
The original change instrumented only the pre-
Found by running a two-node cluster from this branch (see Deployment impact below). Boot order guarantees dropped invalidations: caches are invalidated by startup tasks and the starter import long before
Addresses the review's medium finding: the largest new file in the PR had no coverage. Ten cases over
The review's second medium: The reviewer asked for verification that concurrent invocation is possible before changing anything. It is not, today —
Deliberately not the
Writes into Normalized on both sides inside the wrapper, which owns the map, rather than with a
The rewire retry was the least-protected change in this PR: only the health check's consumption of The decision was an inline condition behind |
Deployment impactMoved out of the PR description to keep it readable. This is the evidence for the alerting-noise question: what an operator actually sees on a node boot, measured before and after the startup-grace change. Verified on a local two-node cluster (PostgreSQL + OpenSearch, Measured, before the grace period was added — two node boots, one against an empty database and one against a populated one:
The conversion WARN is one per boot, not one per poll — the check is polled less often than the window lasts. HTTP status was unaffected throughout: Measured again after the fix, on a rebuilt image and a fresh two-node cluster (
Both counters now read exactly as intended: the alertable one is 0 on a healthy node and the boot burst is parked in the startup bucket, matching the one-off INFO the transport logs ( Two things the re-measurement corrected in the estimate above. The suppressed window is 17–24 consecutive polls, not the 3–11s inferred from log timestamps — the health result is cached and served for a while after Cluster function was re-verified on the same run: bidirectional PING/PONG between both server IDs, one The pre-existing gaps listed under Known gaps do not change this. The Micrometer registry is never initialized in the current build, so none of the gauges above are exported yet and no gauge-based alert can fire regardless of what this PR registers. |
Proposed Changes
Fixes #36803 — cluster cache invalidations were dropped silently when the pub/sub transport failed, and a persistently failing rewire was logged and forgotten (root cause analysis in #36544).
PubSubCacheTransport.send()no longer discards invalidations silently: increments a dropped-message counter and logs at WARN, rate-limited (CACHE_TRANSPORT_DROP_WARN_INTERVAL_MILLIS, default 30s) so a sustained outage cannot flood the log.PubSubCacheTransport.init()is idempotent: a rewire on an already-healthy transport is a no-op instead of a tear-down/rebuild of the pub/sub listener — this removes the rebuild-per-rewire-pass churn measured in Spike: Cluster re-wire re-inits Postgres pub/sub transport and leaks DB connections → pool exhaustion + startup crash-loop #36544 (LISTEN cluster_actions×3,687).ClusterFactory.addMeToCacheIfNeeded()now reports success/failure instead of swallowing exceptions.KNOWN_SERVERSis only updated on success, andrewireClusterIfNeeded()retries whenever there is a pending failure, so a failed transport init is always retried on the next heartbeat. Consecutive failures are tracked and exposed viaClusterFactory.getRewireFailures()(reset on success).cache-transporthealth check (CacheTransportHealthCheck, registered inCoreHealthCheckProvider): reports unhealthy when the transport is uninitialized or rewires are failing persistently; exposesinitialized/droppedInvalidations/startupDroppedInvalidations/failedInvalidations/rewireFailures/awaitingInitializationas structured data. Nodes with no real transport always report healthy, and a node whose transport has not come up yet is treated as still starting for a grace period rather than reported unhealthy.CacheMetricsbinder:dotcms.cache.transport.invalidations.droppeddotcms.cache.transport.invalidations.dropped.startupdotcms.cache.transport.invalidations.faileddotcms.cache.transport.initializeddotcms.cache.transport.rewire.failuresCacheTransportgainsdefault long getDroppedMessages(),default long getStartupDroppedMessages()anddefault long getFailedMessages()(0 for all other transports).Detail in comments
Two sections were moved out of this description to keep it readable:
Scope note for reviewers
The second follow-up commit widens this PR past the cache subsystem the title implies.
QueuingPubSubWrapperandDotPubSubProviderare shared by every pub/sub topic in the JVM — cache invalidation, OSGi restart (OsgiRestartTopic), and cluster management (ClusterManagementTopic) — so those paths now execute the new code too.The changes there are additive and behaviour-preserving:
DotPubSubProvider.getFailedPublishCount(String)is a newdefaultmethod returning 0, so no existing provider changes behaviour or needs updating.QueuingPubSubWrapper.publish(), the submitted task's body moved intopublishAndRecordOutcome(). The publish call itself, the dedupe cache, the submitter, and the unconditionaltruereturn are all unchanged — the only additions are counting afalsereturn and catching a throw that was previously discarded by the submitter.test_failures_are_attributed_per_topic).Worth a second pair of eyes on that file specifically, since a regression there would affect OSGi restarts and cluster management rather than just cache invalidation.
Readiness and alerting decisions (AC: "decide and document")
The health check defaults to MONITOR_MODE: it reports degradation but never fails readiness probes. A node that cannot send invalidations can still serve traffic, and gating readiness on the transport risks a cold-start deadlock (transport init happens during cluster wiring). Operators who prefer to drain such nodes can opt in with
health.check.cache-transport.mode=PRODUCTION. It is never a liveness check — restarting pods on transport failure is what amplified the #36544 incident.Failed invalidations deliberately do not make the check unhealthy on their own. The count is cumulative and never resets, so alarming on "greater than zero" would pin a node DOWN forever after one transient publish error — the same false-positive class fixed for rewire failures. Alert on the rate of increase of
dotcms.cache.transport.invalidations.failedinstead. Rewire failures do flip the check, but only past a threshold, because that counter resets on success and the rewire is retried every heartbeat.Testing
PubSubCacheTransportTest(unit, 10 cases): drops are counted and not published before init; publish works after init;init()is idempotent (singlestart()across repeated calls, re-inits aftershutdown()); a synchronous publish failure is counted as failed rather than dropped; a successful publish counts neither; an async provider's self-reported failures surface without being double counted; the firstinit()retires pre-init drops into the startup counter; drops after the firstinit()survive a later re-init instead of being laundered into it. Plus the atomic init guard: 16 threads racing intoinit()produce exactly onestart()/subscribe(), and a throwingstart()leaves the transport retryable.ClusterFactoryRewireTest(unit, 5 cases, new): steady state does not rewire; a pending failure forces a retry even when membership looks unchanged; membership join and leave both rewire; a node missing from its own alive set rewires; the first heartbeat rewires.QueuingPubSubWrapperTest(unit, 5 cases): afalsereturn from the wrapped provider is counted even thoughpublish()reported success; a thrown failure is counted rather than lost on the submitter thread; failures are attributed to their own topic and do not inflate the cache topic; successful publishes count nothing and an unused topic reports 0.CacheTransportHealthCheckTest(unit, 10 cases, new): see5aecea7292in Review follow-ups.start()calls withsynchronizedremoved (3/3 runs), the case-normalization one reportsexpected:<1> but was:<0>, and the retry one fails when thependingFailuresclause is dropped. Note that running:dotcms-coreunit tests requires-Dmaven.build.cache.enabled=false— the build-cache extension skipsdependency:properties, which populates${net.bytebuddy:byte-buddy-agent:jar}, leaving a literal-javaagent:path that crashes the surefire fork. Pre-existing and unrelated to this PR (an untouchedDotPubSubEventTestfails identically).ORIGINALfrom cache, thenUPDATED-VIA-NODE1after the invalidation); exactly oneiniting PubSubCacheTransportper node, confirming the idempotentinit()in the real rewire loop; an uninitialized transport is detected and MONITOR_MODE keeps readiness passing; the drop WARN is throttled as intended (2 warnings for 2,841 drops); aNullTransportnode reports UP with the per-transport fields omitted; message and structured data agree on every poll.343865b39e: cutting node 2's link to the database producedfailedInvalidations: 2withinitialized: trueanddroppedInvalidationsunchanged, matching exactly twoUnable to send pubsublog lines — no double counting, correct per-topic attribution, node 1 unaffected atfailed: 0. This ran through the default queued path (DOT_PUBSUB_USE_QUEUEdefaults true). Node 2 recovered fully on reconnect.cache-transportpolls across 6,110 samples on two boots, with the counter split readingdropped: 0 / startupDropped: 2841and0 / 6. Full numbers in Deployment impact.ServerHeartbeatJob.execute()callsLicenseUtil.updateLicenseHeartbeat()beforeClusterFactory.rewireClusterIfNeeded(), and the former throws when the database is down, soREWIRE_FAILUREScannot move during a database outage. It only moves when the database is healthy andsetCluster()/testCluster()fails — a narrow window I could not reproduce locally. The threshold and reset logic are covered by unit tests instead.Known gaps
RedisStreamsPubSubImpl.publish()always returnstrue(fire-and-forget asyncxadd), so it reports no failures. Left as-is; its own design decision.StartupTasksExecutor— Pub/sub listener holds a permanent connection from the shared JDBC pool, exhausting jdbc/dotCMSPool #36801 / PGListener lifecycle: unbounded rebuilds with no backoff, leak window before Thread.start(), stop() allocates, flag-based idempotency guard #36802 still own those.dotcms.*meter is ever registered./dotmgt/metricshas no servlet mapping and returns 404, breakingdocker/docker-compose-examples/single-node-metrics-monitoring.DOT_PUBSUB_PROVIDER_OVERRIDEcannot be set by environment variable, so a container meant to use Redis pub/sub can silently run on JDBC.🤖 Generated with Claude Code
https://claude.ai/code/session_01XFuXwYdNsb7irpMEeSGTyj
This PR fixes: #36803