Skip to content

fix: emit a single "event" key when the event-name tag collides with a user key #132

New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

Sign up for GitHub

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Open
OmarAlJarrah wants to merge 2 commits into
base: main
Choose a base branch
from
Open

fix: emit a single "event" key when the event-name tag collides with a user key #132

Show file tree
Hide file tree
Changes from all commits
Commits
Show all changes
2 commits
Select commit Hold shift + click to select a range
7b31372
fix: emit a single event key when the event-name tag collides with a …
OmarAlJarrah Jun 17, 2026
6e365ed
refactor: surface dropped colliding event field at DEBUG
OmarAlJarrah Jun 20, 2026
File filter

Filter by extension

Filter by extension
Conversations
Failed to load comments.
Loading
Jump to
Jump to file
Failed to load files.
Loading
Diff view
Diff view
147 changes: 104 additions & 43 deletions sdk-core/src/main/kotlin/org/dexpace/sdk/core/instrumentation/LoggingEvent.kt
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -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

/**
Expand Down Expand Up @@ -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
Expand Down Expand Up @@ -166,58 +176,109 @@ 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) }

eventName?.let { builder.addKeyValue(EVENT_KEY, it) }
builder.log(message)
}

fields?.let {
for ((k, v) in it) {
builder.addKeyValue(k, renderForLog(v))
}
// -- 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<String, Any?>,
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<String, Any?>,
allowedMdcKeys: Set<String>?,
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, 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,
Expand Down
18 changes: 17 additions & 1 deletion sdk-core/src/test/kotlin/org/dexpace/sdk/core/instrumentation/FakeSlf4jLogger.kt
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -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

Expand All @@ -35,6 +36,18 @@ internal class FakeSlf4jLogger(

val records: MutableList<Recorded> = 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<PlainMessage> = mutableListOf()

private var threshold: Level = threshold
private var disabled: Boolean = false

Expand Down Expand Up @@ -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?,
Expand Down
114 changes: 114 additions & 0 deletions sdk-core/src/test/kotlin/org/dexpace/sdk/core/instrumentation/LoggingEventTest.kt
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -586,6 +586,120 @@ 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 `MDC keys absent from globalContext are still folded`() {
// Guard the collision fix against over-skipping: an MDC key NOT present in
Expand Down
Loading