diff --git a/src/CallbackContext.js b/src/CallbackContext.js index 85607843..2ee3cd3e 100644 --- a/src/CallbackContext.js +++ b/src/CallbackContext.js @@ -5,7 +5,7 @@ 'use strict'; const BeforeExitListener = require('./BeforeExitListener.js'); -const { toFormatted, intoError } = require('./Errors'); +const { structuredConsole } = require('./LogPatch'); /** * Build the callback function and the part of the context which exposes @@ -20,7 +20,7 @@ const { toFormatted, intoError } = require('./Errors'); */ function _rawCallbackContext(client, id, scheduleNext) { const postError = (err, callback) => { - console.error('Invoke Error', toFormatted(intoError(err))); + structuredConsole.logError('Invoke Error', err); client.postInvocationError(err, id, callback); }; diff --git a/src/LogPatch.js b/src/LogPatch.js index 60ebfd61..071de9d4 100644 --- a/src/LogPatch.js +++ b/src/LogPatch.js @@ -6,15 +6,57 @@ const util = require('util'); const fs = require('fs'); +const Errors = require('./Errors'); -const levels = Object.freeze({ - INFO: { name: 'INFO' }, - DEBUG: { name: 'DEBUG' }, - WARN: { name: 'WARN' }, - ERROR: { name: 'ERROR' }, - TRACE: { name: 'TRACE' }, - FATAL: { name: 'FATAL' }, -}); +const structuredConsole = {}; + +const jsonErrorReplacer = (_, value) => { + if (value instanceof Error) { + let serializedErr = Object.assign( + { + errorType: value?.constructor?.name ?? 'UnknownError', + errorMessage: value.message, + stackTrace: + typeof value.stack === 'string' + ? value.stack.split('\n') + : value.stack, + }, + value, + ); + return serializedErr; + } + return value; +}; + +function formatJsonMessage(requestId, timestamp, level, ...messageParams) { + let result = { + timestamp: timestamp, + level: level.name, + requestId: requestId, + }; + + if (messageParams.length === 1) { + result.message = messageParams[0]; + try { + return JSON.stringify(result, jsonErrorReplacer); + } catch (_) { + result.message = util.format(result.message); + return JSON.stringify(result); + } + } + + result.message = util.format(...messageParams); + for (const param of messageParams) { + if (param instanceof Error) { + result.errorType = param?.constructor?.name ?? 'UnknownError'; + result.errorMessage = param.message; + result.stackTrace = + typeof param.stack === 'string' ? param.stack.split('\n') : []; + break; + } + } + return JSON.stringify(result); +} /* Use a unique symbol to provide global access without risk of name clashes. */ const REQUEST_ID_SYMBOL = Symbol.for('aws.lambda.runtime.requestId'); @@ -26,10 +68,21 @@ let _currentRequestId = { /** * Write logs to stdout. */ -let _logToStdout = (level, message) => { +let logTextToStdout = (level, message, ...params) => { + let time = new Date().toISOString(); + let requestId = _currentRequestId.get(); + let line = `${time}\t${requestId}\t${level.name}\t${util.format( + message, + ...params, + )}`; + line = line.replace(/\n/g, '\r'); + process.stdout.write(line + '\n'); +}; + +let logJsonToStdout = (level, message, ...params) => { let time = new Date().toISOString(); let requestId = _currentRequestId.get(); - let line = `${time}\t${requestId}\t${level.name}\t${message}`; + let line = formatJsonMessage(requestId, time, level, message, ...params); line = line.replace(/\n/g, '\r'); process.stdout.write(line + '\n'); }; @@ -46,15 +99,41 @@ let _logToStdout = (level, message) => { * The next 8 bytes are the UNIX timestamp of the message with microseconds precision. * The remaining bytes ar ethe message itself. Byte order is big-endian. */ -let _logToFd = function (logTarget) { +let logTextToFd = function (logTarget) { let typeAndLength = Buffer.alloc(16); - typeAndLength.writeUInt32BE(0xa55a0003, 0); + return (level, message, ...params) => { + let date = new Date(); + let time = date.toISOString(); + let requestId = _currentRequestId.get(); + let enrichedMessage = `${time}\t${requestId}\t${level.name}\t${util.format( + message, + ...params, + )}\n`; - return (level, message) => { + typeAndLength.writeUInt32BE((0xa55a0003 | level.tlvMask) >>> 0, 0); + let messageBytes = Buffer.from(enrichedMessage, 'utf8'); + typeAndLength.writeInt32BE(messageBytes.length, 4); + typeAndLength.writeBigInt64BE(BigInt(date.valueOf()) * 1000n, 8); + fs.writeSync(logTarget, typeAndLength); + fs.writeSync(logTarget, messageBytes); + }; +}; + +let logJsonToFd = function (logTarget) { + let typeAndLength = Buffer.alloc(16); + return (level, message, ...params) => { let date = new Date(); let time = date.toISOString(); let requestId = _currentRequestId.get(); - let enrichedMessage = `${time}\t${requestId}\t${level.name}\t${message}\n`; + let enrichedMessage = formatJsonMessage( + requestId, + time, + level, + message, + ...params, + ); + + typeAndLength.writeUInt32BE((0xa55a0002 | level.tlvMask) >>> 0, 0); let messageBytes = Buffer.from(enrichedMessage, 'utf8'); typeAndLength.writeInt32BE(messageBytes.length, 4); typeAndLength.writeBigInt64BE(BigInt(date.valueOf()) * 1000n, 8); @@ -66,45 +145,100 @@ let _logToFd = function (logTarget) { /** * Replace console functions with a log function. * @param {Function(level, String)} log + * Apply log filters, based on `AWS_LAMBDA_LOG_LEVEL` env var */ function _patchConsoleWith(log) { - console.log = (msg, ...params) => { - log(levels.INFO, util.format(msg, ...params)); - }; - console.debug = (msg, ...params) => { - log(levels.DEBUG, util.format(msg, ...params)); - }; - console.info = (msg, ...params) => { - log(levels.INFO, util.format(msg, ...params)); - }; - console.warn = (msg, ...params) => { - log(levels.WARN, util.format(msg, ...params)); - }; - console.error = (msg, ...params) => { - log(levels.ERROR, util.format(msg, ...params)); - }; - console.trace = (msg, ...params) => { - log(levels.TRACE, util.format(msg, ...params)); - }; + const NopLog = (_message, ..._params) => {}; + const levels = Object.freeze({ + TRACE: { name: 'TRACE', priority: 1, tlvMask: 0b00100 }, + DEBUG: { name: 'DEBUG', priority: 2, tlvMask: 0b01000 }, + INFO: { name: 'INFO', priority: 3, tlvMask: 0b01100 }, + WARN: { name: 'WARN', priority: 4, tlvMask: 0b10000 }, + ERROR: { name: 'ERROR', priority: 5, tlvMask: 0b10100 }, + FATAL: { name: 'FATAL', priority: 6, tlvMask: 0b11000 }, + }); + let awsLambdaLogLevel = + levels[process.env['AWS_LAMBDA_LOG_LEVEL']?.toUpperCase()] ?? levels.TRACE; + + if (levels.TRACE.priority >= awsLambdaLogLevel.priority) { + console.trace = (msg, ...params) => { + log(levels.TRACE, msg, ...params); + }; + } else { + console.trace = NopLog; + } + if (levels.DEBUG.priority >= awsLambdaLogLevel.priority) { + console.debug = (msg, ...params) => { + log(levels.DEBUG, msg, ...params); + }; + } else { + console.debug = NopLog; + } + if (levels.INFO.priority >= awsLambdaLogLevel.priority) { + console.info = (msg, ...params) => { + log(levels.INFO, msg, ...params); + }; + } else { + console.info = NopLog; + } + console.log = console.info; + if (levels.WARN.priority >= awsLambdaLogLevel.priority) { + console.warn = (msg, ...params) => { + log(levels.WARN, msg, ...params); + }; + } else { + console.warn = NopLog; + } + if (levels.ERROR.priority >= awsLambdaLogLevel.priority) { + console.error = (msg, ...params) => { + log(levels.ERROR, msg, ...params); + }; + } else { + console.error = NopLog; + } console.fatal = (msg, ...params) => { - log(levels.FATAL, util.format(msg, ...params)); + log(levels.FATAL, msg, ...params); }; } let _patchConsole = () => { + const JsonName = 'JSON', + TextName = 'TEXT'; + let awsLambdaLogFormat = + process.env['AWS_LAMBDA_LOG_FORMAT']?.toUpperCase() === JsonName + ? JsonName + : TextName; + let jsonErrorLogger = (_, err) => { + console.error(Errors.intoError(err)); + }, + textErrorLogger = (msg, err) => { + console.error(msg, Errors.toFormatted(Errors.intoError(err))); + }; + + /** + Resolve log format here, instead of inside log function. + This avoids conditional statements in the log function hot path. + **/ + let logger; if ( process.env['_LAMBDA_TELEMETRY_LOG_FD'] != null && process.env['_LAMBDA_TELEMETRY_LOG_FD'] != undefined ) { let logFd = parseInt(process.env['_LAMBDA_TELEMETRY_LOG_FD']); - _patchConsoleWith(_logToFd(logFd)); delete process.env['_LAMBDA_TELEMETRY_LOG_FD']; + logger = + awsLambdaLogFormat === JsonName ? logJsonToFd(logFd) : logTextToFd(logFd); } else { - _patchConsoleWith(_logToStdout); + logger = + awsLambdaLogFormat === JsonName ? logJsonToStdout : logTextToStdout; } + _patchConsoleWith(logger); + structuredConsole.logError = + awsLambdaLogFormat === JsonName ? jsonErrorLogger : textErrorLogger; }; module.exports = { setCurrentRequestId: _currentRequestId.set, patchConsole: _patchConsole, + structuredConsole: structuredConsole, }; diff --git a/src/StreamingContext.js b/src/StreamingContext.js index f7a23ea6..921998b6 100644 --- a/src/StreamingContext.js +++ b/src/StreamingContext.js @@ -5,13 +5,10 @@ 'use strict'; const BeforeExitListener = require('./BeforeExitListener.js'); -const { - InvalidStreamingOperation, - toFormatted, - intoError, -} = require('./Errors'); +const { InvalidStreamingOperation } = require('./Errors'); const { verbose, vverbose } = require('./VerboseLog.js').logger('STREAM'); const { tryCallFail } = require('./ResponseStream'); +const { structuredConsole } = require('./LogPatch'); /** * Construct the base-context object which includes the required flags and @@ -67,7 +64,7 @@ module.exports.build = function (client, id, scheduleNext, options) { return { fail: (err, callback) => { - console.error('Invoke Error', toFormatted(intoError(err))); + structuredConsole.logError('Invoke Error', err); tryCallFail(responseStream, err, callback); }, diff --git a/src/index.mjs b/src/index.mjs index 1fc14c0b..9267866a 100755 --- a/src/index.mjs +++ b/src/index.mjs @@ -26,13 +26,13 @@ export async function run(appRootOrHandler, handler = '') { }; process.on('uncaughtException', (error) => { - console.error('Uncaught Exception', Errors.toFormatted(error)); + LogPatch.structuredConsole.logError('Uncaught Exception', error); errorCallbacks.uncaughtException(error); }); process.on('unhandledRejection', (reason, promise) => { let error = new Errors.UnhandledPromiseRejection(reason, promise); - console.error('Unhandled Promise Rejection', Errors.toFormatted(error)); + LogPatch.structuredConsole.logError('Unhandled Promise Rejection', error); errorCallbacks.unhandledRejection(error); }); diff --git a/test/unit/FakeTelemetryTarget.js b/test/unit/FakeTelemetryTarget.js index db9b28d8..e158dbe2 100644 --- a/test/unit/FakeTelemetryTarget.js +++ b/test/unit/FakeTelemetryTarget.js @@ -9,7 +9,16 @@ const fs = require('fs'); const path = require('path'); const assert = require('assert'); -const _LOG_IDENTIFIER = Buffer.from('a55a0003', 'hex'); +const levels = Object.freeze({ + TRACE: { name: 'TRACE', tlvMask: 0b00100 }, + DEBUG: { name: 'DEBUG', tlvMask: 0b01000 }, + INFO: { name: 'INFO', tlvMask: 0b01100 }, + WARN: { name: 'WARN', tlvMask: 0b10000 }, + ERROR: { name: 'ERROR', tlvMask: 0b10100 }, + FATAL: { name: 'FATAL', tlvMask: 0b11000 }, +}); + +const TextName = 'TEXT'; /** * A fake implementation of the multilne logging protocol. @@ -55,7 +64,7 @@ module.exports = class FakeTelemetryTarget { * - the prefix is malformed * - there aren't enough bytes */ - readLine() { + readLine(level = 'INFO', format = TextName, expectEmpty = false) { let readLength = () => { let logPrefix = Buffer.alloc(16); let actualReadBytes = fs.readSync( @@ -64,17 +73,34 @@ module.exports = class FakeTelemetryTarget { 0, logPrefix.length, ); + + if (expectEmpty) { + assert.strictEqual( + actualReadBytes, + 0, + `Expected actualReadBytes[${actualReadBytes}] = 0`, + ); + return 0; + } + assert.strictEqual( actualReadBytes, logPrefix.length, `Expected actualReadBytes[${actualReadBytes}] = ${logPrefix.length}`, ); + + var _tlvHeader; + if (format === TextName) + _tlvHeader = (0xa55a0003 | levels[level].tlvMask) >>> 0; + else _tlvHeader = (0xa55a0002 | levels[level].tlvMask) >>> 0; + + let _logIdentifier = Buffer.from(_tlvHeader.toString(16), 'hex'); assert.strictEqual( - logPrefix.lastIndexOf(_LOG_IDENTIFIER), + logPrefix.lastIndexOf(_logIdentifier), 0, `log prefix ${logPrefix.toString( 'hex', - )} should start with ${_LOG_IDENTIFIER.toString('hex')}`, + )} should start with ${_logIdentifier.toString('hex')}`, ); let len = logPrefix.readUInt32BE(4); // discard the timestamp @@ -83,6 +109,9 @@ module.exports = class FakeTelemetryTarget { }; let lineLength = readLength(); + if (lineLength === 0) { + return ''; + } let lineBytes = Buffer.alloc(lineLength); let actualLineSize = fs.readSync( this.readTarget, diff --git a/test/unit/LogPatchTest.js b/test/unit/LogPatchTest.js index 117f249c..08c8ecae 100644 --- a/test/unit/LogPatchTest.js +++ b/test/unit/LogPatchTest.js @@ -4,12 +4,64 @@ 'use strict'; +const util = require('util'); + let should = require('should'); let LogPatch = require('../../src/LogPatch'); let Errors = require('../../src/Errors'); +let assert = require('assert'); -let { captureStream, consoleSnapshot } = require('./LoggingGlobals'); +let { + captureStream, + consoleSnapshot, + loggingConfig, +} = require('./LoggingGlobals'); let FakeTelemetryTarget = require('./FakeTelemetryTarget'); +let fakeLoggingConfig = new loggingConfig(); +const logFunctions = [ + [ + function (message, ...params) { + console.trace(message, ...params); + }, + 'TRACE', + ], + [ + function (message, ...params) { + console.debug(message, ...params); + }, + 'DEBUG', + ], + [ + function (message, ...params) { + console.info(message, ...params); + }, + 'INFO', + ], + [ + function (message, ...params) { + console.log(message, ...params); + }, + 'INFO', + ], + [ + function (message, ...params) { + console.warn(message, ...params); + }, + 'WARN', + ], + [ + function (message, ...params) { + console.error(message, ...params); + }, + 'ERROR', + ], + [ + function (message, ...params) { + console.fatal(message, ...params); + }, + 'FATAL', + ], +]; describe('Apply the default console log patch', () => { let restoreConsole = consoleSnapshot(); @@ -109,6 +161,76 @@ describe('Apply the default console log patch', () => { recoveredError.should.have.property('code', expected.code); recoveredError.should.have.property('custom', expected.custom); }); + + describe('Structured logging for new line delimited logs', () => { + const EXPECTED_ID = 'structured logging for nd logging request id'; + beforeEach('set the request id', () => { + LogPatch.setCurrentRequestId(EXPECTED_ID); + }); + + beforeEach('turn on structured logging', () => { + fakeLoggingConfig.turnOnStructuredLogging(); + LogPatch.patchConsole(); + }); + afterEach('turn off structured logging', () => { + fakeLoggingConfig.turnOffStructuredLogging(); + }); + + it('should format messages as json correctly', () => { + for (let fIdx = 0; fIdx < logFunctions.length; fIdx++) { + logFunctions[fIdx][0]('hello structured logging'); + let receivedMessage = capturedStdout.captured(); + receivedMessage = JSON.parse(receivedMessage); + + receivedMessage.should.have.property('timestamp'); + let receivedTime = new Date(receivedMessage.timestamp); + let now = new Date(); + assert(now >= receivedTime && now - receivedTime <= 1000); + + receivedMessage.should.have.property( + 'message', + 'hello structured logging', + ); + receivedMessage.should.have.property('level', logFunctions[fIdx][1]); + receivedMessage.should.have.property('requestId', EXPECTED_ID); + + capturedStdout.resetBuffer(); + } + }); + }); + describe(' `structuredConsole.logError()` method in TEXT mode', () => { + const EXPECTED_ID = 'structured logging request id'; + const originalDate = Date; + beforeEach('set the request id', () => { + LogPatch.setCurrentRequestId(EXPECTED_ID); + }); + beforeEach('freeze current date', () => { + function mockDate() { + return new originalDate('2023-09-25T12:00:00Z'); + } + global.Date = mockDate; + }); + afterEach('unfreeze current date', () => { + global.Date = originalDate; + }); + it('should produce stringified output for TEXT mode', () => { + let expected = new Error('some error'); + expected.code = 1234; + expected.custom = 'my custom field'; + LogPatch.structuredConsole.logError('Invocation Error', expected); + + let recoveredMessage = capturedStdout.captured().split('\t'); + recoveredMessage[2].should.be.equal('ERROR'); + recoveredMessage[3].should.be.equal('Invocation Error '); + + let recoveredError = JSON.parse(recoveredMessage[4]); + recoveredError.should.have.property('errorType', expected.name); + recoveredError.should.have.property('errorMessage', expected.message); + recoveredError.should.have.property('stack', expected.stack.split('\n')); + recoveredError.should.have.property('code', expected.code); + recoveredError.should.have.property('custom', expected.custom); + }); + }); }); describe('The multiline log patch', () => { @@ -146,7 +268,7 @@ describe('The multiline log patch', () => { it('should have five tab-separated fields when logging an error', () => { console.error('message', Errors.toFormatted(new Error('garbage'))); - telemetryTarget.readLine().should.match(/.*\t.*\t.*\t.*\t.*/); + telemetryTarget.readLine('ERROR').should.match(/.*\t.*\t.*\t.*\t.*/); }); describe('When the global requestId is set', () => { @@ -169,14 +291,16 @@ describe('The multiline log patch', () => { it('should include the level field as the third field', () => { console.warn('content'); - telemetryTarget.readLine().should.match(new RegExp(`.*\t.*\tWARN\t.*`)); + telemetryTarget + .readLine('WARN') + .should.match(new RegExp(`.*\t.*\tWARN\t.*`)); }); it('should include the message as the fourth field', () => { let message = 'my turbo message'; console.trace(message); telemetryTarget - .readLine() + .readLine('TRACE') .should.match(new RegExp(`.*\t.*\t.*\t${message}`)); }); @@ -193,22 +317,22 @@ describe('The multiline log patch', () => { it('should use WARN for console.warn', () => { console.warn('hello'); - telemetryTarget.readLine().should.containEql('WARN'); + telemetryTarget.readLine('WARN').should.containEql('WARN'); }); it('should use ERROR for console.error', () => { console.error('hello'); - telemetryTarget.readLine().should.containEql('ERROR'); + telemetryTarget.readLine('ERROR').should.containEql('ERROR'); }); it('should use TRACE for console.trace', () => { console.trace('hello'); - telemetryTarget.readLine().should.containEql('TRACE'); + telemetryTarget.readLine('TRACE').should.containEql('TRACE'); }); it('should use FATAL for console.fatal', () => { console.fatal('hello'); - telemetryTarget.readLine().should.containEql('FATAL'); + telemetryTarget.readLine('FATAL').should.containEql('FATAL'); }); }); @@ -219,7 +343,7 @@ describe('The multiline log patch', () => { console.error('message', Errors.toFormatted(expected)); - let errorString = telemetryTarget.readLine().split('\t')[4]; + let errorString = telemetryTarget.readLine('ERROR').split('\t')[4]; let recoveredError = JSON.parse(errorString); recoveredError.should.have.property('errorType', expected.name); @@ -228,4 +352,585 @@ describe('The multiline log patch', () => { recoveredError.should.have.property('code', expected.code); recoveredError.should.have.property('custom', expected.custom); }); + + describe('Structured logging', () => { + const EXPECTED_ID = 'structured logging request id'; + const originalDate = Date; + beforeEach('set the request id', () => { + LogPatch.setCurrentRequestId(EXPECTED_ID); + }); + + beforeEach('turn on structured logging', () => { + fakeLoggingConfig.turnOnStructuredLogging(); + telemetryTarget.openFile(); + telemetryTarget.updateEnv(); + LogPatch.patchConsole(); + }); + beforeEach('freeze current date', () => { + function mockDate() { + return new originalDate('2023-09-25T12:00:00Z'); + } + global.Date = mockDate; + }); + + afterEach('turn off structured logging & reset log level', () => { + fakeLoggingConfig.turnOffStructuredLogging(); + fakeLoggingConfig.resetLogLevel(); + }); + afterEach('unfreeze current date', () => { + global.Date = originalDate; + }); + + it('should format messages as json correctly', () => { + for (let fIdx = 0; fIdx < logFunctions.length; fIdx++) { + logFunctions[fIdx][0]( + 'hello', + 3.14, + 'structured logging', + false, + { test: 'structured logging' }, + ['random', 'logs'], + ); + let receivedMessage = telemetryTarget.readLine( + logFunctions[fIdx][1], + 'JSON', + ); + receivedMessage = JSON.parse(receivedMessage); + + receivedMessage.should.have.property('timestamp'); + let receivedTime = new Date(receivedMessage.timestamp); + let now = new Date(); + assert(now >= receivedTime && now - receivedTime <= 1000); + + receivedMessage.should.have.property( + 'message', + util.format( + 'hello', + 3.14, + 'structured logging', + false, + { test: 'structured logging' }, + ['random', 'logs'], + ), + ); + receivedMessage.should.have.property('level', logFunctions[fIdx][1]); + receivedMessage.should.have.property('requestId', EXPECTED_ID); + } + }); + + it('should filter messages correctly', () => { + const loglevelSettings = [ + undefined, + 'TRACE', + 'DEBUG', + 'INFO', + 'WARN', + 'ERROR', + 'FATAL', + ]; + const filterMatrix = [ + [false, false, false, false, false, false, false], + [false, false, false, false, false, false, false], + [true, false, false, false, false, false, false], + [true, true, false, false, false, false, false], + [true, true, true, true, false, false, false], + [true, true, true, true, true, false, false], + [true, true, true, true, true, true, false], + ]; + + let receivedMessage, + expectEmpty = true; + for (let idx = 0; idx < loglevelSettings.length; idx++) { + fakeLoggingConfig.setLogLevel(loglevelSettings[idx]); + telemetryTarget.openFile(); + telemetryTarget.updateEnv(); + LogPatch.patchConsole(); + + for (let fIdx = 0; fIdx < logFunctions.length; fIdx++) { + logFunctions[fIdx][0]('random log message'); + if (filterMatrix[idx][fIdx]) { + telemetryTarget.readLine( + logFunctions[fIdx][1], + 'JSON', + expectEmpty, + ); + } else { + receivedMessage = telemetryTarget.readLine( + logFunctions[fIdx][1], + 'JSON', + ); + receivedMessage = JSON.parse(receivedMessage); + receivedMessage.should.have.property( + 'message', + 'random log message', + ); + } + } + } + }); + + it('should add error fields to messages if error is supplied', () => { + for (let fIdx = 0; fIdx < logFunctions.length; fIdx++) { + let e1 = new SyntaxError('random syntax error'); + let e2 = new ReferenceError('random reference error'); + logFunctions[fIdx][0]( + 'logged an error', + e1, + 'logged another error', + e2, + ); + let receivedMessage = telemetryTarget.readLine( + logFunctions[fIdx][1], + 'JSON', + ); + receivedMessage = JSON.parse(receivedMessage); + receivedMessage.should.have.property('errorType', e1.constructor.name); + receivedMessage.should.have.property('errorMessage', e1.message); + receivedMessage.should.have.property( + 'stackTrace', + e1.stack.split('\n'), + ); + } + }); + + it('should handle malformed errors', () => { + for (let fIdx = 0; fIdx < logFunctions.length; fIdx++) { + let e1 = new Error(), + e2 = new Error(), + e3 = new Error(), + e4 = new Error(), + e5 = new Error(), + e6 = new Error(), + e7 = new Error(), + e8 = new Error(), + e9 = new Error(); + e1.constructor = null; + e2.stack = null; + e3.message = null; + e4.stack = undefined; + e5.constructor = undefined; + e6.message = undefined; + e7.stack = { customStack: 'of object type' }; + e8.message = 1.23; + e8.constructor = { name: 'overwritten type' }; + e8.stack = 'overwritten\nstack\ntrace'; + e9.errorType = 1.23; + e9.errorMessage = 456; + e9.stackTrace = 'overwritten'; + + logFunctions[fIdx][0]('error with null constructor', e1); + let receivedMessage = telemetryTarget.readLine( + logFunctions[fIdx][1], + 'JSON', + ); + receivedMessage = JSON.parse(receivedMessage); + receivedMessage.should.have.property('errorType', 'UnknownError'); + + logFunctions[fIdx][0]('error with undefined constructor', e5); + receivedMessage = telemetryTarget.readLine( + logFunctions[fIdx][1], + 'JSON', + ); + receivedMessage = JSON.parse(receivedMessage); + receivedMessage.should.have.property('errorType', 'UnknownError'); + + logFunctions[fIdx][0]('error with null stacktrace', e2); + receivedMessage = telemetryTarget.readLine( + logFunctions[fIdx][1], + 'JSON', + ); + receivedMessage = JSON.parse(receivedMessage); + receivedMessage.should.have.property('stackTrace', []); + + logFunctions[fIdx][0]('error with undefined stacktrace', e4); + receivedMessage = telemetryTarget.readLine( + logFunctions[fIdx][1], + 'JSON', + ); + receivedMessage = JSON.parse(receivedMessage); + receivedMessage.should.have.property('stackTrace', []); + + logFunctions[fIdx][0]('error with non-string stacktrace', e7); + receivedMessage = telemetryTarget.readLine( + logFunctions[fIdx][1], + 'JSON', + ); + receivedMessage = JSON.parse(receivedMessage); + receivedMessage.should.have.property('stackTrace', []); + + logFunctions[fIdx][0]('error with null message', e3); + receivedMessage = telemetryTarget.readLine( + logFunctions[fIdx][1], + 'JSON', + ); + receivedMessage = JSON.parse(receivedMessage); + receivedMessage.should.have.property('errorMessage', null); + + logFunctions[fIdx][0]('error with undefined message', e6); + receivedMessage = telemetryTarget.readLine( + logFunctions[fIdx][1], + 'JSON', + ); + receivedMessage = JSON.parse(receivedMessage); + receivedMessage.should.not.have.property('errorMessage'); + + logFunctions[fIdx][0]( + 'error with overwritten `message`, `constructor.name`, `stack`', + e8, + ); + receivedMessage = telemetryTarget.readLine( + logFunctions[fIdx][1], + 'JSON', + ); + receivedMessage.should.be.equal( + JSON.stringify({ + timestamp: '2023-09-25T12:00:00.000Z', + level: logFunctions[fIdx][1], + requestId: 'structured logging request id', + message: util.format( + 'error with overwritten `message`, `constructor.name`, `stack`', + e8, + ), + errorType: 'overwritten type', + errorMessage: 1.23, + stackTrace: ['overwritten', 'stack', 'trace'], + }), + ); + + logFunctions[fIdx][0]( + 'error with overwritten `errorType`, `errorMessage`, `stackTrace`', + e9, + ); + receivedMessage = telemetryTarget.readLine( + logFunctions[fIdx][1], + 'JSON', + ); + receivedMessage.should.be.equal( + JSON.stringify({ + timestamp: '2023-09-25T12:00:00.000Z', + level: logFunctions[fIdx][1], + requestId: 'structured logging request id', + message: util.format( + 'error with overwritten `errorType`, `errorMessage`, `stackTrace`', + e9, + ), + errorType: 'Error', + errorMessage: '', + stackTrace: e9.stack.split('\n'), + }), + ); + } + }); + + it('should not strinfigy single arg', () => { + for (let fIdx = 0; fIdx < logFunctions.length; fIdx++) { + logFunctions[fIdx][0](100.123); + let receivedMessage = telemetryTarget.readLine( + logFunctions[fIdx][1], + 'JSON', + ); + receivedMessage.should.be.equal( + JSON.stringify({ + timestamp: '2023-09-25T12:00:00.000Z', + level: logFunctions[fIdx][1], + requestId: 'structured logging request id', + message: 100.123, + }), + ); + + logFunctions[fIdx][0]([ + { someKey: 'some_val', data: 1000 }, + false, + [1, 2, 3], + 3.14, + ]); // arrays + receivedMessage = telemetryTarget.readLine( + logFunctions[fIdx][1], + 'JSON', + ); + receivedMessage.should.be.equal( + JSON.stringify({ + timestamp: '2023-09-25T12:00:00.000Z', + level: logFunctions[fIdx][1], + requestId: 'structured logging request id', + message: [ + { someKey: 'some_val', data: 1000 }, + false, + [1, 2, 3], + 3.14, + ], + }), + ); + + logFunctions[fIdx][0]({ transactionId: 100, data: 3.14, state: false }); // objects + receivedMessage = telemetryTarget.readLine( + logFunctions[fIdx][1], + 'JSON', + ); + receivedMessage.should.be.equal( + JSON.stringify({ + timestamp: '2023-09-25T12:00:00.000Z', + level: logFunctions[fIdx][1], + requestId: 'structured logging request id', + message: { transactionId: 100, data: 3.14, state: false }, + }), + ); + } + }); + + it('should use custom serializer for single arg containing error instances', () => { + for (let fIdx = 0; fIdx < logFunctions.length; fIdx++) { + let err = new TypeError('some message'); + logFunctions[fIdx][0](err); + let receivedMessage = telemetryTarget.readLine( + logFunctions[fIdx][1], + 'JSON', + ); + receivedMessage.should.be.equal( + JSON.stringify({ + timestamp: '2023-09-25T12:00:00.000Z', + level: logFunctions[fIdx][1], + requestId: 'structured logging request id', + message: { + errorType: 'TypeError', + errorMessage: 'some message', + stackTrace: err.stack.split('\n'), + }, + }), + ); + + // malformed null error + err = new Error('some error'); + err.constructor = null; + err.message = null; + err.stack = null; + logFunctions[fIdx][0](err); + receivedMessage = telemetryTarget.readLine( + logFunctions[fIdx][1], + 'JSON', + ); + receivedMessage.should.be.equal( + JSON.stringify({ + timestamp: '2023-09-25T12:00:00.000Z', + level: logFunctions[fIdx][1], + requestId: 'structured logging request id', + message: { + errorType: 'UnknownError', + errorMessage: null, + stackTrace: null, + constructor: null, + }, + }), + ); + + // malformed undefined error + err = new Error('some error'); + err.constructor = undefined; + err.message = undefined; + err.stack = undefined; + logFunctions[fIdx][0](err); + receivedMessage = telemetryTarget.readLine( + logFunctions[fIdx][1], + 'JSON', + ); + receivedMessage.should.be.equal( + JSON.stringify({ + timestamp: '2023-09-25T12:00:00.000Z', + level: logFunctions[fIdx][1], + requestId: 'structured logging request id', + message: { + errorType: 'UnknownError', + }, + }), + ); + + // nested error + err = new ReferenceError('some error message'); + logFunctions[fIdx][0]({ transactionId: 100, error: err }); + receivedMessage = telemetryTarget.readLine( + logFunctions[fIdx][1], + 'JSON', + ); + receivedMessage.should.be.equal( + JSON.stringify({ + timestamp: '2023-09-25T12:00:00.000Z', + level: logFunctions[fIdx][1], + requestId: 'structured logging request id', + message: { + transactionId: 100, + error: { + errorType: 'ReferenceError', + errorMessage: 'some error message', + stackTrace: err.stack.split('\n'), + }, + }, + }), + ); + + // error with custom fields + err = new SyntaxError('some error'); + err.custom1 = 'custom error data'; + err.custom2 = 123.456; + logFunctions[fIdx][0](err); + receivedMessage = telemetryTarget.readLine( + logFunctions[fIdx][1], + 'JSON', + ); + receivedMessage.should.be.equal( + JSON.stringify({ + timestamp: '2023-09-25T12:00:00.000Z', + level: logFunctions[fIdx][1], + requestId: 'structured logging request id', + message: { + errorType: 'SyntaxError', + errorMessage: 'some error', + stackTrace: err.stack.split('\n'), + custom1: 'custom error data', + custom2: 123.456, + }, + }), + ); + + // error with overriden `err.message`, `err.constructor.name`, `err.stack` + err = new SyntaxError('some error'); + err.message = 123.456; + err.constructor = { name: false }; + err.stack = { customStack: 'should not be formatted' }; + logFunctions[fIdx][0](err); + receivedMessage = telemetryTarget.readLine( + logFunctions[fIdx][1], + 'JSON', + ); + receivedMessage.should.be.equal( + JSON.stringify({ + timestamp: '2023-09-25T12:00:00.000Z', + level: logFunctions[fIdx][1], + requestId: 'structured logging request id', + message: { + errorType: false, + errorMessage: 123.456, + stackTrace: { customStack: 'should not be formatted' }, + constructor: { name: false }, + }, + }), + ); + + // error with overriden `errorMessage`, `errorType`, `stackTrace` + err = new SyntaxError('some error'); + err.errorType = 1.23; + err.errorMessage = 456; + err.stackTrace = ['random', 'values', 1, 2, false]; + logFunctions[fIdx][0](err); + receivedMessage = telemetryTarget.readLine( + logFunctions[fIdx][1], + 'JSON', + ); + receivedMessage.should.be.equal( + JSON.stringify({ + timestamp: '2023-09-25T12:00:00.000Z', + level: logFunctions[fIdx][1], + requestId: 'structured logging request id', + message: { + errorType: 1.23, + errorMessage: 456, + stackTrace: ['random', 'values', 1, 2, false], + }, + }), + ); + } + }); + it('should default to stringifying if single arg contains un-serializable objects', () => { + for (let fIdx = 0; fIdx < logFunctions.length; fIdx++) { + // circular object + let obj = { data: 123 }; + obj.backlink = obj; + + logFunctions[fIdx][0](obj); + let receivedMessage = telemetryTarget.readLine( + logFunctions[fIdx][1], + 'JSON', + ); + receivedMessage.should.be.equal( + JSON.stringify({ + timestamp: '2023-09-25T12:00:00.000Z', + level: logFunctions[fIdx][1], + requestId: 'structured logging request id', + message: ' { data: 123, backlink: [Circular *1] }', + }), + ); + + // circular error + let err = new Error('circular error'); + err.backlink = err; + logFunctions[fIdx][0](err); + receivedMessage = telemetryTarget.readLine( + logFunctions[fIdx][1], + 'JSON', + ); + receivedMessage.should.be.equal( + JSON.stringify({ + timestamp: '2023-09-25T12:00:00.000Z', + level: logFunctions[fIdx][1], + requestId: 'structured logging request id', + message: util.format(err), + }), + ); + } + }); + it('should handle single arg object with custom toJSON implementation', () => { + for (let fIdx = 0; fIdx < logFunctions.length; fIdx++) { + let obj = { data: 123 }; + obj.toJSON = () => 'custom serialized'; + + logFunctions[fIdx][0](obj); + let receivedMessage = telemetryTarget.readLine( + logFunctions[fIdx][1], + 'JSON', + ); + receivedMessage.should.be.equal( + JSON.stringify({ + timestamp: '2023-09-25T12:00:00.000Z', + level: logFunctions[fIdx][1], + requestId: 'structured logging request id', + message: 'custom serialized', + }), + ); + + logFunctions[fIdx][0]('as part of multiple args', obj); + receivedMessage = telemetryTarget.readLine( + logFunctions[fIdx][1], + 'JSON', + ); + receivedMessage.should.be.equal( + JSON.stringify({ + timestamp: '2023-09-25T12:00:00.000Z', + level: logFunctions[fIdx][1], + requestId: 'structured logging request id', + message: + 'as part of multiple args { data: 123, toJSON: [Function (anonymous)] }', + }), + ); + } + }); + it(' `structuredConsole.logError()` output should not be stringified in JSON mode', () => { + let err = new SyntaxError('user syntax error'); + err.code = 123; + LogPatch.structuredConsole.logError('Invoke Error', err); + + let receivedMessage = telemetryTarget.readLine('ERROR', 'JSON'); + receivedMessage.should.be.equal( + JSON.stringify({ + timestamp: '2023-09-25T12:00:00.000Z', + level: 'ERROR', + requestId: 'structured logging request id', + message: { + errorType: 'SyntaxError', + errorMessage: 'user syntax error', + stackTrace: err.stack.split('\n'), + code: 123, + }, + }), + ); + }); + }); }); diff --git a/test/unit/LoggingGlobals.js b/test/unit/LoggingGlobals.js index e61194d7..7ffce3da 100644 --- a/test/unit/LoggingGlobals.js +++ b/test/unit/LoggingGlobals.js @@ -11,6 +11,20 @@ * objects under test. */ +const levels = Object.freeze({ + TRACE: { name: 'TRACE' }, + DEBUG: { name: 'DEBUG' }, + INFO: { name: 'INFO' }, + WARN: { name: 'WARN' }, + ERROR: { name: 'ERROR' }, + FATAL: { name: 'FATAL' }, +}); + +const formats = Object.freeze({ + TEXT: { name: 'TEXT' }, + JSON: { name: 'JSON' }, +}); + module.exports.consoleSnapshot = () => { let log = console.log; let debug = console.debug; @@ -47,5 +61,27 @@ module.exports.captureStream = function captureStream(stream) { }, unhook: () => (stream.write = originalWrite), captured: () => buf, + resetBuffer: () => (buf = ''), }; }; + +module.exports.loggingConfig = class loggingConfig { + turnOnStructuredLogging() { + process.env['AWS_LAMBDA_LOG_FORMAT'] = formats.JSON.name; + } + + turnOffStructuredLogging() { + delete process.env['AWS_LAMBDA_LOG_FORMAT']; + } + + setLogLevel(level) { + if (levels[level] === undefined) { + return; + } + process.env['AWS_LAMBDA_LOG_LEVEL'] = levels[level].name; + } + + resetLogLevel() { + delete process.env['AWS_LAMBDA_LOG_LEVEL']; + } +};