Logging performance improvements

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

@@ -16,11 +16,13 @@
 import sinon from 'sinon';
 import { assert } from 'chai';
 import { getLogger } from '@optimizely/js-sdk-logging';
+import { sprintf } from '@optimizely/js-sdk-utils';
 
 import { createAudienceEvaluator } from './index';
 import * as conditionTreeEvaluator from '../condition_tree_evaluator';
 import * as customAttributeConditionEvaluator from '../custom_attribute_condition_evaluator';
 
+var buildLogMessageFromArgs = args => sprintf(args[1], ...args.splice(2));
 var mockLogger = getLogger();
 
 var chromeUserAudience = {
@@ -233,10 +235,10 @@ describe('lib/core/audience_evaluator', function() {
             assert.isFalse(result);
             assert.strictEqual(2, mockLogger.log.callCount);
             assert.strictEqual(
-              mockLogger.log.args[0][1],
+              buildLogMessageFromArgs(mockLogger.log.args[0]),
               'AUDIENCE_EVALUATOR: Starting to evaluate audience "1" with conditions: ["and",{"name":"device_model","value":"iphone","type":"custom_attribute"}].'
             );
-            assert.strictEqual(mockLogger.log.args[1][1], 'AUDIENCE_EVALUATOR: Audience "1" evaluated to UNKNOWN.');
+            assert.strictEqual(buildLogMessageFromArgs(mockLogger.log.args[1]), 'AUDIENCE_EVALUATOR: Audience "1" evaluated to UNKNOWN.');
           });
 
           it('logs correctly when conditionTreeEvaluator.evaluate returns true', function() {
@@ -255,10 +257,10 @@ describe('lib/core/audience_evaluator', function() {
             assert.isTrue(result);
             assert.strictEqual(2, mockLogger.log.callCount);
             assert.strictEqual(
-              mockLogger.log.args[0][1],
+              buildLogMessageFromArgs(mockLogger.log.args[0]),
               'AUDIENCE_EVALUATOR: Starting to evaluate audience "1" with conditions: ["and",{"name":"device_model","value":"iphone","type":"custom_attribute"}].'
             );
-            assert.strictEqual(mockLogger.log.args[1][1], 'AUDIENCE_EVALUATOR: Audience "1" evaluated to TRUE.');
+            assert.strictEqual(buildLogMessageFromArgs(mockLogger.log.args[1]), 'AUDIENCE_EVALUATOR: Audience "1" evaluated to TRUE.');
           });
 
           it('logs correctly when conditionTreeEvaluator.evaluate returns false', function() {
@@ -277,10 +279,10 @@ describe('lib/core/audience_evaluator', function() {
             assert.isFalse(result);
             assert.strictEqual(2, mockLogger.log.callCount);
             assert.strictEqual(
-              mockLogger.log.args[0][1],
+              buildLogMessageFromArgs(mockLogger.log.args[0]),
               'AUDIENCE_EVALUATOR: Starting to evaluate audience "1" with conditions: ["and",{"name":"device_model","value":"iphone","type":"custom_attribute"}].'
             );
-            assert.strictEqual(mockLogger.log.args[1][1], 'AUDIENCE_EVALUATOR: Audience "1" evaluated to FALSE.');
+            assert.strictEqual(buildLogMessageFromArgs(mockLogger.log.args[1]), 'AUDIENCE_EVALUATOR: Audience "1" evaluated to FALSE.');
           });
         });
       });

packages/optimizely-sdk/lib/core/audience_evaluator/index.ts

@@ -13,7 +13,6 @@
  * See the License for the specific language governing permissions and
  * limitations under the License.
  */
-import { sprintf } from '@optimizely/js-sdk-utils';
 import { getLogger } from '@optimizely/js-sdk-logging';
 
 import fns from '../../utils/fns';
@@ -77,14 +76,14 @@ export class AudienceEvaluator {
       if (audience) {
         logger.log(
           LOG_LEVEL.DEBUG,
-          sprintf(LOG_MESSAGES.EVALUATING_AUDIENCE, MODULE_NAME, audienceId, JSON.stringify(audience.conditions))
+          LOG_MESSAGES.EVALUATING_AUDIENCE, MODULE_NAME, audienceId, JSON.stringify(audience.conditions)
         );
         const result = conditionTreeEvaluator.evaluate(
           audience.conditions as unknown[] ,
           this.evaluateConditionWithUserAttributes.bind(this, userAttributes)
         );
         const resultText = result === null ? 'UNKNOWN' : result.toString().toUpperCase();
-        logger.log(LOG_LEVEL.DEBUG, sprintf(LOG_MESSAGES.AUDIENCE_EVALUATION_RESULT, MODULE_NAME, audienceId, resultText));
+        logger.log(LOG_LEVEL.DEBUG, LOG_MESSAGES.AUDIENCE_EVALUATION_RESULT, MODULE_NAME, audienceId, resultText);
         return result;
       }
       return null;
@@ -103,15 +102,15 @@ export class AudienceEvaluator {
   evaluateConditionWithUserAttributes(userAttributes: UserAttributes, condition: Condition): boolean | null {
     const evaluator = this.typeToEvaluatorMap[condition.type];
     if (!evaluator) {
-      logger.log(LOG_LEVEL.WARNING, sprintf(LOG_MESSAGES.UNKNOWN_CONDITION_TYPE, MODULE_NAME, JSON.stringify(condition)));
+      logger.log(LOG_LEVEL.WARNING, LOG_MESSAGES.UNKNOWN_CONDITION_TYPE, MODULE_NAME, JSON.stringify(condition));
       return null;
     }
     try {
       return evaluator.evaluate(condition, userAttributes);
     } catch (err) {
       logger.log(
         LOG_LEVEL.ERROR,
-        sprintf(ERROR_MESSAGES.CONDITION_EVALUATOR_ERROR, MODULE_NAME, condition.type, err.message)
+        ERROR_MESSAGES.CONDITION_EVALUATOR_ERROR, MODULE_NAME, condition.type, err.message
       );
     }
 

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

@@ -28,6 +28,7 @@ import { createLogger } from '../../plugins/logger';
 import projectConfig from '../project_config';
 import { getTestProjectConfig } from '../../tests/test_data';
 
+var buildLogMessageFromArgs = args => sprintf(args[1], ...args.splice(2));
 var testData = getTestProjectConfig();
 
 describe('lib/core/bucketer', function() {
@@ -75,7 +76,7 @@ describe('lib/core/bucketer', function() {
           var decisionResponse = bucketer.bucket(bucketerParamsTest1);
           expect(decisionResponse.result).to.equal('111128');
 
-          var bucketedUser_log1 = createdLogger.log.args[0][1];
+          var bucketedUser_log1 = buildLogMessageFromArgs(createdLogger.log.args[0]);
           expect(bucketedUser_log1).to.equal(
             sprintf(LOG_MESSAGES.USER_ASSIGNED_TO_EXPERIMENT_BUCKET, 'BUCKETER', '50', 'ppid1')
           );
@@ -84,7 +85,7 @@ describe('lib/core/bucketer', function() {
           bucketerParamsTest2.userId = 'ppid2';
           expect(bucketer.bucket(bucketerParamsTest2).result).to.equal(null);
 
-          var notBucketedUser_log1 = createdLogger.log.args[1][1];
+          var notBucketedUser_log1 = buildLogMessageFromArgs(createdLogger.log.args[1]);
 
           expect(notBucketedUser_log1).to.equal(
             sprintf(LOG_MESSAGES.USER_ASSIGNED_TO_EXPERIMENT_BUCKET, 'BUCKETER', '50000', 'ppid2')
@@ -137,12 +138,12 @@ describe('lib/core/bucketer', function() {
             sinon.assert.calledTwice(bucketerStub);
             sinon.assert.callCount(createdLogger.log, 3);
 
-            var log1 = createdLogger.log.args[0][1];
+            var log1 = buildLogMessageFromArgs(createdLogger.log.args[0]);
             expect(log1).to.equal(
               sprintf(LOG_MESSAGES.USER_ASSIGNED_TO_EXPERIMENT_BUCKET, 'BUCKETER', '50', 'testUser')
             );
 
-            var log2 = createdLogger.log.args[1][1];
+            var log2 = buildLogMessageFromArgs(createdLogger.log.args[1]);
             expect(log2).to.equal(
               sprintf(
                 LOG_MESSAGES.USER_BUCKETED_INTO_EXPERIMENT_IN_GROUP,
@@ -153,7 +154,7 @@ describe('lib/core/bucketer', function() {
               )
             );
 
-            var log3 = createdLogger.log.args[2][1];
+            var log3 = buildLogMessageFromArgs(createdLogger.log.args[2]);
             expect(log3).to.equal(
               sprintf(LOG_MESSAGES.USER_ASSIGNED_TO_EXPERIMENT_BUCKET, 'BUCKETER', '50', 'testUser')
             );
@@ -168,11 +169,11 @@ describe('lib/core/bucketer', function() {
             sinon.assert.calledOnce(bucketerStub);
             sinon.assert.calledTwice(createdLogger.log);
 
-            var log1 = createdLogger.log.args[0][1];
+            var log1 = buildLogMessageFromArgs(createdLogger.log.args[0]);
             expect(log1).to.equal(
               sprintf(LOG_MESSAGES.USER_ASSIGNED_TO_EXPERIMENT_BUCKET, 'BUCKETER', '5000', 'testUser')
             );
-            var log2 = createdLogger.log.args[1][1];
+            var log2 = buildLogMessageFromArgs(createdLogger.log.args[1]);
             expect(log2).to.equal(
               sprintf(
                 LOG_MESSAGES.USER_NOT_BUCKETED_INTO_EXPERIMENT_IN_GROUP,
@@ -193,11 +194,11 @@ describe('lib/core/bucketer', function() {
             sinon.assert.calledOnce(bucketerStub);
             sinon.assert.calledTwice(createdLogger.log);
 
-            var log1 = createdLogger.log.args[0][1];
+            var log1 = buildLogMessageFromArgs(createdLogger.log.args[0]);
             expect(log1).to.equal(
               sprintf(LOG_MESSAGES.USER_ASSIGNED_TO_EXPERIMENT_BUCKET, 'BUCKETER', '50000', 'testUser')
             );
-            var log2 = createdLogger.log.args[1][1];
+            var log2 = buildLogMessageFromArgs(createdLogger.log.args[1]);
             expect(log2).to.equal(sprintf(LOG_MESSAGES.USER_NOT_IN_ANY_EXPERIMENT, 'BUCKETER', 'testUser', '666'));
           });
 
@@ -210,11 +211,11 @@ describe('lib/core/bucketer', function() {
             sinon.assert.calledOnce(bucketerStub);
             sinon.assert.calledTwice(createdLogger.log);
 
-            var log1 = createdLogger.log.args[0][1];
+            var log1 = buildLogMessageFromArgs(createdLogger.log.args[0]);
             expect(log1).to.equal(
               sprintf(LOG_MESSAGES.USER_ASSIGNED_TO_EXPERIMENT_BUCKET, 'BUCKETER', '9000', 'testUser')
             );
-            var log2 = createdLogger.log.args[1][1];
+            var log2 = buildLogMessageFromArgs(createdLogger.log.args[1]);
             expect(log2).to.equal(sprintf(LOG_MESSAGES.USER_NOT_IN_ANY_EXPERIMENT, 'BUCKETER', 'testUser', '666'));
           });
 
@@ -252,7 +253,7 @@ describe('lib/core/bucketer', function() {
             sinon.assert.calledOnce(bucketerStub);
             sinon.assert.calledOnce(createdLogger.log);
 
-            var log1 = createdLogger.log.args[0][1];
+            var log1 = buildLogMessageFromArgs(createdLogger.log.args[0]);
             expect(log1).to.equal(sprintf(LOG_MESSAGES.USER_ASSIGNED_TO_EXPERIMENT_BUCKET, 'BUCKETER', '0', 'testUser'));
           });
 

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

@@ -56,7 +56,7 @@ const RANDOM_POLICY = 'random';
  *                                                                       null if user is not bucketed into any experiment and the decide reasons.
  */
 export const bucket = function(bucketerParams: BucketerParams): DecisionResponse<string | null> {
-  const decideReasons: string[] = [];
+  const decideReasons: (string | number)[][] = [];
   // Check if user is in a random group; if so, check if user is bucketed into a specific experiment
   const experiment = bucketerParams.experimentIdMap[bucketerParams.experimentId];
   const groupId = experiment['groupId'];
@@ -75,68 +75,89 @@ export const bucket = function(bucketerParams: BucketerParams): DecisionResponse
 
       // Return if user is not bucketed into any experiment
       if (bucketedExperimentId === null) {
-        const notbucketedInAnyExperimentLogMessage = sprintf(
+        bucketerParams.logger.log(
+          LOG_LEVEL.INFO,
           LOG_MESSAGES.USER_NOT_IN_ANY_EXPERIMENT,
           MODULE_NAME,
           bucketerParams.userId,
-          groupId
+          groupId,
         );
-        bucketerParams.logger.log(LOG_LEVEL.INFO, notbucketedInAnyExperimentLogMessage);
-        decideReasons.push(notbucketedInAnyExperimentLogMessage);
+        decideReasons.push([
+          LOG_MESSAGES.USER_NOT_IN_ANY_EXPERIMENT,
+          MODULE_NAME,
+          bucketerParams.userId,
+          groupId,
+        ]);
         return {
           result: null,
           reasons: decideReasons,
         };
       }
 
       // Return if user is bucketed into a different experiment than the one specified
-      if (bucketedExperimentId !== bucketerParams.experimentId) {
-        const notBucketedIntoExperimentOfGroupLogMessage = sprintf(
+      if (bucketedExperimentId !== bucketerParams.experimentId) {        
+        bucketerParams.logger.log(
+          LOG_LEVEL.INFO,
           LOG_MESSAGES.USER_NOT_BUCKETED_INTO_EXPERIMENT_IN_GROUP,
           MODULE_NAME,
           bucketerParams.userId,
           bucketerParams.experimentKey,
-          groupId
+          groupId,
         );
-        bucketerParams.logger.log(LOG_LEVEL.INFO, notBucketedIntoExperimentOfGroupLogMessage);
-        decideReasons.push(notBucketedIntoExperimentOfGroupLogMessage);
+        decideReasons.push([
+          LOG_MESSAGES.USER_NOT_BUCKETED_INTO_EXPERIMENT_IN_GROUP,
+          MODULE_NAME,
+          bucketerParams.userId,
+          bucketerParams.experimentKey,
+          groupId,
+        ]);
         return {
           result: null,
           reasons: decideReasons,
         };
       }
 
-      // Continue bucketing if user is bucketed into specified experiment
-      const bucketedIntoExperimentOfGroupLogMessage = sprintf(
+      // Continue bucketing if user is bucketed into specified experiment      
+      bucketerParams.logger.log(
+        LOG_LEVEL.INFO,
         LOG_MESSAGES.USER_BUCKETED_INTO_EXPERIMENT_IN_GROUP,
         MODULE_NAME,
         bucketerParams.userId,
         bucketerParams.experimentKey,
-        groupId
+        groupId,
       );
-      bucketerParams.logger.log(LOG_LEVEL.INFO, bucketedIntoExperimentOfGroupLogMessage);
-      decideReasons.push(bucketedIntoExperimentOfGroupLogMessage);
+      decideReasons.push([
+        LOG_MESSAGES.USER_BUCKETED_INTO_EXPERIMENT_IN_GROUP,
+        MODULE_NAME,
+        bucketerParams.userId,
+        bucketerParams.experimentKey,
+        groupId,
+      ]);
     }
   }
-  const bucketingId = sprintf('%s%s', bucketerParams.bucketingId, bucketerParams.experimentId);
+  const bucketingId = `${bucketerParams.bucketingId}${bucketerParams.experimentId}`;
   const bucketValue = _generateBucketValue(bucketingId);
-
-  const bucketedUserLogMessage = sprintf(
+
+  bucketerParams.logger.log(
+    LOG_LEVEL.DEBUG,
     LOG_MESSAGES.USER_ASSIGNED_TO_EXPERIMENT_BUCKET,
     MODULE_NAME,
     bucketValue,
-    bucketerParams.userId
+    bucketerParams.userId,
   );
-  bucketerParams.logger.log(LOG_LEVEL.DEBUG, bucketedUserLogMessage);
-  decideReasons.push(bucketedUserLogMessage);
+  decideReasons.push([
+    LOG_MESSAGES.USER_ASSIGNED_TO_EXPERIMENT_BUCKET,
+    MODULE_NAME,
+    bucketValue,
+    bucketerParams.userId,
+  ]);
 
   const entityId = _findBucket(bucketValue, bucketerParams.trafficAllocationConfig);
   if (entityId !== null) {
     if (!bucketerParams.variationIdMap[entityId]) {
-      if (entityId) {
-        const invalidVariationIdLogMessage = sprintf(LOG_MESSAGES.INVALID_VARIATION_ID, MODULE_NAME);
-        bucketerParams.logger.log(LOG_LEVEL.WARNING, invalidVariationIdLogMessage);
-        decideReasons.push(invalidVariationIdLogMessage);
+      if (entityId) {        
+        bucketerParams.logger.log(LOG_LEVEL.WARNING, LOG_MESSAGES.INVALID_VARIATION_ID, MODULE_NAME);
+        decideReasons.push([LOG_MESSAGES.INVALID_VARIATION_ID, MODULE_NAME]);
       }
       return {
         result: null,
@@ -165,11 +186,14 @@ export const bucketUserIntoExperiment = function(
   userId: string,
   logger: LogHandler
 ): string | null {
-  const bucketingKey = sprintf('%s%s', bucketingId, group.id);
+  const bucketingKey = `${bucketingId}${group.id}`;
   const bucketValue = _generateBucketValue(bucketingKey);
   logger.log(
     LOG_LEVEL.DEBUG,
-    sprintf(LOG_MESSAGES.USER_ASSIGNED_TO_EXPERIMENT_BUCKET, MODULE_NAME, bucketValue, userId)
+    LOG_MESSAGES.USER_ASSIGNED_TO_EXPERIMENT_BUCKET,
+    MODULE_NAME,
+    bucketValue,
+    userId,
   );
   const trafficAllocationConfig = group.trafficAllocation;
   const bucketedExperimentId = _findBucket(bucketValue, trafficAllocationConfig);