Optimizations (#4135)

* removes costly json serialization to InMemoryCacheAdapter

* Always cache a copy of the array

* Use own mapValues

* Makes sure we dont make unnecessary calls to the logger

* Do not bypass loggers with silent logging (only applies to stdout)

* warn is not warning

* use ===

* Wrap logRequest / logResponse in the loggerController for more granular control

Also give the ability to pass functions to the logger so we don't serialize too early in JSON (costly)

* reconfiguring winston would override the transports levels and make subsequent tests fail

spec/LoggerController.spec.js

@@ -88,4 +88,28 @@ describe('LoggerController', () => {
     }).toThrow();
     done();
   });
+
+  it('should replace implementations with verbose', (done) => {
+    const adapter = new WinstonLoggerAdapter();
+    const logger = new LoggerController(adapter, null, {verbose: true });
+    spyOn(adapter, "log");
+    logger.silly('yo!');
+    expect(adapter.log).not.toHaveBeenCalled();
+    done();
+  });
+
+  it('should replace implementations with logLevel', (done) => {
+    const adapter = new WinstonLoggerAdapter();
+    const logger = new LoggerController(adapter, null, { logLevel: 'error' });
+    spyOn(adapter, "log");
+    logger.warn('yo!');
+    logger.info('yo!');
+    logger.debug('yo!');
+    logger.verbose('yo!');
+    logger.silly('yo!');
+    expect(adapter.log).not.toHaveBeenCalled();
+    logger.error('error');
+    expect(adapter.log).toHaveBeenCalled();
+    done();
+  });
 });

src/Adapters/Cache/InMemoryCacheAdapter.js

@@ -7,18 +7,15 @@ export class InMemoryCacheAdapter {
   }
 
   get(key) {
-    return new Promise((resolve) => {
+    const record = this.cache.get(key);
-      const record = this.cache.get(key);
+    if (record === null) {
-      if (record == null) {
+      return Promise.resolve(null);
-        return resolve(null);
+    }
-      }
+    return Promise.resolve(record);
-
-      return resolve(JSON.parse(record));
-    })
   }
 
   put(key, value, ttl) {
-    this.cache.put(key, JSON.stringify(value), ttl);
+    this.cache.put(key, value, ttl);
     return Promise.resolve();
   }
 

src/Adapters/Storage/Mongo/MongoTransform.js

@@ -107,7 +107,7 @@ const transformKeyValueForUpdate = (className, restKey, restValue, parseFormatSc
   }
 
   // Handle normal objects by recursing
-  value = _.mapValues(restValue, transformInteriorValue);
+  value = mapValues(restValue, transformInteriorValue);
   return {key, value};
 }
 
@@ -132,7 +132,7 @@ const transformInteriorValue = restValue => {
   }
 
   // Handle normal objects by recursing
-  return _.mapValues(restValue, transformInteriorValue);
+  return mapValues(restValue, transformInteriorValue);
 }
 
 const valueAsDate = value => {
@@ -332,7 +332,7 @@ const parseObjectKeyValueToMongoObjectKeyValue = (restKey, restValue, schema) =>
   if (Object.keys(restValue).some(key => key.includes('$') || key.includes('.'))) {
     throw new Parse.Error(Parse.Error.INVALID_NESTED_KEY, "Nested keys should not contain the '$' or '.' characters");
   }
-  value = _.mapValues(restValue, transformInteriorValue);
+  value = mapValues(restValue, transformInteriorValue);
   return {key: restKey, value};
 }
 
@@ -789,6 +789,13 @@ function transformUpdateOperator({
     throw new Parse.Error(Parse.Error.COMMAND_UNAVAILABLE, `The ${__op} operator is not supported yet.`);
   }
 }
+function mapValues(object, iterator) {
+  const result = {};
+  Object.keys(object).forEach((key) => {
+    result[key] = iterator(object[key]);
+  });
+  return result;
+}
 
 const nestedMongoObjectToNestedParseObject = mongoObject => {
   switch(typeof mongoObject) {
@@ -829,7 +836,7 @@ const nestedMongoObjectToNestedParseObject = mongoObject => {
       return mongoObject;
     }
 
-    return _.mapValues(mongoObject, nestedMongoObjectToNestedParseObject);
+    return mapValues(mongoObject, nestedMongoObjectToNestedParseObject);
   default:
     throw 'unknown js type';
   }

src/Auth.js

@@ -135,7 +135,7 @@ Auth.prototype._loadRoles = function() {
         this.fetchedRoles = true;
         this.rolePromise = null;
 
-        cacheAdapter.role.put(this.user.id, this.userRoles);
+        cacheAdapter.role.put(this.user.id, Array(...this.userRoles));
         return Promise.resolve(this.userRoles);
       }
       var rolesMap = results.reduce((m, r) => {
@@ -152,8 +152,7 @@ Auth.prototype._loadRoles = function() {
           });
           this.fetchedRoles = true;
           this.rolePromise = null;
-
+          cacheAdapter.role.put(this.user.id, Array(...this.userRoles));
-          cacheAdapter.role.put(this.user.id, this.userRoles);
           return Promise.resolve(this.userRoles);
         });
     });

src/Controllers/LoggerController.js

@@ -17,8 +17,34 @@ export const LogOrder = {
   ASCENDING: 'asc'
 }
 
+const logLevels = [
+  'error',
+  'warn',
+  'info',
+  'debug',
+  'verbose',
+  'silly',
+]
+
 export class LoggerController extends AdaptableController {
 
+  constructor(adapter, appId, options = {logLevel: 'info'}) {
+    super(adapter, appId, options);
+    let level = 'info';
+    if (options.verbose) {
+      level = 'verbose';
+    }
+    if (options.logLevel) {
+      level = options.logLevel;
+    }
+    const index = logLevels.indexOf(level); // info by default
+    logLevels.forEach((level, levelIndex) => {
+      if (levelIndex > index) { // silence the levels that are > maxIndex
+        this[level] = () => {};
+      }
+    });
+  }
+
   maskSensitiveUrl(urlString) {
     const password = url.parse(urlString, true).query.password;
 
@@ -80,7 +106,10 @@ export class LoggerController extends AdaptableController {
   log(level, args) {
     // make the passed in arguments object an array with the spread operator
     args = this.maskSensitive([...args]);
-    args = [].concat(level, args);
+    args = [].concat(level, args.map((arg) => {
+      if (typeof arg === 'function') { return arg(); }
+      return arg;
+    }));
     this.adapter.log.apply(this.adapter, args);
   }
 
@@ -107,6 +136,36 @@ export class LoggerController extends AdaptableController {
   silly() {
     return this.log('silly', arguments);
   }
+
+  logRequest({
+    method,
+    url,
+    headers,
+    body
+  }) {
+    this.verbose(() => {
+      const stringifiedBody = JSON.stringify(body, null, 2);
+      return `REQUEST for [${method}] ${url}: ${stringifiedBody}`;
+    }, {
+      method,
+      url,
+      headers,
+      body
+    });
+  }
+
+  logResponse({
+    method,
+    url,
+    result
+  }) {
+    this.verbose(
+      () => { const stringifiedResponse = JSON.stringify(result, null, 2);
+        return `RESPONSE from [${method}] ${url}: ${stringifiedResponse}`;
+      },
+      {result: result}
+    );
+  }
   // check that date input is valid
   static validDateTime(date) {
     if (!date) {

src/ParseServer.js

@@ -173,8 +173,9 @@ class ParseServer {
       masterKeyIps
     )));
 
-    const loggerControllerAdapter = loadAdapter(loggerAdapter, WinstonLoggerAdapter, { jsonLogs, logsFolder, verbose, logLevel, silent });
+    const loggerOptions = { jsonLogs, logsFolder, verbose, logLevel, silent };
-    const loggerController = new LoggerController(loggerControllerAdapter, appId);
+    const loggerControllerAdapter = loadAdapter(loggerAdapter, WinstonLoggerAdapter, loggerOptions);
+    const loggerController = new LoggerController(loggerControllerAdapter, appId, loggerOptions);
     logging.setLogger(loggerController);
 
     const filesControllerAdapter = loadAdapter(filesAdapter, () => {

src/PromiseRouter.js

@@ -142,12 +142,13 @@ function makeExpressHandler(appId, promiseHandler) {
     try {
       const url = maskSensitiveUrl(req);
       const body = Object.assign({}, req.body);
-      const stringifiedBody = JSON.stringify(body, null, 2);
+      const method = req.method;
-      log.verbose(`REQUEST for [${req.method}] ${url}: ${stringifiedBody}`, {
+      const headers = req.headers;
-        method: req.method,
+      log.logRequest({
-        url: url,
+        method,
-        headers: req.headers,
+        url,
-        body: body
+        headers,
+        body
       });
       promiseHandler(req).then((result) => {
         if (!result.response && !result.location && !result.text) {
@@ -155,11 +156,7 @@ function makeExpressHandler(appId, promiseHandler) {
           throw 'control should not get here';
         }
 
-        const stringifiedResponse = JSON.stringify(result, null, 2);
+        log.logResponse({ method, url, result });
-        log.verbose(
-          `RESPONSE from [${req.method}] ${url}: ${stringifiedResponse}`,
-          {result: result}
-        );
 
         var status = result.status || 200;
         res.status(status);

src/logger.js

@@ -4,12 +4,13 @@ import { WinstonLoggerAdapter } from './Adapters/Logger/WinstonLoggerAdapter';
 import { LoggerController }     from './Controllers/LoggerController';
 
 function defaultLogger() {
-  const adapter = new WinstonLoggerAdapter({
+  const options = {
     logsFolder: defaults.logsFolder,
     jsonLogs: defaults.jsonLogs,
     verbose: defaults.verbose,
-    silent: defaults.silent });
+    silent: defaults.silent };
-  return new LoggerController(adapter);
+  const adapter = new WinstonLoggerAdapter(options);
+  return new LoggerController(adapter, null, options);
 }
 
 let logger = defaultLogger();