diff --git a/src/main/java/dev/openfeature/sdk/OpenFeatureClient.java b/src/main/java/dev/openfeature/sdk/OpenFeatureClient.java index 05f7fea37..d8004e5de 100644 --- a/src/main/java/dev/openfeature/sdk/OpenFeatureClient.java +++ b/src/main/java/dev/openfeature/sdk/OpenFeatureClient.java @@ -137,7 +137,6 @@ private FlagEvaluationDetails evaluateFlag(FlagValueType type, String key 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.builder().build(); } diff --git a/src/main/java/dev/openfeature/sdk/hooks/logging/LoggingHook.java b/src/main/java/dev/openfeature/sdk/hooks/logging/LoggingHook.java new file mode 100644 index 000000000..3350d551b --- /dev/null +++ b/src/main/java/dev/openfeature/sdk/hooks/logging/LoggingHook.java @@ -0,0 +1,91 @@ +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. + */ +@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 { + + 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 before(HookContext hookContext, Map hints) { + LoggingEventBuilder builder = log.atInfo(); + addCommonProps(builder, hookContext); + builder.log("Before stage"); + + return Optional.empty(); + } + + @Override + public void after(HookContext hookContext, FlagEvaluationDetails details, + Map hints) { + LoggingEventBuilder builder = log.atInfo() + .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 hookContext, Exception error, Map 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 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()); + } + } +} diff --git a/src/test/java/dev/openfeature/sdk/FlagEvaluationSpecTest.java b/src/test/java/dev/openfeature/sdk/FlagEvaluationSpecTest.java index 6d2bca3a5..b4978cb4b 100644 --- a/src/test/java/dev/openfeature/sdk/FlagEvaluationSpecTest.java +++ b/src/test/java/dev/openfeature/sdk/FlagEvaluationSpecTest.java @@ -12,6 +12,7 @@ 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.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 @@ public void initialize(EvaluationContext evaluationContext) throws Exception { 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 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.") diff --git a/src/test/java/dev/openfeature/sdk/hooks/logging/LoggingHookTest.java b/src/test/java/dev/openfeature/sdk/hooks/logging/LoggingHookTest.java new file mode 100644 index 000000000..a10a58c71 --- /dev/null +++ b/src/test/java/dev/openfeature/sdk/hooks/logging/LoggingHookTest.java @@ -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; + +public 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 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.atInfo()).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).atInfo(); + 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).atInfo(); + 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 details = FlagEvaluationDetails.builder().reason(REASON).variant(VARIANT).value(VALUE).build(); + hook.after(hookContext, details, null); + + verify(logger).atInfo(); + 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 details = FlagEvaluationDetails.builder().reason(REASON).variant(VARIANT).value(VALUE).build(); + hook.after(hookContext, details, null); + + verify(logger).atInfo(); + 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); + } +} \ No newline at end of file