Skip to content

fix: production CPU/GC incident - unconditional log masking, missing schema cache, default DEBUG logging - #2920

Closed
hongwei1 wants to merge 1 commit into
OpenBankProject:developfrom
hongwei1:fix/nmb-cpu-gc-incident-combined
Closed

hongwei1 wants to merge 1 commit into
OpenBankProject:developfrom
hongwei1:fix/nmb-cpu-gc-incident-combined

Conversation

@hongwei1

@hongwei1 hongwei1 commented Sep 23, 2026 •

Copy link
Copy Markdown
Contributor

Summary

Root-caused a production incident (sustained 600% CPU, Full-GC thrashing, eventual service timeout) on a sandbox instance. Three independent fixes, bundled together since they trace back to the same investigation and are small enough to review as a set.

  1. MdcLoggable (code/util/Helper.scala) ran SecureLogging.maskSensitive (~19 regex passes) and Redis-shipping JSON serialization unconditionally on every info/warn/error/debug/trace call, before checking whether the underlying logger or Redis would even consume the message -- and, once gated, still ran that work inline on the calling thread. On the http4s/cats-effect request path that's often a fiber-managed worker; non-yielding CPU-bound work there looks identical, to the runtime's own starvation detector, to genuine blocking I/O, and its response (spinning up compensating worker/blocker threads that are never reclaimed) links directly to a heap dump showing hundreds of threads each holding a private Scala-reflection symbol-table cache. Fixed by gating on isXEnabled/RedisLogger.shouldShip (new redis_logging_min_level prop, default INFO) and dispatching the actual work onto a small dedicated ExecutionContext instead of the calling thread.

  2. JsonSchemaGenerator.messageDocsToJsonSchema had no cache of its own, walking every message type's field tree via Scala runtime reflection on every call; its caller's Redis-backed cache silently falls through to a full recompute on any Redis failure. Added an in-process memoization (Guava-backed, no Redis dependency) alongside the existing one, using the same pattern already proven correct by Helper.getRequiredFieldInfo. Independent hardening for a real gap in this file -- not confirmed as this incident's cause; JsonSchemaGenerator doesn't appear anywhere in this incident's JFR execution samples.

  3. logback.xml.example sat inert (Logback only auto-loads files named exactly logback.xml) with root level hard-coded to DEBUG; deployments that never manually copied it over fell back to Logback's own built-in DEBUG-to-console default. Renamed to logback.xml so it's actually loaded, and changed the level to ${LOG_LEVEL:-INFO}: verbose logging should be an explicit per-environment opt-in, not the default every deployment silently pays for.

Test plan

  • mvn -pl obp-commons,obp-api -am compile -DskipTests -o -- BUILD SUCCESS
  • RedisLoggerShouldShipTest, MdcLoggableDispatchTest, JsonSchemaGeneratorCacheTest, MessageDocsJsonSchemaTest, LogbackDefaultLevelTest -- all passing individually
  • Full local suite (run_tests_parallel.sh), run twice -- 3919 tests / 0 failures / 0 errors / 18 skipped, all shards passing
  • CI -- all checks green

…schema cache, and default DEBUG logging

Root-caused a production incident (sustained 600% CPU, Full-GC thrashing,
eventual service timeout) on a sandbox instance. Three independent
fixes, bundled together since they trace back to the same investigation
and are small enough to review as a set.

1. MdcLoggable (code/util/Helper.scala) ran SecureLogging.maskSensitive
   (~19 regex passes) and Redis-shipping JSON serialization unconditionally
   on every info/warn/error/debug/trace call, before checking whether the
   underlying logger or Redis would even consume the message - and, once
   gated, still ran that work inline on the calling thread. On the
   http4s/cats-effect request path that's often a fiber-managed worker;
   non-yielding CPU-bound work there looks identical, to the runtime's own
   starvation detector, to genuine blocking I/O, and its response (spinning
   up compensating worker/blocker threads that are never reclaimed) links
   directly to a heap dump showing hundreds of threads each holding a
   private Scala-reflection symbol-table cache. Fixed by gating on
   isXEnabled/RedisLogger.shouldShip (new redis_logging_min_level prop,
   default INFO) and dispatching the actual work onto a small dedicated
   ExecutionContext instead of the calling thread.

2. JsonSchemaGenerator.messageDocsToJsonSchema had no cache of its own,
   walking every message type's field tree via Scala runtime reflection on
   every call; its caller's Redis-backed cache silently falls through to a
   full recompute on any Redis failure. Added an in-process memoization
   (Guava-backed, no Redis dependency) alongside the existing one, using
   the same pattern already proven correct by Helper.getRequiredFieldInfo.
   Independent hardening for a real gap in this file - not confirmed as
   this incident's cause; JsonSchemaGenerator doesn't appear anywhere in
   this incident's JFR execution samples.

3. logback.xml.example sat inert (Logback only auto-loads files named
   exactly logback.xml) with root level hard-coded to DEBUG; deployments
   that never manually copied it over fell back to Logback's own built-in
   DEBUG-to-console default. Renamed to logback.xml so it's actually
   loaded, and changed the level to ${LOG_LEVEL:-INFO}: verbose logging
   should be an explicit per-environment opt-in, not the default every
   deployment silently pays for.

Test plan: see individual test additions (RedisLoggerShouldShipTest,
MdcLoggableDispatchTest, JsonSchemaGeneratorCacheTest,
LogbackDefaultLevelTest) plus full local suite and CI.
@hongwei1
hongwei1 force-pushed the fix/nmb-cpu-gc-incident-combined branch from 9020ebf to 791875c Compare September 23, 2026 20:22
@hongwei1 hongwei1 changed the title fix: NMB sandbox CPU/GC incident - unconditional log masking, missing schema cache, default DEBUG logging fix: production CPU/GC incident - unconditional log masking, missing schema cache, default DEBUG logging Sep 23, 2026
@sonarqubecloud

Copy link
Copy Markdown

@hongwei1

Copy link
Copy Markdown
Contributor Author

Closing to reopen from a cleanly-named branch (the old branch name referenced a client name that shouldn't appear in this repo's history). Same commit, same content, re-opened here.

@hongwei1 hongwei1 closed this Sep 23, 2026
@hongwei1
hongwei1 deleted the fix/nmb-cpu-gc-incident-combined branch September 23, 2026 20:55
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment

Labels

None yet

Projects

None yet

Development

Successfully merging this pull request may close these issues.

1 participant