"panic: send on closed channel" from the extension

[trentm]

This is the tail end of a AWS Lambda log for a small Node.js function execution. It shows a panic in the extension:

...
2022-02-23T23:00:11.485000+00:00 2022/02/23/[$LATEST]743a0f5ca5744087a061a92d7cb56e5e {"log.level":"trace","@timestamp":"2022-02-23T23:00:11.485Z","log":{"logger":"elastic-apm-node"},"event.module":"apmclient","reqId":"e3f64a016331cdefab5ad1fe46b854d2","timeline":[[219.337168,"completePart gzipStream",null],[219.811828,"completePart intakeReq",null],[357.343887,"completePart intakeRes",null]],"bytesWritten":800,"backoffDelayMs":0,"ecs":{"version":"1.6.0"},"message":"conclude intake request: success"}
2022-02-23T23:00:11.507000+00:00 2022/02/23/[$LATEST]743a0f5ca5744087a061a92d7cb56e5e 2022-02-23T23:00:11.485Z	e3918d8f-7391-4bea-a6e2-9fdefc4c9037	INFO	XXX onFlushed in _writeFlush called
2022-02-23T23:00:11.524000+00:00 2022/02/23/[$LATEST]743a0f5ca5744087a061a92d7cb56e5e 2022-02-23T23:00:11.524Z	e3918d8f-7391-4bea-a6e2-9fdefc4c9037	INFO	XXX _signalLambdaEnd start
2022-02-23T23:00:11.526000+00:00 2022/02/23/[$LATEST]743a0f5ca5744087a061a92d7cb56e5e {"log.level":"trace","@timestamp":"2022-02-23T23:00:11.525Z","log":{"logger":"elastic-apm-node"},"awsRequestId":"e3918d8f-7391-4bea-a6e2-9fdefc4c9037","ecs":{"version":"1.6.0"},"message":"lambda: flushed"}
2022-02-23T23:00:11.565000+00:00 2022/02/23/[$LATEST]743a0f5ca5744087a061a92d7cb56e5e 2022/02/23 23:00:11 Received agent done signal
2022-02-23T23:00:11.566000+00:00 2022/02/23/[$LATEST]743a0f5ca5744087a061a92d7cb56e5e {"log.level":"trace","@timestamp":"2022-02-23T23:00:11.566Z","log":{"logger":"elastic-apm-node"},"event.module":"apmclient","durationMs":41.77897899993695,"ecs":{"version":"1.6.0"},"message":"signaled lambda invocation done"}
2022-02-23T23:00:11.585000+00:00 2022/02/23/[$LATEST]743a0f5ca5744087a061a92d7cb56e5e 2022/02/23 23:00:11 Received log event platform.runtimeDone
2022-02-23T23:00:11.585000+00:00 2022/02/23/[$LATEST]743a0f5ca5744087a061a92d7cb56e5e 2022/02/23 23:00:11 Received runtimeDone event for this function invocation
2022-02-23T23:00:11.764000+00:00 2022/02/23/[$LATEST]743a0f5ca5744087a061a92d7cb56e5e 2022/02/23 23:00:11 APM server response body:
2022-02-23T23:00:11.764000+00:00 2022/02/23/[$LATEST]743a0f5ca5744087a061a92d7cb56e5e 2022/02/23 23:00:11 APM server response status code: 202
2022-02-23T23:00:11.764000+00:00 2022/02/23/[$LATEST]743a0f5ca5744087a061a92d7cb56e5e 2022/02/23 23:00:11 Checking for agent data
2022-02-23T23:00:11.764000+00:00 2022/02/23/[$LATEST]743a0f5ca5744087a061a92d7cb56e5e 2022/02/23 23:00:11 No agent data on buffer
2022-02-23T23:00:11.764000+00:00 2022/02/23/[$LATEST]743a0f5ca5744087a061a92d7cb56e5e 2022/02/23 23:00:11 Waiting for next event...
2022-02-23T23:00:11.765000+00:00 2022/02/23/[$LATEST]743a0f5ca5744087a061a92d7cb56e5e 2022/02/23 23:00:11 funcDone signal received, not processing any more agent data
2022-02-23T23:00:11.766000+00:00 2022/02/23/[$LATEST]743a0f5ca5744087a061a92d7cb56e5e {"log.level":"debug","@timestamp":"2022-02-23T23:00:11.766Z","log":{"logger":"elastic-apm-node"},"event.module":"apmclient","apmServerVersion":"7.15.0","ecs":{"version":"1.6.0"},"message":"fetched APM Server version"}
2022-02-23T23:00:11.768000+00:00 2022/02/23/[$LATEST]743a0f5ca5744087a061a92d7cb56e5e panic: send on closed channel
2022-02-23T23:00:11.768000+00:00 2022/02/23/[$LATEST]743a0f5ca5744087a061a92d7cb56e5e
2022-02-23T23:00:11.768000+00:00 2022/02/23/[$LATEST]743a0f5ca5744087a061a92d7cb56e5e goroutine 36 [running]:
2022-02-23T23:00:11.768000+00:00 2022/02/23/[$LATEST]743a0f5ca5744087a061a92d7cb56e5e main.main.func3()
2022-02-23T23:00:11.768000+00:00 2022/02/23/[$LATEST]743a0f5ca5744087a061a92d7cb56e5e 	/var/lib/jenkins/workspace/ibrary_apm-aws-lambda-mbp_PR-120/src/github.com/elastic/apm-aws-lambda/apm-lambda-extension/main.go:170 +0x209
2022-02-23T23:00:11.768000+00:00 2022/02/23/[$LATEST]743a0f5ca5744087a061a92d7cb56e5e created by main.main
2022-02-23T23:00:11.768000+00:00 2022/02/23/[$LATEST]743a0f5ca5744087a061a92d7cb56e5e 	/var/lib/jenkins/workspace/ibrary_apm-aws-lambda-mbp_PR-120/src/github.com/elastic/apm-aws-lambda/apm-lambda-extension/main.go:157 +0x6af
2022-02-23T23:00:11.827000+00:00 2022/02/23/[$LATEST]743a0f5ca5744087a061a92d7cb56e5e END RequestId: e3918d8f-7391-4bea-a6e2-9fdefc4c9037
2022-02-23T23:00:11.827000+00:00 2022/02/23/[$LATEST]743a0f5ca5744087a061a92d7cb56e5e REPORT RequestId: e3918d8f-7391-4bea-a6e2-9fdefc4c9037	Duration: 1141.18 ms	Billed Duration: 1142 ms	Memory Size: 128 MB	Max Memory Used: 98 MB	Init Duration: 654.65 ms
2022-02-23T23:00:11.827000+00:00 2022/02/23/[$LATEST]743a0f5ca5744087a061a92d7cb56e5e RequestId: e3918d8f-7391-4bea-a6e2-9fdefc4c9037 Error: exit status 2
Extension.Crash

This is running extension version "arn:aws:lambda:us-west-2:267093732750:layer:elastic-apm-extension-ver0-0-3-x86_64:3" and an in-development APM Node.js agent that has support for the ?flushed=true request to signal the function is complete.

This panic does not happen everytime. I think it is a timing issue.

The main.go:170 stacktrace reference is to https://github.com/elastic/apm-aws-lambda/blob/v0.0.3/apm-lambda-extension/main.go#L170

runtimeDoneSignal <- struct{}{}

The earlier Waiting for next event... log line (from the top of the for-loop) shows that all three channels had been closed: https://github.com/elastic/apm-aws-lambda/blob/v0.0.3/apm-lambda-extension/main.go#L203-L205

			close(funcDone)
			close(runtimeDoneSignal)
			close(extension.AgentDoneSignal)

The funcDone signal received, not processing any more agent data log line shows that the case <-funcDone: path was taken for the agent data select. However there is no funcDone signal received, not processing any more log events log line for the Logs API events select.

My naivete with Go channels starts here.

[estolfo]

Thanks for reporting this, @trentm
I believe Andrew noticed this in his code review (see comment here)

In main.go, there can be a panic if the "runtimeDoneSignal" channel is closed (e.g. due to "AgentDoneSignal" being signalled), and then a RuntimeDone log event is processed:

I've fixed it in this PR. The solution is to not explicitly close the runtimeDoneSignal channel and instead just let it get garbage collected.

I'm going to close this issue as it's already covered in the linked issue and PR. Thanks again!

[trentm]

Okay, thanks. I have also seen a "panic: send on closed channel" for the AgentDoneSignal channel as well:

...
2022-02-24T17:19:55.631000+00:00 2022/02/24/[$LATEST]9ce0c1b07e524f52b4d96a7cc65f2518 {"log.level":"trace","@timestamp":"2022-02-24T17:19:55.630Z","log":{"logger":"elastic-apm-node"},"event.module":"apmclient","reqId":"7fdea435666ded83ba8fea2c963e1e2f","timeline":[[139.17091,"completePart gzipStream",null],[177.350885,"completePart intakeReq",null],[219.354473,"completePart intakeRes",null]],"bytesWritten":804,"backoffDelayMs":0,"ecs":{"version":"1.6.0"},"message":"conclude intake request: success"}
2022-02-24T17:19:55.631000+00:00 2022/02/24/[$LATEST]9ce0c1b07e524f52b4d96a7cc65f2518 2022-02-24T17:19:55.631Z	772e7df6-488f-4d4d-aa0b-d84869433d72	INFO	XXX onFlushed in _writeFlush called
2022-02-24T17:19:55.631000+00:00 2022/02/24/[$LATEST]9ce0c1b07e524f52b4d96a7cc65f2518 2022-02-24T17:19:55.631Z	772e7df6-488f-4d4d-aa0b-d84869433d72	INFO	XXX _signalLambdaEnd start
2022-02-24T17:19:55.709000+00:00 2022/02/24/[$LATEST]9ce0c1b07e524f52b4d96a7cc65f2518 2022/02/24 17:19:55 Received log event platform.runtimeDone
2022-02-24T17:19:55.709000+00:00 2022/02/24/[$LATEST]9ce0c1b07e524f52b4d96a7cc65f2518 2022/02/24 17:19:55 Received runtimeDone event for this function invocation
2022-02-24T17:19:55.709000+00:00 2022/02/24/[$LATEST]9ce0c1b07e524f52b4d96a7cc65f2518 2022/02/24 17:19:55 Received runtimeDone signal
2022-02-24T17:19:55.749000+00:00 2022/02/24/[$LATEST]9ce0c1b07e524f52b4d96a7cc65f2518 2022/02/24 17:19:55 APM server response body:
2022-02-24T17:19:55.749000+00:00 2022/02/24/[$LATEST]9ce0c1b07e524f52b4d96a7cc65f2518 2022/02/24 17:19:55 APM server response status code: 202
2022-02-24T17:19:55.749000+00:00 2022/02/24/[$LATEST]9ce0c1b07e524f52b4d96a7cc65f2518 2022/02/24 17:19:55 Checking for agent data
2022-02-24T17:19:55.749000+00:00 2022/02/24/[$LATEST]9ce0c1b07e524f52b4d96a7cc65f2518 2022/02/24 17:19:55 No agent data on buffer
2022-02-24T17:19:55.749000+00:00 2022/02/24/[$LATEST]9ce0c1b07e524f52b4d96a7cc65f2518 2022/02/24 17:19:55 Waiting for next event...
2022-02-24T17:19:55.749000+00:00 2022/02/24/[$LATEST]9ce0c1b07e524f52b4d96a7cc65f2518 2022/02/24 17:19:55 funcDone signal received, not processing any more agent data
2022-02-24T17:19:55.749000+00:00 2022/02/24/[$LATEST]9ce0c1b07e524f52b4d96a7cc65f2518 2022/02/24 17:19:55 http: panic serving 127.0.0.1:44560: send on closed channel
2022-02-24T17:19:55.749000+00:00 2022/02/24/[$LATEST]9ce0c1b07e524f52b4d96a7cc65f2518 goroutine 50 [running]:
2022-02-24T17:19:55.749000+00:00 2022/02/24/[$LATEST]9ce0c1b07e524f52b4d96a7cc65f2518 net/http.(*conn).serve.func1()
2022-02-24T17:19:55.749000+00:00 2022/02/24/[$LATEST]9ce0c1b07e524f52b4d96a7cc65f2518 	/var/lib/jenkins/workspace/ibrary_apm-aws-lambda-mbp_PR-120/.gvm/versions/go1.17.6.linux.amd64/src/net/http/server.go:1802 +0xb9
2022-02-24T17:19:55.749000+00:00 2022/02/24/[$LATEST]9ce0c1b07e524f52b4d96a7cc65f2518 panic({0x67b2a0, 0x71cd00})
2022-02-24T17:19:55.749000+00:00 2022/02/24/[$LATEST]9ce0c1b07e524f52b4d96a7cc65f2518 	/var/lib/jenkins/workspace/ibrary_apm-aws-lambda-mbp_PR-120/.gvm/versions/go1.17.6.linux.amd64/src/runtime/panic.go:1047 +0x266
2022-02-24T17:19:55.749000+00:00 2022/02/24/[$LATEST]9ce0c1b07e524f52b4d96a7cc65f2518 elastic/apm-lambda-extension/extension.handleIntakeV2Events.func1({0x724450, 0xc0001a6000}, 0xc000186400)
2022-02-24T17:19:55.749000+00:00 2022/02/24/[$LATEST]9ce0c1b07e524f52b4d96a7cc65f2518 	/var/lib/jenkins/workspace/ibrary_apm-aws-lambda-mbp_PR-120/src/github.com/elastic/apm-aws-lambda/apm-lambda-extension/extension/route_handlers.go:106 +0x415
2022-02-24T17:19:55.749000+00:00 2022/02/24/[$LATEST]9ce0c1b07e524f52b4d96a7cc65f2518 net/http.HandlerFunc.ServeHTTP(0x0, {0x724450, 0xc0001a6000}, 0x0)
2022-02-24T17:19:55.749000+00:00 2022/02/24/[$LATEST]9ce0c1b07e524f52b4d96a7cc65f2518 	/var/lib/jenkins/workspace/ibrary_apm-aws-lambda-mbp_PR-120/.gvm/versions/go1.17.6.linux.amd64/src/net/http/server.go:2047 +0x2f
2022-02-24T17:19:55.749000+00:00 2022/02/24/[$LATEST]9ce0c1b07e524f52b4d96a7cc65f2518 net/http.(*ServeMux).ServeHTTP(0xc00001c197, {0x724450, 0xc0001a6000}, 0xc000186400)
2022-02-24T17:19:55.749000+00:00 2022/02/24/[$LATEST]9ce0c1b07e524f52b4d96a7cc65f2518 	/var/lib/jenkins/workspace/ibrary_apm-aws-lambda-mbp_PR-120/.gvm/versions/go1.17.6.linux.amd64/src/net/http/server.go:2425 +0x149
2022-02-24T17:19:55.749000+00:00 2022/02/24/[$LATEST]9ce0c1b07e524f52b4d96a7cc65f2518 net/http.serverHandler.ServeHTTP({0xc0001740c0}, {0x724450, 0xc0001a6000}, 0xc000186400)
2022-02-24T17:19:55.749000+00:00 2022/02/24/[$LATEST]9ce0c1b07e524f52b4d96a7cc65f2518 	/var/lib/jenkins/workspace/ibrary_apm-aws-lambda-mbp_PR-120/.gvm/versions/go1.17.6.linux.amd64/src/net/http/server.go:2879 +0x43b
2022-02-24T17:19:55.749000+00:00 2022/02/24/[$LATEST]9ce0c1b07e524f52b4d96a7cc65f2518 net/http.(*conn).serve(0xc000250000, {0x725400, 0xc0000972c0})
2022-02-24T17:19:55.749000+00:00 2022/02/24/[$LATEST]9ce0c1b07e524f52b4d96a7cc65f2518 	/var/lib/jenkins/workspace/ibrary_apm-aws-lambda-mbp_PR-120/.gvm/versions/go1.17.6.linux.amd64/src/net/http/server.go:1930 +0xb08
2022-02-24T17:19:55.749000+00:00 2022/02/24/[$LATEST]9ce0c1b07e524f52b4d96a7cc65f2518 created by net/http.(*Server).Serve
2022-02-24T17:19:55.749000+00:00 2022/02/24/[$LATEST]9ce0c1b07e524f52b4d96a7cc65f2518 	/var/lib/jenkins/workspace/ibrary_apm-aws-lambda-mbp_PR-120/.gvm/versions/go1.17.6.linux.amd64/src/net/http/server.go:3034 +0x4e8
2022-02-24T17:19:55.768000+00:00 2022/02/24/[$LATEST]9ce0c1b07e524f52b4d96a7cc65f2518 END RequestId: 772e7df6-488f-4d4d-aa0b-d84869433d72
2022-02-24T17:19:55.768000+00:00 2022/02/24/[$LATEST]9ce0c1b07e524f52b4d96a7cc65f2518 REPORT RequestId: 772e7df6-488f-4d4d-aa0b-d84869433d72	Duration: 1080.02 ms	Billed Duration: 1081 ms	Memory Size: 128 MB	Max Memory Used: 51 MB

That stack trace elastic/apm-lambda-extension/extension.handleIntakeV2Events.func1 ... route_handlers.go:106 is:

		if len(r.URL.Query()["flushed"]) > 0 && r.URL.Query()["flushed"][0] == "true" {
			AgentDoneSignal <- struct{}{}
		}

IIUC, it looks like the PR will avoid this as well by not closing the channel:
https://github.com/elastic/apm-aws-lambda/pull/132/files#diff-266b2e81a44ec5888932f7d39596edd7855613da2a972f75b75eec6f266ad363L205

[estolfo]

IIUC, it looks like the PR will avoid this as well by not closing the channel:

yes :)