From 7b31372142cbbd7a4e9e36d9b3d9f34807c7aa12 Mon Sep 17 00:00:00 2001 From: OmarAlJarrah Date: Wed, 17 Jun 2026 04:42:24 +0300 Subject: [PATCH 1/4] fix: emit a single event key when the event-name tag collides with a user key LoggingEvent.log() always emitted the structured event-name tag under the reserved "event" key whenever event(name) was called, with no de-duplication against the other key sources (global context, MDC, per-event field). Because SLF4J's addKeyValue appends rather than replaces, a "event" key supplied by the global context, the folded MDC, or a field(...) produced a second KeyValuePair with the same name, which JSON appenders serialise as invalid duplicate-key JSON. The event-name tag is now authoritative for the "event" key: when a non-empty name is set, any "event" key from the global context, MDC, or a per-event field is suppressed so the event carries the key exactly once. When no name is set, a user-supplied "event" key passes through unchanged. The three folding loops in log() are extracted into small private helpers, which keeps the method under the cyclomatic-complexity threshold and removes the multi-jump loop bodies. --- .../sdk/core/instrumentation/LoggingEvent.kt | 123 +++++++++++------- .../core/instrumentation/LoggingEventTest.kt | 66 ++++++++++ 2 files changed, 145 insertions(+), 44 deletions(-) diff --git a/sdk-core/src/main/kotlin/org/dexpace/sdk/core/instrumentation/LoggingEvent.kt b/sdk-core/src/main/kotlin/org/dexpace/sdk/core/instrumentation/LoggingEvent.kt index d59882a6..4371efd0 100644 --- a/sdk-core/src/main/kotlin/org/dexpace/sdk/core/instrumentation/LoggingEvent.kt +++ b/sdk-core/src/main/kotlin/org/dexpace/sdk/core/instrumentation/LoggingEvent.kt @@ -8,6 +8,7 @@ package org.dexpace.sdk.core.instrumentation import org.slf4j.MDC +import org.slf4j.spi.LoggingEventBuilder import java.util.concurrent.atomic.AtomicBoolean /** @@ -133,6 +134,11 @@ public class LoggingEvent internal constructor( /** * Sets the structured event-name tag emitted under the [EVENT_KEY] key. An empty name * clears any previously set value rather than emitting `event=""`. + * + * The name tag is authoritative for the [EVENT_KEY] (`"event"`) key: when a non-empty name + * is set, any `"event"` key arriving from the logger's global context, the folded MDC, or a + * per-event [field] is suppressed so the event carries the `"event"` key exactly once. When + * no name is set (or it was cleared), a user-supplied `"event"` key passes through unchanged. */ public fun event(name: String): LoggingEvent { if (!enabled) return this @@ -166,51 +172,19 @@ public class LoggingEvent internal constructor( val builder = logger.slf4j.atLevel(logger.slf4jLevel(level)) - // Global context first so per-event fields can override on the SLF4J side. A global-context - // key that is also a per-event field is skipped here and emitted once below from `fields`, - // letting the per-event value win. SLF4J's addKeyValue APPENDS rather than replaces, so - // emitting both would put two KeyValuePairs with the same name on the event — invalid - // duplicate-key JSON in JSON appenders. This mirrors the MDC dedup guard below. - val gc = logger.globalContext - if (gc.isNotEmpty()) { - val perEventKeys = fields - for ((k, v) in gc) { - if (perEventKeys?.containsKey(k) == true) continue - builder.addKeyValue(k, renderForLog(v)) - } - } - - // Fold SLF4J MDC into the structured event so trace.id / span.id set by an - // enclosing TracingScope reaches log backends as structured fields. Only keys - // in the logger's mdcKeys allow-list are folded (default: "trace.id", "span.id"). - // Pass mdcKeys = null on ClientLogger to fold everything (backwards-compat). - // A key emitted from MDC is skipped if it is ALREADY emitted by this event, whether - // via a per-event `field(...)` (added below) or via the logger's globalContext - // (emitted above). Folding such a key again would put a second KeyValuePair on the - // event with the same name, which JSON appenders render as invalid duplicate-key - // JSON — exactly the failure this guard prevents. Both lookups are O(1). - val mdcMap = MDC.getCopyOfContextMap() - if (mdcMap != null) { - val perEventKeys = fields - val allowedMdcKeys = logger.mdcKeys - for ((k, v) in mdcMap) { - if (v == null) continue - // Skip keys already emitted via the per-event fields or the global context - // (duplicate-key JSON guard). A null allow-list means "all keys" (unfiltered). - val alreadyEmitted = perEventKeys?.containsKey(k) == true || gc.containsKey(k) - if (!alreadyEmitted && (allowedMdcKeys == null || allowedMdcKeys.contains(k))) { - builder.addKeyValue(k, v) - } - } - } + // When `event(name)` set a non-empty name, the dedicated [EVENT_KEY] tag is authoritative: + // any `"event"` key arriving from the global context, MDC, or a per-event `field(...)` is + // skipped so the name tag is the single `event` entry. SLF4J's addKeyValue APPENDS rather + // than replaces, so emitting both would put two KeyValuePairs named `event` on the event — + // invalid duplicate-key JSON in JSON appenders. `null` means no name tag is emitted, so the + // user's `"event"` key (if any) passes through normally. + val eventNameTag = eventName + val reservedEventKey = if (eventNameTag != null) EVENT_KEY else null - eventName?.let { builder.addKeyValue(EVENT_KEY, it) } - - fields?.let { - for ((k, v) in it) { - builder.addKeyValue(k, renderForLog(v)) - } - } + emitGlobalContext(builder, logger.globalContext, reservedEventKey) + emitMdc(builder, logger, reservedEventKey) + eventNameTag?.let { builder.addKeyValue(EVENT_KEY, it) } + emitFields(builder, reservedEventKey) cause?.let { builder.setCause(it) } @@ -219,6 +193,67 @@ public class LoggingEvent internal constructor( // -- Internals ------------------------------------------------------------------------------- + /** + * Emits the logger's global context. A global-context key that is also a per-event field is + * skipped here and emitted once below from `fields`, letting the per-event value win. SLF4J's + * addKeyValue APPENDS rather than replaces, so emitting both would put two KeyValuePairs with + * the same name on the event — invalid duplicate-key JSON in JSON appenders. The reserved + * [EVENT_KEY] is skipped when an event-name tag is set so the tag stays authoritative. + */ + private fun emitGlobalContext( + builder: LoggingEventBuilder, + gc: Map, + reservedEventKey: String?, + ) { + if (gc.isEmpty()) return + val perEventKeys = fields + for ((k, v) in gc) { + if (k == reservedEventKey || perEventKeys?.containsKey(k) == true) continue + builder.addKeyValue(k, renderForLog(v)) + } + } + + /** + * Folds SLF4J MDC into the structured event so trace.id / span.id set by an enclosing + * TracingScope reaches log backends as structured fields. Only keys in the logger's mdcKeys + * allow-list are folded (default: "trace.id", "span.id"); a `null` allow-list folds everything + * (backwards-compat). A key already emitted by this event — via a per-event `field(...)`, the + * global context, or the authoritative event-name tag — is skipped so JSON appenders never see + * a duplicate-key entry. All lookups are O(1). + */ + private fun emitMdc( + builder: LoggingEventBuilder, + logger: ClientLogger, + reservedEventKey: String?, + ) { + val mdcMap = MDC.getCopyOfContextMap() ?: return + val perEventKeys = fields + val gc = logger.globalContext + val allowedMdcKeys = logger.mdcKeys + for ((k, v) in mdcMap) { + if (v == null || k == reservedEventKey) continue + val alreadyEmitted = perEventKeys?.containsKey(k) == true || gc.containsKey(k) + if (!alreadyEmitted && (allowedMdcKeys == null || allowedMdcKeys.contains(k))) { + builder.addKeyValue(k, v) + } + } + } + + /** + * Emits the per-event fields. The reserved [EVENT_KEY] is skipped when an event-name tag is set + * so the tag — already emitted by [log] — remains the single `event` entry. + */ + private fun emitFields( + builder: LoggingEventBuilder, + reservedEventKey: String?, + ) { + val map = fields ?: return + for ((k, v) in map) { + if (k == reservedEventKey) continue + builder.addKeyValue(k, renderForLog(v)) + } + } + private fun putField( key: String, value: Any?, diff --git a/sdk-core/src/test/kotlin/org/dexpace/sdk/core/instrumentation/LoggingEventTest.kt b/sdk-core/src/test/kotlin/org/dexpace/sdk/core/instrumentation/LoggingEventTest.kt index b445aef1..a27c628c 100644 --- a/sdk-core/src/test/kotlin/org/dexpace/sdk/core/instrumentation/LoggingEventTest.kt +++ b/sdk-core/src/test/kotlin/org/dexpace/sdk/core/instrumentation/LoggingEventTest.kt @@ -586,6 +586,72 @@ class LoggingEventTest { assertEquals("event", regionEntries.single().value) } + @Test + fun `event name and a colliding field both named event are emitted exactly once`() { + // The event-name tag and a per-event field() named "event" collide on the reserved + // EVENT_KEY. They must produce a single "event" entry — two KeyValuePair entries with + // the same key serialise to invalid duplicate-key JSON in JSON appenders. + val (logger, fake) = enabledLogger() + logger.atInfo().event("request.start").field(LoggingEvent.EVENT_KEY, "override").log() + + val rec = fake.records.single() + val eventEntries = rec.keyValues.filter { it.key == LoggingEvent.EVENT_KEY } + assertEquals( + 1, + eventEntries.size, + "expected exactly one event entry; a second from field() would be a duplicate KeyValuePair", + ) + // The dedicated event-name tag wins over a colliding field. + assertEquals("request.start", eventEntries.single().value) + } + + @Test + fun `event name wins over a colliding globalContext event key, emitted once`() { + // A logger whose globalContext carries an "event" key plus a set event-name tag must + // emit the "event" key once, with the name tag winning. + val (logger, fake) = enabledLogger(mapOf(LoggingEvent.EVENT_KEY to "from-context")) + logger.atInfo().event("request.start").log() + + val rec = fake.records.single() + val eventEntries = rec.keyValues.filter { it.key == LoggingEvent.EVENT_KEY } + assertEquals( + 1, + eventEntries.size, + "expected exactly one event entry; a second from globalContext would be a duplicate KeyValuePair", + ) + assertEquals("request.start", eventEntries.single().value) + } + + @Test + fun `event name wins over a colliding MDC event key, emitted once`() { + installBasicMdcAdapter() + MDC.put(LoggingEvent.EVENT_KEY, "from-mdc") + // Null allow-list folds all MDC keys, so "event" would otherwise be folded. + val fake = FakeSlf4jLogger(threshold = Level.TRACE) + val logger = ClientLogger.forTesting(fake, mdcKeys = null) + logger.atInfo().event("request.start").log() + + val rec = fake.records.single() + val eventEntries = rec.keyValues.filter { it.key == LoggingEvent.EVENT_KEY } + assertEquals( + 1, + eventEntries.size, + "expected exactly one event entry; a second from MDC would be a duplicate KeyValuePair", + ) + assertEquals("request.start", eventEntries.single().value) + } + + @Test + fun `user event key passes through unchanged when no event name is set`() { + // Guard against over-suppression: with no event-name tag, a user "event" field is a + // normal field and must be emitted. + val (logger, fake) = enabledLogger() + logger.atInfo().field(LoggingEvent.EVENT_KEY, "user-value").log() + + val kv = fake.records.single().keyValues.toMap() + assertEquals("user-value", kv[LoggingEvent.EVENT_KEY]) + } + @Test fun `MDC keys absent from globalContext are still folded`() { // Guard the collision fix against over-skipping: an MDC key NOT present in From 6e365ed903ba33ebfe488a6e2d1de0f92e2ad30a Mon Sep 17 00:00:00 2001 From: OmarAlJarrah Date: Sat, 20 Jun 2026 15:45:38 +0300 Subject: [PATCH 2/4] refactor: surface dropped colliding event field at DEBUG When event(name) sets the authoritative event-name tag, a per-event field("event", ...) collides with the reserved EVENT_KEY and its value is dropped so the tag stays the single "event" entry. That drop was silent. Surface it at DEBUG via a small warnOnDroppedEventField helper, so the override is visible while debugging without adding noise on the normal path: DEBUG is off by default, and only the explicit field() collision is flagged (ambient "event" keys from the global context or MDC defer to the tag silently, as before). The disabled-path cost is a single containsKey check. Also thread the already-read globalContext and mdcKeys into emitMdc instead of re-reading them off the logger. --- .../sdk/core/instrumentation/LoggingEvent.kt | 44 +++++++++++++---- .../core/instrumentation/FakeSlf4jLogger.kt | 18 ++++++- .../core/instrumentation/LoggingEventTest.kt | 48 +++++++++++++++++++ 3 files changed, 100 insertions(+), 10 deletions(-) diff --git a/sdk-core/src/main/kotlin/org/dexpace/sdk/core/instrumentation/LoggingEvent.kt b/sdk-core/src/main/kotlin/org/dexpace/sdk/core/instrumentation/LoggingEvent.kt index 4371efd0..488c8bb3 100644 --- a/sdk-core/src/main/kotlin/org/dexpace/sdk/core/instrumentation/LoggingEvent.kt +++ b/sdk-core/src/main/kotlin/org/dexpace/sdk/core/instrumentation/LoggingEvent.kt @@ -139,6 +139,10 @@ public class LoggingEvent internal constructor( * is set, any `"event"` key arriving from the logger's global context, the folded MDC, or a * per-event [field] is suppressed so the event carries the `"event"` key exactly once. When * no name is set (or it was cleared), a user-supplied `"event"` key passes through unchanged. + * + * A per-event `field("event", …)` whose value is dropped this way is reported once at DEBUG so + * the override is visible while debugging; ambient `"event"` keys from the global context or MDC + * defer to the tag silently. */ public fun event(name: String): LoggingEvent { if (!enabled) return this @@ -180,9 +184,11 @@ public class LoggingEvent internal constructor( // user's `"event"` key (if any) passes through normally. val eventNameTag = eventName val reservedEventKey = if (eventNameTag != null) EVENT_KEY else null + if (eventNameTag != null) warnOnDroppedEventField(logger, eventNameTag) - emitGlobalContext(builder, logger.globalContext, reservedEventKey) - emitMdc(builder, logger, reservedEventKey) + val gc = logger.globalContext + emitGlobalContext(builder, gc, reservedEventKey) + emitMdc(builder, gc, logger.mdcKeys, reservedEventKey) eventNameTag?.let { builder.addKeyValue(EVENT_KEY, it) } emitFields(builder, reservedEventKey) @@ -215,21 +221,20 @@ public class LoggingEvent internal constructor( /** * Folds SLF4J MDC into the structured event so trace.id / span.id set by an enclosing - * TracingScope reaches log backends as structured fields. Only keys in the logger's mdcKeys - * allow-list are folded (default: "trace.id", "span.id"); a `null` allow-list folds everything + * TracingScope reaches log backends as structured fields. Only keys in [allowedMdcKeys] are + * folded (default: "trace.id", "span.id"); a `null` allow-list folds everything * (backwards-compat). A key already emitted by this event — via a per-event `field(...)`, the - * global context, or the authoritative event-name tag — is skipped so JSON appenders never see - * a duplicate-key entry. All lookups are O(1). + * global context ([gc]), or the authoritative event-name tag — is skipped so JSON appenders + * never see a duplicate-key entry. All lookups are O(1). */ private fun emitMdc( builder: LoggingEventBuilder, - logger: ClientLogger, + gc: Map, + allowedMdcKeys: Set?, reservedEventKey: String?, ) { val mdcMap = MDC.getCopyOfContextMap() ?: return val perEventKeys = fields - val gc = logger.globalContext - val allowedMdcKeys = logger.mdcKeys for ((k, v) in mdcMap) { if (v == null || k == reservedEventKey) continue val alreadyEmitted = perEventKeys?.containsKey(k) == true || gc.containsKey(k) @@ -254,6 +259,27 @@ public class LoggingEvent internal constructor( } } + /** + * Surfaces, at DEBUG, the one case where the authoritative event-name tag silently swallows a + * caller value: a per-event `field(EVENT_KEY, …)` whose key collides with the name tag. That + * field is dropped by [emitFields], so the caller's value never reaches the backend; logging it + * here makes the misuse visible when DEBUG is on (idiomatic SLF4J parameterised logging formats + * the message only then). An ambient `EVENT_KEY` from the global context or MDC is expected to + * defer to the tag and is *not* flagged — only the explicit `field(...)` collision is. + */ + private fun warnOnDroppedEventField( + logger: ClientLogger, + eventNameTag: String, + ) { + if (fields?.containsKey(EVENT_KEY) != true) return + logger.slf4j.debug( + "LoggingEvent: dropped field \"{}\" because event(\"{}\") owns that key; " + + "rename the field to keep its value.", + EVENT_KEY, + eventNameTag, + ) + } + private fun putField( key: String, value: Any?, diff --git a/sdk-core/src/test/kotlin/org/dexpace/sdk/core/instrumentation/FakeSlf4jLogger.kt b/sdk-core/src/test/kotlin/org/dexpace/sdk/core/instrumentation/FakeSlf4jLogger.kt index bd389357..86ab7098 100644 --- a/sdk-core/src/test/kotlin/org/dexpace/sdk/core/instrumentation/FakeSlf4jLogger.kt +++ b/sdk-core/src/test/kotlin/org/dexpace/sdk/core/instrumentation/FakeSlf4jLogger.kt @@ -11,6 +11,7 @@ import org.slf4j.Logger import org.slf4j.Marker import org.slf4j.event.KeyValuePair import org.slf4j.event.Level +import org.slf4j.helpers.MessageFormatter import org.slf4j.spi.LoggingEventBuilder import org.slf4j.spi.NOPLoggingEventBuilder @@ -35,6 +36,18 @@ internal class FakeSlf4jLogger( val records: MutableList = mutableListOf() + /** A plain (non-structured) message logged via the `Logger.debug(...)` etc. seams. */ + data class PlainMessage( + val level: Level, + val message: String?, + ) + + /** + * Captures plain message-API log calls (e.g. `debug(format, a, b)`) separately from [records] + * so structured-event assertions using `records.single()` are unaffected by diagnostics. + */ + val plainMessages: MutableList = mutableListOf() + private var threshold: Level = threshold private var disabled: Boolean = false @@ -144,7 +157,10 @@ internal class FakeSlf4jLogger( format: String?, arg1: Any?, arg2: Any?, - ) {} + ) { + if (!isDebugEnabled) return + plainMessages.add(PlainMessage(Level.DEBUG, MessageFormatter.format(format, arg1, arg2).message)) + } override fun debug( format: String?, diff --git a/sdk-core/src/test/kotlin/org/dexpace/sdk/core/instrumentation/LoggingEventTest.kt b/sdk-core/src/test/kotlin/org/dexpace/sdk/core/instrumentation/LoggingEventTest.kt index a27c628c..716edbe0 100644 --- a/sdk-core/src/test/kotlin/org/dexpace/sdk/core/instrumentation/LoggingEventTest.kt +++ b/sdk-core/src/test/kotlin/org/dexpace/sdk/core/instrumentation/LoggingEventTest.kt @@ -652,6 +652,54 @@ class LoggingEventTest { assertEquals("user-value", kv[LoggingEvent.EVENT_KEY]) } + @Test + fun `dropping a colliding event field is surfaced at DEBUG`() { + // The field() value is silently swallowed by the authoritative name tag; a DEBUG + // diagnostic must surface that so the misuse is visible when debugging. + val (logger, fake) = enabledLogger() + logger.atInfo().event("request.start").field(LoggingEvent.EVENT_KEY, "override").log() + + val message = fake.plainMessages.single { it.level == Level.DEBUG }.message!! + assertContains(message, LoggingEvent.EVENT_KEY) + assertContains(message, "request.start") + // The structured event still carries the name-tag value exactly once (unchanged behaviour). + val eventEntries = fake.records.single().keyValues.filter { it.key == LoggingEvent.EVENT_KEY } + assertEquals("request.start", eventEntries.single().value) + } + + @Test + fun `no DEBUG diagnostic when the level is disabled`() { + // The diagnostic must cost nothing visible when DEBUG is off — SLF4J's parameterised + // logging skips formatting, and nothing is recorded. + val fake = FakeSlf4jLogger(threshold = Level.INFO) + val logger = ClientLogger.forTesting(fake) + logger.atInfo().event("request.start").field(LoggingEvent.EVENT_KEY, "override").log() + + assertTrue(fake.plainMessages.isEmpty()) + } + + @Test + fun `no DEBUG diagnostic without a colliding field`() { + // Only the explicit field() collision is flagged: a plain event(name), or an ambient + // globalContext "event" key, must not emit the diagnostic. + val (loggerNoField, fakeNoField) = enabledLogger() + loggerNoField.atInfo().event("request.start").log() + assertTrue(fakeNoField.plainMessages.isEmpty()) + + val (loggerCtx, fakeCtx) = enabledLogger(mapOf(LoggingEvent.EVENT_KEY to "from-context")) + loggerCtx.atInfo().event("request.start").log() + assertTrue(fakeCtx.plainMessages.isEmpty()) + } + + @Test + fun `no DEBUG diagnostic when a user event field has no name tag`() { + // With no name tag set the user field is legitimately emitted, not dropped — so no warning. + val (logger, fake) = enabledLogger() + logger.atInfo().field(LoggingEvent.EVENT_KEY, "user-value").log() + + assertTrue(fake.plainMessages.isEmpty()) + } + @Test fun `MDC keys absent from globalContext are still folded`() { // Guard the collision fix against over-skipping: an MDC key NOT present in From 75bc3f0da69aa8be94b0c4e40211c235bd30db6f Mon Sep 17 00:00:00 2001 From: OmarAlJarrah Date: Sat, 20 Jun 2026 23:31:01 +0300 Subject: [PATCH 3/4] fix: throttle the dropped-"event"-field log diagnostic to once per logger MIME-Version: 1.0 Content-Type: text/plain; charset=UTF-8 Content-Transfer-Encoding: 8bit The DEBUG hint emitted when a per-event field("event", …) collides with the authoritative event(name) tag fired on every log() call, so a misuse sitting in a hot loop flooded DEBUG with the same line. The collision is a static call-site error, so a single line per logger is enough to surface it. The once-guard lives on ClientLogger because LoggingEvent is single-shot, so the "already warned" state has to outlive it: a CAS-gated AtomicBoolean, checked after isDebugEnabled so the guard is spent only on an actual emission and a level enabled later at runtime still warns once. Adds a regression test asserting the diagnostic fires at most once across repeated collisions on one logger. --- .../sdk/core/instrumentation/ClientLogger.kt | 32 +++++++++++++++++++ .../sdk/core/instrumentation/LoggingEvent.kt | 23 ++++++------- .../core/instrumentation/LoggingEventTest.kt | 22 +++++++++++++ 3 files changed, 64 insertions(+), 13 deletions(-) diff --git a/sdk-core/src/main/kotlin/org/dexpace/sdk/core/instrumentation/ClientLogger.kt b/sdk-core/src/main/kotlin/org/dexpace/sdk/core/instrumentation/ClientLogger.kt index ee36ed81..57987a59 100644 --- a/sdk-core/src/main/kotlin/org/dexpace/sdk/core/instrumentation/ClientLogger.kt +++ b/sdk-core/src/main/kotlin/org/dexpace/sdk/core/instrumentation/ClientLogger.kt @@ -10,6 +10,7 @@ package org.dexpace.sdk.core.instrumentation import org.slf4j.Logger import org.slf4j.LoggerFactory import org.slf4j.event.Level +import java.util.concurrent.atomic.AtomicBoolean /** * Structured-logging facade with a zero-allocation disabled-level fast path. @@ -144,6 +145,37 @@ public class ClientLogger private constructor( internal fun slf4jLevel(level: LogLevel): Level = toSlf4j(level) + /** + * One-shot guard for the [warnDroppedEventFieldOnce] diagnostic. The misuse it flags — a + * per-event `field("event", …)` colliding with the authoritative `event(name)` tag — is a + * static call-site error, so a single line per logger surfaces it. State lives here rather + * than on the single-shot [LoggingEvent] so a hot loop emitting the same misuse can't flood + * DEBUG. + */ + private val droppedEventFieldWarned: AtomicBoolean = AtomicBoolean(false) + + /** + * Emits — at most once per logger — the DEBUG hint that a per-event field named + * [LoggingEvent.EVENT_KEY] was dropped because `event(name)` owns that key. The + * [eventNameTag] of the first observed collision is recorded as an example; the fix + * ("rename the field") is the same regardless of the name. + * + * The `isDebugEnabled` check precedes the one-shot CAS so the guard is spent only on an + * actual emission: if DEBUG is off at the first collision and is enabled later (SLF4J levels + * can change at runtime), the warning still fires once. When DEBUG is off the call is a single + * cheap boolean check, which keeps it off the hot path. + */ + internal fun warnDroppedEventFieldOnce(eventNameTag: String) { + if (!slf4j.isDebugEnabled) return + if (!droppedEventFieldWarned.compareAndSet(false, true)) return + slf4j.debug( + "LoggingEvent: dropped a field named \"{}\" because event(\"{}\") owns that key; " + + "rename the field to keep its value. (logged once per logger)", + LoggingEvent.EVENT_KEY, + eventNameTag, + ) + } + private fun toSlf4j(level: LogLevel): Level = when (level) { LogLevel.ERROR -> Level.ERROR diff --git a/sdk-core/src/main/kotlin/org/dexpace/sdk/core/instrumentation/LoggingEvent.kt b/sdk-core/src/main/kotlin/org/dexpace/sdk/core/instrumentation/LoggingEvent.kt index 488c8bb3..99fd3d90 100644 --- a/sdk-core/src/main/kotlin/org/dexpace/sdk/core/instrumentation/LoggingEvent.kt +++ b/sdk-core/src/main/kotlin/org/dexpace/sdk/core/instrumentation/LoggingEvent.kt @@ -260,24 +260,21 @@ public class LoggingEvent internal constructor( } /** - * Surfaces, at DEBUG, the one case where the authoritative event-name tag silently swallows a - * caller value: a per-event `field(EVENT_KEY, …)` whose key collides with the name tag. That - * field is dropped by [emitFields], so the caller's value never reaches the backend; logging it - * here makes the misuse visible when DEBUG is on (idiomatic SLF4J parameterised logging formats - * the message only then). An ambient `EVENT_KEY` from the global context or MDC is expected to - * defer to the tag and is *not* flagged — only the explicit `field(...)` collision is. + * Surfaces the one case where the authoritative event-name tag silently swallows a caller + * value: a per-event `field(EVENT_KEY, …)` whose key collides with the name tag. That field is + * dropped by [emitFields], so the caller's value never reaches the backend. An ambient + * `EVENT_KEY` from the global context or MDC is expected to defer to the tag and is *not* + * flagged — only the explicit `field(...)` collision is. + * + * The actual DEBUG emission, and its once-per-logger throttle, live on [ClientLogger] — + * [LoggingEvent] is single-shot, so the "already warned" state has to outlive it. See + * [ClientLogger.warnDroppedEventFieldOnce]. */ private fun warnOnDroppedEventField( logger: ClientLogger, eventNameTag: String, ) { - if (fields?.containsKey(EVENT_KEY) != true) return - logger.slf4j.debug( - "LoggingEvent: dropped field \"{}\" because event(\"{}\") owns that key; " + - "rename the field to keep its value.", - EVENT_KEY, - eventNameTag, - ) + if (fields?.containsKey(EVENT_KEY) == true) logger.warnDroppedEventFieldOnce(eventNameTag) } private fun putField( diff --git a/sdk-core/src/test/kotlin/org/dexpace/sdk/core/instrumentation/LoggingEventTest.kt b/sdk-core/src/test/kotlin/org/dexpace/sdk/core/instrumentation/LoggingEventTest.kt index 716edbe0..fdb0c2d4 100644 --- a/sdk-core/src/test/kotlin/org/dexpace/sdk/core/instrumentation/LoggingEventTest.kt +++ b/sdk-core/src/test/kotlin/org/dexpace/sdk/core/instrumentation/LoggingEventTest.kt @@ -700,6 +700,28 @@ class LoggingEventTest { assertTrue(fake.plainMessages.isEmpty()) } + @Test + fun `dropped colliding event field is reported at most once per logger`() { + // The misuse is a static call-site error: repeating it on the same logger (e.g. in a hot + // loop) must not flood DEBUG. The diagnostic fires once per logger; every event is still + // emitted with the name tag intact. + val (logger, fake) = enabledLogger() + repeat(3) { + logger.atInfo().event("request.start").field(LoggingEvent.EVENT_KEY, "override").log() + } + + assertEquals( + 1, + fake.plainMessages.count { it.level == Level.DEBUG }, + "expected the dropped-field diagnostic at most once per logger", + ) + assertEquals(3, fake.records.size, "every structured event is still emitted") + fake.records.forEach { rec -> + val eventEntries = rec.keyValues.filter { it.key == LoggingEvent.EVENT_KEY } + assertEquals("request.start", eventEntries.single().value) + } + } + @Test fun `MDC keys absent from globalContext are still folded`() { // Guard the collision fix against over-skipping: an MDC key NOT present in From 69d3972dcd717a9707b550518ccbd918c1329c0a Mon Sep 17 00:00:00 2001 From: OmarAlJarrah Date: Sat, 20 Jun 2026 23:39:09 +0300 Subject: [PATCH 4/4] perf: skip the dropped-event-field probe when DEBUG is disabled warnOnDroppedEventField probed the per-event field map on every log() call that set an event-name tag, including when DEBUG was off and the diagnostic it guards could never be emitted. Front the probe with the DEBUG-level check so the containsKey lookup is skipped on that hot path; the once-per-logger throttle still re-checks the level before spending its guard, so behaviour is unchanged. --- .../org/dexpace/sdk/core/instrumentation/LoggingEvent.kt | 6 ++++++ 1 file changed, 6 insertions(+) diff --git a/sdk-core/src/main/kotlin/org/dexpace/sdk/core/instrumentation/LoggingEvent.kt b/sdk-core/src/main/kotlin/org/dexpace/sdk/core/instrumentation/LoggingEvent.kt index 99fd3d90..67a226f4 100644 --- a/sdk-core/src/main/kotlin/org/dexpace/sdk/core/instrumentation/LoggingEvent.kt +++ b/sdk-core/src/main/kotlin/org/dexpace/sdk/core/instrumentation/LoggingEvent.kt @@ -269,11 +269,17 @@ public class LoggingEvent internal constructor( * The actual DEBUG emission, and its once-per-logger throttle, live on [ClientLogger] — * [LoggingEvent] is single-shot, so the "already warned" state has to outlive it. See * [ClientLogger.warnDroppedEventFieldOnce]. + * + * The DEBUG check fronts the field-map probe: when DEBUG is off the diagnostic can never fire, + * so the [containsKey] lookup would be pure overhead on the hot path (this runs on every + * `log()` that set an event-name tag). `VERBOSE` maps to SLF4J `DEBUG`, the same level + * [ClientLogger.warnDroppedEventFieldOnce] re-checks before spending its once-per-logger guard. */ private fun warnOnDroppedEventField( logger: ClientLogger, eventNameTag: String, ) { + if (!logger.canLog(LogLevel.VERBOSE)) return if (fields?.containsKey(EVENT_KEY) == true) logger.warnDroppedEventFieldOnce(eventNameTag) }