Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

Sign up for GitHub

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Jump to bottom

aws lambda invoke retries while lambda execution has not failed #8545

Open
Hodir22 opened this issue Feb 22, 2024 · 0 comments
Open

aws lambda invoke retries while lambda execution has not failed #8545

Hodir22 opened this issue Feb 22, 2024 · 0 comments
Assignees
@RyanFitzSimmonsAK
Labels
bug This issue is a bug. investigating This issue is being investigated and/or work is in progress to resolve the issue. lambda p2 This is a standard priority issue

Comments

@Hodir22
Copy link

Hodir22 commented Feb 22, 2024 •
edited

Describe the bug

I use the aws lambda invoke command as following:

aws --debug lambda invoke --function-name <retracted> \
                  --invocation-type RequestResponse \
                  --payload '{"<retracted>": "<retracted>", "<retracted>": [ "<retracted>" ]}' \
                  --cli-binary-format raw-in-base64-out \
                  --cli-read-timeout 60000 \
                  --cli-connect-timeout 60000 \
                  result.txt

The lambda runs for 5 - 10 minutes and should return a response afterwards. However, the response is not returned. Instead, the lambda is retried until the maximum attempts have been reached. Note that no error occurs during the execution of the lambda, which finishes successfully.

I have configured the read and connection time-out to see if the problem that I am facing is related to this, but tried different values. This does not make a difference. After a while, the following debugging lines show:

2024-02-22T20:07:42.3679127Z 2024-02-22 20:07:42,367 - MainThread - botocore.hooks - DEBUG - Event needs-retry.lambda.Invoke: calling handler <bound method RetryHandler.needs_retry of <botocore.retries.standard.RetryHandler object at 0x7f6e02bd6ad0>>
**2024-02-22T20:07:42.3680021Z 2024-02-22 20:07:42,367 - MainThread - botocore.retries.standard - DEBUG - Retry needed, retrying request after delay of: 0.17558782454690847**

I have seen somewhat similar issues on Github, but there the connection was explicitly terminated and an exception was thrown by boto3. In my case, this does not happen until the max. attempts have been reached.

What can be the cause of this issue, and is there any approach to resolve or further debug this issue?

Expected Behavior

The lambda invocation returns a response when its execution has ended.

Current Behavior

The event is retried until the maximum number of attempts (3) is exceeded. When the execution finishes, no response is returned and another invocation is executed.

The below stacktrace shows the CLI call with --debug enabled:

2024-02-22T20:02:45.3955566Z 2024-02-22 20:02:45,394 - MainThread - awscli.clidriver - DEBUG - CLI version: aws-cli/2.15.22 Python/3.11.6 Linux/6.2.0-1019-azure exec-env/VSTS-AWSShellScript exe/x86_64.ubuntu.22
aws lambda invoke --function-name <retracted> --invocation-type RequestResponse  --payload '{"<retracted>": "<retracted>", "<retracted>":[ "<retracted>" ]}' --cli-binary-format raw-in-base64-out
2024-02-22T20:02:45.4071719Z 2024-02-22 20:02:45,406 - MainThread - botocore.hooks - DEBUG - Event building-command-table.main: calling handler <function add_s3 at 0x7f6e05916ac0>
2024-02-22T20:02:45.4072590Z 2024-02-22 20:02:45,406 - MainThread - botocore.hooks - DEBUG - Event building-command-table.main: calling handler <function add_ddb at 0x7f6e06342980>
2024-02-22T20:02:45.4073444Z 2024-02-22 20:02:45,406 - MainThread - botocore.hooks - DEBUG - Event building-command-table.main: calling handler <bound method BasicCommand.add_command of <class 'awscli.customizations.configure.configure.ConfigureCommand'>>
2024-02-22T20:02:45.4074243Z 2024-02-22 20:02:45,406 - MainThread - botocore.hooks - DEBUG - Event building-command-table.main: calling handler <function change_name at 0x7f6e067c0cc0>
2024-02-22T20:02:45.4074927Z 2024-02-22 20:02:45,406 - MainThread - botocore.hooks - DEBUG - Event building-command-table.main: calling handler <function change_name at 0x7f6e067c2340>
2024-02-22T20:02:45.4075665Z 2024-02-22 20:02:45,406 - MainThread - botocore.hooks - DEBUG - Event building-command-table.main: calling handler <function alias_opsworks_cm at 0x7f6e05921580>
2024-02-22T20:02:45.4076721Z 2024-02-22 20:02:45,406 - MainThread - botocore.hooks - DEBUG - Event building-command-table.main: calling handler <function add_history_commands at 0x7f6e063953a0>
2024-02-22T20:02:45.4077555Z 2024-02-22 20:02:45,406 - MainThread - botocore.hooks - DEBUG - Event building-command-table.main: calling handler <bound method BasicCommand.add_command of <class 'awscli.customizations.devcommands.CLIDevCommand'>>
2024-02-22T20:02:45.4078310Z 2024-02-22 20:02:45,407 - MainThread - botocore.hooks - DEBUG - Event building-command-table.main: calling handler <function add_waiters at 0x7f6e05921440>
2024-02-22T20:02:45.4079186Z 2024-02-22 20:02:45,407 - MainThread - botocore.hooks - DEBUG - Event building-command-table.main: calling handler <bound method AliasSubCommandInjector.on_building_command_table of <awscli.alias.AliasSubCommandInjector object at 0x7f6e059d81d0>>
2024-02-22T20:02:45.4079982Z 2024-02-22 20:02:45,407 - MainThread - botocore.loaders - DEBUG - Loading JSON file: /usr/local/aws-cli/v2/2.15.22/dist/awscli/data/cli.json
2024-02-22T20:02:45.4095093Z 2024-02-22 20:02:45,409 - MainThread - botocore.hooks - DEBUG - Event top-level-args-parsed: calling handler <function resolve_types at 0x7f6e05f3ede0>
2024-02-22T20:02:45.4095844Z 2024-02-22 20:02:45,409 - MainThread - botocore.hooks - DEBUG - Event top-level-args-parsed: calling handler <function no_sign_request at 0x7f6e05f3f100>
2024-02-22T20:02:45.4096546Z 2024-02-22 20:02:45,409 - MainThread - botocore.hooks - DEBUG - Event top-level-args-parsed: calling handler <function resolve_verify_ssl at 0x7f6e05f3f060>
2024-02-22T20:02:45.4097249Z 2024-02-22 20:02:45,409 - MainThread - botocore.hooks - DEBUG - Event top-level-args-parsed: calling handler <function resolve_cli_read_timeout at 0x7f6e05f3f240>
2024-02-22T20:02:45.4097973Z 2024-02-22 20:02:45,409 - MainThread - botocore.hooks - DEBUG - Event top-level-args-parsed: calling handler <function resolve_cli_connect_timeout at 0x7f6e05f3f1a0>
2024-02-22T20:02:45.4098703Z 2024-02-22 20:02:45,409 - MainThread - botocore.hooks - DEBUG - Event top-level-args-parsed: calling handler <built-in method update of dict object at 0x7f6e059c9580>
2024-02-22T20:02:45.4101182Z 2024-02-22 20:02:45,409 - MainThread - awscli.clidriver - DEBUG - CLI version: aws-cli/2.15.22 Python/3.11.6 Linux/6.2.0-1019-azure exec-env/VSTS-AWSShellScript exe/x86_64.ubuntu.22 prompt/off
2024-02-22T20:02:45.4102475Z 2024-02-22 20:02:45,409 - MainThread - awscli.clidriver - DEBUG - Arguments entered to CLI: ['--debug', 'lambda', 'invoke', '--function-name', '', '--invocation-type', 'RequestResponse', '--payload', '{"<retracted>": "<retracted>", "<retracted>": [ "<retracted>" ]}', '--cli-binary-format', 'raw-in-base64-out', '--cli-read-timeout', '60000', '--cli-connect-timeout', '60000', 'result.txt']
2024-02-22T20:02:45.4103664Z 2024-02-22 20:02:45,410 - MainThread - botocore.hooks - DEBUG - Event session-initialized: calling handler <function add_timestamp_parser at 0x7f6e05917420>
2024-02-22T20:02:45.4104397Z 2024-02-22 20:02:45,410 - MainThread - botocore.hooks - DEBUG - Event session-initialized: calling handler <function register_uri_param_handler at 0x7f6e06b2e2a0>
2024-02-22T20:02:45.4105091Z 2024-02-22 20:02:45,410 - MainThread - botocore.hooks - DEBUG - Event session-initialized: calling handler <function add_binary_formatter at 0x7f6e05992d40>
2024-02-22T20:02:45.4105769Z 2024-02-22 20:02:45,410 - MainThread - botocore.hooks - DEBUG - Event session-initialized: calling handler <function no_pager_handler at 0x7f6e06f40ae0>
2024-02-22T20:02:45.4106481Z 2024-02-22 20:02:45,410 - MainThread - botocore.hooks - DEBUG - Event session-initialized: calling handler <function inject_assume_role_provider_cache at 0x7f6e06b35bc0>
2024-02-22T20:02:45.4124768Z 2024-02-22 20:02:45,411 - MainThread - botocore.utils - DEBUG - IMDS ENDPOINT: http://169.254.169.254/
2024-02-22T20:02:45.4150006Z 2024-02-22 20:02:45,414 - MainThread - botocore.hooks - DEBUG - Event session-initialized: calling handler <function attach_history_handler at 0x7f6e06375c60>
2024-02-22T20:02:45.4150948Z 2024-02-22 20:02:45,414 - MainThread - botocore.hooks - DEBUG - Event session-initialized: calling handler <function inject_json_file_cache at 0x7f6e0631ec00>
2024-02-22T20:02:45.4266222Z 2024-02-22 20:02:45,426 - MainThread - botocore.loaders - DEBUG - Loading JSON file: /usr/local/aws-cli/v2/2.15.22/dist/awscli/botocore/data/lambda/2015-03-31/service-2.json
2024-02-22T20:02:45.4501189Z 2024-02-22 20:02:45,449 - MainThread - botocore.hooks - DEBUG - Event building-command-table.lambda: calling handler functools.partial(<function _remove_commands at 0x7f6e05f5e3e0>, commands_to_remove=['invoke-with-response-stream'])
2024-02-22T20:02:45.4502099Z 2024-02-22 20:02:45,449 - MainThread - awscli.customizations.removals - DEBUG - Removing operation: invoke-with-response-stream
2024-02-22T20:02:45.4502802Z 2024-02-22 20:02:45,449 - MainThread - botocore.hooks - DEBUG - Event building-command-table.lambda: calling handler <function _add_wizard_command at 0x7f6e05991a80>
2024-02-22T20:02:45.4503516Z 2024-02-22 20:02:45,449 - MainThread - botocore.hooks - DEBUG - Event building-command-table.lambda: calling handler <function add_waiters at 0x7f6e05921440>
2024-02-22T20:02:45.4621843Z 2024-02-22 20:02:45,461 - MainThread - botocore.loaders - DEBUG - Loading JSON file: /usr/local/aws-cli/v2/2.15.22/dist/awscli/botocore/data/lambda/2015-03-31/waiters-2.json
2024-02-22T20:02:45.4622876Z 2024-02-22 20:02:45,461 - MainThread - botocore.hooks - DEBUG - Event building-command-table.lambda: calling handler <bound method AliasSubCommandInjector.on_building_command_table of <awscli.alias.AliasSubCommandInjector object at 0x7f6e059d81d0>>
2024-02-22T20:02:45.4629471Z 2024-02-22 20:02:45,462 - MainThread - awscli.clidriver - DEBUG - OrderedDict([('function-name', <awscli.arguments.CLIArgument object at 0x7f6e043e49d0>), ('invocation-type', <awscli.arguments.CLIArgument object at 0x7f6e043e4c10>), ('log-type', <awscli.arguments.CLIArgument object at 0x7f6e043e4dd0>), ('client-context', <awscli.arguments.CLIArgument object at 0x7f6e043e4fd0>), ('payload', <awscli.arguments.CLIArgument object at 0x7f6e043e51d0>), ('qualifier', <awscli.arguments.CLIArgument object at 0x7f6e043e5490>)])
2024-02-22T20:02:45.4630655Z 2024-02-22 20:02:45,462 - MainThread - botocore.hooks - DEBUG - Event building-argument-table.lambda.invoke: calling handler <function add_streaming_output_arg at 0x7f6e05917920>
2024-02-22T20:02:45.4631422Z 2024-02-22 20:02:45,462 - MainThread - botocore.hooks - DEBUG - Event building-argument-table.lambda.invoke: calling handler <function add_cli_input_json at 0x7f6e06b36520>
2024-02-22T20:02:45.4632177Z 2024-02-22 20:02:45,462 - MainThread - botocore.hooks - DEBUG - Event building-argument-table.lambda.invoke: calling handler <function add_cli_input_yaml at 0x7f6e06b365c0>
2024-02-22T20:02:45.4633230Z 2024-02-22 20:02:45,462 - MainThread - botocore.hooks - DEBUG - Event building-argument-table.lambda.invoke: calling handler <function unify_paging_params at 0x7f6e06342fc0>
2024-02-22T20:02:45.4744790Z 2024-02-22 20:02:45,474 - MainThread - botocore.loaders - DEBUG - Loading JSON file: /usr/local/aws-cli/v2/2.15.22/dist/awscli/botocore/data/lambda/2015-03-31/paginators-1.json
2024-02-22T20:02:45.4745556Z 2024-02-22 20:02:45,474 - MainThread - botocore.hooks - DEBUG - Event building-argument-table.lambda.invoke: calling handler <function add_generate_skeleton at 0x7f6e05f3d620>
2024-02-22T20:02:45.4746206Z 2024-02-22 20:02:45,474 - MainThread - botocore.hooks - DEBUG - Event building-command-table.lambda_invoke: calling handler <function add_waiters at 0x7f6e05921440>
2024-02-22T20:02:45.4746997Z 2024-02-22 20:02:45,474 - MainThread - botocore.hooks - DEBUG - Event building-command-table.lambda_invoke: calling handler <bound method AliasSubCommandInjector.on_building_command_table of <awscli.alias.AliasSubCommandInjector object at 0x7f6e059d81d0>>
2024-02-22T20:02:45.4754199Z 2024-02-22 20:02:45,475 - MainThread - botocore.hooks - DEBUG - Event load-cli-arg.lambda.invoke.function-name: calling handler <awscli.paramfile.URIArgumentHandler object at 0x7f6e059f7550>
2024-02-22T20:02:45.4755144Z 2024-02-22 20:02:45,475 - MainThread - botocore.hooks - DEBUG - Event process-cli-arg.lambda.invoke: calling handler <awscli.argprocess.ParamShorthandParser object at 0x7f6e06f5a190>
2024-02-22T20:02:45.4755832Z 2024-02-22 20:02:45,475 - MainThread - awscli.arguments - DEBUG - Unpacked value of '<retracted>' for parameter "function_name": '<retracted>'
2024-02-22T20:02:45.4756531Z 2024-02-22 20:02:45,475 - MainThread - botocore.hooks - DEBUG - Event load-cli-arg.lambda.invoke.invocation-type: calling handler <awscli.paramfile.URIArgumentHandler object at 0x7f6e059f7550>
2024-02-22T20:02:45.4757227Z 2024-02-22 20:02:45,475 - MainThread - botocore.hooks - DEBUG - Event process-cli-arg.lambda.invoke: calling handler <awscli.argprocess.ParamShorthandParser object at 0x7f6e06f5a190>
2024-02-22T20:02:45.4757853Z 2024-02-22 20:02:45,475 - MainThread - awscli.arguments - DEBUG - Unpacked value of 'RequestResponse' for parameter "invocation_type": 'RequestResponse'
2024-02-22T20:02:45.4758501Z 2024-02-22 20:02:45,475 - MainThread - botocore.hooks - DEBUG - Event load-cli-arg.lambda.invoke.log-type: calling handler <awscli.paramfile.URIArgumentHandler object at 0x7f6e059f7550>
2024-02-22T20:02:45.4759224Z 2024-02-22 20:02:45,475 - MainThread - botocore.hooks - DEBUG - Event load-cli-arg.lambda.invoke.client-context: calling handler <awscli.paramfile.URIArgumentHandler object at 0x7f6e059f7550>
2024-02-22T20:02:45.4759904Z 2024-02-22 20:02:45,475 - MainThread - botocore.hooks - DEBUG - Event load-cli-arg.lambda.invoke.payload: calling handler <awscli.paramfile.URIArgumentHandler object at 0x7f6e059f7550>
2024-02-22T20:02:45.4760572Z 2024-02-22 20:02:45,475 - MainThread - botocore.hooks - DEBUG - Event process-cli-arg.lambda.invoke: calling handler <awscli.argprocess.ParamShorthandParser object at 0x7f6e06f5a190>
2024-02-22T20:02:45.4761157Z 2024-02-22 20:02:45,475 - MainThread - awscli.argprocess - DEBUG - Param payload looks like JSON, not considered for param shorthand.
2024-02-22T20:02:45.4761867Z 2024-02-22 20:02:45,475 - MainThread - awscli.arguments - DEBUG - Unpacked value of '{"<retracted>": "<retracted>", "<retracted>": [ "<retracted>" ]}' for parameter "payload": '{"<retracted>": "<retracted>", "<retracted>": [ "<retracted>" ]}'
2024-02-22T20:02:45.4762600Z 2024-02-22 20:02:45,475 - MainThread - botocore.hooks - DEBUG - Event load-cli-arg.lambda.invoke.qualifier: calling handler <awscli.paramfile.URIArgumentHandler object at 0x7f6e059f7550>
2024-02-22T20:02:45.4763281Z 2024-02-22 20:02:45,475 - MainThread - botocore.hooks - DEBUG - Event load-cli-arg.lambda.invoke.outfile: calling handler <awscli.paramfile.URIArgumentHandler object at 0x7f6e059f7550>
2024-02-22T20:02:45.4763934Z 2024-02-22 20:02:45,476 - MainThread - botocore.credentials - DEBUG - Looking for credentials via: env
2024-02-22T20:02:45.4764421Z 2024-02-22 20:02:45,476 - MainThread - botocore.credentials - INFO - Found credentials in environment variables.
2024-02-22T20:02:45.4780360Z 2024-02-22 20:02:45,477 - MainThread - botocore.loaders - DEBUG - Loading JSON file: /usr/local/aws-cli/v2/2.15.22/dist/awscli/botocore/data/endpoints.json
2024-02-22T20:02:45.4952638Z 2024-02-22 20:02:45,494 - MainThread - botocore.hooks - DEBUG - Event choose-service-name: calling handler <function handle_service_name_alias at 0x7f6e0937e0c0>
2024-02-22T20:02:45.5068714Z 2024-02-22 20:02:45,506 - MainThread - botocore.loaders - DEBUG - Loading JSON file: /usr/local/aws-cli/v2/2.15.22/dist/awscli/botocore/data/lambda/2015-03-31/endpoint-rule-set-1.json
2024-02-22T20:02:45.5069616Z 2024-02-22 20:02:45,506 - MainThread - botocore.loaders - DEBUG - Loading JSON file: /usr/local/aws-cli/v2/2.15.22/dist/awscli/botocore/data/partitions.json
2024-02-22T20:02:45.5087888Z 2024-02-22 20:02:45,508 - MainThread - botocore.hooks - DEBUG - Event creating-client-class.lambda: calling handler <function add_generate_presigned_url at 0x7f6e097cc0e0>
2024-02-22T20:02:45.5089060Z 2024-02-22 20:02:45,508 - MainThread - botocore.configprovider - DEBUG - Looking for endpoint for lambda via: environment_service
2024-02-22T20:02:45.5089693Z 2024-02-22 20:02:45,508 - MainThread - botocore.configprovider - DEBUG - Looking for endpoint for lambda via: environment_global
2024-02-22T20:02:45.5090282Z 2024-02-22 20:02:45,508 - MainThread - botocore.configprovider - DEBUG - Looking for endpoint for lambda via: config_service
2024-02-22T20:02:45.5090866Z 2024-02-22 20:02:45,508 - MainThread - botocore.configprovider - DEBUG - Looking for endpoint for lambda via: config_global
2024-02-22T20:02:45.5091418Z 2024-02-22 20:02:45,508 - MainThread - botocore.configprovider - DEBUG - No configured endpoint found.
2024-02-22T20:02:45.5132558Z 2024-02-22 20:02:45,512 - MainThread - botocore.endpoint - DEBUG - Setting lambda timeout as (60000, 60000)
2024-02-22T20:02:45.5141672Z 2024-02-22 20:02:45,513 - MainThread - botocore.regions - DEBUG - Calling endpoint provider with parameters: {'Region': 'eu-west-1', 'UseDualStack': False, 'UseFIPS': False}
2024-02-22T20:02:45.5144844Z 2024-02-22 20:02:45,514 - MainThread - botocore.regions - DEBUG - Endpoint provider result: https://lambda.eu-west-1.amazonaws.com
2024-02-22T20:02:45.5146155Z 2024-02-22 20:02:45,514 - MainThread - botocore.hooks - DEBUG - Event before-parameter-build.lambda.Invoke: calling handler <function generate_idempotent_uuid at 0x7f6e09398400>
2024-02-22T20:02:45.5148372Z 2024-02-22 20:02:45,514 - MainThread - botocore.hooks - DEBUG - Event before-call.lambda.Invoke: calling handler <function inject_api_version_header_if_needed at 0x7f6e09399ee0>
2024-02-22T20:02:45.5150554Z 2024-02-22 20:02:45,514 - MainThread - botocore.endpoint - DEBUG - Making request for OperationModel(name=Invoke) with params: {'url_path': '/2015-03-31/functions/<retracted>/invocations', 'query_string': {}, 'method': 'POST', 'headers': {'X-Amz-Invocation-Type': 'RequestResponse', 'User-Agent': 'aws-cli/2.15.22 Python/3.11.6 Linux/6.2.0-1019-azure exec-env/VSTS-AWSShellScript exe/x86_64.ubuntu.22 prompt/off command/lambda.invoke'}, 'body': b'{"<retracted>": "<retracted>", "<retracted>": [ "<retracted>" ]}', 'url': 'https://lambda.eu-west-1.amazonaws.com/2015-03-31/functions/<retracted>/invocations', 'context': {'client_region': 'eu-west-1', 'client_config': <botocore.config.Config object at 0x7f6e02bd53d0>, 'has_streaming_input': True, 'auth_type': None}}
2024-02-22T20:02:45.5152257Z 2024-02-22 20:02:45,514 - MainThread - botocore.hooks - DEBUG - Event request-created.lambda.Invoke: calling handler <bound method RequestSigner.handler of <botocore.signers.RequestSigner object at 0x7f6e06759290>>
2024-02-22T20:02:45.5153335Z 2024-02-22 20:02:45,514 - MainThread - botocore.hooks - DEBUG - Event choose-signer.lambda.Invoke: calling handler <function set_operation_specific_signer at 0x7f6e093982c0>
2024-02-22T20:02:45.5153963Z 2024-02-22 20:02:45,515 - MainThread - botocore.auth - DEBUG - Calculating signature using v4 auth.
2024-02-22T20:02:45.5154455Z 2024-02-22 20:02:45,515 - MainThread - botocore.auth - DEBUG - CanonicalRequest:
2024-02-22T20:02:45.5154723Z POST
2024-02-22T20:02:45.5155080Z /2015-03-31/functions/<retracted>/invocations
2024-02-22T20:02:45.5155228Z
2024-02-22T20:02:45.5155516Z host:lambda.eu-west-1.amazonaws.com
2024-02-22T20:02:45.5155873Z x-amz-date:20240222T200245Z
2024-02-22T20:02:45.5156202Z x-amz-invocation-type:RequestResponse
2024-02-22T20:02:45.5157280Z x-amz-security-token:******
2024-02-22T20:02:45.5157768Z
2024-02-22T20:02:45.5158101Z host;x-amz-date;x-amz-invocation-type;x-amz-security-token
2024-02-22T20:02:45.5158530Z ba4cb3b62966488351785f34b8bb2b6d4fe1f743a768b48b9198cd49d41df3b5
2024-02-22T20:02:45.5158996Z 2024-02-22 20:02:45,515 - MainThread - botocore.auth - DEBUG - StringToSign:
2024-02-22T20:02:45.5159315Z AWS4-HMAC-SHA256
2024-02-22T20:02:45.5159530Z 20240222T200245Z
2024-02-22T20:02:45.5159833Z 20240222/eu-west-1/lambda/aws4_request
2024-02-22T20:02:45.5160139Z 60cd869f0aa75cb6aecf75e98abb0cf642dfffa189223a49dbf94fcf819172cf
2024-02-22T20:02:45.5160586Z 2024-02-22 20:02:45,515 - MainThread - botocore.auth - DEBUG - Signature:
2024-02-22T20:02:45.5160922Z 3b4501e06e338e7cc5c60edded9014e6a84bc5ebc63faa5353bdd9cc56f0d71a
2024-02-22T20:02:45.5163666Z 2024-02-22 20:02:45,515 - MainThread - botocore.endpoint - DEBUG - Sending http request: <AWSPreparedRequest stream_output=True, method=POST, url=https://lambda.eu-west-1.amazonaws.com/2015-03-31/functions/<retracted>/invocations, headers={'X-Amz-Invocation-Type': b'RequestResponse', 'User-Agent': b'aws-cli/2.15.22 Python/3.11.6 Linux/6.2.0-1019-azure exec-env/VSTS-AWSShellScript exe/x86_64.ubuntu.22 prompt/off command/lambda.invoke', 'X-Amz-Date': b'20240222T200245Z', 'X-Amz-Security-Token': :******', 'Authorization': b'AWS4-HMAC-SHA256 Credential=ASIA533YXZ764BU6I7LG/20240222/eu-west-1/lambda/aws4_request, SignedHeaders=host;x-amz-date;x-amz-invocation-type;x-amz-security-token, Signature=3b4501e06e338e7cc5c60edded9014e6a84bc5ebc63faa5353bdd9cc56f0d71a', 'Content-Length': '62'}>
2024-02-22T20:02:45.5165462Z 2024-02-22 20:02:45,515 - MainThread - botocore.httpsession - DEBUG - Certificate path: /usr/local/aws-cli/v2/2.15.22/dist/awscli/botocore/cacert.pem
2024-02-22T20:02:45.5166163Z 2024-02-22 20:02:45,516 - MainThread - urllib3.connectionpool - DEBUG - Starting new HTTPS connection (1): lambda.eu-west-1.amazonaws.com:443
2024-02-22T20:07:42.3679127Z 2024-02-22 20:07:42,367 - MainThread - botocore.hooks - DEBUG - Event needs-retry.lambda.Invoke: calling handler <bound method RetryHandler.needs_retry of <botocore.retries.standard.RetryHandler object at 0x7f6e02bd6ad0>>
**2024-02-22T20:07:42.3680021Z 2024-02-22 20:07:42,367 - MainThread - botocore.retries.standard - DEBUG - Retry needed, retrying request after delay of: 0.17558782454690847**
2024-02-22T20:07:42.3680671Z 2024-02-22 20:07:42,367 - MainThread - botocore.endpoint - DEBUG - Response received to retry, sleeping for 0.17558782454690847 seconds
2024-02-22T20:07:42.5445310Z 2024-02-22 20:07:42,543 - MainThread - botocore.hooks - DEBUG - Event request-created.lambda.Invoke: calling handler <bound method RequestSigner.handler of <botocore.signers.RequestSigner object at 0x7f6e06759290>>
2024-02-22T20:07:42.5454665Z 2024-02-22 20:07:42,544 - MainThread - botocore.hooks - DEBUG - Event choose-signer.lambda.Invoke: calling handler <function set_operation_specific_signer at 0x7f6e093982c0>
2024-02-22T20:07:42.5455427Z 2024-02-22 20:07:42,544 - MainThread - botocore.auth - DEBUG - Calculating signature using v4 auth.
2024-02-22T20:07:42.5455935Z 2024-02-22 20:07:42,544 - MainThread - botocore.auth - DEBUG - CanonicalRequest:
2024-02-22T20:07:42.5456211Z POST
2024-02-22T20:07:42.5456575Z /2015-03-31/functions/<retracted>/invocations
2024-02-22T20:07:42.5456740Z
2024-02-22T20:07:42.5460001Z host:lambda.eu-west-1.amazonaws.com
2024-02-22T20:07:42.5460431Z x-amz-date:20240222T200742Z
2024-02-22T20:07:42.5460789Z x-amz-invocation-type:RequestResponse
2024-02-22T20:07:42.5461867Z x-amz-security-token::******
2024-02-22T20:07:42.5462719Z
2024-02-22T20:07:42.5463076Z host;x-amz-date;x-amz-invocation-type;x-amz-security-token
2024-02-22T20:07:42.5463418Z ba4cb3b62966488351785f34b8bb2b6d4fe1f743a768b48b9198cd49d41df3b5
2024-02-22T20:07:42.5463882Z 2024-02-22 20:07:42,544 - MainThread - botocore.auth - DEBUG - StringToSign:
2024-02-22T20:07:42.5464208Z AWS4-HMAC-SHA256
2024-02-22T20:07:42.5464428Z 20240222T200742Z
2024-02-22T20:07:42.5464734Z 20240222/eu-west-1/lambda/aws4_request
2024-02-22T20:07:42.5465039Z 44842e8184eeacf8748caa0775e11ccdf74a99808f5f8ba891ec5e9692075c7c
2024-02-22T20:07:42.5465478Z 2024-02-22 20:07:42,544 - MainThread - botocore.auth - DEBUG - Signature:
2024-02-22T20:07:42.5465819Z b6b86359a4d4de42bdc639bec64b4456be3658762bf620577a2700c0072a8eb0
2024-02-22T20:07:42.5468563Z 2024-02-22 20:07:42,544 - MainThread - botocore.endpoint - DEBUG - Sending http request: <AWSPreparedRequest stream_output=True, method=POST, url=https://lambda.eu-west-1.amazonaws.com/2015-03-31/functions/<retracted>/invocations, headers={'X-Amz-Invocation-Type': b'RequestResponse', 'User-Agent': b'aws-cli/2.15.22 Python/3.11.6 Linux/6.2.0-1019-azure exec-env/VSTS-AWSShellScript exe/x86_64.ubuntu.22 prompt/off command/lambda.invoke', 'X-Amz-Date': b'20240222T200742Z', 'X-Amz-Security-Token': b':******', 'Authorization': b'AWS4-HMAC-SHA256 Credential=ASIA533YXZ764BU6I7LG/20240222/eu-west-1/lambda/aws4_request, SignedHeaders=host;x-amz-date;x-amz-invocation-type;x-amz-security-token, Signature=b6b86359a4d4de42bdc639bec64b4456be3658762bf620577a2700c0072a8eb0', 'Content-Length': '62'}>
2024-02-22T20:07:42.5470369Z 2024-02-22 20:07:42,544 - MainThread - botocore.httpsession - DEBUG - Certificate path: /usr/local/aws-cli/v2/2.15.22/dist/awscli/botocore/cacert.pem
2024-02-22T20:07:42.5471044Z 2024-02-22 20:07:42,545 - MainThread - urllib3.connectionpool - DEBUG - Starting new HTTPS connection (2): lambda.eu-west-1.amazonaws.com:443
2024-02-22T20:12:51.0704622Z 2024-02-22 20:12:51,069 - MainThread - botocore.hooks - DEBUG - Event needs-retry.lambda.Invoke: calling handler <bound method RetryHandler.needs_retry of <botocore.retries.standard.RetryHandler object at 0x7f6e02bd6ad0>>
2024-02-22T20:12:51.0707739Z 2024-02-22 20:12:51,069 - MainThread - botocore.retries.standard - DEBUG - Retry needed, retrying request after delay of: 0.8365010397694674
2024-02-22T20:12:51.0708528Z 2024-02-22 20:12:51,070 - MainThread - botocore.endpoint - DEBUG - Response received to retry, sleeping for 0.8365010397694674 seconds
2024-02-22T20:12:51.9078956Z 2024-02-22 20:12:51,906 - MainThread - botocore.hooks - DEBUG - Event request-created.lambda.Invoke: calling handler <bound method RequestSigner.handler of <botocore.signers.RequestSigner object at 0x7f6e06759290>>
2024-02-22T20:12:51.9079929Z 2024-02-22 20:12:51,907 - MainThread - botocore.hooks - DEBUG - Event choose-signer.lambda.Invoke: calling handler <function set_operation_specific_signer at 0x7f6e093982c0>
2024-02-22T20:12:51.9080548Z 2024-02-22 20:12:51,907 - MainThread - botocore.auth - DEBUG - Calculating signature using v4 auth.
2024-02-22T20:12:51.9081042Z 2024-02-22 20:12:51,907 - MainThread - botocore.auth - DEBUG - CanonicalRequest:
2024-02-22T20:12:51.9081339Z POST
2024-02-22T20:12:51.9081695Z /2015-03-31/functions/<retracted>/invocations
2024-02-22T20:12:51.9091002Z
2024-02-22T20:12:51.9091961Z host:lambda.eu-west-1.amazonaws.com
2024-02-22T20:12:51.9092377Z x-amz-date:20240222T201251Z
2024-02-22T20:12:51.9093021Z x-amz-invocation-type:RequestResponse
2024-02-22T20:12:51.9094268Z x-amz-security-token::******
2024-02-22T20:12:51.9094881Z
2024-02-22T20:12:51.9095230Z host;x-amz-date;x-amz-invocation-type;x-amz-security-token
2024-02-22T20:12:51.9095569Z ba4cb3b62966488351785f34b8bb2b6d4fe1f743a768b48b9198cd49d41df3b5
2024-02-22T20:12:51.9096024Z 2024-02-22 20:12:51,907 - MainThread - botocore.auth - DEBUG - StringToSign:
2024-02-22T20:12:51.9096355Z AWS4-HMAC-SHA256
2024-02-22T20:12:51.9096573Z 20240222T201251Z
2024-02-22T20:12:51.9096880Z 20240222/eu-west-1/lambda/aws4_request
2024-02-22T20:12:51.9097186Z 8fbd86d103fed374b0747bd007dc98e6ed647b9caed5c85a8bcf1bfb1268cc39
2024-02-22T20:12:51.9097667Z 2024-02-22 20:12:51,907 - MainThread - botocore.auth - DEBUG - Signature:
2024-02-22T20:12:51.9098006Z de86d7af65f66876fc5a176204c27b3abdfc5e5bde8075ffe5db5895e520888c
2024-02-22T20:12:51.9100711Z 2024-02-22 20:12:51,908 - MainThread - botocore.endpoint - DEBUG - Sending http request: <AWSPreparedRequest stream_output=True, method=POST, url=https://lambda.eu-west-1.amazonaws.com/2015-03-31/functions/<retracted>/invocations, headers={'X-Amz-Invocation-Type': b'RequestResponse', 'User-Agent': b'aws-cli/2.15.22 Python/3.11.6 Linux/6.2.0-1019-azure exec-env/VSTS-AWSShellScript exe/x86_64.ubuntu.22 prompt/off command/lambda.invoke', 'X-Amz-Date': b'20240222T201251Z', 'X-Amz-Security-Token': :******', 'Authorization': b'AWS4-HMAC-SHA256 Credential=ASIA533YXZ764BU6I7LG/20240222/eu-west-1/lambda/aws4_request, SignedHeaders=host;x-amz-date;x-amz-invocation-type;x-amz-security-token, Signature=de86d7af65f66876fc5a176204c27b3abdfc5e5bde8075ffe5db5895e520888c', 'Content-Length': '62'}>
2024-02-22T20:12:51.9102501Z 2024-02-22 20:12:51,908 - MainThread - botocore.httpsession - DEBUG - Certificate path: /usr/local/aws-cli/v2/2.15.22/dist/awscli/botocore/cacert.pem
2024-02-22T20:12:51.9103197Z 2024-02-22 20:12:51,908 - MainThread - urllib3.connectionpool - DEBUG - Starting new HTTPS connection (3): lambda.eu-west-1.amazonaws.com:443
2024-02-22T20:17:38.0672165Z 2024-02-22 20:17:38,066 - MainThread - botocore.hooks - DEBUG - Event needs-retry.lambda.Invoke: calling handler <bound method RetryHandler.needs_retry of <botocore.retries.standard.RetryHandler object at 0x7f6e02bd6ad0>>
2024-02-22T20:17:38.0674621Z 2024-02-22 20:17:38,066 - MainThread - botocore.retries.standard - DEBUG - Max attempts of 3 reached.
2024-02-22T20:17:38.0675273Z 2024-02-22 20:17:38,066 - MainThread - botocore.retries.standard - DEBUG - Not retrying request.
2024-02-22T20:17:38.0696121Z 2024-02-22 20:17:38,066 - MainThread - awscli.clidriver - DEBUG - Exception caught in main()
2024-02-22T20:17:38.0696547Z Traceback (most recent call last):
2024-02-22T20:17:38.0696842Z   File "urllib3/connectionpool.py", line 715, in urlopen
2024-02-22T20:17:38.0697154Z   File "urllib3/connectionpool.py", line 467, in _make_request
2024-02-22T20:17:38.0700129Z   File "<string>", line 3, in raise_from
2024-02-22T20:17:38.0700498Z   File "urllib3/connectionpool.py", line 462, in _make_request
2024-02-22T20:17:38.0700817Z   File "http/client.py", line 1378, in getresponse
2024-02-22T20:17:38.0701095Z   File "http/client.py", line 318, in begin
2024-02-22T20:17:38.0701373Z   File "http/client.py", line 287, in _read_status
2024-02-22T20:17:38.0708835Z http.client.RemoteDisconnected: Remote end closed connection without response
2024-02-22T20:17:38.0709320Z
2024-02-22T20:17:38.0709589Z During handling of the above exception, another exception occurred:
2024-02-22T20:17:38.0709733Z
2024-02-22T20:17:38.0709946Z Traceback (most recent call last):
2024-02-22T20:17:38.0710242Z   File "awscli/botocore/httpsession.py", line 448, in send
2024-02-22T20:17:38.0710550Z   File "urllib3/connectionpool.py", line 799, in urlopen
2024-02-22T20:17:38.0710846Z   File "urllib3/util/retry.py", line 525, in increment
2024-02-22T20:17:38.0711139Z   File "urllib3/packages/six.py", line 769, in reraise
2024-02-22T20:17:38.0711433Z   File "urllib3/connectionpool.py", line 715, in urlopen
2024-02-22T20:17:38.0711754Z   File "urllib3/connectionpool.py", line 467, in _make_request
2024-02-22T20:17:38.0712039Z   File "<string>", line 3, in raise_from
2024-02-22T20:17:38.0712324Z   File "urllib3/connectionpool.py", line 462, in _make_request
2024-02-22T20:17:38.0712631Z   File "http/client.py", line 1378, in getresponse
2024-02-22T20:17:38.0712908Z   File "http/client.py", line 318, in begin
2024-02-22T20:17:38.0713180Z   File "http/client.py", line 287, in _read_status
2024-02-22T20:17:38.0713766Z urllib3.exceptions.ProtocolError: ('Connection aborted.', RemoteDisconnected('Remote end closed connection without response'))
2024-02-22T20:17:38.0713981Z
2024-02-22T20:17:38.0714239Z During handling of the above exception, another exception occurred:
2024-02-22T20:17:38.0731243Z
2024-02-22T20:17:38.0732875Z Traceback (most recent call last):
2024-02-22T20:17:38.0733176Z   File "awscli/clidriver.py", line 460, in main
2024-02-22T20:17:38.0733637Z   File "awscli/clidriver.py", line 595, in __call__
2024-02-22T20:17:38.0733888Z   File "awscli/clidriver.py", line 798, in __call__
2024-02-22T20:17:38.0734141Z   File "awscli/clidriver.py", line 929, in invoke
2024-02-22T20:17:38.0734392Z   File "awscli/clidriver.py", line 941, in _make_client_call
2024-02-22T20:17:38.0734659Z   File "awscli/botocore/client.py", line 357, in _api_call
2024-02-22T20:17:38.0734933Z   File "awscli/botocore/client.py", line 710, in _make_api_call
2024-02-22T20:17:38.0735200Z   File "awscli/botocore/client.py", line 730, in _make_request
2024-02-22T20:17:38.0735470Z   File "awscli/botocore/endpoint.py", line 101, in make_request
2024-02-22T20:17:38.0735744Z   File "awscli/botocore/endpoint.py", line 155, in _send_request
2024-02-22T20:17:38.0736022Z   File "awscli/botocore/endpoint.py", line 199, in _do_get_response
2024-02-22T20:17:38.0736289Z   File "awscli/botocore/endpoint.py", line 271, in _send
2024-02-22T20:17:38.0736556Z   File "awscli/botocore/httpsession.py", line 487, in send
2024-02-22T20:17:38.0737277Z botocore.exceptions.ConnectionClosedError: Connection was closed before we received a valid response from endpoint URL: "https://lambda.eu-west-1.amazonaws.com/2015-03-31/functions/<retracted>/invocations".
2024-02-22T20:17:38.0737869Z
2024-02-22T20:17:38.0738408Z Connection was closed before we received a valid response from endpoint URL: "https://lambda.eu-west-1.amazonaws.com/2015-03-31/functions/<retracted>/invocations".

Reproduction Steps

  • Lambda that runs for 5+ minutes
  • Invocation through aws-cli v2
  • Invocation type is RequestResponse
  • Read and connection timeout are configured for at least the timeout of the lambda (in my case 10 minutes)

Possible Solution

No response

Additional Information/Context

We run the CLI command from an Azure pipeline agent.

CLI version used

aws-cli/2.15.22 Python/3.11.6

Environment details (OS name and version, etc.)

Linux/6.2.0-1019-azure exe/x86_64.ubuntu.22
@Hodir22 Hodir22 added bug This issue is a bug. needs-triage This issue or PR still needs to be triaged. labels Feb 22, 2024
@RyanFitzSimmonsAK RyanFitzSimmonsAK self-assigned this May 3, 2024
@RyanFitzSimmonsAK RyanFitzSimmonsAK added lambda p2 This is a standard priority issue investigating This issue is being investigated and/or work is in progress to resolve the issue. and removed needs-triage This issue or PR still needs to be triaged. labels May 3, 2024
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Assignees

@RyanFitzSimmonsAK RyanFitzSimmonsAK

Labels
bug This issue is a bug. investigating This issue is being investigated and/or work is in progress to resolve the issue. lambda p2 This is a standard priority issue
Projects
None yet
Milestone
No milestone
Development

No branches or pull requests
2 participants
@RyanFitzSimmonsAK @Hodir22