Skip to content

Commit 7374a4e

Browse files
thenewguy39thenewguy39
authored
introduce advanced logging controls (#91)
1 parent b8d562e commit 7374a4e

7 files changed

+959
-58
lines changed

‎src/CallbackContext.js

+2-2
Original file line numberDiff line numberDiff line change
@@ -5,7 +5,7 @@
55
'use strict';
66

77
const BeforeExitListener = require('./BeforeExitListener.js');
8-
const { toFormatted, intoError } = require('./Errors');
8+
const { structuredConsole } = require('./LogPatch');
99

1010
/**
1111
* Build the callback function and the part of the context which exposes
@@ -20,7 +20,7 @@ const { toFormatted, intoError } = require('./Errors');
2020
*/
2121
function _rawCallbackContext(client, id, scheduleNext) {
2222
const postError = (err, callback) => {
23-
console.error('Invoke Error', toFormatted(intoError(err)));
23+
structuredConsole.logError('Invoke Error', err);
2424
client.postInvocationError(err, id, callback);
2525
};
2626

‎src/LogPatch.js

+169-35
Original file line numberDiff line numberDiff line change
@@ -6,15 +6,57 @@
66

77
const util = require('util');
88
const fs = require('fs');
9+
const Errors = require('./Errors');
910

10-
const levels = Object.freeze({
11-
INFO: { name: 'INFO' },
12-
DEBUG: { name: 'DEBUG' },
13-
WARN: { name: 'WARN' },
14-
ERROR: { name: 'ERROR' },
15-
TRACE: { name: 'TRACE' },
16-
FATAL: { name: 'FATAL' },
17-
});
11+
const structuredConsole = {};
12+
13+
const jsonErrorReplacer = (_, value) => {
14+
if (value instanceof Error) {
15+
let serializedErr = Object.assign(
16+
{
17+
errorType: value?.constructor?.name ?? 'UnknownError',
18+
errorMessage: value.message,
19+
stackTrace:
20+
typeof value.stack === 'string'
21+
? value.stack.split('\n')
22+
: value.stack,
23+
},
24+
value,
25+
);
26+
return serializedErr;
27+
}
28+
return value;
29+
};
30+
31+
function formatJsonMessage(requestId, timestamp, level, ...messageParams) {
32+
let result = {
33+
timestamp: timestamp,
34+
level: level.name,
35+
requestId: requestId,
36+
};
37+
38+
if (messageParams.length === 1) {
39+
result.message = messageParams[0];
40+
try {
41+
return JSON.stringify(result, jsonErrorReplacer);
42+
} catch (_) {
43+
result.message = util.format(result.message);
44+
return JSON.stringify(result);
45+
}
46+
}
47+
48+
result.message = util.format(...messageParams);
49+
for (const param of messageParams) {
50+
if (param instanceof Error) {
51+
result.errorType = param?.constructor?.name ?? 'UnknownError';
52+
result.errorMessage = param.message;
53+
result.stackTrace =
54+
typeof param.stack === 'string' ? param.stack.split('\n') : [];
55+
break;
56+
}
57+
}
58+
return JSON.stringify(result);
59+
}
1860

1961
/* Use a unique symbol to provide global access without risk of name clashes. */
2062
const REQUEST_ID_SYMBOL = Symbol.for('aws.lambda.runtime.requestId');
@@ -26,10 +68,21 @@ let _currentRequestId = {
2668
/**
2769
* Write logs to stdout.
2870
*/
29-
let _logToStdout = (level, message) => {
71+
let logTextToStdout = (level, message, ...params) => {
72+
let time = new Date().toISOString();
73+
let requestId = _currentRequestId.get();
74+
let line = `${time}\t${requestId}\t${level.name}\t${util.format(
75+
message,
76+
...params,
77+
)}`;
78+
line = line.replace(/\n/g, '\r');
79+
process.stdout.write(line + '\n');
80+
};
81+
82+
let logJsonToStdout = (level, message, ...params) => {
3083
let time = new Date().toISOString();
3184
let requestId = _currentRequestId.get();
32-
let line = `${time}\t${requestId}\t${level.name}\t${message}`;
85+
let line = formatJsonMessage(requestId, time, level, message, ...params);
3386
line = line.replace(/\n/g, '\r');
3487
process.stdout.write(line + '\n');
3588
};
@@ -46,15 +99,41 @@ let _logToStdout = (level, message) => {
4699
* The next 8 bytes are the UNIX timestamp of the message with microseconds precision.
47100
* The remaining bytes ar ethe message itself. Byte order is big-endian.
48101
*/
49-
let _logToFd = function (logTarget) {
102+
let logTextToFd = function (logTarget) {
50103
let typeAndLength = Buffer.alloc(16);
51-
typeAndLength.writeUInt32BE(0xa55a0003, 0);
104+
return (level, message, ...params) => {
105+
let date = new Date();
106+
let time = date.toISOString();
107+
let requestId = _currentRequestId.get();
108+
let enrichedMessage = `${time}\t${requestId}\t${level.name}\t${util.format(
109+
message,
110+
...params,
111+
)}\n`;
52112

53-
return (level, message) => {
113+
typeAndLength.writeUInt32BE((0xa55a0003 | level.tlvMask) >>> 0, 0);
114+
let messageBytes = Buffer.from(enrichedMessage, 'utf8');
115+
typeAndLength.writeInt32BE(messageBytes.length, 4);
116+
typeAndLength.writeBigInt64BE(BigInt(date.valueOf()) * 1000n, 8);
117+
fs.writeSync(logTarget, typeAndLength);
118+
fs.writeSync(logTarget, messageBytes);
119+
};
120+
};
121+
122+
let logJsonToFd = function (logTarget) {
123+
let typeAndLength = Buffer.alloc(16);
124+
return (level, message, ...params) => {
54125
let date = new Date();
55126
let time = date.toISOString();
56127
let requestId = _currentRequestId.get();
57-
let enrichedMessage = `${time}\t${requestId}\t${level.name}\t${message}\n`;
128+
let enrichedMessage = formatJsonMessage(
129+
requestId,
130+
time,
131+
level,
132+
message,
133+
...params,
134+
);
135+
136+
typeAndLength.writeUInt32BE((0xa55a0002 | level.tlvMask) >>> 0, 0);
58137
let messageBytes = Buffer.from(enrichedMessage, 'utf8');
59138
typeAndLength.writeInt32BE(messageBytes.length, 4);
60139
typeAndLength.writeBigInt64BE(BigInt(date.valueOf()) * 1000n, 8);
@@ -66,45 +145,100 @@ let _logToFd = function (logTarget) {
66145
/**
67146
* Replace console functions with a log function.
68147
* @param {Function(level, String)} log
148+
* Apply log filters, based on `AWS_LAMBDA_LOG_LEVEL` env var
69149
*/
70150
function _patchConsoleWith(log) {
71-
console.log = (msg, ...params) => {
72-
log(levels.INFO, util.format(msg, ...params));
73-
};
74-
console.debug = (msg, ...params) => {
75-
log(levels.DEBUG, util.format(msg, ...params));
76-
};
77-
console.info = (msg, ...params) => {
78-
log(levels.INFO, util.format(msg, ...params));
79-
};
80-
console.warn = (msg, ...params) => {
81-
log(levels.WARN, util.format(msg, ...params));
82-
};
83-
console.error = (msg, ...params) => {
84-
log(levels.ERROR, util.format(msg, ...params));
85-
};
86-
console.trace = (msg, ...params) => {
87-
log(levels.TRACE, util.format(msg, ...params));
88-
};
151+
const NopLog = (_message, ..._params) => {};
152+
const levels = Object.freeze({
153+
TRACE: { name: 'TRACE', priority: 1, tlvMask: 0b00100 },
154+
DEBUG: { name: 'DEBUG', priority: 2, tlvMask: 0b01000 },
155+
INFO: { name: 'INFO', priority: 3, tlvMask: 0b01100 },
156+
WARN: { name: 'WARN', priority: 4, tlvMask: 0b10000 },
157+
ERROR: { name: 'ERROR', priority: 5, tlvMask: 0b10100 },
158+
FATAL: { name: 'FATAL', priority: 6, tlvMask: 0b11000 },
159+
});
160+
let awsLambdaLogLevel =
161+
levels[process.env['AWS_LAMBDA_LOG_LEVEL']?.toUpperCase()] ?? levels.TRACE;
162+
163+
if (levels.TRACE.priority >= awsLambdaLogLevel.priority) {
164+
console.trace = (msg, ...params) => {
165+
log(levels.TRACE, msg, ...params);
166+
};
167+
} else {
168+
console.trace = NopLog;
169+
}
170+
if (levels.DEBUG.priority >= awsLambdaLogLevel.priority) {
171+
console.debug = (msg, ...params) => {
172+
log(levels.DEBUG, msg, ...params);
173+
};
174+
} else {
175+
console.debug = NopLog;
176+
}
177+
if (levels.INFO.priority >= awsLambdaLogLevel.priority) {
178+
console.info = (msg, ...params) => {
179+
log(levels.INFO, msg, ...params);
180+
};
181+
} else {
182+
console.info = NopLog;
183+
}
184+
console.log = console.info;
185+
if (levels.WARN.priority >= awsLambdaLogLevel.priority) {
186+
console.warn = (msg, ...params) => {
187+
log(levels.WARN, msg, ...params);
188+
};
189+
} else {
190+
console.warn = NopLog;
191+
}
192+
if (levels.ERROR.priority >= awsLambdaLogLevel.priority) {
193+
console.error = (msg, ...params) => {
194+
log(levels.ERROR, msg, ...params);
195+
};
196+
} else {
197+
console.error = NopLog;
198+
}
89199
console.fatal = (msg, ...params) => {
90-
log(levels.FATAL, util.format(msg, ...params));
200+
log(levels.FATAL, msg, ...params);
91201
};
92202
}
93203

94204
let _patchConsole = () => {
205+
const JsonName = 'JSON',
206+
TextName = 'TEXT';
207+
let awsLambdaLogFormat =
208+
process.env['AWS_LAMBDA_LOG_FORMAT']?.toUpperCase() === JsonName
209+
? JsonName
210+
: TextName;
211+
let jsonErrorLogger = (_, err) => {
212+
console.error(Errors.intoError(err));
213+
},
214+
textErrorLogger = (msg, err) => {
215+
console.error(msg, Errors.toFormatted(Errors.intoError(err)));
216+
};
217+
218+
/**
219+
Resolve log format here, instead of inside log function.
220+
This avoids conditional statements in the log function hot path.
221+
**/
222+
let logger;
95223
if (
96224
process.env['_LAMBDA_TELEMETRY_LOG_FD'] != null &&
97225
process.env['_LAMBDA_TELEMETRY_LOG_FD'] != undefined
98226
) {
99227
let logFd = parseInt(process.env['_LAMBDA_TELEMETRY_LOG_FD']);
100-
_patchConsoleWith(_logToFd(logFd));
101228
delete process.env['_LAMBDA_TELEMETRY_LOG_FD'];
229+
logger =
230+
awsLambdaLogFormat === JsonName ? logJsonToFd(logFd) : logTextToFd(logFd);
102231
} else {
103-
_patchConsoleWith(_logToStdout);
232+
logger =
233+
awsLambdaLogFormat === JsonName ? logJsonToStdout : logTextToStdout;
104234
}
235+
_patchConsoleWith(logger);
236+
structuredConsole.logError =
237+
awsLambdaLogFormat === JsonName ? jsonErrorLogger : textErrorLogger;
105238
};
106239

107240
module.exports = {
108241
setCurrentRequestId: _currentRequestId.set,
109242
patchConsole: _patchConsole,
243+
structuredConsole: structuredConsole,
110244
};

‎src/StreamingContext.js

+3-6
Original file line numberDiff line numberDiff line change
@@ -5,13 +5,10 @@
55
'use strict';
66

77
const BeforeExitListener = require('./BeforeExitListener.js');
8-
const {
9-
InvalidStreamingOperation,
10-
toFormatted,
11-
intoError,
12-
} = require('./Errors');
8+
const { InvalidStreamingOperation } = require('./Errors');
139
const { verbose, vverbose } = require('./VerboseLog.js').logger('STREAM');
1410
const { tryCallFail } = require('./ResponseStream');
11+
const { structuredConsole } = require('./LogPatch');
1512

1613
/**
1714
* Construct the base-context object which includes the required flags and
@@ -67,7 +64,7 @@ module.exports.build = function (client, id, scheduleNext, options) {
6764

6865
return {
6966
fail: (err, callback) => {
70-
console.error('Invoke Error', toFormatted(intoError(err)));
67+
structuredConsole.logError('Invoke Error', err);
7168

7269
tryCallFail(responseStream, err, callback);
7370
},

‎src/index.mjs

+2-2
Original file line numberDiff line numberDiff line change
@@ -26,13 +26,13 @@ export async function run(appRootOrHandler, handler = '') {
2626
};
2727

2828
process.on('uncaughtException', (error) => {
29-
console.error('Uncaught Exception', Errors.toFormatted(error));
29+
LogPatch.structuredConsole.logError('Uncaught Exception', error);
3030
errorCallbacks.uncaughtException(error);
3131
});
3232

3333
process.on('unhandledRejection', (reason, promise) => {
3434
let error = new Errors.UnhandledPromiseRejection(reason, promise);
35-
console.error('Unhandled Promise Rejection', Errors.toFormatted(error));
35+
LogPatch.structuredConsole.logError('Unhandled Promise Rejection', error);
3636
errorCallbacks.unhandledRejection(error);
3737
});
3838

‎test/unit/FakeTelemetryTarget.js

+33-4
Original file line numberDiff line numberDiff line change
@@ -9,7 +9,16 @@ const fs = require('fs');
99
const path = require('path');
1010
const assert = require('assert');
1111

12-
const _LOG_IDENTIFIER = Buffer.from('a55a0003', 'hex');
12+
const levels = Object.freeze({
13+
TRACE: { name: 'TRACE', tlvMask: 0b00100 },
14+
DEBUG: { name: 'DEBUG', tlvMask: 0b01000 },
15+
INFO: { name: 'INFO', tlvMask: 0b01100 },
16+
WARN: { name: 'WARN', tlvMask: 0b10000 },
17+
ERROR: { name: 'ERROR', tlvMask: 0b10100 },
18+
FATAL: { name: 'FATAL', tlvMask: 0b11000 },
19+
});
20+
21+
const TextName = 'TEXT';
1322

1423
/**
1524
* A fake implementation of the multilne logging protocol.
@@ -55,7 +64,7 @@ module.exports = class FakeTelemetryTarget {
5564
* - the prefix is malformed
5665
* - there aren't enough bytes
5766
*/
58-
readLine() {
67+
readLine(level = 'INFO', format = TextName, expectEmpty = false) {
5968
let readLength = () => {
6069
let logPrefix = Buffer.alloc(16);
6170
let actualReadBytes = fs.readSync(
@@ -64,17 +73,34 @@ module.exports = class FakeTelemetryTarget {
6473
0,
6574
logPrefix.length,
6675
);
76+
77+
if (expectEmpty) {
78+
assert.strictEqual(
79+
actualReadBytes,
80+
0,
81+
`Expected actualReadBytes[${actualReadBytes}] = 0`,
82+
);
83+
return 0;
84+
}
85+
6786
assert.strictEqual(
6887
actualReadBytes,
6988
logPrefix.length,
7089
`Expected actualReadBytes[${actualReadBytes}] = ${logPrefix.length}`,
7190
);
91+
92+
var _tlvHeader;
93+
if (format === TextName)
94+
_tlvHeader = (0xa55a0003 | levels[level].tlvMask) >>> 0;
95+
else _tlvHeader = (0xa55a0002 | levels[level].tlvMask) >>> 0;
96+
97+
let _logIdentifier = Buffer.from(_tlvHeader.toString(16), 'hex');
7298
assert.strictEqual(
73-
logPrefix.lastIndexOf(_LOG_IDENTIFIER),
99+
logPrefix.lastIndexOf(_logIdentifier),
74100
0,
75101
`log prefix ${logPrefix.toString(
76102
'hex',
77-
)} should start with ${_LOG_IDENTIFIER.toString('hex')}`,
103+
)} should start with ${_logIdentifier.toString('hex')}`,
78104
);
79105
let len = logPrefix.readUInt32BE(4);
80106
// discard the timestamp
@@ -83,6 +109,9 @@ module.exports = class FakeTelemetryTarget {
83109
};
84110

85111
let lineLength = readLength();
112+
if (lineLength === 0) {
113+
return '';
114+
}
86115
let lineBytes = Buffer.alloc(lineLength);
87116
let actualLineSize = fs.readSync(
88117
this.readTarget,

0 commit comments

Comments
 (0)