feat: add logging hook, rm logging from evaluation (#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>
This commit is contained in:
Todd Baert
GitHub
parent
78e3371c05
commit
037826fe1b
|
|
@ -218,6 +218,14 @@ Once you've added a hook as a dependency, it can be registered at the global, cl
|
|||
### Logging
|
||||
|
||||
The Java SDK uses SLF4J. See the [SLF4J manual](https://slf4j.org/manual.html) for complete documentation.
|
||||
Note that in accordance with the OpenFeature specification, the SDK doesn't generally log messages during flag evaluation.
|
||||
|
||||
#### Logging Hook
|
||||
|
||||
The Java SDK includes a `LoggingHook`, which logs detailed information at key points during flag evaluation, using SLF4J's structured logging API.
|
||||
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".
|
||||
|
||||
See [hooks](#hooks) for more information on configuring hooks.
|
||||
|
||||
### Domains
|
||||
|
||||
|
|
|
|||
|
|
@ -17,9 +17,18 @@ import lombok.extern.slf4j.Slf4j;
|
|||
@SuppressWarnings({ "unchecked", "rawtypes" })
|
||||
class HookSupport {
|
||||
|
||||
public void errorHooks(FlagValueType flagValueType, HookContext hookCtx, Exception e, List<Hook> hooks,
|
||||
public EvaluationContext beforeHooks(FlagValueType flagValueType, HookContext hookCtx, List<Hook> hooks,
|
||||
Map<String, Object> hints) {
|
||||
executeHooks(flagValueType, hooks, "error", hook -> hook.error(hookCtx, e, hints));
|
||||
Stream<EvaluationContext> result = callBeforeHooks(flagValueType, hookCtx, hooks, hints);
|
||||
return hookCtx.getCtx().merge(
|
||||
result.reduce(hookCtx.getCtx(), (EvaluationContext accumulated, EvaluationContext current) -> {
|
||||
return accumulated.merge(current);
|
||||
}));
|
||||
}
|
||||
|
||||
public void afterHooks(FlagValueType flagValueType, HookContext hookContext, FlagEvaluationDetails details,
|
||||
List<Hook> hooks, Map<String, Object> hints) {
|
||||
executeHooksUnchecked(flagValueType, hooks, hook -> hook.after(hookContext, details, hints));
|
||||
}
|
||||
|
||||
public void afterAllHooks(FlagValueType flagValueType, HookContext hookCtx, List<Hook> hooks,
|
||||
|
|
@ -27,9 +36,9 @@ class HookSupport {
|
|||
executeHooks(flagValueType, hooks, "finally", hook -> hook.finallyAfter(hookCtx, hints));
|
||||
}
|
||||
|
||||
public void afterHooks(FlagValueType flagValueType, HookContext hookContext, FlagEvaluationDetails details,
|
||||
List<Hook> hooks, Map<String, Object> hints) {
|
||||
executeHooksUnchecked(flagValueType, hooks, hook -> hook.after(hookContext, details, hints));
|
||||
public void errorHooks(FlagValueType flagValueType, HookContext hookCtx, Exception e, List<Hook> hooks,
|
||||
Map<String, Object> hints) {
|
||||
executeHooks(flagValueType, hooks, "error", hook -> hook.error(hookCtx, e, hints));
|
||||
}
|
||||
|
||||
private <T> void executeHooks(
|
||||
|
|
@ -44,6 +53,17 @@ class HookSupport {
|
|||
}
|
||||
}
|
||||
|
||||
// before, error, and finally hooks shouldn't throw
|
||||
private <T> void executeChecked(Hook<T> hook, Consumer<Hook<T>> hookCode, String hookMethod) {
|
||||
try {
|
||||
hookCode.accept(hook);
|
||||
} catch (Exception exception) {
|
||||
log.error("Unhandled exception when running {} hook {} (only 'after' hooks should throw)", hookMethod,
|
||||
hook.getClass(), exception);
|
||||
}
|
||||
}
|
||||
|
||||
// after hooks can throw in order to do validation
|
||||
private <T> void executeHooksUnchecked(
|
||||
FlagValueType flagValueType, List<Hook> hooks,
|
||||
Consumer<Hook<T>> hookCode) {
|
||||
|
|
@ -55,23 +75,6 @@ class HookSupport {
|
|||
}
|
||||
}
|
||||
|
||||
private <T> void executeChecked(Hook<T> hook, Consumer<Hook<T>> hookCode, String hookMethod) {
|
||||
try {
|
||||
hookCode.accept(hook);
|
||||
} catch (Exception exception) {
|
||||
log.error("Exception when running {} hooks {}", hookMethod, hook.getClass(), exception);
|
||||
}
|
||||
}
|
||||
|
||||
public EvaluationContext beforeHooks(FlagValueType flagValueType, HookContext hookCtx, List<Hook> hooks,
|
||||
Map<String, Object> hints) {
|
||||
Stream<EvaluationContext> result = callBeforeHooks(flagValueType, hookCtx, hooks, hints);
|
||||
return hookCtx.getCtx().merge(
|
||||
result.reduce(hookCtx.getCtx(), (EvaluationContext accumulated, EvaluationContext current) -> {
|
||||
return accumulated.merge(current);
|
||||
}));
|
||||
}
|
||||
|
||||
private Stream<EvaluationContext> callBeforeHooks(FlagValueType flagValueType, HookContext hookCtx,
|
||||
List<Hook> hooks, Map<String, Object> hints) {
|
||||
// These traverse backwards from normal.
|
||||
|
|
|
|||
|
|
@ -137,7 +137,6 @@ public class OpenFeatureClient implements Client {
|
|||
hookSupport.afterHooks(type, afterHookContext, details, mergedHooks, hints);
|
||||
}
|
||||
} catch (Exception e) {
|
||||
log.error("Unable to correctly evaluate flag with key '{}'", key, e);
|
||||
if (details == null) {
|
||||
details = FlagEvaluationDetails.<T>builder().build();
|
||||
}
|
||||
|
|
|
|||
|
|
@ -0,0 +1,92 @@
|
|||
package dev.openfeature.sdk.hooks.logging;
|
||||
|
||||
import dev.openfeature.sdk.ErrorCode;
|
||||
import dev.openfeature.sdk.EvaluationContext;
|
||||
import dev.openfeature.sdk.FlagEvaluationDetails;
|
||||
import dev.openfeature.sdk.Hook;
|
||||
import dev.openfeature.sdk.HookContext;
|
||||
import dev.openfeature.sdk.exceptions.OpenFeatureError;
|
||||
import java.util.Map;
|
||||
import java.util.Optional;
|
||||
import lombok.extern.slf4j.Slf4j;
|
||||
import org.slf4j.spi.LoggingEventBuilder;
|
||||
|
||||
/**
|
||||
* A hook for logging flag evaluations.
|
||||
* Useful for debugging.
|
||||
* Flag evaluation data is logged at debug and error in before/after stages and error stages, respectively.
|
||||
*/
|
||||
@Slf4j
|
||||
@edu.umd.cs.findbugs.annotations.SuppressFBWarnings(value = "RV_RETURN_VALUE_IGNORED",
|
||||
justification = "we can ignore return values of chainables (builders) here")
|
||||
public class LoggingHook implements Hook<Object> {
|
||||
|
||||
static final String DOMAIN_KEY = "domain";
|
||||
static final String PROVIDER_NAME_KEY = "provider_name";
|
||||
static final String FLAG_KEY_KEY = "flag_key";
|
||||
static final String DEFAULT_VALUE_KEY = "default_value";
|
||||
static final String EVALUATION_CONTEXT_KEY = "evaluation_context";
|
||||
static final String ERROR_CODE_KEY = "error_code";
|
||||
static final String ERROR_MESSAGE_KEY = "error_message";
|
||||
static final String REASON_KEY = "reason";
|
||||
static final String VARIANT_KEY = "variant";
|
||||
static final String VALUE_KEY = "value";
|
||||
|
||||
private boolean includeEvaluationContext;
|
||||
|
||||
/**
|
||||
* Construct a new LoggingHook.
|
||||
*/
|
||||
public LoggingHook() {
|
||||
this(false);
|
||||
}
|
||||
|
||||
/**
|
||||
* Construct a new LoggingHook.
|
||||
* @param includeEvaluationContext include a serialized evaluation context in the log message (defaults to false)
|
||||
*/
|
||||
public LoggingHook(boolean includeEvaluationContext) {
|
||||
this.includeEvaluationContext = includeEvaluationContext;
|
||||
}
|
||||
|
||||
@Override
|
||||
public Optional<EvaluationContext> before(HookContext<Object> hookContext, Map<String, Object> hints) {
|
||||
LoggingEventBuilder builder = log.atDebug();
|
||||
addCommonProps(builder, hookContext);
|
||||
builder.log("Before stage");
|
||||
|
||||
return Optional.empty();
|
||||
}
|
||||
|
||||
@Override
|
||||
public void after(HookContext<Object> hookContext, FlagEvaluationDetails<Object> details,
|
||||
Map<String, Object> hints) {
|
||||
LoggingEventBuilder builder = log.atDebug()
|
||||
.addKeyValue(REASON_KEY, details.getReason())
|
||||
.addKeyValue(VARIANT_KEY, details.getVariant())
|
||||
.addKeyValue(VALUE_KEY, details.getValue());
|
||||
addCommonProps(builder, hookContext);
|
||||
builder.log("After stage");
|
||||
}
|
||||
|
||||
@Override
|
||||
public void error(HookContext<Object> hookContext, Exception error, Map<String, Object> hints) {
|
||||
LoggingEventBuilder builder = log.atError()
|
||||
.addKeyValue(ERROR_MESSAGE_KEY, error.getMessage());
|
||||
addCommonProps(builder, hookContext);
|
||||
ErrorCode errorCode = error instanceof OpenFeatureError ? ((OpenFeatureError) error).getErrorCode() : null;
|
||||
builder.addKeyValue(ERROR_CODE_KEY, errorCode);
|
||||
builder.log("Error stage", error);
|
||||
}
|
||||
|
||||
private void addCommonProps(LoggingEventBuilder builder, HookContext<Object> hookContext) {
|
||||
builder.addKeyValue(DOMAIN_KEY, hookContext.getClientMetadata().getDomain())
|
||||
.addKeyValue(PROVIDER_NAME_KEY, hookContext.getProviderMetadata().getName())
|
||||
.addKeyValue(FLAG_KEY_KEY, hookContext.getFlagKey())
|
||||
.addKeyValue(DEFAULT_VALUE_KEY, hookContext.getDefaultValue());
|
||||
|
||||
if (includeEvaluationContext) {
|
||||
builder.addKeyValue(EVALUATION_CONTEXT_KEY, hookContext.getCtx());
|
||||
}
|
||||
}
|
||||
}
|
||||
|
|
@ -12,6 +12,7 @@ import static org.junit.jupiter.api.Assertions.assertTrue;
|
|||
import static org.mockito.ArgumentMatchers.any;
|
||||
import static org.mockito.ArgumentMatchers.argThat;
|
||||
import static org.mockito.Mockito.mock;
|
||||
import static org.mockito.Mockito.never;
|
||||
import static org.mockito.Mockito.spy;
|
||||
import static org.mockito.Mockito.times;
|
||||
import static org.mockito.Mockito.verify;
|
||||
|
|
@ -25,12 +26,10 @@ import org.awaitility.Awaitility;
|
|||
import org.junit.jupiter.api.AfterEach;
|
||||
import org.junit.jupiter.api.BeforeEach;
|
||||
import org.junit.jupiter.api.Test;
|
||||
import org.mockito.ArgumentMatchers;
|
||||
import org.mockito.Mockito;
|
||||
import org.simplify4u.slf4jmock.LoggerMock;
|
||||
import org.slf4j.Logger;
|
||||
|
||||
import dev.openfeature.sdk.exceptions.FlagNotFoundError;
|
||||
import dev.openfeature.sdk.exceptions.GeneralError;
|
||||
import dev.openfeature.sdk.fixtures.HookFixtures;
|
||||
import dev.openfeature.sdk.providers.memory.InMemoryProvider;
|
||||
|
|
@ -266,17 +265,17 @@ class FlagEvaluationSpecTest implements HookFixtures {
|
|||
assertEquals(TestConstants.BROKEN_MESSAGE, details.getErrorMessage());
|
||||
}
|
||||
|
||||
@Specification(number="1.4.11", text="In the case of abnormal execution, the client SHOULD log an informative error message.")
|
||||
@Specification(number="1.4.11", text="Methods, functions, or operations on the client SHOULD NOT write log messages.")
|
||||
@Test void log_on_error() throws NotImplementedException {
|
||||
FeatureProviderTestUtils.setFeatureProvider(new AlwaysBrokenProvider());
|
||||
Client c = api.getClient();
|
||||
FlagEvaluationDetails<Boolean> result = c.getBooleanDetails("test", false);
|
||||
|
||||
assertEquals(Reason.ERROR.toString(), result.getReason());
|
||||
Mockito.verify(logger).error(
|
||||
ArgumentMatchers.contains("Unable to correctly evaluate flag with key"),
|
||||
Mockito.verify(logger, never()).error(
|
||||
any(String.class),
|
||||
any(),
|
||||
ArgumentMatchers.isA(FlagNotFoundError.class));
|
||||
any());
|
||||
}
|
||||
|
||||
@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,0 +1,167 @@
|
|||
package dev.openfeature.sdk.hooks.logging;
|
||||
|
||||
import static org.mockito.ArgumentMatchers.any;
|
||||
import static org.mockito.ArgumentMatchers.anyString;
|
||||
import static org.mockito.ArgumentMatchers.argThat;
|
||||
import static org.mockito.ArgumentMatchers.contains;
|
||||
import static org.mockito.Mockito.mock;
|
||||
import static org.mockito.Mockito.never;
|
||||
import static org.mockito.Mockito.verify;
|
||||
import static org.mockito.Mockito.when;
|
||||
|
||||
import dev.openfeature.sdk.ClientMetadata;
|
||||
import dev.openfeature.sdk.ErrorCode;
|
||||
import dev.openfeature.sdk.EvaluationContext;
|
||||
import dev.openfeature.sdk.FlagEvaluationDetails;
|
||||
import dev.openfeature.sdk.FlagValueType;
|
||||
import dev.openfeature.sdk.HookContext;
|
||||
import dev.openfeature.sdk.ImmutableContext;
|
||||
import dev.openfeature.sdk.Metadata;
|
||||
import dev.openfeature.sdk.exceptions.GeneralError;
|
||||
import lombok.SneakyThrows;
|
||||
import org.junit.jupiter.api.BeforeEach;
|
||||
import org.junit.jupiter.api.Test;
|
||||
import org.simplify4u.slf4jmock.LoggerMock;
|
||||
import org.slf4j.Logger;
|
||||
import org.slf4j.spi.LoggingEventBuilder;
|
||||
|
||||
class LoggingHookTest {
|
||||
|
||||
private static final String FLAG_KEY = "some-key";
|
||||
private static final String DEFAULT_VALUE = "default";
|
||||
private static final String DOMAIN = "some-domain";
|
||||
private static final String PROVIDER_NAME = "some-provider";
|
||||
private static final String REASON = "some-reason";
|
||||
private static final String VALUE = "some-value";
|
||||
private static final String VARIANT = "some-variant";
|
||||
private static final String ERROR_MESSAGE = "some fake error!";
|
||||
private static final ErrorCode ERROR_CODE = ErrorCode.GENERAL;
|
||||
|
||||
private HookContext<Object> hookContext;
|
||||
private LoggingEventBuilder mockBuilder;
|
||||
private Logger logger;
|
||||
|
||||
@BeforeEach
|
||||
void each() {
|
||||
|
||||
// create a fake hook context
|
||||
hookContext = HookContext.builder().flagKey(FLAG_KEY).defaultValue(DEFAULT_VALUE)
|
||||
.clientMetadata(new ClientMetadata() {
|
||||
@Override
|
||||
public String getDomain() {
|
||||
return DOMAIN;
|
||||
}
|
||||
}).providerMetadata(new Metadata() {
|
||||
@Override
|
||||
public String getName() {
|
||||
return PROVIDER_NAME;
|
||||
}
|
||||
}).type(FlagValueType.BOOLEAN).ctx(new ImmutableContext()).build();
|
||||
|
||||
// mock logging
|
||||
logger = mock(Logger.class);
|
||||
mockBuilder = mock(LoggingEventBuilder.class);
|
||||
when(mockBuilder.addKeyValue(anyString(), anyString())).thenReturn(mockBuilder);
|
||||
when(logger.atDebug()).thenReturn(mockBuilder);
|
||||
when(logger.atError()).thenReturn(mockBuilder);
|
||||
LoggerMock.setMock(LoggingHook.class, logger);
|
||||
}
|
||||
|
||||
@SneakyThrows
|
||||
@Test
|
||||
void beforeLogsAllPropsExceptEvaluationContext() {
|
||||
LoggingHook hook = new LoggingHook();
|
||||
hook.before(hookContext, null);
|
||||
|
||||
verify(logger).atDebug();
|
||||
verifyCommonProps(mockBuilder);
|
||||
verify(mockBuilder, never()).addKeyValue(anyString(), any(EvaluationContext.class));
|
||||
verify(mockBuilder).log(argThat((String s) -> s.contains("Before")));
|
||||
}
|
||||
|
||||
@SneakyThrows
|
||||
@Test
|
||||
void beforeLogsAllPropsAndEvaluationContext() {
|
||||
LoggingHook hook = new LoggingHook(true);
|
||||
hook.before(hookContext, null);
|
||||
|
||||
verify(logger).atDebug();
|
||||
verifyCommonProps(mockBuilder);
|
||||
verify(mockBuilder).addKeyValue(contains(LoggingHook.EVALUATION_CONTEXT_KEY), any(EvaluationContext.class));
|
||||
verify(mockBuilder).log(argThat((String s) -> s.contains("Before")));
|
||||
}
|
||||
|
||||
@SneakyThrows
|
||||
@Test
|
||||
void afterLogsAllPropsExceptEvaluationContext() {
|
||||
LoggingHook hook = new LoggingHook();
|
||||
FlagEvaluationDetails<Object> details = FlagEvaluationDetails.builder().reason(REASON).variant(VARIANT).value(VALUE).build();
|
||||
hook.after(hookContext, details, null);
|
||||
|
||||
verify(logger).atDebug();
|
||||
verifyAfterProps(mockBuilder);
|
||||
verifyCommonProps(mockBuilder);
|
||||
verify(mockBuilder, never()).addKeyValue(anyString(), any(EvaluationContext.class));
|
||||
verify(mockBuilder).log(argThat((String s) -> s.contains("After")));
|
||||
}
|
||||
|
||||
@SneakyThrows
|
||||
@Test
|
||||
void afterLogsAllPropsAndEvaluationContext() {
|
||||
LoggingHook hook = new LoggingHook(true);
|
||||
FlagEvaluationDetails<Object> details = FlagEvaluationDetails.builder().reason(REASON).variant(VARIANT).value(VALUE).build();
|
||||
hook.after(hookContext, details, null);
|
||||
|
||||
verify(logger).atDebug();
|
||||
verifyAfterProps(mockBuilder);
|
||||
verifyCommonProps(mockBuilder);
|
||||
verify(mockBuilder).addKeyValue(contains(LoggingHook.EVALUATION_CONTEXT_KEY), any(EvaluationContext.class));
|
||||
verify(mockBuilder).log(argThat((String s) -> s.contains("After")));
|
||||
}
|
||||
|
||||
@SneakyThrows
|
||||
@Test
|
||||
void errorLogsAllPropsExceptEvaluationContext() {
|
||||
LoggingHook hook = new LoggingHook();
|
||||
GeneralError error = new GeneralError(ERROR_MESSAGE);
|
||||
hook.error(hookContext, error, null);
|
||||
|
||||
verify(logger).atError();
|
||||
verifyCommonProps(mockBuilder);
|
||||
verifyErrorProps(mockBuilder);
|
||||
verify(mockBuilder, never()).addKeyValue(anyString(), any(EvaluationContext.class));
|
||||
verify(mockBuilder).log(argThat((String s) -> s.contains("Error")), any(Exception.class));
|
||||
}
|
||||
|
||||
@SneakyThrows
|
||||
@Test
|
||||
void errorLogsAllPropsAndEvaluationContext() {
|
||||
LoggingHook hook = new LoggingHook(true);
|
||||
GeneralError error = new GeneralError(ERROR_MESSAGE);
|
||||
hook.error(hookContext, error, null);
|
||||
|
||||
verify(logger).atError();
|
||||
verifyCommonProps(mockBuilder);
|
||||
verifyErrorProps(mockBuilder);
|
||||
verify(mockBuilder).addKeyValue(contains(LoggingHook.EVALUATION_CONTEXT_KEY), any(EvaluationContext.class));
|
||||
verify(mockBuilder).log(argThat((String s) -> s.contains("Error")), any(Exception.class));
|
||||
}
|
||||
|
||||
private void verifyCommonProps(LoggingEventBuilder mockBuilder) {
|
||||
verify(mockBuilder).addKeyValue(LoggingHook.DOMAIN_KEY, DOMAIN);
|
||||
verify(mockBuilder).addKeyValue(LoggingHook.FLAG_KEY_KEY, FLAG_KEY);
|
||||
verify(mockBuilder).addKeyValue(LoggingHook.PROVIDER_NAME_KEY, PROVIDER_NAME);
|
||||
verify(mockBuilder).addKeyValue(LoggingHook.DEFAULT_VALUE_KEY, DEFAULT_VALUE);
|
||||
}
|
||||
|
||||
private void verifyAfterProps(LoggingEventBuilder mockBuilder) {
|
||||
verify(mockBuilder).addKeyValue(LoggingHook.REASON_KEY, REASON);
|
||||
verify(mockBuilder).addKeyValue(LoggingHook.VARIANT_KEY, VARIANT);
|
||||
verify(mockBuilder).addKeyValue(LoggingHook.VALUE_KEY, VALUE);
|
||||
}
|
||||
|
||||
private void verifyErrorProps(LoggingEventBuilder mockBuilder) {
|
||||
verify(mockBuilder).addKeyValue(LoggingHook.ERROR_CODE_KEY, ERROR_CODE);
|
||||
verify(mockBuilder).addKeyValue(LoggingHook.ERROR_MESSAGE_KEY, ERROR_MESSAGE);
|
||||
}
|
||||
}
|
||||
Loading…
Reference in New Issue