Skip to content

Commit 03ba62c

Browse files
author
Mike Davis
authored
(refac): Improve logging levels for common logs. (#300)
* Fix logs leaking in JUnit test due to improper cleanup. * Lower log level for common log output to reduce confusion. * Fix erroneous log where features were reported as enabled and not enabled.
1 parent c955ba9 commit 03ba62c

File tree

6 files changed

+29
-31
lines changed

6 files changed

+29
-31
lines changed

‎core-api/src/main/java/com/optimizely/ab/Optimizely.java

Lines changed: 1 addition & 2 deletions
Original file line numberDiff line numberDiff line change
@@ -411,7 +411,6 @@ public Boolean isFeatureEnabled(@Nonnull String featureKey,
411411
userId, featureKey);
412412
}
413413
if (featureDecision.variation.getFeatureEnabled()) {
414-
logger.info("Feature \"{}\" is enabled for user \"{}\".", featureKey, userId);
415414
featureEnabled = true;
416415
}
417416
}
@@ -427,7 +426,7 @@ public Boolean isFeatureEnabled(@Nonnull String featureKey,
427426

428427
notificationCenter.send(decisionNotification);
429428

430-
logger.info("Feature \"{}\" is not enabled for user \"{}\".", featureKey, userId);
429+
logger.info("Feature \"{}\" is enabled for user \"{}\"? {}", featureKey, userId, featureEnabled);
431430
return featureEnabled;
432431
}
433432

‎core-api/src/main/java/com/optimizely/ab/bucketing/DecisionService.java

Lines changed: 3 additions & 4 deletions
Original file line numberDiff line numberDiff line change
@@ -141,14 +141,14 @@ public Variation getVariation(@Nonnull Experiment experiment,
141141
if (userProfileService != null) {
142142
saveVariation(experiment, variation, userProfile);
143143
} else {
144-
logger.info("This decision will not be saved since the UserProfileService is null.");
144+
logger.debug("This decision will not be saved since the UserProfileService is null.");
145145
}
146146
}
147147

148148
return variation;
149149
}
150-
logger.info("User \"{}\" does not meet conditions to be in experiment \"{}\".", userId, experiment.getKey());
151150

151+
logger.info("User \"{}\" does not meet conditions to be in experiment \"{}\".", userId, experiment.getKey());
152152
return null;
153153
}
154154

@@ -170,8 +170,7 @@ public FeatureDecision getVariationForFeature(@Nonnull FeatureFlag featureFlag,
170170
Experiment experiment = projectConfig.getExperimentIdMapping().get(experimentId);
171171
Variation variation = getVariation(experiment, userId, filteredAttributes, projectConfig);
172172
if (variation != null) {
173-
return new FeatureDecision(experiment, variation,
174-
FeatureDecision.DecisionSource.FEATURE_TEST);
173+
return new FeatureDecision(experiment, variation, FeatureDecision.DecisionSource.FEATURE_TEST);
175174
}
176175
}
177176
} else {

‎core-api/src/main/java/com/optimizely/ab/config/PollingProjectConfigManager.java

Lines changed: 1 addition & 2 deletions
Original file line numberDiff line numberDiff line change
@@ -176,14 +176,13 @@ public boolean isRunning() {
176176
}
177177

178178
private class ProjectConfigFetcher implements Runnable {
179-
180179
@Override
181180
public void run() {
182181
try {
183182
ProjectConfig projectConfig = poll();
184183
setConfig(projectConfig);
185184
} catch (Exception e) {
186-
logger.error("Error polling ProjectConfigManager", e);
185+
logger.error("Uncaught exception polling for ProjectConfig.", e);
187186
}
188187
}
189188
}

‎core-api/src/main/java/com/optimizely/ab/event/internal/serializer/DefaultJsonSerializer.java

Lines changed: 1 addition & 1 deletion
Original file line numberDiff line numberDiff line change
@@ -62,7 +62,7 @@ Serializer create() {
6262
+ "Please see <link> for more information");
6363
}
6464

65-
logger.info("using json serializer: {}", serializer.getClass().getSimpleName());
65+
logger.debug("using json serializer: {}", serializer.getClass().getSimpleName());
6666
return serializer;
6767
}
6868

‎core-api/src/test/java/com/optimizely/ab/OptimizelyTest.java

Lines changed: 13 additions & 13 deletions
Original file line numberDiff line numberDiff line change
@@ -248,7 +248,7 @@ public void activateEndToEnd() throws Exception {
248248

249249
logbackVerifier.expectMessage(Level.DEBUG, "BucketingId is valid: \"bucketingId\"");
250250

251-
logbackVerifier.expectMessage(Level.INFO, "This decision will not be saved since the UserProfileService is null.");
251+
logbackVerifier.expectMessage(Level.DEBUG, "This decision will not be saved since the UserProfileService is null.");
252252

253253
logbackVerifier.expectMessage(Level.INFO, "Activating user \"userId\" in experiment \"" +
254254
activatedExperiment.getKey() + "\".");
@@ -308,7 +308,7 @@ public void activateEndToEndWithTypedAudienceInt() throws Exception {
308308

309309
logbackVerifier.expectMessage(Level.DEBUG, "BucketingId is valid: \"bucketingId\"");
310310

311-
logbackVerifier.expectMessage(Level.INFO, "This decision will not be saved since the UserProfileService is null.");
311+
logbackVerifier.expectMessage(Level.DEBUG, "This decision will not be saved since the UserProfileService is null.");
312312

313313
logbackVerifier.expectMessage(Level.INFO, "Activating user \"userId\" in experiment \"" +
314314
activatedExperiment.getKey() + "\".");
@@ -460,7 +460,7 @@ public void activateEndToEndWithTypedAudienceBool() throws Exception {
460460

461461
logbackVerifier.expectMessage(Level.DEBUG, "BucketingId is valid: \"bucketingId\"");
462462

463-
logbackVerifier.expectMessage(Level.INFO, "This decision will not be saved since the UserProfileService is null.");
463+
logbackVerifier.expectMessage(Level.DEBUG, "This decision will not be saved since the UserProfileService is null.");
464464

465465
logbackVerifier.expectMessage(Level.INFO, "Activating user \"userId\" in experiment \"" +
466466
activatedExperiment.getKey() + "\".");
@@ -520,7 +520,7 @@ public void activateEndToEndWithTypedAudienceDouble() throws Exception {
520520

521521
logbackVerifier.expectMessage(Level.DEBUG, "BucketingId is valid: \"bucketingId\"");
522522

523-
logbackVerifier.expectMessage(Level.INFO, "This decision will not be saved since the UserProfileService is null.");
523+
logbackVerifier.expectMessage(Level.DEBUG, "This decision will not be saved since the UserProfileService is null.");
524524

525525
logbackVerifier.expectMessage(Level.INFO, "Activating user \"userId\" in experiment \"" +
526526
activatedExperiment.getKey() + "\".");
@@ -629,7 +629,7 @@ public void activateEndToEndWithTypedAudienceWithAnd() throws Exception {
629629

630630
logbackVerifier.expectMessage(Level.DEBUG, "BucketingId is valid: \"bucketingId\"");
631631

632-
logbackVerifier.expectMessage(Level.INFO, "This decision will not be saved since the UserProfileService is null.");
632+
logbackVerifier.expectMessage(Level.DEBUG, "This decision will not be saved since the UserProfileService is null.");
633633

634634
logbackVerifier.expectMessage(Level.INFO, "Activating user \"userId\" in experiment \"" +
635635
activatedExperiment.getKey() + "\".");
@@ -2939,7 +2939,7 @@ public void isFeatureEnabledWithListenerUserInExperimentFeatureOn() throws Excep
29392939
logbackVerifier.expectMessage(
29402940
Level.INFO,
29412941
"Feature \"" + validFeatureKey +
2942-
"\" is enabled for user \"" + genericUserId + "\"."
2942+
"\" is enabled for user \"" + genericUserId + "\"? true"
29432943
);
29442944
verify(mockEventHandler, times(1)).dispatchEvent(any(LogEvent.class));
29452945

@@ -3002,7 +3002,7 @@ public void isFeatureEnabledWithListenerUserInExperimentFeatureOff() throws Exce
30023002
logbackVerifier.expectMessage(
30033003
Level.INFO,
30043004
"Feature \"" + validFeatureKey +
3005-
"\" is not enabled for user \"" + genericUserId + "\"."
3005+
"\" is enabled for user \"" + genericUserId + "\"? false"
30063006
);
30073007
verify(mockEventHandler, times(1)).dispatchEvent(any(LogEvent.class));
30083008

@@ -3048,7 +3048,7 @@ public void isFeatureEnabledWithListenerUserNotInExperimentAndNotInRollOut() thr
30483048
logbackVerifier.expectMessage(
30493049
Level.INFO,
30503050
"Feature \"" + validFeatureKey +
3051-
"\" is not enabled for user \"" + genericUserId + "\"."
3051+
"\" is enabled for user \"" + genericUserId + "\"? false"
30523052
);
30533053
verify(mockEventHandler, never()).dispatchEvent(any(LogEvent.class));
30543054

@@ -3095,7 +3095,7 @@ public void isFeatureEnabledWithListenerUserInRollOut() throws Exception {
30953095
logbackVerifier.expectMessage(
30963096
Level.INFO,
30973097
"Feature \"" + validFeatureKey +
3098-
"\" is not enabled for user \"" + genericUserId + "\"."
3098+
"\" is enabled for user \"" + genericUserId + "\"? true"
30993099
);
31003100
verify(mockEventHandler, never()).dispatchEvent(any(LogEvent.class));
31013101

@@ -4498,7 +4498,7 @@ public void isFeatureEnabledReturnsFalseWhenUserIsNotBucketedIntoAnyVariation()
44984498
logbackVerifier.expectMessage(
44994499
Level.INFO,
45004500
"Feature \"" + validFeatureKey +
4501-
"\" is not enabled for user \"" + genericUserId + "\"."
4501+
"\" is enabled for user \"" + genericUserId + "\"? false"
45024502
);
45034503
verify(spyOptimizely).isFeatureEnabled(
45044504
eq(validFeatureKey),
@@ -4555,7 +4555,7 @@ public void isFeatureEnabledReturnsTrueButDoesNotSendWhenUserIsBucketedIntoVaria
45554555
logbackVerifier.expectMessage(
45564556
Level.INFO,
45574557
"Feature \"" + validFeatureKey +
4558-
"\" is enabled for user \"" + genericUserId + "\"."
4558+
"\" is enabled for user \"" + genericUserId + "\"? true"
45594559
);
45604560
verify(spyOptimizely).isFeatureEnabled(
45614561
eq(validFeatureKey),
@@ -4717,7 +4717,7 @@ public void isFeatureEnabledReturnsFalseAndDispatchesWhenUserIsBucketedIntoAnExp
47174717
logbackVerifier.expectMessage(
47184718
Level.INFO,
47194719
"Feature \"" + validFeatureKey +
4720-
"\" is not enabled for user \"" + genericUserId + "\"."
4720+
"\" is enabled for user \"" + genericUserId + "\"? false"
47214721
);
47224722
verify(mockEventHandler, times(1)).dispatchEvent(any(LogEvent.class));
47234723
}
@@ -4750,7 +4750,7 @@ public void isFeatureEnabledReturnsTrueAndDispatchesEventWhenUserIsBucketedIntoA
47504750
logbackVerifier.expectMessage(
47514751
Level.INFO,
47524752
"Feature \"" + validFeatureKey +
4753-
"\" is enabled for user \"" + genericUserId + "\"."
4753+
"\" is enabled for user \"" + genericUserId + "\"? true"
47544754
);
47554755
verify(mockEventHandler, times(1)).dispatchEvent(any(LogEvent.class));
47564756
}

‎core-api/src/test/java/com/optimizely/ab/config/PollingProjectConfigManagerTest.java

Lines changed: 10 additions & 9 deletions
Original file line numberDiff line numberDiff line change
@@ -125,9 +125,9 @@ public void testGetConfigNotStartedDefault() throws Exception {
125125

126126
@Test
127127
public void testSetConfig() {
128-
PollingProjectConfigManager testProjectConfigManager = new PollingProjectConfigManager(10, TimeUnit.MINUTES) {
128+
testProjectConfigManager = new TestProjectConfigManager() {
129129
@Override
130-
protected ProjectConfig poll() {
130+
public ProjectConfig poll() {
131131
return null;
132132
}
133133
};
@@ -149,10 +149,9 @@ protected ProjectConfig poll() {
149149

150150
@Test
151151
public void testErroringProjectConfigManagerWithTimeout() throws Exception {
152-
PollingProjectConfigManager testProjectConfigManager =
153-
new PollingProjectConfigManager(POLLING_PERIOD, POLLING_UNIT, POLLING_PERIOD / 2, POLLING_UNIT, new NotificationCenter()) {
152+
testProjectConfigManager = new TestProjectConfigManager() {
154153
@Override
155-
protected ProjectConfig poll() {
154+
public ProjectConfig poll() {
156155
throw new RuntimeException();
157156
}
158157
};
@@ -165,10 +164,9 @@ protected ProjectConfig poll() {
165164
public void testRecoveringProjectConfigManagerWithTimeout() throws Exception {
166165
AtomicBoolean throwError = new AtomicBoolean(true);
167166

168-
PollingProjectConfigManager testProjectConfigManager =
169-
new PollingProjectConfigManager(POLLING_PERIOD, POLLING_UNIT, POLLING_PERIOD / 2, POLLING_UNIT, new NotificationCenter()) {
167+
testProjectConfigManager = new TestProjectConfigManager() {
170168
@Override
171-
protected ProjectConfig poll() {
169+
public ProjectConfig poll() {
172170
if (throwError.get()) {
173171
throw new RuntimeException("Test class, expected failure");
174172
}
@@ -183,7 +181,6 @@ protected ProjectConfig poll() {
183181
throwError.set(false);
184182
Thread.sleep(2 * PROJECT_CONFIG_DELAY);
185183
assertEquals(projectConfig, testProjectConfigManager.getConfig());
186-
187184
}
188185

189186
@Test
@@ -202,6 +199,10 @@ private static class TestProjectConfigManager extends PollingProjectConfigManage
202199
private final CountDownLatch countDownLatch = new CountDownLatch(1);
203200
private final ProjectConfig projectConfig;
204201

202+
private TestProjectConfigManager() {
203+
this(null);
204+
}
205+
205206
private TestProjectConfigManager(ProjectConfig projectConfig) {
206207
super(POLLING_PERIOD, POLLING_UNIT, POLLING_PERIOD / 2, POLLING_UNIT, new NotificationCenter());
207208
this.projectConfig = projectConfig;

0 commit comments

Comments
 (0)