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

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\"."
+        );
     }
 
     /**