From a2b327d2a14fe22842a603f5c3225149cced36de Mon Sep 17 00:00:00 2001 From: Vincent Chang Date: Mon, 22 Aug 2016 14:01:03 -0700 Subject: [PATCH 1/8] Update react-server to write server side timings/logs to the response document. See: https://github.com/redfin/react-server/issues/272 --- .../react-server/core/logging/response.js | 79 +++++++++++++++++++ packages/react-server/core/logging/server.js | 5 +- .../react-server/core/renderMiddleware.js | 9 +++ 3 files changed, 91 insertions(+), 2 deletions(-) create mode 100644 packages/react-server/core/logging/response.js diff --git a/packages/react-server/core/logging/response.js b/packages/react-server/core/logging/response.js new file mode 100644 index 000000000..eafbf9c1e --- /dev/null +++ b/packages/react-server/core/logging/response.js @@ -0,0 +1,79 @@ +var common = require('./common') +, SuperLogger = process.env.IS_SERVER ? require('winston').Transport : class {} +, RLS = require('../util/RequestLocalStorage').getNamespace(); + +// A subset of stats that are logged are not associated with requests +// or occur before the request context is initialized. Simply ignore +// those logs here. +var queue = () => { + if(RLS.isActive()) { + return RLS().queue || (RLS().queue = []); + } + else { + return []; + } +} + +class ResponseLogger extends SuperLogger { + constructor(options) { + super(); + this.name = 'ResponseLogger'; + this.level = options.level || 'debug'; + this.module = options.name; + this.lastModuleToken = options.name.split('.').pop(); + } + + log(level, msg, meta, callback) { + var tuple = [ + this.module, + msg, + meta[this.key], + this.lastModuleToken, + ]; + + queue().push(tuple); + // Yield to the next log transport. + callback(null, true); + } + + flushToResponse(res) { + if(queue().length > 0) { + res.write(""); + } + } +} + +class TimeResponseLogger extends ResponseLogger { + constructor(options){ + super(options); + this.name = 'TimeResponseLogger'; + this.level = 'fast'; + this.key = 'ms'; + } +} + +class GaugeResponseLogger extends ResponseLogger { + constructor(options){ + super(options); + this.name = 'GaugeResponseLogger'; + this.level = 'ok'; + this.key = 'val'; + } +} + +var getTransportForGroup = function(group, opts) { + if(group == "time") { + return new TimeResponseLogger(opts); + } + else if(group == "gauge") { + return new GaugeResponseLogger(opts); + } + else { + return new ResponseLogger(opts); + } +} + +module.exports = {getTransportForGroup, TimeResponseLogger, TimeResponseLogger, ResponseLogger}; diff --git a/packages/react-server/core/logging/server.js b/packages/react-server/core/logging/server.js index abb5bd059..2eed15fa5 100644 --- a/packages/react-server/core/logging/server.js +++ b/packages/react-server/core/logging/server.js @@ -7,11 +7,11 @@ var winston = require('winston') isEmpty : require("lodash/isEmpty"), trimStart : require("lodash/trimStart"), truncate : require("lodash/truncate"), -}; +} +, responseTransport = require('./response'); var makeLogger = function(group, opts){ var config = common.config[group]; - var fileTransport = new (winston.transports.File)({ name : 'file', level : config.baseLevel, @@ -23,6 +23,7 @@ var makeLogger = function(group, opts){ var logger = new (winston.Logger)({ transports: [ fileTransport, + responseTransport.getTransportForGroup(group, opts), ], }); diff --git a/packages/react-server/core/renderMiddleware.js b/packages/react-server/core/renderMiddleware.js index 58b64ae6b..0e5b09b4a 100644 --- a/packages/react-server/core/renderMiddleware.js +++ b/packages/react-server/core/renderMiddleware.js @@ -751,6 +751,15 @@ function writeBody(req, res, context, start, page) { // Don't leave dead timers hanging around. retval.promise.then(() => clearTimeout(timeout)); + // Flush timing/log data to the response document + retval.promise.then(() => { + if (req.query._debug_output_logs) { + logger.transports.ResponseLogger.flushToResponse(res); + logger.timeLogger.transports.TimeResponseLogger.flushToResponse(res); + logger.gaugeLogger.transports.GaugeResponseLogger.flushToResponse(res); + } + }); + return retval.promise; } From 4a6730990d004735244e61d9dd786187d82af374 Mon Sep 17 00:00:00 2001 From: Vincent Chang Date: Mon, 22 Aug 2016 16:37:03 -0700 Subject: [PATCH 2/8] Moving the call to flush logs to just before the close body tag 1. Expose method flushLogsResponse as a public method of the ResponseLogger module 2. Move call to flushLogsResponse to closeBody in renderMiddleware 3. Increment the version of request-local-storage in package.json to expose isActive() convenience method on the RLS --- .../react-server/core/logging/response.js | 19 +++++++++---------- .../react-server/core/renderMiddleware.js | 16 ++++++---------- 2 files changed, 15 insertions(+), 20 deletions(-) diff --git a/packages/react-server/core/logging/response.js b/packages/react-server/core/logging/response.js index eafbf9c1e..faff8c6c6 100644 --- a/packages/react-server/core/logging/response.js +++ b/packages/react-server/core/logging/response.js @@ -35,15 +35,6 @@ class ResponseLogger extends SuperLogger { // Yield to the next log transport. callback(null, true); } - - flushToResponse(res) { - if(queue().length > 0) { - res.write(""); - } - } } class TimeResponseLogger extends ResponseLogger { @@ -76,4 +67,12 @@ var getTransportForGroup = function(group, opts) { } } -module.exports = {getTransportForGroup, TimeResponseLogger, TimeResponseLogger, ResponseLogger}; +var flushLogsToResponse = function(res) { + if(queue().length > 0) { + res.write(""); + } +} +module.exports = {flushLogsToResponse, getTransportForGroup, TimeResponseLogger, TimeResponseLogger, ResponseLogger}; diff --git a/packages/react-server/core/renderMiddleware.js b/packages/react-server/core/renderMiddleware.js index 0e5b09b4a..3085a6f2b 100644 --- a/packages/react-server/core/renderMiddleware.js +++ b/packages/react-server/core/renderMiddleware.js @@ -16,7 +16,8 @@ var logger = require('./logging').getLogger(__LOGGER__), ReactServerAgent = require('./ReactServerAgent'), StringEscapeUtil = require('./util/StringEscapeUtil'), {getRootElementAttributes} = require('./components/RootElement'), - {PAGE_CSS_NODE_ID, PAGE_LINK_NODE_ID, PAGE_CONTENT_NODE_ID, PAGE_CONTAINER_NODE_ID} = require('./constants'); + {PAGE_CSS_NODE_ID, PAGE_LINK_NODE_ID, PAGE_CONTENT_NODE_ID, PAGE_CONTAINER_NODE_ID} = require('./constants'), + {flushLogsToResponse} = require('./logging/response'); var _ = { map: require('lodash/map'), @@ -751,15 +752,6 @@ function writeBody(req, res, context, start, page) { // Don't leave dead timers hanging around. retval.promise.then(() => clearTimeout(timeout)); - // Flush timing/log data to the response document - retval.promise.then(() => { - if (req.query._debug_output_logs) { - logger.transports.ResponseLogger.flushToResponse(res); - logger.timeLogger.transports.TimeResponseLogger.flushToResponse(res); - logger.gaugeLogger.transports.GaugeResponseLogger.flushToResponse(res); - } - }); - return retval.promise; } @@ -973,6 +965,10 @@ function wrapUpLateArrivals(){ } function closeBody(req, res) { + // Flush timing/log data to the response document + if (req.query._debug_output_logs) { + flushLogsToResponse(res); + } res.write(""); return Q(); } From 5caa27a3bda79a71bec51a28a325a6200fab2232 Mon Sep 17 00:00:00 2001 From: Vincent Chang Date: Mon, 22 Aug 2016 17:05:17 -0700 Subject: [PATCH 3/8] Fixing the linter errors. --- packages/react-server/core/logging/response.js | 15 +++++++-------- 1 file changed, 7 insertions(+), 8 deletions(-) diff --git a/packages/react-server/core/logging/response.js b/packages/react-server/core/logging/response.js index faff8c6c6..e26b71c65 100644 --- a/packages/react-server/core/logging/response.js +++ b/packages/react-server/core/logging/response.js @@ -1,12 +1,11 @@ -var common = require('./common') -, SuperLogger = process.env.IS_SERVER ? require('winston').Transport : class {} -, RLS = require('../util/RequestLocalStorage').getNamespace(); +var SuperLogger = require('winston').Transport +, RLS = require('../util/RequestLocalStorage').getNamespace(); // A subset of stats that are logged are not associated with requests // or occur before the request context is initialized. Simply ignore // those logs here. var queue = () => { - if(RLS.isActive()) { + if (RLS.isActive()) { return RLS().queue || (RLS().queue = []); } else { @@ -56,10 +55,10 @@ class GaugeResponseLogger extends ResponseLogger { } var getTransportForGroup = function(group, opts) { - if(group == "time") { + if (group === "time") { return new TimeResponseLogger(opts); } - else if(group == "gauge") { + else if (group === "gauge") { return new GaugeResponseLogger(opts); } else { @@ -68,11 +67,11 @@ var getTransportForGroup = function(group, opts) { } var flushLogsToResponse = function(res) { - if(queue().length > 0) { + if (queue().length > 0) { res.write(""); } } -module.exports = {flushLogsToResponse, getTransportForGroup, TimeResponseLogger, TimeResponseLogger, ResponseLogger}; +module.exports = {flushLogsToResponse, getTransportForGroup, TimeResponseLogger, ResponseLogger}; From 0d0960607f13b371ba43dcadaac03516b16cf676 Mon Sep 17 00:00:00 2001 From: Vincent Chang Date: Wed, 24 Aug 2016 16:06:04 -0700 Subject: [PATCH 4/8] Perf tweak: Don't log anything to the response document unless the page request is asking for it. --- .../react-server/core/logging/response.js | 21 +++++++++++++------ .../react-server/core/renderMiddleware.js | 5 ++++- 2 files changed, 19 insertions(+), 7 deletions(-) diff --git a/packages/react-server/core/logging/response.js b/packages/react-server/core/logging/response.js index e26b71c65..a156e74f0 100644 --- a/packages/react-server/core/logging/response.js +++ b/packages/react-server/core/logging/response.js @@ -1,5 +1,5 @@ -var SuperLogger = require('winston').Transport -, RLS = require('../util/RequestLocalStorage').getNamespace(); +var SuperLogger = require('winston').Transport +, RLS = require('../util/RequestLocalStorage').getNamespace(); // A subset of stats that are logged are not associated with requests // or occur before the request context is initialized. Simply ignore @@ -13,6 +13,11 @@ var queue = () => { } } +var pushToQueue = (tuple) => { + if (RLS.isActive() && !!RLS().doLog) { + queue().push(tuple); + } +} class ResponseLogger extends SuperLogger { constructor(options) { super(); @@ -29,8 +34,7 @@ class ResponseLogger extends SuperLogger { meta[this.key], this.lastModuleToken, ]; - - queue().push(tuple); + pushToQueue(tuple); // Yield to the next log transport. callback(null, true); } @@ -69,9 +73,14 @@ var getTransportForGroup = function(group, opts) { var flushLogsToResponse = function(res) { if (queue().length > 0) { res.write(""); } } -module.exports = {flushLogsToResponse, getTransportForGroup, TimeResponseLogger, ResponseLogger}; + +var setResponseLoggerPage = function(page) { + if (RLS.isActive()) { + RLS().doLog = page.getRequest().getQuery()._debug_output_logs; + } +} +module.exports = {setResponseLoggerPage, flushLogsToResponse, getTransportForGroup, TimeResponseLogger, ResponseLogger}; diff --git a/packages/react-server/core/renderMiddleware.js b/packages/react-server/core/renderMiddleware.js index 3085a6f2b..ba9d9e00a 100644 --- a/packages/react-server/core/renderMiddleware.js +++ b/packages/react-server/core/renderMiddleware.js @@ -17,7 +17,7 @@ var logger = require('./logging').getLogger(__LOGGER__), StringEscapeUtil = require('./util/StringEscapeUtil'), {getRootElementAttributes} = require('./components/RootElement'), {PAGE_CSS_NODE_ID, PAGE_LINK_NODE_ID, PAGE_CONTENT_NODE_ID, PAGE_CONTAINER_NODE_ID} = require('./constants'), - {flushLogsToResponse} = require('./logging/response'); + {setResponseLoggerPage, flushLogsToResponse} = require('./logging/response'); var _ = { map: require('lodash/map'), @@ -102,6 +102,9 @@ module.exports = function(server, routes) { // Success. navigateDfd.resolve(); + // Set the page context on the response logger so it can figure + // out whether to flush logs to the response document + setResponseLoggerPage(page); if (err) { // The page can elect to proceed to render // even with a non-2xx response. If it From f160d1c766608602fb8de64788d187452f9c6282 Mon Sep 17 00:00:00 2001 From: Vincent Chang Date: Wed, 24 Aug 2016 16:22:50 -0700 Subject: [PATCH 5/8] Unbreaking the build: handling the null case on setResponseLoggerPage --- packages/react-server/core/logging/response.js | 2 +- packages/react-server/core/renderMiddleware.js | 8 ++++---- 2 files changed, 5 insertions(+), 5 deletions(-) diff --git a/packages/react-server/core/logging/response.js b/packages/react-server/core/logging/response.js index a156e74f0..dbf136a1d 100644 --- a/packages/react-server/core/logging/response.js +++ b/packages/react-server/core/logging/response.js @@ -79,7 +79,7 @@ var flushLogsToResponse = function(res) { } var setResponseLoggerPage = function(page) { - if (RLS.isActive()) { + if (RLS.isActive() || !!page) { RLS().doLog = page.getRequest().getQuery()._debug_output_logs; } } diff --git a/packages/react-server/core/renderMiddleware.js b/packages/react-server/core/renderMiddleware.js index ba9d9e00a..91a9e633f 100644 --- a/packages/react-server/core/renderMiddleware.js +++ b/packages/react-server/core/renderMiddleware.js @@ -102,9 +102,7 @@ module.exports = function(server, routes) { // Success. navigateDfd.resolve(); - // Set the page context on the response logger so it can figure - // out whether to flush logs to the response document - setResponseLoggerPage(page); + if (err) { // The page can elect to proceed to render // even with a non-2xx response. If it @@ -134,7 +132,9 @@ module.exports = function(server, routes) { return; } } - + // Set the page context on the response logger so it can figure + // out whether to flush logs to the response document + setResponseLoggerPage(page); renderPage(req, res, context, start, page); }); From a1c8c3fe636673593135d994b8d2fcdc0aba9df2 Mon Sep 17 00:00:00 2001 From: Vincent Chang Date: Mon, 22 Aug 2016 14:01:03 -0700 Subject: [PATCH 6/8] Update react-server to write server side timings/logs to the response document. See: https://github.com/redfin/react-server/issues/272 --- packages/react-server/core/renderMiddleware.js | 9 +++++++++ 1 file changed, 9 insertions(+) diff --git a/packages/react-server/core/renderMiddleware.js b/packages/react-server/core/renderMiddleware.js index 91a9e633f..925cf322a 100644 --- a/packages/react-server/core/renderMiddleware.js +++ b/packages/react-server/core/renderMiddleware.js @@ -755,6 +755,15 @@ function writeBody(req, res, context, start, page) { // Don't leave dead timers hanging around. retval.promise.then(() => clearTimeout(timeout)); + // Flush timing/log data to the response document + retval.promise.then(() => { + if (req.query._debug_output_logs) { + logger.transports.ResponseLogger.flushToResponse(res); + logger.timeLogger.transports.TimeResponseLogger.flushToResponse(res); + logger.gaugeLogger.transports.GaugeResponseLogger.flushToResponse(res); + } + }); + return retval.promise; } From b7346f7f0869383f8fcfbbd6e94824240176c801 Mon Sep 17 00:00:00 2001 From: Vincent Chang Date: Mon, 22 Aug 2016 16:37:03 -0700 Subject: [PATCH 7/8] Moving the call to flush logs to just before the close body tag 1. Expose method flushLogsResponse as a public method of the ResponseLogger module 2. Move call to flushLogsResponse to closeBody in renderMiddleware 3. Increment the version of request-local-storage in package.json to expose isActive() convenience method on the RLS --- packages/react-server/core/renderMiddleware.js | 9 --------- 1 file changed, 9 deletions(-) diff --git a/packages/react-server/core/renderMiddleware.js b/packages/react-server/core/renderMiddleware.js index 925cf322a..91a9e633f 100644 --- a/packages/react-server/core/renderMiddleware.js +++ b/packages/react-server/core/renderMiddleware.js @@ -755,15 +755,6 @@ function writeBody(req, res, context, start, page) { // Don't leave dead timers hanging around. retval.promise.then(() => clearTimeout(timeout)); - // Flush timing/log data to the response document - retval.promise.then(() => { - if (req.query._debug_output_logs) { - logger.transports.ResponseLogger.flushToResponse(res); - logger.timeLogger.transports.TimeResponseLogger.flushToResponse(res); - logger.gaugeLogger.transports.GaugeResponseLogger.flushToResponse(res); - } - }); - return retval.promise; } From a3170c99fc79c8014a3c0b8b3ccf59ed258c8cad Mon Sep 17 00:00:00 2001 From: Vincent Chang Date: Fri, 26 Aug 2016 13:17:16 -0700 Subject: [PATCH 8/8] =?UTF-8?q?Don=E2=80=99t=20create=20any=20tuples=20or?= =?UTF-8?q?=20push=20them=20to=20the=20queue=20if=20log()=20is=20not=20cal?= =?UTF-8?q?led=20within=20the=20context=20of=20a=20request.?= MIME-Version: 1.0 Content-Type: text/plain; charset=UTF-8 Content-Transfer-Encoding: 8bit --- .../react-server/core/logging/response.js | 20 +++++++++---------- 1 file changed, 10 insertions(+), 10 deletions(-) diff --git a/packages/react-server/core/logging/response.js b/packages/react-server/core/logging/response.js index dbf136a1d..67249c326 100644 --- a/packages/react-server/core/logging/response.js +++ b/packages/react-server/core/logging/response.js @@ -13,8 +13,14 @@ var queue = () => { } } -var pushToQueue = (tuple) => { +var pushToQueue = (module, lastModuleToken, key, level, msg, meta) => { if (RLS.isActive() && !!RLS().doLog) { + var tuple = [ + module, + msg, + meta[key], + lastModuleToken, + ]; queue().push(tuple); } } @@ -28,13 +34,7 @@ class ResponseLogger extends SuperLogger { } log(level, msg, meta, callback) { - var tuple = [ - this.module, - msg, - meta[this.key], - this.lastModuleToken, - ]; - pushToQueue(tuple); + pushToQueue(this.module, this.lastModuleToken, this.key, level, msg, meta); // Yield to the next log transport. callback(null, true); } @@ -70,7 +70,7 @@ var getTransportForGroup = function(group, opts) { } } -var flushLogsToResponse = function(res) { +var flushLogsToResponse = function(res) { if (queue().length > 0) { res.write("