From 10bd04dec84cc4ae34634fd04d3e077e9b9c6f0e Mon Sep 17 00:00:00 2001 From: "ethan.romero" Date: Tue, 27 Oct 2026 19:27:21 +0000 Subject: [PATCH 1/4] Add debug diagnostics to dd-openfeature Help onboarding by logging what the dd-openfeature SDK does, at DEBUG. Provider: log the lifecycle (initializing, ready, timed out, recovered, configuration changed or unavailable, shutting down) and why an exposure is suppressed (at TRACE). Log only the type of an initialization failure, since its message can echo the endpoint URL. Evaluations: log the raw outcome of every evaluation, including the evaluation context and any personal data in it, only when DD_TRACE_DEBUG is on and the application logger allows DEBUG. Each value is rendered within 1024 characters and a depth limit, with cycle detection, so that a cyclic or very deep value cannot overflow the stack of the evaluating thread. Say so at INFO, through the logger of the hook, when the hook is registered. When only DD_TRACE_DEBUG is on, warn which logger category to enable. Configuration delivery: log the runtime start-up (source, transport, enabled pipelines) and every configuration applied or removed. For agentless delivery, log the endpoint without its query, applied and unchanged responses, retries with their delay, and that a malformed or empty payload retains the current configuration. For Remote Configuration, log the subscription and malformed documents. Event pipelines: log the exposure flush lifecycle (with the failure reason and the number of dropped exposures), the exposures dropped by a full queue (counted on the application thread and reported once per flush, so the producer never logs), the shutdown requests, and delivered flag evaluation flushes. The module has no SLF4J 2 compatible logging backend in tests, so add a test-only SLF4J provider that captures events. Environment: Datadog workspace Co-Authored-By: Claude Sonnet 5.5 --- .../datadog/openfeature/DebugLoggingHook.java | 256 ++++++++ .../openfeature/ExposureLoggingHook.java | 22 +- .../com/datadog/openfeature/Provider.java | 31 +- .../internal/FeatureFlagsRuntime.java | 18 + .../openfeature/internal/config/Settings.java | 11 + .../delivery/CdnConfigurationSource.java | 36 +- .../delivery/RemoteConfigurationService.java | 6 +- .../internal/exposure/ExposurePipeline.java | 32 +- .../FlagEvaluationPipeline.java | 5 + .../datadog/openfeature/DebugLoggingTest.java | 566 ++++++++++++++++++ .../internal/FeatureFlagsRuntimeTest.java | 51 ++ .../internal/config/SettingsTest.java | 19 + .../delivery/DeliveryDiagnosticsTest.java | 201 +++++++ .../ExposurePipelineDiagnosticsTest.java | 139 +++++ .../FlagEvaluationPipelineTest.java | 29 + .../testlog/CapturingServiceProvider.java | 208 +++++++ .../org.slf4j.spi.SLF4JServiceProvider | 1 + 17 files changed, 1614 insertions(+), 17 deletions(-) create mode 100644 dd-openfeature/src/main/java/com/datadog/openfeature/DebugLoggingHook.java create mode 100644 dd-openfeature/src/test/java/com/datadog/openfeature/DebugLoggingTest.java create mode 100644 dd-openfeature/src/test/java/com/datadog/openfeature/internal/delivery/DeliveryDiagnosticsTest.java create mode 100644 dd-openfeature/src/test/java/com/datadog/openfeature/internal/exposure/ExposurePipelineDiagnosticsTest.java create mode 100644 dd-openfeature/src/test/java/com/datadog/openfeature/testlog/CapturingServiceProvider.java create mode 100644 dd-openfeature/src/test/resources/META-INF/services/org.slf4j.spi.SLF4JServiceProvider diff --git a/dd-openfeature/src/main/java/com/datadog/openfeature/DebugLoggingHook.java b/dd-openfeature/src/main/java/com/datadog/openfeature/DebugLoggingHook.java new file mode 100644 index 00000000000..8d11bb259b0 --- /dev/null +++ b/dd-openfeature/src/main/java/com/datadog/openfeature/DebugLoggingHook.java @@ -0,0 +1,256 @@ +package com.datadog.openfeature; + +import dev.openfeature.sdk.EvaluationContext; +import dev.openfeature.sdk.FlagEvaluationDetails; +import dev.openfeature.sdk.Hook; +import dev.openfeature.sdk.HookContext; +import dev.openfeature.sdk.Structure; +import dev.openfeature.sdk.Value; +import java.util.Collections; +import java.util.IdentityHashMap; +import java.util.Map; +import java.util.Set; +import org.slf4j.Logger; +import org.slf4j.LoggerFactory; + +/** + * Logs the raw outcome of every evaluation, to help onboarding. + * + *

The evaluation context and values are logged as they are, including any personal data they + * carry (targeting keys, emails, user attributes), and they are not subject to the observe full + * evaluation data consent. The provider therefore registers this hook only when both {@code + * DD_TRACE_DEBUG} and the application logger allow DEBUG; do not enable them where application logs + * leave a trusted boundary. The error message is the one the application observes: the consent + * filter applies to the messages the provider produces. Each logged value is capped at {@value + * #MAX_VALUE_LENGTH} characters, not counting the truncation marker, and nested values are rendered + * within that budget and a depth limit, whatever their shape. + * + *

It is not telemetry, so the evaluation telemetry opt-out does not apply. It runs at the + * finally stage to report what the application observes, and a logging failure never reaches the + * evaluation. + */ +final class DebugLoggingHook implements Hook { + private static final Logger log = LoggerFactory.getLogger(DebugLoggingHook.class); + + /** The longest rendering of a context or value, so that a large object cannot flood the log. */ + static final int MAX_VALUE_LENGTH = 1024; + + /** + * Tells whether the hook can log. + * + * @return whether the application logger allows DEBUG for the hook. + */ + static boolean isLoggerEnabled() { + try { + return log.isDebugEnabled(); + } catch (final RuntimeException | LinkageError e) { + // A failing logging backend must not prevent the provider from working. + return false; + } + } + + /** + * Says that raw evaluations are logged. It goes through the logger of the hook, so that enabling + * DEBUG for the hook alone, as the provider warning suggests, also shows it. + */ + static void announce() { + try { + log.info( + "DD_TRACE_DEBUG is enabled and DEBUG is enabled for {}: raw evaluation contexts and" + + " values, including any personal data in them, are written to the application" + + " logs.", + DebugLoggingHook.class.getName()); + } catch (final RuntimeException | LinkageError e) { + // A failing logging backend must not prevent the provider from working. + } + } + + @Override + public void finallyAfter( + final HookContext ctx, + final FlagEvaluationDetails details, + final Map hints) { + // The hook is registered when the logger allows DEBUG, which an application can change later. + if (details == null || !isLoggerEnabled()) { + return; + } + try { + final EvaluationContext context = ctx.getCtx(); + log.debug( + "Feature Flagging evaluation: flag={}, context={}, defaultValue={}, value={}, variant={}, reason={}, errorCode={}, errorMessage={}, metadata={}", + raw(details.getFlagKey()), + raw(context), + raw(ctx.getDefaultValue()), + raw(details.getValue()), + raw(details.getVariant()), + raw(details.getReason()), + details.getErrorCode(), + raw(details.getErrorMessage()), + details.getFlagMetadata() == null + ? null + : raw(details.getFlagMetadata().asUnmodifiableMap())); + } catch (final RuntimeException | LinkageError e) { + // Application supplied values can fail to format, and a diagnostic must not break the + // evaluation. + try { + log.debug("Feature Flagging evaluation diagnostic unavailable: {}", raw(e.toString())); + } catch (final RuntimeException | LinkageError ignored) { + // Nothing more can be done. + } + } + } + + /** + * Renders a value for the log, within {@link #MAX_VALUE_LENGTH} characters and without trusting + * its shape: structures can be user supplied, deeply nested or even refer to themselves. + */ + private static String raw(final Object value) { + if (value instanceof Value + || value instanceof Structure + || value instanceof Map + || value instanceof Iterable) { + return new Renderer().render(value); + } + return capped(String.valueOf(value)); + } + + /** Caps a text, telling how long it was. */ + private static String capped(final String text) { + if (text.length() <= MAX_VALUE_LENGTH) { + return text; + } + // Do not cut a surrogate pair in half. + final int end = + Character.isHighSurrogate(text.charAt(MAX_VALUE_LENGTH - 1)) + ? MAX_VALUE_LENGTH - 1 + : MAX_VALUE_LENGTH; + return text.substring(0, end) + "...(truncated, " + text.length() + " characters)"; + } + + /** + * Renders values within a budget, applied while walking them: the work does not grow with the + * size of the value: it stops walking a container once the budget is spent. Nesting is limited + * and a container already being rendered is not entered again, so a cycle or a very deep value + * cannot overflow the stack of the evaluating thread. + */ + private static final class Renderer { + private static final int MAX_DEPTH = 8; + + private final StringBuilder out = new StringBuilder(); + private final Set path = Collections.newSetFromMap(new IdentityHashMap<>()); + private boolean truncated; + + String render(final Object value) { + write(value, 0); + if (this.truncated) { + final int last = this.out.length() - 1; + if (last >= 0 && Character.isHighSurrogate(this.out.charAt(last))) { + this.out.setLength(last); + } + this.out.append("...(truncated)"); + } + return this.out.toString(); + } + + private void write(final Object value, final int depth) { + if (this.truncated) { + return; + } + if (value == null) { + text("null"); + } else if (value instanceof Value + || value instanceof Structure + || value instanceof Map + || value instanceof Iterable) { + writeContainer(value, depth); + } else { + text(String.valueOf(value)); + } + } + + private void writeContainer(final Object container, final int depth) { + if (depth > MAX_DEPTH) { + text("..."); + return; + } + if (!this.path.add(container)) { + text("(cycle)"); + return; + } + try { + if (container instanceof Value) { + writeValue((Value) container, depth); + } else if (container instanceof Structure) { + final Structure structure = (Structure) container; + text("{"); + boolean first = true; + for (final String key : structure.keySet()) { + if (this.truncated) { + break; + } + if (!first) { + text(", "); + } + first = false; + text(String.valueOf(key)); + text("="); + write(structure.getValue(key), depth + 1); + } + text("}"); + } else if (container instanceof Map) { + text("{"); + boolean first = true; + for (final Map.Entry entry : ((Map) container).entrySet()) { + if (this.truncated) { + break; + } + if (!first) { + text(", "); + } + first = false; + write(entry.getKey(), depth + 1); + text("="); + write(entry.getValue(), depth + 1); + } + text("}"); + } else { + text("["); + boolean first = true; + for (final Object element : (Iterable) container) { + if (this.truncated) { + break; + } + if (!first) { + text(", "); + } + first = false; + write(element, depth + 1); + } + text("]"); + } + } finally { + this.path.remove(container); + } + } + + /** + * Renders what the value wraps. It does not ask {@code isList()} or {@code asList()}: they + * check every element of the list, whatever the budget, and a list holding anything else than + * values is not one for them. + */ + private void writeValue(final Value value, final int depth) { + write(value.asObject(), depth); + } + + /** Appends the text, or what fits of it, and gives up on the rest of the value. */ + private void text(final String text) { + final int remaining = MAX_VALUE_LENGTH - this.out.length(); + if (text.length() > remaining) { + this.out.append(text, 0, Math.max(remaining, 0)); + this.truncated = true; + } else { + this.out.append(text); + } + } + } +} diff --git a/dd-openfeature/src/main/java/com/datadog/openfeature/ExposureLoggingHook.java b/dd-openfeature/src/main/java/com/datadog/openfeature/ExposureLoggingHook.java index f0065abc6df..db6eba8a70d 100644 --- a/dd-openfeature/src/main/java/com/datadog/openfeature/ExposureLoggingHook.java +++ b/dd-openfeature/src/main/java/com/datadog/openfeature/ExposureLoggingHook.java @@ -47,16 +47,22 @@ public void finallyAfter( final Map hints) { try { if (details == null || details.getErrorCode() != null) { + log.trace("Feature Flagging exposure suppressed: evaluation failed or details unavailable"); return; } final ImmutableMetadata metadata = details.getFlagMetadata(); if (metadata == null) { + log.trace("Feature Flagging exposure suppressed: metadata unavailable"); return; } // The ImmutableMetadata getters build a debug message for every absent key. final Map values = metadata.asUnmodifiableMap(); - if (!Boolean.TRUE.equals(values.get(DO_LOG)) - || !Boolean.FALSE.equals(values.get(EXPOSURE_CACHE_HIT))) { + if (!Boolean.TRUE.equals(values.get(DO_LOG))) { + log.trace("Feature Flagging exposure suppressed: allocation does not log exposures"); + return; + } + if (!Boolean.FALSE.equals(values.get(EXPOSURE_CACHE_HIT))) { + log.trace("Feature Flagging exposure suppressed: exposure already recorded"); return; } final Object allocationValue = values.get(ALLOCATION_KEY); @@ -65,11 +71,14 @@ public void finallyAfter( final String variantKey = details.getVariant(); final EvaluationContext context = ctx == null ? null : ctx.getCtx(); if (allocationKey == null || variantKey == null || context == null) { + log.trace( + "Feature Flagging exposure suppressed: allocation, variant, or context unavailable"); return; } final DDEvaluator evaluator = this.evaluatorSupplier.get(); final ExposureDeduplicationCache cache = evaluator == null ? null : evaluator.exposureCache(); if (cache == null) { + log.trace("Feature Flagging exposure suppressed: provider not initialized"); return; } final String flag = details.getFlagKey(); @@ -77,9 +86,12 @@ public void finallyAfter( final Integer serialId = serialValue instanceof Integer ? (Integer) serialValue : null; // The exposure is recorded even when it is not sent, so exposure hooks get the same // decisions whether or not exposures go to Datadog. - if (cache.recordIfChanged( - flag, context.getTargetingKey(), allocationKey, variantKey, serialId) - && evaluator.isExposureDeliveryEnabled()) { + if (!cache.recordIfChanged( + flag, context.getTargetingKey(), allocationKey, variantKey, serialId)) { + log.trace("Feature Flagging exposure suppressed: exposure already recorded"); + } else if (!evaluator.isExposureDeliveryEnabled()) { + log.trace("Feature Flagging exposure suppressed: Datadog exposure delivery is disabled"); + } else { evaluator.recordExposure( DDEvaluator.exposureEvent( flag, diff --git a/dd-openfeature/src/main/java/com/datadog/openfeature/Provider.java b/dd-openfeature/src/main/java/com/datadog/openfeature/Provider.java index e3ac093b7ad..3ea8a364b21 100644 --- a/dd-openfeature/src/main/java/com/datadog/openfeature/Provider.java +++ b/dd-openfeature/src/main/java/com/datadog/openfeature/Provider.java @@ -102,7 +102,7 @@ public Provider(final Options options) { // Precompute the immutable hook list once so getProviderHooks() (called on every evaluation) // allocates nothing, including when the gate is off. - final List hooks = new ArrayList<>(4); + final List hooks = new ArrayList<>(5); if (flagEvalMetricsHook != null) { hooks.add(flagEvalMetricsHook); } @@ -117,6 +117,20 @@ public Provider(final Options options) { hooks.set(i, new EvaluationTelemetryOptOutHook(hooks.get(i))); } } + // Local debug diagnostics are not telemetry, so the opt-out does not apply to them. + if (this.settings.isTraceDebug()) { + if (DebugLoggingHook.isLoggerEnabled()) { + hooks.add(new DebugLoggingHook<>()); + DebugLoggingHook.announce(); + } else { + // DD_TRACE_DEBUG cannot raise the application's logger levels, so name the second gate. + log.warn( + "DD_TRACE_DEBUG is enabled, but DEBUG is disabled for {} in the application's logging" + + " configuration; evaluation debug diagnostics are off. Enable DEBUG for that" + + " category before constructing the Provider.", + DebugLoggingHook.class.getName()); + } + } // Exposure hook: always registered last, and independent of evaluation telemetry opt-out; no-op // when the evaluator is not a Datadog one or is // not initialized. @@ -136,21 +150,30 @@ public Provider(final Options options) { @Override public void initialize(final EvaluationContext context) throws Exception { initializationState.set(InitializationState.INITIALIZING); + log.debug( + "Feature Flagging provider initializing: timeout={} {}", + options.getTimeout(), + options.getUnit()); try { evaluator = buildEvaluator(); if (!evaluator.initialize(options.getTimeout(), options.getUnit(), context)) { if (markInitialConfigReceivedReady()) { + log.debug( + "Feature Flagging provider ready: configuration received during initialization"); return; } markInitializationError(); + log.debug("Feature Flagging provider initialization timed out waiting for configuration"); throw new ProviderNotReadyError( "Provider timed-out while waiting for initial configuration"); } if (!evaluator.hasConfiguration() || !markSuccessfulInitializationReady()) { markInitializationError(); + log.debug("Feature Flagging provider initialization timed out waiting for configuration"); throw new ProviderNotReadyError( "Provider timed-out while waiting for initial configuration"); } + log.debug("Feature Flagging provider ready"); } catch (final RemoteConfigurationUnavailableException e) { // No RC connector means no configuration can arrive in this JVM. Complete registration // without waiting or switching sources. The evaluator has no runtime/configuration and @@ -164,6 +187,8 @@ public void initialize(final EvaluationContext context) throws Exception { throw e; } catch (final Throwable e) { markInitializationError(); + // Only the type: the message of a configuration error can echo a URL with credentials. + log.debug("Feature Flagging provider initialization failed: {}", e.getClass().getName()); throw new FatalError( "Failed to initialize Datadog Feature Flags provider: " + e.getMessage(), e); } @@ -187,6 +212,7 @@ void onConfigurationChange() { if (state == InitializationState.ERROR && initializationState.compareAndSet( InitializationState.ERROR, InitializationState.READY)) { + log.debug("Feature Flagging provider recovered: configuration received after an error"); emit( ProviderEvent.PROVIDER_READY, ProviderEventDetails.builder().message("Provider ready").build()); @@ -195,6 +221,7 @@ void onConfigurationChange() { if (initializationState.get() != InitializationState.READY) { return; } + log.debug("Feature Flagging provider configuration changed"); emit( ProviderEvent.PROVIDER_CONFIGURATION_CHANGED, ProviderEventDetails.builder().message("New configuration received").build()); @@ -208,6 +235,7 @@ private void onConfigurationUnavailable() { if (!initializationState.compareAndSet(InitializationState.READY, InitializationState.ERROR)) { return; } + log.debug("Feature Flagging provider configuration unavailable; evaluations return defaults"); emit( ProviderEvent.PROVIDER_ERROR, ProviderEventDetails.builder() @@ -266,6 +294,7 @@ public List getProviderHooks() { @Override public void shutdown() { + log.debug("Feature Flagging provider shutting down"); if (flagEvalMetrics != null) { flagEvalMetrics.shutdown(); } diff --git a/dd-openfeature/src/main/java/com/datadog/openfeature/internal/FeatureFlagsRuntime.java b/dd-openfeature/src/main/java/com/datadog/openfeature/internal/FeatureFlagsRuntime.java index 4466e1a53c6..e2cd9536c34 100644 --- a/dd-openfeature/src/main/java/com/datadog/openfeature/internal/FeatureFlagsRuntime.java +++ b/dd-openfeature/src/main/java/com/datadog/openfeature/internal/FeatureFlagsRuntime.java @@ -100,6 +100,7 @@ static FeatureFlagsRuntime create(final AgentBridge bridge, final Settings setti throw new IllegalStateException("Feature Flags is disabled"); } final boolean remoteConfig = CONFIGURATION_SOURCE_REMOTE_CONFIG.equals(sourceName); + LOGGER.debug("Feature Flags runtime starting: configurationSource={}", sourceName); final RuntimeServices services = new RuntimeServices(bridge.healthMetrics()); final ConfigurationService source; final EventTransport transport; @@ -150,6 +151,11 @@ static FeatureFlagsRuntime create(final AgentBridge bridge, final Settings setti context, services) : null; + LOGGER.debug( + "Feature Flags event delivery: transport={}, exposures={}, evaluationCounts={}", + transport.getClass().getSimpleName(), + exposures != null ? "enabled" : "disabled", + evaluations != null ? "enabled" : "disabled"); return new FeatureFlagsRuntime(source, exposures, evaluations); } @@ -256,9 +262,21 @@ void stop() { if (this.exposures != null) { this.exposures.awaitTermination(deadline); } + // Logged last: a diagnostic must not get in the way of the cleanup. + LOGGER.debug("Feature Flags runtime stopped"); } private void onConfiguration(@Nullable final ServerConfiguration configuration) { + if (configuration == null) { + LOGGER.debug("Feature Flags configuration removed"); + } else if (LOGGER.isDebugEnabled()) { + LOGGER.debug( + "Feature Flags configuration applied: flags={}, invalidFlags={}, configurationEnv={}, createdAt={}", + configuration.flags == null ? "missing" : configuration.flags.size(), + configuration.invalidFlags == null ? 0 : configuration.invalidFlags.size(), + configuration.environment == null ? null : configuration.environment.name, + configuration.createdAt); + } final Iterator> snapshot; synchronized (this.listeners) { this.configuration = configuration; diff --git a/dd-openfeature/src/main/java/com/datadog/openfeature/internal/config/Settings.java b/dd-openfeature/src/main/java/com/datadog/openfeature/internal/config/Settings.java index b9dc8a63c0d..aa43f1ab4cf 100644 --- a/dd-openfeature/src/main/java/com/datadog/openfeature/internal/config/Settings.java +++ b/dd-openfeature/src/main/java/com/datadog/openfeature/internal/config/Settings.java @@ -38,6 +38,7 @@ public final class Settings { "feature.flags.exposures.datadog.logging.enabled"; static final String EVALUATION_TELEMETRY_PER_SUBJECT_OPT_OUT_ENABLED = "feature.flags.evaluation.telemetry.per.subject.opt.out.enabled"; + static final String TRACE_DEBUG = "trace.debug"; static final String API_KEY = "api-key"; static final String SITE = "site"; static final String ENV = "env"; @@ -174,6 +175,16 @@ public boolean isEvaluationTelemetryPerSubjectOptOutEnabled() { return Boolean.TRUE.equals(getBoolean(EVALUATION_TELEMETRY_PER_SUBJECT_OPT_OUT_ENABLED)); } + /** + * Tells whether {@code DD_TRACE_DEBUG} is on. It gates the diagnostics that log raw evaluation + * contexts and values, on top of the application's logging configuration. + * + * @return whether trace debug is enabled (off by default). + */ + public boolean isTraceDebug() { + return Boolean.TRUE.equals(getBoolean(TRACE_DEBUG)); + } + /** * @return the Datadog API key, or {@code null} if not set. */ diff --git a/dd-openfeature/src/main/java/com/datadog/openfeature/internal/delivery/CdnConfigurationSource.java b/dd-openfeature/src/main/java/com/datadog/openfeature/internal/delivery/CdnConfigurationSource.java index cfb38849cab..e39ec9ee015 100644 --- a/dd-openfeature/src/main/java/com/datadog/openfeature/internal/delivery/CdnConfigurationSource.java +++ b/dd-openfeature/src/main/java/com/datadog/openfeature/internal/delivery/CdnConfigurationSource.java @@ -109,6 +109,14 @@ public void start(final Consumer listener) { this.started = true; this.listener = listener; } + LOGGER.debug( + "Feature Flags starting agentless configuration source: endpoint={}://{}{}{}, pollIntervalMillis={}, requestTimeout={}", + this.endpoint.getScheme(), + this.endpoint.getHost(), + this.endpoint.getPort() < 0 ? "" : ":" + this.endpoint.getPort(), + this.endpoint.getRawPath(), + this.pollIntervalMillis, + this.requestTimeout); // Complete the first poll cycle on the calling thread so provider initialization observes a // successful retry before it checks whether configuration is ready. pollOnceSafely(); @@ -138,6 +146,7 @@ public void close() { call = this.activeCall; this.activeCall = null; } + LOGGER.debug("Feature Flags agentless configuration source stopping"); this.closedSignal.countDown(); if (call != null) { call.cancel(); @@ -212,6 +221,7 @@ private boolean fetchAndApply() { private boolean apply(final HttpResponse response) { final int status = response.statusCode(); if (status == HttpURLConnection.HTTP_NOT_MODIFIED) { + LOGGER.debug("Feature Flags agentless configuration unchanged (HTTP 304)"); return true; } if (status == HttpURLConnection.HTTP_UNAUTHORIZED @@ -229,15 +239,21 @@ private boolean apply(final HttpResponse response) { try { configuration = UniversalFlagConfigParser.parseJsonApi(Gzip.decode(response)); } catch (final IOException | RuntimeException e) { - LOGGER.debug("Feature Flags configuration endpoint returned a malformed payload", e); + LOGGER.debug( + "Feature Flags configuration endpoint returned a malformed payload ({}); retaining the current configuration", + e.getClass().getSimpleName(), + e); return false; } if (configuration == null) { + LOGGER.debug( + "Feature Flags configuration endpoint returned no flag data; retaining the current configuration"); return false; } this.listener.accept(configuration); final String nextEtag = response.headers().firstValue("ETag").orElse(null); this.etag = nextEtag == null || nextEtag.trim().isEmpty() ? null : nextEtag; + LOGGER.debug("Feature Flags agentless configuration applied: etag={}", this.etag); return true; } @@ -254,10 +270,20 @@ private HttpResponse fetchWithRetries() throws IOException, InterruptedE return this.activeCall; } }, - (response, attempt) -> - response == null || isRetryableStatus(response.statusCode()) - ? retryDelayMillis(this.pollIntervalMillis, attempt, this.jitter.getAsDouble()) - : -1, + (response, attempt) -> { + if (response != null && !isRetryableStatus(response.statusCode())) { + return -1; + } + final long delayMillis = + retryDelayMillis(this.pollIntervalMillis, attempt, this.jitter.getAsDouble()); + LOGGER.debug( + "Feature Flags agentless configuration poll attempt {}/{} {}; retrying in {} ms", + attempt, + MAX_ATTEMPTS, + response == null ? "failed" : "returned HTTP " + response.statusCode(), + delayMillis); + return delayMillis; + }, MAX_ATTEMPTS, this.retrySleeper, () -> this.closed); diff --git a/dd-openfeature/src/main/java/com/datadog/openfeature/internal/delivery/RemoteConfigurationService.java b/dd-openfeature/src/main/java/com/datadog/openfeature/internal/delivery/RemoteConfigurationService.java index 63cae4527cb..f0179ab3b81 100644 --- a/dd-openfeature/src/main/java/com/datadog/openfeature/internal/delivery/RemoteConfigurationService.java +++ b/dd-openfeature/src/main/java/com/datadog/openfeature/internal/delivery/RemoteConfigurationService.java @@ -25,6 +25,7 @@ public synchronized void start(final Consumer listener) { if (this.subscription != null) { return; } + LOGGER.debug("Feature Flags subscribing to Remote Configuration"); this.subscription = this.source.subscribe( content -> { @@ -36,7 +37,10 @@ public synchronized void start(final Consumer listener) { try { configuration = UniversalFlagConfigParser.parse(content); } catch (final IOException | RuntimeException e) { - LOGGER.debug("Remote Configuration returned a malformed flag configuration", e); + LOGGER.debug( + "Remote Configuration returned a malformed flag configuration ({}); retaining the current configuration", + e.getClass().getSimpleName(), + e); return; } if (configuration != null) { diff --git a/dd-openfeature/src/main/java/com/datadog/openfeature/internal/exposure/ExposurePipeline.java b/dd-openfeature/src/main/java/com/datadog/openfeature/internal/exposure/ExposurePipeline.java index fb0acac0989..4c758b5f276 100644 --- a/dd-openfeature/src/main/java/com/datadog/openfeature/internal/exposure/ExposurePipeline.java +++ b/dd-openfeature/src/main/java/com/datadog/openfeature/internal/exposure/ExposurePipeline.java @@ -11,6 +11,7 @@ import java.util.Map; import java.util.concurrent.TimeUnit; import java.util.concurrent.atomic.AtomicBoolean; +import java.util.concurrent.atomic.AtomicLong; import java.util.function.Consumer; import org.slf4j.Logger; import org.slf4j.LoggerFactory; @@ -29,6 +30,7 @@ public class ExposurePipeline implements Consumer, EventPipeline private final Thread serializerThread; private final Object lifecycleLock = new Object(); private final AtomicBoolean closed = new AtomicBoolean(); + private final AtomicLong droppedQueueFull = new AtomicLong(); public ExposurePipeline( final int capacity, @@ -39,7 +41,8 @@ public ExposurePipeline( final RuntimeServices services) { this.queue = new EventQueue<>(capacity); this.serializer = - new ExposureSerializingHandler(transport, this.queue, flushInterval, timeUnit, context); + new ExposureSerializingHandler( + transport, this.queue, flushInterval, timeUnit, context, this.droppedQueueFull); this.serializerThread = services.newThread("exposures", this.serializer); } @@ -56,6 +59,9 @@ public void start() { public void requestShutdown() { synchronized (this.lifecycleLock) { if (this.closed.compareAndSet(false, true)) { + LOGGER.debug( + "Feature Flags exposure shutdown requested: queued={}; pending exposures get a final best-effort flush", + this.queue.size()); this.serializer.requestShutdown(); } } @@ -68,8 +74,9 @@ public void awaitTermination(final long deadlineNanos) { @Override public void accept(final ExposureEvent event) { - if (!this.closed.get()) { - this.queue.offer(event); + // Runs on the application thread: count the drops, the serializer reports them once per flush. + if (!this.closed.get() && !this.queue.offer(event)) { + this.droppedQueueFull.incrementAndGet(); } } @@ -91,13 +98,16 @@ private static class ExposureSerializingHandler implements Runnable { private final List buffer = new ArrayList<>(); private final AtomicBoolean shutdownRequested = new AtomicBoolean(); + private final AtomicLong droppedQueueFull; ExposureSerializingHandler( final EventTransport transport, final EventQueue queue, final long flushInterval, final TimeUnit timeUnit, - final Map context) { + final Map context, + final AtomicLong droppedQueueFull) { + this.droppedQueueFull = droppedQueueFull; this.queue = queue; this.transport = transport; this.context = context; @@ -163,9 +173,16 @@ protected void flushIfNecessary() { } private void flush() { + final long dropped = this.droppedQueueFull.getAndSet(0); + if (dropped > 0) { + LOGGER.debug( + "Feature Flags exposures dropped since the last flush: queue full, count={}", dropped); + } if (this.buffer.isEmpty()) { return; } + final int count = this.buffer.size(); + LOGGER.debug("Feature Flags exposure flush starting: count={}", count); final byte[] payload; try { final ExposuresRequest exposures = new ExposuresRequest(this.context, this.buffer); @@ -177,8 +194,13 @@ private void flush() { } try { this.transport.post(EXPOSURES_ROUTE, payload); + LOGGER.debug("Feature Flags exposure flush delivered: count={}", count); } catch (Exception e) { - LOGGER.debug("Could not submit exposures", e); + LOGGER.debug( + "Feature Flags exposure flush failed: {}; dropping the batch of {} exposure(s)", + e.toString(), + count, + e); } finally { // Best-effort delivery must not retry an ambiguously accepted batch. this.buffer.clear(); diff --git a/dd-openfeature/src/main/java/com/datadog/openfeature/internal/flagevaluation/FlagEvaluationPipeline.java b/dd-openfeature/src/main/java/com/datadog/openfeature/internal/flagevaluation/FlagEvaluationPipeline.java index 915ce31f61b..5df53cb2c98 100644 --- a/dd-openfeature/src/main/java/com/datadog/openfeature/internal/flagevaluation/FlagEvaluationPipeline.java +++ b/dd-openfeature/src/main/java/com/datadog/openfeature/internal/flagevaluation/FlagEvaluationPipeline.java @@ -128,6 +128,7 @@ int aggregatorFullTierSizeForTest() { public void requestShutdown() { synchronized (lifecycleLock) { if (closed.compareAndSet(false, true)) { + LOGGER.debug("Feature Flags flag evaluation shutdown requested"); // The worker polls every 100 ms: do not interrupt a current or final HTTP request. serializer.requestShutdown(); } @@ -407,6 +408,10 @@ void flush() { for (final byte[] payload : payloads.bodies) { transport.post(FLAG_EVALUATION_ROUTE, payload); } + if (!payloads.bodies.isEmpty()) { + LOGGER.debug( + "Feature Flags flag evaluation flush delivered: payloads={}", payloads.bodies.size()); + } } catch (Exception e) { LOGGER.error("Could not submit flag evaluations", e); } finally { diff --git a/dd-openfeature/src/test/java/com/datadog/openfeature/DebugLoggingTest.java b/dd-openfeature/src/test/java/com/datadog/openfeature/DebugLoggingTest.java new file mode 100644 index 00000000000..e700846689c --- /dev/null +++ b/dd-openfeature/src/test/java/com/datadog/openfeature/DebugLoggingTest.java @@ -0,0 +1,566 @@ +package com.datadog.openfeature; + +import static java.util.Collections.emptyList; +import static java.util.Collections.emptyMap; +import static java.util.Collections.singletonList; +import static java.util.concurrent.TimeUnit.SECONDS; +import static org.junit.jupiter.api.Assertions.assertDoesNotThrow; +import static org.junit.jupiter.api.Assertions.assertEquals; +import static org.junit.jupiter.api.Assertions.assertFalse; +import static org.junit.jupiter.api.Assertions.assertThrows; +import static org.junit.jupiter.api.Assertions.assertTimeoutPreemptively; +import static org.junit.jupiter.api.Assertions.assertTrue; +import static org.mockito.Mockito.mock; +import static org.mockito.Mockito.when; + +import com.datadog.openfeature.Provider.Options; +import com.datadog.openfeature.internal.ufc.Allocation; +import com.datadog.openfeature.internal.ufc.Flag; +import com.datadog.openfeature.internal.ufc.ServerConfiguration; +import com.datadog.openfeature.internal.ufc.Split; +import com.datadog.openfeature.internal.ufc.ValueType; +import com.datadog.openfeature.internal.ufc.Variant; +import com.datadog.openfeature.testlog.CapturingServiceProvider; +import com.datadog.openfeature.testlog.CapturingServiceProvider.Event; +import dev.openfeature.sdk.Client; +import dev.openfeature.sdk.EvaluationContext; +import dev.openfeature.sdk.FlagEvaluationDetails; +import dev.openfeature.sdk.FlagValueType; +import dev.openfeature.sdk.HookContext; +import dev.openfeature.sdk.MutableContext; +import dev.openfeature.sdk.MutableStructure; +import dev.openfeature.sdk.OpenFeatureAPI; +import dev.openfeature.sdk.Value; +import java.time.Duration; +import java.util.AbstractList; +import java.util.ArrayList; +import java.util.Arrays; +import java.util.Collections; +import java.util.HashMap; +import java.util.IdentityHashMap; +import java.util.Iterator; +import java.util.List; +import java.util.Map; +import java.util.stream.Collectors; +import org.junit.jupiter.api.AfterEach; +import org.junit.jupiter.api.BeforeEach; +import org.junit.jupiter.api.Test; +import org.slf4j.event.Level; + +class DebugLoggingTest { + private static final String TRACE_DEBUG = "dd.trace.debug"; + private static final String AGENTLESS_BASE_URL = + "dd.feature.flags.configuration.source.agentless.base.url"; + + private static final String SDK_LOGGERS = "com.datadog.openfeature"; + + @BeforeEach + void captureLogs() { + CapturingServiceProvider.reset(); + CapturingServiceProvider.enable(SDK_LOGGERS, Level.DEBUG); + } + + @AfterEach + void restore() { + System.clearProperty(TRACE_DEBUG); + System.clearProperty(AGENTLESS_BASE_URL); + OpenFeatureAPI.getInstance().clearHooks(); + OpenFeatureAPI.getInstance().shutdown(); + CapturingServiceProvider.reset(); + } + + @Test + void logsTheRawEvaluationWhenTraceDebugIsOn() throws Exception { + System.setProperty(TRACE_DEBUG, "true"); + final Client client = register(); + + client.getIntegerValue("flag", 5, new MutableContext("user-1").add("plan", "pro")); + + final String message = singleMessage("Feature Flagging evaluation:"); + assertTrue(message.contains("flag=flag"), message); + assertTrue(message.contains("targetingKey=user-1"), message); + assertTrue(message.contains("plan=pro"), message); + assertTrue(message.contains("defaultValue=5"), message); + assertTrue(message.contains("value=1"), message); + assertTrue(message.contains("variant=on"), message); + assertTrue(message.contains("reason=STATIC"), message); + assertEquals( + Level.DEBUG, + CapturingServiceProvider.events().stream() + .filter(e -> e.message.equals(message)) + .findFirst() + .get() + .level); + } + + @Test + void logsTheErrorOfAnEvaluation() throws Exception { + System.setProperty(TRACE_DEBUG, "true"); + final Client client = register(); + + client.getIntegerValue("missing", 5, new MutableContext("user-1")); + + final String message = singleMessage("Feature Flagging evaluation:"); + assertTrue(message.contains("flag=missing"), message); + assertTrue(message.contains("errorCode=FLAG_NOT_FOUND"), message); + } + + @Test + void doesNotLogRawEvaluationsWithoutTraceDebug() throws Exception { + // Explicit, so that a DD_TRACE_DEBUG in the environment of the test JVM does not matter. + System.setProperty(TRACE_DEBUG, "false"); + final Client client = register(); + + client.getIntegerValue("flag", 5, new MutableContext("user-1")); + + assertTrue(messages("Feature Flagging evaluation:").isEmpty()); + } + + @Test + void warnsWhenTraceDebugIsOnButTheLoggerDoesNotAllowDebug() throws Exception { + System.setProperty(TRACE_DEBUG, "true"); + CapturingServiceProvider.enable(DebugLoggingHook.class.getName(), Level.INFO); + final Client client = register(); + + client.getIntegerValue("flag", 5, new MutableContext("user-1")); + + assertTrue(messages("Feature Flagging evaluation:").isEmpty()); + final List warnings = + CapturingServiceProvider.events().stream() + .filter(e -> e.level == Level.WARN) + .filter(e -> e.message.contains("DD_TRACE_DEBUG is enabled")) + .collect(Collectors.toList()); + assertEquals(1, warnings.size()); + } + + @Test + void stopsLoggingRawEvaluationsWhenTheLoggerIsLoweredAfterRegistration() throws Exception { + System.setProperty(TRACE_DEBUG, "true"); + final Client client = register(); + client.getIntegerValue("flag", 5, new MutableContext("user-1")); + assertEquals(1, messages("Feature Flagging evaluation:").size()); + + CapturingServiceProvider.enable(DebugLoggingHook.class.getName(), Level.INFO); + client.getIntegerValue("flag", 5, new MutableContext("user-2")); + + assertEquals(1, messages("Feature Flagging evaluation:").size()); + } + + @Test + void announcesThatRawEvaluationsAreLoggedWhenTheHookIsRegistered() throws Exception { + System.setProperty(TRACE_DEBUG, "true"); + register(); + + final List announcements = + CapturingServiceProvider.events().stream() + .filter(e -> e.message.contains("personal data")) + .collect(Collectors.toList()); + assertEquals(1, announcements.size(), announcements.toString()); + assertEquals(Level.INFO, announcements.get(0).level); + } + + @Test + void announcesThroughTheLoggerOfTheHookAlone() throws Exception { + System.setProperty(TRACE_DEBUG, "true"); + // Only the category named by the provider warning is enabled: the provider logger is not. + CapturingServiceProvider.enable(SDK_LOGGERS, Level.WARN); + CapturingServiceProvider.enable(DebugLoggingHook.class.getName(), Level.DEBUG); + register(); + + final List announcements = + CapturingServiceProvider.events().stream() + .filter(e -> e.message.contains("personal data")) + .collect(Collectors.toList()); + assertEquals(1, announcements.size(), announcements.toString()); + assertEquals(DebugLoggingHook.class.getName(), announcements.get(0).logger); + assertEquals(Level.INFO, announcements.get(0).level); + } + + @Test + void doesNotAnnounceRawLoggingWithoutTraceDebug() throws Exception { + System.setProperty(TRACE_DEBUG, "false"); + register(); + + assertTrue(messages("DD_TRACE_DEBUG is enabled").isEmpty()); + } + + @Test + void containsAFailureToFormatTheEvaluation() { + final EvaluationContext failing = mock(EvaluationContext.class); + when(failing.keySet()).thenThrow(new IllegalStateException("cannot render")); + final HookContext hookContext = + HookContext.builder() + .flagKey("flag") + .type(FlagValueType.INTEGER) + .defaultValue(0) + .ctx(failing) + .build(); + final FlagEvaluationDetails details = + FlagEvaluationDetails.builder().flagKey("flag").value(1).build(); + + assertDoesNotThrow( + () -> new DebugLoggingHook<>().finallyAfter(hookContext, details, emptyMap())); + + assertEquals( + 1, + messages("Feature Flagging evaluation diagnostic unavailable: java.lang.IllegalState") + .size()); + } + + @Test + void doesNotExplainExposureSuppressionsAtDebug() throws Exception { + final Client client = register(); + + client.getIntegerValue("missing", 5, new MutableContext("user-1")); + client.getIntegerValue("flag", 5, new MutableContext("user-1")); + client.getIntegerValue("flag", 5, new MutableContext("user-1")); + + assertTrue(messages("Feature Flagging exposure suppressed").isEmpty()); + } + + @Test + void capsTheLengthOfALoggedContextValue() throws Exception { + System.setProperty(TRACE_DEBUG, "true"); + final Client client = register(); + final String blob = "x".repeat(5_000); + + client.getIntegerValue("flag", 5, new MutableContext("user-1").add("blob", blob)); + + final String message = singleMessage("Feature Flagging evaluation:"); + assertTrue(message.contains("...(truncated)"), message); + assertFalse(message.contains(blob), message); + assertTrue(message.length() < 3_000, "Logged " + message.length() + " characters"); + } + + @Test + void rendersNestedValuesAsTheyAre() { + final Value nested = + new Value( + Arrays.asList( + new Value("a"), new Value(new MutableStructure().add("k", "v")), new Value(2))); + + final String message = hookMessage(hookContext(new MutableContext("u"), nested), details()); + + assertTrue(message.contains("defaultValue=[a, {k=v}, 2]"), message); + assertTrue(message.contains("context={targetingKey=u}"), message); + } + + @Test + void doesNotFollowAValueThatContainsItself() { + final List list = new ArrayList<>(); + final Value cyclic = new Value(list); + list.add(cyclic); + final Map attributes = new HashMap<>(); + attributes.put("loop", cyclic); + + final String message = + hookMessage(hookContext(new MutableContext("u", attributes), new Value(0)), details()); + + assertTrue(message.contains("loop=[(cycle)]"), message); + } + + @Test + @SuppressWarnings({"unchecked", "rawtypes"}) + void doesNotFollowAListThatContainsNullAndItself() { + final List list = new ArrayList<>(); + final Value cyclic = new Value((List) list); + list.add(null); + list.add(cyclic); + + final String message = hookMessage(hookContext(new MutableContext("u"), cyclic), details()); + + assertTrue(message.contains("defaultValue=[null, (cycle)]"), message); + } + + @Test + void stopsWalkingAListOnceTheBudgetIsSpent() { + final int[] reads = {0}; + final List wide = + new AbstractList() { + @Override + public String get(final int index) { + reads[0]++; + return "element-" + index; + } + + @Override + public int size() { + return 1_000_000; + } + }; + + final String message = hookMessage(hookContext(new MutableContext("u"), wide), details()); + + assertTrue(message.contains("...(truncated)"), message); + assertTrue(reads[0] < 1_000, "Read " + reads[0] + " elements"); + } + + @Test + void doesNotScanAWrappedListBeforeRenderingIt() { + final int[] reads = {0}; + final List wide = + new AbstractList() { + @Override + public Value get(final int index) { + reads[0]++; + return new Value("element-" + index); + } + + @Override + public int size() { + return 1_000_000; + } + }; + + final String message = + hookMessage(hookContext(new MutableContext("u"), new Value(wide)), details()); + + assertTrue(message.contains("...(truncated)"), message); + assertTrue(reads[0] < 1_000, "Read " + reads[0] + " elements"); + } + + @Test + void returnsFromAnInfiniteIterable() { + final Iterable infinite = + () -> + new Iterator() { + @Override + public boolean hasNext() { + return true; + } + + @Override + public String next() { + return "x"; + } + }; + + final String message = + assertTimeoutPreemptively( + Duration.ofSeconds(10), + () -> hookMessage(hookContext(new MutableContext("u"), infinite), details())); + + assertTrue(message.contains("...(truncated)"), message); + } + + @Test + void doesNotRenderAMapKeyOutsideTheGuards() { + final List first = new ArrayList<>(); + final List second = new ArrayList<>(); + first.add(second); + second.add(first); + final Map map = new IdentityHashMap<>(); + map.put(first, "v"); + + final String message = hookMessage(hookContext(new MutableContext("u"), map), details()); + + assertTrue(message.contains("defaultValue={[[(cycle)]]=v}"), message); + } + + @Test + void rendersANullStructureKey() { + final Value structure = new Value(new MutableStructure().add((String) null, "v")); + + final String message = hookMessage(hookContext(new MutableContext("u"), structure), details()); + + assertTrue(message.contains("defaultValue={null=v}"), message); + } + + @Test + void doesNotOverflowTheStackOnAVeryDeepValue() { + Value deep = new Value("leaf"); + for (int i = 0; i < 5_000; i++) { + deep = new Value(Collections.singletonList(deep)); + } + final Map attributes = new HashMap<>(); + attributes.put("deep", deep); + + final String message = + hookMessage(hookContext(new MutableContext("u", attributes), new Value(0)), details()); + + assertTrue(message.contains("deep=[[[[[[[[...]]]]]]]]"), message); + assertFalse(message.contains("leaf"), message); + assertTrue(message.length() < 2_000, "Logged " + message.length() + " characters"); + } + + @Test + void rendersAWideContextWithinTheBudget() { + final Map attributes = new HashMap<>(); + for (int i = 0; i < 20_000; i++) { + attributes.put("attribute-" + i, new Value("value-" + i)); + } + + final String message = + hookMessage(hookContext(new MutableContext("u", attributes), new Value(0)), details()); + + assertTrue(message.contains("...(truncated)"), message); + assertTrue(message.length() < 2_000, "Logged " + message.length() + " characters"); + } + + @Test + void capsTheVariantAndTheReason() { + final FlagEvaluationDetails details = + FlagEvaluationDetails.builder() + .flagKey("flag") + .value(1) + .variant("v".repeat(5_000)) + .reason("r".repeat(5_000)) + .build(); + + final String message = hookMessage(hookContext(new MutableContext("u"), new Value(0)), details); + + assertTrue( + message.contains("variant=" + "v".repeat(1_024) + "...(truncated, 5000 characters), "), + message); + assertTrue( + message.contains("reason=" + "r".repeat(1_024) + "...(truncated, 5000 characters), "), + message); + } + + @Test + void capsTheFlagKey() throws Exception { + System.setProperty(TRACE_DEBUG, "true"); + final Client client = register(); + + client.getIntegerValue("k".repeat(5_000), 5, new MutableContext("user-1")); + + final String message = singleMessage("Feature Flagging evaluation:"); + assertTrue( + message.startsWith( + "Feature Flagging evaluation: flag=" + + "k".repeat(1_024) + + "...(truncated, 5000 characters), context="), + message.substring(0, Math.min(message.length(), 1_200))); + } + + @Test + void doesNotCutASurrogatePairAtTheLimit() throws Exception { + System.setProperty(TRACE_DEBUG, "true"); + final Client client = register(); + // The emoji is a surrogate pair whose first half is the last character below the limit. + final String key = "k".repeat(1_023) + "\uD83D\uDE00" + "k".repeat(100); + + client.getIntegerValue(key, 5, new MutableContext("user-1")); + + final String message = singleMessage("Feature Flagging evaluation:"); + assertTrue( + message.startsWith( + "Feature Flagging evaluation: flag=" + + "k".repeat(1_023) + + "...(truncated, 1125 characters), context="), + message.substring(0, Math.min(message.length(), 1_200))); + assertFalse(message.contains("\uD83D"), "A lone surrogate was logged"); + } + + @Test + void doesNotLogTheCredentialsOfAnInvalidEndpoint() { + System.setProperty(AGENTLESS_BASE_URL, "ftp://user:pw-secret@example.com/ufc?token=tok-secret"); + + // The provider cannot initialize: the endpoint is invalid. + assertThrows( + Exception.class, + () -> + OpenFeatureAPI.getInstance() + .setProviderAndWait(new Provider(new Options().initTimeout(1, SECONDS)))); + + assertEquals(1, messages("Feature Flagging provider initialization failed: java.lang.").size()); + for (final Event event : CapturingServiceProvider.events()) { + assertFalse(event.message.contains("pw-secret"), event.toString()); + assertFalse(event.message.contains("tok-secret"), event.toString()); + } + } + + @Test + void logsTheErrorMessageTheApplicationObserves() throws Exception { + System.setProperty(TRACE_DEBUG, "true"); + final Client client = register(); + + // The configuration does not observe full evaluation data, so the provider drops the message. + client.getStringValue("flag", "default", new MutableContext("user-1")); + + final String message = singleMessage("Feature Flagging evaluation:"); + assertTrue(message.contains("errorCode=TYPE_MISMATCH"), message); + assertTrue(message.contains("errorMessage=null"), message); + } + + @Test + void logsTheProviderLifecycle() throws Exception { + register(); + OpenFeatureAPI.getInstance().shutdown(); + + assertEquals(1, messages("Feature Flagging provider initializing").size()); + assertFalse(messages("Feature Flagging provider ready").isEmpty()); + assertFalse(messages("Feature Flagging provider shutting down").isEmpty()); + } + + @Test + void explainsWhyAnExposureIsSuppressed() throws Exception { + CapturingServiceProvider.enable(SDK_LOGGERS, Level.TRACE); + final Client client = register(); + + client.getIntegerValue("missing", 5, new MutableContext("user-1")); + client.getIntegerValue("flag", 5, new MutableContext("user-1")); + client.getIntegerValue("flag", 5, new MutableContext("user-1")); + + assertEquals( + 1, + messages("Feature Flagging exposure suppressed: evaluation failed or details unavailable") + .size()); + assertEquals( + 1, messages("Feature Flagging exposure suppressed: exposure already recorded").size()); + } + + private static HookContext hookContext( + final EvaluationContext context, final Object defaultValue) { + return HookContext.builder() + .flagKey("flag") + .type(FlagValueType.OBJECT) + .defaultValue(defaultValue) + .ctx(context) + .build(); + } + + private static FlagEvaluationDetails details() { + return FlagEvaluationDetails.builder().flagKey("flag").value(1).build(); + } + + private String hookMessage( + final HookContext hookContext, final FlagEvaluationDetails details) { + new DebugLoggingHook<>().finallyAfter(hookContext, details, emptyMap()); + return singleMessage("Feature Flagging evaluation:"); + } + + private Client register() throws Exception { + final OpenFeatureAPI api = OpenFeatureAPI.getInstance(); + api.setProviderAndWait( + new Provider( + new Options().initTimeout(10, SECONDS), + new ExposureTestEvaluator(configuration(), true))); + return api.getClient(); + } + + private String singleMessage(final String prefix) { + final List messages = messages(prefix); + assertEquals(1, messages.size(), messages.toString()); + return messages.get(0); + } + + private List messages(final String prefix) { + return CapturingServiceProvider.events().stream() + .map(e -> e.message) + .filter(message -> message.startsWith(prefix)) + .collect(Collectors.toList()); + } + + private static ServerConfiguration configuration() { + final Map variations = new HashMap<>(); + variations.put("on", new Variant("on", 1)); + final Split split = new Split(emptyList(), "on", emptyMap(), 7); + final Allocation allocation = + new Allocation("allocation", null, null, null, singletonList(split), Boolean.TRUE); + final Map flags = new HashMap<>(); + flags.put( + "flag", new Flag("flag", true, ValueType.INTEGER, variations, singletonList(allocation))); + return new ServerConfiguration("", "", false, null, flags); + } +} diff --git a/dd-openfeature/src/test/java/com/datadog/openfeature/internal/FeatureFlagsRuntimeTest.java b/dd-openfeature/src/test/java/com/datadog/openfeature/internal/FeatureFlagsRuntimeTest.java index 1104b34f8fc..78d21300099 100644 --- a/dd-openfeature/src/test/java/com/datadog/openfeature/internal/FeatureFlagsRuntimeTest.java +++ b/dd-openfeature/src/test/java/com/datadog/openfeature/internal/FeatureFlagsRuntimeTest.java @@ -23,6 +23,7 @@ import com.datadog.openfeature.internal.config.TestSettings; import com.datadog.openfeature.internal.flagevaluation.FlagEvalEvent; import com.datadog.openfeature.internal.ufc.ServerConfiguration; +import com.datadog.openfeature.testlog.CapturingServiceProvider; import java.nio.charset.StandardCharsets; import java.util.List; import java.util.Map; @@ -33,7 +34,10 @@ import java.util.concurrent.Future; import java.util.concurrent.TimeoutException; import java.util.function.Consumer; +import java.util.stream.Collectors; +import org.junit.jupiter.api.AfterEach; import org.junit.jupiter.api.Test; +import org.slf4j.event.Level; class FeatureFlagsRuntimeTest { private static final byte[] EMPTY_UFC = @@ -143,6 +147,53 @@ void remoteConfigurationDeliversParsedConfigurationsAndReplaysToLateListeners() assertTrue(source.closed); } + @AfterEach + void resetCapturedLogs() { + CapturingServiceProvider.reset(); + } + + @Test + void stoppingDoesNotDependOnTheLoggingBackend() { + CapturingServiceProvider.enable("com.datadog.openfeature", Level.DEBUG); + CapturingServiceProvider.failOn("Feature Flags runtime stopped"); + final TestConfigurationSource source = new TestConfigurationSource(); + final FeatureFlagsRuntime runtime = + FeatureFlagsRuntime.create( + new TestAgentBridge(source, null), + TestSettings.of("feature.flags.configuration.source", "remote_config")); + runtime.start(); + + assertThrows(IllegalStateException.class, runtime::stop); + + assertTrue(source.closed); + } + + @Test + void reportsAppliedAndRemovedConfigurations() { + CapturingServiceProvider.enable("com.datadog.openfeature", Level.DEBUG); + final TestConfigurationSource source = new TestConfigurationSource(); + final FeatureFlagsRuntime runtime = + FeatureFlagsRuntime.create( + new TestAgentBridge(source, null), + TestSettings.of("feature.flags.configuration.source", "remote_config")); + runtime.start(); + try { + source.listener.accept(EMPTY_UFC); + source.listener.accept(null); + } finally { + runtime.stop(); + } + + final List messages = + CapturingServiceProvider.events().stream().map(e -> e.message).collect(Collectors.toList()); + assertTrue( + messages.contains( + "Feature Flags configuration applied: flags=0, invalidFlags=0, configurationEnv=Test, createdAt=null"), + messages.toString()); + assertTrue(messages.contains("Feature Flags configuration removed"), messages.toString()); + assertTrue(messages.contains("Feature Flags runtime stopped"), messages.toString()); + } + @Test void concurrentRemovalIsDeliveredAfterTheInitialReplay() throws Exception { final TestConfigurationSource source = new TestConfigurationSource(); diff --git a/dd-openfeature/src/test/java/com/datadog/openfeature/internal/config/SettingsTest.java b/dd-openfeature/src/test/java/com/datadog/openfeature/internal/config/SettingsTest.java index 9e6675a1edc..a2476b5bae7 100644 --- a/dd-openfeature/src/test/java/com/datadog/openfeature/internal/config/SettingsTest.java +++ b/dd-openfeature/src/test/java/com/datadog/openfeature/internal/config/SettingsTest.java @@ -192,6 +192,25 @@ void readsToggles() { assertFalse(settings.isEvaluationCountsEnabled()); } + @Test + void readsTraceDebugFromTheBridgeThenSystemPropertiesThenEnvironment() { + final Map bridge = new HashMap<>(); + final Map properties = new HashMap<>(); + final Map environment = new HashMap<>(); + final Settings settings = + new Settings(new SettingAgentBridge(bridge), properties::get, environment::get); + assertFalse(settings.isTraceDebug()); + + environment.put("DD_TRACE_DEBUG", "1"); + assertTrue(settings.isTraceDebug()); + + properties.put("dd.trace.debug", "false"); + assertFalse(settings.isTraceDebug()); + + bridge.put("trace.debug", "TRUE"); + assertTrue(settings.isTraceDebug()); + } + private static void putIfNotNull( final Map map, final String key, final String value) { if (value != null) { diff --git a/dd-openfeature/src/test/java/com/datadog/openfeature/internal/delivery/DeliveryDiagnosticsTest.java b/dd-openfeature/src/test/java/com/datadog/openfeature/internal/delivery/DeliveryDiagnosticsTest.java new file mode 100644 index 00000000000..c4f9d3be39b --- /dev/null +++ b/dd-openfeature/src/test/java/com/datadog/openfeature/internal/delivery/DeliveryDiagnosticsTest.java @@ -0,0 +1,201 @@ +package com.datadog.openfeature.internal.delivery; + +import static java.nio.charset.StandardCharsets.UTF_8; +import static org.junit.jupiter.api.Assertions.assertEquals; +import static org.junit.jupiter.api.Assertions.assertFalse; +import static org.junit.jupiter.api.Assertions.assertNull; +import static org.junit.jupiter.api.Assertions.assertTrue; +import static org.mockito.Mockito.mock; + +import com.datadog.openfeature.internal.LocalHttpServer; +import com.datadog.openfeature.internal.bridge.v1.ConfigurationSource; +import com.datadog.openfeature.internal.ufc.ServerConfiguration; +import com.datadog.openfeature.testlog.CapturingServiceProvider; +import java.io.IOException; +import java.net.URI; +import java.net.http.HttpClient; +import java.time.Duration; +import java.util.List; +import java.util.concurrent.CopyOnWriteArrayList; +import java.util.concurrent.ScheduledExecutorService; +import java.util.function.Consumer; +import java.util.stream.Collectors; +import org.junit.jupiter.api.AfterEach; +import org.junit.jupiter.api.BeforeEach; +import org.junit.jupiter.api.Test; +import org.slf4j.event.Level; + +class DeliveryDiagnosticsTest { + private static final String CONFIG = + "{\"data\":{\"type\":\"universal-flag-configuration\",\"attributes\":" + + "{\"createdAt\":\"2024-04-17T19:40:53.716Z\",\"environment\":{\"name\":\"Test\"}," + + "\"flags\":{}}}}"; + + private LocalHttpServer server; + + @BeforeEach + void setUp() throws IOException { + this.server = new LocalHttpServer(); + CapturingServiceProvider.reset(); + CapturingServiceProvider.enable("com.datadog.openfeature", Level.DEBUG); + } + + @AfterEach + void tearDown() { + CapturingServiceProvider.reset(); + this.server.close(); + } + + @Test + void agentlessReportsAppliedAndUnchangedConfigurations() { + this.server.enqueue(200, CONFIG, "ETag", "\"v1\"").enqueue(304, null); + final CdnConfigurationSource source = source(); + + assertTrue(source.pollOnce()); + assertTrue(source.pollOnce()); + + assertLogged("agentless configuration applied: etag=\"v1\""); + assertLogged("agentless configuration unchanged (HTTP 304)"); + // A successful poll reports its outcome once: a retry line is only for a retry. + assertTrue(messages("poll attempt").isEmpty(), messages("").toString()); + } + + @Test + void agentlessReportsAFailedAttemptWithoutItsStackTrace() { + final CdnConfigurationSource source = source(URI.create("http://127.0.0.1:1/ufc"), null); + + assertFalse(source.pollOnce()); + + final List attempts = + CapturingServiceProvider.events().stream() + .filter(e -> e.message.contains("poll attempt")) + .collect(Collectors.toList()); + assertEquals(2, attempts.size(), attempts.toString()); + for (final CapturingServiceProvider.Event attempt : attempts) { + assertNull(attempt.throwable, attempt.toString()); + } + } + + @Test + void agentlessReportsAMalformedPayloadAsRetainingTheConfiguration() { + this.server.enqueue(200, "{not json"); + + assertFalse(source().pollOnce()); + + assertLogged("malformed payload"); + assertLogged("retaining the current configuration"); + } + + @Test + void agentlessReportsRetriesAndTheirDelay() { + this.server.enqueue(503, null).enqueue(200, CONFIG); + + assertTrue(source().pollOnce()); + + assertLogged("poll attempt 1/3 returned HTTP 503; retrying in"); + } + + @Test + void agentlessReportsItsLifecycleWithoutQueryOrCredentials() { + final CdnConfigurationSource source = source("secret"); + this.server.enqueue(200, CONFIG); + + source.start(configuration -> {}); + source.close(); + + final String starting = logged("starting agentless configuration source"); + assertTrue(starting.contains("pollIntervalMillis=30000"), starting); + assertTrue(starting.contains("/ufc,"), starting); + assertFalse(starting.contains("secret"), starting); + assertFalse(starting.contains("token"), starting); + assertFalse(starting.contains("hidden"), starting); + assertLogged("agentless configuration source stopping"); + } + + @Test + void agentlessDoesNotReportTheUserInfoOfTheEndpoint() { + final URI server = this.server.uri("/ufc?token=hidden"); + final URI endpoint = + URI.create( + "http://user:s3cret@" + + server.getHost() + + ":" + + server.getPort() + + "/ufc?token=hidden"); + this.server.enqueue(200, CONFIG); + final CdnConfigurationSource source = source(endpoint, null); + + source.start(configuration -> {}); + source.close(); + + final String starting = logged("starting agentless configuration source"); + assertTrue(starting.contains("http://" + server.getHost() + ":" + server.getPort()), starting); + assertFalse(starting.contains("user"), starting); + assertFalse(starting.contains("s3cret"), starting); + assertFalse(starting.contains("hidden"), starting); + } + + @Test + void remoteConfigurationReportsItsSubscriptionAndMalformedDocuments() { + final CapturingSource connector = new CapturingSource(); + final RemoteConfigurationService service = new RemoteConfigurationService(connector); + service.start(configuration -> {}); + + connector.listener.accept("{\"environment\":{\"name\":\"Test\"},\"flags\":{}}".getBytes(UTF_8)); + connector.listener.accept("{not json".getBytes(UTF_8)); + connector.listener.accept(null); + + assertLogged("subscribing to Remote Configuration"); + assertLogged("malformed flag configuration"); + } + + private CdnConfigurationSource source() { + return source(null); + } + + private CdnConfigurationSource source(final String apiKey) { + return source(this.server.uri("/ufc?token=hidden"), apiKey); + } + + private CdnConfigurationSource source(final URI endpoint, final String apiKey) { + final CdnConfigurationSource source = + new CdnConfigurationSource( + endpoint, + apiKey, + 30_000, + Duration.ofSeconds(5), + HttpClient.newHttpClient(), + mock(ScheduledExecutorService.class), + delay -> {}, + () -> 1.0); + source.setListenerForTest(new CopyOnWriteArrayList()::add); + return source; + } + + private void assertLogged(final String text) { + assertFalse(messages(text).isEmpty(), "Missing log: " + text + " in " + messages("")); + } + + private String logged(final String text) { + final List found = messages(text); + assertEquals(1, found.size(), found.toString()); + return found.get(0); + } + + private static List messages(final String text) { + return CapturingServiceProvider.events().stream() + .map(e -> e.message) + .filter(message -> message.contains(text)) + .collect(Collectors.toList()); + } + + private static final class CapturingSource implements ConfigurationSource { + volatile Consumer listener; + + @Override + public AutoCloseable subscribe(final Consumer listener) { + this.listener = listener; + return () -> {}; + } + } +} diff --git a/dd-openfeature/src/test/java/com/datadog/openfeature/internal/exposure/ExposurePipelineDiagnosticsTest.java b/dd-openfeature/src/test/java/com/datadog/openfeature/internal/exposure/ExposurePipelineDiagnosticsTest.java new file mode 100644 index 00000000000..0afeeb286d9 --- /dev/null +++ b/dd-openfeature/src/test/java/com/datadog/openfeature/internal/exposure/ExposurePipelineDiagnosticsTest.java @@ -0,0 +1,139 @@ +package com.datadog.openfeature.internal.exposure; + +import static java.util.Collections.emptyMap; +import static java.util.concurrent.TimeUnit.MILLISECONDS; +import static java.util.concurrent.TimeUnit.SECONDS; +import static org.junit.jupiter.api.Assertions.assertEquals; +import static org.junit.jupiter.api.Assertions.assertFalse; + +import com.datadog.openfeature.internal.RuntimeServices; +import com.datadog.openfeature.internal.bridge.v1.EventTransport; +import com.datadog.openfeature.internal.bridge.v1.HealthMetrics; +import com.datadog.openfeature.testlog.CapturingServiceProvider; +import java.io.IOException; +import java.util.List; +import java.util.stream.Collectors; +import org.junit.jupiter.api.AfterEach; +import org.junit.jupiter.api.BeforeEach; +import org.junit.jupiter.api.Test; +import org.slf4j.event.Level; + +class ExposurePipelineDiagnosticsTest { + private static final long AWAIT_MILLIS = SECONDS.toMillis(5); + + @BeforeEach + void captureLogs() { + CapturingServiceProvider.reset(); + CapturingServiceProvider.enable("com.datadog.openfeature", Level.DEBUG); + } + + @AfterEach + void restore() { + CapturingServiceProvider.reset(); + } + + @Test + void reportsTheExposuresDroppedByAFullQueueOncePerFlush() throws Exception { + final ExposurePipeline pipeline = pipeline(1, (route, json) -> {}); + final int logged = pipelineEvents().size(); + + pipeline.accept(exposure()); + pipeline.accept(exposure()); + pipeline.accept(exposure()); + + // The producer, an application thread, does not log. + assertEquals(logged, pipelineEvents().size(), messages("").toString()); + pipeline.start(); + try { + awaitLog("exposures dropped since the last flush: queue full, count=2"); + } finally { + pipeline.close(); + } + assertEquals(1, messages("queue full").size(), messages("").toString()); + } + + @Test + void reportsTheShutdownRequestWithoutLoggingEachExposure() { + final ExposurePipeline pipeline = pipeline(16, (route, json) -> {}); + final int logged = pipelineEvents().size(); + + pipeline.accept(exposure()); + pipeline.requestShutdown(); + pipeline.accept(exposure()); + + assertEquals(logged + 1, pipelineEvents().size(), messages("").toString()); + assertEquals(1, messages("exposure shutdown requested: queued=1").size()); + } + + @Test + void reportsADeliveredFlush() throws Exception { + final ExposurePipeline pipeline = pipeline(16, (route, json) -> {}); + pipeline.start(); + try { + pipeline.accept(exposure()); + + awaitLog("exposure flush delivered: count=1"); + } finally { + pipeline.close(); + } + + assertFalse(messages("exposure flush starting: count=1").isEmpty()); + } + + @Test + void reportsAFailedFlushAsDroppingTheBatch() throws Exception { + final ExposurePipeline pipeline = + pipeline( + 16, + (route, json) -> { + throw new IOException("returned error response 503"); + }); + pipeline.start(); + try { + pipeline.accept(exposure()); + + awaitLog("exposure flush failed: java.io.IOException: returned error response 503"); + } finally { + pipeline.close(); + } + + assertFalse(messages("dropping the batch of 1 exposure(s)").isEmpty()); + } + + private static ExposurePipeline pipeline(final int capacity, final EventTransport transport) { + return new ExposurePipeline( + capacity, 10, MILLISECONDS, transport, emptyMap(), new RuntimeServices(HealthMetrics.NOOP)); + } + + private static ExposureEvent exposure() { + return new ExposureEvent( + 1L, + new Allocation("allocation"), + new Flag("flag"), + new Variant("variant"), + new Subject("subject", emptyMap()), + 1); + } + + private static void awaitLog(final String text) throws InterruptedException { + final long deadline = System.currentTimeMillis() + AWAIT_MILLIS; + while (messages(text).isEmpty() && System.currentTimeMillis() < deadline) { + Thread.sleep(10); + } + assertFalse(messages(text).isEmpty(), "Missing log: " + text + " in " + messages("")); + } + + /** The events of the pipeline only: other threads of the JVM can log in the same window. */ + private static List pipelineEvents() { + return CapturingServiceProvider.events().stream() + .filter(e -> e.logger.equals(ExposurePipeline.class.getName())) + .collect(Collectors.toList()); + } + + private static List messages(final String text) { + return CapturingServiceProvider.events().stream() + .map(e -> e.message) + .filter(message -> message.contains(text)) + .collect(Collectors.toList()); + } +} diff --git a/dd-openfeature/src/test/java/com/datadog/openfeature/internal/flagevaluation/FlagEvaluationPipelineTest.java b/dd-openfeature/src/test/java/com/datadog/openfeature/internal/flagevaluation/FlagEvaluationPipelineTest.java index 269c37f3b48..f5c3fe5a7c6 100644 --- a/dd-openfeature/src/test/java/com/datadog/openfeature/internal/flagevaluation/FlagEvaluationPipelineTest.java +++ b/dd-openfeature/src/test/java/com/datadog/openfeature/internal/flagevaluation/FlagEvaluationPipelineTest.java @@ -20,13 +20,17 @@ import com.datadog.openfeature.internal.RuntimeServices; import com.datadog.openfeature.internal.flagevaluation.FlagEvaluationTestSupport.CapturingTransport; import com.datadog.openfeature.internal.flagevaluation.FlagEvaluationTestSupport.RecordingMetrics; +import com.datadog.openfeature.testlog.CapturingServiceProvider; import java.util.HashMap; +import java.util.List; import java.util.Map; import java.util.concurrent.ConcurrentHashMap; import java.util.concurrent.CountDownLatch; import java.util.concurrent.TimeUnit; import java.util.concurrent.atomic.AtomicLong; +import java.util.stream.Collectors; import org.junit.jupiter.api.Test; +import org.slf4j.event.Level; class FlagEvaluationPipelineTest { @@ -58,6 +62,31 @@ void degradedCapOverflowTelemetryIsEmittedOnFlush() { "reason:" + FlagEvaluationPipeline.DROP_REASON_DEGRADED_CAP)); } + @Test + void reportsADeliveredFlushAndTheShutdownRequest() { + CapturingServiceProvider.reset(); + CapturingServiceProvider.enable("com.datadog.openfeature", Level.DEBUG); + try { + final FlagEvaluationTestSupport.TestWriterSetup setup = buildTestWriter(); + setup.handler.add(simpleEvent("logged-flag", "on")); + flushAndCapture(setup); + writer(16, Long.MAX_VALUE, TimeUnit.NANOSECONDS).requestShutdown(); + + final List messages = + CapturingServiceProvider.events().stream() + .map(e -> e.message) + .collect(Collectors.toList()); + assertTrue( + messages.contains("Feature Flags flag evaluation flush delivered: payloads=1"), + messages.toString()); + assertTrue( + messages.contains("Feature Flags flag evaluation shutdown requested"), + messages.toString()); + } finally { + CapturingServiceProvider.reset(); + } + } + @Test void queueOverflowIncrementsObservableDropCounter() { final FlagEvaluationPipeline writer = writer(2, 10L, TimeUnit.SECONDS); diff --git a/dd-openfeature/src/test/java/com/datadog/openfeature/testlog/CapturingServiceProvider.java b/dd-openfeature/src/test/java/com/datadog/openfeature/testlog/CapturingServiceProvider.java new file mode 100644 index 00000000000..c1a8bba0e9a --- /dev/null +++ b/dd-openfeature/src/test/java/com/datadog/openfeature/testlog/CapturingServiceProvider.java @@ -0,0 +1,208 @@ +package com.datadog.openfeature.testlog; + +import java.util.List; +import java.util.Map; +import java.util.concurrent.ConcurrentHashMap; +import java.util.concurrent.ConcurrentMap; +import java.util.concurrent.CopyOnWriteArrayList; +import org.slf4j.ILoggerFactory; +import org.slf4j.IMarkerFactory; +import org.slf4j.Marker; +import org.slf4j.event.Level; +import org.slf4j.helpers.AbstractLogger; +import org.slf4j.helpers.BasicMarkerFactory; +import org.slf4j.helpers.MessageFormatter; +import org.slf4j.helpers.NOPMDCAdapter; +import org.slf4j.spi.MDCAdapter; +import org.slf4j.spi.SLF4JServiceProvider; + +/** + * Test SLF4J provider that captures log events. The module has no SLF4J 2 compatible logging + * backend, so this one lets tests assert diagnostics. Nothing is enabled or captured until a test + * calls {@link #enable(String, Level)}, which keeps the other tests as quiet as without a backend. + */ +public final class CapturingServiceProvider implements SLF4JServiceProvider { + private static final ConcurrentMap LEVELS = new ConcurrentHashMap<>(); + private static final List EVENTS = new CopyOnWriteArrayList<>(); + private static volatile String failOn; + + /** A captured log event. */ + public static final class Event { + public final String logger; + public final Level level; + public final String message; + public final Throwable throwable; + + Event(final String logger, final Level level, final String message, final Throwable throwable) { + this.logger = logger; + this.level = level; + this.message = message; + this.throwable = throwable; + } + + @Override + public String toString() { + return level + " " + logger + ": " + message; + } + } + + private final ILoggerFactory loggerFactory = name -> new CapturingLogger(name); + private final IMarkerFactory markerFactory = new BasicMarkerFactory(); + private final MDCAdapter mdcAdapter = new NOPMDCAdapter(); + + /** + * Enables a level and captures the events of the loggers whose name starts with the prefix. The + * longest matching prefix decides. + * + * @param prefix the logger name prefix. + * @param level the lowest enabled level, or {@code null} to disable the prefix. + */ + public static void enable(final String prefix, final Level level) { + if (level == null) { + LEVELS.remove(prefix); + } else { + LEVELS.put(prefix, level); + } + } + + /** + * Makes the logging calls throw, as a failing logging backend would: an enabled event whose + * message contains the text is captured, then the logging call throws. + * + * @param text the text of the messages that fail, or {@code null} to stop failing. + */ + public static void failOn(final String text) { + failOn = text; + } + + /** Disables every logger, stops the failures and forgets the captured events. */ + public static void reset() { + LEVELS.clear(); + EVENTS.clear(); + failOn = null; + } + + /** + * @return the captured events, oldest first. + */ + public static List events() { + return EVENTS; + } + + @Override + public ILoggerFactory getLoggerFactory() { + return this.loggerFactory; + } + + @Override + public IMarkerFactory getMarkerFactory() { + return this.markerFactory; + } + + @Override + public MDCAdapter getMDCAdapter() { + return this.mdcAdapter; + } + + @Override + public String getRequestedApiVersion() { + return "2.0.99"; + } + + @Override + public void initialize() {} + + private static final class CapturingLogger extends AbstractLogger { + private static final long serialVersionUID = 1L; + + CapturingLogger(final String name) { + this.name = name; + } + + private boolean isEnabled(final Level level) { + // Read the entries once: a test can reset the levels while a worker thread is logging. + String best = null; + Level threshold = null; + for (final Map.Entry entry : LEVELS.entrySet()) { + final String prefix = entry.getKey(); + if (name.startsWith(prefix) && (best == null || prefix.length() > best.length())) { + best = prefix; + threshold = entry.getValue(); + } + } + return threshold != null && level.toInt() >= threshold.toInt(); + } + + @Override + public boolean isTraceEnabled() { + return isEnabled(Level.TRACE); + } + + @Override + public boolean isTraceEnabled(final Marker marker) { + return isTraceEnabled(); + } + + @Override + public boolean isDebugEnabled() { + return isEnabled(Level.DEBUG); + } + + @Override + public boolean isDebugEnabled(final Marker marker) { + return isDebugEnabled(); + } + + @Override + public boolean isInfoEnabled() { + return isEnabled(Level.INFO); + } + + @Override + public boolean isInfoEnabled(final Marker marker) { + return isInfoEnabled(); + } + + @Override + public boolean isWarnEnabled() { + return isEnabled(Level.WARN); + } + + @Override + public boolean isWarnEnabled(final Marker marker) { + return isWarnEnabled(); + } + + @Override + public boolean isErrorEnabled() { + return isEnabled(Level.ERROR); + } + + @Override + public boolean isErrorEnabled(final Marker marker) { + return isErrorEnabled(); + } + + @Override + protected String getFullyQualifiedCallerName() { + return null; + } + + @Override + protected void handleNormalizedLoggingCall( + final Level level, + final Marker marker, + final String messagePattern, + final Object[] arguments, + final Throwable throwable) { + if (isEnabled(level)) { + final String message = MessageFormatter.arrayFormat(messagePattern, arguments).getMessage(); + EVENTS.add(new Event(this.name, level, message, throwable)); + final String failing = failOn; + if (failing != null && message.contains(failing)) { + throw new IllegalStateException("The logging backend failed on: " + message); + } + } + } + } +} diff --git a/dd-openfeature/src/test/resources/META-INF/services/org.slf4j.spi.SLF4JServiceProvider b/dd-openfeature/src/test/resources/META-INF/services/org.slf4j.spi.SLF4JServiceProvider new file mode 100644 index 00000000000..4b23d4ccf4a --- /dev/null +++ b/dd-openfeature/src/test/resources/META-INF/services/org.slf4j.spi.SLF4JServiceProvider @@ -0,0 +1 @@ +com.datadog.openfeature.testlog.CapturingServiceProvider From 03eb4e0783cda4febf201223bf39120b40d3ee84 Mon Sep 17 00:00:00 2001 From: "ethan.romero" Date: Tue, 27 Oct 2026 20:20:14 +0000 Subject: [PATCH 2/4] Log the endpoint origin only and the shutdown after the cleanup Address the review of the SDK diagnostics. Log only the scheme, host and port of the agentless endpoint when the configuration source starts. The path of a custom base URL can carry a credential, as its userinfo and query can. Log that the provider shut down after its cleanup, so that a failing logging backend cannot keep the metrics and the evaluator from being shut down. Environment: Datadog workspace Co-Authored-By: Claude Sonnet 5.5 --- .../com/datadog/openfeature/Provider.java | 3 ++- .../delivery/CdnConfigurationSource.java | 5 +++-- .../datadog/openfeature/DebugLoggingTest.java | 21 ++++++++++++++++++- .../delivery/DeliveryDiagnosticsTest.java | 7 ++++--- 4 files changed, 29 insertions(+), 7 deletions(-) diff --git a/dd-openfeature/src/main/java/com/datadog/openfeature/Provider.java b/dd-openfeature/src/main/java/com/datadog/openfeature/Provider.java index 3ea8a364b21..3fbc11260d6 100644 --- a/dd-openfeature/src/main/java/com/datadog/openfeature/Provider.java +++ b/dd-openfeature/src/main/java/com/datadog/openfeature/Provider.java @@ -294,7 +294,6 @@ public List getProviderHooks() { @Override public void shutdown() { - log.debug("Feature Flagging provider shutting down"); if (flagEvalMetrics != null) { flagEvalMetrics.shutdown(); } @@ -302,6 +301,8 @@ public void shutdown() { if (evaluator != null) { evaluator.shutdown(); } + // Logged last: a diagnostic must not get in the way of the cleanup. + log.debug("Feature Flagging provider shut down"); } // Visible for tests: expose whether span enrichment is wired (gate-on) without leaking the impl. diff --git a/dd-openfeature/src/main/java/com/datadog/openfeature/internal/delivery/CdnConfigurationSource.java b/dd-openfeature/src/main/java/com/datadog/openfeature/internal/delivery/CdnConfigurationSource.java index e39ec9ee015..62e38039668 100644 --- a/dd-openfeature/src/main/java/com/datadog/openfeature/internal/delivery/CdnConfigurationSource.java +++ b/dd-openfeature/src/main/java/com/datadog/openfeature/internal/delivery/CdnConfigurationSource.java @@ -110,11 +110,12 @@ public void start(final Consumer listener) { this.listener = listener; } LOGGER.debug( - "Feature Flags starting agentless configuration source: endpoint={}://{}{}{}, pollIntervalMillis={}, requestTimeout={}", + "Feature Flags starting agentless configuration source: endpoint={}://{}{}, pollIntervalMillis={}, requestTimeout={}", + // The origin only: the userinfo, the path and the query of a custom endpoint can carry a + // credential. this.endpoint.getScheme(), this.endpoint.getHost(), this.endpoint.getPort() < 0 ? "" : ":" + this.endpoint.getPort(), - this.endpoint.getRawPath(), this.pollIntervalMillis, this.requestTimeout); // Complete the first poll cycle on the calling thread so provider initialization observes a diff --git a/dd-openfeature/src/test/java/com/datadog/openfeature/DebugLoggingTest.java b/dd-openfeature/src/test/java/com/datadog/openfeature/DebugLoggingTest.java index e700846689c..ce71caea424 100644 --- a/dd-openfeature/src/test/java/com/datadog/openfeature/DebugLoggingTest.java +++ b/dd-openfeature/src/test/java/com/datadog/openfeature/DebugLoggingTest.java @@ -490,7 +490,26 @@ void logsTheProviderLifecycle() throws Exception { assertEquals(1, messages("Feature Flagging provider initializing").size()); assertFalse(messages("Feature Flagging provider ready").isEmpty()); - assertFalse(messages("Feature Flagging provider shutting down").isEmpty()); + assertFalse(messages("Feature Flagging provider shut down").isEmpty()); + } + + @Test + void shuttingDownDoesNotDependOnTheLoggingBackend() { + final boolean[] evaluatorShutDown = {false}; + final ExposureTestEvaluator evaluator = + new ExposureTestEvaluator(configuration(), true) { + @Override + public synchronized void shutdown() { + super.shutdown(); + evaluatorShutDown[0] = true; + } + }; + final Provider provider = new Provider(new Options(), evaluator); + CapturingServiceProvider.failOn("provider shut down"); + + assertThrows(IllegalStateException.class, provider::shutdown); + + assertTrue(evaluatorShutDown[0], "The cleanup must not wait for the log"); } @Test diff --git a/dd-openfeature/src/test/java/com/datadog/openfeature/internal/delivery/DeliveryDiagnosticsTest.java b/dd-openfeature/src/test/java/com/datadog/openfeature/internal/delivery/DeliveryDiagnosticsTest.java index c4f9d3be39b..a3c7506c89e 100644 --- a/dd-openfeature/src/test/java/com/datadog/openfeature/internal/delivery/DeliveryDiagnosticsTest.java +++ b/dd-openfeature/src/test/java/com/datadog/openfeature/internal/delivery/DeliveryDiagnosticsTest.java @@ -105,7 +105,7 @@ void agentlessReportsItsLifecycleWithoutQueryOrCredentials() { final String starting = logged("starting agentless configuration source"); assertTrue(starting.contains("pollIntervalMillis=30000"), starting); - assertTrue(starting.contains("/ufc,"), starting); + assertFalse(starting.contains("/ufc"), starting); assertFalse(starting.contains("secret"), starting); assertFalse(starting.contains("token"), starting); assertFalse(starting.contains("hidden"), starting); @@ -113,7 +113,7 @@ void agentlessReportsItsLifecycleWithoutQueryOrCredentials() { } @Test - void agentlessDoesNotReportTheUserInfoOfTheEndpoint() { + void agentlessReportsTheOriginOfTheEndpointOnly() { final URI server = this.server.uri("/ufc?token=hidden"); final URI endpoint = URI.create( @@ -121,7 +121,7 @@ void agentlessDoesNotReportTheUserInfoOfTheEndpoint() { + server.getHost() + ":" + server.getPort() - + "/ufc?token=hidden"); + + "/path-secret/ufc?token=hidden"); this.server.enqueue(200, CONFIG); final CdnConfigurationSource source = source(endpoint, null); @@ -132,6 +132,7 @@ void agentlessDoesNotReportTheUserInfoOfTheEndpoint() { assertTrue(starting.contains("http://" + server.getHost() + ":" + server.getPort()), starting); assertFalse(starting.contains("user"), starting); assertFalse(starting.contains("s3cret"), starting); + assertFalse(starting.contains("path-secret"), starting); assertFalse(starting.contains("hidden"), starting); } From a105bfd95c79b1730c88cc06fb8773bfdc374e8a Mon Sep 17 00:00:00 2001 From: "ethan.romero" Date: Tue, 27 Oct 2026 21:20:03 +0000 Subject: [PATCH 3/4] Log the lifecycle diagnostics after the work they describe A debug log that ran after a state flag was set but before the work it describes could, with a failing logging backend, skip that work, and the flag then kept it from being retried. Log after the work instead: - apply a configuration, or its removal, and notify the listeners before logging it; - signal the exposure and flag evaluation workers before logging the shutdown request; - cancel the polling and shut the executor down before logging that the agentless source stopped; - log that the agentless source started after its first poll and the scheduling of the next ones. The provider lifecycle logs cannot be moved after their work without restructuring the initialization, so they are contained instead: a log that fails no longer turns a successful initialization into an error or skips an event. Each path has a test that makes the logging backend throw and checks the work still happened. Add a test accessor to the flag evaluation pipeline, like the exposure pipeline has. Environment: Datadog workspace Co-Authored-By: Claude Sonnet 5.5 --- .../com/datadog/openfeature/Provider.java | 31 ++++++++----- .../internal/FeatureFlagsRuntime.java | 21 ++++----- .../delivery/CdnConfigurationSource.java | 22 +++++----- .../internal/exposure/ExposurePipeline.java | 6 ++- .../FlagEvaluationPipeline.java | 7 ++- .../datadog/openfeature/DebugLoggingTest.java | 10 +++++ .../internal/FeatureFlagsRuntimeTest.java | 28 ++++++++++++ .../delivery/DeliveryDiagnosticsTest.java | 43 +++++++++++++++++-- .../ExposurePipelineDiagnosticsTest.java | 13 ++++++ .../FlagEvaluationPipelineTest.java | 18 ++++++++ 10 files changed, 162 insertions(+), 37 deletions(-) diff --git a/dd-openfeature/src/main/java/com/datadog/openfeature/Provider.java b/dd-openfeature/src/main/java/com/datadog/openfeature/Provider.java index 3fbc11260d6..70ac3436b8c 100644 --- a/dd-openfeature/src/main/java/com/datadog/openfeature/Provider.java +++ b/dd-openfeature/src/main/java/com/datadog/openfeature/Provider.java @@ -150,7 +150,7 @@ public Provider(final Options options) { @Override public void initialize(final EvaluationContext context) throws Exception { initializationState.set(InitializationState.INITIALIZING); - log.debug( + debug( "Feature Flagging provider initializing: timeout={} {}", options.getTimeout(), options.getUnit()); @@ -158,22 +158,21 @@ public void initialize(final EvaluationContext context) throws Exception { evaluator = buildEvaluator(); if (!evaluator.initialize(options.getTimeout(), options.getUnit(), context)) { if (markInitialConfigReceivedReady()) { - log.debug( - "Feature Flagging provider ready: configuration received during initialization"); + debug("Feature Flagging provider ready: configuration received during initialization"); return; } markInitializationError(); - log.debug("Feature Flagging provider initialization timed out waiting for configuration"); + debug("Feature Flagging provider initialization timed out waiting for configuration"); throw new ProviderNotReadyError( "Provider timed-out while waiting for initial configuration"); } if (!evaluator.hasConfiguration() || !markSuccessfulInitializationReady()) { markInitializationError(); - log.debug("Feature Flagging provider initialization timed out waiting for configuration"); + debug("Feature Flagging provider initialization timed out waiting for configuration"); throw new ProviderNotReadyError( "Provider timed-out while waiting for initial configuration"); } - log.debug("Feature Flagging provider ready"); + debug("Feature Flagging provider ready"); } catch (final RemoteConfigurationUnavailableException e) { // No RC connector means no configuration can arrive in this JVM. Complete registration // without waiting or switching sources. The evaluator has no runtime/configuration and @@ -188,12 +187,24 @@ public void initialize(final EvaluationContext context) throws Exception { } catch (final Throwable e) { markInitializationError(); // Only the type: the message of a configuration error can echo a URL with credentials. - log.debug("Feature Flagging provider initialization failed: {}", e.getClass().getName()); + debug("Feature Flagging provider initialization failed: {}", e.getClass().getName()); throw new FatalError( "Failed to initialize Datadog Feature Flags provider: " + e.getMessage(), e); } } + /** + * Logs a lifecycle diagnostic. A failing logging backend must not turn a state change into a + * failure, such as a successful initialization into an error. + */ + private static void debug(final String message, final Object... arguments) { + try { + log.debug(message, arguments); + } catch (final RuntimeException | LinkageError ignored) { + // Nothing more can be done. + } + } + void onConfigurationChange() { if (evaluator == null || !evaluator.hasConfiguration()) { onConfigurationUnavailable(); @@ -212,7 +223,7 @@ void onConfigurationChange() { if (state == InitializationState.ERROR && initializationState.compareAndSet( InitializationState.ERROR, InitializationState.READY)) { - log.debug("Feature Flagging provider recovered: configuration received after an error"); + debug("Feature Flagging provider recovered: configuration received after an error"); emit( ProviderEvent.PROVIDER_READY, ProviderEventDetails.builder().message("Provider ready").build()); @@ -221,7 +232,7 @@ void onConfigurationChange() { if (initializationState.get() != InitializationState.READY) { return; } - log.debug("Feature Flagging provider configuration changed"); + debug("Feature Flagging provider configuration changed"); emit( ProviderEvent.PROVIDER_CONFIGURATION_CHANGED, ProviderEventDetails.builder().message("New configuration received").build()); @@ -235,7 +246,7 @@ private void onConfigurationUnavailable() { if (!initializationState.compareAndSet(InitializationState.READY, InitializationState.ERROR)) { return; } - log.debug("Feature Flagging provider configuration unavailable; evaluations return defaults"); + debug("Feature Flagging provider configuration unavailable; evaluations return defaults"); emit( ProviderEvent.PROVIDER_ERROR, ProviderEventDetails.builder() diff --git a/dd-openfeature/src/main/java/com/datadog/openfeature/internal/FeatureFlagsRuntime.java b/dd-openfeature/src/main/java/com/datadog/openfeature/internal/FeatureFlagsRuntime.java index e2cd9536c34..b06f5386133 100644 --- a/dd-openfeature/src/main/java/com/datadog/openfeature/internal/FeatureFlagsRuntime.java +++ b/dd-openfeature/src/main/java/com/datadog/openfeature/internal/FeatureFlagsRuntime.java @@ -267,16 +267,6 @@ void stop() { } private void onConfiguration(@Nullable final ServerConfiguration configuration) { - if (configuration == null) { - LOGGER.debug("Feature Flags configuration removed"); - } else if (LOGGER.isDebugEnabled()) { - LOGGER.debug( - "Feature Flags configuration applied: flags={}, invalidFlags={}, configurationEnv={}, createdAt={}", - configuration.flags == null ? "missing" : configuration.flags.size(), - configuration.invalidFlags == null ? 0 : configuration.invalidFlags.size(), - configuration.environment == null ? null : configuration.environment.name, - configuration.createdAt); - } final Iterator> snapshot; synchronized (this.listeners) { this.configuration = configuration; @@ -290,6 +280,17 @@ private void onConfiguration(@Nullable final ServerConfiguration configuration) LOGGER.warn("Feature Flags configuration listener failed", e); } } + // Logged last: a diagnostic must not keep the configuration from being applied. + if (configuration == null) { + LOGGER.debug("Feature Flags configuration removed"); + } else if (LOGGER.isDebugEnabled()) { + LOGGER.debug( + "Feature Flags configuration applied: flags={}, invalidFlags={}, configurationEnv={}, createdAt={}", + configuration.flags == null ? "missing" : configuration.flags.size(), + configuration.invalidFlags == null ? 0 : configuration.invalidFlags.size(), + configuration.environment == null ? null : configuration.environment.name, + configuration.createdAt); + } } /** diff --git a/dd-openfeature/src/main/java/com/datadog/openfeature/internal/delivery/CdnConfigurationSource.java b/dd-openfeature/src/main/java/com/datadog/openfeature/internal/delivery/CdnConfigurationSource.java index 62e38039668..7eed50bb8d2 100644 --- a/dd-openfeature/src/main/java/com/datadog/openfeature/internal/delivery/CdnConfigurationSource.java +++ b/dd-openfeature/src/main/java/com/datadog/openfeature/internal/delivery/CdnConfigurationSource.java @@ -109,15 +109,6 @@ public void start(final Consumer listener) { this.started = true; this.listener = listener; } - LOGGER.debug( - "Feature Flags starting agentless configuration source: endpoint={}://{}{}, pollIntervalMillis={}, requestTimeout={}", - // The origin only: the userinfo, the path and the query of a custom endpoint can carry a - // credential. - this.endpoint.getScheme(), - this.endpoint.getHost(), - this.endpoint.getPort() < 0 ? "" : ":" + this.endpoint.getPort(), - this.pollIntervalMillis, - this.requestTimeout); // Complete the first poll cycle on the calling thread so provider initialization observes a // successful retry before it checks whether configuration is ready. pollOnceSafely(); @@ -131,6 +122,16 @@ public void start(final Consumer listener) { TimeUnit.MILLISECONDS); } } + // Logged last: a diagnostic must not keep the polling from starting. + LOGGER.debug( + "Feature Flags agentless configuration source started: endpoint={}://{}{}, pollIntervalMillis={}, requestTimeout={}", + // The origin only: the userinfo, the path and the query of a custom endpoint can carry a + // credential. + this.endpoint.getScheme(), + this.endpoint.getHost(), + this.endpoint.getPort() < 0 ? "" : ":" + this.endpoint.getPort(), + this.pollIntervalMillis, + this.requestTimeout); } @Override @@ -147,7 +148,6 @@ public void close() { call = this.activeCall; this.activeCall = null; } - LOGGER.debug("Feature Flags agentless configuration source stopping"); this.closedSignal.countDown(); if (call != null) { call.cancel(); @@ -156,6 +156,8 @@ public void close() { poll.cancel(true); } this.executor.shutdownNow(); + // Logged last: a diagnostic must not keep the source from being closed. + LOGGER.debug("Feature Flags agentless configuration source stopped"); } /** Test seam: sets the configuration listener without starting the polling. */ diff --git a/dd-openfeature/src/main/java/com/datadog/openfeature/internal/exposure/ExposurePipeline.java b/dd-openfeature/src/main/java/com/datadog/openfeature/internal/exposure/ExposurePipeline.java index 4c758b5f276..829d74f77d7 100644 --- a/dd-openfeature/src/main/java/com/datadog/openfeature/internal/exposure/ExposurePipeline.java +++ b/dd-openfeature/src/main/java/com/datadog/openfeature/internal/exposure/ExposurePipeline.java @@ -59,10 +59,12 @@ public void start() { public void requestShutdown() { synchronized (this.lifecycleLock) { if (this.closed.compareAndSet(false, true)) { + final int queued = this.queue.size(); + this.serializer.requestShutdown(); + // Logged last: a diagnostic must not keep the worker from being signaled. LOGGER.debug( "Feature Flags exposure shutdown requested: queued={}; pending exposures get a final best-effort flush", - this.queue.size()); - this.serializer.requestShutdown(); + queued); } } } diff --git a/dd-openfeature/src/main/java/com/datadog/openfeature/internal/flagevaluation/FlagEvaluationPipeline.java b/dd-openfeature/src/main/java/com/datadog/openfeature/internal/flagevaluation/FlagEvaluationPipeline.java index 5df53cb2c98..af4dfaa2ca3 100644 --- a/dd-openfeature/src/main/java/com/datadog/openfeature/internal/flagevaluation/FlagEvaluationPipeline.java +++ b/dd-openfeature/src/main/java/com/datadog/openfeature/internal/flagevaluation/FlagEvaluationPipeline.java @@ -128,9 +128,10 @@ int aggregatorFullTierSizeForTest() { public void requestShutdown() { synchronized (lifecycleLock) { if (closed.compareAndSet(false, true)) { - LOGGER.debug("Feature Flags flag evaluation shutdown requested"); // The worker polls every 100 ms: do not interrupt a current or final HTTP request. serializer.requestShutdown(); + // Logged last: a diagnostic must not keep the worker from being signaled. + LOGGER.debug("Feature Flags flag evaluation shutdown requested"); } } } @@ -221,6 +222,10 @@ FlagEvalEvent pollQueuedEventForTest() { return queue.poll(); } + boolean isSerializerThreadAlive() { + return serializerThread.isAlive(); + } + /** Test seam: flushes serializer state without starting the worker. */ void flushForTest() { serializer.flush(); diff --git a/dd-openfeature/src/test/java/com/datadog/openfeature/DebugLoggingTest.java b/dd-openfeature/src/test/java/com/datadog/openfeature/DebugLoggingTest.java index ce71caea424..c45b47b40b0 100644 --- a/dd-openfeature/src/test/java/com/datadog/openfeature/DebugLoggingTest.java +++ b/dd-openfeature/src/test/java/com/datadog/openfeature/DebugLoggingTest.java @@ -493,6 +493,16 @@ void logsTheProviderLifecycle() throws Exception { assertFalse(messages("Feature Flagging provider shut down").isEmpty()); } + @Test + void initializesWhenTheReadyLogFails() throws Exception { + CapturingServiceProvider.failOn("Feature Flagging provider ready"); + + final Client client = register(); + + // The registration did not fail, and the provider evaluates. + assertEquals(1, client.getIntegerValue("flag", 5, new MutableContext("user-1"))); + } + @Test void shuttingDownDoesNotDependOnTheLoggingBackend() { final boolean[] evaluatorShutDown = {false}; diff --git a/dd-openfeature/src/test/java/com/datadog/openfeature/internal/FeatureFlagsRuntimeTest.java b/dd-openfeature/src/test/java/com/datadog/openfeature/internal/FeatureFlagsRuntimeTest.java index 78d21300099..f6924b3b4a9 100644 --- a/dd-openfeature/src/test/java/com/datadog/openfeature/internal/FeatureFlagsRuntimeTest.java +++ b/dd-openfeature/src/test/java/com/datadog/openfeature/internal/FeatureFlagsRuntimeTest.java @@ -168,6 +168,34 @@ void stoppingDoesNotDependOnTheLoggingBackend() { assertTrue(source.closed); } + @Test + void appliesConfigurationsWhenTheirLogFails() { + CapturingServiceProvider.enable("com.datadog.openfeature", Level.DEBUG); + CapturingServiceProvider.failOn("Feature Flags configuration"); + final TestConfigurationSource source = new TestConfigurationSource(); + final FeatureFlagsRuntime runtime = + FeatureFlagsRuntime.create( + new TestAgentBridge(source, null), + TestSettings.of("feature.flags.configuration.source", "remote_config")); + final List received = new CopyOnWriteArrayList<>(); + runtime.addConfigurationListener(received::add); + runtime.start(); + try { + assertThrows(IllegalStateException.class, () -> source.listener.accept(EMPTY_UFC)); + assertEquals(1, received.size(), "The listener must not wait for the log"); + assertThrows(IllegalStateException.class, () -> source.listener.accept(null)); + assertEquals(2, received.size(), "The removal must not wait for the log"); + assertNull(received.get(1)); + + final List late = new CopyOnWriteArrayList<>(); + runtime.addConfigurationListener(late::add); + assertTrue(late.isEmpty(), "The removed configuration is still the current one"); + } finally { + CapturingServiceProvider.reset(); + runtime.stop(); + } + } + @Test void reportsAppliedAndRemovedConfigurations() { CapturingServiceProvider.enable("com.datadog.openfeature", Level.DEBUG); diff --git a/dd-openfeature/src/test/java/com/datadog/openfeature/internal/delivery/DeliveryDiagnosticsTest.java b/dd-openfeature/src/test/java/com/datadog/openfeature/internal/delivery/DeliveryDiagnosticsTest.java index a3c7506c89e..d8e8e46abf3 100644 --- a/dd-openfeature/src/test/java/com/datadog/openfeature/internal/delivery/DeliveryDiagnosticsTest.java +++ b/dd-openfeature/src/test/java/com/datadog/openfeature/internal/delivery/DeliveryDiagnosticsTest.java @@ -1,11 +1,16 @@ package com.datadog.openfeature.internal.delivery; import static java.nio.charset.StandardCharsets.UTF_8; +import static java.util.concurrent.TimeUnit.MILLISECONDS; import static org.junit.jupiter.api.Assertions.assertEquals; import static org.junit.jupiter.api.Assertions.assertFalse; import static org.junit.jupiter.api.Assertions.assertNull; +import static org.junit.jupiter.api.Assertions.assertThrows; import static org.junit.jupiter.api.Assertions.assertTrue; +import static org.mockito.ArgumentMatchers.any; +import static org.mockito.ArgumentMatchers.eq; import static org.mockito.Mockito.mock; +import static org.mockito.Mockito.verify; import com.datadog.openfeature.internal.LocalHttpServer; import com.datadog.openfeature.internal.bridge.v1.ConfigurationSource; @@ -103,13 +108,38 @@ void agentlessReportsItsLifecycleWithoutQueryOrCredentials() { source.start(configuration -> {}); source.close(); - final String starting = logged("starting agentless configuration source"); + final String starting = logged("agentless configuration source started"); assertTrue(starting.contains("pollIntervalMillis=30000"), starting); assertFalse(starting.contains("/ufc"), starting); assertFalse(starting.contains("secret"), starting); assertFalse(starting.contains("token"), starting); assertFalse(starting.contains("hidden"), starting); - assertLogged("agentless configuration source stopping"); + assertLogged("agentless configuration source stopped"); + } + + @Test + void agentlessStartsPollingWhenItsLogFails() { + final ScheduledExecutorService executor = mock(ScheduledExecutorService.class); + final CdnConfigurationSource source = source(this.server.uri("/ufc"), null, executor); + this.server.enqueue(200, CONFIG); + CapturingServiceProvider.failOn("agentless configuration source started"); + + assertThrows(IllegalStateException.class, () -> source.start(configuration -> {})); + + assertEquals(1, this.server.requests().size(), "The first poll must not wait for the log"); + verify(executor) + .scheduleWithFixedDelay(any(Runnable.class), eq(30_000L), eq(30_000L), eq(MILLISECONDS)); + } + + @Test + void agentlessClosesWhenItsLogFails() { + final ScheduledExecutorService executor = mock(ScheduledExecutorService.class); + final CdnConfigurationSource source = source(this.server.uri("/ufc"), null, executor); + CapturingServiceProvider.failOn("agentless configuration source stopped"); + + assertThrows(IllegalStateException.class, source::close); + + verify(executor).shutdownNow(); } @Test @@ -128,7 +158,7 @@ void agentlessReportsTheOriginOfTheEndpointOnly() { source.start(configuration -> {}); source.close(); - final String starting = logged("starting agentless configuration source"); + final String starting = logged("agentless configuration source started"); assertTrue(starting.contains("http://" + server.getHost() + ":" + server.getPort()), starting); assertFalse(starting.contains("user"), starting); assertFalse(starting.contains("s3cret"), starting); @@ -159,6 +189,11 @@ private CdnConfigurationSource source(final String apiKey) { } private CdnConfigurationSource source(final URI endpoint, final String apiKey) { + return source(endpoint, apiKey, mock(ScheduledExecutorService.class)); + } + + private CdnConfigurationSource source( + final URI endpoint, final String apiKey, final ScheduledExecutorService executor) { final CdnConfigurationSource source = new CdnConfigurationSource( endpoint, @@ -166,7 +201,7 @@ private CdnConfigurationSource source(final URI endpoint, final String apiKey) { 30_000, Duration.ofSeconds(5), HttpClient.newHttpClient(), - mock(ScheduledExecutorService.class), + executor, delay -> {}, () -> 1.0); source.setListenerForTest(new CopyOnWriteArrayList()::add); diff --git a/dd-openfeature/src/test/java/com/datadog/openfeature/internal/exposure/ExposurePipelineDiagnosticsTest.java b/dd-openfeature/src/test/java/com/datadog/openfeature/internal/exposure/ExposurePipelineDiagnosticsTest.java index 0afeeb286d9..98343ea2fbe 100644 --- a/dd-openfeature/src/test/java/com/datadog/openfeature/internal/exposure/ExposurePipelineDiagnosticsTest.java +++ b/dd-openfeature/src/test/java/com/datadog/openfeature/internal/exposure/ExposurePipelineDiagnosticsTest.java @@ -5,6 +5,7 @@ import static java.util.concurrent.TimeUnit.SECONDS; import static org.junit.jupiter.api.Assertions.assertEquals; import static org.junit.jupiter.api.Assertions.assertFalse; +import static org.junit.jupiter.api.Assertions.assertThrows; import com.datadog.openfeature.internal.RuntimeServices; import com.datadog.openfeature.internal.bridge.v1.EventTransport; @@ -65,6 +66,18 @@ void reportsTheShutdownRequestWithoutLoggingEachExposure() { assertEquals(1, messages("exposure shutdown requested: queued=1").size()); } + @Test + void signalsTheWorkerWhenTheShutdownLogFails() { + final ExposurePipeline pipeline = pipeline(16, (route, json) -> {}); + pipeline.start(); + CapturingServiceProvider.failOn("exposure shutdown requested"); + + assertThrows(IllegalStateException.class, pipeline::requestShutdown); + + pipeline.awaitTermination(System.nanoTime() + SECONDS.toNanos(5)); + assertFalse(pipeline.isSerializerThreadAlive(), "The worker was not signaled"); + } + @Test void reportsADeliveredFlush() throws Exception { final ExposurePipeline pipeline = pipeline(16, (route, json) -> {}); diff --git a/dd-openfeature/src/test/java/com/datadog/openfeature/internal/flagevaluation/FlagEvaluationPipelineTest.java b/dd-openfeature/src/test/java/com/datadog/openfeature/internal/flagevaluation/FlagEvaluationPipelineTest.java index f5c3fe5a7c6..433e8e26135 100644 --- a/dd-openfeature/src/test/java/com/datadog/openfeature/internal/flagevaluation/FlagEvaluationPipelineTest.java +++ b/dd-openfeature/src/test/java/com/datadog/openfeature/internal/flagevaluation/FlagEvaluationPipelineTest.java @@ -14,6 +14,7 @@ import static org.junit.jupiter.api.Assertions.assertFalse; import static org.junit.jupiter.api.Assertions.assertNotNull; import static org.junit.jupiter.api.Assertions.assertNull; +import static org.junit.jupiter.api.Assertions.assertThrows; import static org.junit.jupiter.api.Assertions.assertTrue; import com.datadog.openfeature.internal.EventQueue; @@ -87,6 +88,23 @@ void reportsADeliveredFlushAndTheShutdownRequest() { } } + @Test + void signalsTheWorkerWhenTheShutdownLogFails() { + CapturingServiceProvider.reset(); + CapturingServiceProvider.enable("com.datadog.openfeature", Level.DEBUG); + CapturingServiceProvider.failOn("flag evaluation shutdown requested"); + final FlagEvaluationPipeline writer = writer(16, 10L, TimeUnit.SECONDS); + writer.start(); + try { + assertThrows(IllegalStateException.class, writer::requestShutdown); + + writer.awaitTermination(System.nanoTime() + TimeUnit.SECONDS.toNanos(5)); + assertFalse(writer.isSerializerThreadAlive(), "The worker was not signaled"); + } finally { + CapturingServiceProvider.reset(); + } + } + @Test void queueOverflowIncrementsObservableDropCounter() { final FlagEvaluationPipeline writer = writer(2, 10L, TimeUnit.SECONDS); From a244377cabafedd7c936146eab1257c5e5642585 Mon Sep 17 00:00:00 2001 From: "ethan.romero" Date: Wed, 28 Oct 2026 15:26:23 +0000 Subject: [PATCH 4/4] Render structures through their unmodifiable map view The debug renderer read a Structure through keySet() and getValue(). For an immutable structure these copy every key and deep-clone the value, so the whole context was copied before the budget applied. Walk asUnmodifiableMap() instead, and cover immutable contexts. Environment: Datadog workspace Co-Authored-By: Claude Opus 5.5 --- .../datadog/openfeature/DebugLoggingHook.java | 52 ++++++++----------- .../datadog/openfeature/DebugLoggingTest.java | 33 +++++++++++- 2 files changed, 53 insertions(+), 32 deletions(-) diff --git a/dd-openfeature/src/main/java/com/datadog/openfeature/DebugLoggingHook.java b/dd-openfeature/src/main/java/com/datadog/openfeature/DebugLoggingHook.java index 8d11bb259b0..94f88109e80 100644 --- a/dd-openfeature/src/main/java/com/datadog/openfeature/DebugLoggingHook.java +++ b/dd-openfeature/src/main/java/com/datadog/openfeature/DebugLoggingHook.java @@ -181,38 +181,10 @@ private void writeContainer(final Object container, final int depth) { if (container instanceof Value) { writeValue((Value) container, depth); } else if (container instanceof Structure) { - final Structure structure = (Structure) container; - text("{"); - boolean first = true; - for (final String key : structure.keySet()) { - if (this.truncated) { - break; - } - if (!first) { - text(", "); - } - first = false; - text(String.valueOf(key)); - text("="); - write(structure.getValue(key), depth + 1); - } - text("}"); + // A view: the keys and values of an immutable structure are copied on each access. + writeEntries(((Structure) container).asUnmodifiableMap(), depth); } else if (container instanceof Map) { - text("{"); - boolean first = true; - for (final Map.Entry entry : ((Map) container).entrySet()) { - if (this.truncated) { - break; - } - if (!first) { - text(", "); - } - first = false; - write(entry.getKey(), depth + 1); - text("="); - write(entry.getValue(), depth + 1); - } - text("}"); + writeEntries((Map) container, depth); } else { text("["); boolean first = true; @@ -233,6 +205,24 @@ private void writeContainer(final Object container, final int depth) { } } + private void writeEntries(final Map map, final int depth) { + text("{"); + boolean first = true; + for (final Map.Entry entry : map.entrySet()) { + if (this.truncated) { + break; + } + if (!first) { + text(", "); + } + first = false; + write(entry.getKey(), depth + 1); + text("="); + write(entry.getValue(), depth + 1); + } + text("}"); + } + /** * Renders what the value wraps. It does not ask {@code isList()} or {@code asList()}: they * check every element of the list, whatever the budget, and a list holding anything else than diff --git a/dd-openfeature/src/test/java/com/datadog/openfeature/DebugLoggingTest.java b/dd-openfeature/src/test/java/com/datadog/openfeature/DebugLoggingTest.java index c45b47b40b0..e09e14df637 100644 --- a/dd-openfeature/src/test/java/com/datadog/openfeature/DebugLoggingTest.java +++ b/dd-openfeature/src/test/java/com/datadog/openfeature/DebugLoggingTest.java @@ -27,9 +27,11 @@ import dev.openfeature.sdk.FlagEvaluationDetails; import dev.openfeature.sdk.FlagValueType; import dev.openfeature.sdk.HookContext; +import dev.openfeature.sdk.ImmutableContext; import dev.openfeature.sdk.MutableContext; import dev.openfeature.sdk.MutableStructure; import dev.openfeature.sdk.OpenFeatureAPI; +import dev.openfeature.sdk.Structure; import dev.openfeature.sdk.Value; import java.time.Duration; import java.util.AbstractList; @@ -187,7 +189,7 @@ void doesNotAnnounceRawLoggingWithoutTraceDebug() throws Exception { @Test void containsAFailureToFormatTheEvaluation() { final EvaluationContext failing = mock(EvaluationContext.class); - when(failing.keySet()).thenThrow(new IllegalStateException("cannot render")); + when(failing.asUnmodifiableMap()).thenThrow(new IllegalStateException("cannot render")); final HookContext hookContext = HookContext.builder() .flagKey("flag") @@ -397,6 +399,35 @@ void rendersAWideContextWithinTheBudget() { assertTrue(message.length() < 2_000, "Logged " + message.length() + " characters"); } + @Test + void rendersAWideImmutableContextWithinTheBudget() { + final Map attributes = new HashMap<>(); + for (int i = 0; i < 20_000; i++) { + attributes.put("attribute-" + i, new Value("value-" + i)); + } + + final String message = + hookMessage(hookContext(new ImmutableContext("u", attributes), new Value(0)), details()); + + assertTrue(message.contains("...(truncated)"), message); + assertTrue(message.length() < 2_000, "Logged " + message.length() + " characters"); + } + + @Test + void rendersAStructureWithoutCopyingItsKeysOrValues() { + final Map attributes = new HashMap<>(); + attributes.put("plan", new Value("pro")); + final Structure structure = mock(Structure.class); + when(structure.asUnmodifiableMap()).thenReturn(Collections.unmodifiableMap(attributes)); + when(structure.keySet()).thenThrow(new AssertionError("keySet() copies the keys")); + when(structure.getValue("plan")).thenThrow(new AssertionError("getValue() clones the value")); + + final String message = + hookMessage(hookContext(new MutableContext("u"), new Value(structure)), details()); + + assertTrue(message.contains("defaultValue={plan=pro}"), message); + } + @Test void capsTheVariantAndTheReason() { final FlagEvaluationDetails details =