Skip to content

feat: add logging on provider state transitions #1444

New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Merged
merged 6 commits into from
May 14, 2025
Merged
Show file tree
Hide file tree
Changes from all commits
Commits
File filter

Filter by extension

Filter by extension

Conversations
Failed to load comments.
Loading
Jump to
Jump to file
Failed to load files.
Loading
Diff view
Diff view
Original file line number Diff line number Diff line change
Expand Up @@ -2,14 +2,14 @@

import dev.openfeature.sdk.exceptions.OpenFeatureError;
import java.util.concurrent.atomic.AtomicBoolean;
import lombok.Getter;
import java.util.concurrent.atomic.AtomicReference;
import lombok.extern.slf4j.Slf4j;

@Slf4j
class FeatureProviderStateManager implements EventProviderListener {
private final FeatureProvider delegate;
private final AtomicBoolean isInitialized = new AtomicBoolean();

@Getter
private ProviderState state = ProviderState.NOT_READY;
private final AtomicReference<ProviderState> state = new AtomicReference<>(ProviderState.NOT_READY);

public FeatureProviderStateManager(FeatureProvider delegate) {
this.delegate = delegate;
Expand All @@ -24,43 +24,60 @@ public void initialize(EvaluationContext evaluationContext) throws Exception {
}
try {
delegate.initialize(evaluationContext);
state = ProviderState.READY;
setState(ProviderState.READY);
} catch (OpenFeatureError openFeatureError) {
if (ErrorCode.PROVIDER_FATAL.equals(openFeatureError.getErrorCode())) {
state = ProviderState.FATAL;
setState(ProviderState.FATAL);
} else {
state = ProviderState.ERROR;
setState(ProviderState.ERROR);
}
isInitialized.set(false);
throw openFeatureError;
} catch (Exception e) {
state = ProviderState.ERROR;
setState(ProviderState.ERROR);
isInitialized.set(false);
throw e;
}
}

public void shutdown() {
delegate.shutdown();
state = ProviderState.NOT_READY;
setState(ProviderState.NOT_READY);
isInitialized.set(false);
}

@Override
public void onEmit(ProviderEvent event, ProviderEventDetails details) {
if (ProviderEvent.PROVIDER_ERROR.equals(event)) {
if (details != null && details.getErrorCode() == ErrorCode.PROVIDER_FATAL) {
state = ProviderState.FATAL;
setState(ProviderState.FATAL);
} else {
state = ProviderState.ERROR;
setState(ProviderState.ERROR);
}
} else if (ProviderEvent.PROVIDER_STALE.equals(event)) {
state = ProviderState.STALE;
setState(ProviderState.STALE);
} else if (ProviderEvent.PROVIDER_READY.equals(event)) {
state = ProviderState.READY;
setState(ProviderState.READY);
}
}

private void setState(ProviderState state) {
ProviderState oldState = this.state.getAndSet(state);
if (oldState != state) {
String providerName;
if (delegate.getMetadata() == null || delegate.getMetadata().getName() == null) {
providerName = "unknown";
} else {
providerName = delegate.getMetadata().getName();
}
log.info("Provider {} transitioned from state {} to state {}", providerName, oldState, state);
Copy link
Member

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

I think this should be a debug log.

Copy link
Member

@toddbaert toddbaert May 13, 2025

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

I understand why you'd say so, and I think I would agree most times, but the point of this change was to get better visibly into state transitions, particularly for when providers become ready again. Because this isn't in a hot code path, I think it might be worthwhile to have at info level. We've seen internally that such a log would be very useful to confirm the provider is back in a good state.

If we make it debug, we'll never see it "after the fact" if logging it set to normal level, so I think it will make troubleshooting things like connection issues harder. I think the chances of spam here are very low in normal situations.

Copy link
Member

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

I am not sure, we need this log all the time. imho I think it is important when we are going from error back to ready - but the other transitions are not as important to see. Stale can happen, we have a gracePeriod, I do not need to know it. but after an error, I need to know when got back to ready

}
}

public ProviderState getState() {
return state.get();
}

FeatureProvider getProvider() {
return delegate;
}
Expand Down
3 changes: 2 additions & 1 deletion src/test/java/dev/openfeature/sdk/OpenFeatureAPITest.java
Original file line number Diff line number Diff line change
Expand Up @@ -5,6 +5,7 @@
import static org.junit.jupiter.api.Assertions.assertEquals;
import static org.mockito.ArgumentMatchers.any;
import static org.mockito.Mockito.mock;
import static org.mockito.Mockito.times;
import static org.mockito.Mockito.verify;

import dev.openfeature.sdk.providers.memory.InMemoryProvider;
Expand Down Expand Up @@ -112,7 +113,7 @@ void featureProviderTrackIsCalled() throws Exception {
api.getClient().track("track-event", new ImmutableContext(), new MutableTrackingEventDetails(22.2f));

verify(featureProvider).initialize(any());
verify(featureProvider).getMetadata();
verify(featureProvider, times(2)).getMetadata();
verify(featureProvider).track(any(), any(), any());
}
}
Loading