APM data fails to send on initial request following cold start

[pushred]

I'm able to reproduce an issue where on cold start of our Lambda functions APM data does not seem to be sent following the initial request. Subsequent requests succeed with a 202 response however, and it appears that the initial request's data is also sent at that point. If I only make a single request however data is never sent if I do not make another request before the function exits.

One nuance of our setup that could be involved is the use of a VPC endpoint. I do see an error prior to shutdown in most of the failing instances (however not all) that might be related:

Error sending to APM server, skipping: failed to post to APM server: Post "https://example.vpce.us-east-1.aws.elastic-cloud.com/intake/v2/events": net/http: TLS handshake timeout

I saw this was previously reported in #27 and #30 attempted to address it, but I'm still experiencing this with a build of v0.0.2. I was curious if this might be a lower level issue in net/http and saw that Go 1.17 made changes in this area. I tried a new build where I updated the version specified in go.mod — not sure if that's correct, I'm not a Go developer — but still experienced the error.

Following are complete logs for each case, let me know if there are any other details I can provide that might be helpful.

Successful (2 requests made)

START RequestId: 7793f785-01b3-4622-a51b-1abdb0d851a9 Version: $LATEST
2022/01/06 19:40:24 dafec285-3fbd-43b4-9963-620c3b3f7dc1
2022/01/06 19:40:24 Register response: {
	"functionName": "example",
	"functionVersion": "$LATEST",
	"handler": "src/functions/example.main"
}
2022/01/06 19:40:24 Could not read ELASTIC_APM_DATA_RECEIVER_TIMEOUT_SECONDS, defaulting to 15: strconv.Atoi: parsing "": invalid syntax
2022/01/06 19:40:24 Extension listening for apm data on :8200
LOGS	Name: apm-lambda-extension	State: Subscribed	Types: [platform]
2022/01/06 19:40:24 Waiting for next event...
2022/01/06 19:40:24 Server listening for logs data from AWS Logs API on sandbox:1234
2022-01-06T19:40:25.436Z	undefined	INFO	environment: local
EXTENSION	Name: apm-lambda-extension	State: Ready	Events: [SHUTDOWN,INVOKE]
2022/01/06 19:40:27 Received event: {
	"eventType": "INVOKE",
	"deadlineMs": 1641498033074,
	"requestId": "7793f785-01b3-4622-a51b-1abdb0d851a9",
	"invokedFunctionArn": "arn:aws:lambda:us-east-1:123456789:function:example",
	"tracing": {
		"type": "X-Amzn-Trace-Id",
		"value": "Root=1-61d745a8-6712259e4421fd28323493a4;Parent=5fe0cfd90ee4f348;Sampled=0"
	}
}
2022/01/06 19:40:27 Checking for agent data
2022/01/06 19:40:27 No agent data on buffer
2022/01/06 19:40:27 Received log event platform.logsSubscription
{
    "log.level": "info",
    "@timestamp": "2022-01-06T19:40:27.076Z",
    "process": {
        "pid": 17
    },
    "host": {
        "hostname": "169.254.224.13"
    },
    "log": {
        "logger": "example"
    },
    "ecs": {
        "version": "1.6.0"
    },
    "service": {
        "environment": "local",
        "name": "example",
        "version": "0.0.1"
    },
    "event": {
        "type": "event"
    },
    "client": {
        "ip": "137.83.250.80"
    },
    "http": {
        "version": "1.1",
        "request": {
            "id": "28575b2d-a119-4075-9fe1-24cf867994f9",
            "method": "GET",
            "mime_type": "application/json"
        }
    },
    "url": {
        "domain": "example.execute-api.us-east-1.amazonaws.com",
        "full": "https://example.execute-api.us-east-1.amazonaws.com/example",
        "path": "/example"
    },
    "user_agent": {
        "original": "Paw/3.3.3 (Macintosh; OS X/11.6.2) GCDHTTPRequest"
    },
    "message": "GET /example"
}

2022/01/06 19:40:27 Received log event platform.start
2022/01/06 19:40:27 Received log event platform.extension



2022/01/06 19:40:27 Adding agent data to buffer to be sent to apm server
2022/01/06 19:40:27 Received log event platform.runtimeDone
2022/01/06 19:40:27 Received runtimeDone event {2022-01-06 19:40:27.142 +0000 UTC platform.runtimeDone [123 34 114 101 113 117 101 115 116 73 100 34 58 34 55 55 57 51 102 55 56 53 45 48 49 98 51 45 52 54 50 50 45 97 53 49 98 45 49 97 98 100 98 48 100 56 53 49 97 57 34 44 34 115 116 97 116 117 115 34 58 34 115 117 99 99 101 115 115 34 125] {7793f785-01b3-4622-a51b-1abdb0d851a9 success}}
2022/01/06 19:40:27 Received runtimeDone event signal
2022/01/06 19:40:27 Checking for agent data
2022/01/06 19:40:27 No agent data on buffer
2022/01/06 19:40:27 Waiting for next event...
END RequestId: 7793f785-01b3-4622-a51b-1abdb0d851a9
REPORT RequestId: 7793f785-01b3-4622-a51b-1abdb0d851a9	Duration: 100.43 ms	Billed Duration: 101 ms	Memory Size: 1024 MB	Max Memory Used: 141 MB	Init Duration: 2307.93 ms	
START RequestId: 59772466-fa90-48c8-a083-cb4ca63b0247 Version: $LATEST
2022/01/06 19:40:28 Received event: {
	"eventType": "INVOKE",
	"deadlineMs": 1641498034659,
	"requestId": "59772466-fa90-48c8-a083-cb4ca63b0247",
	"invokedFunctionArn": "arn:aws:lambda:us-east-1:123456789:function:example",
	"tracing": {
		"type": "X-Amzn-Trace-Id",
		"value": "Root=1-61d745ac-6d86457a7e3c62080ad266e7;Parent=36025f0128c835e2;Sampled=0"
	}
}
2022/01/06 19:40:28 Checking for agent data
2022/01/06 19:40:28 No agent data on buffer
2022/01/06 19:40:28 Received log event platform.end
2022/01/06 19:40:28 Received log event platform.report
{
    "log.level": "info",
    "@timestamp": "2022-01-06T19:40:28.660Z",
    "process": {
        "pid": 17
    },
    "host": {
        "hostname": "169.254.224.13"
    },
    "log": {
        "logger": "example"
    },
    "ecs": {
        "version": "1.6.0"
    },
    "service": {
        "environment": "local",
        "name": "example",
        "version": "0.0.1"
    },
    "event": {
        "type": "event"
    },
    "client": {
        "ip": "137.83.250.80"
    },
    "http": {
        "version": "1.1",
        "request": {
            "id": "53af426b-f9ef-44dd-a909-749f51208a06",
            "method": "GET",
            "mime_type": "application/json"
        }
    },
    "url": {
        "domain": "example.execute-api.us-east-1.amazonaws.com",
        "full": "https://example.execute-api.us-east-1.amazonaws.com/example",
        "path": "/example"
    },
    "user_agent": {
        "original": "Paw/3.3.3 (Macintosh; OS X/11.6.2) GCDHTTPRequest"
    },
    "message": "GET /example"
}



2022/01/06 19:40:28 APM server response body: 
2022/01/06 19:40:28 APM server response status code: 202
2022/01/06 19:40:28 Function invocation is complete, not receiving any more agent data
2022/01/06 19:40:28 Received log event platform.start
2022/01/06 19:40:28 Adding agent data to buffer to be sent to apm server
2022/01/06 19:40:28 APM server response body: 
2022/01/06 19:40:28 APM server response status code: 202
2022/01/06 19:40:28 Received log event platform.runtimeDone
2022/01/06 19:40:28 Received runtimeDone event {2022-01-06 19:40:28.708 +0000 UTC platform.runtimeDone [123 34 114 101 113 117 101 115 116 73 100 34 58 34 53 57 55 55 50 52 54 54 45 102 97 57 48 45 52 56 99 56 45 97 48 56 51 45 99 98 52 99 97 54 51 98 48 50 52 55 34 44 34 115 116 97 116 117 115 34 58 34 115 117 99 99 101 115 115 34 125] {59772466-fa90-48c8-a083-cb4ca63b0247 success}}
2022/01/06 19:40:28 Received runtimeDone event signal
2022/01/06 19:40:28 Checking for agent data
2022/01/06 19:40:28 No agent data on buffer
2022/01/06 19:40:28 Waiting for next event...
2022/01/06 19:40:28 Function invocation is complete, not receiving any more agent data
END RequestId: 59772466-fa90-48c8-a083-cb4ca63b0247
REPORT RequestId: 59772466-fa90-48c8-a083-cb4ca63b0247	Duration: 75.42 ms	Billed Duration: 76 ms	Memory Size: 1024 MB	Max Memory Used: 143 MB	
2022/01/06 19:46:24 Received event: {
	"eventType": "SHUTDOWN",
	"deadlineMs": 1641498386392,
	"requestId": "",
	"invokedFunctionArn": "",
	"tracing": {
		"type": "",
		"value": ""
	}
}
2022/01/06 19:46:24 Received SHUTDOWN event
2022/01/06 19:46:24 Exiting

Failing (1 request made)

START RequestId: 87034d95-cc28-47bf-a883-315708cc4541 Version: $LATEST
2022/01/06 20:06:34 0e0efbd3-486b-4b6a-8fa9-3e08895eddbc
2022/01/06 20:06:34 Register response: {
	"functionName": "example",
	"functionVersion": "$LATEST",
	"handler": "src/functions/example.main"
}
2022/01/06 20:06:34 Could not read ELASTIC_APM_DATA_RECEIVER_TIMEOUT_SECONDS, defaulting to 15: strconv.Atoi: parsing "": invalid syntax
2022/01/06 20:06:34 Extension listening for apm data on :8200
LOGS	Name: apm-lambda-extension	State: Subscribed	Types: [platform]
2022/01/06 20:06:34 Waiting for next event...
2022/01/06 20:06:34 Server listening for logs data from AWS Logs API on sandbox:1234
2022-01-06T20:06:35.062Z	undefined	INFO	environment: local
EXTENSION	Name: apm-lambda-extension	State: Ready	Events: [INVOKE,SHUTDOWN]
2022/01/06 20:06:36 Received event: {
	"eventType": "INVOKE",
	"deadlineMs": 1641499602632,
	"requestId": "87034d95-cc28-47bf-a883-315708cc4541",
	"invokedFunctionArn": "arn:aws:lambda:us-east-1:123456789:function:example",
	"tracing": {
		"type": "X-Amzn-Trace-Id",
		"value": "Root=1-61d74bc9-2c57d3874a56e71643d82488;Parent=46d54995211d520d;Sampled=0"
	}
}
2022/01/06 20:06:36 Checking for agent data
2022/01/06 20:06:36 No agent data on buffer
2022/01/06 20:06:36 Received log event platform.logsSubscription
{
    "log.level": "info",
    "@timestamp": "2022-01-06T20:06:36.635Z",
    "process": {
        "pid": 18
    },
    "host": {
        "hostname": "169.254.226.157"
    },
    "log": {
        "logger": "example"
    },
    "ecs": {
        "version": "1.6.0"
    },
    "service": {
        "environment": "local",
        "name": "example",
        "version": "0.0.1"
    },
    "event": {
        "type": "event"
    },
    "client": {
        "ip": "137.83.250.80"
    },
    "http": {
        "version": "1.1",
        "request": {
            "id": "e68f9f6a-f283-434e-814f-68a23c824129",
            "method": "GET",
            "mime_type": "application/json"
        }
    },
    "url": {
        "domain": "example.execute-api.us-east-1.amazonaws.com",
        "full": "https://example.execute-api.us-east-1.amazonaws.com/example",
        "path": "/example"
    },
    "user_agent": {
        "original": "Paw/3.3.3 (Macintosh; OS X/11.6.2) GCDHTTPRequest"
    },
    "message": "GET /example"
}
2022/01/06 20:06:36 Received log event platform.start

2022/01/06 20:06:36 Received log event platform.extension

2022/01/06 20:06:36 Adding agent data to buffer to be sent to apm server

2022/01/06 20:06:36 Received log event platform.runtimeDone

2022/01/06 20:06:36 Received runtimeDone event {2022-01-06 20:06:36.699 +0000 UTC platform.runtimeDone [123 34 114 101 113 117 101 115 116 73 100 34 58 34 56 55 48 51 52 100 57 53 45 99 99 50 56 45 52 55 98 102 45 97 56 56 51 45 51 49 53 55 48 56 99 99 52 53 52 49 34 44 34 115 116 97 116 117 115 34 58 34 115 117 99 99 101 115 115 34 125] {87034d95-cc28-47bf-a883-315708cc4541 success}}

2022/01/06 20:06:36 Received runtimeDone event signal

2022/01/06 20:06:36 Checking for agent data

2022/01/06 20:06:36 No agent data on buffer

2022/01/06 20:06:36 Waiting for next event...

END RequestId: 87034d95-cc28-47bf-a883-315708cc4541

REPORT RequestId: 87034d95-cc28-47bf-a883-315708cc4541	Duration: 99.43 ms	Billed Duration: 100 ms	Memory Size: 1024 MB	Max Memory Used: 140 MB	Init Duration: 2267.62 ms

2022/01/06 20:12:24 Error sending to APM server, skipping: failed to post to APM server: Post "https://example.vpce.us-east-1.aws.elastic-cloud.com/intake/v2/events": EOF

2022/01/06 20:12:24 Function invocation is complete, not receiving any more agent data

2022/01/06 20:12:24 Received event: {

"eventType": "SHUTDOWN",

"deadlineMs": 1641499946747,

"requestId": "",

"invokedFunctionArn": "",

"tracing": {

"type": "",

"value": ""

}

}

2022/01/06 20:12:24 Received SHUTDOWN event

2022/01/06 20:12:24 Exiting

[astorm]

Thanks for the thorough and thoughtful report @pushred. One clarifying question -- putting asside the lack of observability data, when the cold start fails to send data does the actual function invocation during the cold start still work, or does it return an unexpected error? I presume it still works and that we're not interfering with the result of the invocation, but if I've misunderstood that please let me know.

Also, I assume "VPC" here means Amazon's virtual private cloud.

Looking over what you've reported, the error logged

Error sending to APM server, skipping: failed to post to APM server: Post "https://example.vpce.us-east-1.aws.elastic-cloud.com/intake/v2/events": net/http: TLS handshake timeout

indicates that when APM Server tries to post its data to https://example.vpce.us-east-1.aws.elastic-cloud.com/intake/v2/events, that there's a timeout during the TLS/SSL handshake portion of the request.

This means either there's a real timeout, or that the request to https://example.vpce.us-east-1.aws.elastic-cloud.com/intake/v2/events is hanging forever and the lambda function itself times out.

One possible experiment to run would be to create a custom Transport object for the HTTP Client and increase the TLSHandshakeTimeout value.

apm-aws-lambda/apm-lambda-extension/main.go

Line 70 in 7b797b5

client := &http.Client{

If that worked we could introduce an env. variable that would let you control this value.

However -- I suspect this is a case of the VPC server (https://example.vpce.us-east-1.aws.elastic-cloud.com/intake/v2/events) simply refusing to talk to a Lambda function's VM during that first request for some reason. I would normally ask the VPC operator what's happening on their end when I'm making these requests, but I'm not sure if that's available with Amazon's virtual private cloud.

Does that all make sense and at least give you a sense of which direction to head on this @pushred?

[pushred]

Thank you for the fast response!

putting asside the lack of observability data, when the cold start fails to send data does the actual function invocation during the cold start still work, or does it return an unexpected error? I presume it still works and that we're not interfering with the result of the invocation, but if I've misunderstood that please let me know.

Correct, it seems to work as I get a response as expected and logging for the function appears to be normal, aside from what is coming from the extension.

Also, I assume "VPC" here means Amazon's virtual private cloud.

Correct

One possible experiment to run would be to create a custom Transport object for the HTTP Client and increase the TLSHandshakeTimeout value.

I'll give this a shot, I will need to learn just enough Go to do it though, so may take a bit! Unless there is a quick code snippet you could provide.

I would normally ask the VPC operator what's happening on their end when I'm making these requests, but I'm not sure if that's available with Amazon's virtual private cloud.

We'll try opening an AWS support case to see if we can get any explanation for the behavior we're experiencing.

[AlexanderWert]

Hi @pushred,

the problem you reported should be fixed with #106.
Please reopen if you still experience this problem with new versions (> 0.0.2) of the lambda extension.