Feat(AudienceEvalLogging): Added logging in Audience evaluation and its unit tests (#251)

mnoman09 · thomaszurkan-optimizely · commit 28097f0bf444 · 2019-01-24T14:03:45.000-08:00
* Refact(AudienceLogging): Added  logging in audience evaluation

* Updated headers

* changed missing attribute log level to debug from warn

* potential bug fixes and added null test in isuserinexperiment tests

* Refact and changed log message of missing attribute value

* Code refact

* Added matchType Error enum to get match type error and log with audience condition

* Updated logging with latest changes in audience logging docs

* Refactored code and edited some logs

* nit changes

* made expected logging inline

* header update

* requested changes - on behalf of Noman

* tom commits
diff --git a/core-api/src/main/java/com/optimizely/ab/config/audience/AudienceIdCondition.java b/core-api/src/main/java/com/optimizely/ab/config/audience/AudienceIdCondition.java
@@ -71,10 +71,13 @@ public Boolean evaluate(ProjectConfig config, Map<String, ?> attributes) {
             audience = config.getAudienceIdMapping().get(audienceId);
         }
         if (audience == null) {
-            logger.error(String.format("Audience not set for audienceConditions %s", audienceId));
+            logger.error("Audience {} could not be found.", audienceId);
             return null;
         }
-        return audience.getConditions().evaluate(config, attributes);
+        logger.debug("Starting to evaluate audience {} with conditions: \"{}\"", audience.getName(), audience.getConditions());
+        Boolean result = audience.getConditions().evaluate(config, attributes);
+        logger.info("Audience {} evaluated to {}", audience.getName(), result);
+        return result;
     }
 
     @Override
diff --git a/core-api/src/main/java/com/optimizely/ab/config/audience/UserAttribute.java b/core-api/src/main/java/com/optimizely/ab/config/audience/UserAttribute.java
@@ -20,7 +20,12 @@
 import com.fasterxml.jackson.annotation.JsonIgnoreProperties;
 import com.fasterxml.jackson.annotation.JsonProperty;
 import com.optimizely.ab.config.ProjectConfig;
+import com.optimizely.ab.config.audience.match.Match;
 import com.optimizely.ab.config.audience.match.MatchType;
+import com.optimizely.ab.config.audience.match.UnexpectedValueTypeException;
+import com.optimizely.ab.config.audience.match.UnknownMatchTypeException;
+import org.slf4j.Logger;
+import org.slf4j.LoggerFactory;
 
 import javax.annotation.Nonnull;
 import javax.annotation.Nullable;
@@ -35,6 +40,7 @@
 @JsonIgnoreProperties(ignoreUnknown = true)
 public class UserAttribute<T> implements Condition<T> {
 
+    private static final Logger logger = LoggerFactory.getLogger(UserAttribute.class);
     private final String name;
     private final String type;
     private final String match;
@@ -76,16 +82,42 @@ public Boolean evaluate(ProjectConfig config, Map<String, ?> attributes) {
         Object userAttributeValue = attributes.get(name);
 
         if (!"custom_attribute".equals(type)) {
-            MatchType.logger.error(String.format("condition type not equal to `custom_attribute` %s", type));
+            logger.warn("Audience condition \"{}\" has 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
         try {
-            return MatchType.getMatchType(match, value).getMatcher().eval(userAttributeValue);
+            Match matchType = MatchType.getMatchType(match, value).getMatcher();
+            Boolean result = matchType.eval(userAttributeValue);
+
+            if (result == null) {
+                if (!attributes.containsKey(name)) {
+                    //Missing attribute value
+                    logger.debug("Audience condition \"{}\" evaluated to UNKNOWN because no value was passed for user attribute \"{}\"", this, name);
+                } else {
+                    //if attribute value is not valid
+                    if (userAttributeValue != null) {
+                        logger.warn(
+                            "Audience condition \"{}\" evaluated to UNKNOWN because a value of type \"{}\" was passed for user attribute \"{}\"",
+                            this,
+                            userAttributeValue.getClass().getCanonicalName(),
+                            name);
+                    } else {
+                        logger.warn(
+                            "Audience condition \"{}\" evaluated to UNKNOWN because a null value was passed for user attribute \"{}\"",
+                            this,
+                            name);
+                    }
+                }
+            }
+            return result;
+        } catch (UnknownMatchTypeException | UnexpectedValueTypeException ex) {
+            logger.warn("Audience condition \"{}\" " + ex.getMessage(),
+                this);
         } catch (NullPointerException np) {
-            MatchType.logger.error(String.format("attribute or value null for match %s", match != null ? match : "legacy condition"), np);
-            return null;
+            logger.error("attribute or value null for match {}", match != null ? match : "legacy condition", np);
         }
+        return null;
     }
 
     @Override
diff --git a/core-api/src/main/java/com/optimizely/ab/config/audience/match/AttributeMatch.java b/core-api/src/main/java/com/optimizely/ab/config/audience/match/AttributeMatch.java
@@ -20,22 +20,13 @@ abstract class AttributeMatch<T> implements Match {
     T castToValueType(Object o, Object value) {
         try {
             if (!o.getClass().isInstance(value) && !(o instanceof Number && value instanceof Number)) {
-                MatchType.logger.warn(
-                    String.format("Incompatible type %s, %s",
-                        o.getClass().getCanonicalName(), value.getClass().getCanonicalName())
-                );
-
                 return null;
             }
 
             T rv = (T) o;
 
             return rv;
         } catch (Exception e) {
-            MatchType.logger.error(
-                "Cannot evaluate targeting condition since the value for attribute is an incompatible type",
-                e
-            );
             return null;
         }
     }
diff --git a/core-api/src/main/java/com/optimizely/ab/config/audience/match/ExactNumberMatch.java b/core-api/src/main/java/com/optimizely/ab/config/audience/match/ExactNumberMatch.java
@@ -36,7 +36,6 @@ public Boolean eval(Object attributeValue) {
         try {
             return value.doubleValue() == castToValueType(attributeValue, value).doubleValue();
         } catch (Exception e) {
-            MatchType.logger.error("Exact number match failed ", e);
         }
 
         return null;
diff --git a/core-api/src/main/java/com/optimizely/ab/config/audience/match/GTMatch.java b/core-api/src/main/java/com/optimizely/ab/config/audience/match/GTMatch.java
@@ -30,7 +30,6 @@ public Boolean eval(Object attributeValue) {
         try {
             return castToValueType(attributeValue, value).doubleValue() > value.doubleValue();
         } catch (Exception e) {
-            MatchType.logger.error("Greater than match failed ", e);
             return null;
         }
     }
diff --git a/core-api/src/main/java/com/optimizely/ab/config/audience/match/LTMatch.java b/core-api/src/main/java/com/optimizely/ab/config/audience/match/LTMatch.java
@@ -30,7 +30,6 @@ public Boolean eval(Object attributeValue) {
         try {
             return castToValueType(attributeValue, value).doubleValue() < value.doubleValue();
         } catch (Exception e) {
-            MatchType.logger.error("Less than match failed ", e);
             return null;
         }
     }
diff --git a/core-api/src/main/java/com/optimizely/ab/config/audience/match/MatchType.java b/core-api/src/main/java/com/optimizely/ab/config/audience/match/MatchType.java
@@ -28,7 +28,7 @@ public class MatchType {
     private String matchType;
     private Match matcher;
 
-    public static MatchType getMatchType(String matchType, Object conditionValue) {
+    public static MatchType getMatchType(String matchType, Object conditionValue) throws UnexpectedValueTypeException, UnknownMatchTypeException {
         if (matchType == null) matchType = "legacy_custom_attribute";
 
         switch (matchType) {
@@ -64,10 +64,10 @@ public static MatchType getMatchType(String matchType, Object conditionValue) {
                 }
                 break;
             default:
-                return new MatchType(matchType, new NullMatch());
+                throw new UnknownMatchTypeException();
         }
 
-        return new MatchType(matchType, new NullMatch());
+        throw new UnexpectedValueTypeException();
     }
 
     private static boolean isValidNumber(Object conditionValue) {
diff --git a/core-api/src/main/java/com/optimizely/ab/config/audience/match/SubstringMatch.java b/core-api/src/main/java/com/optimizely/ab/config/audience/match/SubstringMatch.java
@@ -36,7 +36,6 @@ public Boolean eval(Object attributeValue) {
         try {
             return castToValueType(attributeValue, value).contains(value);
         } catch (Exception e) {
-            MatchType.logger.error("Substring match failed ", e);
             return null;
         }
     }
diff --git a/core-api/src/main/java/com/optimizely/ab/config/audience/match/UnexpectedValueTypeException.java b/core-api/src/main/java/com/optimizely/ab/config/audience/match/UnexpectedValueTypeException.java
@@ -1,6 +1,6 @@
 /**
  *
- *    Copyright 2018-2019, Optimizely and contributors
+ *    Copyright 2019, 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.
@@ -14,22 +14,13 @@
  *    See the License for the specific language governing permissions and
  *    limitations under the License.
  */
-package com.optimizely.ab.config.audience.match;
-
-import edu.umd.cs.findbugs.annotations.SuppressFBWarnings;
-
-import javax.annotation.Nullable;
 
-class NullMatch extends AttributeMatch<Object> {
-    @SuppressFBWarnings("URF_UNREAD_FIELD")
-    Object value;
+package com.optimizely.ab.config.audience.match;
 
-    protected NullMatch() {
-        this.value = null;
-    }
+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";
 
-    @Nullable
-    public Boolean eval(Object attributeValue) {
-        return null;
+    public UnexpectedValueTypeException() {
+        super(message);
     }
 }
diff --git a/core-api/src/main/java/com/optimizely/ab/config/audience/match/UnknownMatchTypeException.java b/core-api/src/main/java/com/optimizely/ab/config/audience/match/UnknownMatchTypeException.java
@@ -0,0 +1,26 @@
+/**
+ *
+ *    Copyright 2019, 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.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";
+
+    public UnknownMatchTypeException() {
+        super(message);
+    }
+}
diff --git a/core-api/src/main/java/com/optimizely/ab/internal/ExperimentUtils.java b/core-api/src/main/java/com/optimizely/ab/internal/ExperimentUtils.java
@@ -73,14 +73,15 @@ public static boolean isUserInExperiment(@Nonnull ProjectConfig projectConfig,
         }
     }
 
-    public static @Nullable
-    Boolean evaluateAudience(@Nonnull ProjectConfig projectConfig,
-                             @Nonnull Experiment experiment,
-                             @Nonnull Map<String, ?> attributes) {
+    @Nullable
+    public static Boolean evaluateAudience(@Nonnull ProjectConfig projectConfig,
+                                           @Nonnull Experiment experiment,
+                                           @Nonnull Map<String, ?> attributes) {
         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;
         }
 
@@ -92,20 +93,27 @@ Boolean evaluateAudience(@Nonnull ProjectConfig projectConfig,
 
         OrCondition implicitOr = new OrCondition(conditions);
 
-        return implicitOr.evaluate(projectConfig, attributes);
+        logger.debug("Evaluating audiences for experiment \"{}\": \"{}\"", experiment.getKey(), conditions);
 
+        Boolean result = implicitOr.evaluate(projectConfig, attributes);
+
+        logger.info("Audiences for experiment {} collectively evaluated to {}", experiment.getKey(), result);
+
+        return result;
     }
 
-    public static @Nullable
-    Boolean evaluateAudienceConditions(@Nonnull ProjectConfig projectConfig,
-                                       @Nonnull Experiment experiment,
-                                       @Nonnull Map<String, ?> attributes) {
+    @Nullable
+    public static Boolean evaluateAudienceConditions(@Nonnull ProjectConfig projectConfig,
+                                                     @Nonnull Experiment experiment,
+                                                     @Nonnull Map<String, ?> attributes) {
 
         Condition conditions = experiment.getAudienceConditions();
         if (conditions == null) return null;
-
+        logger.debug("Evaluating audiences for experiment \"{}\": \"{}\"", experiment.getKey(), conditions.toString());
         try {
-            return conditions.evaluate(projectConfig, attributes);
+            Boolean result = conditions.evaluate(projectConfig, attributes);
+            logger.info("Audiences for experiment {} collectively evaluated to {}", experiment.getKey(), result);
+            return result;
         } catch (Exception e) {
             logger.error("Condition invalid", e);
             return null;
diff --git a/core-api/src/test/java/com/optimizely/ab/OptimizelyTest.java b/core-api/src/test/java/com/optimizely/ab/OptimizelyTest.java
@@ -524,8 +524,6 @@ public void activateEndToEndWithTypedAudienceBoolWithAndAudienceConditions() thr
         when(mockBucketer.bucket(activatedExperiment, bucketingId))
             .thenReturn(bucketedVariation);
 
-        logbackVerifier.expectMessage(Level.ERROR, "Greater than match failed");
-
         // activate the experiment
         Variation actualVariation = optimizely.activate(activatedExperiment.getKey(), userId, testUserAttributes);
 
diff --git a/core-api/src/test/java/com/optimizely/ab/config/audience/AudienceConditionEvaluationTest.java b/core-api/src/test/java/com/optimizely/ab/config/audience/AudienceConditionEvaluationTest.java
@@ -16,7 +16,10 @@
  */
 package com.optimizely.ab.config.audience;
 
+import ch.qos.logback.classic.Level;
+import com.optimizely.ab.internal.LogbackVerifier;
 import org.junit.Before;
+import org.junit.Rule;
 import org.junit.Test;
 
 import java.math.BigInteger;
@@ -44,6 +47,9 @@
     justification = "mockito verify calls do have a side-effect")
 public class AudienceConditionEvaluationTest {
 
+    @Rule
+    public LogbackVerifier logbackVerifier = new LogbackVerifier();
+
     Map<String, String> testUserAttributes;
     Map<String, Object> testTypedUserAttributes;
 
@@ -108,6 +114,64 @@ public void invalidMatchCondition() throws Exception {
     public void invalidMatch() throws Exception {
         UserAttribute testInstance = new UserAttribute("browser_type", "custom_attribute", "blah", "chrome");
         assertNull(testInstance.evaluate(null, testUserAttributes));
+        logbackVerifier.expectMessage(Level.WARN,
+            "Audience condition \"{name='browser_type', type='custom_attribute', match='blah', value='chrome'}\" uses an unknown match type. You may need to upgrade to a newer release of the Optimizely SDK");
+    }
+
+    /**
+     * Verify that UserAttribute.evaluate returns null on invalid attribute type.
+     */
+    @Test
+    public void unexpectedAttributeType() throws Exception {
+        UserAttribute testInstance = new UserAttribute("browser_type", "custom_attribute", "gt", 20);
+        assertNull(testInstance.evaluate(null, testUserAttributes));
+        logbackVerifier.expectMessage(Level.WARN,
+            "Audience condition \"{name='browser_type', type='custom_attribute', match='gt', value=20}\" evaluated to UNKNOWN because a value of type \"java.lang.String\" was passed for user attribute \"browser_type\"");
+    }
+
+    /**
+     * Verify that UserAttribute.evaluate returns null on invalid attribute type.
+     */
+    @Test
+    public void unexpectedAttributeTypeNull() throws Exception {
+        UserAttribute testInstance = new UserAttribute("browser_type", "custom_attribute", "gt", 20);
+        assertNull(testInstance.evaluate(null, Collections.singletonMap("browser_type", null)));
+        logbackVerifier.expectMessage(Level.WARN,
+            "Audience condition \"{name='browser_type', type='custom_attribute', match='gt', value=20}\" evaluated to UNKNOWN because a null value was passed for user attribute \"browser_type\"");
+    }
+
+
+    /**
+     * Verify that UserAttribute.evaluate returns null on missing attribute value.
+     */
+    @Test
+    public void missingAttribute() throws Exception {
+        UserAttribute testInstance = new UserAttribute("browser_type", "custom_attribute", "gt", 20);
+        assertNull(testInstance.evaluate(null, Collections.EMPTY_MAP));
+        logbackVerifier.expectMessage(Level.DEBUG,
+            "Audience condition \"{name='browser_type', type='custom_attribute', match='gt', value=20}\" evaluated to UNKNOWN because no value was passed for user attribute \"browser_type\"");
+    }
+
+    /**
+     * Verify that UserAttribute.evaluate returns null on passing null attribute object.
+     */
+    @Test
+    public void nullAttribute() throws Exception {
+        UserAttribute testInstance = new UserAttribute("browser_type", "custom_attribute", "gt", 20);
+        assertNull(testInstance.evaluate(null, null));
+        logbackVerifier.expectMessage(Level.DEBUG,
+            "Audience condition \"{name='browser_type', type='custom_attribute', match='gt', value=20}\" evaluated to UNKNOWN because no value was passed for user attribute \"browser_type\"");
+    }
+
+    /**
+     * Verify that UserAttribute.evaluate returns null on unknown condition type.
+     */
+    @Test
+    public void unknownConditionType() throws Exception {
+        UserAttribute testInstance = new UserAttribute("browser_type", "blah", "exists", "firefox");
+        assertNull(testInstance.evaluate(null, testUserAttributes));
+        logbackVerifier.expectMessage(Level.WARN,
+            "Audience condition \"{name='browser_type', type='blah', match='exists', value='firefox'}\" has an unknown condition type. You may need to upgrade to a newer release of the Optimizely SDK");
     }
 
     /**
diff --git a/core-api/src/test/java/com/optimizely/ab/internal/ExperimentUtilsTest.java b/core-api/src/test/java/com/optimizely/ab/internal/ExperimentUtilsTest.java

Original file line number	Diff line number	Diff line change
`@@ -71,10 +71,13 @@ public Boolean evaluate(ProjectConfig config, Map<String, ?> attributes) {`
`71`	`71`	`audience = config.getAudienceIdMapping().get(audienceId);`
`72`	`72`	`}`
`73`	`73`	`if (audience == null) {`
`74`		`- logger.error(String.format("Audience not set for audienceConditions %s", audienceId));`
	`74`	`+ logger.error("Audience {} could not be found.", audienceId);`
`75`	`75`	`return null;`
`76`	`76`	`}`
`77`		`- return audience.getConditions().evaluate(config, attributes);`
	`77`	`+ logger.debug("Starting to evaluate audience {} with conditions: \"{}\"", audience.getName(), audience.getConditions());`
	`78`	`+ Boolean result = audience.getConditions().evaluate(config, attributes);`
	`79`	`+ logger.info("Audience {} evaluated to {}", audience.getName(), result);`
	`80`	`+ return result;`
`78`	`81`	`}`
`79`	`82`
`80`	`83`	`@Override`
Original file line number	Diff line number	Diff line change
`@@ -36,7 +36,6 @@ public Boolean eval(Object attributeValue) {`
`36`	`36`	`try {`
`37`	`37`	`return value.doubleValue() == castToValueType(attributeValue, value).doubleValue();`
`38`	`38`	`} catch (Exception e) {`
`39`		`- MatchType.logger.error("Exact number match failed ", e);`
`40`	`39`	`}`
`41`	`40`
`42`	`41`	`return null;`
Original file line number	Diff line number	Diff line change
`@@ -30,7 +30,6 @@ public Boolean eval(Object attributeValue) {`
`30`	`30`	`try {`
`31`	`31`	`return castToValueType(attributeValue, value).doubleValue() > value.doubleValue();`
`32`	`32`	`} catch (Exception e) {`
`33`		`- MatchType.logger.error("Greater than match failed ", e);`
`34`	`33`	`return null;`
`35`	`34`	`}`
`36`	`35`	`}`
Original file line number	Diff line number	Diff line change
`@@ -28,7 +28,7 @@ public class MatchType {`
`28`	`28`	`private String matchType;`
`29`	`29`	`private Match matcher;`
`30`	`30`
`31`		`- public static MatchType getMatchType(String matchType, Object conditionValue) {`
	`31`	`+ public static MatchType getMatchType(String matchType, Object conditionValue) throws UnexpectedValueTypeException, UnknownMatchTypeException {`
`32`	`32`	`if (matchType == null) matchType = "legacy_custom_attribute";`
`33`	`33`
`34`	`34`	`switch (matchType) {`
`@@ -64,10 +64,10 @@ public static MatchType getMatchType(String matchType, Object conditionValue) {`
`64`	`64`	`}`
`65`	`65`	`break;`
`66`	`66`	`default:`
`67`		`- return new MatchType(matchType, new NullMatch());`
	`67`	`+ throw new UnknownMatchTypeException();`
`68`	`68`	`}`
`69`	`69`
`70`		`- return new MatchType(matchType, new NullMatch());`
	`70`	`+ throw new UnexpectedValueTypeException();`
`71`	`71`	`}`
`72`	`72`
`73`	`73`	`private static boolean isValidNumber(Object conditionValue) {`