From fae0a886af70d26eac6939fe4ec3dcf50b5460ce Mon Sep 17 00:00:00 2001 From: SteveSandersonMS Date: Mon, 18 Jul 2016 16:34:36 +0100 Subject: [PATCH] Transfer multiline log messages from Node to .NET without treating each line as a separate log entry --- .../Content/Node/entrypoint-http.js | 52 ++++++++++-- .../Content/Node/entrypoint-socket.js | 80 ++++++++++++++----- .../HostingModels/OutOfProcessNodeInstance.cs | 16 +++- .../TypeScript/HttpNodeInstanceEntryPoint.ts | 1 + .../SocketNodeInstanceEntryPoint.ts | 1 + .../TypeScript/Util/OverrideStdOutputs.ts | 37 +++++++++ 6 files changed, 161 insertions(+), 26 deletions(-) create mode 100644 src/Microsoft.AspNetCore.NodeServices/TypeScript/Util/OverrideStdOutputs.ts diff --git a/src/Microsoft.AspNetCore.NodeServices/Content/Node/entrypoint-http.js b/src/Microsoft.AspNetCore.NodeServices/Content/Node/entrypoint-http.js index ab728ae..fef873e 100644 --- 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 index 1585613..e59b6ed 100644 --- 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) { + + // 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"); /***/ }, -/* 4 */ +/* 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 index 0cba1cd..0664999 100644 --- a/src/Microsoft.AspNetCore.NodeServices/HostingModels/OutOfProcessNodeInstance.cs +++ b/src/Microsoft.AspNetCore.NodeServices/HostingModels/OutOfProcessNodeInstance.cs @@ -168,6 +168,18 @@ namespace Microsoft.AspNetCore.NodeServices.HostingModels 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 @@ namespace Microsoft.AspNetCore.NodeServices.HostingModels } else if (evt.Data != null) { - OnOutputDataReceived(evt.Data); + OnOutputDataReceived(UnencodeNewlines(evt.Data)); } }; @@ -197,7 +209,7 @@ namespace Microsoft.AspNetCore.NodeServices.HostingModels } 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 index 3be759a..0e10d99 100644 --- 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 index 0aec541..0a6f713 100644 --- 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 new file mode 100644 index 0000000..01e4bc6 --- /dev/null +++ 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 = 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); +}