refact(audience-logs): Added and refactored audience and feature variable evaluation logs (#380)

Author: mnoman09

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

@@ -693,13 +693,15 @@ <T> T getFeatureVariableValueForType(@Nonnull String featureKey,
  featureDecision.variation.getVariableIdToFeatureVariableUsageInstanceMap().get(variable.getId());
  if (featureVariableUsageInstance != null) {
  variableValue = featureVariableUsageInstance.getValue();
+ logger.info("Got variable value \"{}\" for variable \"{}\" of feature flag \"{}\".", variableValue, variableKey, featureKey);
  } else {
  variableValue = variable.getDefaultValue();
+ logger.info("Value is not defined for variable \"{}\". Returning default value \"{}\".", variableKey, variableValue);
  }
  } else {
- logger.info("Feature \"{}\" for variation \"{}\" was not enabled. " +
- "The default value is being returned.",
- featureKey, featureDecision.variation.getKey(), variableValue, variableKey
+ logger.info("Feature \"{}\" is not enabled for user \"{}\". " +
+ "Returning the default variable value \"{}\".",
+ featureKey, userId, variableValue
  );
  }
  featureEnabled = featureDecision.variation.getFeatureEnabled();
@@ -822,12 +824,12 @@ public OptimizelyJSON getAllFeatureVariables(@Nonnull String featureKey,
  Variation variation = featureDecision.variation;
 
  if (variation != null) {
- if (!variation.getFeatureEnabled()) {
- logger.info("Feature \"{}\" for variation \"{}\" was not enabled. " +
- "The default value is being returned.", featureKey, featureDecision.variation.getKey());
- }
-
  featureEnabled = variation.getFeatureEnabled();
+ if (featureEnabled) {
+ logger.info("Feature \"{}\" is enabled for user \"{}\".", featureKey, userId);
+ } else {
+ logger.info("Feature \"{}\" is not enabled for user \"{}\".", featureKey, userId);
+ }
  } else {
  logger.info("User \"{}\" was not bucketed into any variation for feature flag \"{}\". " +
  "The default values are being returned.", userId, featureKey);

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

@@ -1,5 +1,5 @@
 /****************************************************************************
- * Copyright 2017-2019, Optimizely, Inc. and contributors *
+ * Copyright 2017-2020, Optimizely, Inc. and contributors *
  * *
  * Licensed under the Apache License, Version 2.0 (the "License"); *
  * you may not use this file except in compliance with the License. *
@@ -17,7 +17,6 @@
 
 import com.optimizely.ab.OptimizelyRuntimeException;
 import com.optimizely.ab.config.*;
-import com.optimizely.ab.config.audience.Audience;
 import com.optimizely.ab.error.ErrorHandler;
 import com.optimizely.ab.internal.ExperimentUtils;
 import com.optimizely.ab.internal.ControlAttribute;
@@ -32,6 +31,9 @@
 import javax.annotation.Nonnull;
 import javax.annotation.Nullable;
 
+import static com.optimizely.ab.internal.LoggingConstants.LoggingEntityType.EXPERIMENT;
+import static com.optimizely.ab.internal.LoggingConstants.LoggingEntityType.RULE;
+
 /**
  * Optimizely's decision service that determines which variation of an experiment the user will be allocated to.
  *
@@ -133,7 +135,7 @@ public Variation getVariation(@Nonnull Experiment experiment,
  userProfile = new UserProfile(userId, new HashMap<String, Decision>());
  }
 
- if (ExperimentUtils.isUserInExperiment(projectConfig, experiment, filteredAttributes)) {
+ if (ExperimentUtils.doesUserMeetAudienceConditions(projectConfig, experiment, filteredAttributes, EXPERIMENT, experiment.getKey())) {
  String bucketingId = getBucketingId(userId, filteredAttributes);
  variation = bucketer.bucket(experiment, bucketingId, projectConfig);
 
@@ -221,25 +223,24 @@ FeatureDecision getVariationForFeatureInRollout(@Nonnull FeatureFlag featureFlag
  Variation variation;
  for (int i = 0; i < rolloutRulesLength - 1; i++) {
  Experiment rolloutRule = rollout.getExperiments().get(i);
- Audience audience = projectConfig.getAudienceIdMapping().get(rolloutRule.getAudienceIds().get(0));
- if (ExperimentUtils.isUserInExperiment(projectConfig, rolloutRule, filteredAttributes)) {
+ if (ExperimentUtils.doesUserMeetAudienceConditions(projectConfig, rolloutRule, filteredAttributes, RULE, Integer.toString(i + 1))) {
  variation = bucketer.bucket(rolloutRule, bucketingId, projectConfig);
  if (variation == null) {
  break;
  }
  return new FeatureDecision(rolloutRule, variation,
  FeatureDecision.DecisionSource.ROLLOUT);
  } else {
- logger.debug("User \"{}\" did not meet the conditions to be in rollout rule for audience \"{}\".",
- userId, audience.getName());
+ logger.debug("User \"{}\" does not meet conditions for targeting rule \"{}\".", userId, i + 1);
  }
  }
 
  // get last rule which is the fall back rule
  Experiment finalRule = rollout.getExperiments().get(rolloutRulesLength - 1);
- if (ExperimentUtils.isUserInExperiment(projectConfig, finalRule, filteredAttributes)) {
+ if (ExperimentUtils.doesUserMeetAudienceConditions(projectConfig, finalRule, filteredAttributes, RULE, "Everyone Else")) {
  variation = bucketer.bucket(finalRule, bucketingId, projectConfig);
  if (variation != null) {
+ logger.debug("User \"{}\" meets conditions for targeting rule \"Everyone Else\".", userId);
  return new FeatureDecision(finalRule, variation,
  FeatureDecision.DecisionSource.ROLLOUT);
  }
@@ -394,7 +395,6 @@ public boolean setForcedVariation(@Nonnull Experiment experiment,
  @Nullable String variationKey) {
 
 
-
  Variation variation = null;
 
  // keep in mind that you can pass in a variationKey that is null if you want to

core-api/src/main/java/com/optimizely/ab/config/audience/AudienceIdCondition.java

@@ -74,9 +74,9 @@ public Boolean evaluate(ProjectConfig config, Map<String, ?> attributes) {
  logger.error("Audience {} could not be found.", audienceId);
  return null;
  }
- logger.debug("Starting to evaluate audience {} with conditions: \"{}\"", audience.getName(), audience.getConditions());
+ logger.debug("Starting to evaluate audience \"{}\" with conditions: {}.", audience.getId(), audience.getConditions());
  Boolean result = audience.getConditions().evaluate(config, attributes);
- logger.debug("Audience {} evaluated to {}", audience.getName(), result);
+ logger.debug("Audience \"{}\" evaluated to {}.", audience.getId(), result);
  return result;
  }
 

core-api/src/main/java/com/optimizely/ab/config/audience/UserAttribute.java

@@ -1,6 +1,6 @@
 /**
  *
- * Copyright 2016-2019, Optimizely and contributors
+ * Copyright 2016-2020, Optimizely and contributors
  *
  * Licensed under the Apache License, Version 2.0 (the "License");
  * you may not use this file except in compliance with the License.
@@ -82,7 +82,7 @@ public Boolean evaluate(ProjectConfig config, Map<String, ?> attributes) {
  Object userAttributeValue = attributes.get(name);
 
  if (!"custom_attribute".equals(type)) {
- logger.warn("Audience condition \"{}\" has an unknown condition type. You may need to upgrade to a newer release of the Optimizely SDK", this);
+ logger.warn("Audience condition \"{}\" uses an unknown condition type. You may need to upgrade to a newer release of the Optimizely SDK.", this);
  return null; // unknown type
  }
  // check user attribute value is equal
@@ -103,7 +103,7 @@ public Boolean evaluate(ProjectConfig config, Map<String, ?> attributes) {
  userAttributeValue.getClass().getCanonicalName(),
  name);
  } else {
- logger.warn(
+ logger.debug(
  "Audience condition \"{}\" evaluated to UNKNOWN because a null value was passed for user attribute \"{}\"",
  this,
  name);

core-api/src/main/java/com/optimizely/ab/config/audience/match/UnexpectedValueTypeException.java

@@ -1,6 +1,6 @@
 /**
  *
- * Copyright 2019, Optimizely and contributors
+ * Copyright 2019-2020, Optimizely and contributors
  *
  * Licensed under the Apache License, Version 2.0 (the "License");
  * you may not use this file except in compliance with the License.
@@ -18,7 +18,7 @@
 package com.optimizely.ab.config.audience.match;
 
 public class UnexpectedValueTypeException extends Exception {
- private static String message = "has an unexpected value type. You may need to upgrade to a newer release of the Optimizely SDK";
+ private static String message = "has an unsupported condition value. You may need to upgrade to a newer release of the Optimizely SDK.";
 
  public UnexpectedValueTypeException() {
  super(message);

core-api/src/main/java/com/optimizely/ab/config/audience/match/UnknownMatchTypeException.java

@@ -1,6 +1,6 @@
 /**
  *
- * Copyright 2019, Optimizely and contributors
+ * Copyright 2019-2020, Optimizely and contributors
  *
  * Licensed under the Apache License, Version 2.0 (the "License");
  * you may not use this file except in compliance with the License.
@@ -18,7 +18,7 @@
 package com.optimizely.ab.config.audience.match;
 
 public class UnknownMatchTypeException extends Exception {
- private static String message = "uses an unknown match type. You may need to upgrade to a newer release of the Optimizely SDK";
+ private static String message = "uses an unknown match type. You may need to upgrade to a newer release of the Optimizely SDK.";
 
  public UnknownMatchTypeException() {
  super(message);

core-api/src/main/java/com/optimizely/ab/internal/ExperimentUtils.java

@@ -1,6 +1,6 @@
 /**
  *
- * Copyright 2017-2019, Optimizely and contributors
+ * Copyright 2017-2020, Optimizely and contributors
  *
  * Licensed under the Apache License, Version 2.0 (the "License");
  * you may not use this file except in compliance with the License.
@@ -56,32 +56,38 @@ public static boolean isExperimentActive(@Nonnull Experiment experiment) {
  /**
  * Determines whether a user satisfies audience conditions for the experiment.
  *
- * @param projectConfig the current projectConfig
- * @param experiment the experiment we are evaluating audiences for
- * @param attributes the attributes of the user
+ * @param projectConfig the current projectConfig
+ * @param experiment the experiment we are evaluating audiences for
+ * @param attributes the attributes of the user
+ * @param loggingEntityType It can be either experiment or rule.
+ * @param loggingKey In case of loggingEntityType is experiment it will be experiment key or else it will be rule number.
  * @return whether the user meets the criteria for the experiment
  */
- public static boolean isUserInExperiment(@Nonnull ProjectConfig projectConfig,
- @Nonnull Experiment experiment,
- @Nonnull Map<String, ?> attributes) {
+ public static boolean doesUserMeetAudienceConditions(@Nonnull ProjectConfig projectConfig,
+ @Nonnull Experiment experiment,
+ @Nonnull Map<String, ?> attributes,
+ @Nonnull String loggingEntityType,
+ @Nonnull String loggingKey) {
  if (experiment.getAudienceConditions() != null) {
- Boolean resolveReturn = evaluateAudienceConditions(projectConfig, experiment, attributes);
+ logger.debug("Evaluating audiences for {} \"{}\": {}.", loggingEntityType, loggingKey, experiment.getAudienceConditions());
+ Boolean resolveReturn = evaluateAudienceConditions(projectConfig, experiment, attributes, loggingEntityType, loggingKey);
  return resolveReturn == null ? false : resolveReturn;
  } else {
- Boolean resolveReturn = evaluateAudience(projectConfig, experiment, attributes);
+ Boolean resolveReturn = evaluateAudience(projectConfig, experiment, attributes, loggingEntityType, loggingKey);
  return Boolean.TRUE.equals(resolveReturn);
  }
  }
 
  @Nullable
  public static Boolean evaluateAudience(@Nonnull ProjectConfig projectConfig,
  @Nonnull Experiment experiment,
- @Nonnull Map<String, ?> attributes) {
+ @Nonnull Map<String, ?> attributes,
+ @Nonnull String loggingEntityType,
+ @Nonnull String loggingKey) {
  List<String> experimentAudienceIds = experiment.getAudienceIds();
 
  // if there are no audiences, ALL users should be part of the experiment
  if (experimentAudienceIds.isEmpty()) {
- logger.debug("There is no Audience associated with experiment {}", experiment.getKey());
  return true;
  }
 
@@ -93,26 +99,28 @@ public static Boolean evaluateAudience(@Nonnull ProjectConfig projectConfig,
 
  OrCondition implicitOr = new OrCondition(conditions);
 
- logger.debug("Evaluating audiences for experiment \"{}\": \"{}\"", experiment.getKey(), conditions);
+ logger.debug("Evaluating audiences for {} \"{}\": {}.", loggingEntityType, loggingKey, conditions);
 
  Boolean result = implicitOr.evaluate(projectConfig, attributes);
 
- logger.info("Audiences for experiment {} collectively evaluated to {}", experiment.getKey(), result);
+ logger.info("Audiences for {} \"{}\" collectively evaluated to {}.", loggingEntityType, loggingKey, result);
 
  return result;
  }
 
  @Nullable
  public static Boolean evaluateAudienceConditions(@Nonnull ProjectConfig projectConfig,
  @Nonnull Experiment experiment,
- @Nonnull Map<String, ?> attributes) {
+ @Nonnull Map<String, ?> attributes,
+ @Nonnull String loggingEntityType,
+ @Nonnull String loggingKey) {
 
  Condition conditions = experiment.getAudienceConditions();
  if (conditions == null) return null;
- logger.debug("Evaluating audiences for experiment \"{}\": \"{}\"", experiment.getKey(), conditions.toString());
+
  try {
  Boolean result = conditions.evaluate(projectConfig, attributes);
- logger.info("Audiences for experiment {} collectively evaluated to {}", experiment.getKey(), result);
+ logger.info("Audiences for {} \"{}\" collectively evaluated to {}.", loggingEntityType, loggingKey, result);
  return result;
  } catch (Exception e) {
  logger.error("Condition invalid", e);

core-api/src/main/java/com/optimizely/ab/internal/LoggingConstants.java

@@ -0,0 +1,24 @@
+/**
+ *
+ * Copyright 2020, Optimizely and contributors
+ *
+ * Licensed under the Apache License, Version 2.0 (the "License");
+ * you may not use this file except in compliance with the License.
+ * You may obtain a copy of the License at
+ *
+ * http://www.apache.org/licenses/LICENSE-2.0
+ *
+ * Unless required by applicable law or agreed to in writing, software
+ * distributed under the License is distributed on an "AS IS" BASIS,
+ * WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied.
+ * See the License for the specific language governing permissions and
+ * limitations under the License.
+ */
+package com.optimizely.ab.internal;
+
+public class LoggingConstants {
+ public static class LoggingEntityType {
+ public static final String EXPERIMENT = "experiment";
+ public static final String RULE = "rule";
+ }
+}

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

@@ -2890,8 +2890,7 @@ public void getFeatureVariableValueReturnsDefaultValueWhenFeatureEnabledIsFalse(
 
  logbackVerifier.expectMessage(
  Level.INFO,
- "Feature \"" + validFeatureKey + "\" for variation \"Gred\" was not enabled. " +
- "The default value is being returned."
+ "Feature \"multi_variate_feature\" is not enabled for user \"genericUserId\". Returning the default variable value \"H\"."
  );
 
  assertEquals(expectedValue, value);
@@ -2918,6 +2917,11 @@ public void getFeatureVariableUserInExperimentFeatureOn() throws Exception {
  testUserId,
  Collections.singletonMap(ATTRIBUTE_HOUSE_KEY, AUDIENCE_GRYFFINDOR_VALUE)),
  expectedValue);
+
+ logbackVerifier.expectMessage(
+ Level.INFO,
+ "Got variable value \"F\" for variable \"first_letter\" of feature flag \"multi_variate_feature\"."
+ );
  }
 
  /**
@@ -3061,6 +3065,11 @@ public void getFeatureVariableValueReturnsDefaultValueWhenNoVariationUsageIsPres
  );
 
  assertEquals(expectedValue, value);
+
+ logbackVerifier.expectMessage(
+ Level.INFO,
+ "Value is not defined for variable \"integer_variable\". Returning default value \"7\"."
+ );
  }
 
  /**