fix: reduce logging overhead, cache message-docs, default log level INFO

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.

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**

obp-api/src/main/resources/logback.xml

@@ -0,0 +1,19 @@
+<configuration>
+
+  <appender name="STDOUT" class="ch.qos.logback.core.ConsoleAppender">
+    <encoder>
+      <pattern>%d{yyyy-MM-dd HH:mm:ss} %t %X{callerThread:-} %c{0} [%p] %m%n</pattern>
+    </encoder>
+  </appender>
+
+  <!-- %X{callerThread} is the thread that logged: log writes run on a background pool, so %t alone
+       would always be mdc-log-dispatch-N. It is empty for entries not written through that pool. -->
+  <!-- LOG_LEVEL env var (or -DLOG_LEVEL= system property) overrides this; unset falls back to
+       INFO. Default is intentionally quiet, not DEBUG: DEBUG by default means every deployment
+       silently pays the cost of maximal log volume (including the per-message secret-masking
+       pass in SecureLogging) unless someone remembers to turn it down, an opt-out default that
+       is easy to forget. Verbose logging should be an explicit, per-environment opt-in instead. -->
+  <root level="${LOG_LEVEL:-INFO}">
+    <appender-ref ref="STDOUT"/>
+  </root>
+</configuration>

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,27 @@ 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) only adds overhead. Keep this small; it's meant to decouple from the
+## calling thread, not to parallelize heavy logging.
+mdc_logging_dispatch_thread_pool_size = 2
+
+## Maximum number of log entries that may wait for a dispatch thread. The queue is bounded so a
+## burst of log calls cannot become heap growth. When it is full, DEBUG/TRACE/INFO entries are
+## dropped (and counted) while WARN/ERROR entries run on the calling thread, so a warning or an
+## error is never silently lost. Default 10000.
+mdc_logging_dispatch_queue_size = 10000
+
 ## Optional: Circuit breaker reset interval (ms)
 ## How long before retrying after circuit breaker opens. Default 60s.
 redis_logging_circuit_breaker_reset_ms = 60000

obp-api/src/main/scala/bootstrap/liftweb/Boot.scala

@@ -234,6 +234,18 @@ class Boot extends MdcLoggable {
     }
 
     if (Props.mode == Props.RunModes.Development) logger.info("OBP-API Props all fields : \n" + Props.props.mkString("\n"))
+    // Make the effective root log level visible at start-up. DEBUG/TRACE is expensive on this
+    // code base and is only meant to be enabled deliberately (LOG_LEVEL), so say so loudly.
+    try {
+      org.slf4j.LoggerFactory.getLogger(org.slf4j.Logger.ROOT_LOGGER_NAME) match {
+        case l: ch.qos.logback.classic.Logger =>
+          val level = l.getEffectiveLevel
+          if (level.levelInt <= ch.qos.logback.classic.Level.DEBUG_INT)
+            logger.warn(s"Effective root log level is $level (LOG_LEVEL override); expect higher CPU and log volume")
+          else logger.info(s"Effective root log level is $level")
+        case _ => ()
+      }
+    } catch { case _: Throwable => () }
     logger.info("external props folder: " + propsPath)
     TimeZone.setDefault(TimeZone.getTimeZone("UTC"))
     logger.info("Current Project TimeZone: " + TimeZone.getDefault)

obp-api/src/main/scala/code/api/cache/RedisLogger.scala

@@ -60,6 +60,48 @@ 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 =
+    parseMinLevel(APIUtil.getPropsValue("redis_logging_min_level", "INFO"))
+
+  /**
+   * Parse the configured floor. An unrecognised value must not throw: this runs while the
+   * RedisLogger object is being initialised, and MdcLoggable consults RedisLogger on every log
+   * call, so a throwing initialiser would turn a config typo into failures at ordinary logging
+   * statements across the application. Fall back to INFO and say so on stderr (not through a
+   * logger, which would re-enter this initialiser).
+   */
+  private[cache] def parseMinLevel(configured: String): LogLevel.LogLevel =
+    try LogLevel.valueOf(configured.trim)
+    catch {
+      case _: IllegalArgumentException =>
+        System.err.println(s"Invalid redis_logging_min_level '$configured'; using INFO. Valid values: TRACE, DEBUG, INFO, WARN, WARNING, ERROR, ALL")
+        LogLevel.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 +217,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(())
     }
 

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 keeps
+   * adding them and grows old-gen heap usage. 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 =>

obp-api/src/main/scala/code/api/v2_2_0/Http4s220.scala

@@ -425,7 +425,9 @@ object Http4s220 {
               Some(cc),
               s"$InvalidConnector Current Input is $connector. It should be eg: rest_vMar2019..."
             )
-            JSONFactory220.createMessageDocsJson(connectorObject.messageDocs.toList)
+            MessageDocsJsonCache.getOrCompute(connector) {
+              Extraction.decompose(JSONFactory220.createMessageDocsJson(connectorObject.messageDocs.toList))
+            }
           }
         }
     }

obp-api/src/main/scala/code/api/v2_2_0/MessageDocsJsonCache.scala

@@ -0,0 +1,88 @@
+package code.api.v2_2_0
+
+import java.util.concurrent.Callable
+
+import code.api.cache.Caching
+import com.google.common.cache.{Cache, CacheBuilder}
+import com.openbankproject.commons.util.JsonAliases.{compactRender, parse}
+import net.liftweb.common.Loggable
+import org.json4s.JValue
+
+/**
+ * Two-level cache for the fully built `GET /message-docs/CONNECTOR` response.
+ *
+ * Building the response runs Scala runtime reflection over every message doc's example
+ * inbound and outbound message, which is expensive in CPU and grows the reflection
+ * universe. The result only depends on the connector's `messageDocs`, which a connector
+ * fills once while its singleton is initialised and never changes afterwards.
+ *
+ * Levels, checked in this order:
+ *  1. In-process: a bounded Guava cache holding the immutable JValue. It keeps working when
+ *     Redis is down, so an unreachable Redis can never send every request back into
+ *     reflection.
+ *  2. Shared: the same Redis-backed store the resource-doc and swagger endpoints use
+ *     (`Caching.getStaticSwaggerDocCache`, same key prefix and TTL, same fail-safe behaviour:
+ *     an unreachable Redis is a miss, never an error). It lets replicas and restarts reuse
+ *     one instance's work.
+ *
+ * Contract:
+ *  - Key: the connector name, and only after it has been resolved to a real connector.
+ *    Unknown names fail before reaching the cache, so request input cannot grow it;
+ *    `MaxEntries` is a second, hard bound on the in-process level.
+ *  - Single flight: concurrent cold requests for one connector run the loader once, and
+ *    therefore touch Redis and the generator once.
+ *  - A failure is never cached; the next request retries.
+ *  - Redis is written only after a successful generation. An unparsable Redis value is
+ *    treated as a miss and regenerated.
+ *  - Invalidation: `invalidateAll()` clears the in-process level. The Redis level expires by
+ *    `staticResourceDocsObp.cache.ttl.seconds`. Nothing in production mutates a connector's
+ *    message docs after start-up, so nothing calls `invalidateAll()` there.
+ */
+object MessageDocsJsonCache extends Loggable {
+  private val MaxEntries = 64L
+
+  /** The shared level. Abstracted so tests can count reads and writes without a Redis. */
+  trait SharedStore {
+    def get(key: String): Option[String]
+    def set(key: String, value: String): Unit
+  }
+
+  object RedisStore extends SharedStore {
+    def get(key: String): Option[String] = Caching.getStaticSwaggerDocCache(key)
+    def set(key: String, value: String): Unit = Caching.setStaticSwaggerDocCache(key, value)
+  }
+
+  private def sharedKey(connectorName: String) = s"message-docs-v2.2.0-$connectorName"
+
+  private val cache: Cache[String, JValue] =
+    CacheBuilder.newBuilder().maximumSize(MaxEntries).build[String, JValue]()
+
+  def getOrCompute(connectorName: String, store: SharedStore = RedisStore)(generate: => JValue): JValue =
+    try cache.get(connectorName, new Callable[JValue] {
+      def call(): JValue = {
+        val key = sharedKey(connectorName)
+        val fromShared = store.get(key).flatMap { s =>
+          try Some(parse(s))
+          catch { case e: Exception => logger.warn(s"Ignoring unparsable shared message-docs entry $key: ${e.getMessage}"); None }
+        }
+        fromShared.getOrElse {
+          // Serve the round-tripped form even on the instance that generated it. Otherwise this
+          // instance would return the JValue it built while every other replica (and this one
+          // after a restart) returns parse(compactRender(...)), and number formatting could differ
+          // between them.
+          val rendered = compactRender(generate)
+          store.set(key, rendered)
+          parse(rendered)
+        }
+      }
+    })
+    catch {
+      // Surface the loader's own exception, not Guava's wrapper.
+      case e: java.util.concurrent.ExecutionException if e.getCause != null => throw e.getCause
+      case e: com.google.common.util.concurrent.UncheckedExecutionException if e.getCause != null => throw e.getCause
+    }
+
+  def invalidateAll(): Unit = cache.invalidateAll()
+
+  def size: Long = cache.size()
+}