Merge pull request #606 from vinsewah/vc-react-server-with-timings

Update react-server to write server side timings/logs to the response document.

packages/react-server/core/logging/response.js

@@ -0,0 +1,86 @@
+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()) {
+		return RLS().queue || (RLS().queue = []);
+	}
+	else {
+		return [];
+	}
+}
+
+var pushToQueue = (module, lastModuleToken, key, level, msg, meta) => {
+	if (RLS.isActive() && !!RLS().doLog) {
+		var tuple = [
+			module,
+			msg,
+			meta[key],
+			lastModuleToken,
+		];
+		queue().push(tuple);
+	}
+}
+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) {
+		pushToQueue(this.module, this.lastModuleToken, this.key, level, msg, meta);
+		// Yield to the next log transport.
+		callback(null, true);
+	}
+}
+
+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);
+	}
+}
+
+var flushLogsToResponse = function(res) {
+	if (queue().length > 0) {
+		res.write("<script>");
+		res.write(`window.reactServerLogs = ${JSON.stringify(queue())};\n`);
+		res.write("</script>");
+	}
+}
+
+var setResponseLoggerPage = function(page) {
+	if (RLS.isActive() && !!page) {
+		RLS().doLog = page.getRequest().getQuery()._debug_output_logs;
+	}
+}
+module.exports = {setResponseLoggerPage, flushLogsToResponse, getTransportForGroup, TimeResponseLogger, ResponseLogger};

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),
 		],
 	});
 

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'),
+	{setResponseLoggerPage, flushLogsToResponse} = require('./logging/response');
 
 var _ = {
 	map: require('lodash/map'),
@@ -101,6 +102,7 @@ module.exports = function(server, routes) {
 			// Success.
 			navigateDfd.resolve();
 
+
 			if (err) {
 				// The page can elect to proceed to render
 				// even with a non-2xx response.  If it
@@ -130,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);
 
 		});
@@ -964,6 +968,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("</div></body></html>");
 	return Q();
 }