diff --git a/README.md b/README.md index 0863230ffa..1cec985add 100644 --- a/README.md +++ b/README.md @@ -304,9 +304,12 @@ Note: Your Java environment may need to be set up correctly to use SSL. Restart OBP-API, if you get an error, check your Java environment can connect to the host over SSL. -Note: You can copy the following example files to prepare your own configurations: +Note: `/obp-api/src/main/resources/logback.xml` ships ready to use, defaulting to INFO. Set the +`LOG_LEVEL` environment variable (e.g. `LOG_LEVEL=DEBUG` or `LOG_LEVEL=TRACE`) to override it per +environment without editing the file. + +You can also copy the following example file to prepare your own test-run configuration: -- `/obp-api/src/main/resources/logback.xml.example` -> `/obp-api/src/main/resources/logback.xml` (try TRACE or DEBUG). - `/obp-api/src/main/resources/logback-test.xml.example` -> `/obp-api/src/main/resources/logback-test.xml` (try TRACE or DEBUG). There is a gist/tool which is useful for this. Search the web for SSLPoke. Note this is an external repository. diff --git a/obp-api/src/main/resources/docs/brief_system_documentation.md b/obp-api/src/main/resources/docs/brief_system_documentation.md index 86d568b7cd..e93a6ca464 100644 --- a/obp-api/src/main/resources/docs/brief_system_documentation.md +++ b/obp-api/src/main/resources/docs/brief_system_documentation.md @@ -137,7 +137,7 @@ User ──(has roles/entitlements)──► Bank/System actions **Logging** -- Copy `logback.xml.example` to `logback.xml`; adjust levels (TRACE/DEBUG/INFO) per environment. +- `logback.xml` ships ready to use, defaulting to INFO; set `LOG_LEVEL` (TRACE/DEBUG/INFO/...) to override per environment. - In Docker/K8s, logs go to stdout/stderr → aggregate with your stack (e.g., Loki/Promtail, EFK). **Health & metrics** diff --git a/obp-api/src/main/resources/logback.xml b/obp-api/src/main/resources/logback.xml new file mode 100644 index 0000000000..8044beb0bf --- /dev/null +++ b/obp-api/src/main/resources/logback.xml @@ -0,0 +1,17 @@ + + + + + %d{yyyy-MM-dd HH:mm:ss} %t %c{0} [%p] %m%n + + + + + + + + \ No newline at end of file diff --git a/obp-api/src/main/resources/logback.xml.example b/obp-api/src/main/resources/logback.xml.example deleted file mode 100644 index 871aea062a..0000000000 --- a/obp-api/src/main/resources/logback.xml.example +++ /dev/null @@ -1,12 +0,0 @@ - - - - - %d{yyyy-MM-dd HH:mm:ss} %t %c{0} [%p] %m%n - - - - - - - \ No newline at end of file diff --git a/obp-api/src/main/resources/props/sample.props.template b/obp-api/src/main/resources/props/sample.props.template index 0882711cb1..950de02420 100644 --- a/obp-api/src/main/resources/props/sample.props.template +++ b/obp-api/src/main/resources/props/sample.props.template @@ -1948,6 +1948,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 @@ -1978,6 +1985,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 7c22956d5a..5342d11a23 100644 --- a/obp-api/src/main/scala/code/api/cache/RedisLogger.scala +++ b/obp-api/src/main/scala/code/api/cache/RedisLogger.scala @@ -60,6 +60,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) @@ -175,7 +202,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/api/util/JsonSchemaGenerator.scala b/obp-api/src/main/scala/code/api/util/JsonSchemaGenerator.scala index 55d41bcb76..c465a8bb33 100644 --- a/obp-api/src/main/scala/code/api/util/JsonSchemaGenerator.scala +++ b/obp-api/src/main/scala/code/api/util/JsonSchemaGenerator.scala @@ -30,8 +30,10 @@ package code.api.util import org.json4s._ import code.api.util.APIUtil.MessageDoc import com.openbankproject.commons.util.ReflectUtils +import com.tesobe.CacheKeyFromArguments import org.json4s.JsonDSL._ +import scala.concurrent.duration._ import scala.reflect.runtime.universe._ /** @@ -42,9 +44,34 @@ import scala.reflect.runtime.universe._ object JsonSchemaGenerator { /** - * Convert a list of MessageDoc to a complete JSON Schema document + * Convert a list of MessageDoc to a complete JSON Schema document. + * + * Memoized in-process, keyed by connectorName: for a given connector the message docs + * (and therefore the schema) are static for the lifetime of the JVM, but building it + * walks every message type's full field tree via Scala runtime reflection (`<:<`/`=:=` + * subtype checks), which is expensive and -- unlike a plain field lookup -- leaves behind + * long-lived reflection bookkeeping objects (TypeConstraint/UndoPair/Symbol) that don't + * get reclaimed promptly. Recomputing this on every request under sustained polling is + * what drove a production old-gen heap to exhaustion. The caller (Http4s600) also has a + * Redis-backed cache in front of this, but that one silently falls through to a full + * recompute if Redis is unreachable or slow -- this in-memory layer doesn't depend on + * Redis at all, so it stays a working safety net even when Redis is the one struggling. */ def messageDocsToJsonSchema(messageDocs: List[MessageDoc], connectorName: String): JObject = { + // This 3-tuple of random UUIDs is a placeholder only -- CacheKeyFromArguments is a macro + // that replaces it at compile time with a real key derived from this method's owner, + // name and arguments (regardless of this method's own arity; the convention throughout + // this codebase is always a 3-tuple here). See: + // https://github.com/OpenBankProject/scala-macros/blob/master/macros/src/main/scala/com/tesobe/CacheKeyFromArgumentsMacro.scala#L49 + var cacheKey = (java.util.UUID.randomUUID().toString, java.util.UUID.randomUUID().toString, java.util.UUID.randomUUID().toString) + CacheKeyFromArguments.buildCacheKey { + code.api.cache.Caching.memoizeSyncWithImMemory(Some(cacheKey.toString()))(100000.days) { + messageDocsToJsonSchemaUncached(messageDocs, connectorName) + } + } + } + + private def messageDocsToJsonSchemaUncached(messageDocs: List[MessageDoc], connectorName: String): JObject = { val allDefinitions = scala.collection.mutable.Map[String, JObject]() val messages = messageDocs.map { messageDoc => diff --git a/obp-api/src/main/scala/code/util/Helper.scala b/obp-api/src/main/scala/code/util/Helper.scala index b45b10414d..0b3cfdf817 100644 --- a/obp-api/src/main/scala/code/util/Helper.scala +++ b/obp-api/src/main/scala/code/util/Helper.scala @@ -286,6 +286,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 @@ -311,63 +355,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/bootstrap/http4s/LogbackDefaultLevelTest.scala b/obp-api/src/test/scala/bootstrap/http4s/LogbackDefaultLevelTest.scala new file mode 100644 index 0000000000..527c81bfa5 --- /dev/null +++ b/obp-api/src/test/scala/bootstrap/http4s/LogbackDefaultLevelTest.scala @@ -0,0 +1,55 @@ +package bootstrap.http4s + +import ch.qos.logback.classic.{Level, Logger, LoggerContext} +import ch.qos.logback.classic.joran.JoranConfigurator +import ch.qos.logback.classic.spi.LoggerContextListener +import org.scalatest.{BeforeAndAfterEach, FlatSpec, Matchers} +import org.slf4j.Logger.ROOT_LOGGER_NAME + +/** + * Directly verifies the shipped src/main/resources/logback.xml resolves + * the way this fix depends on: + * + * - LOG_LEVEL unset -> root defaults to INFO, not the old hard-coded DEBUG. + * - LOG_LEVEL set -> root honours it. + * + * The application's actual SLF4J LoggerContext is configured once, at JVM start, from whatever + * LOG_LEVEL happened to be set at that moment -- so asserting against + * LoggerFactory.getILoggerFactory() here wouldn't exercise the default-value resolution at all, + * only whatever this test JVM's own environment happened to be. Instead this parses the actual + * classpath resource into a fresh, throwaway LoggerContext per scenario (via Joran, the same + * parser Logback uses internally), with the system property set immediately beforehand -- this is + * the standard way to unit-test a logback.xml's own logic rather than the ambient environment. + */ +class LogbackDefaultLevelTest extends FlatSpec with Matchers with BeforeAndAfterEach { + + private val propertyName = "LOG_LEVEL" + + override def afterEach(): Unit = { + System.clearProperty(propertyName) + } + + private def rootLevelFromShippedConfig(): Level = { + val context = new LoggerContext() + context.reset() + val configurator = new JoranConfigurator() + configurator.setContext(context) + configurator.doConfigure(getClass.getClassLoader.getResource("logback.xml")) + context.getLogger(ROOT_LOGGER_NAME).getLevel + } + + "the shipped logback.xml" should "default the root level to INFO when LOG_LEVEL is unset" in { + System.clearProperty(propertyName) + rootLevelFromShippedConfig() should equal(Level.INFO) + } + + it should "honour LOG_LEVEL=DEBUG when set" in { + System.setProperty(propertyName, "DEBUG") + rootLevelFromShippedConfig() should equal(Level.DEBUG) + } + + it should "honour LOG_LEVEL=WARN when set" in { + System.setProperty(propertyName, "WARN") + rootLevelFromShippedConfig() should equal(Level.WARN) + } +} 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/api/util/JsonSchemaGeneratorCacheTest.scala b/obp-api/src/test/scala/code/api/util/JsonSchemaGeneratorCacheTest.scala new file mode 100644 index 0000000000..eef09f6d1e --- /dev/null +++ b/obp-api/src/test/scala/code/api/util/JsonSchemaGeneratorCacheTest.scala @@ -0,0 +1,116 @@ +package code.api.util + +import code.api.util.APIUtil.MessageDoc +import org.scalatest.{FlatSpec, Matchers} + +/** + * Guards the in-process cache added to JsonSchemaGenerator.messageDocsToJsonSchema. + * + * Building the schema walks the full field tree of every message type via Scala runtime + * reflection (recursive <: "v")) + SchemaCacheTestPayload("id-1", BigDecimal(1), List("a", "b"), address, batch) + } + + private def sampleMessageDocs(connectorName: String): List[MessageDoc] = List( + MessageDoc( + process = s"obp.$connectorName.getThing", + messageFormat = "JSON", + description = "test message doc for cache verification", + exampleOutboundMessage = samplePayload(), + exampleInboundMessage = samplePayload() + ) + ) + + "JsonSchemaGenerator.messageDocsToJsonSchema" should "return identical output on a cache hit as on the initial cold call" in { + val connectorName = freshConnectorName("identical-output") + val docs = sampleMessageDocs(connectorName) + + val first = JsonSchemaGenerator.messageDocsToJsonSchema(docs, connectorName) + val second = JsonSchemaGenerator.messageDocsToJsonSchema(docs, connectorName) + + second should equal(first) + } + + it should "be dramatically faster on a cache hit than on the initial cold call" in { + val connectorName = freshConnectorName("timing") + val docs = sampleMessageDocs(connectorName) + + val coldStart = System.nanoTime() + JsonSchemaGenerator.messageDocsToJsonSchema(docs, connectorName) + val coldNanos = System.nanoTime() - coldStart + + // A handful of warm calls, not just one: a single fast call could be a lucky JIT/scheduling + // blip rather than an actual cache hit. Comparing the median (not every sample, and not the + // fastest) against the cold call keeps this robust to a single GC pause or JIT hiccup landing + // on one warm sample while still requiring a real, consistent improvement. + val warmNanosSamples = (1 to 7).map { _ => + val start = System.nanoTime() + JsonSchemaGenerator.messageDocsToJsonSchema(docs, connectorName) + System.nanoTime() - start + } + val medianWarmNanos = warmNanosSamples.sorted.apply(warmNanosSamples.size / 2) + + withClue(s"cold=${coldNanos}ns warm=${warmNanosSamples.sorted.mkString(",")}ns median=${medianWarmNanos}ns: ") { + medianWarmNanos should be < (coldNanos / 2) + } + } + + it should "isolate different connector names as independent cache entries" in { + val connectorA = freshConnectorName("connector-a") + val connectorB = freshConnectorName("connector-b") + + val schemaA = JsonSchemaGenerator.messageDocsToJsonSchema(sampleMessageDocs(connectorA), connectorA) + val schemaB = JsonSchemaGenerator.messageDocsToJsonSchema(sampleMessageDocs(connectorB), connectorB) + + (schemaA \ "title") should equal(org.json4s.JString(s"$connectorA Message Schemas")) + (schemaB \ "title") should equal(org.json4s.JString(s"$connectorB Message Schemas")) + } +} 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) + } + } +}