Skip to content

Commit fae0a88

Browse files
SteveSandersonMSSteveSandersonMS
committed
Transfer multiline log messages from Node to .NET without treating each line as a separate log entry
1 parent f4efcac commit fae0a88

6 files changed

Lines changed: 161 additions & 26 deletions

File tree

‎src/Microsoft.AspNetCore.NodeServices/Content/Node/entrypoint-http.js‎

Lines changed: 47 additions & 5 deletions
Original file line numberDiff line numberDiff line change
@@ -54,9 +54,10 @@
5454
"use strict";
5555
// Limit dependencies to core Node modules. This means the code in this file has to be very low-level and unattractive,
5656
// but simplifies things for the consumer of this module.
57-
var http = __webpack_require__(2);
58-
var path = __webpack_require__(3);
59-
var ArgsUtil_1 = __webpack_require__(4);
57+
__webpack_require__(2);
58+
var http = __webpack_require__(3);
59+
var path = __webpack_require__(4);
60+
var ArgsUtil_1 = __webpack_require__(5);
6061
// Webpack doesn't support dynamic requires for files not present at compile time, so grab a direct
6162
// reference to Node's runtime 'require' function.
6263
var dynamicRequire = eval('require');
@@ -132,16 +133,57 @@
132133
/* 2 */
133134
/***/ function(module, exports) {
134135

135-
module.exports = require("http");
136+
// When Node writes to stdout/strerr, we capture that and convert the lines into calls on the
137+
// active .NET ILogger. But by default, stdout/stderr don't have any way of distinguishing
138+
// linebreaks inside log messages from the linebreaks that delimit separate log messages,
139+
// so multiline strings will end up being written to the ILogger as multiple independent
140+
// log messages. This makes them very hard to make sense of, especially when they represent
141+
// something like stack traces.
142+
//
143+
// To fix this, we intercept stdout/stderr writes, and replace internal linebreaks with a
144+
// marker token. When .NET receives the lines, it converts the marker tokens back to regular
145+
// linebreaks within the logged messages.
146+
//
147+
// Note that it's better to do the interception at the stdout/stderr level, rather than at
148+
// the console.log/console.error (etc.) level, because this takes place after any native
149+
// message formatting has taken place (e.g., inserting values for % placeholders).
150+
var findInternalNewlinesRegex = /\n(?!$)/g;
151+
var encodedNewline = '__ns_newline__';
152+
encodeNewlinesWrittenToStream(process.stdout);
153+
encodeNewlinesWrittenToStream(process.stderr);
154+
function encodeNewlinesWrittenToStream(outputStream) {
155+
var origWriteFunction = outputStream.write;
156+
outputStream.write = function (value) {
157+
// Only interfere with the write if it's definitely a string
158+
if (typeof value === 'string') {
159+
var argsClone = Array.prototype.slice.call(arguments, 0);
160+
argsClone[0] = encodeNewlinesInString(value);
161+
origWriteFunction.apply(this, argsClone);
162+
}
163+
else {
164+
origWriteFunction.apply(this, arguments);
165+
}
166+
};
167+
}
168+
function encodeNewlinesInString(str) {
169+
return str.replace(findInternalNewlinesRegex, encodedNewline);
170+
}
171+
136172

137173
/***/ },
138174
/* 3 */
139175
/***/ function(module, exports) {
140176

141-
module.exports = require("path");
177+
module.exports = require("http");
142178

143179
/***/ },
144180
/* 4 */
181+
/***/ function(module, exports) {
182+
183+
module.exports = require("path");
184+
185+
/***/ },
186+
/* 5 */
145187
/***/ function(module, exports) {
146188

147189
"use strict";

‎src/Microsoft.AspNetCore.NodeServices/Content/Node/entrypoint-socket.js‎

Lines changed: 61 additions & 19 deletions
Original file line numberDiff line numberDiff line change
@@ -44,19 +44,60 @@
4444
/* 0 */
4545
/***/ function(module, exports, __webpack_require__) {
4646

47-
module.exports = __webpack_require__(5);
47+
module.exports = __webpack_require__(6);
4848

4949

5050
/***/ },
5151
/* 1 */,
52-
/* 2 */,
53-
/* 3 */
52+
/* 2 */
5453
/***/ function(module, exports) {
5554

56-
module.exports = require("path");
55+
// When Node writes to stdout/strerr, we capture that and convert the lines into calls on the
56+
// active .NET ILogger. But by default, stdout/stderr don't have any way of distinguishing
57+
// linebreaks inside log messages from the linebreaks that delimit separate log messages,
58+
// so multiline strings will end up being written to the ILogger as multiple independent
59+
// log messages. This makes them very hard to make sense of, especially when they represent
60+
// something like stack traces.
61+
//
62+
// To fix this, we intercept stdout/stderr writes, and replace internal linebreaks with a
63+
// marker token. When .NET receives the lines, it converts the marker tokens back to regular
64+
// linebreaks within the logged messages.
65+
//
66+
// Note that it's better to do the interception at the stdout/stderr level, rather than at
67+
// the console.log/console.error (etc.) level, because this takes place after any native
68+
// message formatting has taken place (e.g., inserting values for % placeholders).
69+
var findInternalNewlinesRegex = /\n(?!$)/g;
70+
var encodedNewline = '__ns_newline__';
71+
encodeNewlinesWrittenToStream(process.stdout);
72+
encodeNewlinesWrittenToStream(process.stderr);
73+
function encodeNewlinesWrittenToStream(outputStream) {
74+
var origWriteFunction = outputStream.write;
75+
outputStream.write = function (value) {
76+
// Only interfere with the write if it's definitely a string
77+
if (typeof value === 'string') {
78+
var argsClone = Array.prototype.slice.call(arguments, 0);
79+
argsClone[0] = encodeNewlinesInString(value);
80+
origWriteFunction.apply(this, argsClone);
81+
}
82+
else {
83+
origWriteFunction.apply(this, arguments);
84+
}
85+
};
86+
}
87+
function encodeNewlinesInString(str) {
88+
return str.replace(findInternalNewlinesRegex, encodedNewline);
89+
}
90+
5791

5892
/***/ },
93+
/* 3 */,
5994
/* 4 */
95+
/***/ function(module, exports) {
96+
97+
module.exports = require("path");
98+
99+
/***/ },
100+
/* 5 */
60101
/***/ function(module, exports) {
61102

62103
"use strict";
@@ -82,17 +123,18 @@
82123

83124

84125
/***/ },
85-
/* 5 */
126+
/* 6 */
86127
/***/ function(module, exports, __webpack_require__) {
87128

88129
"use strict";
89130
// Limit dependencies to core Node modules. This means the code in this file has to be very low-level and unattractive,
90131
// but simplifies things for the consumer of this module.
91-
var net = __webpack_require__(6);
92-
var path = __webpack_require__(3);
93-
var readline = __webpack_require__(7);
94-
var ArgsUtil_1 = __webpack_require__(4);
95-
var virtualConnectionServer = __webpack_require__(8);
132+
__webpack_require__(2);
133+
var net = __webpack_require__(7);
134+
var path = __webpack_require__(4);
135+
var readline = __webpack_require__(8);
136+
var ArgsUtil_1 = __webpack_require__(5);
137+
var virtualConnectionServer = __webpack_require__(9);
96138
// Webpack doesn't support dynamic requires for files not present at compile time, so grab a direct
97139
// reference to Node's runtime 'require' function.
98140
var dynamicRequire = eval('require');
@@ -150,24 +192,24 @@
150192

151193

152194
/***/ },
153-
/* 6 */
195+
/* 7 */
154196
/***/ function(module, exports) {
155197

156198
module.exports = require("net");
157199

158200
/***/ },
159-
/* 7 */
201+
/* 8 */
160202
/***/ function(module, exports) {
161203

162204
module.exports = require("readline");
163205

164206
/***/ },
165-
/* 8 */
207+
/* 9 */
166208
/***/ function(module, exports, __webpack_require__) {
167209

168210
"use strict";
169-
var events_1 = __webpack_require__(9);
170-
var VirtualConnection_1 = __webpack_require__(10);
211+
var events_1 = __webpack_require__(10);
212+
var VirtualConnection_1 = __webpack_require__(11);
171213
// Keep this in sync with the equivalent constant in the .NET code. Both sides split up their transmissions into frames with this max length,
172214
// and both will reject longer frames.
173215
var MaxFrameBodyLength = 16 * 1024;
@@ -348,13 +390,13 @@
348390

349391

350392
/***/ },
351-
/* 9 */
393+
/* 10 */
352394
/***/ function(module, exports) {
353395

354396
module.exports = require("events");
355397

356398
/***/ },
357-
/* 10 */
399+
/* 11 */
358400
/***/ function(module, exports, __webpack_require__) {
359401

360402
"use strict";
@@ -363,7 +405,7 @@
363405
function __() { this.constructor = d; }
364406
d.prototype = b === null ? Object.create(b) : (__.prototype = b.prototype, new __());
365407
};
366-
var stream_1 = __webpack_require__(11);
408+
var stream_1 = __webpack_require__(12);
367409
/**
368410
* Represents a virtual connection. Multiple virtual connections may be multiplexed over a single physical socket connection.
369411
*/
@@ -404,7 +446,7 @@
404446

405447

406448
/***/ },
407-
/* 11 */
449+
/* 12 */
408450
/***/ function(module, exports) {
409451

410452
module.exports = require("stream");

‎src/Microsoft.AspNetCore.NodeServices/HostingModels/OutOfProcessNodeInstance.cs‎

Lines changed: 14 additions & 2 deletions
Original file line numberDiff line numberDiff line change
@@ -168,6 +168,18 @@ private static Process LaunchNodeProcess(ProcessStartInfo startInfo)
168168
return process;
169169
}
170170

171+
private static string UnencodeNewlines(string str)
172+
{
173+
if (str != null)
174+
{
175+
// The token here needs to match the const in OverrideStdOutputs.ts.
176+
// See the comment there for why we're doing this.
177+
str = str.Replace("__ns_newline__", Environment.NewLine);
178+
}
179+
180+
return str;
181+
}
182+
171183
private void ConnectToInputOutputStreams()
172184
{
173185
var initializationIsCompleted = false;
@@ -181,7 +193,7 @@ private void ConnectToInputOutputStreams()
181193
}
182194
else if (evt.Data != null)
183195
{
184-
OnOutputDataReceived(evt.Data);
196+
OnOutputDataReceived(UnencodeNewlines(evt.Data));
185197
}
186198
};
187199

@@ -197,7 +209,7 @@ private void ConnectToInputOutputStreams()
197209
}
198210
else
199211
{
200-
OnErrorDataReceived(evt.Data);
212+
OnErrorDataReceived(UnencodeNewlines(evt.Data));
201213
}
202214
}
203215
};

‎src/Microsoft.AspNetCore.NodeServices/TypeScript/HttpNodeInstanceEntryPoint.ts‎

Lines changed: 1 addition & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -1,5 +1,6 @@
11
// Limit dependencies to core Node modules. This means the code in this file has to be very low-level and unattractive,
22
// but simplifies things for the consumer of this module.
3+
import './Util/OverrideStdOutputs';
34
import * as http from 'http';
45
import * as path from 'path';
56
import { parseArgs } from './Util/ArgsUtil';

‎src/Microsoft.AspNetCore.NodeServices/TypeScript/SocketNodeInstanceEntryPoint.ts‎

Lines changed: 1 addition & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -1,5 +1,6 @@
11
// Limit dependencies to core Node modules. This means the code in this file has to be very low-level and unattractive,
22
// but simplifies things for the consumer of this module.
3+
import './Util/OverrideStdOutputs';
34
import * as net from 'net';
45
import * as path from 'path';
56
import * as readline from 'readline';

‎src/Microsoft.AspNetCore.NodeServices/TypeScript/Util/OverrideStdOutputs.ts‎

Lines changed: 37 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -0,0 +1,37 @@
1+
// When Node writes to stdout/strerr, we capture that and convert the lines into calls on the
2+
// active .NET ILogger. But by default, stdout/stderr don't have any way of distinguishing
3+
// linebreaks inside log messages from the linebreaks that delimit separate log messages,
4+
// so multiline strings will end up being written to the ILogger as multiple independent
5+
// log messages. This makes them very hard to make sense of, especially when they represent
6+
// something like stack traces.
7+
//
8+
// To fix this, we intercept stdout/stderr writes, and replace internal linebreaks with a
9+
// marker token. When .NET receives the lines, it converts the marker tokens back to regular
10+
// linebreaks within the logged messages.
11+
//
12+
// Note that it's better to do the interception at the stdout/stderr level, rather than at
13+
// the console.log/console.error (etc.) level, because this takes place after any native
14+
// message formatting has taken place (e.g., inserting values for % placeholders).
15+
const findInternalNewlinesRegex = /\n(?!$)/g;
16+
const encodedNewline = '__ns_newline__';
17+
18+
encodeNewlinesWrittenToStream(process.stdout);
19+
encodeNewlinesWrittenToStream(process.stderr);
20+
21+
function encodeNewlinesWrittenToStream(outputStream: NodeJS.WritableStream) {
22+
const origWriteFunction = outputStream.write;
23+
outputStream.write = <any>function (value: any) {
24+
// Only interfere with the write if it's definitely a string
25+
if (typeof value === 'string') {
26+
const argsClone = Array.prototype.slice.call(arguments, 0);
27+
argsClone[0] = encodeNewlinesInString(value);
28+
origWriteFunction.apply(this, argsClone);
29+
} else {
30+
origWriteFunction.apply(this, arguments);
31+
}
32+
};
33+
}
34+
35+
function encodeNewlinesInString(str: string): string {
36+
return str.replace(findInternalNewlinesRegex, encodedNewline);
37+
}

0 commit comments

Comments
 (0)