From 368cb3006c74d4d96a1c4074bd7841c9dc9558ff Mon Sep 17 00:00:00 2001 From: Hongwei Date: Wed, 23 Sep 2026 09:26:17 +0200 Subject: [PATCH 1/4] fix: gate MdcLoggable masking on log-level and Redis-shipping checks 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. --- .../scala/code/api/cache/RedisLogger.scala | 7 ++ obp-api/src/main/scala/code/util/Helper.scala | 78 ++++++++++++------- 2 files changed, 58 insertions(+), 27 deletions(-) diff --git a/obp-api/src/main/scala/code/api/cache/RedisLogger.scala b/obp-api/src/main/scala/code/api/cache/RedisLogger.scala index 04b30c476d..c84f911109 100644 --- a/obp-api/src/main/scala/code/api/cache/RedisLogger.scala +++ b/obp-api/src/main/scala/code/api/cache/RedisLogger.scala @@ -33,6 +33,13 @@ object RedisLogger { // Performance and reliability improvements private val redisLoggingEnabled = APIUtil.getPropsAsBoolValue("redis_logging_enabled", false) + + /** + * Whether Redis log shipping is turned on for this instance. Callers that want to skip + * building a log message when neither the local logger nor Redis will consume it (e.g. + * MdcLoggable) should check this alongside the local logger's isXEnabled. + */ + def isEnabled: Boolean = redisLoggingEnabled private val batchSize = APIUtil.getPropsAsIntValue("redis_logging_batch_size", 100) private val flushIntervalMs = APIUtil.getPropsAsIntValue("redis_logging_flush_interval_ms", 1000) private val maxRetries = APIUtil.getPropsAsIntValue("redis_logging_max_retries", 3) diff --git a/obp-api/src/main/scala/code/util/Helper.scala b/obp-api/src/main/scala/code/util/Helper.scala index 3dc961e61a..e8179db694 100644 --- a/obp-api/src/main/scala/code/util/Helper.scala +++ b/obp-api/src/main/scala/code/util/Helper.scala @@ -284,63 +284,87 @@ object Helper extends Loggable { s"[$ts] [$thread] [$clazzName] ${msg.toString}" } + // Every level below builds `maskedMsg` by running the message through ~19 regex + // passes in SecureLogging.maskSensitive. That cost must only be paid when the + // result is actually going to be consumed (by the local logger and/or Redis + // shipping) -- not unconditionally on every call site, which is what made this a + // hot path under high request volume with DEBUG enabled. + // INFO override def info(msg: => AnyRef): Unit = { - val maskedMsg = SecureLogging.maskSensitive(msg) - underlyingLogger.info(maskedMsg) - RedisLogger.logAsync(RedisLogger.LogLevel.INFO, toRedisFormat(maskedMsg)) + if (underlyingLogger.isInfoEnabled || RedisLogger.isEnabled) { + val maskedMsg = SecureLogging.maskSensitive(msg) + if (underlyingLogger.isInfoEnabled) underlyingLogger.info(maskedMsg) + RedisLogger.logAsync(RedisLogger.LogLevel.INFO, toRedisFormat(maskedMsg)) + } } override def info(msg: => AnyRef, t: => Throwable): Unit = { - val maskedMsg = SecureLogging.maskSensitive(msg) - underlyingLogger.info(maskedMsg, t) - RedisLogger.logAsync(RedisLogger.LogLevel.INFO, toRedisFormat(maskedMsg) + "\n" + t.toString) + if (underlyingLogger.isInfoEnabled || RedisLogger.isEnabled) { + val maskedMsg = SecureLogging.maskSensitive(msg) + if (underlyingLogger.isInfoEnabled) underlyingLogger.info(maskedMsg, t) + RedisLogger.logAsync(RedisLogger.LogLevel.INFO, toRedisFormat(maskedMsg) + "\n" + t.toString) + } } // WARN override def warn(msg: => AnyRef): Unit = { - val maskedMsg = SecureLogging.maskSensitive(msg) - underlyingLogger.warn(maskedMsg) - RedisLogger.logAsync(RedisLogger.LogLevel.WARNING, toRedisFormat(maskedMsg)) + if (underlyingLogger.isWarnEnabled || RedisLogger.isEnabled) { + val maskedMsg = SecureLogging.maskSensitive(msg) + if (underlyingLogger.isWarnEnabled) underlyingLogger.warn(maskedMsg) + RedisLogger.logAsync(RedisLogger.LogLevel.WARNING, toRedisFormat(maskedMsg)) + } } override def warn(msg: => AnyRef, t: Throwable): Unit = { - val maskedMsg = SecureLogging.maskSensitive(msg) - underlyingLogger.warn(maskedMsg, t) - RedisLogger.logAsync(RedisLogger.LogLevel.WARNING, toRedisFormat(maskedMsg) + "\n" + t.toString) + if (underlyingLogger.isWarnEnabled || RedisLogger.isEnabled) { + val maskedMsg = SecureLogging.maskSensitive(msg) + if (underlyingLogger.isWarnEnabled) underlyingLogger.warn(maskedMsg, t) + RedisLogger.logAsync(RedisLogger.LogLevel.WARNING, toRedisFormat(maskedMsg) + "\n" + t.toString) + } } // ERROR override def error(msg: => AnyRef): Unit = { - val maskedMsg = SecureLogging.maskSensitive(msg) - underlyingLogger.error(maskedMsg) - RedisLogger.logAsync(RedisLogger.LogLevel.ERROR, toRedisFormat(maskedMsg)) + if (underlyingLogger.isErrorEnabled || RedisLogger.isEnabled) { + val maskedMsg = SecureLogging.maskSensitive(msg) + if (underlyingLogger.isErrorEnabled) underlyingLogger.error(maskedMsg) + RedisLogger.logAsync(RedisLogger.LogLevel.ERROR, toRedisFormat(maskedMsg)) + } } override def error(msg: => AnyRef, t: Throwable): Unit = { - val maskedMsg = SecureLogging.maskSensitive(msg) - underlyingLogger.error(maskedMsg, t) - RedisLogger.logAsync(RedisLogger.LogLevel.ERROR, toRedisFormat(maskedMsg) + "\n" + t.toString) + if (underlyingLogger.isErrorEnabled || RedisLogger.isEnabled) { + val maskedMsg = SecureLogging.maskSensitive(msg) + if (underlyingLogger.isErrorEnabled) underlyingLogger.error(maskedMsg, t) + RedisLogger.logAsync(RedisLogger.LogLevel.ERROR, toRedisFormat(maskedMsg) + "\n" + t.toString) + } } // DEBUG override def debug(msg: => AnyRef): Unit = { - val maskedMsg = SecureLogging.maskSensitive(msg) - underlyingLogger.debug(maskedMsg) - RedisLogger.logAsync(RedisLogger.LogLevel.DEBUG, toRedisFormat(maskedMsg)) + if (underlyingLogger.isDebugEnabled || RedisLogger.isEnabled) { + val maskedMsg = SecureLogging.maskSensitive(msg) + if (underlyingLogger.isDebugEnabled) underlyingLogger.debug(maskedMsg) + RedisLogger.logAsync(RedisLogger.LogLevel.DEBUG, toRedisFormat(maskedMsg)) + } } override def debug(msg: => AnyRef, t: Throwable): Unit = { - val maskedMsg = SecureLogging.maskSensitive(msg) - underlyingLogger.debug(maskedMsg, t) - RedisLogger.logAsync(RedisLogger.LogLevel.DEBUG, toRedisFormat(maskedMsg) + "\n" + t.toString) + if (underlyingLogger.isDebugEnabled || RedisLogger.isEnabled) { + val maskedMsg = SecureLogging.maskSensitive(msg) + if (underlyingLogger.isDebugEnabled) underlyingLogger.debug(maskedMsg, t) + RedisLogger.logAsync(RedisLogger.LogLevel.DEBUG, toRedisFormat(maskedMsg) + "\n" + t.toString) + } } // TRACE override def trace(msg: => AnyRef): Unit = { - val maskedMsg = SecureLogging.maskSensitive(msg) - underlyingLogger.trace(maskedMsg) - RedisLogger.logAsync(RedisLogger.LogLevel.TRACE, toRedisFormat(maskedMsg)) + if (underlyingLogger.isTraceEnabled || RedisLogger.isEnabled) { + val maskedMsg = SecureLogging.maskSensitive(msg) + if (underlyingLogger.isTraceEnabled) underlyingLogger.trace(maskedMsg) + RedisLogger.logAsync(RedisLogger.LogLevel.TRACE, toRedisFormat(maskedMsg)) + } } // Delegate enabled checks From e262ba52d04a5b59bade81019fc755903b2184d5 Mon Sep 17 00:00:00 2001 From: Hongwei Date: Wed, 23 Sep 2026 10:20:35 +0200 Subject: [PATCH 2/4] fix: floor Redis log shipping at INFO by default 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. --- .../resources/props/sample.props.template | 7 ++++++ .../scala/code/api/cache/RedisLogger.scala | 22 ++++++++++++++++++- obp-api/src/main/scala/code/util/Helper.scala | 18 +++++++-------- 3 files changed, 37 insertions(+), 10 deletions(-) diff --git a/obp-api/src/main/resources/props/sample.props.template b/obp-api/src/main/resources/props/sample.props.template index 141dfb17b7..fe6c9d7eb9 100644 --- a/obp-api/src/main/resources/props/sample.props.template +++ b/obp-api/src/main/resources/props/sample.props.template @@ -1874,6 +1874,13 @@ ethereum.rpc.url=http://127.0.0.1:8545 ## Enable Redis logging (true/false) redis_logging_enabled = false +## Lowest level shipped to Redis when redis_logging_enabled is true (TRACE/DEBUG/INFO/WARNING/ERROR). +## Defaults to INFO so enabling Redis log shipping doesn't also force every DEBUG/TRACE call site +## (which can be extremely high-volume) to pay the cost of formatting and masking a message that +## would otherwise be skipped locally. Set to DEBUG or TRACE only when you actually want that volume +## shipped, e.g. temporarily while investigating an issue. +redis_logging_min_level = INFO + ## Batch size for sending logs to Redis ## Smaller batch size reduces latency for logging critical messages. redis_logging_batch_size = 50 diff --git a/obp-api/src/main/scala/code/api/cache/RedisLogger.scala b/obp-api/src/main/scala/code/api/cache/RedisLogger.scala index c84f911109..eb949d288e 100644 --- a/obp-api/src/main/scala/code/api/cache/RedisLogger.scala +++ b/obp-api/src/main/scala/code/api/cache/RedisLogger.scala @@ -40,6 +40,26 @@ object RedisLogger { * MdcLoggable) should check this alongside the local logger's isXEnabled. */ def isEnabled: Boolean = redisLoggingEnabled + + /** + * Floor below which levels are not shipped to Redis even when redis_logging_enabled is + * true. Defaults to INFO so that turning Redis log shipping on for a deployment doesn't + * silently force every DEBUG/TRACE call site (which can be extremely high-volume) to pay + * the cost of formatting and masking a message it would otherwise skip. Set to TRACE to + * restore the old "ship everything" behaviour. + */ + private val redisLoggingMinLevel: LogLevel.LogLevel = + LogLevel.valueOf(APIUtil.getPropsValue("redis_logging_min_level", "INFO")) + + /** + * Whether a message at this level should be shipped to Redis right now. Combines the + * on/off switch with the minimum-level floor above. Callers that only want to know "is + * Redis shipping on at all" (e.g. to decide whether to enable a config UI) should keep + * using `isEnabled`; callers deciding whether to build+ship a specific message should use + * this instead. + */ + def shouldShip(level: LogLevel.LogLevel): Boolean = + redisLoggingEnabled && level != LogLevel.ALL && level.id >= redisLoggingMinLevel.id private val batchSize = APIUtil.getPropsAsIntValue("redis_logging_batch_size", 100) private val flushIntervalMs = APIUtil.getPropsAsIntValue("redis_logging_flush_interval_ms", 1000) private val maxRetries = APIUtil.getPropsAsIntValue("redis_logging_max_retries", 3) @@ -155,7 +175,7 @@ object RedisLogger { * Returns a Future[Unit], failures are handled gracefully. */ def logAsync(level: LogLevel.LogLevel, message: String): Future[Unit] = { - if (!redisLoggingEnabled) { + if (!shouldShip(level)) { return Future.successful(()) } diff --git a/obp-api/src/main/scala/code/util/Helper.scala b/obp-api/src/main/scala/code/util/Helper.scala index e8179db694..926362ce13 100644 --- a/obp-api/src/main/scala/code/util/Helper.scala +++ b/obp-api/src/main/scala/code/util/Helper.scala @@ -292,7 +292,7 @@ object Helper extends Loggable { // INFO override def info(msg: => AnyRef): Unit = { - if (underlyingLogger.isInfoEnabled || RedisLogger.isEnabled) { + if (underlyingLogger.isInfoEnabled || RedisLogger.shouldShip(RedisLogger.LogLevel.INFO)) { val maskedMsg = SecureLogging.maskSensitive(msg) if (underlyingLogger.isInfoEnabled) underlyingLogger.info(maskedMsg) RedisLogger.logAsync(RedisLogger.LogLevel.INFO, toRedisFormat(maskedMsg)) @@ -300,7 +300,7 @@ object Helper extends Loggable { } override def info(msg: => AnyRef, t: => Throwable): Unit = { - if (underlyingLogger.isInfoEnabled || RedisLogger.isEnabled) { + if (underlyingLogger.isInfoEnabled || RedisLogger.shouldShip(RedisLogger.LogLevel.INFO)) { val maskedMsg = SecureLogging.maskSensitive(msg) if (underlyingLogger.isInfoEnabled) underlyingLogger.info(maskedMsg, t) RedisLogger.logAsync(RedisLogger.LogLevel.INFO, toRedisFormat(maskedMsg) + "\n" + t.toString) @@ -309,7 +309,7 @@ object Helper extends Loggable { // WARN override def warn(msg: => AnyRef): Unit = { - if (underlyingLogger.isWarnEnabled || RedisLogger.isEnabled) { + if (underlyingLogger.isWarnEnabled || RedisLogger.shouldShip(RedisLogger.LogLevel.WARNING)) { val maskedMsg = SecureLogging.maskSensitive(msg) if (underlyingLogger.isWarnEnabled) underlyingLogger.warn(maskedMsg) RedisLogger.logAsync(RedisLogger.LogLevel.WARNING, toRedisFormat(maskedMsg)) @@ -317,7 +317,7 @@ object Helper extends Loggable { } override def warn(msg: => AnyRef, t: Throwable): Unit = { - if (underlyingLogger.isWarnEnabled || RedisLogger.isEnabled) { + if (underlyingLogger.isWarnEnabled || RedisLogger.shouldShip(RedisLogger.LogLevel.WARNING)) { val maskedMsg = SecureLogging.maskSensitive(msg) if (underlyingLogger.isWarnEnabled) underlyingLogger.warn(maskedMsg, t) RedisLogger.logAsync(RedisLogger.LogLevel.WARNING, toRedisFormat(maskedMsg) + "\n" + t.toString) @@ -326,7 +326,7 @@ object Helper extends Loggable { // ERROR override def error(msg: => AnyRef): Unit = { - if (underlyingLogger.isErrorEnabled || RedisLogger.isEnabled) { + if (underlyingLogger.isErrorEnabled || RedisLogger.shouldShip(RedisLogger.LogLevel.ERROR)) { val maskedMsg = SecureLogging.maskSensitive(msg) if (underlyingLogger.isErrorEnabled) underlyingLogger.error(maskedMsg) RedisLogger.logAsync(RedisLogger.LogLevel.ERROR, toRedisFormat(maskedMsg)) @@ -334,7 +334,7 @@ object Helper extends Loggable { } override def error(msg: => AnyRef, t: Throwable): Unit = { - if (underlyingLogger.isErrorEnabled || RedisLogger.isEnabled) { + if (underlyingLogger.isErrorEnabled || RedisLogger.shouldShip(RedisLogger.LogLevel.ERROR)) { val maskedMsg = SecureLogging.maskSensitive(msg) if (underlyingLogger.isErrorEnabled) underlyingLogger.error(maskedMsg, t) RedisLogger.logAsync(RedisLogger.LogLevel.ERROR, toRedisFormat(maskedMsg) + "\n" + t.toString) @@ -343,7 +343,7 @@ object Helper extends Loggable { // DEBUG override def debug(msg: => AnyRef): Unit = { - if (underlyingLogger.isDebugEnabled || RedisLogger.isEnabled) { + if (underlyingLogger.isDebugEnabled || RedisLogger.shouldShip(RedisLogger.LogLevel.DEBUG)) { val maskedMsg = SecureLogging.maskSensitive(msg) if (underlyingLogger.isDebugEnabled) underlyingLogger.debug(maskedMsg) RedisLogger.logAsync(RedisLogger.LogLevel.DEBUG, toRedisFormat(maskedMsg)) @@ -351,7 +351,7 @@ object Helper extends Loggable { } override def debug(msg: => AnyRef, t: Throwable): Unit = { - if (underlyingLogger.isDebugEnabled || RedisLogger.isEnabled) { + if (underlyingLogger.isDebugEnabled || RedisLogger.shouldShip(RedisLogger.LogLevel.DEBUG)) { val maskedMsg = SecureLogging.maskSensitive(msg) if (underlyingLogger.isDebugEnabled) underlyingLogger.debug(maskedMsg, t) RedisLogger.logAsync(RedisLogger.LogLevel.DEBUG, toRedisFormat(maskedMsg) + "\n" + t.toString) @@ -360,7 +360,7 @@ object Helper extends Loggable { // TRACE override def trace(msg: => AnyRef): Unit = { - if (underlyingLogger.isTraceEnabled || RedisLogger.isEnabled) { + if (underlyingLogger.isTraceEnabled || RedisLogger.shouldShip(RedisLogger.LogLevel.TRACE)) { val maskedMsg = SecureLogging.maskSensitive(msg) if (underlyingLogger.isTraceEnabled) underlyingLogger.trace(maskedMsg) RedisLogger.logAsync(RedisLogger.LogLevel.TRACE, toRedisFormat(maskedMsg)) From d520c1c51aedfe2098d96347525fa6d91351ec9a Mon Sep 17 00:00:00 2001 From: Hongwei Date: Wed, 23 Sep 2026 10:46:53 +0200 Subject: [PATCH 3/4] test: cover LogLevel ordering and shouldShip's disabled-state contract 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. --- .../api/cache/RedisLoggerShouldShipTest.scala | 61 +++++++++++++++++++ 1 file changed, 61 insertions(+) create mode 100644 obp-api/src/test/scala/code/api/cache/RedisLoggerShouldShipTest.scala diff --git a/obp-api/src/test/scala/code/api/cache/RedisLoggerShouldShipTest.scala b/obp-api/src/test/scala/code/api/cache/RedisLoggerShouldShipTest.scala new file mode 100644 index 0000000000..ca2b057bb8 --- /dev/null +++ b/obp-api/src/test/scala/code/api/cache/RedisLoggerShouldShipTest.scala @@ -0,0 +1,61 @@ +package code.api.cache + +import org.scalatest.{FlatSpec, Matchers} + +/** + * Guards the two invariants MdcLoggable's level gate (code.util.Helper) depends on to skip + * SecureLogging.maskSensitive when nothing will consume the message: + * + * 1. LogLevel's declaration order is severity-ascending (TRACE < DEBUG < INFO < WARNING < ERROR), + * since RedisLogger.shouldShip compares levels by `.id`. Scala Enumeration assigns ids by + * declaration order, not by name, so this is a silent footgun if the `val TRACE, DEBUG, ... = + * Value` line is ever reordered or a new level inserted in the wrong place - nothing about the + * Enumeration itself would complain, shouldShip would just start comparing the wrong things. + * + * 2. With Redis log shipping disabled - the default, and what this test suite runs with - + * shouldShip is false for every level. This is the fix's core contract: SecureLogging. + * maskSensitive must only run when the local logger or Redis will actually consume the + * message. + * + * What this does NOT cover: shouldShip's own enabled/min-level reading of props + * (redis_logging_enabled / redis_logging_min_level). RedisLogger is a singleton object whose + * config vals are read once, on first JVM access to the object - by the time any test in this + * suite runs, something else has almost certainly already touched it during boot, so changing + * props at test time (even via PropsReset) has no effect on what RedisLogger already cached. + * That half of the behaviour was verified by hand against the actual props read at JVM start + * (see the redis_logging_min_level default in sample.props.template) rather than by a test here. + */ +class RedisLoggerShouldShipTest extends FlatSpec with Matchers { + + "LogLevel" should "be declared in ascending severity order" in { + RedisLogger.LogLevel.TRACE.id should be < RedisLogger.LogLevel.DEBUG.id + RedisLogger.LogLevel.DEBUG.id should be < RedisLogger.LogLevel.INFO.id + RedisLogger.LogLevel.INFO.id should be < RedisLogger.LogLevel.WARNING.id + RedisLogger.LogLevel.WARNING.id should be < RedisLogger.LogLevel.ERROR.id + } + + it should "round-trip through valueOf for every level MdcLoggable actually calls shouldShip with" in { + RedisLogger.LogLevel.valueOf("TRACE") should equal(RedisLogger.LogLevel.TRACE) + RedisLogger.LogLevel.valueOf("DEBUG") should equal(RedisLogger.LogLevel.DEBUG) + RedisLogger.LogLevel.valueOf("INFO") should equal(RedisLogger.LogLevel.INFO) + RedisLogger.LogLevel.valueOf("WARNING") should equal(RedisLogger.LogLevel.WARNING) + RedisLogger.LogLevel.valueOf("ERROR") should equal(RedisLogger.LogLevel.ERROR) + } + + "RedisLogger.shouldShip" should "be false for every level when Redis log shipping is disabled" in { + // This suite's props leave redis_logging_enabled at its default (false), which is also the + // production-safe default - so this exercises the same configuration MdcLoggable runs under + // wherever nobody has opted into Redis log shipping. + RedisLogger.isEnabled shouldBe false + + RedisLogger.shouldShip(RedisLogger.LogLevel.TRACE) shouldBe false + RedisLogger.shouldShip(RedisLogger.LogLevel.DEBUG) shouldBe false + RedisLogger.shouldShip(RedisLogger.LogLevel.INFO) shouldBe false + RedisLogger.shouldShip(RedisLogger.LogLevel.WARNING) shouldBe false + RedisLogger.shouldShip(RedisLogger.LogLevel.ERROR) shouldBe false + } + + it should "never ship LogLevel.ALL, which is a read-side aggregate queue, not a real message level" in { + RedisLogger.shouldShip(RedisLogger.LogLevel.ALL) shouldBe false + } +} From 4ec0e56475fbc33edc187ee4f75c3b7aa8989cb1 Mon Sep 17 00:00:00 2001 From: Hongwei Date: Wed, 23 Sep 2026 14:46:59 +0200 Subject: [PATCH 4/4] fix: dispatch MdcLoggable's masking and write off the calling thread 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. --- .../resources/props/sample.props.template | 15 +++ obp-api/src/main/scala/code/util/Helper.scala | 127 ++++++++++++++---- .../code/util/MdcLoggableDispatchTest.scala | 67 +++++++++ 3 files changed, 181 insertions(+), 28 deletions(-) create mode 100644 obp-api/src/test/scala/code/util/MdcLoggableDispatchTest.scala diff --git a/obp-api/src/main/resources/props/sample.props.template b/obp-api/src/main/resources/props/sample.props.template index fe6c9d7eb9..715eca6920 100644 --- a/obp-api/src/main/resources/props/sample.props.template +++ b/obp-api/src/main/resources/props/sample.props.template @@ -1911,6 +1911,21 @@ redis_logging_warning_queue_max_entries = 1000 # Max WARNING messages redis_logging_error_queue_max_entries = 1000 # Max ERROR messages redis_logging_all_queue_max_entries = 1000 # Max ALL messages + + +########################################################## +# MDC Logging Dispatch # +########################################################## +## Number of threads used to run secret-masking (SecureLogging.maskSensitive) and the local/ +## Redis log write itself, once a call to logger.debug/info/warn/error/trace has determined +## the message will actually be consumed. This work used to run inline on whatever thread +## called the logger, including http4s/cats-effect fiber-managed threads -- CPU-bound work +## that doesn't yield can trip the runtime's own fiber-starvation detector the same way real +## blocking I/O would, and its response (spinning up more worker/blocker threads that are +## never reclaimed) was a contributing factor in a real incident. Keep this small; it's meant +## to decouple from the calling thread, not to parallelize heavy logging. +mdc_logging_dispatch_thread_pool_size = 2 + ## Optional: Circuit breaker reset interval (ms) ## How long before retrying after circuit breaker opens. Default 60s. redis_logging_circuit_breaker_reset_ms = 60000 diff --git a/obp-api/src/main/scala/code/util/Helper.scala b/obp-api/src/main/scala/code/util/Helper.scala index 926362ce13..050778e1d9 100644 --- a/obp-api/src/main/scala/code/util/Helper.scala +++ b/obp-api/src/main/scala/code/util/Helper.scala @@ -259,6 +259,50 @@ object Helper extends Loggable { + // Shared across every class mixing in MdcLoggable below -- created once at object-init, + // not per mixing instance. Masking (SecureLogging.maskSensitive, ~19 regex passes) and + // Redis-shipping serialization are CPU-bound work that used to run inline on whatever + // thread called logger.debug/info/etc. On this codebase's http4s/cats-effect request path + // that thread is often a fiber-managed worker; running non-yielding CPU work on it directly + // is indistinguishable, from the runtime's own fairness/starvation detector, from genuine + // blocking I/O -- cats-effect's "your CPU is probably starving" warning fires the same way + // either way, and its response is to compensate by spinning up additional worker/blocker + // threads that are never reclaimed. Dispatching this work onto a small dedicated pool + // instead means the calling thread (fiber or otherwise) returns immediately, regardless of + // what kind of thread it happens to be -- this trait is mixed into ~260 classes, many of + // them called from contexts (actors, scheduled jobs, Lift-era code) that have no IO runtime + // at all, so wrapping in cats.effect.IO.blocking isn't an option here: nothing would ever + // run it in those contexts. A plain background ExecutionContext works everywhere the + // trait itself is used. Same pattern RedisLogger already uses for its own async shipping. + // + // Trade-off worth being explicit about: log output for a given logger is no longer + // strictly write-ordered relative to other concurrent callers (each dispatched entry lands + // whenever its turn on this small pool comes up). That's the same trade-off any async + // logging setup makes (Logback's own AsyncAppender, Log4j2's AsyncLogger); this was never a + // strict global ordering guarantee to begin with once Redis shipping (already async) was in + // the picture. + // lazy, not val: Helper's own static initializer transitively touches other objects + // (APIUtil/Constant among them) that log during THEIR initialization, which can re-enter + // here before a plain val declared at this point in the object body would have run yet -- + // observed as a NullPointerException on this executor during Helper's own , caught + // by MdcLoggableDispatchTest. `lazy val` computes on first real use instead of at a fixed + // point in top-to-bottom initialization order, which is what this needs given how + // entangled this codebase's early object initialization already is (not something + // introduced here). + private lazy val mdcLoggingExecutor: java.util.concurrent.ExecutorService = { + val threadCount = new java.util.concurrent.atomic.AtomicInteger(0) + java.util.concurrent.Executors.newFixedThreadPool( + APIUtil.getPropsAsIntValue("mdc_logging_dispatch_thread_pool_size", 2), + (r: Runnable) => { + val t = new Thread(r, s"mdc-log-dispatch-${threadCount.incrementAndGet()}") + t.setDaemon(true) + t + } + ) + } + private lazy val mdcLoggingExecutionContext: scala.concurrent.ExecutionContext = + scala.concurrent.ExecutionContext.fromExecutor(mdcLoggingExecutor) + trait MdcLoggable extends Loggable { // Capture the class name of the component mixing in this trait @@ -288,82 +332,109 @@ object Helper extends Loggable { // passes in SecureLogging.maskSensitive. That cost must only be paid when the // result is actually going to be consumed (by the local logger and/or Redis // shipping) -- not unconditionally on every call site, which is what made this a - // hot path under high request volume with DEBUG enabled. + // hot path under high request volume with DEBUG enabled. And once it is going to be + // paid, it's dispatched onto mdcLoggingExecutionContext (see its own doc comment) + // rather than run inline on whatever thread called into this logger. + private def dispatch(body: => Unit): Unit = { + val future = scala.concurrent.Future(body)(mdcLoggingExecutionContext) + future.failed.foreach { e => + System.err.println(s"[$clazzName] background log dispatch failed: ${e.getMessage}") + }(mdcLoggingExecutionContext) + } // INFO override def info(msg: => AnyRef): Unit = { if (underlyingLogger.isInfoEnabled || RedisLogger.shouldShip(RedisLogger.LogLevel.INFO)) { - val maskedMsg = SecureLogging.maskSensitive(msg) - if (underlyingLogger.isInfoEnabled) underlyingLogger.info(maskedMsg) - RedisLogger.logAsync(RedisLogger.LogLevel.INFO, toRedisFormat(maskedMsg)) + dispatch { + val maskedMsg = SecureLogging.maskSensitive(msg) + if (underlyingLogger.isInfoEnabled) underlyingLogger.info(maskedMsg) + RedisLogger.logAsync(RedisLogger.LogLevel.INFO, toRedisFormat(maskedMsg)) + } } } override def info(msg: => AnyRef, t: => Throwable): Unit = { if (underlyingLogger.isInfoEnabled || RedisLogger.shouldShip(RedisLogger.LogLevel.INFO)) { - val maskedMsg = SecureLogging.maskSensitive(msg) - if (underlyingLogger.isInfoEnabled) underlyingLogger.info(maskedMsg, t) - RedisLogger.logAsync(RedisLogger.LogLevel.INFO, toRedisFormat(maskedMsg) + "\n" + t.toString) + dispatch { + val maskedMsg = SecureLogging.maskSensitive(msg) + val capturedT = t + if (underlyingLogger.isInfoEnabled) underlyingLogger.info(maskedMsg, capturedT) + RedisLogger.logAsync(RedisLogger.LogLevel.INFO, toRedisFormat(maskedMsg) + "\n" + capturedT.toString) + } } } // WARN override def warn(msg: => AnyRef): Unit = { if (underlyingLogger.isWarnEnabled || RedisLogger.shouldShip(RedisLogger.LogLevel.WARNING)) { - val maskedMsg = SecureLogging.maskSensitive(msg) - if (underlyingLogger.isWarnEnabled) underlyingLogger.warn(maskedMsg) - RedisLogger.logAsync(RedisLogger.LogLevel.WARNING, toRedisFormat(maskedMsg)) + dispatch { + val maskedMsg = SecureLogging.maskSensitive(msg) + if (underlyingLogger.isWarnEnabled) underlyingLogger.warn(maskedMsg) + RedisLogger.logAsync(RedisLogger.LogLevel.WARNING, toRedisFormat(maskedMsg)) + } } } override def warn(msg: => AnyRef, t: Throwable): Unit = { if (underlyingLogger.isWarnEnabled || RedisLogger.shouldShip(RedisLogger.LogLevel.WARNING)) { - val maskedMsg = SecureLogging.maskSensitive(msg) - if (underlyingLogger.isWarnEnabled) underlyingLogger.warn(maskedMsg, t) - RedisLogger.logAsync(RedisLogger.LogLevel.WARNING, toRedisFormat(maskedMsg) + "\n" + t.toString) + dispatch { + val maskedMsg = SecureLogging.maskSensitive(msg) + if (underlyingLogger.isWarnEnabled) underlyingLogger.warn(maskedMsg, t) + RedisLogger.logAsync(RedisLogger.LogLevel.WARNING, toRedisFormat(maskedMsg) + "\n" + t.toString) + } } } // ERROR override def error(msg: => AnyRef): Unit = { if (underlyingLogger.isErrorEnabled || RedisLogger.shouldShip(RedisLogger.LogLevel.ERROR)) { - val maskedMsg = SecureLogging.maskSensitive(msg) - if (underlyingLogger.isErrorEnabled) underlyingLogger.error(maskedMsg) - RedisLogger.logAsync(RedisLogger.LogLevel.ERROR, toRedisFormat(maskedMsg)) + dispatch { + val maskedMsg = SecureLogging.maskSensitive(msg) + if (underlyingLogger.isErrorEnabled) underlyingLogger.error(maskedMsg) + RedisLogger.logAsync(RedisLogger.LogLevel.ERROR, toRedisFormat(maskedMsg)) + } } } override def error(msg: => AnyRef, t: Throwable): Unit = { if (underlyingLogger.isErrorEnabled || RedisLogger.shouldShip(RedisLogger.LogLevel.ERROR)) { - val maskedMsg = SecureLogging.maskSensitive(msg) - if (underlyingLogger.isErrorEnabled) underlyingLogger.error(maskedMsg, t) - RedisLogger.logAsync(RedisLogger.LogLevel.ERROR, toRedisFormat(maskedMsg) + "\n" + t.toString) + dispatch { + val maskedMsg = SecureLogging.maskSensitive(msg) + if (underlyingLogger.isErrorEnabled) underlyingLogger.error(maskedMsg, t) + RedisLogger.logAsync(RedisLogger.LogLevel.ERROR, toRedisFormat(maskedMsg) + "\n" + t.toString) + } } } // DEBUG override def debug(msg: => AnyRef): Unit = { if (underlyingLogger.isDebugEnabled || RedisLogger.shouldShip(RedisLogger.LogLevel.DEBUG)) { - val maskedMsg = SecureLogging.maskSensitive(msg) - if (underlyingLogger.isDebugEnabled) underlyingLogger.debug(maskedMsg) - RedisLogger.logAsync(RedisLogger.LogLevel.DEBUG, toRedisFormat(maskedMsg)) + dispatch { + val maskedMsg = SecureLogging.maskSensitive(msg) + if (underlyingLogger.isDebugEnabled) underlyingLogger.debug(maskedMsg) + RedisLogger.logAsync(RedisLogger.LogLevel.DEBUG, toRedisFormat(maskedMsg)) + } } } override def debug(msg: => AnyRef, t: Throwable): Unit = { if (underlyingLogger.isDebugEnabled || RedisLogger.shouldShip(RedisLogger.LogLevel.DEBUG)) { - val maskedMsg = SecureLogging.maskSensitive(msg) - if (underlyingLogger.isDebugEnabled) underlyingLogger.debug(maskedMsg, t) - RedisLogger.logAsync(RedisLogger.LogLevel.DEBUG, toRedisFormat(maskedMsg) + "\n" + t.toString) + dispatch { + val maskedMsg = SecureLogging.maskSensitive(msg) + if (underlyingLogger.isDebugEnabled) underlyingLogger.debug(maskedMsg, t) + RedisLogger.logAsync(RedisLogger.LogLevel.DEBUG, toRedisFormat(maskedMsg) + "\n" + t.toString) + } } } // TRACE override def trace(msg: => AnyRef): Unit = { if (underlyingLogger.isTraceEnabled || RedisLogger.shouldShip(RedisLogger.LogLevel.TRACE)) { - val maskedMsg = SecureLogging.maskSensitive(msg) - if (underlyingLogger.isTraceEnabled) underlyingLogger.trace(maskedMsg) - RedisLogger.logAsync(RedisLogger.LogLevel.TRACE, toRedisFormat(maskedMsg)) + dispatch { + val maskedMsg = SecureLogging.maskSensitive(msg) + if (underlyingLogger.isTraceEnabled) underlyingLogger.trace(maskedMsg) + RedisLogger.logAsync(RedisLogger.LogLevel.TRACE, toRedisFormat(maskedMsg)) + } } } diff --git a/obp-api/src/test/scala/code/util/MdcLoggableDispatchTest.scala b/obp-api/src/test/scala/code/util/MdcLoggableDispatchTest.scala new file mode 100644 index 0000000000..56de27238f --- /dev/null +++ b/obp-api/src/test/scala/code/util/MdcLoggableDispatchTest.scala @@ -0,0 +1,67 @@ +package code.util + +import ch.qos.logback.classic.spi.ILoggingEvent +import ch.qos.logback.classic.{Level, Logger => LogbackLogger} +import ch.qos.logback.core.AppenderBase +import org.scalatest.{FlatSpec, Matchers} +import org.slf4j.LoggerFactory + +import java.util.concurrent.{CopyOnWriteArrayList, TimeUnit} + +/** + * Verifies the actual behavioural change from the fix in Helper.scala: masking + the local + * write now happen on a dedicated background pool (mdcLoggingExecutionContext) instead of + * inline on the calling thread. RedisLoggerShouldShipTest covers the gating logic + * (shouldShip); this covers the dispatch itself -- that a call which passes the gate still + * reliably reaches the underlying logger (just asynchronously), and that it does so on a + * thread other than the caller's. + */ +class MdcLoggableDispatchTest extends FlatSpec with Matchers { + + private object ProbeLogger extends Helper.MdcLoggable { + // `logger` is protected on the MdcLoggable/Loggable trait -- only reachable from within a + // mixing class's own body, not from the test. Expose the one call the test needs. + def probeDebug(msg: String): Unit = logger.debug(msg) + } + + "MdcLoggable" should "deliver an enabled log call to the underlying logger asynchronously, off the calling thread" in { + val logbackLogger = LoggerFactory.getLogger(ProbeLogger.getClass.getName).asInstanceOf[LogbackLogger] + val originalLevel = logbackLogger.getLevel + logbackLogger.setLevel(Level.DEBUG) + + val captured = new CopyOnWriteArrayList[ILoggingEvent]() + val appender = new AppenderBase[ILoggingEvent] { + override def append(event: ILoggingEvent): Unit = captured.add(event) + } + appender.setContext(logbackLogger.getLoggerContext) + appender.start() + logbackLogger.addAppender(appender) + + val callingThreadName = Thread.currentThread().getName + // Not a bare digit run: a 16-19 digit nanoTime() collides with SecureLogging's + // credit-card-shaped masking pattern and gets partially masked -- correct behaviour from + // the masking regex, but it broke this test's own substring check the first time around. + val marker = s"MdcLoggableDispatchTest-probe-id${System.nanoTime()}" + + try { + ProbeLogger.probeDebug(marker) + + // The dispatch is asynchronous, so the event won't necessarily be there immediately -- + // poll briefly rather than asserting right away (which would just be testing timing, + // not the actual delivery guarantee). + val deadline = System.nanoTime() + TimeUnit.SECONDS.toNanos(5) + while (captured.isEmpty && System.nanoTime() < deadline) { + Thread.sleep(20) + } + + captured should not be empty + val event = captured.get(0) + event.getFormattedMessage should include(marker) + event.getThreadName should not equal callingThreadName + event.getThreadName should startWith("mdc-log-dispatch-") + } finally { + logbackLogger.detachAppender(appender) + logbackLogger.setLevel(originalLevel) + } + } +}