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 d59882a6..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 @@ -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,15 @@ 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. + * + * 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 @@ -166,58 +176,112 @@ 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. + // 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 + if (eventNameTag != null) warnOnDroppedEventField(logger, eventNameTag) + 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)) - } - } + emitGlobalContext(builder, gc, reservedEventKey) + emitMdc(builder, gc, logger.mdcKeys, reservedEventKey) + eventNameTag?.let { builder.addKeyValue(EVENT_KEY, it) } + emitFields(builder, reservedEventKey) - // 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) - } - } - } + cause?.let { builder.setCause(it) } + + builder.log(message) + } - eventName?.let { builder.addKeyValue(EVENT_KEY, it) } + // -- Internals ------------------------------------------------------------------------------- - fields?.let { - for ((k, v) in it) { - builder.addKeyValue(k, renderForLog(v)) - } + /** + * 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)) } + } - cause?.let { builder.setCause(it) } + /** + * 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 [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 ([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, + gc: Map, + allowedMdcKeys: Set?, + reservedEventKey: String?, + ) { + val mdcMap = MDC.getCopyOfContextMap() ?: return + val perEventKeys = fields + 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) + } + } + } - builder.log(message) + /** + * 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)) + } } - // -- Internals ------------------------------------------------------------------------------- + /** + * 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]. + * + * 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) + } private fun putField( key: String, 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 b445aef1..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 @@ -586,6 +586,142 @@ 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 `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 `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