panic: sync: WaitGroup is reused before previous Wait has returned

[estolfo]

Error from the extension:

panic: sync: WaitGroup is reused before previous Wait has returned
goroutine 1 [running]:
sync.(*WaitGroup).Wait(0xc0001a3f10)
/usr/local/go/src/sync/waitgroup.go:132 +0xa5
main.main()
main.go:197 +0x87e

We'll have to revisit our use of a waitgroup to allow the send to the apm server to complete before the extension is frozen. Added in #106

[jlvoiseux]

Current reproduction results

Repro 1 : main branch, Ruby Runtime, function EmilyTestRepro

With a lambda function similar to the one used by Emily, the error is successfully reproduced. I added additional to the extension to monitor the behavior of backgroundDataSendWg, which is the WaitGroup triggering the panic. The most relevant excerpt is below :

START RequestId: 757912f1-8f13-4a2e-bb3a-a28619dd6b28 Version: $LATEST
2022/02/24 13:26:40 546ab00f-33b1-4915-ad6b-bb8d45ca5f37
2022/02/24 13:26:40 Register response: {
	"functionName": "EmilyTestRepro",
	"functionVersion": "$LATEST",
	"handler": "lambda_function.lambda_handler"
}
2022/02/24 13:26:40 Could not read ELASTIC_APM_DATA_RECEIVER_TIMEOUT_SECONDS, defaulting to 15: strconv.Atoi: parsing "": invalid syntax
2022/02/24 13:26:40 Extension listening for apm data on :8200
LOGS	Name: extension-dev-linux-amd64	State: Subscribed	Types: [platform]
2022/02/24 13:26:40 Waiting for next event...
2022/02/24 13:26:40 Server listening for logs data from AWS Logs API on sandbox:1234
I, [2022-02-24T13:26:41.218545 #17]  INFO  -- : [4.4.0] Starting agent, reporting to http://localhost:8200EXTENSION	Name: extension-dev-linux-amd64	State: Ready	Events: [INVOKE,SHUTDOWN]
2022/02/24 13:26:41 Received event: {
	"eventType": "INVOKE",
	"deadlineMs": 1645709221255,
	"requestId": "757912f1-8f13-4a2e-bb3a-a28619dd6b28",
	"invokedFunctionArn": "arn:aws:lambda:eu-central-1:627286350134:function:EmilyTestRepro",
	"tracing": {
		"type": "X-Amzn-Trace-Id",
		"value": "Root=1-62178790-41bd206a7002d2993498774a;Parent=61bd78a6009931ae;Sampled=0"
	}
}
2022/02/24 13:26:41 Checking for agent data
2022/02/24 13:26:41 No agent data on buffer
2022/02/24 13:26:41 Received log event platform.logsSubscription
first transaction
2022/02/24 13:26:41 Received log event platform.start
2022/02/24 13:26:41 Received log event platform.extension
second transaction
third transaction
2022/02/24 13:26:45 Adding agent data to buffer to be sent to apm server
2022/02/24 13:26:45 ADDING TO WAITGROUP
2022/02/24 13:26:45 Adding agent data to buffer to be sent to apm server
2022/02/24 13:26:45 Received log event platform.runtimeDone
2022/02/24 13:26:45 Received runtimeDone event for this function invocation
2022/02/24 13:26:45 Received runtimeDone signal
2022/02/24 13:26:45 WAITGROUP WAITING
2022/02/24 13:26:45 APM server response body: 
2022/02/24 13:26:45 APM server response status code: 202
2022/02/24 13:26:45 WAITGROUP DONE
2022/02/24 13:26:45 ADDING TO WAITGROUP
panic: sync: WaitGroup is reused before previous Wait has returned

goroutine 1 [running]:
sync.(*WaitGroup).Wait(0xc0001a7f10)
	/usr/local/go/src/sync/waitgroup.go:132 +0xa5
main.main()
	/Users/jlvoiseux/Documents/github/apm/apm-aws-lambda/apm-lambda-extension/main.go:200 +0x8da
END RequestId: 757912f1-8f13-4a2e-bb3a-a28619dd6b28
REPORT RequestId: 757912f1-8f13-4a2e-bb3a-a28619dd6b28	Duration: 4558.98 ms	Billed Duration: 4559 ms	Memory Size: 128 MB	Max Memory Used: 80 MB	Init Duration: 715.76 ms	
RequestId: 757912f1-8f13-4a2e-bb3a-a28619dd6b28 Error: exit status 2
Extension.Crash

Another call to backgroundDataSendWg.Add(1) seems to be done before the Waitgroup ends its wait, which is illegal.

Repro 2 : main branch, Python Runtime, function lambda-sample-dev-jlvoiseux

Here, I tried to manually instrument a Python lambda handler to get as close as possible to translating the original Ruby function. Everything seems to work fine, and I cannot reproduce the issue - the wait group behaves as expected.

START RequestId: 27fe85f4-7f49-4e82-9c77-ae9d4479d00b Version: $LATEST
2022/02/24 14:19:14 Received event: {
	"eventType": "INVOKE",
	"deadlineMs": 1645712374347,
	"requestId": "27fe85f4-7f49-4e82-9c77-ae9d4479d00b",
	"invokedFunctionArn": "arn:aws:lambda:eu-central-1:627286350134:function:lambda-sample-dev-jlvoiseux",
	"tracing": {
		"type": "X-Amzn-Trace-Id",
		"value": "Root=1-621793e2-75b7dcad54c5cdb6504dcbc7;Parent=71703f007d5f1ea3;Sampled=0"
	}
}
2022/02/24 14:19:14 Checking for agent data
2022/02/24 14:19:14 No agent data on buffer
2022/02/24 14:19:14 Received log event platform.end
2022/02/24 14:19:14 Received log event platform.report
2022/02/24 14:19:14 Received log event platform.start
first transaction
second transaction
third transaction
2022/02/24 14:19:18 Adding agent data to buffer to be sent to apm server
2022/02/24 14:19:18 ADDING TO WAITGROUP
2022/02/24 14:19:18 Received log event platform.runtimeDone
2022/02/24 14:19:18 Received runtimeDone event for this function invocation
2022/02/24 14:19:18 Received runtimeDone signal
2022/02/24 14:19:18 WAITGROUP WAITING
2022/02/24 14:19:18 APM server response body: 
2022/02/24 14:19:18 APM server response status code: 202
2022/02/24 14:19:18 WAITGROUP DONE
2022/02/24 14:19:18 WAITGROUP RELEASED MAIN THREAD
2022/02/24 14:19:18 Checking for agent data
2022/02/24 14:19:18 No agent data on buffer
2022/02/24 14:19:18 Waiting for next event...
2022/02/24 14:19:18 funcDone signal received, not processing any more agent data
END RequestId: 27fe85f4-7f49-4e82-9c77-ae9d4479d00b
REPORT RequestId: 27fe85f4-7f49-4e82-9c77-ae9d4479d00b	Duration: 4175.15 ms	Billed Duration: 4176 ms	Memory Size: 128 MB	Max Memory Used: 67 MB	

@estolfo , when comparing your Ruby handler with my Python handler, do you observe any major difference ? If not, the issue might possibly be due to the way the Ruby agent sends its data ?

[jlvoiseux]

As an addendum, the modified main with the prints is available on the branch fix-waitgroups

[jlvoiseux]

A attempt at solving this issue was pushed on fix-waitgroups : (164a82a).

While this solves the panic described above, this introduces a new issue, which is a lost race against the closure of the funcDone channel. In other words, the channel funcDone is closed before the extension gets to process APM data, resulting in the following patterns :

1st invocation (cold start) - normal behavior : APM data sent

START RequestId: a4a1105e-0586-40c4-a217-dc60107baad0 Version: $LATEST
2022/02/28 11:13:45 c5e1588f-5cfc-4b74-b1b8-87b83131e41f
2022/02/28 11:13:45 Register response: {
	"functionName": "EmilyTestRepro",
	"functionVersion": "$LATEST",
	"handler": "lambda_function.lambda_handler"
}
2022/02/28 11:13:45 Could not read ELASTIC_APM_DATA_RECEIVER_TIMEOUT_SECONDS, defaulting to 15: strconv.Atoi: parsing "": invalid syntax
2022/02/28 11:13:45 Extension listening for apm data on :8200
LOGS	Name: extension-dev-linux-amd64	State: Subscribed	Types: [platform]
2022/02/28 11:13:45 Waiting for next event...
2022/02/28 11:13:45 Server listening for logs data from AWS Logs API on sandbox:1234
I, [2022-02-28T11:13:46.269972 #17]  INFO  -- : [4.4.0] Starting agent, reporting to http://localhost:8200EXTENSION	Name: extension-dev-linux-amd64	State: Ready	Events: [INVOKE,SHUTDOWN]
2022/02/28 11:13:46 Received event: {
	"eventType": "INVOKE",
	"deadlineMs": 1646046846303,
	"requestId": "a4a1105e-0586-40c4-a217-dc60107baad0",
	"invokedFunctionArn": "arn:aws:lambda:eu-central-1:627286350134:function:EmilyTestRepro",
	"tracing": {
		"type": "X-Amzn-Trace-Id",
		"value": "Root=1-621cae68-64511bb15e2fd76d0dc633a4;Parent=3b1afcf07a05927c;Sampled=0"
	}
}
2022/02/28 11:13:46 Checking for agent data
2022/02/28 11:13:46 No agent data on buffer
2022/02/28 11:13:46 Received log event platform.logsSubscription
2022/02/28 11:13:46 Received log event platform.start
2022/02/28 11:13:46 Received log event platform.extension
first transaction
2022/02/28 11:13:46 Adding agent data to buffer to be sent to apm server
2022/02/28 11:13:46 Received log event platform.runtimeDone
2022/02/28 11:13:46 Received runtimeDone event for this function invocation
2022/02/28 11:13:46 Received runtimeDone signal
2022/02/28 11:13:46 Checking for agent data
2022/02/28 11:13:46 No agent data on buffer
2022/02/28 11:13:46 {"metadata":{"service":{"name":"LambdaRepro","environment":null,"version":null,"agent":{"name":"ruby","version":"4.4.0"},"framework":{"name":null,"version":null},"language":{"name":"ruby","version":"2.7.5"},"runtime":{"name":"ruby","version":"2.7.5"}},"process":{"pid":17,"title":"/var/runtime/lib/runtime.rb","argv":[]},"system":{"configured_hostname":null,"architecture":"x86_64","platform":"linux","kubernetes":{"namespace":null,"node":{"name":null},"pod":{"name":null,"uid":null}},"container":null,"detected_hostname":"169.254.94.233"},"labels":null}}
{"metricset":{"timestamp":1646046826280243,"samples":{"system.cpu.total.norm.pct":{"value":1.0},"system.memory.actual.free":{"value":130961408},"system.memory.total":{"value":196698112},"system.process.cpu.total.norm.pct":{"value":1.0},"system.process.memory.size":{"value":577310720},"system.process.memory.rss.bytes":{"value":35106816}}}}

2022/02/28 11:13:46 Adding agent data to buffer to be sent to apm server
2022/02/28 11:13:47 APM server response body: 
2022/02/28 11:13:47 APM server response status code: 202
2022/02/28 11:13:47 funcDone signal received, not processing any more agent data
2022/02/28 11:13:47 Waiting for next event...
END RequestId: a4a1105e-0586-40c4-a217-dc60107baad0
REPORT RequestId: a4a1105e-0586-40c4-a217-dc60107baad0	Duration: 723.44 ms	Billed Duration: 724 ms	Memory Size: 128 MB	Max Memory Used: 80 MB	Init Duration: 716.12 ms	

2nd invocation - race lost : no APM data sent

START RequestId: cb46eb4b-28e7-40fb-afa1-86b8b9f1dd15 Version: $LATEST
2022/02/28 11:14:03 Received event: {
	"eventType": "INVOKE",
	"deadlineMs": 1646046863804,
	"requestId": "cb46eb4b-28e7-40fb-afa1-86b8b9f1dd15",
	"invokedFunctionArn": "arn:aws:lambda:eu-central-1:627286350134:function:EmilyTestRepro",
	"tracing": {
		"type": "X-Amzn-Trace-Id",
		"value": "Root=1-621cae7b-4b4277603baab37e2d598014;Parent=67578c530c50ee78;Sampled=0"
	}
}
2022/02/28 11:14:03 Checking for agent data
2022/02/28 11:14:03 Processing agent data
first transaction
2022/02/28 11:14:03 APM server response body: 
2022/02/28 11:14:03 APM server response status code: 202
2022/02/28 11:14:03 No agent data on buffer
2022/02/28 11:14:03 Received log event platform.end
2022/02/28 11:14:03 Received log event platform.report
2022/02/28 11:14:03 Received log event platform.start
2022/02/28 11:14:03 Received log event platform.runtimeDone
2022/02/28 11:14:03 Received runtimeDone event for this function invocation
2022/02/28 11:14:03 Received runtimeDone signal
2022/02/28 11:14:03 Checking for agent data
2022/02/28 11:14:03 No agent data on buffer
2022/02/28 11:14:03 funcDone signal received, not processing any more agent data
2022/02/28 11:14:03 Waiting for next event...
END RequestId: cb46eb4b-28e7-40fb-afa1-86b8b9f1dd15
REPORT RequestId: cb46eb4b-28e7-40fb-afa1-86b8b9f1dd15	Duration: 153.65 ms	Billed Duration: 154 ms	Memory Size: 128 MB	Max Memory Used: 81 MB	

3rd invocation - behavior impacted by previous race lost, and APM server error

START RequestId: caf29878-ae6e-40fc-bf64-1e9b01ae40ce Version: $LATEST
E, [2022-02-28T11:15:26.751218 #17] ERROR cc141bb4-f5ca-498a-a94b-d5046a89cfeb -- : [ElasticAPM] [THREAD:540]: APM Server not responding in time, terminating requestE, [2022-02-28T11:15:26.752061 #17] ERROR cc141bb4-f5ca-498a-a94b-d5046a89cfeb -- : [ElasticAPM] [THREAD:560]: APM Server not responding in time, terminating request2022/02/28 11:15:26 Received event: {
	"eventType": "INVOKE",
	"deadlineMs": 1646046946753,
	"requestId": "caf29878-ae6e-40fc-bf64-1e9b01ae40ce",
	"invokedFunctionArn": "arn:aws:lambda:eu-central-1:627286350134:function:EmilyTestRepro",
	"tracing": {
		"type": "X-Amzn-Trace-Id",
		"value": "Root=1-621caece-6281dda53cace0cd52488344;Parent=120eb7f02d0462a7;Sampled=0"
	}
}
2022/02/28 11:15:26 Checking for agent data
2022/02/28 11:15:26 No agent data on buffer
2022/02/28 11:15:26 Received log event platform.end
2022/02/28 11:15:26 Received log event platform.report
2022/02/28 11:15:26 Received log event platform.start
first transaction
2022/02/28 11:15:27 Received log event platform.runtimeDone
2022/02/28 11:15:27 Received runtimeDone event for this function invocation
2022/02/28 11:15:27 Received runtimeDone signal
2022/02/28 11:15:27 Checking for agent data
2022/02/28 11:15:27 No agent data on buffer
2022/02/28 11:15:27 funcDone signal received, not processing any more agent data
2022/02/28 11:15:27 Waiting for next event...
END RequestId: caf29878-ae6e-40fc-bf64-1e9b01ae40ce
REPORT RequestId: caf29878-ae6e-40fc-bf64-1e9b01ae40ce	Duration: 305.29 ms	Billed Duration: 306 ms	Memory Size: 128 MB	Max Memory Used: 82 MB	

4th invocation - race won : the extension sends the accumulated data at once to the APM server

START RequestId: 67b59410-36ff-4777-ab0b-d7d145bfbf30 Version: $LATEST
2022/02/28 11:16:03 Received event: {
	"eventType": "INVOKE",
	"deadlineMs": 1646046983297,
	"requestId": "67b59410-36ff-4777-ab0b-d7d145bfbf30",
	"invokedFunctionArn": "arn:aws:lambda:eu-central-1:627286350134:function:EmilyTestRepro",
	"tracing": {
		"type": "X-Amzn-Trace-Id",
		"value": "Root=1-621caef3-0576a4cc6272c3c1585cf425;Parent=408dbdd76b1b1ab0;Sampled=0"
	}
}
2022/02/28 11:16:03 Checking for agent data
2022/02/28 11:16:03 No agent data on buffer
2022/02/28 11:16:03 Received log event platform.end
2022/02/28 11:16:03 Received log event platform.report
first transaction
2022/02/28 11:16:03 Received log event platform.start
2022/02/28 11:16:03 Adding agent data to buffer to be sent to apm server
2022/02/28 11:16:03 {"metadata":{"service":{"name":"LambdaRepro","environment":null,"version":null,"agent":{"name":"ruby","version":"4.4.0"},"framework":{"name":null,"version":null},"language":{"name":"ruby","version":"2.7.5"},"runtime":{"name":"ruby","version":"2.7.5"}},"process":{"pid":17,"title":"/var/runtime/lib/runtime.rb","argv":[]},"system":{"configured_hostname":null,"architecture":"x86_64","platform":"linux","kubernetes":{"namespace":null,"node":{"name":null},"pod":{"name":null,"uid":null}},"container":null,"detected_hostname":"169.254.94.233"},"labels":null}}
{"span":{"id":"d69c9c8167bd5a60","transaction_id":"9b82eef6fd0c4350","parent_id":"9b82eef6fd0c4350","name":"first","type":"custom","duration":0.061,"context":{},"stacktrace":[],"timestamp":1646046956299514,"trace_id":"a6f19ded8987ba90999506035ad11d87","sample_rate":1.0,"outcome":"success"}}
{"span":{"id":"3ddb9455fc7294dc","transaction_id":"00671997b65b9d8e","parent_id":"00671997b65b9d8e","name":"first","type":"custom","duration":0.066,"context":{},"stacktrace":[],"timestamp":1646046961998614,"trace_id":"e85895b335d5b56d387826f8dfa3926a","sample_rate":1.0,"outcome":"success"}}
{"transaction":{"id":"00671997b65b9d8e","trace_id":"e85895b335d5b56d387826f8dfa3926a","parent_id":null,"name":"test-1","type":"custom","result":"","outcome":"success","duration":79.926,"timestamp":1646046961918841,"sampled":true,"sample_rate":1.0,"context":null,"span_count":{"started":1,"dropped":0}}}

2022/02/28 11:16:03 Received log event platform.runtimeDone
2022/02/28 11:16:03 Received runtimeDone event for this function invocation
2022/02/28 11:16:03 Received runtimeDone signal
2022/02/28 11:16:03 Checking for agent data
2022/02/28 11:16:03 No agent data on buffer
2022/02/28 11:16:03 APM server response body: 
2022/02/28 11:16:03 APM server response status code: 202
2022/02/28 11:16:03 funcDone signal received, not processing any more agent data
2022/02/28 11:16:03 Waiting for next event...
END RequestId: 67b59410-36ff-4777-ab0b-d7d145bfbf30
REPORT RequestId: 67b59410-36ff-4777-ab0b-d7d145bfbf30	Duration: 302.19 ms	Billed Duration: 303 ms	Memory Size: 128 MB	Max Memory Used: 82 MB	

Next Steps

• Improve Unit Testing on main.go to detect the mentioned behavior
• Simplify the agent data processing logic by using other patterns