Skip to content

Commit efa7616

Browse files
EtaCassiopeiaEtaCassiopeia
authored
Add structured logging hook with ZIO log annotations (#99)
* Add structured logging hook with ZIO log annotations * Document context redaction behavior in hooks guide * Fix review issues: hookData for start time, renderAttributeValue, docs accuracy
1 parent 0b03531 commit efa7616

3 files changed

Lines changed: 265 additions & 0 deletions

File tree

‎core/src/main/scala/zio/openfeature/Hook.scala‎

Lines changed: 125 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -191,6 +191,131 @@ object FeatureHook {
191191
.unit
192192
}
193193

194+
/** A structured logging hook that adds machine-readable annotations to log output.
195+
*
196+
* Unlike `logging()` which produces plain text messages, this hook uses `ZIO.logAnnotate` to attach structured
197+
* fields (flag key, type, provider, reason, variant, duration) that are preserved by `zio-logging` backends (JSON,
198+
* SLF4J MDC, etc.). This enables filtering and querying flag evaluations in log aggregation systems.
199+
*
200+
* @param beforeLevel
201+
* Log level for pre-evaluation messages. `None` disables before logging.
202+
* @param afterLevel
203+
* Log level for successful evaluation messages.
204+
* @param errorLevel
205+
* Log level for evaluation error messages.
206+
* @param logContext
207+
* Whether to include the evaluation context (targeting key + attributes) in log annotations.
208+
* @param redactKeys
209+
* Attribute keys to redact from logged context (e.g., `Set("email", "ip")`). Values are replaced with
210+
* `"[REDACTED]"`. Only applies when `logContext` is true.
211+
*/
212+
def structuredLogging(
213+
beforeLevel: Option[LogLevel] = Some(LogLevel.Debug),
214+
afterLevel: Option[LogLevel] = Some(LogLevel.Debug),
215+
errorLevel: Option[LogLevel] = Some(LogLevel.Warning),
216+
logContext: Boolean = false,
217+
redactKeys: Set[String] = Set.empty
218+
): FeatureHook = new FeatureHook {
219+
private val startTimeKey = TypedKey[Long]("structuredLogging.startTime")
220+
221+
private def annotate(annotations: Set[zio.LogAnnotation])(effect: UIO[Unit]): UIO[Unit] =
222+
ZIO.logAnnotate(annotations)(effect)
223+
224+
private def baseAnnotations(ctx: HookContext): Set[zio.LogAnnotation] =
225+
Set(
226+
zio.LogAnnotation("flag.key", ctx.flagKey),
227+
zio.LogAnnotation("flag.type", ctx.flagType.name),
228+
zio.LogAnnotation("flag.provider", ctx.providerMetadata.name)
229+
) ++ ctx.clientMetadata.domain.map(d => zio.LogAnnotation("flag.domain", d)).toSet
230+
231+
private def contextAnnotations(ctx: HookContext): Set[zio.LogAnnotation] =
232+
if (!logContext) Set.empty
233+
else {
234+
val targeting = ctx.evaluationContext.targetingKey
235+
.map(k => zio.LogAnnotation("flag.context.targetingKey", k))
236+
.toSet
237+
val attrs = ctx.evaluationContext.attributes.map { case (key, value) =>
238+
val v = if (redactKeys.contains(key)) "[REDACTED]" else renderAttributeValue(value)
239+
zio.LogAnnotation(s"flag.context.$key", v)
240+
}.toSet
241+
targeting ++ attrs
242+
}
243+
244+
private def renderAttributeValue(attr: AttributeValue): String = attr match {
245+
case AttributeValue.BoolValue(v) => v.toString
246+
case AttributeValue.StringValue(v) => v
247+
case AttributeValue.IntValue(v) => v.toString
248+
case AttributeValue.LongValue(v) => v.toString
249+
case AttributeValue.DoubleValue(v) => v.toString
250+
case AttributeValue.InstantValue(v) => v.toString
251+
case AttributeValue.ListValue(vs) => vs.map(renderAttributeValue).mkString("[", ", ", "]")
252+
case AttributeValue.StructValue(m) =>
253+
m.map { case (k, v) => s"$k=${renderAttributeValue(v)}" }.mkString("{", ", ", "}")
254+
}
255+
256+
private def logAtLevel(level: LogLevel, message: String): UIO[Unit] =
257+
level match {
258+
case LogLevel.Trace => ZIO.logTrace(message)
259+
case LogLevel.Debug => ZIO.logDebug(message)
260+
case LogLevel.Info => ZIO.logInfo(message)
261+
case LogLevel.Warning => ZIO.logWarning(message)
262+
case LogLevel.Error => ZIO.logError(message)
263+
case _ => ZIO.logInfo(message)
264+
}
265+
266+
// Uses HookData (per-hook mutable state) for start time instead of HookHints,
267+
// so that `before` can return None and avoid corrupting the compose pipeline's
268+
// context-modified tracking.
269+
override def before(ctx: HookContext, hints: HookHints): UIO[Option[(EvaluationContext, HookHints)]] =
270+
for {
271+
now <- Clock.nanoTime
272+
_ = ctx.hookData.set(startTimeKey, now)
273+
_ <- beforeLevel match {
274+
case Some(level) =>
275+
annotate(baseAnnotations(ctx) ++ contextAnnotations(ctx))(
276+
logAtLevel(level, s"Evaluating flag '${ctx.flagKey}'")
277+
)
278+
case None => ZIO.unit
279+
}
280+
} yield None
281+
282+
private def elapsed(ctx: HookContext): Duration = {
283+
val end = java.lang.System.nanoTime()
284+
val start = ctx.hookData.get(startTimeKey).getOrElse(end)
285+
Duration.fromNanos(end - start)
286+
}
287+
288+
override def after[A](ctx: HookContext, details: FlagResolution[A], hints: HookHints): UIO[Unit] =
289+
afterLevel match {
290+
case Some(level) =>
291+
val duration = elapsed(ctx)
292+
val annotations = baseAnnotations(ctx) ++ contextAnnotations(ctx) ++ Set(
293+
zio.LogAnnotation("flag.value", String.valueOf(details.value)),
294+
zio.LogAnnotation("flag.reason", details.reason.toString),
295+
zio.LogAnnotation("flag.duration_ms", duration.toMillis.toString)
296+
) ++ details.variant.map(v => zio.LogAnnotation("flag.variant", v)).toSet
297+
annotate(annotations)(
298+
logAtLevel(level, s"Flag '${ctx.flagKey}' = ${details.value} (${details.reason}, ${duration.toMillis}ms)")
299+
)
300+
case None => ZIO.unit
301+
}
302+
303+
override def error(ctx: HookContext, err: FeatureFlagError, hints: HookHints): UIO[Unit] =
304+
errorLevel match {
305+
case Some(level) =>
306+
val duration = elapsed(ctx)
307+
val annotations = baseAnnotations(ctx) ++ contextAnnotations(ctx) ++ Set(
308+
zio.LogAnnotation("flag.error", err.message),
309+
zio.LogAnnotation("flag.error.type", err.getClass.getSimpleName),
310+
zio.LogAnnotation("flag.duration_ms", duration.toMillis.toString)
311+
)
312+
annotate(annotations)(
313+
logAtLevel(level, s"Flag '${ctx.flagKey}' evaluation failed: ${err.message}")
314+
)
315+
case None => ZIO.unit
316+
}
317+
}
318+
194319
def metrics(onEvaluation: (String, Duration, Boolean) => UIO[Unit]): FeatureHook =
195320
new FeatureHook {
196321
private val startTimeKey = TypedKey[Long]("metrics.startTime")

‎core/src/test/scala/zio/openfeature/HookSpec.scala‎

Lines changed: 70 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -269,6 +269,76 @@ object HookSpec extends ZIOSpecDefault {
269269
} yield assertTrue(beforeResult.isEmpty)
270270
}
271271
),
272+
suite("FeatureHook.structuredLogging")(
273+
test("before records start time in hookData and returns None") {
274+
val hook = FeatureHook.structuredLogging()
275+
val hookCtx = makeHookContext()
276+
for {
277+
result <- hook.before(hookCtx, HookHints.empty)
278+
} yield
279+
// Returns None so it doesn't interfere with compose pipeline's context tracking
280+
assertTrue(result.isEmpty) &&
281+
assertTrue(hookCtx.hookData.get(TypedKey[Long]("structuredLogging.startTime")).isDefined)
282+
},
283+
test("after completes successfully") {
284+
val hook = FeatureHook.structuredLogging()
285+
val hookCtx = makeHookContext()
286+
val resolution = FlagResolution.default("test", true)
287+
for {
288+
_ <- hook.before(hookCtx, HookHints.empty)
289+
_ <- hook.after(hookCtx, resolution, HookHints.empty)
290+
} yield assertTrue(true)
291+
},
292+
test("error completes successfully") {
293+
val hook = FeatureHook.structuredLogging()
294+
val hookCtx = makeHookContext()
295+
for {
296+
_ <- hook.before(hookCtx, HookHints.empty)
297+
_ <- hook.error(hookCtx, FeatureFlagError.FlagNotFound("test"), HookHints.empty)
298+
} yield assertTrue(true)
299+
},
300+
test("disabled levels skip logging but still track start time") {
301+
val hook = FeatureHook.structuredLogging(beforeLevel = None, afterLevel = None, errorLevel = None)
302+
val hookCtx = makeHookContext()
303+
val resolution = FlagResolution.default("test", true)
304+
for {
305+
beforeResult <- hook.before(hookCtx, HookHints.empty)
306+
_ <- hook.after(hookCtx, resolution, HookHints.empty)
307+
_ <- hook.error(hookCtx, FeatureFlagError.FlagNotFound("test"), HookHints.empty)
308+
} yield assertTrue(beforeResult.isEmpty) &&
309+
assertTrue(hookCtx.hookData.get(TypedKey[Long]("structuredLogging.startTime")).isDefined)
310+
},
311+
test("context logging with targeting key and attributes completes") {
312+
val hook = FeatureHook.structuredLogging(logContext = true)
313+
val hookCtx = makeHookContext().copy(
314+
evaluationContext = EvaluationContext.builder
315+
.targetingKey("user-123")
316+
.attribute("plan", "premium")
317+
.build
318+
)
319+
val resolution = FlagResolution.default("test", true)
320+
for {
321+
_ <- hook.before(hookCtx, HookHints.empty)
322+
_ <- hook.after(hookCtx, resolution, HookHints.empty)
323+
} yield assertTrue(true)
324+
},
325+
test("redactKeys hides sensitive values while preserving others") {
326+
val hook =
327+
FeatureHook.structuredLogging(logContext = true, redactKeys = Set("email"))
328+
val hookCtx = makeHookContext().copy(
329+
evaluationContext = EvaluationContext.builder
330+
.targetingKey("user-123")
331+
.attribute("email", "secret@example.com")
332+
.attribute("plan", "premium")
333+
.build
334+
)
335+
val resolution = FlagResolution.default("test", true)
336+
for {
337+
_ <- hook.before(hookCtx, HookHints.empty)
338+
_ <- hook.after(hookCtx, resolution, HookHints.empty)
339+
} yield assertTrue(true)
340+
}
341+
),
272342
suite("FeatureHook.compose edge cases")(
273343
test("compose with empty list") {
274344
val composed = FeatureHook.compose(Nil)

‎docs/hooks.md‎

Lines changed: 70 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -84,6 +84,76 @@ val loggingHook = FeatureHook.logging(
8484
FeatureFlags.addHook(loggingHook)
8585
```
8686

87+
### Structured Logging Hook
88+
89+
A richer logging hook that adds machine-readable annotations to log output via `ZIO.logAnnotate`. Unlike the basic `logging()` hook which produces plain text messages, structured logging attaches typed fields that are preserved by `zio-logging` backends (JSON, SLF4J MDC, OpenTelemetry, etc.).
90+
91+
```scala
92+
val hook = FeatureHook.structuredLogging(
93+
beforeLevel = Some(LogLevel.Debug), // None to disable
94+
afterLevel = Some(LogLevel.Debug),
95+
errorLevel = Some(LogLevel.Warning),
96+
logContext = false, // include evaluation context in annotations
97+
redactKeys = Set("email", "ip") // redact sensitive context attributes
98+
)
99+
100+
FeatureFlags.addHook(hook)
101+
```
102+
103+
**Log annotations added:**
104+
105+
| Annotation | Stage | Example |
106+
|:-----------|:------|:--------|
107+
| `flag.key` | all | `"dark-mode"` |
108+
| `flag.type` | all | `"Boolean"` |
109+
| `flag.provider` | all | `"OptimizelyProvider"` |
110+
| `flag.domain` | all (if set) | `"my-service"` |
111+
| `flag.value` | after | `"true"` |
112+
| `flag.reason` | after | `"TargetingMatch"` |
113+
| `flag.variant` | after (if present) | `"treatment-a"` |
114+
| `flag.duration_ms` | after, error | `"12"` |
115+
| `flag.error` | error | `"Flag 'x' not found"` |
116+
| `flag.error.type` | error | `"FlagNotFound"` |
117+
| `flag.context.targetingKey` | before, after, error (if `logContext`) | `"user-123"` |
118+
| `flag.context.<attr>` | before, after, error (if `logContext`) | `"premium"` |
119+
120+
**Context logging and redaction:**
121+
122+
When `logContext = true`, the hook includes the evaluation context (targeting key + attributes) in log annotations. The `redactKeys` parameter specifies which attribute keys should have their values replaced with `"[REDACTED]"` — the key is still logged so you know the attribute was present, but the value is hidden.
123+
124+
```scala
125+
val hook = FeatureHook.structuredLogging(
126+
logContext = true,
127+
redactKeys = Set("email", "ssn")
128+
)
129+
130+
// With context: targetingKey="user-123", email="john@example.com", plan="premium"
131+
// Produces annotations:
132+
// flag.context.targetingKey = "user-123" ← not redacted
133+
// flag.context.email = "[REDACTED]" ← value hidden
134+
// flag.context.plan = "premium" ← not redacted
135+
```
136+
137+
When `logContext = false` (default), no context attributes are logged and `redactKeys` has no effect.
138+
139+
Note: `redactKeys` only applies to context attributes, not to the targeting key. The targeting key is always logged as-is when `logContext` is enabled.
140+
141+
**Example JSON output** (with `zio-logging` JSON backend):
142+
143+
```json
144+
{
145+
"level": "DEBUG",
146+
"message": "Flag 'dark-mode' = true (TargetingMatch, 3ms)",
147+
"flag.key": "dark-mode",
148+
"flag.type": "Boolean",
149+
"flag.provider": "OptimizelyProvider",
150+
"flag.value": "true",
151+
"flag.reason": "TargetingMatch",
152+
"flag.variant": "treatment-a",
153+
"flag.duration_ms": "3"
154+
}
155+
```
156+
87157
### Metrics Hook
88158

89159
Records evaluation metrics:

0 commit comments

Comments
 (0)