From 3079270b3efc5e5971c1cc3c8dfa7dcd507a7c4b Mon Sep 17 00:00:00 2001 From: Florent Vilmart Date: Mon, 4 Sep 2017 20:47:49 -0400 Subject: [PATCH] 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 | 24 ++++++++ src/Adapters/Cache/InMemoryCacheAdapter.js | 15 ++--- src/Adapters/Storage/Mongo/MongoTransform.js | 15 +++-- src/Auth.js | 5 +- src/Controllers/LoggerController.js | 61 +++++++++++++++++++- src/ParseServer.js | 5 +- src/PromiseRouter.js | 19 +++--- src/logger.js | 7 ++- 8 files changed, 118 insertions(+), 33 deletions(-) diff --git a/spec/LoggerController.spec.js b/spec/LoggerController.spec.js index f4df8a91..3ce65433 100644 --- a/spec/LoggerController.spec.js +++ b/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(); + }); }); diff --git a/src/Adapters/Cache/InMemoryCacheAdapter.js b/src/Adapters/Cache/InMemoryCacheAdapter.js index 5be9a24e..585e2ead 100644 --- a/src/Adapters/Cache/InMemoryCacheAdapter.js +++ b/src/Adapters/Cache/InMemoryCacheAdapter.js @@ -7,18 +7,15 @@ export class InMemoryCacheAdapter { } get(key) { - return new Promise((resolve) => { - const record = this.cache.get(key); - if (record == null) { - return resolve(null); - } - - return resolve(JSON.parse(record)); - }) + const record = this.cache.get(key); + if (record === null) { + return Promise.resolve(null); + } + return Promise.resolve(record); } put(key, value, ttl) { - this.cache.put(key, JSON.stringify(value), ttl); + this.cache.put(key, value, ttl); return Promise.resolve(); } diff --git a/src/Adapters/Storage/Mongo/MongoTransform.js b/src/Adapters/Storage/Mongo/MongoTransform.js index f46c310e..c8ba3c29 100644 --- a/src/Adapters/Storage/Mongo/MongoTransform.js +++ b/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'; } diff --git a/src/Auth.js b/src/Auth.js index 150fa7ad..fcf59fcd 100644 --- a/src/Auth.js +++ b/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, this.userRoles); + cacheAdapter.role.put(this.user.id, Array(...this.userRoles)); return Promise.resolve(this.userRoles); }); }); diff --git a/src/Controllers/LoggerController.js b/src/Controllers/LoggerController.js index c87f8f46..5e5da683 100644 --- a/src/Controllers/LoggerController.js +++ b/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) { diff --git a/src/ParseServer.js b/src/ParseServer.js index 252c3cbd..be9d8160 100644 --- a/src/ParseServer.js +++ b/src/ParseServer.js @@ -173,8 +173,9 @@ class ParseServer { masterKeyIps ))); - const loggerControllerAdapter = loadAdapter(loggerAdapter, WinstonLoggerAdapter, { jsonLogs, logsFolder, verbose, logLevel, silent }); - const loggerController = new LoggerController(loggerControllerAdapter, appId); + const loggerOptions = { jsonLogs, logsFolder, verbose, logLevel, silent }; + const loggerControllerAdapter = loadAdapter(loggerAdapter, WinstonLoggerAdapter, loggerOptions); + const loggerController = new LoggerController(loggerControllerAdapter, appId, loggerOptions); logging.setLogger(loggerController); const filesControllerAdapter = loadAdapter(filesAdapter, () => { diff --git a/src/PromiseRouter.js b/src/PromiseRouter.js index 4d9a8873..e57b577f 100644 --- a/src/PromiseRouter.js +++ b/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); - log.verbose(`REQUEST for [${req.method}] ${url}: ${stringifiedBody}`, { - method: req.method, - url: url, - headers: req.headers, - body: body + const method = req.method; + const headers = req.headers; + log.logRequest({ + method, + url, + 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.verbose( - `RESPONSE from [${req.method}] ${url}: ${stringifiedResponse}`, - {result: result} - ); + log.logResponse({ method, url, result }); var status = result.status || 200; res.status(status); diff --git a/src/logger.js b/src/logger.js index 59baff39..ee69c42c 100644 --- a/src/logger.js +++ b/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 }); - return new LoggerController(adapter); + silent: defaults.silent }; + const adapter = new WinstonLoggerAdapter(options); + return new LoggerController(adapter, null, options); } let logger = defaultLogger();