Lambda : Unreadable HTTP body sent when using pg.Pool() and the AWS SAM CLI

[jlvoiseux]

Bug description

When running an APM-instrumented Lambda function and querying a Postgres instance using pg.Pool (example), the agent sends an HTTP request to the Lambda extension whose body is unreadable by the extension.

Afterwards, no data is sent to the APM server, and subsequent invocations of the Lambda function are interrupted.

Sample execution logs

First invocation (unreadable body)

opbeans-lambda_1  | 2022/02/15 17:06:47 Received event: {
opbeans-lambda_1  |     "eventType": "INVOKE",
opbeans-lambda_1  |     "deadlineMs": 1644944817828,
opbeans-lambda_1  |     "requestId": "0ca8d962-201b-4e94-a4b5-0585b955004e",
opbeans-lambda_1  |     "invokedFunctionArn": "arn:aws:lambda:us-east-1:012345678912:function:OpbeansLambdaItemsPool",
opbeans-lambda_1  |     "tracing": {
opbeans-lambda_1  |             "type": "",
opbeans-lambda_1  |             "value": ""
opbeans-lambda_1  |     }
opbeans-lambda_1  | }
opbeans-lambda_1  | 2022/02/15 17:06:47 Checking for agent data
opbeans-lambda_1  | 2022/02/15 17:06:47 No agent data on buffer
opbeans-lambda_1  | {"log.level":"trace","@timestamp":"2022-02-15T17:06:47.894Z","log":{"logger":"elastic-apm-node"},"awsRequestId":"0ca8d962-201b-4e94-a4b5-0585b955004e","ecs":{"version":"1.6.0"},"message":"lambda: fn start"}
opbeans-lambda_1  | {"log.level":"trace","@timestamp":"2022-02-15T17:06:47.895Z","log":{"logger":"elastic-apm-node"},"awsRequestId":"0ca8d962-201b-4e94-a4b5-0585b955004e","ecs":{"version":"1.6.0"},"message":"lambda: setExtraMetadata"}
opbeans-lambda_1  | {"log.level":"trace","@timestamp":"2022-02-15T17:06:47.907Z","log":{"logger":"elastic-apm-node"},"event.module":"apmclient","_encodedMetadata":"{\"metadata\":{\"service\":{\"name\":\"OpbeansLambdaItemsPool\",\"environment\":\"development\",\"runtime\":{\"name\":\"AWS_Lambda_nodejs14.x\",\"version\":\"14.18.3\"},\"language\":{\"name\":\"javascript\"},\"agent\":{\"name\":\"nodejs\",\"version\":\"3.29.0\"},\"version\":\"$LATEST\",\"id\":\"arn:aws:lambda:us-east-1:012345678912:function:OpbeansLambdaItemsPool\",\"framework\":{\"name\":\"AWS Lambda\"},\"node\":{\"configured_name\":\"$LATEST\"}},\"process\":{\"pid\":29,\"ppid\":1,\"title\":\"/var/lang/bin/node\",\"argv\":[\"/var/lang/bin/node\",\"/var/runtime/index.js\"]},\"system\":{\"hostname\":\"0d992400a1e7\",\"architecture\":\"x64\",\"platform\":\"linux\",\"container\":{\"id\":\"0d992400a1e7b07ad4b9f4989dbb8ab8e562e1cedf6a542f54563b42a8a5ac55\"}},\"cloud\":{\"provider\":\"aws\",\"region\":\"us-east-1\",\"service\":{\"name\":\"lambda\"},\"account\":{\"id\":\"012345678912\"}}}}\n","ecs":{"version":"1.6.0"},"message":"_resetEncodedMetadata"}
opbeans-lambda_1  | {"log.level":"trace","@timestamp":"2022-02-15T17:06:47.908Z","log":{"logger":"elastic-apm-node"},"event.module":"apmclient","ecs":{"version":"1.6.0"},"message":"uncorked (expectExtraMetadata)"}
opbeans-lambda_1  | {"log.level":"debug","@timestamp":"2022-02-15T17:06:47.924Z","log":{"logger":"elastic-apm-node"},"ecs":{"version":"1.6.0"},"message":"start trace {\"trans\":\"0b0492f19ef7c917\",\"trace\":\"8f687dc4c7633f5d6db2afceb4fa67db\",\"name\":\"unnamed\",\"type\":\"lambda\",\"subtype\":null,\"action\":null}"}
opbeans-lambda_1  | {"log.level":"debug","@timestamp":"2022-02-15T17:06:47.926Z","log":{"logger":"elastic-apm-node"},"ctxmgr":"AsyncHooksRunContextManager( RC(Trans(0b0492, OpbeansLambdaItemsPool)) )","ecs":{"version":"1.6.0"},"message":"supersedeWithTransRunContext()"}
opbeans-lambda_1  | {"log.level":"debug","@timestamp":"2022-02-15T17:06:47.928Z","log":{"logger":"elastic-apm-node"},"ecs":{"version":"1.6.0"},"message":"setting transaction name {\"trans\":\"0b0492f19ef7c917\",\"trace\":\"8f687dc4c7633f5d6db2afceb4fa67db\",\"name\":\"OpbeansLambdaItemsPool\"}"}
opbeans-lambda_1  | {"log.level":"debug","@timestamp":"2022-02-15T17:06:47.928Z","log":{"logger":"elastic-apm-node"},"ecs":{"version":"1.6.0"},"message":"setting transaction result {\"trans\":\"0b0492f19ef7c917\",\"trace\":\"8f687dc4c7633f5d6db2afceb4fa67db\",\"result\":\"success\"}"}
opbeans-lambda_1  | {"log.level":"debug","@timestamp":"2022-02-15T17:06:47.930Z","log":{"logger":"elastic-apm-node"},"ecs":{"version":"1.6.0"},"message":"setting transaction name {\"trans\":\"0b0492f19ef7c917\",\"trace\":\"8f687dc4c7633f5d6db2afceb4fa67db\",\"name\":\"GET OpbeansLambdaItemsPool\"}"}
opbeans-lambda_1  | {"log.level":"debug","@timestamp":"2022-02-15T17:06:47.978Z","log":{"logger":"elastic-apm-node"},"event.module":"apmclient","apmServerVersion":"7.16.3","ecs":{"version":"1.6.0"},"message":"fetched APM Server version"}
opbeans-lambda_1  | {"log.level":"debug","@timestamp":"2022-02-15T17:06:48.481Z","log":{"logger":"elastic-apm-node"},"ecs":{"version":"1.6.0"},"message":"intercepted call to pg.Client.prototype.query"}
opbeans-lambda_1  | {"log.level":"debug","@timestamp":"2022-02-15T17:06:48.488Z","log":{"logger":"elastic-apm-node"},"ecs":{"version":"1.6.0"},"message":"start span {\"span\":\"1336391f1f7fb3bc\",\"parent\":\"0b0492f19ef7c917\",\"trace\":\"8f687dc4c7633f5d6db2afceb4fa67db\",\"name\":\"SQL\",\"type\":\"db\",\"subtype\":\"postgresql\",\"action\":\"query\"}"}
postgres_1        | 2022-02-15 17:06:48.499 UTC [481] LOG:  statement: CREATE TABLE IF NOT EXISTS products (Id SERIAL PRIMARY KEY, Name varchar(255) NOT NULL, Description varchar(255) NOT NULL)
opbeans-lambda_1  | {"log.level":"debug","@timestamp":"2022-02-15T17:06:48.509Z","log":{"logger":"elastic-apm-node"},"ecs":{"version":"1.6.0"},"message":"intercepted end of pg.Client.prototype.query"}
opbeans-lambda_1  | {"log.level":"debug","@timestamp":"2022-02-15T17:06:48.511Z","log":{"logger":"elastic-apm-node"},"ecs":{"version":"1.6.0"},"message":"ended span {\"span\":\"1336391f1f7fb3bc\",\"parent\":\"0b0492f19ef7c917\",\"trace\":\"8f687dc4c7633f5d6db2afceb4fa67db\",\"name\":\"CREATE TABLE IF\",\"type\":\"db\",\"subtype\":\"postgresql\",\"action\":\"query\"}"}
opbeans-lambda_1  | {"log.level":"debug","@timestamp":"2022-02-15T17:06:48.530Z","log":{"logger":"elastic-apm-node"},"ctxmgr":"AsyncHooksRunContextManager( RC(Trans(0b0492, GET OpbeansLambdaItemsPool)), RC(Trans(0b0492, GET OpbeansLambdaItemsPool)), RC(Trans(0b0492, GET OpbeansLambdaItemsPool)) )","ecs":{"version":"1.6.0"},"message":"addEndedSpan(CREATE TABLE IF)"}
opbeans-lambda_1  | {"log.level":"debug","@timestamp":"2022-02-15T17:06:48.532Z","log":{"logger":"elastic-apm-node"},"ecs":{"version":"1.6.0"},"message":"encoding span {\"span\":\"1336391f1f7fb3bc\",\"parent\":\"0b0492f19ef7c917\",\"trace\":\"8f687dc4c7633f5d6db2afceb4fa67db\",\"name\":\"CREATE TABLE IF\",\"type\":\"db\"}"}
opbeans-lambda_1  | 2022-02-15T17:06:48.542Z    0ca8d962-201b-4e94-a4b5-0585b955004e    INFO    Table created
opbeans-lambda_1  | {"log.level":"trace","@timestamp":"2022-02-15T17:06:48.555Z","log":{"logger":"elastic-apm-node"},"awsRequestId":"0ca8d962-201b-4e94-a4b5-0585b955004e","ecs":{"version":"1.6.0"},"message":"lambda: fn end"}
opbeans-lambda_1  | {"log.level":"debug","@timestamp":"2022-02-15T17:06:48.556Z","log":{"logger":"elastic-apm-node"},"ecs":{"version":"1.6.0"},"message":"setting transaction result {\"trans\":\"0b0492f19ef7c917\",\"trace\":\"8f687dc4c7633f5d6db2afceb4fa67db\",\"result\":\"HTTP 2xx\"}"}
opbeans-lambda_1  | {"log.level":"debug","@timestamp":"2022-02-15T17:06:48.558Z","log":{"logger":"elastic-apm-node"},"ctxmgr":"AsyncHooksRunContextManager( RC() )","ecs":{"version":"1.6.0"},"message":"addEndedTransaction(GET OpbeansLambdaItemsPool)"}
opbeans-lambda_1  | {"log.level":"debug","@timestamp":"2022-02-15T17:06:48.562Z","log":{"logger":"elastic-apm-node"},"ecs":{"version":"1.6.0"},"message":"sending transaction {\"trans\":\"0b0492f19ef7c917\",\"trace\":\"8f687dc4c7633f5d6db2afceb4fa67db\"}"}
opbeans-lambda_1  | {"log.level":"debug","@timestamp":"2022-02-15T17:06:48.566Z","log":{"logger":"elastic-apm-node"},"ecs":{"version":"1.6.0"},"message":"ended transaction {\"trans\":\"0b0492f19ef7c917\",\"trace\":\"8f687dc4c7633f5d6db2afceb4fa67db\",\"type\":\"request\",\"result\":\"HTTP 2xx\",\"name\":\"GET OpbeansLambdaItemsPool\"}"}
opbeans-lambda_1  | {"log.level":"trace","@timestamp":"2022-02-15T17:06:48.605Z","log":{"logger":"elastic-apm-node"},"event.module":"apmclient","reqId":"b0e4485922badf64df394dd84273ad8c","ecs":{"version":"1.6.0"},"message":"intake request start"}
opbeans-lambda_1  | {"log.level":"trace","@timestamp":"2022-02-15T17:06:48.615Z","log":{"logger":"elastic-apm-node"},"event.module":"apmclient","fullTimeMs":22.875,"numEvents":1,"numBytes":683,"ecs":{"version":"1.6.0"},"message":"_write: encode object"}
opbeans-lambda_1  | {"log.level":"trace","@timestamp":"2022-02-15T17:06:48.619Z","log":{"logger":"elastic-apm-node"},"event.module":"apmclient","reqId":"b0e4485922badf64df394dd84273ad8c","ecs":{"version":"1.6.0"},"message":"intakeReq \"socket\": unref it"}
opbeans-lambda_1  | 2022/02/15 17:06:49 Could not read bytes from agent request body 
opbeans-lambda_1  | 2022-02-15 17:06:49,172 | Unable to find Click Context for getting session_id.
opbeans-lambda_1  | 2022-02-15 17:06:49,172 | Invalid lambda response received: Lambda response must be valid json
opbeans-lambda_1  | 2022-02-15 17:06:49 172.21.0.1 - - [15/Feb/2022 17:06:49] "GET /itemsPool HTTP/1.1" 502 -
opbeans-lambda_1  | 2022-02-15 17:06:49 172.21.0.1 - - [15/Feb/2022 17:06:49] "GET /favicon.ico HTTP/1.1" 403 -
opbeans-lambda_1  | 2022/02/15 17:06:57 Time expired waiting for agent signal or runtimeDone event
opbeans-lambda_1  | 2022/02/15 17:06:57 Checking for agent data
opbeans-lambda_1  | 2022/02/15 17:06:57 No agent data on buffer
opbeans-lambda_1  | 2022/02/15 17:06:57 funcDone signal received, not processing any more log events
opbeans-lambda_1  | 2022/02/15 17:06:57 funcDone signal received, not processing any more agent data
opbeans-lambda_1  | 2022/02/15 17:06:57 Waiting for next event...

Second invocation (the Lambda function seems to be interrupted)

opbeans-lambda_1  | 2022-02-15 17:19:59,705 | Constructed String representation of Event to invoke Lambda. Event: {"body": null, "headers": {"Accept": "text/html,application/xhtml+xml,application/xml;q=0.9,image/avif,image/webp,image/apng,*/*;q=0.8,application/signed-exchange;v=b3;q=0.9", "Accept-Encoding": "gzip, deflate", "Accept-Language": "en-GB,en-US;q=0.9,en;q=0.8", "Cache-Control": "max-age=0", "Connection": "keep-alive", "Host": "0.0.0.0:3000", "Upgrade-Insecure-Requests": "1", "User-Agent": "Mozilla/5.0 (Macintosh; Intel Mac OS X 10_15_7) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/98.0.4758.80 Safari/537.36", "X-Forwarded-Port": "3000", "X-Forwarded-Proto": "http"}, "httpMethod": "GET", "isBase64Encoded": false, "multiValueHeaders": {"Accept": ["text/html,application/xhtml+xml,application/xml;q=0.9,image/avif,image/webp,image/apng,*/*;q=0.8,application/signed-exchange;v=b3;q=0.9"], "Accept-Encoding": ["gzip, deflate"], "Accept-Language": ["en-GB,en-US;q=0.9,en;q=0.8"], "Cache-Control": ["max-age=0"], "Connection": ["keep-alive"], "Host": ["0.0.0.0:3000"], "Upgrade-Insecure-Requests": ["1"], "User-Agent": ["Mozilla/5.0 (Macintosh; Intel Mac OS X 10_15_7) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/98.0.4758.80 Safari/537.36"], "X-Forwarded-Port": ["3000"], "X-Forwarded-Proto": ["http"]}, "multiValueQueryStringParameters": null, "path": "/itemsPool", "pathParameters": null, "queryStringParameters": null, "requestContext": {"accountId": "123456789012", "apiId": "1234567890", "domainName": "0.0.0.0:3000", "extendedRequestId": null, "httpMethod": "GET", "identity": {"accountId": null, "apiKey": null, "caller": null, "cognitoAuthenticationProvider": null, "cognitoAuthenticationType": null, "cognitoIdentityPoolId": null, "sourceIp": "172.21.0.1", "user": null, "userAgent": "Custom User Agent String", "userArn": null}, "path": "/itemsPool", "protocol": "HTTP/1.1", "requestId": "3ef1043b-987e-4579-b61c-10956dd16b37", "requestTime": "15/Feb/2022:17:05:16 +0000", "requestTimeEpoch": 1644944716, "resourceId": "123456", "resourcePath": "/itemsPool", "stage": "Prod"}, "resource": "/itemsPool", "stageVariables": null, "version": "1.0"}
opbeans-lambda_1  | 2022-02-15 17:19:59,706 | Found one Lambda function with name 'OpbeansLambdaItemsPool'
opbeans-lambda_1  | 2022-02-15 17:19:59,706 | Invoking src/itemsPool.itemsPool (nodejs14.x)
opbeans-lambda_1  | 2022-02-15 17:19:59,706 | Environment variables overrides data is standard format
opbeans-lambda_1  | 2022-02-15 17:19:59,706 | Loading AWS credentials from session with profile 'None'
opbeans-lambda_1  | 2022-02-15 17:20:01,734 | Resolving code path. Cwd=/Users/jlvoiseux/Documents/github/apm/sandbox/opbeans-lambda/nodejs, CodeUri=/Users/jlvoiseux/Documents/github/apm/sandbox/opbeans-lambda/nodejs/.aws-sam/build/OpbeansLambdaItemsPool
opbeans-lambda_1  | 2022-02-15 17:20:01,734 | Resolved absolute path to code is /Users/jlvoiseux/Documents/github/apm/sandbox/opbeans-lambda/nodejs/.aws-sam/build/OpbeansLambdaItemsPool
opbeans-lambda_1  | 2022-02-15 17:20:01,739 | Reuse the created warm container for Lambda function 'OpbeansLambdaItemsPool'
opbeans-lambda_1  | 2022-02-15 17:20:01,744 | Lambda function 'OpbeansLambdaItemsPool' is already running
opbeans-lambda_1  | 2022-02-15 17:20:01,745 | Starting a timer for 10 seconds for function 'OpbeansLambdaItemsPool'
opbeans-lambda_1  | START RequestId: d5c34398-2c78-440d-9de2-4c2f1e983224 Version: $LATEST
opbeans-lambda_1  | END RequestId: d5c34398-2c78-440d-9de2-4c2f1e983224
 opbeans-lambda_1  | REPORT RequestId: d5c34398-2c78-440d-9de2-4c2f1e983224      Duration: 5.77 ms       Billed Duration: 6 ms   Memory Size: 128 MB     Max Memory Used: 128 MB 
opbeans-lambda_1  | 2022-02-15 17:20:01,779 | Invalid lambda response received: Lambda response must be valid json
opbeans-lambda_1  | 2022-02-15 17:20:01 172.21.0.1 - - [15/Feb/2022 17:20:01] "GET /itemsPool HTTP/1.1" 502 -
opbeans-lambda_1  | 2022-02-15 17:20:01 172.21.0.1 - - [15/Feb/2022 17:20:01] "GET /favicon.ico HTTP/1.1" 403 -
opbeans-lambda_1  | 2022/02/15 17:20:01 Received event: {
opbeans-lambda_1  |     "eventType": "INVOKE",
opbeans-lambda_1  |     "deadlineMs": 1644945611768,
opbeans-lambda_1  |     "requestId": "d5c34398-2c78-440d-9de2-4c2f1e983224",
opbeans-lambda_1  |     "invokedFunctionArn": "arn:aws:lambda:us-east-1:012345678912:function:OpbeansLambdaItemsPool",
opbeans-lambda_1  |     "tracing": {
opbeans-lambda_1  |             "type": "",
opbeans-lambda_1  |             "value": ""
opbeans-lambda_1  |     }
opbeans-lambda_1  | }
opbeans-lambda_1  | 2022/02/15 17:20:01 Checking for agent data
opbeans-lambda_1  | 2022/02/15 17:20:01 No agent data on buffer

To Reproduce

This behavior can be reproduced by running the Opbeans Lambda demo and accessing the localhost:3000/itemsPool endpoint. Else, one needs to setup a Postgres database, write, build and execute a function dedicated to querying it with the AWS SAM CLI.

Expected behavior

The expected behavior is to send a transaction containing a span corresponding to the database interaction, similar to what happens here :

Environment (please complete the following information)

• OS: Linux (Docker image : https://gallery.ecr.aws/sam/build-nodejs14.x)
• Node.js version: v14
• APM Server version: 7.16.3
• Agent version: 3.27.0

How are you starting the agent? (please tick one of the boxes)

• Calling agent.start() directly (e.g. require('elastic-apm-node').start(...))
• Requiring elastic-apm-node/start from within the source code
• Starting node with -r elastic-apm-node/start

Additional context

• Agent config options

  Click to expand

  ELASTIC_APM_CENTRAL_CONFIG: false
  ELASTIC_APM_CLOUD_PROVIDER: none
  ELASTIC_APM_SERVER_URL: http://localhost:8200
  ELASTIC_APM_LOG_LEVEL: trace
  

• package.json dependencies:

  Click to expand

  "dependencies": {
  "elastic-apm-node": "^3.27.0",
  "pg": "^8.7.1",
  "axios" : "^0.25.0"
  }
  

[trentm]

theory: a race

If there are "inflight" spans being processed, then agent.flush() (which is called when the lambda invocation has completed) will not synchronously call apmclient.flush(). Currently that apmclient.flush() call sets a flag to say "don't unref your socket, because we are finishing up the intake request for this lambda invocation quickly".
With a delayed apmclient.flush(), there is an open time window during which an intake request can be started and get a socket for that request, before that "don't unref your socket" flag is set.

log shows we lost the race

The "First invocation" log in the description above (prettified with ecslog and trimmed) shows that this did happen:

...
 (elastic-apm-node): start trace {"trans":"0b0492f19ef7c917","trace":"8f687dc4c7633f5d6db2afceb4fa67db"...}
...
 (elastic-apm-node): intercepted call to pg.Client.prototype.query
 (elastic-apm-node): start span {"span":"1336391f1f7fb3bc"...}
2022-02-15 17:06:48.499 UTC [481] LOG:  statement: CREATE TABLE IF NOT EXISTS products (Id SERIAL PRIMARY KEY, Name varchar(255) NOT NULL, Description varchar(255) NOT NULL)
 (elastic-apm-node): intercepted end of pg.Client.prototype.query
 (elastic-apm-node): ended span {"span":"1336391f1f7fb3bc","name":"CREATE TABLE IF",...}
 (elastic-apm-node): encoding span {"span":"1336391f1f7fb3bc","name":"CREATE TABLE IF",...}
2022-02-15T17:06:48.542Z    0ca8d962-201b-4e94-a4b5-0585b955004e    INFO    Table created
 (elastic-apm-node): lambda: fn end
...
 (elastic-apm-node): sending transaction {"trans":"0b0492f19ef7c917","trace":"8f687dc4c7633f5d6db2afceb4fa67db"}
...
 (elastic-apm-node): intake request start
...
 (elastic-apm-node): intakeReq "socket": unref it
2022/02/15 17:06:49 Could not read bytes from agent request body
...

1. start trace: A trace/transaction was started.
2. start span: A span (for the pg client call) was started.
3. ended span, encoding span: The span ended and encoding it began.
   However, that span is "in flight" until we see a sending span.
4. lambda: fn end, sending transaction: The invocation completed, and the transaction was encoded and sent to the APM agent's "transport" to be sent to APM server. This synchronously calls agent.flush() which either synchronously or asynchronously (if there are inflight events) calls agent._transport.flush().
5. intake request start: The sent transaction initiates an intake request to APM Server.
6. There is now a race between agent._transport.flush() and that intake request getting a socket. In this example we lose the race: it takes 14ms from intake request start to intakeReq "socket": ...; the time to encode the span and send it is something longer (we would have seen sending span and _writeFlush log messages).

Q: Why did this not happen with Jean-Louis' other example that did not use pg.Pool?

[trentm]

Q: Why did this not happen with Jean-Louis' other example that did not use pg.Pool?

@jlvoiseux When you have a chance, could you please post the other lambda handler code (the one not using a pg.Pool and doing await pg.someCommand(...) a number of times)? If you have it handy, a ELASTIC_APM_LOG_LEVEL=trace log of the first invocation of that would be helpful.

[trentm]

@jlvoiseux So far I cannot repro. Here is my complete log of the docker-compose up: https://gist.github.com/trentm/fa22b1009fe7fcefb19072a4bfe27b65

1. I started docker-compose up and waited for the opbeans-lambda container to be ready: opbeans-lambda_1 | 2022-02-15 20:19:41 * Running on http://0.0.0.0:3000/ (Press CTRL+C to quit)
2. Then I called:

% time curl -i localhost:3000/itemsPool
HTTP/1.0 502 BAD GATEWAY
Content-Type: application/json
Content-Length: 36
Server: Werkzeug/1.0.1 Python/3.7.10
Date: Tue, 15 Feb 2022 20:20:01 GMT

{"message":"Internal server error"}
curl -i localhost:3000/itemsPool  0.01s user 0.01s system 0% cpu 12.152 total

Note that I am frequently getting a 10s timeout on my invocations:

opbeans-lambda_1  | 2022-02-15 20:20:01,735 | Function 'OpbeansLambdaItemsPool' timed out after 10 seconds

In the docker logs I see that the function is invoked fairly quickly, and it completes (the APM agent logs show a successful intake request and flush), then nothing happens for 7-8s until the timeout:

...
opbeans-lambda_1  | {"log.level":"trace","@timestamp":"2022-02-15T20:19:53.092Z",...,"message":"conclude intake request: success"}
opbeans-lambda_1  | {"log.level":"trace","@timestamp":"2022-02-15T20:19:53.093Z",...,"message":"lambda: flushed"}
...
opbeans-lambda_1  | END RequestId: b1c07dd8-f4b3-42cd-951c-64682c226d6e
opbeans-lambda_1  | REPORT RequestId: b1c07dd8-f4b3-42cd-951c-64682c226d6e	Init Duration: 0.11 ms	Duration: 10000.00 ms	Billed Duration: 10000 ms	Memory Size: 128 MB	Max Memory Used: 128 MB
opbeans-lambda_1  | 2022-02-15 20:20:01,735 | Function 'OpbeansLambdaItemsPool' timed out after 10 seconds

Perhaps this is expected in local testing (where there is no Logs API) and the APM agent isn't yet sending the ?flushed=true signal to the extension that it is done.

3. The APM agent log from run did not "lose the race" as your log showed.

I'll try to tweak the APM agent code so it is more likely to lose that race.

[trentm]

@jlvoiseux I can sort of reproduce, but not exactly the same way your log has shown, and I haven't been able to reproduce the case where the subsequent invocations of the function fail.

I think it would help me if you could repro on your end once or a few times with some changes I have made in a branch, and then post the complete log from docker-compose up.

1. Get the "trentm/issue2575-lambda-end-race" branch of opbeans-lambda (https://github.com/elastic/opbeans-lambda/compare/trentm/issue2575-lambda-end-race).
2. Clean up old samcli Docker containers like the ones below with docker ps -q | xargs docker kill

% docker ps
CONTAINER ID   IMAGE                                                       COMMAND                  CREATED       STATUS                            PORTS                                NAMES
98c486bcdecf   samcli/lambda:nodejs14.x-x86_64-7552d3bb22ef712e66294d115   "/var/rapid/aws-lamb…"   2 hours ago   Up 2 hours                        0.0.0.0:6580->8080/tcp               wizardly_beaver
3e657a00fb6f   samcli/lambda:nodejs14.x-x86_64-7552d3bb22ef712e66294d115   "/var/rapid/aws-lamb…"   2 hours ago   Up 2 hours                        0.0.0.0:7065->8080/tcp               focused_swirles
4e5cba454eb8   samcli/lambda:nodejs14.x-x86_64-7552d3bb22ef712e66294d115   "/var/rapid/aws-lamb…"   2 hours ago   Up 2 hours                        0.0.0.0:5598->8080/tcp               quirky_bassi
...

3. docker-compose up
4. When the opbeans-lambda server is ready, then time curl -i localhost:3000/itemsPool or whatever you have used to reproduce.

The "trentm/issue2575-lambda-end-race" branch includes some changes to:

• use a branch of the APM Node.js agent which adds some debug logging
• fixes the itemsPool response to be valid JSON to avoid the Invalid lambda response received: Lambda response must be valid json warning
• ensure that span.stacktrace is collected for the PG span to make it slower (more likely to hit the race)

Thanks!

[jlvoiseux]

@trentm Please find the requested execution logs here: https://gist.github.com/jlvoiseux/05c2bff3a7033896d7a624e766f880a6

These logs contain two calls to itemsPool, starting on line 539.

As an addendum, please also find logs generated by the execution of Opbeans Lambda (main branch) on a x86_64 Windows machine : https://gist.github.com/jlvoiseux/5e1d5f3f92ae7ad9da3a39bec4173e6e. I believe that the behavior is sensibly similar to the one that you reported in your first answer :

@jlvoiseux So far I cannot repro. Here is my complete log of the docker-compose up: https://gist.github.com/trentm/fa22b1009fe7fcefb19072a4bfe27b65

The two main differences that these behaviors exhibit wrt. the ones observed on my machine are:

• Absence of the Could not read bytes from agent request body error
• Subsequent invocations of the Lambda are not shortened/impaired

[trentm]

Thanks. Some notes:

I still don't understand what is happening on your M1 reproductions

opbeans-lambda_1  | {"log.level":"trace","@timestamp":"2022-02-16T18:23:44.165Z","log":{"logger":"elastic-apm-node"},"event.module":"apmclient","reqId":"0145826f65b95f03b0bbca0d68e680c3","ecs":{"version":"1.6.0"},"message":"intake request start"}
opbeans-lambda_1  | {"log.level":"trace","@timestamp":"2022-02-16T18:23:44.173Z","log":{"logger":"elastic-apm-node"},"event.module":"apmclient","fullTimeMs":25.02075,"numEvents":1,"numBytes":683,"ecs":{"version":"1.6.0"},"message":"_write: encode object"}
opbeans-lambda_1  | {"log.level":"trace","@timestamp":"2022-02-16T18:23:44.176Z","log":{"logger":"elastic-apm-node"},"event.module":"apmclient","reqId":"0145826f65b95f03b0bbca0d68e680c3","ecs":{"version":"1.6.0"},"message":"intakeReq \"socket\": unref it"}
opbeans-lambda_1  | 2022/02/16 18:23:44 Could not read bytes from agent request body
opbeans-lambda_1  | 2022-02-16 18:23:44,682 | Unable to find Click Context for getting session_id.
opbeans-lambda_1  | 2022-02-16 18:23:44,682 | Invalid lambda response received: Lambda response must be valid json
opbeans-lambda_1  | 2022-02-16 18:23:44 172.21.0.1 - - [16/Feb/2022 18:23:44] "GET /itemsPool HTTP/1.1" 502 -

Odd things here:

• The APM agent starts an intake request to the extension, and gets the socket connection. There isn't data available right away because it is a streaming request with compression that hasn't been flushed yet (because the span is still encoding). Why does the Go extension's ioutil.ReadAll() call error out somewhere between 0 and ~500ms after the socket is setup? I tweaked the Go extension to print the actual error:

--- a/apm-lambda-extension/extension/route_handlers.go
+++ b/apm-lambda-extension/extension/route_handlers.go
@@ -89,7 +89,7 @@ func handleIntakeV2Events(agentDataChan chan AgentData) func(w http.ResponseWrit
                rawBytes, err := ioutil.ReadAll(r.Body)
                defer r.Body.Close()
                if err != nil {
-                       log.Println("Could not read bytes from agent request body")
+                       log.Printf("Could not read agent intake request body: %v\n", err)
                        return
                }

and it prints: Could not read agent intake request body: unexpected EOF. I haven't chased that down in Go's stdlib. Is this somehow specific to something on your M1 Mac?

• Why does the span._encode never complete in your log? There should be a "sending span" log message, unless the process died silently, or the node.js process is wedged in some async task.

your Windows example

Your Windows/x86_64 example didn't hit the race. If you try with the "trentm/issue2575-lambda-end-race" branch, you might be more likely to hit the race there. But, don't bother at this point, I don't know that it'll be helpful.

next steps

• I don't grok what is happening in your repro case, and I think we may need to investigate that "why does io.ReadAll error out so quickly" at some point.
• For now, I believe I see a separate bug in the Node.js APM agent: the theory I mentioned above. I may look at this first.
• Also, I think I should implement the ?flushed=true call to signal the extension and then we should revisit the errors above. So I'll work on that ([META 569] Add query param flushed=true to final intake request at the end of lambda function #2485) first.

[trentm]

From @jlvoiseux's repro log in the issue description:

opbeans-lambda_1 | {"log.level":"trace","@timestamp":"2022-02-15T17:06:48.619Z","log":{"logger":"elastic-apm-node"},"event.module":"apmclient","reqId":"b0e4485922badf64df394dd84273ad8c","ecs":{"version":"1.6.0"},"message":"intakeReq "socket": unref it"}
opbeans-lambda_1 | 2022/02/15 17:06:49 Could not read bytes from agent request body

After having worked #2485 (and especially on the issue described at #2166 (comment)) I think it is a good chance that the premature "beforeExit" is relevant to this error. After the PRs for this issue are in, we can test again.

[trentm]

@jlvoiseux Would it be relatively easy for you to try to reproduce this with the latest extension ARN, latest (v3.30.0) APM agent version (using the ARN or an npm dep))?

[jlvoiseux]

@trentm Thanks for the heads-up ! I am now unable to reproduce, as the function ItemsPool.js now runs flawlessly. A log of the successful run is available here. All Lambda functions also run faster on SAM now, probably thanks to the implentation of flushed=true. Unless you had some follow-up in mind, I think that this issue can be closed.

[trentm]

@jlvoiseux Thanks! That is good news. Yes, let's close this. I don't think it would be a good use of time to dig into exactly what had been going on with the older agent and extension.