fix(default logger): log each message at the correct level (optimizely#209)

nchilada · mikeproeng37 · commit d6e68096d0c1 · 2019-01-24T11:14:45.000-08:00
diff --git a/packages/optimizely-sdk/lib/plugins/logger/index.js b/packages/optimizely-sdk/lib/plugins/logger/index.js
@@ -15,6 +15,9 @@
  */
 var fns = require('../../utils/fns');
 var enums = require('../../utils/enums');
+var sprintf = require('sprintf-js').sprintf;
+
+var MODULE_NAME = 'DEFAULT_LOGGER';
 
 /**
  * Default logger implementation
@@ -37,9 +40,9 @@ function Logger(config) {
     prefix: '[OPTIMIZELY]',
   }, config);
 
-  this.setLogLevel(config.logLevel);
   this.logToConsole = config.logToConsole;
   this.prefix = config.prefix;
+  this.setLogLevel(config.logLevel);
 }
 
 /**
@@ -50,7 +53,11 @@ function Logger(config) {
 Logger.prototype.log = function(logLevel, logMessage) {
   if (this.__shouldLog(logLevel)) {
     if (this.prefix) {
-      logMessage = this.prefix + ' - ' + this.logLevelName + ' ' + getTime() + ' ' + logMessage;
+      var logLevelName = getLogLevelName(logLevel);
+      logMessage = sprintf(
+        enums.DEFAULT_LOGGER_MESSAGE_TEMPLATE,
+        this.prefix, logLevelName, getTime(), logMessage
+      );
     }
 
     if (this.logToConsole) {
@@ -66,8 +73,8 @@ Logger.prototype.log = function(logLevel, logMessage) {
 Logger.prototype.setLogLevel = function(logLevel) {
   // Check that logLevel is valid, otherwise default to ERROR
   this.logLevel = (fns.values(enums.LOG_LEVEL).indexOf(logLevel) > -1) ? logLevel : enums.LOG_LEVEL.ERROR;
-  this.logLevelName = getLogLevelName(this.logLevel);
-  this.log('Setting log level to ' + logLevel);
+  var logLevelName = getLogLevelName(this.logLevel);
+  this.log(enums.LOG_LEVEL.DEBUG, sprintf(enums.LOG_MESSAGES.SET_LOG_LEVEL, MODULE_NAME, logLevelName));
 };
 
 /**
@@ -93,7 +100,7 @@ Logger.prototype.__consoleLog = function(logLevel, logArguments) {
       console.log.apply(console, logArguments);
       break;
     case enums.LOG_LEVEL.INFO:
-      console.log.apply(console, logArguments);
+      console.info.apply(console, logArguments);
       break;
     case enums.LOG_LEVEL.WARNING:
       console.warn.apply(console, logArguments);
diff --git a/packages/optimizely-sdk/lib/plugins/logger/index.tests.js b/packages/optimizely-sdk/lib/plugins/logger/index.tests.js
@@ -35,18 +35,47 @@ describe('lib/plugins/logger', function() {
     describe('log', function() {
       beforeEach(function() {
         defaultLogger = logger.createLogger({logLevel: LOG_LEVEL.INFO});
-        sinon.stub(defaultLogger, '__consoleLog');
+
+        sinon.stub(console, 'log');
+        sinon.stub(console, 'info');
+        sinon.stub(console, 'warn');
+        sinon.stub(console, 'error');
+      });
+
+      afterEach(function() {
+        console.log.restore();
+        console.info.restore();
+        console.warn.restore();
+        console.error.restore();
       });
 
-      it('should log the given message', function() {
+      it('should log a message at the threshold log level', function() {
         defaultLogger.log(LOG_LEVEL.INFO, 'message');
-        assert.isTrue(defaultLogger.__consoleLog.calledOnce);
-        assert.notStrictEqual(defaultLogger.__consoleLog.firstCall.args, [LOG_LEVEL.INFO, ['message']]);
+
+        sinon.assert.notCalled(console.log);
+        sinon.assert.calledOnce(console.info);
+        sinon.assert.calledWithExactly(console.info, sinon.match(/.*INFO.*message.*/));
+        sinon.assert.notCalled(console.warn);
+        sinon.assert.notCalled(console.error);
       });
 
-      it('should not log the message if the log level is lower than the current log level', function() {
+      it('should log a message if its log level is higher than the threshold log level', function() {
+        defaultLogger.log(LOG_LEVEL.WARNING, 'message');
+
+        sinon.assert.notCalled(console.log);
+        sinon.assert.notCalled(console.info);
+        sinon.assert.calledOnce(console.warn);
+        sinon.assert.calledWithExactly(console.warn, sinon.match(/.*WARNING.*message.*/));
+        sinon.assert.notCalled(console.error);
+      });
+
+      it('should not log a message if its log level is lower than the threshold log level', function() {
         defaultLogger.log(LOG_LEVEL.DEBUG, 'message');
-        assert.isTrue(defaultLogger.__consoleLog.notCalled);
+
+        sinon.assert.notCalled(console.log);
+        sinon.assert.notCalled(console.info);
+        sinon.assert.notCalled(console.warn);
+        sinon.assert.notCalled(console.error);
       });
     });
 
diff --git a/packages/optimizely-sdk/lib/utils/enums/index.js b/packages/optimizely-sdk/lib/utils/enums/index.js
@@ -88,6 +88,7 @@ exports.LOG_MESSAGES = {
   ROLLOUT_HAS_NO_EXPERIMENTS: '%s: Rollout of feature %s has no experiments',
   SAVED_VARIATION: '%s: Saved variation "%s" of experiment "%s" for user "%s".',
   SAVED_VARIATION_NOT_FOUND: '%s: User %s was previously bucketed into variation with ID %s for experiment %s, but no matching variation was found.',
+  SET_LOG_LEVEL: '%s: Setting log level to "%s"',
   SHOULD_NOT_DISPATCH_ACTIVATE: '%s: Experiment %s is in "Launched" state. Not activating user.',
   SKIPPING_JSON_VALIDATION: '%s: Skipping JSON schema validation.',
   TRACK_EVENT: '%s: Tracking event %s for user %s.',
@@ -125,6 +126,8 @@ exports.LOG_MESSAGES = {
   BUCKETING_ID_NOT_STRING: '%s: BucketingID attribute is not a string. Defaulted to userId',
 };
 
+exports.DEFAULT_LOGGER_MESSAGE_TEMPLATE = '%s - %s %s %s';
+
 exports.RESERVED_EVENT_KEYWORDS = {
   REVENUE: 'revenue',
   VALUE: 'value',
