API Gateway makes duplicate lambda function calls

0

When a single Gateway API POST URL is hit, it seems that AWS will stack multiple calls using the same input to the target lambda.

As an example of what happened, the API was called four times: 11/01/2021 1:14:18,
11/01/2021 1:16:15, 11/01/2021 1:20:14, and then again a few second later at 1:20:56. These were combined
into one Cloudwatch log. Inside this log, the function during the 11/01/2021 1:14:18 was run once, the
1:16:15 called the function twice in immediate succession, the 1:20:14 called the function three times in immediate succession,
and the last one called the function four times in immediate succession:

Date/Time message
======== =======
11/01/2021 01:14:18 "START RequestId: ....899998 Version: 2
11/01/2021 01:14:19 "INFO:lambda_function:processing started
11/01/2021 01:14:19 "Other Processing lines....
11/01/2021 01:14:21 "INFO:lambda_function:processing ended
11/01/2021 01:14:21 "END RequestId: ....899998
11/01/2021 01:14:21 "REPORT RequestId: ....899998Duration: 2444.03 msBilled Duration: 2445 msMemory Size: 1024 MBMax Memory Used: 87 MBInit Duration: 567.65 ms

11/01/2021 01:16:15 "START RequestId: ....1234348 Version: 2
11/01/2021 01:16:16 "INFO:lambda_function:processing started
11/01/2021 01:16:16 "INFO:lambda_function:processing started
11/01/2021 01:16:16 "Other Processing lines....
11/01/2021 01:16:16 "Other Processing lines (Duplicated)
11/01/2021 01:16:18 "INFO:lambda_function:processing ended
11/01/2021 01:16:18 "INFO:lambda_function:processing ended
11/01/2021 01:16:18 "END RequestId: ....1234348
11/01/2021 01:16:18 "REPORT RequestId: ....1234348Duration: 3199.58 msBilled Duration: 3200 msMemory Size: 1024 MBMax Memory Used: 90 MB

11/01/2021 01:20:14 "START RequestId: ....a8fa9d6 Version: 2
11/01/2021 01:20:16 "INFO:lambda_function:processing started
11/01/2021 01:20:16 "INFO:lambda_function:processing started
11/01/2021 01:20:16 "INFO:lambda_function:processing started
11/01/2021 01:20:16 "Other Processing lines....
11/01/2021 01:20:16 "Other Processing lines (Duplicated)
11/01/2021 01:20:16 "Other Processing lines (Duplicated)
11/01/2021 01:20:17 "INFO:lambda_function:processing ended
11/01/2021 01:20:17 "INFO:lambda_function:processing ended
11/01/2021 01:20:17 "INFO:lambda_function:processing ended
11/01/2021 01:20:17 "END RequestId: ....a8fa9d6
11/01/2021 01:20:17 "REPORT RequestId: ....a8fa9d6Duration: 2419.70 msBilled Duration: 2420 msMemory Size: 1024 MBMax Memory Used: 92 MB

11/01/2021 01:20:55 "START RequestId: ....41d56e5 Version: 2
11/01/2021 01:20:56 "INFO:lambda_function:processing started
11/01/2021 01:20:56 "INFO:lambda_function:processing started
11/01/2021 01:20:56 "INFO:lambda_function:processing started
11/01/2021 01:20:56 "INFO:lambda_function:processing started
11/01/2021 01:20:56 "Other Processing lines....
11/01/2021 01:20:56 "Other Processing lines (Duplicated)
11/01/2021 01:20:56 "Other Processing lines (Duplicated)
11/01/2021 01:20:56 "Other Processing lines (Duplicated)
11/01/2021 01:20:57 "INFO:lambda_function:processing ended
11/01/2021 01:20:57 "INFO:lambda_function:processing ended
11/01/2021 01:20:57 "INFO:lambda_function:processing ended
11/01/2021 01:20:57 "INFO:lambda_function:processing ended
11/01/2021 01:20:57 "END RequestId: ....41d56e5
11/01/2021 01:20:57 "REPORT RequestId: ....41d56e5Duration: 2526.89 msBilled Duration: 2527 msMemory Size: 1024 MBMax Memory Used: 94 MB

I have no idea why this is happening. It's not as if the API call itself is being duplicated, as the API logs show as expected:
(4cfd8bbe-23a6-4c80-9d00-7f97e511f3e5) Extended Request Id: {TRUNCATED}
(4cfd8bbe-23a6-4c80-9d00-7f97e511f3e5) Verifying Usage Plan for request: {TRUNCATED}
(4cfd8bbe-23a6-4c80-9d00-7f97e511f3e5) Usage Plan check succeeded for API Key {TRUNCATED} and API Stage {TRUNCATED}
(4cfd8bbe-23a6-4c80-9d00-7f97e511f3e5) Starting execution for request: {TRUNCATED}
(4cfd8bbe-23a6-4c80-9d00-7f97e511f3e5) HTTP Method: POST, Resource Path: {TRUNCATED}
(4cfd8bbe-23a6-4c80-9d00-7f97e511f3e5) API Key: {TRUNCATED}
(4cfd8bbe-23a6-4c80-9d00-7f97e511f3e5) API Key ID: {TRUNCATED}
(4cfd8bbe-23a6-4c80-9d00-7f97e511f3e5) Method request path: {}
(4cfd8bbe-23a6-4c80-9d00-7f97e511f3e5) Method request query string: {}
(4cfd8bbe-23a6-4c80-9d00-7f97e511f3e5) Method request headers: {TRUNCATED}
(4cfd8bbe-23a6-4c80-9d00-7f97e511f3e5) Method request body before transformations: {TRUNCATED}
(4cfd8bbe-23a6-4c80-9d00-7f97e511f3e5) Endpoint request URI: {TRUNCATED}
(4cfd8bbe-23a6-4c80-9d00-7f97e511f3e5) Endpoint request headers: {TRUNCATED}
(4cfd8bbe-23a6-4c80-9d00-7f97e511f3e5) Endpoint request body after transformations: {TRUNCATED}
(4cfd8bbe-23a6-4c80-9d00-7f97e511f3e5) Sending request to {TRUNCATED}
(4cfd8bbe-23a6-4c80-9d00-7f97e511f3e5) Received response. Status: 200, Integration latency: 3457 ms
(4cfd8bbe-23a6-4c80-9d00-7f97e511f3e5) Endpoint response headers: {TRUNCATED}
(4cfd8bbe-23a6-4c80-9d00-7f97e511f3e5) Endpoint response body before transformations: {TRUNCATED}
(4cfd8bbe-23a6-4c80-9d00-7f97e511f3e5) Method response body after transformations: {TRUNCATED}
(4cfd8bbe-23a6-4c80-9d00-7f97e511f3e5) Method response headers: {X-Amzn-Trace-Id=Root={TRUNCATED};Sampled=0, Content-Type=application/json}
(4cfd8bbe-23a6-4c80-9d00-7f97e511f3e5) Successfully completed execution
(4cfd8bbe-23a6-4c80-9d00-7f97e511f3e5) Method completed with status: 200
(4cfd8bbe-23a6-4c80-9d00-7f97e511f3e5) AWS Integration Endpoint RequestId : {TRUNCATED}

Any help is most appreciated. Thank you very much.

Edited by: scopi on Nov 3, 2021 1:13 PM - Don't know why [TRUNCATED] came out as a link

scopi
asked 2 years ago1277 views
6 Answers
1

That is indeed weird.
Can you outline what your code is doing? E.g. are there relevant variables and functions initialized outside the handler function?
What do you do inside the handler function?

If you can play around and this doesn't happen in your production environment: can you strip everything from your code and basically only keep a console.log(event)? This would help exclude error factors and sources.

answered 2 years ago
0

Without seeing your code it is difficult to help.
I'd suggest adding some counter parameter or unique id to the request body.
Then log the complete event input so you can see what is happening with it.

answered 2 years ago
0

Thanks for the reply. I do log the event input, and for the duplicates, they are exactly the same. Between API calls, they are not, as expected. We do use a timestamp which acts (more or less) as a unique id as well.

scopi
answered 2 years ago
0

The code takes elastic search document ids that are in an array of the event input and processes them into new documents in elastic search. There are lambda variables defined in the Configuration/Environment Variables section of the lambda function, which are used as 'environment variables' to the function itself. But those are just passwords/logging level settings/etc. There are no other functions initialized outside the lambda code itself, although the function does call internal functions/classes/etc. as the code isn't all in just one function. (lambda handler creates instances of classes and calls methods on those classes). It is written in python 3.7 and the .py files are in different folders/etc. If there aren't any errors, the code finishes by returning a json object of an array of response/msg strings that are created during the execution. During the run in question, there were no exceptions so the code ran to completion each time.

Could it be I have to 'return' some statusCode (like 200) on completion instead of just a json object with whatever? If that were the case, though, then I would expect the 'duplication' behavior to be consistent, and it isn't.

This behavior does happen for both the prod API stage and dev API stage. Both stages call the same lambda function, although the dev stage/alias uses the $LATEST version while the prod stage/alias uses a numbered release version.

I'll look into just logging the event line and basically doing nothing else.

Thanks again!

scopi
answered 2 years ago
0

Great suggestion to strip everything and just keep a log event! When I did that, the problem went away.

What I found out was the lambda function wasn't being called multiple times. The custom logger I use to output to elastic and the standard output was not being closed in the code, and so when the lambda ran again, it used that logger plus the new logger of the current run, etc. and stacked the output until cloudwatch used a new log file. I added code to close the custom log handlers and the problem is gone.

Thanks, Eric! Very much appreciated.

scopi
answered 2 years ago
0

I had similar issues with Lambda when I went serverless for the first time.
Anyhow, I'm glad I could help.

answered 2 years ago

You are not logged in. Log in to post an answer.

A good answer clearly answers the question and provides constructive feedback and encourages professional growth in the question asker.

Guidelines for Answering Questions