Transfer multiline log messages from Node to .NET without treating ea…

…ch line as a separate log entry
MarkPieszak · Jul 6, 2016 · Jul 6, 2016 · Jul 6, 2016 · Jul 6, 2016 · Jul 7, 2016
commit fae0a886af70d26eac6939fe4ec3dcf50b5460ce
diff --git a/src/Microsoft.AspNetCore.NodeServices/Content/Node/entrypoint-http.js b/src/Microsoft.AspNetCore.NodeServices/Content/Node/entrypoint-http.js
@@ -54,9 +54,10 @@
 	"use strict";
 	// Limit dependencies to core Node modules. This means the code in this file has to be very low-level and unattractive,
 	// but simplifies things for the consumer of this module.
-	var http = __webpack_require__(2);
-	var path = __webpack_require__(3);
-	var ArgsUtil_1 = __webpack_require__(4);
+	__webpack_require__(2);
+	var http = __webpack_require__(3);
+	var path = __webpack_require__(4);
+	var ArgsUtil_1 = __webpack_require__(5);
 	// Webpack doesn't support dynamic requires for files not present at compile time, so grab a direct
 	// reference to Node's runtime 'require' function.
 	var dynamicRequire = eval('require');
@@ -132,16 +133,57 @@
 /* 2 */
 /***/ function(module, exports) {
 
-	module.exports = require("http");
+	// When Node writes to stdout/strerr, we capture that and convert the lines into calls on the
+	// active .NET ILogger. But by default, stdout/stderr don't have any way of distinguishing
+	// linebreaks inside log messages from the linebreaks that delimit separate log messages,
+	// so multiline strings will end up being written to the ILogger as multiple independent
+	// log messages. This makes them very hard to make sense of, especially when they represent
+	// something like stack traces.
+	//
+	// To fix this, we intercept stdout/stderr writes, and replace internal linebreaks with a
+	// marker token. When .NET receives the lines, it converts the marker tokens back to regular
+	// linebreaks within the logged messages.
+	//
+	// Note that it's better to do the interception at the stdout/stderr level, rather than at
+	// the console.log/console.error (etc.) level, because this takes place after any native
+	// message formatting has taken place (e.g., inserting values for % placeholders).
+	var findInternalNewlinesRegex = /\n(?!$)/g;
+	var encodedNewline = '__ns_newline__';
+	encodeNewlinesWrittenToStream(process.stdout);
+	encodeNewlinesWrittenToStream(process.stderr);
+	function encodeNewlinesWrittenToStream(outputStream) {
+	    var origWriteFunction = outputStream.write;
+	    outputStream.write = function (value) {
+	        // Only interfere with the write if it's definitely a string
+	        if (typeof value === 'string') {
+	            var argsClone = Array.prototype.slice.call(arguments, 0);
+	            argsClone[0] = encodeNewlinesInString(value);
+	            origWriteFunction.apply(this, argsClone);
+	        }
+	        else {
+	            origWriteFunction.apply(this, arguments);
+	        }
+	    };
+	}
+	function encodeNewlinesInString(str) {
+	    return str.replace(findInternalNewlinesRegex, encodedNewline);
+	}
+
 
 /***/ },
 /* 3 */
 /***/ function(module, exports) {
 
-	module.exports = require("path");
+	module.exports = require("http");
 
 /***/ },
 /* 4 */
+/***/ function(module, exports) {
+
+	module.exports = require("path");
+
+/***/ },
+/* 5 */
 /***/ function(module, exports) {
 
 	"use strict";

diff --git a/src/Microsoft.AspNetCore.NodeServices/Content/Node/entrypoint-socket.js b/src/Microsoft.AspNetCore.NodeServices/Content/Node/entrypoint-socket.js
@@ -44,19 +44,60 @@
 /* 0 */
 /***/ function(module, exports, __webpack_require__) {
 
-	module.exports = __webpack_require__(5);
+	module.exports = __webpack_require__(6);
 
 
 /***/ },
 /* 1 */,
-/* 2 */,
-/* 3 */
+/* 2 */
 /***/ function(module, exports) {
 
-	module.exports = require("path");
+	// When Node writes to stdout/strerr, we capture that and convert the lines into calls on the
+	// active .NET ILogger. But by default, stdout/stderr don't have any way of distinguishing
+	// linebreaks inside log messages from the linebreaks that delimit separate log messages,
+	// so multiline strings will end up being written to the ILogger as multiple independent
+	// log messages. This makes them very hard to make sense of, especially when they represent
+	// something like stack traces.
+	//
+	// To fix this, we intercept stdout/stderr writes, and replace internal linebreaks with a
+	// marker token. When .NET receives the lines, it converts the marker tokens back to regular
+	// linebreaks within the logged messages.
+	//
+	// Note that it's better to do the interception at the stdout/stderr level, rather than at
+	// the console.log/console.error (etc.) level, because this takes place after any native
+	// message formatting has taken place (e.g., inserting values for % placeholders).
+	var findInternalNewlinesRegex = /\n(?!$)/g;
+	var encodedNewline = '__ns_newline__';
+	encodeNewlinesWrittenToStream(process.stdout);
+	encodeNewlinesWrittenToStream(process.stderr);
+	function encodeNewlinesWrittenToStream(outputStream) {
+	    var origWriteFunction = outputStream.write;
+	    outputStream.write = function (value) {
+	        // Only interfere with the write if it's definitely a string
+	        if (typeof value === 'string') {
+	            var argsClone = Array.prototype.slice.call(arguments, 0);
+	            argsClone[0] = encodeNewlinesInString(value);
+	            origWriteFunction.apply(this, argsClone);
+	        }
+	        else {
+	            origWriteFunction.apply(this, arguments);
+	        }
+	    };
+	}
+	function encodeNewlinesInString(str) {
+	    return str.replace(findInternalNewlinesRegex, encodedNewline);
+	}
+
 
 /***/ },
+/* 3 */,
 /* 4 */
+/***/ function(module, exports) {
+
+	module.exports = require("path");
+
+/***/ },
+/* 5 */
 /***/ function(module, exports) {
 
 	"use strict";
@@ -82,17 +123,18 @@
 
 
 /***/ },
-/* 5 */
+/* 6 */
 /***/ function(module, exports, __webpack_require__) {
 
 	"use strict";
 	// Limit dependencies to core Node modules. This means the code in this file has to be very low-level and unattractive,
 	// but simplifies things for the consumer of this module.
-	var net = __webpack_require__(6);
-	var path = __webpack_require__(3);
-	var readline = __webpack_require__(7);
-	var ArgsUtil_1 = __webpack_require__(4);
-	var virtualConnectionServer = __webpack_require__(8);
+	__webpack_require__(2);
+	var net = __webpack_require__(7);
+	var path = __webpack_require__(4);
+	var readline = __webpack_require__(8);
+	var ArgsUtil_1 = __webpack_require__(5);
+	var virtualConnectionServer = __webpack_require__(9);
 	// Webpack doesn't support dynamic requires for files not present at compile time, so grab a direct
 	// reference to Node's runtime 'require' function.
 	var dynamicRequire = eval('require');
@@ -150,24 +192,24 @@
 
 
 /***/ },
-/* 6 */
+/* 7 */
 /***/ function(module, exports) {
 
 	module.exports = require("net");
 
 /***/ },
-/* 7 */
+/* 8 */
 /***/ function(module, exports) {
 
 	module.exports = require("readline");
 
 /***/ },
-/* 8 */
+/* 9 */
 /***/ function(module, exports, __webpack_require__) {
 
 	"use strict";
-	var events_1 = __webpack_require__(9);
-	var VirtualConnection_1 = __webpack_require__(10);
+	var events_1 = __webpack_require__(10);
+	var VirtualConnection_1 = __webpack_require__(11);
 	// Keep this in sync with the equivalent constant in the .NET code. Both sides split up their transmissions into frames with this max length,
 	// and both will reject longer frames.
 	var MaxFrameBodyLength = 16 * 1024;
@@ -348,13 +390,13 @@
 
 
 /***/ },
-/* 9 */
+/* 10 */
 /***/ function(module, exports) {
 
 	module.exports = require("events");
 
 /***/ },
-/* 10 */
+/* 11 */
 /***/ function(module, exports, __webpack_require__) {
 
 	"use strict";
@@ -363,7 +405,7 @@
 	    function __() { this.constructor = d; }
 	    d.prototype = b === null ? Object.create(b) : (__.prototype = b.prototype, new __());
 	};
-	var stream_1 = __webpack_require__(11);
+	var stream_1 = __webpack_require__(12);
 	/**
 	 * Represents a virtual connection. Multiple virtual connections may be multiplexed over a single physical socket connection.
 	 */
@@ -404,7 +446,7 @@
 
 
 /***/ },
-/* 11 */
+/* 12 */
 /***/ function(module, exports) {
 
 	module.exports = require("stream");

diff --git a/src/Microsoft.AspNetCore.NodeServices/HostingModels/OutOfProcessNodeInstance.cs b/src/Microsoft.AspNetCore.NodeServices/HostingModels/OutOfProcessNodeInstance.cs
@@ -168,6 +168,18 @@ private static Process LaunchNodeProcess(ProcessStartInfo startInfo)
             return process;
         }
 
+        private static string UnencodeNewlines(string str)
+        {
+            if (str != null)
+            {
+                // The token here needs to match the const in OverrideStdOutputs.ts.
+                // See the comment there for why we're doing this.
+                str = str.Replace("__ns_newline__", Environment.NewLine);
+            }
+
+            return str;
+        }
+
         private void ConnectToInputOutputStreams()
         {
             var initializationIsCompleted = false;
@@ -181,7 +193,7 @@ private void ConnectToInputOutputStreams()
                 }
                 else if (evt.Data != null)
                 {
-                    OnOutputDataReceived(evt.Data);
+                    OnOutputDataReceived(UnencodeNewlines(evt.Data));
                 }
             };
 
@@ -197,7 +209,7 @@ private void ConnectToInputOutputStreams()
                     }
                     else
                     {
-                        OnErrorDataReceived(evt.Data);
+                        OnErrorDataReceived(UnencodeNewlines(evt.Data));
                     }
                 }
             };

diff --git a/src/Microsoft.AspNetCore.NodeServices/TypeScript/HttpNodeInstanceEntryPoint.ts b/src/Microsoft.AspNetCore.NodeServices/TypeScript/HttpNodeInstanceEntryPoint.ts
@@ -1,5 +1,6 @@
 // Limit dependencies to core Node modules. This means the code in this file has to be very low-level and unattractive,
 // but simplifies things for the consumer of this module.
+import './Util/OverrideStdOutputs';
 import * as http from 'http';
 import * as path from 'path';
 import { parseArgs } from './Util/ArgsUtil';

diff --git a/src/Microsoft.AspNetCore.NodeServices/TypeScript/SocketNodeInstanceEntryPoint.ts b/src/Microsoft.AspNetCore.NodeServices/TypeScript/SocketNodeInstanceEntryPoint.ts
@@ -1,5 +1,6 @@
 // Limit dependencies to core Node modules. This means the code in this file has to be very low-level and unattractive,
 // but simplifies things for the consumer of this module.
+import './Util/OverrideStdOutputs';
 import * as net from 'net';
 import * as path from 'path';
 import * as readline from 'readline';

diff --git a/src/Microsoft.AspNetCore.NodeServices/TypeScript/Util/OverrideStdOutputs.ts b/src/Microsoft.AspNetCore.NodeServices/TypeScript/Util/OverrideStdOutputs.ts
@@ -0,0 +1,37 @@
+// When Node writes to stdout/strerr, we capture that and convert the lines into calls on the
+// active .NET ILogger. But by default, stdout/stderr don't have any way of distinguishing
+// linebreaks inside log messages from the linebreaks that delimit separate log messages,
+// so multiline strings will end up being written to the ILogger as multiple independent
+// log messages. This makes them very hard to make sense of, especially when they represent
+// something like stack traces.
+//
+// To fix this, we intercept stdout/stderr writes, and replace internal linebreaks with a
+// marker token. When .NET receives the lines, it converts the marker tokens back to regular
+// linebreaks within the logged messages.
+//
+// Note that it's better to do the interception at the stdout/stderr level, rather than at
+// the console.log/console.error (etc.) level, because this takes place after any native
+// message formatting has taken place (e.g., inserting values for % placeholders).
+const findInternalNewlinesRegex = /\n(?!$)/g;
+const encodedNewline = '__ns_newline__';
+
+encodeNewlinesWrittenToStream(process.stdout);
+encodeNewlinesWrittenToStream(process.stderr);
+
+function encodeNewlinesWrittenToStream(outputStream: NodeJS.WritableStream) {
+    const origWriteFunction = outputStream.write;
+    outputStream.write = <any>function (value: any) {
+        // Only interfere with the write if it's definitely a string
+        if (typeof value === 'string') {
+            const argsClone = Array.prototype.slice.call(arguments, 0);
+            argsClone[0] = encodeNewlinesInString(value);
+            origWriteFunction.apply(this, argsClone);
+        } else {
+            origWriteFunction.apply(this, arguments);
+        }
+    };
+}
+
+function encodeNewlinesInString(str: string): string {
+    return str.replace(findInternalNewlinesRegex, encodedNewline);
+}