Skip to content

Commit 037826f

Browse files
toddbaerttoddbaert
authored
feat: add logging hook, rm logging from evaluation (open-feature#1084)
* feat: add logging hook, rm logging from evaluation Signed-off-by: Todd Baert <todd.baert@dynatrace.com> * fixup: remove public Signed-off-by: Todd Baert <todd.baert@dynatrace.com> * fixup: debug, not info Signed-off-by: Todd Baert <todd.baert@dynatrace.com> * fixup: move comment Signed-off-by: Todd Baert <todd.baert@dynatrace.com> * fixup: underscoes Signed-off-by: Todd Baert <todd.baert@dynatrace.com> * fixup: add to readme Signed-off-by: Todd Baert <todd.baert@dynatrace.com> --------- Signed-off-by: Todd Baert <todd.baert@dynatrace.com>
1 parent 78e3371 commit 037826f

File tree

6 files changed

+297
-29
lines changed

6 files changed

+297
-29
lines changed

‎README.md

+8
Original file line numberDiff line numberDiff line change
@@ -218,6 +218,14 @@ Once you've added a hook as a dependency, it can be registered at the global, cl
218218
### Logging
219219

220220
The Java SDK uses SLF4J. See the [SLF4J manual](https://slf4j.org/manual.html) for complete documentation.
221+
Note that in accordance with the OpenFeature specification, the SDK doesn't generally log messages during flag evaluation.
222+
223+
#### Logging Hook
224+
225+
The Java SDK includes a `LoggingHook`, which logs detailed information at key points during flag evaluation, using SLF4J's structured logging API.
226+
This hook can be particularly helpful for troubleshooting and debugging; simply attach it at the global, client or invocation level and ensure your log level is set to "debug".
227+
228+
See [hooks](#hooks) for more information on configuring hooks.
221229

222230
### Domains
223231

‎src/main/java/dev/openfeature/sdk/HookSupport.java

+25-22
Original file line numberDiff line numberDiff line change
@@ -17,19 +17,28 @@
1717
@SuppressWarnings({ "unchecked", "rawtypes" })
1818
class HookSupport {
1919

20-
public void errorHooks(FlagValueType flagValueType, HookContext hookCtx, Exception e, List<Hook> hooks,
20+
public EvaluationContext beforeHooks(FlagValueType flagValueType, HookContext hookCtx, List<Hook> hooks,
2121
Map<String, Object> hints) {
22-
executeHooks(flagValueType, hooks, "error", hook -> hook.error(hookCtx, e, hints));
22+
Stream<EvaluationContext> result = callBeforeHooks(flagValueType, hookCtx, hooks, hints);
23+
return hookCtx.getCtx().merge(
24+
result.reduce(hookCtx.getCtx(), (EvaluationContext accumulated, EvaluationContext current) -> {
25+
return accumulated.merge(current);
26+
}));
27+
}
28+
29+
public void afterHooks(FlagValueType flagValueType, HookContext hookContext, FlagEvaluationDetails details,
30+
List<Hook> hooks, Map<String, Object> hints) {
31+
executeHooksUnchecked(flagValueType, hooks, hook -> hook.after(hookContext, details, hints));
2332
}
2433

2534
public void afterAllHooks(FlagValueType flagValueType, HookContext hookCtx, List<Hook> hooks,
2635
Map<String, Object> hints) {
2736
executeHooks(flagValueType, hooks, "finally", hook -> hook.finallyAfter(hookCtx, hints));
2837
}
2938

30-
public void afterHooks(FlagValueType flagValueType, HookContext hookContext, FlagEvaluationDetails details,
31-
List<Hook> hooks, Map<String, Object> hints) {
32-
executeHooksUnchecked(flagValueType, hooks, hook -> hook.after(hookContext, details, hints));
39+
public void errorHooks(FlagValueType flagValueType, HookContext hookCtx, Exception e, List<Hook> hooks,
40+
Map<String, Object> hints) {
41+
executeHooks(flagValueType, hooks, "error", hook -> hook.error(hookCtx, e, hints));
3342
}
3443

3544
private <T> void executeHooks(
@@ -44,6 +53,17 @@ private <T> void executeHooks(
4453
}
4554
}
4655

56+
// before, error, and finally hooks shouldn't throw
57+
private <T> void executeChecked(Hook<T> hook, Consumer<Hook<T>> hookCode, String hookMethod) {
58+
try {
59+
hookCode.accept(hook);
60+
} catch (Exception exception) {
61+
log.error("Unhandled exception when running {} hook {} (only 'after' hooks should throw)", hookMethod,
62+
hook.getClass(), exception);
63+
}
64+
}
65+
66+
// after hooks can throw in order to do validation
4767
private <T> void executeHooksUnchecked(
4868
FlagValueType flagValueType, List<Hook> hooks,
4969
Consumer<Hook<T>> hookCode) {
@@ -55,23 +75,6 @@ private <T> void executeHooksUnchecked(
5575
}
5676
}
5777

58-
private <T> void executeChecked(Hook<T> hook, Consumer<Hook<T>> hookCode, String hookMethod) {
59-
try {
60-
hookCode.accept(hook);
61-
} catch (Exception exception) {
62-
log.error("Exception when running {} hooks {}", hookMethod, hook.getClass(), exception);
63-
}
64-
}
65-
66-
public EvaluationContext beforeHooks(FlagValueType flagValueType, HookContext hookCtx, List<Hook> hooks,
67-
Map<String, Object> hints) {
68-
Stream<EvaluationContext> result = callBeforeHooks(flagValueType, hookCtx, hooks, hints);
69-
return hookCtx.getCtx().merge(
70-
result.reduce(hookCtx.getCtx(), (EvaluationContext accumulated, EvaluationContext current) -> {
71-
return accumulated.merge(current);
72-
}));
73-
}
74-
7578
private Stream<EvaluationContext> callBeforeHooks(FlagValueType flagValueType, HookContext hookCtx,
7679
List<Hook> hooks, Map<String, Object> hints) {
7780
// These traverse backwards from normal.

‎src/main/java/dev/openfeature/sdk/OpenFeatureClient.java

-1
Original file line numberDiff line numberDiff line change
@@ -137,7 +137,6 @@ private <T> FlagEvaluationDetails<T> evaluateFlag(FlagValueType type, String key
137137
hookSupport.afterHooks(type, afterHookContext, details, mergedHooks, hints);
138138
}
139139
} catch (Exception e) {
140-
log.error("Unable to correctly evaluate flag with key '{}'", key, e);
141140
if (details == null) {
142141
details = FlagEvaluationDetails.<T>builder().build();
143142
}

‎src/main/java/dev/openfeature/sdk/hooks/logging/LoggingHook.java

+92
Original file line numberDiff line numberDiff line change
@@ -0,0 +1,92 @@
1+
package dev.openfeature.sdk.hooks.logging;
2+
3+
import dev.openfeature.sdk.ErrorCode;
4+
import dev.openfeature.sdk.EvaluationContext;
5+
import dev.openfeature.sdk.FlagEvaluationDetails;
6+
import dev.openfeature.sdk.Hook;
7+
import dev.openfeature.sdk.HookContext;
8+
import dev.openfeature.sdk.exceptions.OpenFeatureError;
9+
import java.util.Map;
10+
import java.util.Optional;
11+
import lombok.extern.slf4j.Slf4j;
12+
import org.slf4j.spi.LoggingEventBuilder;
13+
14+
/**
15+
* A hook for logging flag evaluations.
16+
* Useful for debugging.
17+
* Flag evaluation data is logged at debug and error in before/after stages and error stages, respectively.
18+
*/
19+
@Slf4j
20+
@edu.umd.cs.findbugs.annotations.SuppressFBWarnings(value = "RV_RETURN_VALUE_IGNORED",
21+
justification = "we can ignore return values of chainables (builders) here")
22+
public class LoggingHook implements Hook<Object> {
23+
24+
static final String DOMAIN_KEY = "domain";
25+
static final String PROVIDER_NAME_KEY = "provider_name";
26+
static final String FLAG_KEY_KEY = "flag_key";
27+
static final String DEFAULT_VALUE_KEY = "default_value";
28+
static final String EVALUATION_CONTEXT_KEY = "evaluation_context";
29+
static final String ERROR_CODE_KEY = "error_code";
30+
static final String ERROR_MESSAGE_KEY = "error_message";
31+
static final String REASON_KEY = "reason";
32+
static final String VARIANT_KEY = "variant";
33+
static final String VALUE_KEY = "value";
34+
35+
private boolean includeEvaluationContext;
36+
37+
/**
38+
* Construct a new LoggingHook.
39+
*/
40+
public LoggingHook() {
41+
this(false);
42+
}
43+
44+
/**
45+
* Construct a new LoggingHook.
46+
* @param includeEvaluationContext include a serialized evaluation context in the log message (defaults to false)
47+
*/
48+
public LoggingHook(boolean includeEvaluationContext) {
49+
this.includeEvaluationContext = includeEvaluationContext;
50+
}
51+
52+
@Override
53+
public Optional<EvaluationContext> before(HookContext<Object> hookContext, Map<String, Object> hints) {
54+
LoggingEventBuilder builder = log.atDebug();
55+
addCommonProps(builder, hookContext);
56+
builder.log("Before stage");
57+
58+
return Optional.empty();
59+
}
60+
61+
@Override
62+
public void after(HookContext<Object> hookContext, FlagEvaluationDetails<Object> details,
63+
Map<String, Object> hints) {
64+
LoggingEventBuilder builder = log.atDebug()
65+
.addKeyValue(REASON_KEY, details.getReason())
66+
.addKeyValue(VARIANT_KEY, details.getVariant())
67+
.addKeyValue(VALUE_KEY, details.getValue());
68+
addCommonProps(builder, hookContext);
69+
builder.log("After stage");
70+
}
71+
72+
@Override
73+
public void error(HookContext<Object> hookContext, Exception error, Map<String, Object> hints) {
74+
LoggingEventBuilder builder = log.atError()
75+
.addKeyValue(ERROR_MESSAGE_KEY, error.getMessage());
76+
addCommonProps(builder, hookContext);
77+
ErrorCode errorCode = error instanceof OpenFeatureError ? ((OpenFeatureError) error).getErrorCode() : null;
78+
builder.addKeyValue(ERROR_CODE_KEY, errorCode);
79+
builder.log("Error stage", error);
80+
}
81+
82+
private void addCommonProps(LoggingEventBuilder builder, HookContext<Object> hookContext) {
83+
builder.addKeyValue(DOMAIN_KEY, hookContext.getClientMetadata().getDomain())
84+
.addKeyValue(PROVIDER_NAME_KEY, hookContext.getProviderMetadata().getName())
85+
.addKeyValue(FLAG_KEY_KEY, hookContext.getFlagKey())
86+
.addKeyValue(DEFAULT_VALUE_KEY, hookContext.getDefaultValue());
87+
88+
if (includeEvaluationContext) {
89+
builder.addKeyValue(EVALUATION_CONTEXT_KEY, hookContext.getCtx());
90+
}
91+
}
92+
}

‎src/test/java/dev/openfeature/sdk/FlagEvaluationSpecTest.java

+5-6
Original file line numberDiff line numberDiff line change
@@ -12,6 +12,7 @@
1212
import static org.mockito.ArgumentMatchers.any;
1313
import static org.mockito.ArgumentMatchers.argThat;
1414
import static org.mockito.Mockito.mock;
15+
import static org.mockito.Mockito.never;
1516
import static org.mockito.Mockito.spy;
1617
import static org.mockito.Mockito.times;
1718
import static org.mockito.Mockito.verify;
@@ -25,12 +26,10 @@
2526
import org.junit.jupiter.api.AfterEach;
2627
import org.junit.jupiter.api.BeforeEach;
2728
import org.junit.jupiter.api.Test;
28-
import org.mockito.ArgumentMatchers;
2929
import org.mockito.Mockito;
3030
import org.simplify4u.slf4jmock.LoggerMock;
3131
import org.slf4j.Logger;
3232

33-
import dev.openfeature.sdk.exceptions.FlagNotFoundError;
3433
import dev.openfeature.sdk.exceptions.GeneralError;
3534
import dev.openfeature.sdk.fixtures.HookFixtures;
3635
import dev.openfeature.sdk.providers.memory.InMemoryProvider;
@@ -266,17 +265,17 @@ public void initialize(EvaluationContext evaluationContext) throws Exception {
266265
assertEquals(TestConstants.BROKEN_MESSAGE, details.getErrorMessage());
267266
}
268267

269-
@Specification(number="1.4.11", text="In the case of abnormal execution, the client SHOULD log an informative error message.")
268+
@Specification(number="1.4.11", text="Methods, functions, or operations on the client SHOULD NOT write log messages.")
270269
@Test void log_on_error() throws NotImplementedException {
271270
FeatureProviderTestUtils.setFeatureProvider(new AlwaysBrokenProvider());
272271
Client c = api.getClient();
273272
FlagEvaluationDetails<Boolean> result = c.getBooleanDetails("test", false);
274273

275274
assertEquals(Reason.ERROR.toString(), result.getReason());
276-
Mockito.verify(logger).error(
277-
ArgumentMatchers.contains("Unable to correctly evaluate flag with key"),
275+
Mockito.verify(logger, never()).error(
276+
any(String.class),
278277
any(),
279-
ArgumentMatchers.isA(FlagNotFoundError.class));
278+
any());
280279
}
281280

282281
@Specification(number="1.2.2", text="The client interface MUST define a metadata member or accessor, containing an immutable domain field or accessor of type string, which corresponds to the domain value supplied during client creation. In previous drafts, this property was called name. For backwards compatibility, implementations should consider name an alias to domain.")

0 commit comments

Comments
 (0)