Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

Sign up for GitHub

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Jump to bottom

lambda instrumentation: handler timeout #2597

Closed
trentm opened this issue Mar 4, 2022 · 2 comments
Closed

lambda instrumentation: handler timeout #2597

trentm opened this issue Mar 4, 2022 · 2 comments
Labels
8.3-candidate agent-nodejs Make available for APM Agents project planning.

Comments

@trentm
Copy link
Member

trentm commented Mar 4, 2022

What should the APM instrumentation of a Lambda function do when the handler times out. E.g.:

exports.handler = function thisTimesOut (event, context, callback) {
  setInterval(() => {
    console.log('still here waiting...')
  }, 1000)
}

Currently, with a Lambda function configured with a 12s timeout, you get this response (pretty-printed):

{
  "errorMessage": "2022-03-04T23:45:34.985Z 19c955e4-4279-4334-9e00-d413693473d8 Task timed out after 12.02 seconds"
}

which I believe is the same as without the agent (which is a good thing).
However, no error or transaction is reported.

The function log (excluding the leading lines showing the agent and extension setup):

...
2022-03-04T23:42:10.705000+00:00 2022/03/04/[$LATEST]cbb01d06f90d457bbadd355fc4f0a54a 2022/03/04 23:42:10 Received event: {
2022-03-04T23:42:10.705000+00:00 2022/03/04/[$LATEST]cbb01d06f90d457bbadd355fc4f0a54a 	"eventType": "INVOKE",
2022-03-04T23:42:10.705000+00:00 2022/03/04/[$LATEST]cbb01d06f90d457bbadd355fc4f0a54a 	"deadlineMs": 1646437342588,
2022-03-04T23:42:10.705000+00:00 2022/03/04/[$LATEST]cbb01d06f90d457bbadd355fc4f0a54a 	"requestId": "1e71c15e-e02e-4a33-80af-834ec0100953",
2022-03-04T23:42:10.705000+00:00 2022/03/04/[$LATEST]cbb01d06f90d457bbadd355fc4f0a54a 	"invokedFunctionArn": "arn:aws:lambda:us-west-2:627286350134:function:trentm-play-fn1",
2022-03-04T23:42:10.705000+00:00 2022/03/04/[$LATEST]cbb01d06f90d457bbadd355fc4f0a54a 	"tracing": {
2022-03-04T23:42:10.705000+00:00 2022/03/04/[$LATEST]cbb01d06f90d457bbadd355fc4f0a54a 		"type": "X-Amzn-Trace-Id",
2022-03-04T23:42:10.705000+00:00 2022/03/04/[$LATEST]cbb01d06f90d457bbadd355fc4f0a54a 		"value": "Root=1-6222a3d1-2420dece08b5b9051c040e07;Parent=176c36a241a6d5a5;Sampled=0"
2022-03-04T23:42:10.705000+00:00 2022/03/04/[$LATEST]cbb01d06f90d457bbadd355fc4f0a54a 	}
2022-03-04T23:42:10.705000+00:00 2022/03/04/[$LATEST]cbb01d06f90d457bbadd355fc4f0a54a }
2022-03-04T23:42:10.705000+00:00 2022/03/04/[$LATEST]cbb01d06f90d457bbadd355fc4f0a54a 2022/03/04 23:42:10 Checking for agent data
2022-03-04T23:42:10.705000+00:00 2022/03/04/[$LATEST]cbb01d06f90d457bbadd355fc4f0a54a 2022/03/04 23:42:10 No agent data on buffer
2022-03-04T23:42:10.705000+00:00 2022/03/04/[$LATEST]cbb01d06f90d457bbadd355fc4f0a54a 2022/03/04 23:42:10 Received log event platform.logsSubscription
2022-03-04T23:42:10.765000+00:00 2022/03/04/[$LATEST]cbb01d06f90d457bbadd355fc4f0a54a 2022/03/04 23:42:10 Received log event platform.start
2022-03-04T23:42:10.765000+00:00 2022/03/04/[$LATEST]cbb01d06f90d457bbadd355fc4f0a54a 2022/03/04 23:42:10 Received log event platform.extension
2022-03-04T23:42:10.768000+00:00 2022/03/04/[$LATEST]cbb01d06f90d457bbadd355fc4f0a54a {"log.level":"trace","@timestamp":"2022-03-04T23:42:10.767Z","log":{"logger":"elastic-apm-node"},"awsRequestId":"1e71c15e-e02e-4a33-80af-834ec0100953","ecs":{"version":"1.6.0"},"message":"lambda: fn start"}
2022-03-04T23:42:10.768000+00:00 2022/03/04/[$LATEST]cbb01d06f90d457bbadd355fc4f0a54a {"log.level":"trace","@timestamp":"2022-03-04T23:42:10.767Z","log":{"logger":"elastic-apm-node"},"awsRequestId":"1e71c15e-e02e-4a33-80af-834ec0100953","ecs":{"version":"1.6.0"},"message":"lambda: setExtraMetadata"}
2022-03-04T23:42:10.805000+00:00 2022/03/04/[$LATEST]cbb01d06f90d457bbadd355fc4f0a54a {"log.level":"trace","@timestamp":"2022-03-04T23:42:10.805Z","log":{"logger":"elastic-apm-node"},"event.module":"apmclient","_encodedMetadata":"{\"metadata\":{\"service\":{\"name\":\"trentm-play-fn1\",\"environment\":\"development\",\"runtime\":{\"name\":\"AWS_Lambda_nodejs14.x\",\"version\":\"14.18.3\"},\"language\":{\"name\":\"javascript\"},\"agent\":{\"name\":\"nodejs\",\"version\":\"3.29.0\"},\"version\":\"$LATEST\",\"framework\":{\"name\":\"AWS Lambda\"},\"node\":{\"configured_name\":\"2022/03/04/[$LATEST]cbb01d06f90d457bbadd355fc4f0a54a\"}},\"process\":{\"pid\":18,\"ppid\":1,\"title\":\"/var/lang/bin/node\",\"argv\":[\"/var/lang/bin/node\",\"/var/runtime/index.js\"]},\"system\":{\"hostname\":\"169.254.104.181\",\"architecture\":\"x64\",\"platform\":\"linux\"},\"cloud\":{\"provider\":\"aws\",\"region\":\"us-west-2\",\"service\":{\"name\":\"lambda\"},\"account\":{\"id\":\"627286350134\"}}}}\n","ecs":{"version":"1.6.0"},"message":"_resetEncodedMetadata"}
2022-03-04T23:42:10.805000+00:00 2022/03/04/[$LATEST]cbb01d06f90d457bbadd355fc4f0a54a {"log.level":"trace","@timestamp":"2022-03-04T23:42:10.805Z","log":{"logger":"elastic-apm-node"},"event.module":"apmclient","ecs":{"version":"1.6.0"},"message":"uncorked (expectExtraMetadata)"}
2022-03-04T23:42:10.808000+00:00 2022/03/04/[$LATEST]cbb01d06f90d457bbadd355fc4f0a54a {"log.level":"debug","@timestamp":"2022-03-04T23:42:10.808Z","log":{"logger":"elastic-apm-node"},"ecs":{"version":"1.6.0"},"message":"start trace {\"trans\":\"3824e3b3d0624c0a\",\"trace\":\"fad1b25888e93dd009317a926fc8802d\",\"name\":\"unnamed\",\"type\":\"lambda\",\"subtype\":null,\"action\":null}"}
2022-03-04T23:42:10.808000+00:00 2022/03/04/[$LATEST]cbb01d06f90d457bbadd355fc4f0a54a {"log.level":"debug","@timestamp":"2022-03-04T23:42:10.808Z","log":{"logger":"elastic-apm-node"},"ctxmgr":"AsyncHooksRunContextManager( RC(Trans(3824e3, trentm-play-fn1)) )","ecs":{"version":"1.6.0"},"message":"supersedeWithTransRunContext(<Trans 3824e3b3d0624c0a>)"}
2022-03-04T23:42:10.845000+00:00 2022/03/04/[$LATEST]cbb01d06f90d457bbadd355fc4f0a54a {"log.level":"debug","@timestamp":"2022-03-04T23:42:10.844Z","log":{"logger":"elastic-apm-node"},"ecs":{"version":"1.6.0"},"message":"setting transaction name {\"trans\":\"3824e3b3d0624c0a\",\"trace\":\"fad1b25888e93dd009317a926fc8802d\",\"name\":\"trentm-play-fn1\"}"}
2022-03-04T23:42:11.568000+00:00 2022/03/04/[$LATEST]cbb01d06f90d457bbadd355fc4f0a54a {"log.level":"debug","@timestamp":"2022-03-04T23:42:11.568Z","log":{"logger":"elastic-apm-node"},"event.module":"apmclient","apmServerVersion":"7.15.0","ecs":{"version":"1.6.0"},"message":"fetched APM Server version"}
2022-03-04T23:42:11.846000+00:00 2022/03/04/[$LATEST]cbb01d06f90d457bbadd355fc4f0a54a 2022-03-04T23:42:11.846Z	1e71c15e-e02e-4a33-80af-834ec0100953	INFO	still here waiting...
2022-03-04T23:42:12.848000+00:00 2022/03/04/[$LATEST]cbb01d06f90d457bbadd355fc4f0a54a 2022-03-04T23:42:12.848Z	1e71c15e-e02e-4a33-80af-834ec0100953	INFO	still here waiting...
2022-03-04T23:42:13.849000+00:00 2022/03/04/[$LATEST]cbb01d06f90d457bbadd355fc4f0a54a 2022-03-04T23:42:13.849Z	1e71c15e-e02e-4a33-80af-834ec0100953	INFO	still here waiting...
2022-03-04T23:42:14.850000+00:00 2022/03/04/[$LATEST]cbb01d06f90d457bbadd355fc4f0a54a 2022-03-04T23:42:14.849Z	1e71c15e-e02e-4a33-80af-834ec0100953	INFO	still here waiting...
2022-03-04T23:42:15.851000+00:00 2022/03/04/[$LATEST]cbb01d06f90d457bbadd355fc4f0a54a 2022-03-04T23:42:15.851Z	1e71c15e-e02e-4a33-80af-834ec0100953	INFO	still here waiting...
2022-03-04T23:42:16.852000+00:00 2022/03/04/[$LATEST]cbb01d06f90d457bbadd355fc4f0a54a 2022-03-04T23:42:16.852Z	1e71c15e-e02e-4a33-80af-834ec0100953	INFO	still here waiting...
2022-03-04T23:42:17.853000+00:00 2022/03/04/[$LATEST]cbb01d06f90d457bbadd355fc4f0a54a 2022-03-04T23:42:17.852Z	1e71c15e-e02e-4a33-80af-834ec0100953	INFO	still here waiting...
2022-03-04T23:42:18.853000+00:00 2022/03/04/[$LATEST]cbb01d06f90d457bbadd355fc4f0a54a 2022-03-04T23:42:18.853Z	1e71c15e-e02e-4a33-80af-834ec0100953	INFO	still here waiting...
2022-03-04T23:42:19.854000+00:00 2022/03/04/[$LATEST]cbb01d06f90d457bbadd355fc4f0a54a 2022-03-04T23:42:19.853Z	1e71c15e-e02e-4a33-80af-834ec0100953	INFO	still here waiting...
2022-03-04T23:42:20.855000+00:00 2022/03/04/[$LATEST]cbb01d06f90d457bbadd355fc4f0a54a 2022-03-04T23:42:20.855Z	1e71c15e-e02e-4a33-80af-834ec0100953	INFO	still here waiting...
2022-03-04T23:42:21.856000+00:00 2022/03/04/[$LATEST]cbb01d06f90d457bbadd355fc4f0a54a 2022-03-04T23:42:21.856Z	1e71c15e-e02e-4a33-80af-834ec0100953	INFO	still here waiting...
2022-03-04T23:42:22.009000+00:00 2022/03/04/[$LATEST]cbb01d06f90d457bbadd355fc4f0a54a 2022/03/04 23:42:22 Time expired waiting for agent signal or runtimeDone event
2022-03-04T23:42:22.009000+00:00 2022/03/04/[$LATEST]cbb01d06f90d457bbadd355fc4f0a54a 2022/03/04 23:42:22 Checking for agent data
2022-03-04T23:42:22.009000+00:00 2022/03/04/[$LATEST]cbb01d06f90d457bbadd355fc4f0a54a 2022/03/04 23:42:22 No agent data on buffer
2022-03-04T23:42:22.009000+00:00 2022/03/04/[$LATEST]cbb01d06f90d457bbadd355fc4f0a54a 2022/03/04 23:42:22 Waiting for next event...
2022-03-04T23:42:22.009000+00:00 2022/03/04/[$LATEST]cbb01d06f90d457bbadd355fc4f0a54a 2022/03/04 23:42:22 funcDone signal received, not processing any more log events
2022-03-04T23:42:22.009000+00:00 2022/03/04/[$LATEST]cbb01d06f90d457bbadd355fc4f0a54a 2022/03/04 23:42:22 funcDone signal received, not processing any more agent data
2022-03-04T23:42:22.605000+00:00 2022/03/04/[$LATEST]cbb01d06f90d457bbadd355fc4f0a54a 2022/03/04 23:42:22 Received event: {
2022-03-04T23:42:22.605000+00:00 2022/03/04/[$LATEST]cbb01d06f90d457bbadd355fc4f0a54a 	"eventType": "SHUTDOWN",
2022-03-04T23:42:22.605000+00:00 2022/03/04/[$LATEST]cbb01d06f90d457bbadd355fc4f0a54a 	"deadlineMs": 1646437344600,
2022-03-04T23:42:22.605000+00:00 2022/03/04/[$LATEST]cbb01d06f90d457bbadd355fc4f0a54a 	"requestId": "",
2022-03-04T23:42:22.605000+00:00 2022/03/04/[$LATEST]cbb01d06f90d457bbadd355fc4f0a54a 	"invokedFunctionArn": "",
2022-03-04T23:42:22.605000+00:00 2022/03/04/[$LATEST]cbb01d06f90d457bbadd355fc4f0a54a 	"tracing": {
2022-03-04T23:42:22.605000+00:00 2022/03/04/[$LATEST]cbb01d06f90d457bbadd355fc4f0a54a 		"type": "",
2022-03-04T23:42:22.605000+00:00 2022/03/04/[$LATEST]cbb01d06f90d457bbadd355fc4f0a54a 		"value": ""
2022-03-04T23:42:22.605000+00:00 2022/03/04/[$LATEST]cbb01d06f90d457bbadd355fc4f0a54a 	}
2022-03-04T23:42:22.605000+00:00 2022/03/04/[$LATEST]cbb01d06f90d457bbadd355fc4f0a54a }
2022-03-04T23:42:22.605000+00:00 2022/03/04/[$LATEST]cbb01d06f90d457bbadd355fc4f0a54a 2022/03/04 23:42:22 Checking for agent data
2022-03-04T23:42:22.605000+00:00 2022/03/04/[$LATEST]cbb01d06f90d457bbadd355fc4f0a54a 2022/03/04 23:42:22 No agent data on buffer
2022-03-04T23:42:22.605000+00:00 2022/03/04/[$LATEST]cbb01d06f90d457bbadd355fc4f0a54a 2022/03/04 23:42:22 Received SHUTDOWN event
2022-03-04T23:42:22.605000+00:00 2022/03/04/[$LATEST]cbb01d06f90d457bbadd355fc4f0a54a 2022/03/04 23:42:22 Exiting
2022-03-04T23:42:22.607000+00:00 2022/03/04/[$LATEST]cbb01d06f90d457bbadd355fc4f0a54a END RequestId: 1e71c15e-e02e-4a33-80af-834ec0100953
2022-03-04T23:42:22.607000+00:00 2022/03/04/[$LATEST]cbb01d06f90d457bbadd355fc4f0a54a REPORT RequestId: 1e71c15e-e02e-4a33-80af-834ec0100953	Duration: 12017.97 ms	Billed Duration: 12000 msMemory Size: 128 MB	Max Memory Used: 96 MB	Init Duration: 732.87 ms
2022-03-04T23:42:22.607000+00:00 2022/03/04/[$LATEST]cbb01d06f90d457bbadd355fc4f0a54a 2022-03-04T23:42:22.606Z 1e71c15e-e02e-4a33-80af-834ec0100953 Task timed out after 12.02 seconds

I'm not sure what we would like the APM agent, if anything, to do. How the extension should handle this was discussed in elastic/apm-aws-lambda#3 Currently it waits until "timeout - 100ms" and uses that 100ms to flush any agent data -- assuming that is enough time.
@github-actions github-actions bot added the agent-nodejs Make available for APM Agents project planning. label Mar 4, 2022
@trentm trentm mentioned this issue Mar 4, 2022
Closed
@AlexanderWert
Copy link
Member

I think we should handle this in the extension. So I guess there is nothing expected from the agent.
Related: elastic/apm-aws-lambda#118

@trentm
Copy link
Member Author

trentm commented Mar 15, 2022

So I guess there is nothing expected from the agent.

Sounds good to me.

@trentm trentm closed this as completed Mar 15, 2022
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Assignees
No one assigned
Labels
8.3-candidate agent-nodejs Make available for APM Agents project planning.
Projects
None yet
Milestone
No milestone
Development

No branches or pull requests
2 participants
@trentm @AlexanderWert