aws-cli icon indicating copy to clipboard operation
aws-cli copied to clipboard
verified publisher icon aws

aws lambda invoke does not complete

Open yogeshlonkar opened this issue 5 years ago • 13 comments

Describe the bug aws lambda invoke command does not complete even though the lambda run has completed successfully

SDK version number

aws --version
aws-cli/2.1.6 Python/3.7.3 Linux/4.14.200-116.320.amzn1.x86_64 exe/x86_64.debian.9 prompt/off

Platform/OS/Hardware/Device Inside debian container running on AWS t3.2xlarge/Amazon Linux

To Reproduce (observed behavior)

  • Lambda with runtime more than 7 minutes
  • aws --debug lambda invoke --cli-read-timeout 0 --cli-connect-timeout 0 --function-name lambda_name --invocation-type RequestResponse output.log

Expected behavior cli to complete after lambda execution is done

Logs/output

  • Command debug log
2020-12-04 10:06:08,353 - MainThread - awscli.clidriver - DEBUG - CLI version: aws-cli/2.1.6 Python/3.7.3 Linux/4.14.200-116.320.amzn1.x86_64 exe/x86_64.debian.9
2020-12-04 10:06:08,353 - MainThread - awscli.clidriver - DEBUG - Arguments entered to CLI: ['--debug', 'lambda', 'invoke', '--cli-read-timeout', '0', '--cli-connect-timeout', '0', '--function-name', '****', '--invocation-type', 'RequestResponse', 'output.log']
2020-12-04 10:06:08,365 - MainThread - botocore.hooks - DEBUG - Event building-command-table.main: calling handler <function add_s3 at 0x7f8adf55b1e0>
2020-12-04 10:06:08,365 - MainThread - botocore.hooks - DEBUG - Event building-command-table.main: calling handler <function add_ddb at 0x7f8adf6d7d08>
2020-12-04 10:06:08,365 - MainThread - botocore.hooks - DEBUG - Event building-command-table.main: calling handler <bound method BasicCommand.add_command of <class 'awscli.customizations.configure.configure.ConfigureCommand'>>
2020-12-04 10:06:08,365 - MainThread - botocore.hooks - DEBUG - Event building-command-table.main: calling handler <function change_name at 0x7f8adf7048c8>
2020-12-04 10:06:08,365 - MainThread - botocore.hooks - DEBUG - Event building-command-table.main: calling handler <function change_name at 0x7f8adf70c8c8>
2020-12-04 10:06:08,366 - MainThread - botocore.hooks - DEBUG - Event building-command-table.main: calling handler <function alias_opsworks_cm at 0x7f8adf4ec8c8>
2020-12-04 10:06:08,366 - MainThread - botocore.hooks - DEBUG - Event building-command-table.main: calling handler <function add_history_commands at 0x7f8adf6a5400>
2020-12-04 10:06:08,366 - MainThread - botocore.hooks - DEBUG - Event building-command-table.main: calling handler <bound method BasicCommand.add_command of <class 'awscli.customizations.devcommands.CLIDevCommand'>>
2020-12-04 10:06:08,366 - MainThread - botocore.hooks - DEBUG - Event building-command-table.main: calling handler <function add_waiters at 0x7f8adf561b70>
2020-12-04 10:06:08,366 - MainThread - botocore.loaders - DEBUG - Loading JSON file: /usr/local/aws-cli/v2/2.1.6/dist/awscli/data/cli.json
2020-12-04 10:06:08,370 - MainThread - botocore.hooks - DEBUG - Event top-level-args-parsed: calling handler <function resolve_types at 0x7f8adf5cb400>
2020-12-04 10:06:08,370 - MainThread - botocore.hooks - DEBUG - Event top-level-args-parsed: calling handler <function no_sign_request at 0x7f8adf5cb6a8>
2020-12-04 10:06:08,370 - MainThread - botocore.hooks - DEBUG - Event top-level-args-parsed: calling handler <function resolve_verify_ssl at 0x7f8adf5cb620>
2020-12-04 10:06:08,370 - MainThread - botocore.hooks - DEBUG - Event top-level-args-parsed: calling handler <function resolve_cli_read_timeout at 0x7f8adf5cb7b8>
2020-12-04 10:06:08,370 - MainThread - botocore.hooks - DEBUG - Event top-level-args-parsed: calling handler <function resolve_cli_connect_timeout at 0x7f8adf5cb730>
2020-12-04 10:06:08,371 - MainThread - botocore.hooks - DEBUG - Event top-level-args-parsed: calling handler <built-in method update of dict object at 0x7f8adf4df828>
2020-12-04 10:06:08,371 - MainThread - awscli.clidriver - DEBUG - CLI version: aws-cli/2.1.6 Python/3.7.3 Linux/4.14.200-116.320.amzn1.x86_64 exe/x86_64.debian.9 prompt/off
2020-12-04 10:06:08,371 - MainThread - awscli.clidriver - DEBUG - Arguments entered to CLI: ['--debug', 'lambda', 'invoke', '--cli-read-timeout', '0', '--cli-connect-timeout', '0', '--function-name', '****', '--invocation-type', 'RequestResponse', 'output.log']
2020-12-04 10:06:08,371 - MainThread - botocore.hooks - DEBUG - Event session-initialized: calling handler <function add_timestamp_parser at 0x7f8adf55b730>
2020-12-04 10:06:08,371 - MainThread - botocore.hooks - DEBUG - Event session-initialized: calling handler <function register_uri_param_handler at 0x7f8adfafb400>
2020-12-04 10:06:08,372 - MainThread - botocore.hooks - DEBUG - Event session-initialized: calling handler <function add_binary_formatter at 0x7f8adf51b488>
2020-12-04 10:06:08,372 - MainThread - botocore.hooks - DEBUG - Event session-initialized: calling handler <function no_pager_handler at 0x7f8adfaf4ae8>
2020-12-04 10:06:08,372 - MainThread - botocore.hooks - DEBUG - Event session-initialized: calling handler <function inject_assume_role_provider_cache at 0x7f8adfadd9d8>
2020-12-04 10:06:08,373 - MainThread - botocore.utils - DEBUG - IMDS ENDPOINT: http://169.254.169.254/
2020-12-04 10:06:08,375 - MainThread - botocore.hooks - DEBUG - Event session-initialized: calling handler <function attach_history_handler at 0x7f8adf6a52f0>
2020-12-04 10:06:08,375 - MainThread - botocore.hooks - DEBUG - Event session-initialized: calling handler <function inject_json_file_cache at 0x7f8adf6d4c80>
2020-12-04 10:06:08,386 - MainThread - botocore.loaders - DEBUG - Loading JSON file: /usr/local/aws-cli/v2/2.1.6/dist/botocore/data/lambda/2015-03-31/service-2.json
2020-12-04 10:06:08,401 - MainThread - botocore.hooks - DEBUG - Event building-command-table.lambda: calling handler <function _add_wizard_command at 0x7f8adf51b400>
2020-12-04 10:06:08,401 - MainThread - botocore.hooks - DEBUG - Event building-command-table.lambda: calling handler <function add_waiters at 0x7f8adf561b70>
2020-12-04 10:06:08,414 - MainThread - botocore.loaders - DEBUG - Loading JSON file: /usr/local/aws-cli/v2/2.1.6/dist/botocore/data/lambda/2015-03-31/waiters-2.json
2020-12-04 10:06:08,415 - MainThread - awscli.clidriver - DEBUG - OrderedDict([('function-name', <awscli.arguments.CLIArgument object at 0x7f8adf27f2e8>), ('invocation-type', <awscli.arguments.CLIArgument object at 0x7f8adf28a710>), ('log-type', <awscli.arguments.CLIArgument object at 0x7f8adf28a748>), ('client-context', <awscli.arguments.CLIArgument object at 0x7f8adf28a828>), ('payload', <awscli.arguments.CLIArgument object at 0x7f8adf28a8d0>), ('qualifier', <awscli.arguments.CLIArgument object at 0x7f8adf28a898>)])
2020-12-04 10:06:08,415 - MainThread - botocore.hooks - DEBUG - Event building-argument-table.lambda.invoke: calling handler <function add_streaming_output_arg at 0x7f8adf55b9d8>
2020-12-04 10:06:08,416 - MainThread - botocore.hooks - DEBUG - Event building-argument-table.lambda.invoke: calling handler <function add_cli_input_json at 0x7f8adfae5268>
2020-12-04 10:06:08,416 - MainThread - botocore.hooks - DEBUG - Event building-argument-table.lambda.invoke: calling handler <function add_cli_input_yaml at 0x7f8adfae58c8>
2020-12-04 10:06:08,416 - MainThread - botocore.hooks - DEBUG - Event building-argument-table.lambda.invoke: calling handler <function unify_paging_params at 0x7f8adf6e3400>
2020-12-04 10:06:08,428 - MainThread - botocore.loaders - DEBUG - Loading JSON file: /usr/local/aws-cli/v2/2.1.6/dist/botocore/data/lambda/2015-03-31/paginators-1.json
2020-12-04 10:06:08,428 - MainThread - botocore.hooks - DEBUG - Event building-argument-table.lambda.invoke: calling handler <function add_generate_skeleton at 0x7f8adf5c7158>
2020-12-04 10:06:08,430 - MainThread - botocore.hooks - DEBUG - Event load-cli-arg.lambda.invoke.function-name: calling handler <awscli.paramfile.URIArgumentHandler object at 0x7f8adf42ab38>
2020-12-04 10:06:08,430 - MainThread - botocore.hooks - DEBUG - Event process-cli-arg.lambda.invoke: calling handler <awscli.argprocess.ParamShorthandParser object at 0x7f8adfb21518>
2020-12-04 10:06:08,430 - MainThread - awscli.arguments - DEBUG - Unpacked value of '****' for parameter "function_name": '****'
2020-12-04 10:06:08,430 - MainThread - botocore.hooks - DEBUG - Event load-cli-arg.lambda.invoke.invocation-type: calling handler <awscli.paramfile.URIArgumentHandler object at 0x7f8adf42ab38>
2020-12-04 10:06:08,430 - MainThread - botocore.hooks - DEBUG - Event process-cli-arg.lambda.invoke: calling handler <awscli.argprocess.ParamShorthandParser object at 0x7f8adfb21518>
2020-12-04 10:06:08,430 - MainThread - awscli.arguments - DEBUG - Unpacked value of 'RequestResponse' for parameter "invocation_type": 'RequestResponse'
2020-12-04 10:06:08,430 - MainThread - botocore.hooks - DEBUG - Event load-cli-arg.lambda.invoke.log-type: calling handler <awscli.paramfile.URIArgumentHandler object at 0x7f8adf42ab38>
2020-12-04 10:06:08,430 - MainThread - botocore.hooks - DEBUG - Event load-cli-arg.lambda.invoke.client-context: calling handler <awscli.paramfile.URIArgumentHandler object at 0x7f8adf42ab38>
2020-12-04 10:06:08,431 - MainThread - botocore.hooks - DEBUG - Event load-cli-arg.lambda.invoke.payload: calling handler <awscli.paramfile.URIArgumentHandler object at 0x7f8adf42ab38>
2020-12-04 10:06:08,431 - MainThread - botocore.hooks - DEBUG - Event load-cli-arg.lambda.invoke.qualifier: calling handler <awscli.paramfile.URIArgumentHandler object at 0x7f8adf42ab38>
2020-12-04 10:06:08,431 - MainThread - botocore.hooks - DEBUG - Event load-cli-arg.lambda.invoke.outfile: calling handler <awscli.paramfile.URIArgumentHandler object at 0x7f8adf42ab38>
2020-12-04 10:06:08,431 - MainThread - botocore.utils - DEBUG - IMDS ENDPOINT: http://169.254.169.254/
2020-12-04 10:06:08,433 - MainThread - urllib3.connectionpool - DEBUG - Starting new HTTP connection (1): 169.254.169.254:80
2020-12-04 10:06:09,436 - MainThread - urllib3.connectionpool - DEBUG - Starting new HTTP connection (2): 169.254.169.254:80
2020-12-04 10:06:09,437 - MainThread - urllib3.connectionpool - DEBUG - http://169.254.169.254:80 "GET /latest/meta-data/placement/availability-zone/ HTTP/1.1" 200 13
2020-12-04 10:06:09,439 - MainThread - botocore.credentials - DEBUG - Looking for credentials via: env
2020-12-04 10:06:09,439 - MainThread - botocore.credentials - INFO - Found credentials in environment variables.
2020-12-04 10:06:09,440 - MainThread - botocore.loaders - DEBUG - Loading JSON file: /usr/local/aws-cli/v2/2.1.6/dist/botocore/data/endpoints.json
2020-12-04 10:06:09,449 - MainThread - botocore.hooks - DEBUG - Event choose-service-name: calling handler <function handle_service_name_alias at 0x7f8ae0f01620>
2020-12-04 10:06:09,453 - MainThread - botocore.hooks - DEBUG - Event creating-client-class.lambda: calling handler <function add_generate_presigned_url at 0x7f8ae0f37a60>
2020-12-04 10:06:09,459 - MainThread - botocore.endpoint - DEBUG - Setting lambda timeout as (None, None)
2020-12-04 10:06:09,461 - MainThread - botocore.hooks - DEBUG - Event provide-client-params.lambda.Invoke: calling handler <function base64_decode_input_blobs at 0x7f8adf51bb70>
2020-12-04 10:06:09,461 - MainThread - botocore.hooks - DEBUG - Event before-parameter-build.lambda.Invoke: calling handler <function generate_idempotent_uuid at 0x7f8ae0ea3488>
2020-12-04 10:06:09,462 - MainThread - botocore.hooks - DEBUG - Event before-call.lambda.Invoke: calling handler <function inject_api_version_header_if_needed at 0x7f8ae0ea7bf8>
2020-12-04 10:06:09,462 - MainThread - botocore.endpoint - DEBUG - Making request for OperationModel(name=Invoke) with params: {'url_path': '/2015-03-31/functions/****/invocations', 'query_string': {}, 'method': 'POST', 'headers': {'X-Amz-Invocation-Type': 'RequestResponse', 'User-Agent': 'aws-cli/2.1.6 Python/3.7.3 Linux/4.14.200-116.320.amzn1.x86_64 exe/x86_64.debian.9 prompt/off command/lambda.invoke'}, 'body': b'', 'url': 'https://lambda.eu-central-1.amazonaws.com/2015-03-31/functions/****/invocations', 'context': {'client_region': 'eu-central-1', 'client_config': <botocore.config.Config object at 0x7f8adefeecf8>, 'has_streaming_input': True, 'auth_type': None}}
2020-12-04 10:06:09,463 - MainThread - botocore.hooks - DEBUG - Event request-created.lambda.Invoke: calling handler <bound method RequestSigner.handler of <botocore.signers.RequestSigner object at 0x7f8adefeec88>>
2020-12-04 10:06:09,463 - MainThread - botocore.hooks - DEBUG - Event choose-signer.lambda.Invoke: calling handler <function set_operation_specific_signer at 0x7f8ae0ea3378>
2020-12-04 10:06:09,464 - MainThread - botocore.auth - DEBUG - Calculating signature using v4 auth.
2020-12-04 10:06:09,464 - MainThread - botocore.auth - DEBUG - CanonicalRequest:
POST
/2015-03-31/functions/****/invocations

host:lambda.eu-central-1.amazonaws.com
x-amz-date:20201204T100609Z
x-amz-invocation-type:RequestResponse
x-amz-security-token:****

host;x-amz-date;x-amz-invocation-type;x-amz-security-token
e3b0c44298fc1c149afbf4c8996fb92427ae41e4649b934ca495991b7852b855
2020-12-04 10:06:09,464 - MainThread - botocore.auth - DEBUG - StringToSign:
AWS4-HMAC-SHA256
20201204T100609Z
20201204/eu-central-1/lambda/aws4_request
c655785ab919c6cba65f96b1a4a7e87915bf0d3798ef04326fbe4de6f0daa43e
2020-12-04 10:06:09,464 - MainThread - botocore.auth - DEBUG - Signature:
6f1f4c51328de9e5bd5fe6dda15c05613f8a98e54373907c1b8256332cd94b3f
2020-12-04 10:06:09,464 - MainThread - botocore.endpoint - DEBUG - Sending http request: <AWSPreparedRequest stream_output=True, method=POST, url=https://lambda.eu-central-1.amazonaws.com/2015-03-31/functions/****/invocations, headers={'X-Amz-Invocation-Type': b'RequestResponse', 'User-Agent': b'aws-cli/2.1.6 Python/3.7.3 Linux/4.14.200-116.320.amzn1.x86_64 exe/x86_64.debian.9 prompt/off command/lambda.invoke', 'X-Amz-Date': b'20201204T100609Z', 'X-Amz-Security-Token': b'****', 'Authorization': b'AWS4-HMAC-SHA256 Credential=ASIAY7KECBSOOHYOLANB/20201204/eu-central-1/lambda/aws4_request, SignedHeaders=host;x-amz-date;x-amz-invocation-type;x-amz-security-token, Signature=6f1f4c51328de9e5bd5fe6dda15c05613f8a98e54373907c1b8256332cd94b3f', 'Content-Length': '0'}>
2020-12-04 10:06:09,465 - MainThread - urllib3.connectionpool - DEBUG - Starting new HTTPS connection (1): lambda.eu-central-1.amazonaws.com:443
  • Lambda CloudWatch Logs image 
REPORT RequestId: 519d7462-6fe5-4bb7-8abe-88648d78c61d	Duration: 535808.12 ms	Billed Duration: 535809 ms	Memory Size: 1024 MB	Max Memory Used: 98 MB	Init Duration: 133.51 ms

Additional context The same command runs perfectly on macOS

yogeshlonkar avatar Dec 04 '20 10:12 yogeshlonkar

Hi @yogeshlonkar,

Thanks for posting. The docs for the aws lambda invoke mention that this is a potential issue:

For functions with a long timeout, your client might be disconnected during synchronous invocation while it waits for a response. Configure your HTTP client, SDK, firewall, proxy, or operating system to allow for long connections with timeout or keep-alive settings.

Since this works on Mac (where I tested as well) and not on your Amazon Linux instance (or the container), I imagine it is an OS or container issue.

kdaily avatar Dec 07 '20 20:12 kdaily

I'm going to look into this some more. I tried it again on my Mac, and it did not exit as expected when the Lambda finished.

kdaily avatar Dec 07 '20 20:12 kdaily

Sending an interrupt shows this:

^C2020-12-07 14:45:06,778 - MainThread - awscli.clidriver - DEBUG - Exception caught in main()
Traceback (most recent call last):
  File "awscli/clidriver.py", line 457, in main
  File "awscli/clidriver.py", line 586, in __call__
  File "awscli/clidriver.py", line 765, in __call__
  File "awscli/clidriver.py", line 894, in invoke
  File "awscli/clidriver.py", line 906, in _make_client_call
  File "botocore/client.py", line 249, in _api_call
  File "botocore/client.py", line 555, in _make_api_call
  File "botocore/client.py", line 574, in _make_request
  File "botocore/endpoint.py", line 102, in make_request
  File "botocore/endpoint.py", line 135, in _send_request
  File "botocore/endpoint.py", line 167, in _get_response
  File "botocore/endpoint.py", line 200, in _do_get_response
  File "botocore/endpoint.py", line 269, in _send
  File "botocore/httpsession.py", line 263, in send
  File "urllib3/connectionpool.py", line 706, in urlopen
  File "urllib3/connectionpool.py", line 445, in _make_request
  File "<string>", line 3, in raise_from
  File "urllib3/connectionpool.py", line 440, in _make_request
  File "http/client.py", line 1336, in getresponse
  File "http/client.py", line 306, in begin
  File "http/client.py", line 267, in _read_status
  File "socket.py", line 589, in readinto
  File "ssl.py", line 1071, in recv_into
  File "ssl.py", line 929, in read
KeyboardInterrupt

kdaily avatar Dec 07 '20 22:12 kdaily

I'm still trying to determine if this is on the Python SDK/CLI or Lambda side of things by trying it in the AWS SDK for JavaScript.

There is this Knowledge Base article which discusses strategies for this type of issue:

https://aws.amazon.com/premiumsupport/knowledge-center/lambda-function-retry-timeout-sdk/

I think we're doing the right thing here, based on this statement:

To fix the retry and timeout issues, review the logs of the API call to find the problem. Then, change the retry count and timeout settings of the SDK as needed for each use case. To allow enough time for a response to the API call, add time to the Lambda function timeout setting.

We can't review the logs of the API call, because it's not returning. We have adjusted the timeout settings of the API call (to infinity in our case), and the Lambda function timeout setting to the maximum.

This 4-year old Stack Overflow post hints at the same thing (with the same solution), which isn't working here.

https://stackoverflow.com/questions/36648377/aws-lambda-invoke-function-doesnt-always-return

kdaily avatar Dec 09 '20 21:12 kdaily

Hi @yogeshlonkar,

Could you try to enable the CLI to use keep alive packets?

https://docs.aws.amazon.com/credref/latest/refdocs/setting-global-tcp_keepalive.html

You have to do this within your AWS CLI config file - it's not available through an environment variable or a command line parameter. If you're using the default profile, it will look something like:

[default]
tcp_keepalive = true

kdaily avatar Dec 09 '20 23:12 kdaily

@kdaily tried it but doesn't change the behavior, command keeps running. Had to terminate after 30 minutes each time

yogeshlonkar avatar Dec 10 '20 10:12 yogeshlonkar

Long story short - I think this is a bug of some sort that we'll look at, but I want to see if there's a way that I can keep you moving. You may need to adjust your TCP keep alive settings, which are OS-specific. This shows how to make changes at the OS level, so proceed with caution. I did not test how this would work inside a container, as the connection from inside to outside the container may work differently or have different settings.

I'm able to rescue using the TCP keep alive, but only if I change my operating system's settings to a lower interval. I followed this guide (external link):

http://coryklein.com/tcp/2015/11/25/custom-configuration-of-tcp-socket-keep-alive-timeouts.html

On my Mac (Catalina), I changed them to:

$ sudo sysctl -w net.inet.tcp.keepidle=180000 net.inet.tcp.keepcnt=3 net.inet.tcp.keepintvl=10000
$ sysctl net.inet.tcp | grep -E "keepidle|keepintvl|keepcnt"
net.inet.tcp.keepidle: 180000
net.inet.tcp.keepintvl: 10000
net.inet.tcp.keepcnt: 3

While running the aws lambda invoke command, in another terminal I used tcpdump to assert that the keep alives were being sent:

sudo tcpdump port 443 and host lambda.us-west-2.amazonaws.com

The default keep alive settings on my Mac were:

$ sysctl net.inet.tcp | grep -E "keepidle|keepintvl|keepcnt"
net.inet.tcp.keepidle: 720000
net.inet.tcp.keepintvl: 75000
net.inet.tcp.keepcnt: 8

If I waited long enough, it would finally timeout, but only with the TCP keep alive on:

time aws2 --debug lambda invoke --cli-read-timeout 0 --cli-connect-timeout 0 --function-name aws-cli-issue-5783 output.log --payload fileb://payload.json
2020-12-10 07:08:39,623 - MainThread - awscli.clidriver - DEBUG - CLI version: aws-cli/2.1.6 Python/3.7.4 Darwin/19.6.0 exe/x86_64
2020-12-10 07:08:39,623 - MainThread - awscli.clidriver - DEBUG - Arguments entered to CLI: ['--debug', 'lambda', 'invoke', '--cli-read-timeout', '0', '--cli-connect-timeout', '0', '--function-name', 'aws-cli-issue-5783', 'output.log', '--payload', 'fileb://payload.json']
2020-12-10 07:08:39,680 - MainThread - botocore.hooks - DEBUG - Event building-command-table.main: calling handler <function add_s3 at 0x7ff2b1774f80>
2020-12-10 07:08:39,681 - MainThread - botocore.hooks - DEBUG - Event building-command-table.main: calling handler <function add_ddb at 0x7ff2b163d7a0>
2020-12-10 07:08:39,681 - MainThread - botocore.hooks - DEBUG - Event building-command-table.main: calling handler <bound method BasicCommand.add_command of <class 'awscli.customizations.configure.configure.ConfigureCommand'>>
2020-12-10 07:08:39,681 - MainThread - botocore.hooks - DEBUG - Event building-command-table.main: calling handler <function change_name at 0x7ff2b15e4200>
2020-12-10 07:08:39,681 - MainThread - botocore.hooks - DEBUG - Event building-command-table.main: calling handler <function change_name at 0x7ff2b15e97a0>
2020-12-10 07:08:39,681 - MainThread - botocore.hooks - DEBUG - Event building-command-table.main: calling handler <function alias_opsworks_cm at 0x7ff2b17e94d0>
2020-12-10 07:08:39,681 - MainThread - botocore.hooks - DEBUG - Event building-command-table.main: calling handler <function add_history_commands at 0x7ff2b168a710>
2020-12-10 07:08:39,681 - MainThread - botocore.hooks - DEBUG - Event building-command-table.main: calling handler <bound method BasicCommand.add_command of <class 'awscli.customizations.devcommands.CLIDevCommand'>>
2020-12-10 07:08:39,681 - MainThread - botocore.hooks - DEBUG - Event building-command-table.main: calling handler <function add_waiters at 0x7ff2b17e95f0>
2020-12-10 07:08:39,682 - MainThread - botocore.loaders - DEBUG - Loading JSON file: /Users/kdaily/aws-cli/awscli/data/cli.json
2020-12-10 07:08:39,686 - MainThread - botocore.hooks - DEBUG - Event top-level-args-parsed: calling handler <function resolve_types at 0x7ff2b17420e0>
2020-12-10 07:08:39,686 - MainThread - botocore.hooks - DEBUG - Event top-level-args-parsed: calling handler <function no_sign_request at 0x7ff2b17423b0>
2020-12-10 07:08:39,686 - MainThread - botocore.hooks - DEBUG - Event top-level-args-parsed: calling handler <function resolve_verify_ssl at 0x7ff2b1742320>
2020-12-10 07:08:39,686 - MainThread - botocore.hooks - DEBUG - Event top-level-args-parsed: calling handler <function resolve_cli_read_timeout at 0x7ff2b17424d0>
2020-12-10 07:08:39,686 - MainThread - botocore.hooks - DEBUG - Event top-level-args-parsed: calling handler <function resolve_cli_connect_timeout at 0x7ff2b1742440>
2020-12-10 07:08:39,686 - MainThread - botocore.hooks - DEBUG - Event top-level-args-parsed: calling handler <built-in method update of dict object at 0x7ff2b196c960>
2020-12-10 07:08:39,687 - MainThread - awscli.clidriver - DEBUG - CLI version: aws-cli/2.1.6 Python/3.7.4 Darwin/19.6.0 exe/x86_64 prompt/off
2020-12-10 07:08:39,687 - MainThread - awscli.clidriver - DEBUG - Arguments entered to CLI: ['--debug', 'lambda', 'invoke', '--cli-read-timeout', '0', '--cli-connect-timeout', '0', '--function-name', 'aws-cli-issue-5783', 'output.log', '--payload', 'fileb://payload.json']
2020-12-10 07:08:39,687 - MainThread - botocore.hooks - DEBUG - Event session-initialized: calling handler <function add_timestamp_parser at 0x7ff2b17db950>
2020-12-10 07:08:39,687 - MainThread - botocore.hooks - DEBUG - Event session-initialized: calling handler <function register_uri_param_handler at 0x7ff2b13e98c0>
2020-12-10 07:08:39,687 - MainThread - botocore.hooks - DEBUG - Event session-initialized: calling handler <function add_binary_formatter at 0x7ff2b1921f80>
2020-12-10 07:08:39,687 - MainThread - botocore.hooks - DEBUG - Event session-initialized: calling handler <function no_pager_handler at 0x7ff2b1396200>
2020-12-10 07:08:39,687 - MainThread - botocore.hooks - DEBUG - Event session-initialized: calling handler <function inject_assume_role_provider_cache at 0x7ff2b1414e60>
2020-12-10 07:08:39,688 - MainThread - botocore.utils - DEBUG - IMDS ENDPOINT: http://169.254.169.254/
2020-12-10 07:08:39,693 - MainThread - botocore.hooks - DEBUG - Event session-initialized: calling handler <function attach_history_handler at 0x7ff2b168a7a0>
2020-12-10 07:08:39,694 - MainThread - awscli.customizations.history - DEBUG - Enabling CLI history
2020-12-10 07:08:39,697 - MainThread - botocore.hooks - DEBUG - Event session-initialized: calling handler <function inject_json_file_cache at 0x7ff2b162bd40>
2020-12-10 07:08:39,720 - MainThread - botocore.loaders - DEBUG - Loading JSON file: /Users/kdaily/aws-cli/botocore/data/lambda/2015-03-31/service-2.json
2020-12-10 07:08:39,730 - MainThread - botocore.hooks - DEBUG - Event building-command-table.lambda: calling handler <function _add_wizard_command at 0x7ff2b191ee60>
2020-12-10 07:08:39,730 - MainThread - botocore.hooks - DEBUG - Event building-command-table.lambda: calling handler <function add_waiters at 0x7ff2b17e95f0>
2020-12-10 07:08:39,752 - MainThread - botocore.loaders - DEBUG - Loading JSON file: /Users/kdaily/aws-cli/botocore/data/lambda/2015-03-31/waiters-2.json
2020-12-10 07:08:39,753 - MainThread - awscli.clidriver - DEBUG - OrderedDict([('function-name', <awscli.arguments.CLIArgument object at 0x7ff2b1b78b10>), ('invocation-type', <awscli.arguments.CLIArgument object at 0x7ff2b1b78c90>), ('log-type', <awscli.arguments.CLIArgument object at 0x7ff2b1b78d90>), ('client-context', <awscli.arguments.CLIArgument object at 0x7ff2b1b78e10>), ('payload', <awscli.arguments.CLIArgument object at 0x7ff2b1b78dd0>), ('qualifier', <awscli.arguments.CLIArgument object at 0x7ff2b1b78e90>)])
2020-12-10 07:08:39,753 - MainThread - botocore.hooks - DEBUG - Event building-argument-table.lambda.invoke: calling handler <function add_streaming_output_arg at 0x7ff2b17dfb00>
2020-12-10 07:08:39,753 - MainThread - botocore.hooks - DEBUG - Event building-argument-table.lambda.invoke: calling handler <function add_cli_input_json at 0x7ff2b141d8c0>
2020-12-10 07:08:39,753 - MainThread - botocore.hooks - DEBUG - Event building-argument-table.lambda.invoke: calling handler <function add_cli_input_yaml at 0x7ff2b141db00>
2020-12-10 07:08:39,753 - MainThread - botocore.hooks - DEBUG - Event building-argument-table.lambda.invoke: calling handler <function unify_paging_params at 0x7ff2b1647a70>
2020-12-10 07:08:39,774 - MainThread - botocore.loaders - DEBUG - Loading JSON file: /Users/kdaily/aws-cli/botocore/data/lambda/2015-03-31/paginators-1.json
2020-12-10 07:08:39,774 - MainThread - botocore.hooks - DEBUG - Event building-argument-table.lambda.invoke: calling handler <function add_generate_skeleton at 0x7ff2b173bb00>
2020-12-10 07:08:39,775 - MainThread - botocore.hooks - DEBUG - Event load-cli-arg.lambda.invoke.function-name: calling handler <awscli.paramfile.URIArgumentHandler object at 0x7ff2b19b8990>
2020-12-10 07:08:39,775 - MainThread - botocore.hooks - DEBUG - Event process-cli-arg.lambda.invoke: calling handler <awscli.argprocess.ParamShorthandParser object at 0x7ff2b13e0910>
2020-12-10 07:08:39,775 - MainThread - awscli.arguments - DEBUG - Unpacked value of 'aws-cli-issue-5783' for parameter "function_name": 'aws-cli-issue-5783'
2020-12-10 07:08:39,775 - MainThread - botocore.hooks - DEBUG - Event load-cli-arg.lambda.invoke.invocation-type: calling handler <awscli.paramfile.URIArgumentHandler object at 0x7ff2b19b8990>
2020-12-10 07:08:39,775 - MainThread - botocore.hooks - DEBUG - Event load-cli-arg.lambda.invoke.log-type: calling handler <awscli.paramfile.URIArgumentHandler object at 0x7ff2b19b8990>
2020-12-10 07:08:39,775 - MainThread - botocore.hooks - DEBUG - Event load-cli-arg.lambda.invoke.client-context: calling handler <awscli.paramfile.URIArgumentHandler object at 0x7ff2b19b8990>
2020-12-10 07:08:39,775 - MainThread - botocore.hooks - DEBUG - Event load-cli-arg.lambda.invoke.payload: calling handler <awscli.paramfile.URIArgumentHandler object at 0x7ff2b19b8990>
2020-12-10 07:08:39,776 - MainThread - botocore.hooks - DEBUG - Event process-cli-arg.lambda.invoke: calling handler <awscli.argprocess.ParamShorthandParser object at 0x7ff2b13e0910>
2020-12-10 07:08:39,776 - MainThread - awscli.arguments - DEBUG - Unpacked value of b'{"delay": 450}\n' for parameter "payload": b'{"delay": 450}\n'
2020-12-10 07:08:39,776 - MainThread - botocore.hooks - DEBUG - Event load-cli-arg.lambda.invoke.qualifier: calling handler <awscli.paramfile.URIArgumentHandler object at 0x7ff2b19b8990>
2020-12-10 07:08:39,776 - MainThread - botocore.hooks - DEBUG - Event load-cli-arg.lambda.invoke.outfile: calling handler <awscli.paramfile.URIArgumentHandler object at 0x7ff2b19b8990>
2020-12-10 07:08:39,776 - MainThread - botocore.credentials - DEBUG - Looking for credentials via: env
2020-12-10 07:08:39,776 - MainThread - botocore.credentials - DEBUG - Looking for credentials via: assume-role
2020-12-10 07:08:39,776 - MainThread - botocore.credentials - DEBUG - Looking for credentials via: assume-role-with-web-identity
2020-12-10 07:08:39,776 - MainThread - botocore.credentials - DEBUG - Looking for credentials via: sso
2020-12-10 07:08:39,776 - MainThread - botocore.credentials - DEBUG - Looking for credentials via: shared-credentials-file
2020-12-10 07:08:39,777 - MainThread - botocore.credentials - INFO - Found credentials in shared credentials file: ~/.aws/credentials
2020-12-10 07:08:39,778 - MainThread - botocore.loaders - DEBUG - Loading JSON file: /Users/kdaily/aws-cli/botocore/data/endpoints.json
2020-12-10 07:08:39,784 - MainThread - botocore.hooks - DEBUG - Event choose-service-name: calling handler <function handle_service_name_alias at 0x7ff2b0a77950>
2020-12-10 07:08:39,786 - MainThread - botocore.hooks - DEBUG - Event creating-client-class.lambda: calling handler <function add_generate_presigned_url at 0x7ff2b0a02050>
2020-12-10 07:08:39,789 - MainThread - botocore.endpoint - DEBUG - Setting lambda timeout as (None, None)
2020-12-10 07:08:39,791 - MainThread - botocore.hooks - DEBUG - Event provide-client-params.lambda.Invoke: calling handler <function base64_decode_input_blobs at 0x7ff2b1925050>
2020-12-10 07:08:39,791 - MainThread - botocore.hooks - DEBUG - Event before-parameter-build.lambda.Invoke: calling handler <function generate_idempotent_uuid at 0x7ff2b0a7e5f0>
2020-12-10 07:08:39,791 - MainThread - botocore.hooks - DEBUG - Event before-call.lambda.Invoke: calling handler <function inject_api_version_header_if_needed at 0x7ff2b0a84e60>
2020-12-10 07:08:39,792 - MainThread - botocore.endpoint - DEBUG - Making request for OperationModel(name=Invoke) with params: {'url_path': '/2015-03-31/functions/aws-cli-issue-5783/invocations', 'query_string': {}, 'method': 'POST', 'headers': {'User-Agent': 'aws-cli/2.1.6 Python/3.7.4 Darwin/19.6.0 exe/x86_64 prompt/off command/lambda.invoke'}, 'body': b'{"delay": 450}\n', 'url': 'https://lambda.us-west-2.amazonaws.com/2015-03-31/functions/aws-cli-issue-5783/invocations', 'context': {'client_region': 'us-west-2', 'client_config': <botocore.config.Config object at 0x7ff2b1f26f90>, 'has_streaming_input': True, 'auth_type': None}}
2020-12-10 07:08:39,792 - MainThread - botocore.hooks - DEBUG - Event request-created.lambda.Invoke: calling handler <bound method RequestSigner.handler of <botocore.signers.RequestSigner object at 0x7ff2b1f26e10>>
2020-12-10 07:08:39,792 - MainThread - botocore.hooks - DEBUG - Event choose-signer.lambda.Invoke: calling handler <function set_operation_specific_signer at 0x7ff2b0a73680>
2020-12-10 07:08:39,792 - MainThread - botocore.auth - DEBUG - Calculating signature using v4 auth.
2020-12-10 07:08:39,792 - MainThread - botocore.auth - DEBUG - CanonicalRequest:
POST
/2015-03-31/functions/aws-cli-issue-5783/invocations

host:lambda.us-west-2.amazonaws.com
x-amz-date:20201210T150839Z

host;x-amz-date
a2a041ecdcdd8638f4a3091e4fa57c69e2e0cefe9389c14ef9e3b171b23384d6
2020-12-10 07:08:39,792 - MainThread - botocore.auth - DEBUG - StringToSign:
AWS4-HMAC-SHA256
20201210T150839Z
20201210/us-west-2/lambda/aws4_request
0b8903555fb894381b8d6a960dabaea3e3bb756b3b29781c282106c2619c5557
2020-12-10 07:08:39,792 - MainThread - botocore.auth - DEBUG - Signature:
59d23e1f2228ce15b9a427851fc63c5b324df60774d19161851f36e729e4f0e5
2020-12-10 07:08:39,793 - MainThread - botocore.endpoint - DEBUG - Sending http request: <AWSPreparedRequest stream_output=True, method=POST, url=https://lambda.us-west-2.amazonaws.com/2015-03-31/functions/aws-cli-issue-5783/invocations, headers={'User-Agent': b'aws-cli/2.1.6 Python/3.7.4 Darwin/19.6.0 exe/x86_64 prompt/off command/lambda.invoke', 'X-Amz-Date': b'20201210T150839Z', 'Authorization': b'AWS4-HMAC-SHA256 Credential=ZZZ/20201210/us-west-2/lambda/aws4_request, SignedHeaders=host;x-amz-date, Signature=59d23e1f2228ce15b9a427851fc63c5b324df60774d19161851f36e729e4f0e5', 'Content-Length': '15'}>
2020-12-10 07:08:39,794 - MainThread - urllib3.connectionpool - DEBUG - Starting new HTTPS connection (1): lambda.us-west-2.amazonaws.com:443
2020-12-10 07:20:57,521 - MainThread - botocore.hooks - DEBUG - Event needs-retry.lambda.Invoke: calling handler <bound method RetryHandler.needs_retry of <botocore.retries.standard.RetryHandler object at 0x7ff2b1d33810>>
2020-12-10 07:20:57,527 - MainThread - botocore.retries.standard - DEBUG - Max attempts of 1 reached.
2020-12-10 07:20:57,533 - MainThread - botocore.retries.standard - DEBUG - Not retrying request.
2020-12-10 07:20:57,534 - MainThread - awscli.clidriver - DEBUG - Exception caught in main()
Traceback (most recent call last):
  File "urllib3/connectionpool.py", line 706, in urlopen
  File "urllib3/connectionpool.py", line 445, in _make_request
  File "<string>", line 3, in raise_from
  File "urllib3/connectionpool.py", line 440, in _make_request
  File "http/client.py", line 1336, in getresponse
  File "http/client.py", line 306, in begin
  File "http/client.py", line 267, in _read_status
  File "socket.py", line 589, in readinto
  File "ssl.py", line 1071, in recv_into
  File "ssl.py", line 929, in read
ConnectionResetError: [Errno 54] Connection reset by peer

During handling of the above exception, another exception occurred:

Traceback (most recent call last):
  File "botocore/httpsession.py", line 263, in send
  File "urllib3/connectionpool.py", line 756, in urlopen
  File "urllib3/util/retry.py", line 506, in increment
  File "urllib3/packages/six.py", line 734, in reraise
  File "urllib3/connectionpool.py", line 706, in urlopen
  File "urllib3/connectionpool.py", line 445, in _make_request
  File "<string>", line 3, in raise_from
  File "urllib3/connectionpool.py", line 440, in _make_request
  File "http/client.py", line 1336, in getresponse
  File "http/client.py", line 306, in begin
  File "http/client.py", line 267, in _read_status
  File "socket.py", line 589, in readinto
  File "ssl.py", line 1071, in recv_into
  File "ssl.py", line 929, in read
urllib3.exceptions.ProtocolError: ('Connection aborted.', ConnectionResetError(54, 'Connection reset by peer'))

During handling of the above exception, another exception occurred:

Traceback (most recent call last):
  File "awscli/clidriver.py", line 457, in main
  File "awscli/clidriver.py", line 586, in __call__
  File "awscli/clidriver.py", line 765, in __call__
  File "awscli/clidriver.py", line 894, in invoke
  File "awscli/clidriver.py", line 906, in _make_client_call
  File "botocore/client.py", line 249, in _api_call
  File "botocore/client.py", line 555, in _make_api_call
  File "botocore/client.py", line 574, in _make_request
  File "botocore/endpoint.py", line 102, in make_request
  File "botocore/endpoint.py", line 156, in _send_request
  File "botocore/endpoint.py", line 200, in _do_get_response
  File "botocore/endpoint.py", line 269, in _send
  File "botocore/httpsession.py", line 294, in send
botocore.exceptions.ConnectionClosedError: Connection was closed before we received a valid response from endpoint URL: "https://lambda.us-west-2.amazonaws.com/2015-03-31/functions/aws-cli-issue-5783/invocations".

Connection was closed before we received a valid response from endpoint URL: "https://lambda.us-west-2.amazonaws.com/2015-03-31/functions/aws-cli-issue-5783/invocations".
/Users/kdaily/aws-cli/aws --debug lambda invoke --cli-read-timeout 0  0       0.56s user 0.39s system 0% cpu 12:19.49 total

kdaily avatar Dec 10 '20 17:12 kdaily

We just ran into this bug ourselves, as the firewall severs the idle connection after a few minutes. And tampering with the OS defaults is a non-starter when running the CLI within Docker or Kubernetes.

Please add three additional properties to the config file:

  1. tcp_keepalive_time
  2. tcp_keepalive_intvl
  3. tcp_keepalive_probes (Unix only)

If tcp_keepalive is not set, then these three values are ignored. Otherwise, they are used to set the corresponding socket options.

For Windows you have to use SIO_KEEPALIVE_VALS, which is not compatible with requests. https://github.com/psf/requests/issues/5121 I think it would be fine to only support these three options on Unix, as it is better than nothing.

cc @kdaily

rittneje avatar May 11 '22 18:05 rittneje

Hi Team,

We are facing the read timeout error while calling our Lambda function from AWS CLI.

We are using the IAM role of the EC2 instance to make the AWS CLI calls and haven't set the user with "aws configure", no config file was created.

We then tried the following workarounds: 1. Manually created a config file manually under the "aws" folder. 2. Changed the folder name from "aws" to ".aws" to make it a hidden folder. 3. Modified the "KeepAlivetime" registry parameter value to "600000". Added the parameters "KeepAliveInterval" with value 1000 and "TcpMaxDataRetransmissions" with value 10. Restarted the EC2 instance.

Unfortunately, none of the above options helped in mitigating the issue.

Added --debug option to the CLI command for your reference. Requesting you to provide a solution to avoid this read timeout error.

PS C:\Users\cdh_qa> aws lambda --region us-west-2 invoke --function-name arn:aws:lambda:us-west-2:169042900902:function:dsbi-redshift-act1 C:\DSBI\Control-M\Logs\outfile_dsbi-redshift-act1.txt --cli-read-timeout 900 --debug 2022-06-08 07:41:00,927 - MainThread - awscli.clidriver - DEBUG - CLI version: aws-cli/2.7.3 Python/3.9.11 Windows/10 exec-env/EC2 exe/AMD64 2022-06-08 07:41:00,927 - MainThread - awscli.clidriver - DEBUG - Arguments entered to CLI: ['lambda', '--region', 'us-west-2', 'invoke', '--function-name', 'arn:aws:lambda:us-west-2:169042900902:function:dsbi-redshift-act1', 'C:\DSBI\Control-M\Logs\outfile_dsbi-redshift-act1.txt', '--cli-read-timeout', '900', '--debug'] 2022-06-08 07:41:01,113 - MainThread - botocore.hooks - DEBUG - Event building-command-table.main: calling handler <function add_s3 at 0x00000219CFD59A60> 2022-06-08 07:41:01,149 - MainThread - botocore.hooks - DEBUG - Event building-command-table.main: calling handler <function add_ddb at 0x00000219CFBB08B0> 2022-06-08 07:41:01,207 - MainThread - botocore.hooks - DEBUG - Event building-command-table.main: calling handler <bound method BasicCommand.add_command of <class 'awscli.customizations.configure.configure.ConfigureCommand'>> 2022-06-08 07:41:01,292 - MainThread - botocore.hooks - DEBUG - Event building-command-table.main: calling handler <function change_name at 0x00000219CFB4FC10> 2022-06-08 07:41:01,340 - MainThread - botocore.hooks - DEBUG - Event building-command-table.main: calling handler <function change_name at 0x00000219CFB59D30> 2022-06-08 07:41:01,436 - MainThread - botocore.hooks - DEBUG - Event building-command-table.main: calling handler <function alias_opsworks_cm at 0x00000219CFD6C430> 2022-06-08 07:41:01,452 - MainThread - botocore.hooks - DEBUG - Event building-command-table.main: calling handler <function add_history_commands at 0x00000219CFBFC430> 2022-06-08 07:41:01,457 - MainThread - botocore.hooks - DEBUG - Event building-command-table.main: calling handler <bound method BasicCommand.add_command of <class 'awscli.customizations.devcommands.CLIDevCommand'>> 2022-06-08 07:41:01,468 - MainThread - botocore.hooks - DEBUG - Event building-command-table.main: calling handler <function add_waiters at 0x00000219CFD64670> 2022-06-08 07:41:01,500 - MainThread - botocore.loaders - DEBUG - Loading JSON file: C:\Program Files\Amazon\AWSCLIV2\awscli\data\cli.json 2022-06-08 07:41:01,879 - MainThread - botocore.hooks - DEBUG - Event top-level-args-parsed: calling handler <function resolve_types at 0x00000219CFCAE430> 2022-06-08 07:41:01,879 - MainThread - botocore.hooks - DEBUG - Event top-level-args-parsed: calling handler <function no_sign_request at 0x00000219CFCAEF70> 2022-06-08 07:41:01,879 - MainThread - botocore.hooks - DEBUG - Event top-level-args-parsed: calling handler <function resolve_verify_ssl at 0x00000219CFCAEEE0> 2022-06-08 07:41:01,895 - MainThread - botocore.hooks - DEBUG - Event top-level-args-parsed: calling handler <function resolve_cli_read_timeout at 0x00000219CFCB20D0> 2022-06-08 07:41:01,895 - MainThread - botocore.hooks - DEBUG - Event top-level-args-parsed: calling handler <function resolve_cli_connect_timeout at 0x00000219CFCB2040> 2022-06-08 07:41:01,895 - MainThread - botocore.hooks - DEBUG - Event top-level-args-parsed: calling handler <built-in method update of dict object at 0x00000219CFE08480> 2022-06-08 07:41:01,895 - MainThread - botocore.session - DEBUG - Setting config variable for region to 'us-west-2' 2022-06-08 07:41:01,911 - MainThread - awscli.clidriver - DEBUG - CLI version: aws-cli/2.7.3 Python/3.9.11 Windows/10 exec-env/EC2 exe/AMD64 prompt/off 2022-06-08 07:41:01,911 - MainThread - awscli.clidriver - DEBUG - Arguments entered to CLI: ['lambda', '--region', 'us-west-2', 'invoke', '--function-name', 'arn:aws:lambda:us-west-2:169042900902:function:dsbi-redshift-act1', 'C:\DSBI\Control-M\Logs\outfile_dsbi-redshift-act1.txt', '--cli-read-timeout', '900', '--debug'] 2022-06-08 07:41:01,911 - MainThread - botocore.hooks - DEBUG - Event session-initialized: calling handler <function add_timestamp_parser at 0x00000219CFD5D0D0> 2022-06-08 07:41:01,926 - MainThread - botocore.hooks - DEBUG - Event session-initialized: calling handler <function register_uri_param_handler at 0x00000219CF8C9DC0> 2022-06-08 07:41:01,926 - MainThread - botocore.hooks - DEBUG - Event session-initialized: calling handler <function add_binary_formatter at 0x00000219CFDC88B0> 2022-06-08 07:41:01,942 - MainThread - botocore.hooks - DEBUG - Event session-initialized: calling handler <function no_pager_handler at 0x00000219CF8B6280> 2022-06-08 07:41:01,942 - MainThread - botocore.hooks - DEBUG - Event session-initialized: calling handler <function inject_assume_role_provider_cache at 0x00000219CF926CA0> 2022-06-08 07:41:01,942 - MainThread - botocore.utils - DEBUG - IMDS ENDPOINT: http://169.254.169.254/ 2022-06-08 07:41:01,958 - MainThread - botocore.hooks - DEBUG - Event session-initialized: calling handler <function attach_history_handler at 0x00000219CFBFC310> 2022-06-08 07:41:01,958 - MainThread - botocore.hooks - DEBUG - Event session-initialized: calling handler <function inject_json_file_cache at 0x00000219CFBAC790> 2022-06-08 07:41:02,101 - MainThread - botocore.loaders - DEBUG - Loading JSON file: C:\Program Files\Amazon\AWSCLIV2\awscli\botocore\data\lambda\2015-03-31\service-2.json 2022-06-08 07:41:02,117 - MainThread - botocore.hooks - DEBUG - Event building-command-table.lambda: calling handler <function _add_wizard_command at 0x00000219CFDC8820> 2022-06-08 07:41:02,133 - MainThread - botocore.hooks - DEBUG - Event building-command-table.lambda: calling handler <function add_waiters at 0x00000219CFD64670> 2022-06-08 07:41:02,245 - MainThread - botocore.loaders - DEBUG - Loading JSON file: C:\Program Files\Amazon\AWSCLIV2\awscli\botocore\data\lambda\2015-03-31\waiters-2.json 2022-06-08 07:41:02,261 - MainThread - awscli.clidriver - DEBUG - OrderedDict([('function-name', <awscli.arguments.CLIArgument object at 0x00000219CFF91610>), ('invocation-type', <awscli.arguments.CLIArgument object at 0x00000219CFF915E0>), ('log-type', <awscli.arguments.CLIArgument object at 0x00000219CFF91580>), ('client-context', <awscli.arguments.CLIArgument object at 0x00000219CFF91550>), ('payload', <awscli.arguments.CLIArgument object at 0x00000219CFF91520>), ('qualifier', <awscli.arguments.CLIArgument object at 0x00000219CFF91730>)]) 2022-06-08 07:41:02,261 - MainThread - botocore.hooks - DEBUG - Event building-argument-table.lambda.invoke: calling handler <function add_streaming_output_arg at 0x00000219CFD5D3A0> 2022-06-08 07:41:02,270 - MainThread - botocore.hooks - DEBUG - Event building-argument-table.lambda.invoke: calling handler <function add_cli_input_json at 0x00000219CF92C4C0> 2022-06-08 07:41:02,270 - MainThread - botocore.hooks - DEBUG - Event building-argument-table.lambda.invoke: calling handler <function add_cli_input_yaml at 0x00000219CF92C700> 2022-06-08 07:41:02,270 - MainThread - botocore.hooks - DEBUG - Event building-argument-table.lambda.invoke: calling handler <function unify_paging_params at 0x00000219CFBB0DC0> 2022-06-08 07:41:02,426 - MainThread - botocore.loaders - DEBUG - Loading JSON file: C:\Program Files\Amazon\AWSCLIV2\awscli\botocore\data\lambda\2015-03-31\paginators-1.json 2022-06-08 07:41:02,436 - MainThread - botocore.hooks - DEBUG - Event building-argument-table.lambda.invoke: calling handler <function add_generate_skeleton at 0x00000219CFCA69D0> 2022-06-08 07:41:02,582 - MainThread - botocore.hooks - DEBUG - Event load-cli-arg.lambda.invoke.function-name: calling handler <awscli.paramfile.URIArgumentHandler object at 0x00000219CFE4BA90> 2022-06-08 07:41:02,614 - MainThread - botocore.hooks - DEBUG - Event process-cli-arg.lambda.invoke: calling handler <awscli.argprocess.ParamShorthandParser object at 0x00000219CF8F1850> 2022-06-08 07:41:02,614 - MainThread - awscli.arguments - DEBUG - Unpacked value of 'arn:aws:lambda:us-west-2:169042900902:function:dsbi-redshift-act1' for parameter "function_name": 'arn:aws:lambda:us-west-2:169042900902:function:dsbi-redshift-act1' 2022-06-08 07:41:02,659 - MainThread - botocore.hooks - DEBUG - Event load-cli-arg.lambda.invoke.invocation-type: calling handler <awscli.paramfile.URIArgumentHandler object at 0x00000219CFE4BA90> 2022-06-08 07:41:02,659 - MainThread - botocore.hooks - DEBUG - Event load-cli-arg.lambda.invoke.log-type: calling handler <awscli.paramfile.URIArgumentHandler object at 0x00000219CFE4BA90> 2022-06-08 07:41:02,675 - MainThread - botocore.hooks - DEBUG - Event load-cli-arg.lambda.invoke.client-context: calling handler <awscli.paramfile.URIArgumentHandler object at 0x00000219CFE4BA90> 2022-06-08 07:41:02,676 - MainThread - botocore.hooks - DEBUG - Event load-cli-arg.lambda.invoke.payload: calling handler <awscli.paramfile.URIArgumentHandler object at 0x00000219CFE4BA90> 2022-06-08 07:41:02,676 - MainThread - botocore.hooks - DEBUG - Event load-cli-arg.lambda.invoke.qualifier: calling handler <awscli.paramfile.URIArgumentHandler object at 0x00000219CFE4BA90> 2022-06-08 07:41:02,676 - MainThread - botocore.hooks - DEBUG - Event load-cli-arg.lambda.invoke.outfile: calling handler <awscli.paramfile.URIArgumentHandler object at 0x00000219CFE4BA90> 2022-06-08 07:41:02,754 - MainThread - botocore.credentials - DEBUG - Looking for credentials via: env 2022-06-08 07:41:02,801 - MainThread - botocore.credentials - DEBUG - Looking for credentials via: assume-role 2022-06-08 07:41:02,817 - MainThread - botocore.credentials - DEBUG - Looking for credentials via: assume-role-with-web-identity 2022-06-08 07:41:02,911 - MainThread - botocore.credentials - DEBUG - Looking for credentials via: sso 2022-06-08 07:41:02,942 - MainThread - botocore.credentials - DEBUG - Looking for credentials via: shared-credentials-file 2022-06-08 07:41:02,942 - MainThread - botocore.credentials - DEBUG - Looking for credentials via: custom-process 2022-06-08 07:41:02,942 - MainThread - botocore.credentials - DEBUG - Looking for credentials via: config-file 2022-06-08 07:41:02,942 - MainThread - botocore.credentials - DEBUG - Looking for credentials via: ec2-credentials-file 2022-06-08 07:41:02,942 - MainThread - botocore.credentials - DEBUG - Looking for credentials via: boto-config 2022-06-08 07:41:02,942 - MainThread - botocore.credentials - DEBUG - Looking for credentials via: container-role 2022-06-08 07:41:02,957 - MainThread - botocore.credentials - DEBUG - Looking for credentials via: iam-role 2022-06-08 07:41:02,973 - MainThread - urllib3.connectionpool - DEBUG - Starting new HTTP connection (1): 169.254.169.254:80 2022-06-08 07:41:02,973 - MainThread - urllib3.connectionpool - DEBUG - http://169.254.169.254:80 "PUT /latest/api/token HTTP/1.1" 200 56 2022-06-08 07:41:02,973 - MainThread - urllib3.connectionpool - DEBUG - Resetting dropped connection: 169.254.169.254 2022-06-08 07:41:02,973 - MainThread - urllib3.connectionpool - DEBUG - http://169.254.169.254:80 "GET /latest/meta-data/iam/security-credentials/ HTTP/1.1" 200 6 2022-06-08 07:41:02,973 - MainThread - urllib3.connectionpool - DEBUG - Resetting dropped connection: 169.254.169.254 2022-06-08 07:41:02,973 - MainThread - urllib3.connectionpool - DEBUG - http://169.254.169.254:80 "GET /latest/meta-data/iam/security-credentials/s3_ec2 HTTP/1.1" 200 1442 2022-06-08 07:41:02,973 - MainThread - botocore.credentials - DEBUG - Found credentials from IAM Role: s3_ec2 2022-06-08 07:41:02,989 - MainThread - botocore.loaders - DEBUG - Loading JSON file: C:\Program Files\Amazon\AWSCLIV2\awscli\botocore\data\endpoints.json 2022-06-08 07:41:03,037 - MainThread - botocore.hooks - DEBUG - Event choose-service-name: calling handler <function handle_service_name_alias at 0x00000219CE72B430> 2022-06-08 07:41:03,053 - MainThread - botocore.hooks - DEBUG - Event creating-client-class.lambda: calling handler <function add_generate_presigned_url at 0x00000219CE6AEC10> 2022-06-08 07:41:03,053 - MainThread - botocore.endpoint - DEBUG - Setting lambda timeout as (60, 900) 2022-06-08 07:41:03,069 - MainThread - botocore.hooks - DEBUG - Event provide-client-params.lambda.Invoke: calling handler <function base64_decode_input_blobs at 0x00000219CFDCD040> 2022-06-08 07:41:03,069 - MainThread - botocore.hooks - DEBUG - Event before-parameter-build.lambda.Invoke: calling handler <function generate_idempotent_uuid at 0x00000219CE743430> 2022-06-08 07:41:03,085 - MainThread - botocore.hooks - DEBUG - Event before-call.lambda.Invoke: calling handler <function inject_api_version_header_if_needed at 0x00000219CE748CA0> 2022-06-08 07:41:03,085 - MainThread - botocore.endpoint - DEBUG - Making request for OperationModel(name=Invoke) with params: {'url_path': '/2015-03-31/functions/arn%3Aaws%3Alambda%3Aus-west-2%3A169042900902%3Afunction%3Adsbi-redshift-act1/invocations', 'query_string': {}, 'method': 'POST', 'headers': {'User-Agent': 'aws-cli/2.7.3 Python/3.9.11 Windows/10 exec-env/EC2 exe/AMD64 prompt/off command/lambda.invoke'}, 'body': b'', 'url': 'https://lambda.us-west-2.amazonaws.com/2015-03-31/functions/arn%3Aaws%3Alambda%3Aus-west-2%3A169042900902%3Afunction%3Adsbi-redshift-act1/invocations', 'context': {'client_region': 'us-west-2', 'client_config': <botocore.config.Config object at 0x00000219D03CB280>, 'has_streaming_input': True, 'auth_type': None}} 2022-06-08 07:41:03,085 - MainThread - botocore.hooks - DEBUG - Event request-created.lambda.Invoke: calling handler <bound method RequestSigner.handler of <botocore.signers.RequestSigner object at 0x00000219D03CB370>> 2022-06-08 07:41:03,085 - MainThread - botocore.hooks - DEBUG - Event choose-signer.lambda.Invoke: calling handler <function set_operation_specific_signer at 0x00000219CE743310> 2022-06-08 07:41:03,085 - MainThread - botocore.auth - DEBUG - Calculating signature using v4 auth. 2022-06-08 07:41:03,085 - MainThread - botocore.auth - DEBUG - CanonicalRequest: POST /2015-03-31/functions/arn%253Aaws%253Alambda%253Aus-west-2%253A169042900902%253Afunction%253Adsbi-redshift-act1/invocations

host:lambda.us-west-2.amazonaws.com x-amz-date:20220608T074103Z x-amz-security-token:{removed*}

host;x-amz-date;x-amz-security-token e3b0c44298fc1c149afbf4c8996fb92427ae41e4649b934ca495991b7852b855 2022-06-08 07:41:03,113 - MainThread - botocore.auth - DEBUG - StringToSign: AWS4-HMAC-SHA256 20220608T074103Z 20220608/us-west-2/lambda/aws4_request b034e0d6ae09c5b6368921f3d301e2fb53592695877e109e4ce86f1189deb1ee 2022-06-08 07:41:03,113 - MainThread - botocore.auth - DEBUG - Signature: 220ca9329f7f582604acfd17c5aa8b41f5fe3a85370ec3e0a20628292d5dde85 2022-06-08 07:41:03,117 - MainThread - botocore.endpoint - DEBUG - Sending http request: <AWSPreparedRequest stream_output=True, method=POST, url=https://lambda.us-west-2.amazonaws.com/2015-03-31/functions/arn%3Aaws%3Alambda%3Aus-west-2%3A169042900902%3Afunction%3Adsbi-redshift-act1/invocations, headers={'User-Agent': b'aws-cli/2.7.3 Python/3.9.11 Windows/10 exec-env/EC2 exe/AMD64 prompt/off command/lambda.invoke', 'X-Amz-Date': b'20220608T074103Z', 'X-Amz-Security-Token': b'{removed*}', 'Authorization': b'AWS4-HMAC-SHA256 Credential={removed*}/20220608/us-west-2/lambda/aws4_request, SignedHeaders=host;x-amz-date;x-amz-security-token, Signature=220ca9329f7f582604acfd17c5aa8b41f5fe3a85370ec3e0a20628292d5dde85', 'Content-Length': '0'}> 2022-06-08 07:41:03,117 - MainThread - urllib3.connectionpool - DEBUG - Starting new HTTPS connection (1): lambda.us-west-2.amazonaws.com:443 2022-06-08 07:56:03,178 - MainThread - botocore.hooks - DEBUG - Event needs-retry.lambda.Invoke: calling handler <bound method RetryHandler.needs_retry of <botocore.retries.standard.RetryHandler object at 0x00000219D03CBDC0>> 2022-06-08 07:56:03,178 - MainThread - botocore.retries.standard - DEBUG - Retry needed, retrying request after delay of: 0.41416196179868636 2022-06-08 07:56:03,178 - MainThread - botocore.endpoint - DEBUG - Response received to retry, sleeping for 0.41416196179868636 seconds 2022-06-08 07:56:03,607 - MainThread - botocore.hooks - DEBUG - Event request-created.lambda.Invoke: calling handler <bound method RequestSigner.handler of <botocore.signers.RequestSigner object at 0x00000219D03CB370>> 2022-06-08 07:56:03,607 - MainThread - botocore.hooks - DEBUG - Event choose-signer.lambda.Invoke: calling handler <function set_operation_specific_signer at 0x00000219CE743310> 2022-06-08 07:56:03,607 - MainThread - botocore.auth - DEBUG - Calculating signature using v4 auth. 2022-06-08 07:56:03,607 - MainThread - botocore.auth - DEBUG - CanonicalRequest: POST /2015-03-31/functions/arn%253Aaws%253Alambda%253Aus-west-2%253A169042900902%253Afunction%253Adsbi-redshift-act1/invocations

host:lambda.us-west-2.amazonaws.com x-amz-date:20220608T075603Z x-amz-security-token:{removed}

host;x-amz-date;x-amz-security-token e3b0c44298fc1c149afbf4c8996fb92427ae41e4649b934ca495991b7852b855 2022-06-08 07:56:03,607 - MainThread - botocore.auth - DEBUG - StringToSign: AWS4-HMAC-SHA256 20220608T075603Z 20220608/us-west-2/lambda/aws4_request 8a556b5a9ba26320de5943c804be5b20275a95686b7b94a606df328985ddacbc 2022-06-08 07:56:03,607 - MainThread - botocore.auth - DEBUG - Signature: dc4730758aef9ba970499266d3746f793576c814da1916982582ce9160214dd9 2022-06-08 07:56:03,614 - MainThread - botocore.endpoint - DEBUG - Sending http request: <AWSPreparedRequest stream_output=True, method=POST, url=https://lambda.us-west-2.amazonaws.com/2015-03-31/functions/arn%3Aaws%3Alambda%3Aus-west-2%3A169042900902%3Afunction%3Adsbi-redshift-act1/invocations, headers={'User-Agent': b'aws-cli/2.7.3 Python/3.9.11 Windows/10 exec-env/EC2 exe/AMD64 prompt/off command/lambda.invoke', 'X-Amz-Date': b'20220608T075603Z', 'X-Amz-Security-Token': b'{removed}', 'Authorization': b'AWS4-HMAC-SHA256 Credential={removed}/20220608/us-west-2/lambda/aws4_request, SignedHeaders=host;x-amz-date;x-amz-security-token, Signature=dc4730758aef9ba970499266d3746f793576c814da1916982582ce9160214dd9', 'Content-Length': '0'}> 2022-06-08 07:56:03,614 - MainThread - urllib3.connectionpool - DEBUG - Starting new HTTPS connection (2): lambda.us-west-2.amazonaws.com:443 2022-06-08 08:11:03,672 - MainThread - botocore.hooks - DEBUG - Event needs-retry.lambda.Invoke: calling handler <bound method RetryHandler.needs_retry of <botocore.retries.standard.RetryHandler object at 0x00000219D03CBDC0>> 2022-06-08 08:11:03,688 - MainThread - botocore.retries.standard - DEBUG - Retry needed, retrying request after delay of: 1.9234343515456467 2022-06-08 08:11:03,688 - MainThread - botocore.endpoint - DEBUG - Response received to retry, sleeping for 1.9234343515456467 seconds 2022-06-08 08:11:05,626 - MainThread - botocore.hooks - DEBUG - Event request-created.lambda.Invoke: calling handler <bound method RequestSigner.handler of <botocore.signers.RequestSigner object at 0x00000219D03CB370>> 2022-06-08 08:11:05,642 - MainThread - botocore.hooks - DEBUG - Event choose-signer.lambda.Invoke: calling handler <function set_operation_specific_signer at 0x00000219CE743310> 2022-06-08 08:11:05,642 - MainThread - botocore.auth - DEBUG - Calculating signature using v4 auth. 2022-06-08 08:11:05,642 - MainThread - botocore.auth - DEBUG - CanonicalRequest: POST /2015-03-31/functions/arn%253Aaws%253Alambda%253Aus-west-2%253A169042900902%253Afunction%253Adsbi-redshift-act1/invocations

host:lambda.us-west-2.amazonaws.com x-amz-date:20220608T081105Z x-amz-security-token:{removed}

host;x-amz-date;x-amz-security-token e3b0c44298fc1c149afbf4c8996fb92427ae41e4649b934ca495991b7852b855 2022-06-08 08:11:05,689 - MainThread - botocore.auth - DEBUG - StringToSign: AWS4-HMAC-SHA256 20220608T081105Z 20220608/us-west-2/lambda/aws4_request 02d77f44add9accc14a591089505815476d63abc815347cbfc5bc152e90a1bb2 2022-06-08 08:11:05,767 - MainThread - botocore.auth - DEBUG - Signature: bee4458ca4f71066a8f396a581ff6d78593d51f95f4132590a3ddccc2dee18d0 2022-06-08 08:11:05,783 - MainThread - botocore.endpoint - DEBUG - Sending http request: <AWSPreparedRequest stream_output=True, method=POST, url=https://lambda.us-west-2.amazonaws.com/2015-03-31/functions/arn%3Aaws%3Alambda%3Aus-west-2%3A169042900902%3Afunction%3Adsbi-redshift-act1/invocations, headers={'User-Agent': b'aws-cli/2.7.3 Python/3.9.11 Windows/10 exec-env/EC2 exe/AMD64 prompt/off command/lambda.invoke', 'X-Amz-Date': b'20220608T081105Z', 'X-Amz-Security-Token': b'{removed}', 'Authorization': b'AWS4-HMAC-SHA256 Credential={removed}/20220608/us-west-2/lambda/aws4_request, SignedHeaders=host;x-amz-date;x-amz-security-token, Signature=bee4458ca4f71066a8f396a581ff6d78593d51f95f4132590a3ddccc2dee18d0', 'Content-Length': '0'}> 2022-06-08 08:11:05,814 - MainThread - urllib3.connectionpool - DEBUG - Starting new HTTPS connection (3): lambda.us-west-2.amazonaws.com:443 2022-06-08 08:26:05,936 - MainThread - botocore.hooks - DEBUG - Event needs-retry.lambda.Invoke: calling handler <bound method RetryHandler.needs_retry of <botocore.retries.standard.RetryHandler object at 0x00000219D03CBDC0>> 2022-06-08 08:26:05,936 - MainThread - botocore.retries.standard - DEBUG - Max attempts of 3 reached. 2022-06-08 08:26:05,936 - MainThread - botocore.retries.standard - DEBUG - Not retrying request. 2022-06-08 08:26:05,936 - MainThread - awscli.clidriver - DEBUG - Exception caught in main() Traceback (most recent call last): File "urllib3\connectionpool.py", line 449, in _make_request File "", line 3, in raise_from File "urllib3\connectionpool.py", line 444, in _make_request File "http\client.py", line 1377, in getresponse File "http\client.py", line 320, in begin File "http\client.py", line 281, in _read_status File "socket.py", line 704, in readinto File "ssl.py", line 1241, in recv_into File "ssl.py", line 1099, in read socket.timeout: The read operation timed out

During handling of the above exception, another exception occurred:

Traceback (most recent call last): File "awscli\botocore\httpsession.py", line 358, in send File "urllib3\connectionpool.py", line 785, in urlopen File "urllib3\util\retry.py", line 525, in increment File "urllib3\packages\six.py", line 770, in reraise File "urllib3\connectionpool.py", line 703, in urlopen File "urllib3\connectionpool.py", line 451, in _make_request File "urllib3\connectionpool.py", line 340, in _raise_timeout urllib3.exceptions.ReadTimeoutError: AWSHTTPSConnectionPool(host='lambda.us-west-2.amazonaws.com', port=443): Read timed out. (read timeout=900)

During handling of the above exception, another exception occurred:

Traceback (most recent call last): File "awscli\clidriver.py", line 458, in main File "awscli\clidriver.py", line 593, in call File "awscli\clidriver.py", line 769, in call File "awscli\clidriver.py", line 900, in invoke File "awscli\clidriver.py", line 912, in _make_client_call File "awscli\botocore\client.py", line 304, in _api_call File "awscli\botocore\client.py", line 620, in _make_api_call File "awscli\botocore\client.py", line 640, in _make_request File "awscli\botocore\endpoint.py", line 101, in make_request File "awscli\botocore\endpoint.py", line 155, in _send_request File "awscli\botocore\endpoint.py", line 199, in _do_get_response File "awscli\botocore\endpoint.py", line 271, in _send File "awscli\botocore\httpsession.py", line 393, in send botocore.exceptions.ReadTimeoutError: Read timeout on endpoint URL: "https://lambda.us-west-2.amazonaws.com/2015-03-31/functions/arn%3Aaws%3Alambda%3Aus-west-2%3A169042900902%3Afunction%3Adsbi-redshift-act1/invocations"

Read timeout on endpoint URL: "https://lambda.us-west-2.amazonaws.com/2015-03-31/functions/arn%3Aaws%3Alambda%3Aus-west-2%3A169042900902%3Afunction%3Adsbi-redshift-act1/invocations"

Sivakami3 avatar Jun 08 '22 08:06 Sivakami3

Hi team, I am facing same issue as @Sivakami3

Any solutions on it? Thanks!

aihiangng avatar Jul 15 '22 01:07 aihiangng

Here is the fix: Solution: Set the tcp_keepalive less than 350s e.g. tcp_keepalive=300. On Amazon Linux you can set this as shown below:

sudo sysctl net.ipv4.tcp_keepalive=300

Also, you would need to set tcp_keepalive configuration of AWS CLI [1] so that it honors the system tcp_keepalive settings.

aws configure set tcp_keepalive true

Cause: The issue occurs because the Network Resource such as NAT Gateway, Amazon Virtual Private Cloud (Amazon VPC) Endpoints, and Network Load Balancer (NLB) currently have a fixed idle timeout of 350 seconds. [2] [3]

The default setting on Amazon Linux is:

sudo sysctl net.ipv4.tcp_keepalive_time
net.ipv4.tcp_keepalive_time=7200

This means, when the connection is idle for 2 hrs then a keepalive signal is sent on the connection. However, the VPC resources have idle timeout of 350s. So the connection RST packet is send by VPC resources after 350s of idle TCP connection.

cc: @kdaily @aihiangng

punkwalker avatar Jun 17 '23 00:06 punkwalker

sudo sysctl net.ipv4.tcp_keepalive_time

This command does not work with error: sysctl: cannot stat /proc/sys/net/ipv4/tcp_keepalive: No such file or directory

jeremy-brooks avatar Jul 24 '23 16:07 jeremy-brooks