diff --git a/obp-api/src/main/resources/props/sample.props.template b/obp-api/src/main/resources/props/sample.props.template index 141dfb17b7..715eca6920 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 @@ -1904,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/api/cache/RedisLogger.scala b/obp-api/src/main/scala/code/api/cache/RedisLogger.scala index 04b30c476d..eb949d288e 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,33 @@ 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 + + /** + * 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) @@ -148,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 3dc961e61a..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 @@ -284,63 +328,114 @@ 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. 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 = { - val maskedMsg = SecureLogging.maskSensitive(msg) - underlyingLogger.info(maskedMsg) - RedisLogger.logAsync(RedisLogger.LogLevel.INFO, toRedisFormat(maskedMsg)) + if (underlyingLogger.isInfoEnabled || RedisLogger.shouldShip(RedisLogger.LogLevel.INFO)) { + 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 = { - val maskedMsg = SecureLogging.maskSensitive(msg) - underlyingLogger.info(maskedMsg, t) - RedisLogger.logAsync(RedisLogger.LogLevel.INFO, toRedisFormat(maskedMsg) + "\n" + t.toString) + if (underlyingLogger.isInfoEnabled || RedisLogger.shouldShip(RedisLogger.LogLevel.INFO)) { + 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 = { - val maskedMsg = SecureLogging.maskSensitive(msg) - underlyingLogger.warn(maskedMsg) - RedisLogger.logAsync(RedisLogger.LogLevel.WARNING, toRedisFormat(maskedMsg)) + if (underlyingLogger.isWarnEnabled || RedisLogger.shouldShip(RedisLogger.LogLevel.WARNING)) { + 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 = { - val maskedMsg = SecureLogging.maskSensitive(msg) - underlyingLogger.warn(maskedMsg, t) - RedisLogger.logAsync(RedisLogger.LogLevel.WARNING, toRedisFormat(maskedMsg) + "\n" + t.toString) + if (underlyingLogger.isWarnEnabled || RedisLogger.shouldShip(RedisLogger.LogLevel.WARNING)) { + 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 = { - val maskedMsg = SecureLogging.maskSensitive(msg) - underlyingLogger.error(maskedMsg) - RedisLogger.logAsync(RedisLogger.LogLevel.ERROR, toRedisFormat(maskedMsg)) + if (underlyingLogger.isErrorEnabled || RedisLogger.shouldShip(RedisLogger.LogLevel.ERROR)) { + 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 = { - val maskedMsg = SecureLogging.maskSensitive(msg) - underlyingLogger.error(maskedMsg, t) - RedisLogger.logAsync(RedisLogger.LogLevel.ERROR, toRedisFormat(maskedMsg) + "\n" + t.toString) + if (underlyingLogger.isErrorEnabled || RedisLogger.shouldShip(RedisLogger.LogLevel.ERROR)) { + 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 = { - val maskedMsg = SecureLogging.maskSensitive(msg) - underlyingLogger.debug(maskedMsg) - RedisLogger.logAsync(RedisLogger.LogLevel.DEBUG, toRedisFormat(maskedMsg)) + if (underlyingLogger.isDebugEnabled || RedisLogger.shouldShip(RedisLogger.LogLevel.DEBUG)) { + 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 = { - val maskedMsg = SecureLogging.maskSensitive(msg) - underlyingLogger.debug(maskedMsg, t) - RedisLogger.logAsync(RedisLogger.LogLevel.DEBUG, toRedisFormat(maskedMsg) + "\n" + t.toString) + if (underlyingLogger.isDebugEnabled || RedisLogger.shouldShip(RedisLogger.LogLevel.DEBUG)) { + 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 = { - val maskedMsg = SecureLogging.maskSensitive(msg) - underlyingLogger.trace(maskedMsg) - RedisLogger.logAsync(RedisLogger.LogLevel.TRACE, toRedisFormat(maskedMsg)) + if (underlyingLogger.isTraceEnabled || RedisLogger.shouldShip(RedisLogger.LogLevel.TRACE)) { + dispatch { + val maskedMsg = SecureLogging.maskSensitive(msg) + if (underlyingLogger.isTraceEnabled) underlyingLogger.trace(maskedMsg) + RedisLogger.logAsync(RedisLogger.LogLevel.TRACE, toRedisFormat(maskedMsg)) + } + } } // Delegate enabled checks 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 + } +} 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) + } + } +}