diff --git a/README.md b/README.md index 041e0e2a..97d3fad5 100644 --- a/README.md +++ b/README.md @@ -10,7 +10,6 @@ You can include this package in your preferred base image to make that base imag ## Requirements The NodeJS Runtime Interface Client package currently supports NodeJS versions: - - 14.x - 16.x - 18.x - 20.x diff --git a/package-lock.json b/package-lock.json index d0d6913d..a755d3ba 100644 --- a/package-lock.json +++ b/package-lock.json @@ -1,12 +1,12 @@ { "name": "aws-lambda-ric", - "version": "3.1.0", + "version": "3.2.0", "lockfileVersion": 3, "requires": true, "packages": { "": { "name": "aws-lambda-ric", - "version": "3.1.0", + "version": "3.2.0", "hasInstallScript": true, "license": "Apache-2.0", "dependencies": { @@ -22,6 +22,7 @@ "eslint-config-prettier": "8.8.0", "eslint-plugin-prettier": "4.2.1", "husky": "^8.0.3", + "lambda-runtime": "file:./src/", "mocha": "10.2.0", "mock-http-server": "^1.4.5", "nyc": "^15.1.0", @@ -1499,12 +1500,12 @@ } }, "node_modules/braces": { - "version": "3.0.2", - "resolved": "https://registry.npmjs.org/braces/-/braces-3.0.2.tgz", - "integrity": "sha512-b8um+L1RzM3WDSzvhm6gIz1yfTbBt6YTlcEKAvsmqCZZFw46z626lVj9j1yEPW33H5H+lBQpZMP1k8l+78Ha0A==", + "version": "3.0.3", + "resolved": "https://registry.npmjs.org/braces/-/braces-3.0.3.tgz", + "integrity": "sha512-yQbXgO/OSZVD2IsiLlro+7Hf6Q18EJrKSEsdoMzKePKXct3gvD8oLcOQdIzGupr5Fj+EDe8gO/lxc1BzfMpxvA==", "dev": true, "dependencies": { - "fill-range": "^7.0.1" + "fill-range": "^7.1.1" }, "engines": { "node": ">=8" @@ -2359,9 +2360,9 @@ } }, "node_modules/fill-range": { - "version": "7.0.1", - "resolved": "https://registry.npmjs.org/fill-range/-/fill-range-7.0.1.tgz", - "integrity": "sha512-qOo9F+dMUmC2Lcb4BbVvnKJxTPjCm+RRpe4gDuGrzkL7mEVl/djYSu2OdQ2Pa302N4oqkSg9ir6jaLWJ2USVpQ==", + "version": "7.1.1", + "resolved": "https://registry.npmjs.org/fill-range/-/fill-range-7.1.1.tgz", + "integrity": "sha512-YsGpe3WHLK8ZYi4tWDg2Jy3ebRz2rXowDxnld4bkQB00cc/1Zw9AWnC0i9ztDJitivtQvaI9KaLyKrc+hBW0yg==", "dev": true, "dependencies": { "to-regex-range": "^5.0.1" @@ -2897,10 +2898,22 @@ "resolved": "https://registry.npmjs.org/inherits/-/inherits-2.0.4.tgz", "integrity": "sha512-k/vGaX4/Yla3WzyMCvTQOXYeIHvqOKtnqBduzTHpzpQZzAskKMhZ2K+EnBiSM9zGSoIFeMpXKxa4dYeZIQqewQ==" }, - "node_modules/ip": { - "version": "2.0.0", - "resolved": "https://registry.npmjs.org/ip/-/ip-2.0.0.tgz", - "integrity": "sha512-WKa+XuLG1A1R0UWhl2+1XQSi+fZWMsYKffMZTTYsiZaUD8k2yDAj5atimTUD2TZkyCkNEeYE5NhFZmupOGtjYQ==" + "node_modules/ip-address": { + "version": "9.0.5", + "resolved": "https://registry.npmjs.org/ip-address/-/ip-address-9.0.5.tgz", + "integrity": "sha512-zHtQzGojZXTwZTHQqra+ETKd4Sn3vgi7uBmlPoXVWZqYvuKmtI0l/VZTjqGmJY9x88GGOaZ9+G9ES8hC4T4X8g==", + "dependencies": { + "jsbn": "1.1.0", + "sprintf-js": "^1.1.3" + }, + "engines": { + "node": ">= 12" + } + }, + "node_modules/ip-address/node_modules/sprintf-js": { + "version": "1.1.3", + "resolved": "https://registry.npmjs.org/sprintf-js/-/sprintf-js-1.1.3.tgz", + "integrity": "sha512-Oo+0REFV59/rz3gfJNKQiBlwfHaSESl1pcGyABQsnnIfWOFt6JNj5gCog2U6MLZ//IGYD+nA8nI+mTShREReaA==" }, "node_modules/is-binary-path": { "version": "2.1.0", @@ -3169,6 +3182,11 @@ "js-yaml": "bin/js-yaml.js" } }, + "node_modules/jsbn": { + "version": "1.1.0", + "resolved": "https://registry.npmjs.org/jsbn/-/jsbn-1.1.0.tgz", + "integrity": "sha512-4bYVV3aAMtDTTu4+xsDYa6sy9GyJ69/amsu9sYF2zqjiEoZA5xJi3BrfX3uY+/IekIu7MwdObdbDWpoZdBv3/A==" + }, "node_modules/jsesc": { "version": "2.5.2", "resolved": "https://registry.npmjs.org/jsesc/-/jsesc-2.5.2.tgz", @@ -3205,6 +3223,10 @@ "node": ">=6" } }, + "node_modules/lambda-runtime": { + "resolved": "src", + "link": true + }, "node_modules/levn": { "version": "0.4.1", "resolved": "https://registry.npmjs.org/levn/-/levn-0.4.1.tgz", @@ -4623,15 +4645,15 @@ } }, "node_modules/socks": { - "version": "2.7.1", - "resolved": "https://registry.npmjs.org/socks/-/socks-2.7.1.tgz", - "integrity": "sha512-7maUZy1N7uo6+WVEX6psASxtNlKaNVMlGQKkG/63nEDdLOWNbiUMoLK7X4uYoLhQstau72mLgfEWcXcwsaHbYQ==", + "version": "2.7.3", + "resolved": "https://registry.npmjs.org/socks/-/socks-2.7.3.tgz", + "integrity": "sha512-vfuYK48HXCTFD03G/1/zkIls3Ebr2YNa4qU9gHDZdblHLiqhJrJGkY3+0Nx0JpN9qBhJbVObc1CNciT1bIZJxw==", "dependencies": { - "ip": "^2.0.0", + "ip-address": "^9.0.5", "smart-buffer": "^4.2.0" }, "engines": { - "node": ">= 10.13.0", + "node": ">= 10.0.0", "npm": ">= 3.0.0" } }, @@ -4816,9 +4838,9 @@ } }, "node_modules/tar": { - "version": "6.1.15", - "resolved": "https://registry.npmjs.org/tar/-/tar-6.1.15.tgz", - "integrity": "sha512-/zKt9UyngnxIT/EAGYuxaMYgOIJiP81ab9ZfkILq4oNLPFX50qyYmu7jRj9qeXoxmJHjGlbH0+cm2uy1WCs10A==", + "version": "6.2.1", + "resolved": "https://registry.npmjs.org/tar/-/tar-6.2.1.tgz", + "integrity": "sha512-DZ4yORTwrbTj/7MZYq2w+/ZFdI6OZ/f9SFHR+71gIVUZhOQPHzVCLpvRnPgyaMpfWxxk/4ONva3GQSyNIKRv6A==", "dependencies": { "chownr": "^2.0.0", "fs-minipass": "^2.0.0", @@ -5258,6 +5280,9 @@ "funding": { "url": "https://github.com/sponsors/sindresorhus" } + }, + "src": { + "dev": true } } } diff --git a/package.json b/package.json index 8a7374ba..8c70cbbc 100644 --- a/package.json +++ b/package.json @@ -1,6 +1,6 @@ { "name": "aws-lambda-ric", - "version": "3.1.0", + "version": "3.2.0", "description": "AWS Lambda Runtime Interface Client for NodeJs", "homepage": "https://github.com/aws/aws-lambda-nodejs-runtime-interface-client", "main": "dist/index.mjs", @@ -59,6 +59,7 @@ "node-gyp": "9.4.0" }, "devDependencies": { + "lambda-runtime": "file:./src/", "esbuild": "^0.18.3", "eslint": "8.42.0", "eslint-config-prettier": "8.8.0", 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/Errors.js b/src/Errors.js index 22cf0ced..6f92075c 100644 --- a/src/Errors.js +++ b/src/Errors.js @@ -38,9 +38,9 @@ function toRapidResponse(error) { try { if (util.types.isNativeError(error) || _isError(error)) { return { - errorType: error.name, - errorMessage: error.message, - trace: error.stack.split('\n'), + errorType: error.name?.replace(/\x7F/g, '%7F'), + errorMessage: error.message?.replace(/\x7F/g, '%7F'), + trace: error.stack.replace(/\x7F/g, '%7F').split('\n'), }; } else { return { 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/RAPIDClient.js b/src/RAPIDClient.js index 84ce5f36..cf027879 100644 --- a/src/RAPIDClient.js +++ b/src/RAPIDClient.js @@ -44,7 +44,7 @@ module.exports = class RAPIDClient { */ postInvocationResponse(response, id, callback) { let bodyString = _trySerializeResponse(response); - this.nativeClient.done(id, bodyString); + this.nativeClient.done(encodeURIComponent(id), bodyString); callback(); } @@ -65,7 +65,10 @@ module.exports = class RAPIDClient { hostname: this.hostname, method: 'POST', port: this.port, - path: '/2018-06-01/runtime/invocation/' + id + '/response', + path: + '/2018-06-01/runtime/invocation/' + + encodeURIComponent(id) + + '/response', highWaterMark: options?.highWaterMark, }, }); @@ -108,7 +111,7 @@ module.exports = class RAPIDClient { let response = Errors.toRapidResponse(error); let bodyString = _trySerializeResponse(response); let xrayString = XRayError.formatted(error); - this.nativeClient.error(id, bodyString, xrayString); + this.nativeClient.error(encodeURIComponent(id), bodyString, xrayString); callback(); } 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/XRayError.js b/src/XRayError.js index 86c01d12..520152ec 100644 --- a/src/XRayError.js +++ b/src/XRayError.js @@ -50,7 +50,7 @@ class XRayFormattedCause { let stack = []; if (err.stack) { - let stackLines = err.stack.split('\n'); + let stackLines = err.stack.replace(/\x7F/g, '%7F').split('\n'); stackLines.shift(); stackLines.forEach((stackLine) => { @@ -79,8 +79,8 @@ class XRayFormattedCause { this.exceptions = [ { - type: err.name, - message: err.message, + type: err.name?.replace(/\x7F/g, '%7F'), + message: err.message?.replace(/\x7F/g, '%7F'), stack: stack, }, ]; 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/integration/codebuild-local/codebuild_build.sh b/test/integration/codebuild-local/codebuild_build.sh index ffadfa30..a858d940 100755 --- a/test/integration/codebuild-local/codebuild_build.sh +++ b/test/integration/codebuild-local/codebuild_build.sh @@ -36,6 +36,7 @@ function usage { echo " -a Used to specify an artifact output directory." echo "Options:" echo " -l IMAGE Used to override the default local agent image." + echo " -r Used to specify a report output directory." echo " -s Used to specify source information. Defaults to the current working directory for primary source." echo " * First (-s) is for primary source" echo " * Use additional (-s) in : format for secondary source" @@ -61,10 +62,11 @@ awsconfig_flag=false mount_src_dir_flag=false docker_privileged_mode_flag=false -while getopts "cmdi:a:s:b:e:l:p:h" opt; do +while getopts "cmdi:a:r:s:b:e:l:p:h" opt; do case $opt in i ) image_flag=true; image_name=$OPTARG;; a ) artifact_flag=true; artifact_dir=$OPTARG;; + r ) report_dir=$OPTARG;; b ) buildspec=$OPTARG;; c ) awsconfig_flag=true;; m ) mount_src_dir_flag=true;; @@ -106,6 +108,11 @@ fi docker_command+="\"IMAGE_NAME=$image_name\" -e \ \"ARTIFACTS=$(allOSRealPath "$artifact_dir")\"" +if [ -n "$report_dir" ] +then + docker_command+=" -e \"REPORTS=$(allOSRealPath "$report_dir")\"" +fi + if [ -z "$source_dirs" ] then docker_command+=" -e \"SOURCE=$(allOSRealPath "$PWD")\"" @@ -176,7 +183,12 @@ else docker_command+=" -e \"INITIATOR=$USER\"" fi -docker_command+=" amazon/aws-codebuild-local:latest" +if [ -n "$local_agent_image" ] +then + docker_command+=" $local_agent_image" +else + docker_command+=" public.ecr.aws/codebuild/local-builds:latest" +fi # Note we do not expose the AWS_SECRET_ACCESS_KEY or the AWS_SESSION_TOKEN exposed_command=$docker_command diff --git a/test/integration/codebuild/buildspec.os.alpine.1.yml b/test/integration/codebuild/buildspec.os.alpine.1.yml index a754022e..e4c14cd8 100644 --- a/test/integration/codebuild/buildspec.os.alpine.1.yml +++ b/test/integration/codebuild/buildspec.os.alpine.1.yml @@ -16,7 +16,6 @@ batch: DISTRO_VERSION: - "3.16" RUNTIME_VERSION: - - "14" - "16" - "18" phases: diff --git a/test/integration/codebuild/buildspec.os.alpine.2.yml b/test/integration/codebuild/buildspec.os.alpine.2.yml index 5117783f..a4528465 100644 --- a/test/integration/codebuild/buildspec.os.alpine.2.yml +++ b/test/integration/codebuild/buildspec.os.alpine.2.yml @@ -16,9 +16,9 @@ batch: env: variables: DISTRO_VERSION: - - "3.16" + - "3.18" RUNTIME_VERSION: - - "14" + - "20" phases: pre_build: commands: diff --git a/test/integration/codebuild/buildspec.os.alpine.4.yml b/test/integration/codebuild/buildspec.os.alpine.4.yml deleted file mode 100644 index a4528465..00000000 --- a/test/integration/codebuild/buildspec.os.alpine.4.yml +++ /dev/null @@ -1,102 +0,0 @@ -version: 0.2 - -env: - variables: - OS_DISTRIBUTION: alpine - NODE_BINARY_LOCATION: "/usr/local/bin/node" - NPX_BINARY_LOCATION: "/usr/local/bin/npx" -batch: - build-matrix: - static: - ignore-failure: false - env: - type: LINUX_CONTAINER - privileged-mode: true - dynamic: - env: - variables: - DISTRO_VERSION: - - "3.18" - RUNTIME_VERSION: - - "20" -phases: - pre_build: - commands: - - export IMAGE_TAG="nodejs-${OS_DISTRIBUTION}-${DISTRO_VERSION}:${RUNTIME_VERSION}" - - echo "Extracting and including the Runtime Interface Emulator" - - SCRATCH_DIR=".scratch" - - mkdir "${SCRATCH_DIR}" - - tar -xvf test/integration/resources/aws-lambda-rie.tar.gz --directory "${SCRATCH_DIR}" - - > - cp "test/integration/docker/Dockerfile.programmatic.${OS_DISTRIBUTION}" \ - "${SCRATCH_DIR}/Dockerfile.programmatic.${OS_DISTRIBUTION}.tmp" - - > - echo "RUN apk add curl" >> \ - "${SCRATCH_DIR}/Dockerfile.programmatic.${OS_DISTRIBUTION}.tmp" - - > - echo "COPY ${SCRATCH_DIR}/aws-lambda-rie /usr/bin/aws-lambda-rie" >> \ - "${SCRATCH_DIR}/Dockerfile.programmatic.${OS_DISTRIBUTION}.tmp" - - > - if [[ -z "${DOCKERHUB_USERNAME}" && -z "${DOCKERHUB_PASSWORD}" ]]; - then - echo "DockerHub credentials not set as CodeBuild environment variables. Continuing without docker login." - else - echo "Performing DockerHub login . . ." - docker login -u $DOCKERHUB_USERNAME -p $DOCKERHUB_PASSWORD - fi - - echo "Building image ${IMAGE_TAG}" - - > - docker build . \ - -f "${SCRATCH_DIR}/Dockerfile.programmatic.${OS_DISTRIBUTION}.tmp" \ - -t "${IMAGE_TAG}" \ - --build-arg RUNTIME_VERSION="${RUNTIME_VERSION}" \ - --build-arg DISTRO_VERSION="${DISTRO_VERSION}" - build: - commands: - - set -x - - echo "Running Image ${IMAGE_TAG}" - - docker network create "${OS_DISTRIBUTION}-network" - - > - docker run \ - --detach \ - -e "NODE_BINARY_LOCATION=${NODE_BINARY_LOCATION}" \ - --name "${OS_DISTRIBUTION}-app" \ - --network "${OS_DISTRIBUTION}-network" \ - --entrypoint="" \ - "${IMAGE_TAG}" \ - sh -c '/usr/bin/aws-lambda-rie ${NODE_BINARY_LOCATION} index.mjs' - - sleep 2 - - > - docker run \ - --name "${OS_DISTRIBUTION}-tester" \ - --env "TARGET=${OS_DISTRIBUTION}-app" \ - --network "${OS_DISTRIBUTION}-network" \ - --entrypoint="" \ - "${IMAGE_TAG}" \ - sh -c 'curl -X POST "http://${TARGET}:8080/2015-03-31/functions/function/invocations" -d "{}" --max-time 10' - - actual="$(docker logs --tail 1 "${OS_DISTRIBUTION}-tester" | xargs)" - - expected='success' - - | - echo "Response: ${actual}" - if [[ "$actual" != "$expected" ]]; then - echo "fail! runtime: $RUNTIME - expected output $expected - got $actual" - echo "---------Container Logs: ${OS_DISTRIBUTION}-app----------" - echo - docker logs "${OS_DISTRIBUTION}-app" - echo - echo "---------------------------------------------------" - echo "--------Container Logs: ${OS_DISTRIBUTION}-tester--------" - echo - docker logs "${OS_DISTRIBUTION}-tester" - echo - echo "---------------------------------------------------" - exit -1 - fi - finally: - - echo "Cleaning up..." - - docker stop "${OS_DISTRIBUTION}-app" || true - - docker rm --force "${OS_DISTRIBUTION}-app" || true - - docker stop "${OS_DISTRIBUTION}-tester" || true - - docker rm --force "${OS_DISTRIBUTION}-tester" || true - - docker network rm "${OS_DISTRIBUTION}-network" || true - - docker rmi "${IMAGE_TAG}" || true diff --git a/test/integration/codebuild/buildspec.os.centos.yml b/test/integration/codebuild/buildspec.os.centos.yml index 586f4cf6..f3be37e2 100644 --- a/test/integration/codebuild/buildspec.os.centos.yml +++ b/test/integration/codebuild/buildspec.os.centos.yml @@ -14,11 +14,8 @@ batch: env: variables: DISTRO_VERSION: - - "stream8" - "stream9" RUNTIME_VERSION: - - "14" - - "16" - "18" - "20" phases: diff --git a/test/integration/codebuild/buildspec.os.debian.1.yml b/test/integration/codebuild/buildspec.os.debian.1.yml index 9978db79..de1fd34c 100644 --- a/test/integration/codebuild/buildspec.os.debian.1.yml +++ b/test/integration/codebuild/buildspec.os.debian.1.yml @@ -17,7 +17,6 @@ batch: - "buster" - "bullseye" RUNTIME_VERSION: - - "14" - "16" - "18" - "20" diff --git a/test/integration/codebuild/buildspec.os.ubuntu.1.yml b/test/integration/codebuild/buildspec.os.ubuntu.1.yml index 2427e5ac..7adb59ba 100644 --- a/test/integration/codebuild/buildspec.os.ubuntu.1.yml +++ b/test/integration/codebuild/buildspec.os.ubuntu.1.yml @@ -18,7 +18,6 @@ batch: - "20.04" - "22.04" RUNTIME_VERSION: - - "14" - "16" phases: pre_build: diff --git a/test/integration/docker/Dockerfile.echo.alpine b/test/integration/docker/Dockerfile.echo.alpine index bba37350..10f1aab4 100644 --- a/test/integration/docker/Dockerfile.echo.alpine +++ b/test/integration/docker/Dockerfile.echo.alpine @@ -40,11 +40,6 @@ RUN mkdir -p ${FUNCTION_DIR} WORKDIR ${FUNCTION_DIR}/deps/aws-lambda-ric COPY . . -# Node14 uses npm@6.14.18 by default which will downgrade permissions, if it's root, -# before running any build scripts: https://github.com/npm/npm/issues/3497 -# Starting from npm@7.0.0, when npm is run as root, -# scripts are always run with the effective uid and gid of the working directory owner. -RUN if [[ $(node -v | cut -c 1-3) == "v14" ]] ; then npm install -g npm@7 ; fi RUN make build && \ npm run test:unit diff --git a/test/integration/docker/Dockerfile.echo.amazonlinux b/test/integration/docker/Dockerfile.echo.amazonlinux index c17bfbd6..b54956df 100644 --- a/test/integration/docker/Dockerfile.echo.amazonlinux +++ b/test/integration/docker/Dockerfile.echo.amazonlinux @@ -51,8 +51,8 @@ WORKDIR ${FUNCTION_DIR}/deps/aws-lambda-ric COPY . . # Node14 uses npm@6.14.18 by default which will downgrade permissions, if it's root, -# before running any build scripts: https://github.com/npm/npm/issues/3497 -# Starting from npm@7.0.0, when npm is run as root, +# before running any build scripts: https://github.com/npm/npm/issues/3497 +# Starting from npm@7.0.0, when npm is run as root, # scripts are always run with the effective uid and gid of the working directory owner. RUN if [[ $(node -v | cut -c 1-3) == "v14" ]] ; then npm install -g npm@7 ; fi RUN make build && \ diff --git a/test/integration/docker/Dockerfile.echo.centos b/test/integration/docker/Dockerfile.echo.centos index df403188..778b5560 100644 --- a/test/integration/docker/Dockerfile.echo.centos +++ b/test/integration/docker/Dockerfile.echo.centos @@ -9,7 +9,7 @@ FROM quay.io/centos/centos:${DISTRO_VERSION} AS node-centos # Include global arg in this stage of the build ARG RUNTIME_VERSION # Install NodeJS -RUN curl -sL https://rpm.nodesource.com/setup_${RUNTIME_VERSION}.x | bash - && \ +RUN yum module enable -y nodejs:${RUNTIME_VERSION} && \ yum install -y nodejs @@ -40,11 +40,6 @@ RUN mkdir -p ${FUNCTION_DIR} WORKDIR ${FUNCTION_DIR}/deps/aws-lambda-ric COPY . . -# Node14 uses npm@6.14.18 by default which will downgrade permissions, if it's root, -# before running any build scripts: https://github.com/npm/npm/issues/3497 -# Starting from npm@7.0.0, when npm is run as root, -# scripts are always run with the effective uid and gid of the working directory owner. -RUN if [[ $(node -v | cut -c 1-3) == "v14" ]] ; then npm install -g npm@7 ; fi RUN make build && \ npm run test:unit diff --git a/test/integration/docker/Dockerfile.echo.debian b/test/integration/docker/Dockerfile.echo.debian index 4581ad59..a611d8f3 100644 --- a/test/integration/docker/Dockerfile.echo.debian +++ b/test/integration/docker/Dockerfile.echo.debian @@ -22,11 +22,6 @@ RUN mkdir -p ${FUNCTION_DIR} WORKDIR ${FUNCTION_DIR}/deps/aws-lambda-ric COPY . . -# Node14 uses npm@6.14.18 by default which will downgrade permissions, if it's root, -# before running any build scripts: https://github.com/npm/npm/issues/3497 -# Starting from npm@7.0.0, when npm is run as root, -# scripts are always run with the effective uid and gid of the working directory owner. -RUN if [ $(node -v | cut -c 1-3) = "v14" ] ; then npm install -g npm@7 ; fi RUN make build && \ npm run test:unit diff --git a/test/integration/docker/Dockerfile.echo.ubuntu b/test/integration/docker/Dockerfile.echo.ubuntu index bbabd50b..567768bf 100644 --- a/test/integration/docker/Dockerfile.echo.ubuntu +++ b/test/integration/docker/Dockerfile.echo.ubuntu @@ -34,7 +34,8 @@ RUN apt-get update && \ automake \ libtool \ wget \ - libcurl4-openssl-dev + libcurl4-openssl-dev \ + python3 # Install a modern CMake RUN wget --quiet -O cmake-install https://github.com/Kitware/CMake/releases/download/v3.20.0/cmake-3.20.0-linux-${ARCHITECTURE}.sh && \ sh cmake-install --skip-license --prefix=/usr --exclude-subdirectory; @@ -48,11 +49,6 @@ RUN mkdir -p ${FUNCTION_DIR} WORKDIR ${FUNCTION_DIR}/deps/aws-lambda-ric COPY . . -# Node14 uses npm@6.14.18 by default which will downgrade permissions, if it's root, -# before running any build scripts: https://github.com/npm/npm/issues/3497 -# Starting from npm@7.0.0, when npm is run as root, -# scripts are always run with the effective uid and gid of the working directory owner. -RUN if [ $(node -v | cut -c 1-3) = "v14" ] ; then npm install -g npm@7 ; fi RUN make build && \ npm run test:unit diff --git a/test/integration/docker/Dockerfile.programmatic.alpine b/test/integration/docker/Dockerfile.programmatic.alpine index 1057cd24..5bcb4b7b 100644 --- a/test/integration/docker/Dockerfile.programmatic.alpine +++ b/test/integration/docker/Dockerfile.programmatic.alpine @@ -40,11 +40,6 @@ RUN mkdir -p ${FUNCTION_DIR} WORKDIR ${FUNCTION_DIR}/deps/aws-lambda-ric COPY . . -# Node14 uses npm@6.14.18 by default which will downgrade permissions, if it's root, -# before running any build scripts: https://github.com/npm/npm/issues/3497 -# Starting from npm@7.0.0, when npm is run as root, -# scripts are always run with the effective uid and gid of the working directory owner. -RUN if [[ $(node -v | cut -c 1-3) == "v14" ]] ; then npm install -g npm@7 ; fi RUN make build && \ npm run test:unit diff --git a/test/unit/ErrorsTest.js b/test/unit/ErrorsTest.js index f72b73bd..8f88ae62 100644 --- a/test/unit/ErrorsTest.js +++ b/test/unit/ErrorsTest.js @@ -5,7 +5,7 @@ 'use strict'; require('should'); -let Errors = require('../../src/Errors'); +let Errors = require('lambda-runtime/Errors'); describe('Formatted Error Logging', () => { it('should fall back to a minimal error format when an exception occurs', () => { @@ -19,3 +19,14 @@ describe('Formatted Error Logging', () => { loggedError.should.have.property('trace').with.length(11); }); }); + +describe('Invalid chars in HTTP header', () => { + it('should be replaced', () => { + let errorWithInvalidChar = new Error('\x7F \x7F'); + errorWithInvalidChar.name = 'ErrorWithInvalidChar'; + + let loggedError = Errors.toRapidResponse(errorWithInvalidChar); + loggedError.should.have.property('errorType', 'ErrorWithInvalidChar'); + loggedError.should.have.property('errorMessage', '%7F %7F'); + }); +}); diff --git a/test/unit/FakeTelemetryTarget.js b/test/unit/FakeTelemetryTarget.js index db9b28d8..21b38fcf 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,10 @@ 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/InvokeContextTest.js b/test/unit/InvokeContextTest.js index 58b35a2b..c351b5d2 100644 --- a/test/unit/InvokeContextTest.js +++ b/test/unit/InvokeContextTest.js @@ -7,7 +7,7 @@ require('should'); const sleep = require('util').promisify(setTimeout); -let InvokeContext = require('../../src/InvokeContext'); +let InvokeContext = require('lambda-runtime/InvokeContext'); describe('Getting remaining invoke time', () => { it('should reduce by at least elapsed time', async () => { diff --git a/test/unit/LogPatchTest.js b/test/unit/LogPatchTest.js index 117f249c..7a8d2f6f 100644 --- a/test/unit/LogPatchTest.js +++ b/test/unit/LogPatchTest.js @@ -4,12 +4,64 @@ 'use strict'; -let should = require('should'); -let LogPatch = require('../../src/LogPatch'); -let Errors = require('../../src/Errors'); +const util = require('util'); -let { captureStream, consoleSnapshot } = require('./LoggingGlobals'); +let should = require('should'); +let LogPatch = require('lambda-runtime/LogPatch'); +let Errors = require('lambda-runtime/Errors'); +let assert = require('assert'); + +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']; + } +}; diff --git a/test/unit/RAPIDClientTest.js b/test/unit/RAPIDClientTest.js new file mode 100644 index 00000000..828bd6de --- /dev/null +++ b/test/unit/RAPIDClientTest.js @@ -0,0 +1,117 @@ +/** + * Copyright 2024 Amazon.com, Inc. or its affiliates. All Rights Reserved. + */ + +'use strict'; + +require('should'); + +let RAPIDClient = require('lambda-runtime/RAPIDClient.js'); +let runtimeErrors = require('lambda-runtime/Errors.js'); + +/** + * Stub request object. + * Provides no-op definitions of the request functions used by the rapid client. + */ +const noOpRequest = Object.freeze({ + /* no op, return itself to allow continuations/chaining */ + on: () => noOpRequest, + /* no op, return itself to allow continuations/chaining */ + end: () => noOpRequest, +}); + +class StubHttp { + constructor() { + this.lastUsedOptions = {}; + this.Agent = class FakeAgent {}; + } + + request(options, _callback) { + this.lastUsedOptions = options; + return noOpRequest; + } +} + +class NoOpNativeHttp { + constructor() { + this.lastRequestId = ''; + this.lastErrorRequestId = ''; + } + + done(requestId) { + this.lastRequestId = requestId; + } + + error(requestId) { + this.lastErrorRequestId = requestId; + } +} + +class EvilError extends Error { + get name() { + throw 'gotcha'; + } +} + +const EXPECTED_ERROR_HEADER = 'Lambda-Runtime-Function-Error-Type'; + +describe('building error requests with the RAPIDClient', () => { + let stubHttp = new StubHttp(); + let client = new RAPIDClient('notUsed:1337', stubHttp, new NoOpNativeHttp()); + + let errors = [ + [new Error('generic failure'), 'Error'], + [new runtimeErrors.ImportModuleError(), 'Runtime.ImportModuleError'], + [new runtimeErrors.HandlerNotFound(), 'Runtime.HandlerNotFound'], + [new runtimeErrors.MalformedHandlerName(), 'Runtime.MalformedHandlerName'], + [new runtimeErrors.UserCodeSyntaxError(), 'Runtime.UserCodeSyntaxError'], + [{ data: 'some random object' }, 'object'], + [new EvilError(), 'handled'], + ]; + + describe('the error header in postInitError', () => { + errors.forEach(([error, name]) => { + it(`should be ${name} for ${error.constructor.name}`, () => { + client.postInitError(error); + stubHttp.lastUsedOptions.should.have + .property('headers') + .have.property(EXPECTED_ERROR_HEADER, name); + }); + }); + }); +}); + +describe('invalid request id works', () => { + const nativeClient = new NoOpNativeHttp(); + const client = new RAPIDClient('notUsed:1337', undefined, nativeClient); + + [ + // Encoding expected: + ['#', '%23'], + ['%', '%25'], + ['/', '%2F'], + ['?', '%3F'], + ['\x7F', '%7F'], + ["", "%3Cscript%3Ealert('1')%3C%2Fscript%3E"], + ['⚡', '%E2%9A%A1'], + + // No encoding: + ['.', '.'], + ['..', '..'], + ['a', 'a'], + [ + '59b22c65-fa81-47fb-a6dc-23028a63566f', + '59b22c65-fa81-47fb-a6dc-23028a63566f', + ], + ].forEach(([requestId, expected]) => { + it(`postInvocationResponse should encode requestId: '${requestId}'`, () => { + client.postInvocationResponse({}, requestId, () => {}); + nativeClient.lastRequestId.should.be.equal(expected); + }); + + it(`postInvocationError should encode requestId: '${requestId}'`, () => { + client.postInvocationError(new Error(), requestId, () => {}); + nativeClient.lastErrorRequestId.should.be.equal(expected); + }); + }); +}); diff --git a/test/unit/ResponseStreamTest.js b/test/unit/ResponseStreamTest.js index dbfe9405..b5d46c26 100644 --- a/test/unit/ResponseStreamTest.js +++ b/test/unit/ResponseStreamTest.js @@ -9,10 +9,10 @@ const ServerMock = require('mock-http-server'); const { createResponseStream, tryCallFail, -} = require('../../src/ResponseStream.js'); -const { HttpResponseStream } = require('../../src/HttpResponseStream.js'); -const { InvalidStreamingOperation } = require('../../src/Errors.js'); -const { verbose, vverbose, vvverbose } = require('../../src/VerboseLog').logger( +} = require('lambda-runtime/ResponseStream.js'); +const { HttpResponseStream } = require('lambda-runtime/HttpResponseStream.js'); +const { InvalidStreamingOperation } = require('lambda-runtime/Errors.js'); +const { verbose, vverbose, vvverbose } = require('lambda-runtime/VerboseLog').logger( 'TEST', ); const Throttle = require('throttle'); diff --git a/test/unit/StreamingContextTest.js b/test/unit/StreamingContextTest.js index b9e67a08..833ac8f7 100644 --- a/test/unit/StreamingContextTest.js +++ b/test/unit/StreamingContextTest.js @@ -5,9 +5,9 @@ 'use strict'; require('should'); -const StreamingContext = require('../../src/StreamingContext.js'); +const StreamingContext = require('lambda-runtime/StreamingContext.js'); const { PassThrough } = require('stream'); -const BeforeExitListener = require('../../src/BeforeExitListener.js'); +const BeforeExitListener = require('lambda-runtime/BeforeExitListener.js'); class MockRapidClient { constructor() { diff --git a/test/unit/UserFunctionTest.js b/test/unit/UserFunctionTest.js index cf53b091..6ffe4c0b 100644 --- a/test/unit/UserFunctionTest.js +++ b/test/unit/UserFunctionTest.js @@ -10,8 +10,8 @@ const { HandlerNotFound, ImportModuleError, MalformedHandlerName, -} = require('../../src/Errors.js'); -const UserFunction = require('../../src/UserFunction.js'); +} = require('lambda-runtime/Errors.js'); +const UserFunction = require('lambda-runtime/UserFunction.js'); const TEST_ROOT = path.join(__dirname, '../'); const HANDLERS_ROOT = path.join(TEST_ROOT, 'handlers');