fix(logs): Fixing log messages for Targeted Rollouts (#515)

Author: fayyazarshad

packages/optimizely-sdk/lib/core/bucketer/index.js

@@ -104,36 +104,19 @@ export var bucket = function(bucketerParams) {
   var bucketValue = this._generateBucketValue(bucketingId);
 
   var bucketedUserLogMessage = sprintf(
-    LOG_MESSAGES.USER_ASSIGNED_TO_VARIATION_BUCKET,
+    LOG_MESSAGES.USER_ASSIGNED_TO_EXPERIMENT_BUCKET,
     MODULE_NAME,
     bucketValue,
     bucketerParams.userId
   );
   bucketerParams.logger.log(LOG_LEVEL.DEBUG, bucketedUserLogMessage);
 
   var entityId = this._findBucket(bucketValue, bucketerParams.trafficAllocationConfig);
-  if (!entityId) {
-    var userHasNoVariationLogMessage = sprintf(
-      LOG_MESSAGES.USER_HAS_NO_VARIATION,
-      MODULE_NAME,
-      bucketerParams.userId,
-      bucketerParams.experimentKey
-    );
-    bucketerParams.logger.log(LOG_LEVEL.DEBUG, userHasNoVariationLogMessage);
-  } else if (!bucketerParams.variationIdMap.hasOwnProperty(entityId)) {
+
+  if (!bucketerParams.variationIdMap.hasOwnProperty(entityId)) {
     var invalidVariationIdLogMessage = sprintf(LOG_MESSAGES.INVALID_VARIATION_ID, MODULE_NAME);
     bucketerParams.logger.log(LOG_LEVEL.WARNING, invalidVariationIdLogMessage);
     return null;
-  } else {
-    var variationKey = bucketerParams.variationIdMap[entityId].key;
-    var userInVariationLogMessage = sprintf(
-      LOG_MESSAGES.USER_HAS_VARIATION,
-      MODULE_NAME,
-      bucketerParams.userId,
-      variationKey,
-      bucketerParams.experimentKey
-    );
-    bucketerParams.logger.log(LOG_LEVEL.INFO, userInVariationLogMessage);
   }
 
   return entityId;

packages/optimizely-sdk/lib/core/bucketer/index.tests.js

@@ -75,27 +75,18 @@ describe('lib/core/bucketer', function() {
           expect(bucketer.bucket(bucketerParamsTest1)).to.equal('111128');
 
           var bucketedUser_log1 = createdLogger.log.args[0][1];
-          var bucketedUser_log2 = createdLogger.log.args[1][1];
-
           expect(bucketedUser_log1).to.equal(
-            sprintf(LOG_MESSAGES.USER_ASSIGNED_TO_VARIATION_BUCKET, 'BUCKETER', '50', 'ppid1')
-          );
-          expect(bucketedUser_log2).to.equal(
-            sprintf(LOG_MESSAGES.USER_HAS_VARIATION, 'BUCKETER', 'ppid1', 'control', 'testExperiment')
+            sprintf(LOG_MESSAGES.USER_ASSIGNED_TO_EXPERIMENT_BUCKET, 'BUCKETER', '50', 'ppid1')
           );
 
           var bucketerParamsTest2 = cloneDeep(bucketerParams);
           bucketerParamsTest2.userId = 'ppid2';
           expect(bucketer.bucket(bucketerParamsTest2)).to.equal(null);
 
-          var notBucketedUser_log1 = createdLogger.log.args[2][1];
-          var notBucketedUser_log2 = createdLogger.log.args[3][1];
+          var notBucketedUser_log1 = createdLogger.log.args[1][1];
 
           expect(notBucketedUser_log1).to.equal(
-            sprintf(LOG_MESSAGES.USER_ASSIGNED_TO_VARIATION_BUCKET, 'BUCKETER', '50000', 'ppid2')
-          );
-          expect(notBucketedUser_log2).to.equal(
-            sprintf(LOG_MESSAGES.USER_HAS_NO_VARIATION, 'BUCKETER', 'ppid2', 'testExperiment')
+            sprintf(LOG_MESSAGES.USER_ASSIGNED_TO_EXPERIMENT_BUCKET, 'BUCKETER', '50000', 'ppid2')
           );
         });
       });
@@ -142,7 +133,7 @@ describe('lib/core/bucketer', function() {
             expect(bucketer.bucket(bucketerParams)).to.equal('551');
 
             sinon.assert.calledTwice(bucketerStub);
-            sinon.assert.callCount(createdLogger.log, 4);
+            sinon.assert.callCount(createdLogger.log, 3);
 
             var log1 = createdLogger.log.args[0][1];
             expect(log1).to.equal(
@@ -162,12 +153,7 @@ describe('lib/core/bucketer', function() {
 
             var log3 = createdLogger.log.args[2][1];
             expect(log3).to.equal(
-              sprintf(LOG_MESSAGES.USER_ASSIGNED_TO_VARIATION_BUCKET, 'BUCKETER', '50', 'testUser')
-            );
-
-            var log4 = createdLogger.log.args[3][1];
-            expect(log4).to.equal(
-              sprintf(LOG_MESSAGES.USER_HAS_VARIATION, 'BUCKETER', 'testUser', 'var1exp1', 'groupExperiment1')
+              sprintf(LOG_MESSAGES.USER_ASSIGNED_TO_EXPERIMENT_BUCKET, 'BUCKETER', '50', 'testUser')
             );
           });
 
@@ -258,20 +244,10 @@ describe('lib/core/bucketer', function() {
             expect(bucketer.bucket(bucketerParams)).to.equal('553');
 
             sinon.assert.calledOnce(bucketerStub);
-            sinon.assert.calledTwice(createdLogger.log);
+            sinon.assert.calledOnce(createdLogger.log);
 
             var log1 = createdLogger.log.args[0][1];
-            expect(log1).to.equal(sprintf(LOG_MESSAGES.USER_ASSIGNED_TO_VARIATION_BUCKET, 'BUCKETER', '0', 'testUser'));
-            var log2 = createdLogger.log.args[1][1];
-            expect(log2).to.equal(
-              sprintf(
-                LOG_MESSAGES.USER_HAS_VARIATION,
-                'BUCKETER',
-                'testUser',
-                'overlappingvar1',
-                'overlappingGroupExperiment1'
-              )
-            );
+            expect(log1).to.equal(sprintf(LOG_MESSAGES.USER_ASSIGNED_TO_EXPERIMENT_BUCKET, 'BUCKETER', '0', 'testUser'));
           });
 
           it('should return null when a user does not fall into an experiment within an overlapping group', function() {
@@ -308,7 +284,7 @@ describe('lib/core/bucketer', function() {
         it('should return null', function() {
           var bucketerParamsTest1 = cloneDeep(bucketerParams);
           bucketerParamsTest1.userId = 'ppid1';
-          expect(bucketer.bucket(bucketerParamsTest1)).to.equal('');
+          expect(bucketer.bucket(bucketerParamsTest1)).to.equal(null);
         });
       });
 

packages/optimizely-sdk/lib/core/decision_service/index.js

@@ -27,6 +27,7 @@ var ERROR_MESSAGES = enums.ERROR_MESSAGES;
 var LOG_LEVEL = enums.LOG_LEVEL;
 var LOG_MESSAGES = enums.LOG_MESSAGES;
 var DECISION_SOURCES = enums.DECISION_SOURCES;
+var AUDIENCE_EVALUATION_TYPES = enums.AUDIENCE_EVALUATION_TYPES;
 
 /**
  * Optimizely's decision service that determines which variation of an experiment the user will be allocated to.
@@ -90,17 +91,39 @@ DecisionService.prototype.getVariation = function(configObj, experimentKey, user
   }
 
   // Perform regular targeting and bucketing
-  if (!this.__checkIfUserIsInAudience(configObj, experimentKey, userId, attributes)) {
+  if (!this.__checkIfUserIsInAudience(configObj, experimentKey, AUDIENCE_EVALUATION_TYPES.EXPERIMENT, userId, attributes, '')) {
+    var userDoesNotMeetConditionsLogMessage = sprintf(
+      LOG_MESSAGES.USER_NOT_IN_EXPERIMENT,
+      MODULE_NAME,
+      userId,
+      experimentKey
+    );
+    this.logger.log(LOG_LEVEL.INFO, userDoesNotMeetConditionsLogMessage);
     return null;
   }
 
   var bucketerParams = this.__buildBucketerParams(configObj, experimentKey, bucketingId, userId);
   var variationId = bucketer.bucket(bucketerParams);
   variation = configObj.variationIdMap[variationId];
   if (!variation) {
+    var userHasNoVariationLogMessage = sprintf(
+      LOG_MESSAGES.USER_HAS_NO_VARIATION,
+      MODULE_NAME,
+      userId,
+      experimentKey
+    );
+    this.logger.log(LOG_LEVEL.DEBUG, userHasNoVariationLogMessage);
     return null;
   }
 
+  var userInVariationLogMessage = sprintf(
+    LOG_MESSAGES.USER_HAS_VARIATION,
+    MODULE_NAME,
+    userId,
+    variation.key,
+    experimentKey
+  );
+  this.logger.log(LOG_LEVEL.INFO, userInVariationLogMessage);
   // persist bucketing
   this.__saveUserProfile(experiment, variation, userId, experimentBucketMap);
 
@@ -171,21 +194,24 @@ DecisionService.prototype.__getWhitelistedVariation = function(experiment, userI
 
 /**
  * Checks whether the user is included in experiment audience
- * @param  {Object}  configObj     The parsed project configuration object
- * @param  {string}  experimentKey Key of experiment being validated
- * @param  {string}  userId        ID of user
- * @param  {Object}  attributes    Optional parameter for user's attributes
+ * @param  {Object}  configObj            The parsed project configuration object
+ * @param  {string}  experimentKey        Key of experiment being validated
+ * @param  {string}  evaluationAttribute  String representing experiment key or rule
+ * @param  {string}  userId               ID of user
+ * @param  {Object}  attributes           Optional parameter for user's attributes
+ * @param  {string}  loggingKey           String representing experiment key or rollout rule. To be used in log messages only.
  * @return {boolean} True if user meets audience conditions
  */
-DecisionService.prototype.__checkIfUserIsInAudience = function(configObj, experimentKey, userId, attributes) {
+DecisionService.prototype.__checkIfUserIsInAudience = function(configObj, experimentKey, evaluationAttribute, userId, attributes, loggingKey) {
   var experimentAudienceConditions = projectConfig.getExperimentAudienceConditions(configObj, experimentKey);
   var audiencesById = projectConfig.getAudiencesById(configObj);
   this.logger.log(
     LOG_LEVEL.DEBUG,
     sprintf(
       LOG_MESSAGES.EVALUATING_AUDIENCES_COMBINED,
       MODULE_NAME,
-      experimentKey,
+      evaluationAttribute,
+      loggingKey || experimentKey,
       JSON.stringify(experimentAudienceConditions)
     )
   );
@@ -195,23 +221,13 @@ DecisionService.prototype.__checkIfUserIsInAudience = function(configObj, experi
     sprintf(
       LOG_MESSAGES.AUDIENCE_EVALUATION_RESULT_COMBINED,
       MODULE_NAME,
-      experimentKey,
+      evaluationAttribute,
+      loggingKey || experimentKey,
       result.toString().toUpperCase()
     )
   );
 
-  if (!result) {
-    var userDoesNotMeetConditionsLogMessage = sprintf(
-      LOG_MESSAGES.USER_NOT_IN_EXPERIMENT,
-      MODULE_NAME,
-      userId,
-      experimentKey
-    );
-    this.logger.log(LOG_LEVEL.INFO, userDoesNotMeetConditionsLogMessage);
-    return false;
-  }
-
-  return true;
+  return result;
 };
 
 /**
@@ -335,25 +351,9 @@ DecisionService.prototype.__saveUserProfile = function(experiment, variation, us
 DecisionService.prototype.getVariationForFeature = function(configObj, feature, userId, attributes) {
   var experimentDecision = this._getVariationForFeatureExperiment(configObj, feature, userId, attributes);
   if (experimentDecision.variation !== null) {
-    this.logger.log(
-      LOG_LEVEL.DEBUG,
-      sprintf(
-        LOG_MESSAGES.USER_IN_FEATURE_EXPERIMENT,
-        MODULE_NAME,
-        userId,
-        experimentDecision.variation.key,
-        experimentDecision.experiment.key,
-        feature.key
-      )
-    );
     return experimentDecision;
   }
 
-  this.logger.log(
-    LOG_LEVEL.DEBUG,
-    sprintf(LOG_MESSAGES.USER_NOT_IN_FEATURE_EXPERIMENT, MODULE_NAME, userId, feature.key)
-  );
-
   var rolloutDecision = this._getVariationForRollout(configObj, feature, userId, attributes);
   if (rolloutDecision.variation !== null) {
     this.logger.log(LOG_LEVEL.DEBUG, sprintf(LOG_MESSAGES.USER_IN_ROLLOUT, MODULE_NAME, userId, feature.key));
@@ -456,50 +456,56 @@ DecisionService.prototype._getVariationForRollout = function(configObj, feature,
   // "everyone else", which will be evaluated separately outside this loop
   var endIndex = rollout.experiments.length - 1;
   var index;
-  var experiment;
+  var rolloutRule;
   var bucketerParams;
   var variationId;
   var variation;
+  var loggingKey;
   for (index = 0; index < endIndex; index++) {
-    experiment = configObj.experimentKeyMap[rollout.experiments[index].key];
+    rolloutRule = configObj.experimentKeyMap[rollout.experiments[index].key];
+    loggingKey = index + 1;
 
-    if (!this.__checkIfUserIsInAudience(configObj, experiment.key, userId, attributes)) {
+    if (!this.__checkIfUserIsInAudience(configObj, rolloutRule.key, AUDIENCE_EVALUATION_TYPES.RULE, userId, attributes, loggingKey)) {
       this.logger.log(
         LOG_LEVEL.DEBUG,
-        sprintf(LOG_MESSAGES.USER_DOESNT_MEET_CONDITIONS_FOR_TARGETING_RULE, MODULE_NAME, userId, index + 1)
+        sprintf(LOG_MESSAGES.USER_DOESNT_MEET_CONDITIONS_FOR_TARGETING_RULE, MODULE_NAME, userId, loggingKey)
       );
       continue;
     }
 
     this.logger.log(
       LOG_LEVEL.DEBUG,
-      sprintf(LOG_MESSAGES.USER_MEETS_CONDITIONS_FOR_TARGETING_RULE, MODULE_NAME, userId, index + 1)
+      sprintf(LOG_MESSAGES.USER_MEETS_CONDITIONS_FOR_TARGETING_RULE, MODULE_NAME, userId, loggingKey)
     );
-    bucketerParams = this.__buildBucketerParams(configObj, experiment.key, bucketingId, userId);
+    bucketerParams = this.__buildBucketerParams(configObj, rolloutRule.key, bucketingId, userId);
     variationId = bucketer.bucket(bucketerParams);
     variation = configObj.variationIdMap[variationId];
     if (variation) {
       this.logger.log(
         LOG_LEVEL.DEBUG,
-        sprintf(LOG_MESSAGES.USER_BUCKETED_INTO_TARGETING_RULE, MODULE_NAME, userId, index + 1)
+        sprintf(LOG_MESSAGES.USER_BUCKETED_INTO_TARGETING_RULE, MODULE_NAME, userId, loggingKey)
       );
       return {
-        experiment: experiment,
+        experiment: rolloutRule,
         variation: variation,
         decisionSource: DECISION_SOURCES.ROLLOUT,
       };
     } else {
       this.logger.log(
         LOG_LEVEL.DEBUG,
-        sprintf(LOG_MESSAGES.USER_NOT_BUCKETED_INTO_TARGETING_RULE, MODULE_NAME, userId, index + 1)
+        sprintf(LOG_MESSAGES.USER_NOT_BUCKETED_INTO_TARGETING_RULE, MODULE_NAME, userId, loggingKey)
       );
       break;
     }
   }
 
-  var everyoneElseExperiment = configObj.experimentKeyMap[rollout.experiments[endIndex].key];
-  if (this.__checkIfUserIsInAudience(configObj, everyoneElseExperiment.key, userId, attributes)) {
-    bucketerParams = this.__buildBucketerParams(configObj, everyoneElseExperiment.key, bucketingId, userId);
+  var everyoneElseRule = configObj.experimentKeyMap[rollout.experiments[endIndex].key];
+  if (this.__checkIfUserIsInAudience(configObj, everyoneElseRule.key, AUDIENCE_EVALUATION_TYPES.RULE, userId, attributes, 'Everyone Else')) {
+    this.logger.log(
+      LOG_LEVEL.DEBUG,
+      sprintf(LOG_MESSAGES.USER_MEETS_CONDITIONS_FOR_TARGETING_RULE, MODULE_NAME, userId, 'Everyone Else')
+    );
+    bucketerParams = this.__buildBucketerParams(configObj, everyoneElseRule.key, bucketingId, userId);
     variationId = bucketer.bucket(bucketerParams);
     variation = configObj.variationIdMap[variationId];
     if (variation) {
@@ -508,7 +514,7 @@ DecisionService.prototype._getVariationForRollout = function(configObj, feature,
         sprintf(LOG_MESSAGES.USER_BUCKETED_INTO_EVERYONE_TARGETING_RULE, MODULE_NAME, userId)
       );
       return {
-        experiment: everyoneElseExperiment,
+        experiment: everyoneElseRule,
         variation: variation,
         decisionSource: DECISION_SOURCES.ROLLOUT,
       };