diff --git a/CHANGELOG.asciidoc b/CHANGELOG.asciidoc index 312c2c178d..05bf8be84e 100644 --- a/CHANGELOG.asciidoc +++ b/CHANGELOG.asciidoc @@ -32,6 +32,29 @@ Notes: === Node.js Agent version 3.x +==== Unreleased + +[float] +===== Breaking changes + +[float] +===== Features + +* Improve error handling with AWS Lambda. When used together with the + https://github.com/elastic/apm-aws-lambda[Elastic AWS Lambda extension] + v1.4.0 or greater, the APM agent will pre-register a partial transaction + before the user's handler function is run. If the handler function fails + with a Lambda timeout, `uncaughtException`, `unhandledRejection`, or crash + then the Lambda extension will report the failed transaction so it can be + seen in the Kibana APM app. ({pull}3285[#3285]) + +[float] +===== Bug fixes + +[float] +===== Chores + + [[release-notes-3.45.0]] ==== 3.45.0 2023/04/28 diff --git a/docs/lambda.asciidoc b/docs/lambda.asciidoc index b403350996..02e0dcf5b5 100644 --- a/docs/lambda.asciidoc +++ b/docs/lambda.asciidoc @@ -55,38 +55,29 @@ You can optionally <> or the {apm-la That's it. After following the steps above, you're ready to go! Your Lambda function invocations should be traced from now on. -Read on to learn more about the features and limitations of the Node.js APM Agent on AWS Lambda Functions. [float] -[[aws-lambda-features-and-caveats]] -=== Features and Caveats +[[aws-lambda-features]] +=== Features -The AWS Lambda as a runtime behaves differently from conventional runtimes. -While most APM and monitoring concepts apply to AWS Lambda, there are a few differences and limitations to be aware of. +The AWS Lambda instrumentation will report a transaction for all function invocations +and trace any <>. In addition, the +created transactions will capture additional data for a number of Lambda +trigger types -- API Gateway, SNS, SQS, S3 (with the trigger is a single event), +and ELB. -[float] -[[aws-lambda-performance-monitoring]] -==== Performance monitoring - -Elastic APM automatically measures the performance of your lambda function executions. -It records traces for database queries, external HTTP requests, -and other slow operations that happen during execution. - -By default, the agent will trace <>. -To trace other events, -you can use custom traces. -For information about custom traces, -see the <>. - -[float] -[[aws-lambda-error-monitoring]] -==== Error monitoring +A transaction will be reported for Lambda invocations that fail due to a +timeout, crash, `uncaughtException`, or `unhandledRejection`. (This requires +APM agent v3.45.0 or later and +https://www.elastic.co/guide/en/apm/lambda/current/aws-lambda-arch.html[Elastic's APM Lambda extension] +version 1.4.0 or later.) -include::./shared-set-up.asciidoc[tag=error-logging] [float] [[aws-lambda-caveats]] -==== Caveats +=== Caveats and Troubleshooting * System and custom metrics are not collected for Lambda functions. This is both because most of those are irrelevant and because the interval-based event sending model is not suitable for FaaS environments. +* Lambda instrumentation does not currently work when the (deprecated) <> configuration setting is used. +* The APM agent does not yet support a Lambda handler module that uses ECMAScript modules (ESM). That means a your handler file name should end with ".js" (and not have `"type": "module"` in package.json if you have one) or end with ".cjs". A handler file that uses the ".mjs" suffix will not be instrumented by the APM agent. diff --git a/lib/lambda.js b/lib/lambda.js index 77d70bcca4..93d9c5d2fc 100644 --- a/lib/lambda.js +++ b/lib/lambda.js @@ -439,6 +439,54 @@ function setS3SingleData (trans, event, context, faasId, isColdStart) { function elasticApmAwsLambda (agent) { const log = agent.logger + /** + * Register this transaction with the Lambda extension, if possible. This + * function is `await`able so that the transaction is registered before + * executing the user's Lambda handler. + * + * Perf note: Using a Lambda sized to have 1 vCPU (1769MB memory), some + * rudimentary perf tests showed an average of 0.8ms for this call to the ext. + */ + function registerTransaction (trans, awsRequestId) { + if (!agent._transport) { + return + } + if (!agent._transport.lambdaShouldRegisterTransactions()) { + return + } + + // Reproduce the filtering logic from `Instrumentation.prototype.addEndedTransaction`. + if (agent._conf.contextPropagationOnly) { + return + } + if (!trans.sampled && !agent._transport.supportsKeepingUnsampledTransaction()) { + return + } + + var payload = trans.toJSON() + // If this partial transaction is used, the Lambda Extension will fill in: + // - `transaction.result` will be set to one of: + // - The "status" field from the Logs API platform `runtimeDone` message. + // https://docs.aws.amazon.com/lambda/latest/dg/runtimes-logs-api.html#runtimes-logs-api-ref-done + // Values: "success", "failure" + // - The "shutdownReason" field from the `Shutdown` event from the Extensions API. + // https://docs.aws.amazon.com/lambda/latest/dg/runtimes-extensions-api.html#runtimes-lifecycle-shutdown + // Values: "spindown", "timeout", "failure" (I think these are the values.) + // - `transaction.outcome` will be set to "failure" if the status above is + // not "success". Therefore we want a default outcome value. + // - `transaction.duration` will be estimated + delete payload.result + delete payload.duration + + payload = agent._transactionFilters.process(payload) + if (!payload) { + log.trace({ traceId: trans.traceId, transactionId: trans.id }, 'transaction ignored by filter') + return + } + + return agent._transport.lambdaRegisterTransaction(payload, awsRequestId) + } + function endAndFlushTransaction (err, result, trans, event, context, triggerType, cb) { log.trace({ awsRequestId: context && context.awsRequestId }, 'lambda: fn end') @@ -509,7 +557,7 @@ function elasticApmAwsLambda (agent) { } } - return function wrapLambda (type, fn) { + return function wrapLambdaHandler (type, fn) { if (typeof type === 'function') { fn = type type = 'request' @@ -519,7 +567,7 @@ function elasticApmAwsLambda (agent) { return fn } - return function wrappedLambda (event, context, callback) { + return async function wrappedLambdaHandler (event, context, callback) { if (!(event && context && typeof callback === 'function')) { // Skip instrumentation if arguments are unexpected. // https://docs.aws.amazon.com/lambda/latest/dg/nodejs-handler.html @@ -592,16 +640,32 @@ function elasticApmAwsLambda (agent) { log.warn(`not setting transaction data for triggerType=${triggerType}`) } - // Wrap context and callback to finish and send transaction + // Wrap context and callback to finish and send transaction. + // Note: Wrapping context needs to happen *before any `await` calls* in + // this function, otherwise the Lambda Node.js Runtime will call the + // *unwrapped* `context.{succeed,fail,done}()` methods. wrapContext(trans, event, context, triggerType) - if (typeof callback === 'function') { - callback = wrapLambdaCallback(trans, event, context, triggerType, callback) - } + const wrappedCallback = wrapLambdaCallback(trans, event, context, triggerType, callback) + + await registerTransaction(trans, context.awsRequestId) try { - return fn.call(this, event, context, callback) + var retval = fn.call(this, event, context, wrappedCallback) + if (retval instanceof Promise) { + return retval + } else { + // In this case, our wrapping of the user's handler has changed it + // from a sync function to an async function. We need to ensure the + // Lambda Runtime does not end the invocation based on this returned + // promise -- the invocation should end when the `callback` is called + // -- so we return a promise that never resolves. + return new Promise((resolve, reject) => { /* never resolves */ }) + } } catch (handlerErr) { - callback(handlerErr) + wrappedCallback(handlerErr) + // Return a promise that never resolves, so that the Lambda Runtime's + // doesn't attempt its "success" handling. + return new Promise((resolve, reject) => { /* never resolves */ }) } } } diff --git a/lib/noop-transport.js b/lib/noop-transport.js index 0ac3a47d48..0e26d2ed80 100644 --- a/lib/noop-transport.js +++ b/lib/noop-transport.js @@ -17,7 +17,10 @@ class NoopTransport { addMetadataFilter (fn) {} setExtraMetadata (metadata) {} + lambdaStart () {} + lambdaShouldRegisterTransactions () { return true } + lambdaRegisterTransaction (trans, awsRequestId) { } sendSpan (span, cb) { if (cb) { diff --git a/package-lock.json b/package-lock.json index f03e684660..368998b779 100644 --- a/package-lock.json +++ b/package-lock.json @@ -17,7 +17,7 @@ "basic-auth": "^2.0.1", "cookie": "^0.5.0", "core-util-is": "^1.0.2", - "elastic-apm-http-client": "11.3.1", + "elastic-apm-http-client": "11.4.0", "end-of-stream": "^1.4.4", "error-callsites": "^2.0.4", "error-stack-parser": "^2.0.6", @@ -3941,18 +3941,26 @@ } }, "node_modules/agentkeepalive": { - "version": "4.2.1", - "resolved": "https://registry.npmjs.org/agentkeepalive/-/agentkeepalive-4.2.1.tgz", - "integrity": "sha512-Zn4cw2NEqd+9fiSVWMscnjyQ1a8Yfoc5oBajLeo5w+YBHgDUcEBY2hS4YpTz6iN5f/2zQiktcuM6tS8x1p9dpA==", + "version": "4.3.0", + "resolved": "https://registry.npmjs.org/agentkeepalive/-/agentkeepalive-4.3.0.tgz", + "integrity": "sha512-7Epl1Blf4Sy37j4v9f9FjICCh4+KAQOyXgHEwlyBiAQLbhKdq/i2QQU3amQalS/wPhdPzDXPL5DMR5bkn+YeWg==", "dependencies": { "debug": "^4.1.0", - "depd": "^1.1.2", + "depd": "^2.0.0", "humanize-ms": "^1.2.1" }, "engines": { "node": ">= 8.0.0" } }, + "node_modules/agentkeepalive/node_modules/depd": { + "version": "2.0.0", + "resolved": "https://registry.npmjs.org/depd/-/depd-2.0.0.tgz", + "integrity": "sha512-g7nH6P6dyDioJogAAGprGpCtVImJhpPk/roCzdb3fIh61/s/nPsfR6onyMwkCAR/OlC3yBC0lESvUoQEAssIrw==", + "engines": { + "node": ">= 0.8" + } + }, "node_modules/aggregate-error": { "version": "3.1.0", "resolved": "https://registry.npmjs.org/aggregate-error/-/aggregate-error-3.1.0.tgz", @@ -5960,6 +5968,7 @@ "version": "1.1.2", "resolved": "https://registry.npmjs.org/depd/-/depd-1.1.2.tgz", "integrity": "sha1-m81S4UwJd2PnSbJ0xDRu0uVgtak=", + "dev": true, "engines": { "node": ">= 0.6" } @@ -6154,9 +6163,9 @@ "dev": true }, "node_modules/elastic-apm-http-client": { - "version": "11.3.1", - "resolved": "https://registry.npmjs.org/elastic-apm-http-client/-/elastic-apm-http-client-11.3.1.tgz", - "integrity": "sha512-AicMDPJYmO4tGTRcZQZFS7nhyGAQ6f4hUTKQVxiM/6mHo6F895JsJoPVwOE2yCathKDnD9LVS9zWdT2wvG8gxA==", + "version": "11.4.0", + "resolved": "https://registry.npmjs.org/elastic-apm-http-client/-/elastic-apm-http-client-11.4.0.tgz", + "integrity": "sha512-DxPy8MFrcL04qxMG4sxmI5yIKrFCIhJc2xx0eupE3qjCIIPHeLJaUrjFbQbsAnnuhC9sljWsEebtFweHj+Vmug==", "dependencies": { "agentkeepalive": "^4.2.1", "breadth-filter": "^2.0.0", @@ -18490,13 +18499,20 @@ } }, "agentkeepalive": { - "version": "4.2.1", - "resolved": "https://registry.npmjs.org/agentkeepalive/-/agentkeepalive-4.2.1.tgz", - "integrity": "sha512-Zn4cw2NEqd+9fiSVWMscnjyQ1a8Yfoc5oBajLeo5w+YBHgDUcEBY2hS4YpTz6iN5f/2zQiktcuM6tS8x1p9dpA==", + "version": "4.3.0", + "resolved": "https://registry.npmjs.org/agentkeepalive/-/agentkeepalive-4.3.0.tgz", + "integrity": "sha512-7Epl1Blf4Sy37j4v9f9FjICCh4+KAQOyXgHEwlyBiAQLbhKdq/i2QQU3amQalS/wPhdPzDXPL5DMR5bkn+YeWg==", "requires": { "debug": "^4.1.0", - "depd": "^1.1.2", + "depd": "^2.0.0", "humanize-ms": "^1.2.1" + }, + "dependencies": { + "depd": { + "version": "2.0.0", + "resolved": "https://registry.npmjs.org/depd/-/depd-2.0.0.tgz", + "integrity": "sha512-g7nH6P6dyDioJogAAGprGpCtVImJhpPk/roCzdb3fIh61/s/nPsfR6onyMwkCAR/OlC3yBC0lESvUoQEAssIrw==" + } } }, "aggregate-error": { @@ -20048,7 +20064,8 @@ "depd": { "version": "1.1.2", "resolved": "https://registry.npmjs.org/depd/-/depd-1.1.2.tgz", - "integrity": "sha1-m81S4UwJd2PnSbJ0xDRu0uVgtak=" + "integrity": "sha1-m81S4UwJd2PnSbJ0xDRu0uVgtak=", + "dev": true }, "dependency-check": { "version": "4.1.0", @@ -20201,9 +20218,9 @@ "dev": true }, "elastic-apm-http-client": { - "version": "11.3.1", - "resolved": "https://registry.npmjs.org/elastic-apm-http-client/-/elastic-apm-http-client-11.3.1.tgz", - "integrity": "sha512-AicMDPJYmO4tGTRcZQZFS7nhyGAQ6f4hUTKQVxiM/6mHo6F895JsJoPVwOE2yCathKDnD9LVS9zWdT2wvG8gxA==", + "version": "11.4.0", + "resolved": "https://registry.npmjs.org/elastic-apm-http-client/-/elastic-apm-http-client-11.4.0.tgz", + "integrity": "sha512-DxPy8MFrcL04qxMG4sxmI5yIKrFCIhJc2xx0eupE3qjCIIPHeLJaUrjFbQbsAnnuhC9sljWsEebtFweHj+Vmug==", "requires": { "agentkeepalive": "^4.2.1", "breadth-filter": "^2.0.0", diff --git a/package.json b/package.json index fa1577bc6d..9221013039 100644 --- a/package.json +++ b/package.json @@ -94,7 +94,7 @@ "basic-auth": "^2.0.1", "cookie": "^0.5.0", "core-util-is": "^1.0.2", - "elastic-apm-http-client": "11.3.1", + "elastic-apm-http-client": "11.4.0", "end-of-stream": "^1.4.4", "error-callsites": "^2.0.4", "error-stack-parser": "^2.0.6", diff --git a/test/_capturing_transport.js b/test/_capturing_transport.js index a731152cf2..f28cbad9d0 100644 --- a/test/_capturing_transport.js +++ b/test/_capturing_transport.js @@ -94,6 +94,13 @@ class CapturingTransport { } } + lambdaShouldRegisterTransactions () { + return true + } + + lambdaRegisterTransaction (trans, awsRequestId) { + } + supportsKeepingUnsampledTransaction () { return true } diff --git a/test/_mock_apm_server.js b/test/_mock_apm_server.js index 9587199336..353c970c3d 100644 --- a/test/_mock_apm_server.js +++ b/test/_mock_apm_server.js @@ -5,6 +5,7 @@ */ // A mock APM server to use in tests. +// It also has an option to attempt to behave like the Elastic Lambda extension. // // Usage: // const server = new MockAPMServer(opts) @@ -22,14 +23,20 @@ const { URL } = require('url') const zlib = require('zlib') class MockAPMServer { - // - @param {Object} opts - // - {String} opts.apmServerVersion - The version to report in the - // "GET /" response body. Defaults to "8.0.0". + /** + * @param {object} opts + * - {string} opts.apmServerVersion - The version to report in the `GET /` + * response body. Defaults to "8.0.0". + * - {boolean} opts.mockLambdaExtension - Default false. If enabled then + * this will add some behaviour expected of APM Lambda extension, e.g. + * responding to the `POST /register/transaction` endpoint. + */ constructor (opts) { opts = opts || {} this.clear() this.serverUrl = null // set in .start() - this.apmServerVersion = opts.apmServerVersion || '8.0.0' + this._apmServerVersion = opts.apmServerVersion || '8.0.0' + this._mockLambdaExtension = !!opts.mockLambdaExtension this._http = http.createServer(this._onRequest.bind(this)) } @@ -60,7 +67,7 @@ class MockAPMServer { resBody = JSON.stringify({ build_date: '2021-09-16T02:05:39Z', build_sha: 'a183f675ecd03fca4a897cbe85fda3511bc3ca43', - version: this.apmServerVersion + version: this._apmServerVersion }) } else if (parsedUrl.pathname === '/config/v1/agents') { // Central config mocking. @@ -75,6 +82,12 @@ class MockAPMServer { }) resBody = '{}' res.writeHead(202) + } else if (this._mockLambdaExtension && req.method === 'POST' && parsedUrl.pathname === '/register/transaction') { + // See `func handleTransactionRegistration` in apm-aws-lambda.git. + // This mock doesn't handle the various checks there. It only handles + // the status code, so the APM agent will continue to register + // transactions. + res.writeHead(200) } else { res.writeHead(404) } diff --git a/test/lambda/callbacks.test.js b/test/lambda/callbacks.test.js index bbfed3afd9..99fc942940 100644 --- a/test/lambda/callbacks.test.js +++ b/test/lambda/callbacks.test.js @@ -6,6 +6,11 @@ 'use strict' +if (process.env.ELASTIC_APM_CONTEXT_MANAGER === 'patch') { + console.log('# SKIP Lambda instrumentation currently does not work with contextManager="patch"') + process.exit() +} + const test = require('tape') const lambdaLocal = require('lambda-local') diff --git a/test/lambda/context.test.js b/test/lambda/context.test.js index f6d1c7d861..4e484b5361 100644 --- a/test/lambda/context.test.js +++ b/test/lambda/context.test.js @@ -6,6 +6,11 @@ 'use strict' +if (process.env.ELASTIC_APM_CONTEXT_MANAGER === 'patch') { + console.log('# SKIP Lambda instrumentation currently does not work with contextManager="patch"') + process.exit() +} + const test = require('tape') const lambdaLocal = require('lambda-local') diff --git a/test/lambda/github-issue-2709.test.js b/test/lambda/github-issue-2709.test.js index f83347abcd..1a3086fd5b 100644 --- a/test/lambda/github-issue-2709.test.js +++ b/test/lambda/github-issue-2709.test.js @@ -4,6 +4,13 @@ * compliance with the BSD 2-Clause License. */ +'use strict' + +if (process.env.ELASTIC_APM_CONTEXT_MANAGER === 'patch') { + console.log('# SKIP Lambda instrumentation currently does not work with contextManager="patch"') + process.exit() +} + const tape = require('tape') const path = require('path') @@ -35,7 +42,7 @@ tape.test('test _HANDLER=fixture/lambda.foo form', function (t) { // check that the handler fixture is wrapped const handler = require(path.join(__dirname, '/fixtures/lambda')).foo - t.equals(handler.name, 'wrappedLambda', 'handler function wrapped correctly') + t.equals(handler.name, 'wrappedLambdaHandler', 'handler function wrapped correctly') // did normal patching/wrapping take place t.equals(express.static.name, 'wrappedStatic', 'express module was instrumented correctly') diff --git a/test/lambda/metadata.test.js b/test/lambda/metadata.test.js index 78f6a6008d..354258319d 100644 --- a/test/lambda/metadata.test.js +++ b/test/lambda/metadata.test.js @@ -8,6 +8,11 @@ // Test that a lambda invocation sends the appropriate "metadata" to APM server. +if (process.env.ELASTIC_APM_CONTEXT_MANAGER === 'patch') { + console.log('# SKIP Lambda instrumentation currently does not work with contextManager="patch"') + process.exit() +} + const lambdaLocal = require('lambda-local') const tape = require('tape') diff --git a/test/lambda/metadata2.test.js b/test/lambda/metadata2.test.js index acf5880128..77596b356b 100644 --- a/test/lambda/metadata2.test.js +++ b/test/lambda/metadata2.test.js @@ -9,6 +9,11 @@ // Test that the "metadata" sent to APM server from a lambda invocation // respects the `serviceName` and `serviceVersion` config settings. +if (process.env.ELASTIC_APM_CONTEXT_MANAGER === 'patch') { + console.log('# SKIP Lambda instrumentation currently does not work with contextManager="patch"') + process.exit() +} + const lambdaLocal = require('lambda-local') const tape = require('tape') diff --git a/test/lambda/mock/agent.js b/test/lambda/mock/agent.js index c4b7fa6fbe..c7fc2d280b 100644 --- a/test/lambda/mock/agent.js +++ b/test/lambda/mock/agent.js @@ -6,6 +6,8 @@ 'use strict' +const Filters = require('object-filter-sequence') + const { CapturingTransport } = require('../../_capturing_transport') const logging = require('../../../lib/logging') const TransactionMock = require('./transaction') @@ -22,6 +24,7 @@ module.exports = class AgentMock { usePathAsTransactionName: false }, conf) this._transport = new CapturingTransport() + this._transactionFilters = new Filters() } startTransaction (name, type, opts) { diff --git a/test/lambda/mock/transaction.js b/test/lambda/mock/transaction.js index cdb901f997..3170b47c76 100644 --- a/test/lambda/mock/transaction.js +++ b/test/lambda/mock/transaction.js @@ -79,6 +79,27 @@ module.exports = class TransactionMock { this._links = this._links.concat(links) } + toJSON () { + // A simplified version of the real Transaction.prototype.toJSON. + var payload = { + name: this.name, + type: this.type, + context: { + tags: this._labels || {}, + custom: this._custom || {}, + service: this._service || {}, + cloud: this._cloud || {}, + message: this._message || {} + }, + outcome: this.outcome, + faas: this._faas + } + if (this._links.length > 0) { + payload.links = this._links + } + return payload + } + end () { this.ended = true } diff --git a/test/lambda/promises.test.js b/test/lambda/promises.test.js index bf6ed9523b..68263d0ff0 100644 --- a/test/lambda/promises.test.js +++ b/test/lambda/promises.test.js @@ -6,6 +6,11 @@ 'use strict' +if (process.env.ELASTIC_APM_CONTEXT_MANAGER === 'patch') { + console.log('# SKIP Lambda instrumentation currently does not work with contextManager="patch"') + process.exit() +} + const test = require('tape') const lambdaLocal = require('lambda-local') diff --git a/test/lambda/trace-context.test.js b/test/lambda/trace-context.test.js index ddade77239..d535407b15 100644 --- a/test/lambda/trace-context.test.js +++ b/test/lambda/trace-context.test.js @@ -8,6 +8,11 @@ // Test trace-context propagation in Lambda instrumentation. +if (process.env.ELASTIC_APM_CONTEXT_MANAGER === 'patch') { + console.log('# SKIP Lambda instrumentation currently does not work with contextManager="patch"') + process.exit() +} + const test = require('tape') const lambdaLocal = require('lambda-local') diff --git a/test/lambda/trans-setDefaultName.test.js b/test/lambda/trans-setDefaultName.test.js index 0d8ae130a8..e25723501d 100644 --- a/test/lambda/trans-setDefaultName.test.js +++ b/test/lambda/trans-setDefaultName.test.js @@ -9,6 +9,17 @@ // Test that instrumentation using `Transaction.setDefaultName(...)` still // works after the Lambda instrumentation has set the transaction name. +const semver = require('semver') +if (process.env.ELASTIC_APM_CONTEXT_MANAGER === 'patch') { + console.log('# SKIP Lambda instrumentation currently does not work with contextManager="patch"') + process.exit() +} else if (semver.satisfies(process.version, '>=10.0.0 <10.4.0')) { + // This isn't considered an issue because AWS Lambda doesn't support a node + // v10 runtime, and node v10 is EOL. + console.log(`# SKIP async context propagation currently does not work to a Lambda handler with node ${process.version}`) + process.exit() +} + const lambdaLocal = require('lambda-local') const tape = require('tape') diff --git a/test/lambda/transaction.test.js b/test/lambda/transaction.test.js index 3918b655f0..ca8b499d33 100644 --- a/test/lambda/transaction.test.js +++ b/test/lambda/transaction.test.js @@ -4,6 +4,11 @@ * compliance with the BSD 2-Clause License. */ +if (process.env.ELASTIC_APM_CONTEXT_MANAGER === 'patch') { + console.log('# SKIP Lambda instrumentation currently does not work with contextManager="patch"') + process.exit() +} + const tape = require('tape') const AgentMock = require('./mock/agent') diff --git a/test/lambda/transaction2.test.js b/test/lambda/transaction2.test.js index 187a72bf96..851f87db7c 100644 --- a/test/lambda/transaction2.test.js +++ b/test/lambda/transaction2.test.js @@ -12,16 +12,24 @@ // "AgentMock". The mock doesn't fully test the "transaction" intake event // object creation path.) +const semver = require('semver') +if (process.env.ELASTIC_APM_CONTEXT_MANAGER === 'patch') { + console.log('# SKIP Lambda instrumentation currently does not work with contextManager="patch"') + process.exit() +} else if (semver.satisfies(process.version, '>=10.0.0 <10.4.0')) { + // This isn't considered an issue because AWS Lambda doesn't support a node + // v10 runtime, and node v10 is EOL. + console.log(`# SKIP async context propagation currently does not work to a Lambda handler with node ${process.version}`) + process.exit() +} + const fs = require('fs') const path = require('path') const lambdaLocal = require('lambda-local') const tape = require('tape') -const apm = require('../../') -const { MockAPMServer } = require('../_mock_apm_server') - -// Setup env for both apm.start() and lambdaLocal.execute(). +// Setup env for `require('elastic-apm-http-client')` and lambdaLocal.execute(). process.env.AWS_LAMBDA_FUNCTION_NAME = 'fixture-function-name' // Set these values to have stable data from lambdaLocal.execute(). process.env.AWS_EXECUTION_ENV = 'AWS_Lambda_nodejs14.x' @@ -37,16 +45,57 @@ process.env.AWS_LAMBDA_LOG_STREAM_NAME = '2021/11/01/[1.0]lambda/e7b05091b39b4aa // warning Using both auth systems: aws_access_key/id and secret_access_token! process.env.AWS_PROFILE = 'fake' +const apm = require('../../') +const { MockAPMServer } = require('../_mock_apm_server') +const { findObjInArray } = require('../_utils') + +// ---- support functions + function loadFixture (file) { return JSON.parse(fs.readFileSync(path.join(__dirname, 'fixtures', file))) } +// There is an expected order and set of requests from the APM agent to the +// Elastic Lambda extension in a Lambda function. +// +// - There may be a `GET /` request. +// - There must be a `POST /register/transaction` request -- at least for the +// first invocation. If that fails, then the APM agent will stop sending this. +// - For a lambda invocation that completes (as opposed to a timeout, crash, etc.): +// - There must be one or more `POST /intake/v2/events` req with tracing data. +// - The last `POST /intake/v2/events` request must have the `?flushed=true` +// query param. +function assertExpectedServerRequests (t, requests, expectIntakeRequests = true) { + const rootReq = findObjInArray(requests, 'url', '/') + if (rootReq) { + t.equal(rootReq.method, 'GET', '"GET /" request') + } + + const regReq = findObjInArray(requests, 'url', '/register/transaction') + t.equal(regReq.method, 'POST', '"POST /register/transaction" request') + t.equal(regReq.headers['content-type'], 'application/vnd.elastic.apm.transaction+ndjson', '"POST /register/transaction" content-type') + t.ok(regReq.headers['x-elastic-aws-request-id'], '"POST /register/transaction" x-elastic-aws-request-id header') + t.ok(regReq.body.includes('{"metadata":'), '"POST /register/transaction" body includes metadata') + t.ok(regReq.body.includes('{"transaction":'), '"POST /register/transaction" body includes transaction') + + if (expectIntakeRequests) { + const intakeReqs = requests.filter(r => r.url.startsWith('/intake/v2/events')) + intakeReqs.forEach(intakeReq => { + t.equal(intakeReq.method, 'POST', '"POST /intake/v2/events" request') + }) + t.equal(intakeReqs[intakeReqs.length - 1].url, '/intake/v2/events?flushed=true', + 'last intake request uses "?flushed=true"') + } +} + +// ---- tests + tape.test('lambda transactions', function (suite) { let server let serverUrl suite.test('setup', function (t) { - server = new MockAPMServer() + server = new MockAPMServer({ mockLambdaExtension: true }) server.start(function (serverUrl_) { serverUrl = serverUrl_ t.comment('mock APM serverUrl: ' + serverUrl) @@ -65,7 +114,8 @@ tape.test('lambda transactions', function (suite) { { name: 'transaction.context.{request,response} for API Gateway payload format version 1.0', event: loadFixture('aws_api_rest_test_data.json'), - checkApmEvents: (t, events) => { + checkResults: (t, requests, events) => { + assertExpectedServerRequests(t, requests) const trans = events[1].transaction t.deepEqual(trans.context.request, { http_version: '1.1', @@ -110,7 +160,8 @@ tape.test('lambda transactions', function (suite) { { name: 'transaction.context.{request,response} for API Gateway payload format version 2.0', event: loadFixture('aws_api_http_test_data.json'), - checkApmEvents: (t, events) => { + checkResults: (t, requests, events) => { + assertExpectedServerRequests(t, requests) const trans = events[1].transaction t.deepEqual(trans.context.request, { http_version: '1.1', @@ -150,7 +201,8 @@ tape.test('lambda transactions', function (suite) { handler: (_event, _context, cb) => { cb(null, 'hi') }, - checkApmEvents: (t, events) => { + checkResults: (t, requests, events) => { + assertExpectedServerRequests(t, requests) const trans = events[1].transaction t.deepEqual(trans.context.response, { status_code: 200, @@ -164,7 +216,8 @@ tape.test('lambda transactions', function (suite) { handler: (_event, _context, cb) => { cb(new Error('boom')) }, - checkApmEvents: (t, events) => { + checkResults: (t, requests, events) => { + assertExpectedServerRequests(t, requests) const trans = events[1].transaction const error = events[2].error t.equal(trans.outcome, 'failure', 'transaction.outcome') @@ -176,7 +229,8 @@ tape.test('lambda transactions', function (suite) { { name: 'ALB (ELB) event', event: loadFixture('aws_elb_test_data.json'), - checkApmEvents: (t, events) => { + checkResults: (t, requests, events) => { + assertExpectedServerRequests(t, requests) const trans = events[1].transaction t.equal(trans.trace_id, '12345678901234567890123456789012', 'transaction.trace_id') t.equal(trans.parent_id, '1234567890123456', 'transaction.parent_id') @@ -210,7 +264,8 @@ tape.test('lambda transactions', function (suite) { hi: 'there' } }, - checkApmEvents: (t, events) => { + checkResults: (t, requests, events) => { + assertExpectedServerRequests(t, requests) const trans = events[1].transaction t.equal(trans.name, 'POST unknown route', 'transaction.name') t.equal(trans.result, 'HTTP 5xx', 'transaction.result') @@ -229,7 +284,7 @@ tape.test('lambda transactions', function (suite) { handler: (_event, _context, cb) => { cb(null, { statusCode: 200, body: 'hi' }) }, - checkApmEvents: (t, events) => { + checkResults: (t, requests, events) => { const trans = events[1].transaction t.equal(trans.name, 'POST /default/the-function-name', 'transaction.name') t.equal(trans.outcome, 'success', 'transaction.outcome') @@ -245,11 +300,51 @@ tape.test('lambda transactions', function (suite) { handler: (_event, _context, cb) => { cb(null, { statusCode: 200, body: 'hi' }) }, - checkApmEvents: (t, events) => { + checkResults: (t, requests, events) => { const trans = events[1].transaction t.equal(trans.faas.name, 'fixture-function-name', 'transaction.faas.name') t.equal(trans.outcome, 'success', 'transaction.outcome') } + }, + { + // Test that a `POST /register/transaction` request from the APM agent + // will result in this transaction getting reported -- assuming the + // Lambda extension does its job. + name: 'lambda fn timeout', + event: {}, + timeoutMs: 500, + handler: (_event, _context, cb) => { + setTimeout(() => { + cb(null, 'hi') + }, 1000) + }, + checkResults: (t, requests, events) => { + assertExpectedServerRequests(t, requests, /* expectIntakeRequests */ false) + t.equal(events.length, 0, 'no intake events were reported') + // Get the transaction from the `POST /register/transaction` request + // and assert some basic structure. + const regReq = findObjInArray(requests, 'url', '/register/transaction') + const trans = JSON.parse(regReq.body.split(/\n/g)[1]).transaction + t.equal(trans.faas.name, process.env.AWS_LAMBDA_FUNCTION_NAME, 'transaction.faas.name') + t.equal(trans.outcome, 'unknown', 'transaction.outcome') + } + }, + { + name: 'lambda fn sync throw', + event: {}, + handler: (_event, _context, cb) => { + throw new Error('errorThrowSync') + }, + checkResults: (t, requests, events) => { + assertExpectedServerRequests(t, requests) + const trans = events[1].transaction + t.equal(trans.result, 'failure', 'transaction.result') + t.equal(trans.outcome, 'failure', 'transaction.outcome') + const error = events[2].error + t.ok(error, 'error is reported') + t.equal(error.parent_id, trans.id, 'error is a child of the transaction') + t.equal(error.exception.message, 'errorThrowSync', 'error.exception.message') + } } ] @@ -275,10 +370,10 @@ tape.test('lambda transactions', function (suite) { [process.env.AWS_LAMBDA_FUNCTION_NAME]: wrappedHandler }, lambdaHandler: process.env.AWS_LAMBDA_FUNCTION_NAME, - timeoutMs: 3000, + timeoutMs: c.timeoutMs || 3000, verboseLevel: 0, callback: function (_err, _result) { - c.checkApmEvents(t, server.events) + c.checkResults(t, server.requests, server.events) t.end() } }) diff --git a/test/lambda/wrap-bundled-handler.test.js b/test/lambda/wrap-bundled-handler.test.js index 05d5308698..961a824ded 100644 --- a/test/lambda/wrap-bundled-handler.test.js +++ b/test/lambda/wrap-bundled-handler.test.js @@ -12,6 +12,11 @@ // The created module exports its properties only with a getter, so wrapping // of the handler cannot modify the module object directly. +if (process.env.ELASTIC_APM_CONTEXT_MANAGER === 'patch') { + console.log('# SKIP Lambda instrumentation currently does not work with contextManager="patch"') + process.exit() +} + const tape = require('tape') const path = require('path') @@ -43,7 +48,7 @@ tape.test('automatic wrapping of _HANDLER=esbuild-bundled-handler/hello.main', f const express = require('express') const handler = require(path.join(__dirname, 'fixtures/esbuild-bundled-handler/hello')).main - t.equals(handler.name, 'wrappedLambda', 'handler function wrapped correctly') + t.equals(handler.name, 'wrappedLambdaHandler', 'handler function wrapped correctly') // Did normal patching/wrapping take place? t.equals(express.static.name, 'wrappedStatic', 'express module was instrumented correctly') diff --git a/test/lambda/wrapper.test.js b/test/lambda/wrapper.test.js index cd6baf0d6f..88af89ea36 100644 --- a/test/lambda/wrapper.test.js +++ b/test/lambda/wrapper.test.js @@ -5,6 +5,12 @@ */ 'use strict' + +if (process.env.ELASTIC_APM_CONTEXT_MANAGER === 'patch') { + console.log('# SKIP Lambda instrumentation currently does not work with contextManager="patch"') + process.exit() +} + const tape = require('tape') const path = require('path') const Instrumentation = require('../../lib/instrumentation') @@ -144,7 +150,7 @@ tape.test('integration test', function (t) { // check that the handler fixture is wrapped const handler = require(path.join(__dirname, '/fixtures/lambda')).foo - t.equals(handler.name, 'wrappedLambda', 'handler function wrapped correctly') + t.equals(handler.name, 'wrappedLambdaHandler', 'handler function wrapped correctly') // did normal patching/wrapping take place t.equals(express.static.name, 'wrappedStatic', 'express module was instrumented correctly')