Conversation
SecureLogging.maskSensitive ran unconditionally inside every info/warn/ error/debug/trace override in MdcLoggable, regardless of whether the underlying logger would actually emit the message. Each call walked the message through roughly 19 sequential regex passes, so any code path logging at DEBUG/TRACE volume paid that cost even with those levels disabled, and paid it every single time when they were enabled. Gate each level on the underlying logger's isXEnabled plus a new RedisLogger.isEnabled check (Redis log shipping is an independent sink with its own per-level queues, so it must still receive a level's messages when enabled even if the local logger threshold is higher). When neither sink wants the message, the call-by-name msg argument is never evaluated and maskSensitive never runs. Behaviour is unchanged when a level is actually enabled.
MdcLoggable's isXEnabled-or-RedisLogger.isEnabled gate treated Redis log shipping as all-or-nothing: turning redis_logging_enabled on for a deployment made every DEBUG/TRACE call site ship to Redis regardless of the local logger's own level, defeating the level check this same change just added for the local-logger-only case. On a deployment that enables Redis shipping and also happens to log at high DEBUG/TRACE volume, that reintroduces the same masking cost the isXEnabled gate was meant to remove. Add a configurable floor (redis_logging_min_level, default INFO) and RedisLogger.shouldShip(level), and use it in place of the blanket isEnabled check both in MdcLoggable and inside logAsync itself. Redis shipping still works exactly as before for INFO and up; DEBUG/TRACE now also need the floor lowered explicitly, not just the switch flipped on.
1 task
shouldShip compares levels by LogLevel.id, which depends on Scala Enumeration's declaration-order id assignment matching severity order -- nothing about the Enumeration itself enforces that, so pin it explicitly. Also covers the actually-testable half of shouldShip: with Redis log shipping disabled (this suite's default, and the production-safe default), it returns false for every level, including ALL. The props-driven half (redis_logging_enabled / redis_logging_min_level) isn't covered here: RedisLogger's config vals are read once on first JVM access to the object, and something during boot has almost certainly already touched it before any test runs, so changing props at test time has no effect on what's already cached. That part was verified by hand against the actual deployed jar over SSH instead.
3 tasks
Once a log call passes the level/Redis-shipping gate added earlier in this branch, SecureLogging.maskSensitive and the local/Redis write still ran inline on whatever thread called logger.debug/info/etc. On this codebase's http4s/cats-effect request path that's often a fiber-managed worker thread; non-yielding CPU-bound work run directly on it is indistinguishable, from the runtime's own fairness/starvation detector, from genuine blocking I/O. cats-effect's runtime responds to detected starvation by spinning up additional compensating worker/ blocker threads that are never reclaimed -- observed directly during the NMB incident investigation as io-compute-blocker-* thread counts climbing into the thousands, and traced independently via a heap dump to hundreds of threads each holding their own private Scala-reflection symbol-table cache in thread-local storage. cats.effect.IO.blocking isn't the right tool here: MdcLoggable is mixed into ~260 classes, many called from contexts with no IO runtime in scope at all (actors, scheduled jobs, Lift-era code), so nothing would ever run an IO value in those contexts. Dispatch onto a small dedicated ExecutionContext instead -- works everywhere the trait itself is used, mirrors the pattern RedisLogger already uses for its own async shipping, and decouples the calling thread regardless of what kind of thread it happens to be. Writing MdcLoggableDispatchTest caught a second, unrelated real bug before it shipped: the new executor was a plain val, but Helper's own static initializer transitively touches other objects (APIUtil/ Constant) that log during their own initialization -- a call that can re-enter Helper's initialization before a val at this point in the object body would have run, throwing a NullPointerException on the executor. Changed to lazy val, which computes on first real use instead of at a fixed point in top-to-bottom initialization order.
|
Owner
Author
|
Superseded — squashed together with #103 and #104 into one combined commit, PR'd upstream directly: OpenBankProject#2920 |
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
1 participant
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.
Summary
org.json4s.native.Serialization.write) still ran inline on whatever thread called into the logger. On this codebase's http4s/cats-effect request path that's frequently a fiber-managed worker thread; non-yielding CPU-bound work run directly on it looks identical, from the runtime's own fairness/starvation detector, to genuine blocking I/O. cats-effect's response to detected starvation is to spin up additional compensating worker/blocker threads that are never reclaimed -- observed directly during the incident this PR traces back to (io-compute-blocker-*thread counts climbing into the thousands), and independently confirmed via a heap dump: hundreds of threads each holding their own private Scala-reflection symbol-table cache in thread-local storage, accounting for most of a ~7.7GB old-gen.Change
RedisLogger.isEnabled/RedisLogger.shouldShip(level)plus a newredis_logging_min_levelprop (defaultINFO). Redis log shipping is an independent sink with its own per-level queues, so a level must still reach it when Redis shipping is on -- but shouldn't force DEBUG/TRACE volume through just because the switch is on, since that reintroduces the same masking cost the level gate below is meant to remove.MdcLoggablelevel (info/warn/error/debug/trace, including the Throwable overloads) onunderlyingLogger.isXEnabled || RedisLogger.shouldShip(level). When neither sink wants the message, the call-by-namemsgargument is never evaluated andmaskSensitivenever runs. Behaviour is unchanged when a level is actually enabled.ExecutionContext(mdc_logging_dispatch_thread_pool_size, default 2) instead of running inline on the calling thread -- the same patternRedisLoggeralready uses for its own async shipping.cats.effect.IO.blockingisn't an option here:MdcLoggableis mixed into ~260 classes, many called from contexts with no IO runtime in scope at all (actors, scheduled jobs, Lift-era code), so nothing would ever run anIOvalue in those contexts. A plain backgroundExecutionContextworks everywhere the trait itself is used.AsyncAppender, Log4j2'sAsyncLogger); this was never a strict ordering guarantee once Redis shipping (already async) was in the picture.Test plan
mvn -pl obp-commons,obp-api -am compile -DskipTests -o-- BUILD SUCCESSRedisLoggerShouldShipTest(4/4) -- pinsLogLevel's declaration-order-as-severity-order invariantshouldShipdepends on, and the disabled-state contract.MdcLoggableDispatchTest(1/1) -- verifies an enabled log call actually reaches the underlying logger asynchronously, on a thread other than the caller's. Caught a real bug before it shipped: the new executor was a plainval, butHelper's own static initializer transitively touches other objects (APIUtil/Constant) that log during their own initialization, re-enteringHelper's init before thevalat that point in the object body had run -- aNullPointerExceptionon every such call. Fixed by making itlazy val.