diff --git a/samcli/commands/deploy/command.py b/samcli/commands/deploy/command.py index d349f0b660..1a31d0d6f8 100644 --- a/samcli/commands/deploy/command.py +++ b/samcli/commands/deploy/command.py @@ -2,6 +2,7 @@ CLI command for "deploy" command """ import logging +import os import click @@ -43,6 +44,10 @@ HELP_TEXT = """The sam deploy command creates a Cloudformation Stack and deploys your resources. +\b +Set SAM_CLI_POLL_DELAY Environment Vairable with a value of seconds in your shell to configure +how often SAM CLI checks the Stack state, which is useful when seeing throttling from CloudFormation. + \b e.g. sam deploy --template-file packaged.yaml --stack-name sam-app --capabilities CAPABILITY_IAM @@ -290,6 +295,15 @@ def do_cli( ) as package_context: package_context.run() + # 500ms of sleep time between stack checks and describe stack events. + DEFAULT_POLL_DELAY = 0.5 + try: + poll_delay = float(os.getenv("SAM_CLI_POLL_DELAY", str(DEFAULT_POLL_DELAY))) + except ValueError: + poll_delay = DEFAULT_POLL_DELAY + if poll_delay <= 0: + poll_delay = DEFAULT_POLL_DELAY + with DeployContext( template_file=output_template_file.name, stack_name=guided_context.guided_stack_name if guided else stack_name, @@ -315,5 +329,6 @@ def do_cli( signing_profiles=guided_context.signing_profiles if guided else signing_profiles, use_changeset=True, disable_rollback=guided_context.disable_rollback if guided else disable_rollback, + poll_delay=poll_delay, ) as deploy_context: deploy_context.run() diff --git a/samcli/commands/deploy/deploy_context.py b/samcli/commands/deploy/deploy_context.py index dfb77045c3..25d6068944 100644 --- a/samcli/commands/deploy/deploy_context.py +++ b/samcli/commands/deploy/deploy_context.py @@ -72,6 +72,7 @@ def __init__( signing_profiles, use_changeset, disable_rollback, + poll_delay, ): self.template_file = template_file self.stack_name = stack_name @@ -101,6 +102,7 @@ def __init__( self.signing_profiles = signing_profiles self.use_changeset = use_changeset self.disable_rollback = disable_rollback + self.poll_delay = poll_delay def __enter__(self): return self @@ -142,7 +144,7 @@ def run(self): s3_client, self.s3_bucket, self.s3_prefix, self.kms_key_id, self.force_upload, self.no_progressbar ) - self.deployer = Deployer(cloudformation_client) + self.deployer = Deployer(cloudformation_client, client_sleep=self.poll_delay) region = s3_client._client_config.region_name if s3_client else self.region # pylint: disable=W0212 display_parameter_overrides = hide_noecho_parameter_overrides(template_dict, self.parameter_overrides) diff --git a/samcli/commands/sync/command.py b/samcli/commands/sync/command.py index 43ce1a451e..76c53d5650 100644 --- a/samcli/commands/sync/command.py +++ b/samcli/commands/sync/command.py @@ -296,6 +296,15 @@ def do_cli( force_upload=True, ) as package_context: + # 500ms of sleep time between stack checks and describe stack events. + DEFAULT_POLL_DELAY = 0.5 + try: + poll_delay = float(os.getenv("SAM_CLI_POLL_DELAY", str(DEFAULT_POLL_DELAY))) + except ValueError: + poll_delay = DEFAULT_POLL_DELAY + if poll_delay <= 0: + poll_delay = DEFAULT_POLL_DELAY + with DeployContext( template_file=output_template_file.name, stack_name=stack_name, @@ -319,6 +328,7 @@ def do_cli( force_upload=True, signing_profiles=None, disable_rollback=False, + poll_delay=poll_delay, ) as deploy_context: if watch: execute_watch(template_file, build_context, package_context, deploy_context, dependency_layer) diff --git a/samcli/lib/deploy/deployer.py b/samcli/lib/deploy/deployer.py index 97a8e7c32d..6170232e36 100644 --- a/samcli/lib/deploy/deployer.py +++ b/samcli/lib/deploy/deployer.py @@ -72,13 +72,20 @@ OUTPUTS_TABLE_HEADER_NAME = "CloudFormation outputs from deployed stack" +# 500ms of sleep time between stack checks and describe stack events. +DEFAULT_CLIENT_SLEEP = 0.5 + class Deployer: - def __init__(self, cloudformation_client, changeset_prefix="samcli-deploy"): + def __init__(self, cloudformation_client, changeset_prefix="samcli-deploy", client_sleep=DEFAULT_CLIENT_SLEEP): self._client = cloudformation_client self.changeset_prefix = changeset_prefix - # 500ms of sleep time between stack checks and describe stack events. - self.client_sleep = 0.5 + try: + self.client_sleep = float(client_sleep) + except ValueError: + self.client_sleep = DEFAULT_CLIENT_SLEEP + if self.client_sleep <= 0: + self.client_sleep = DEFAULT_CLIENT_SLEEP # 2000ms of backoff time which is exponentially used, when there are exceptions during describe stack events self.backoff = 2 # Maximum number of attempts before raising exception back up the chain. @@ -409,6 +416,8 @@ def describe_stack_events(self, stack_name, time_stamp_marker, **kwargs): if self._check_stack_not_in_progress(stack_status): stack_change_in_progress = False break + # Reset retry attempts if iteration is a success to use client_sleep again + retry_attempts = 0 except botocore.exceptions.ClientError as ex: retry_attempts = retry_attempts + 1 if retry_attempts > self.max_attempts: diff --git a/tests/unit/commands/deploy/test_command.py b/tests/unit/commands/deploy/test_command.py index cf620a844a..e46bdf99b7 100644 --- a/tests/unit/commands/deploy/test_command.py +++ b/tests/unit/commands/deploy/test_command.py @@ -1,3 +1,4 @@ +import os from unittest import TestCase from unittest.mock import ANY, MagicMock, Mock, call, patch @@ -63,6 +64,7 @@ def setUp(self): def tearDown(self): self.companion_stack_manager_patch.stop() + @patch("os.environ", {**os.environ, "SAM_CLI_POLL_DELAY": 10}) @patch("samcli.commands.package.command.click") @patch("samcli.commands.package.package_context.PackageContext") @patch("samcli.commands.deploy.command.click") @@ -126,6 +128,7 @@ def test_all_args(self, mock_deploy_context, mock_deploy_click, mock_package_con signing_profiles=self.signing_profiles, use_changeset=self.use_changeset, disable_rollback=self.disable_rollback, + poll_delay=10, ) context_mock.run.assert_called_with() @@ -332,6 +335,7 @@ def test_all_args_guided( signing_profiles=self.signing_profiles, use_changeset=self.use_changeset, disable_rollback=True, + poll_delay=0.5, ) context_mock.run.assert_called_with() @@ -479,6 +483,7 @@ def test_all_args_guided_no_save_echo_param_to_config( signing_profiles=self.signing_profiles, use_changeset=self.use_changeset, disable_rollback=True, + poll_delay=0.5, ) context_mock.run.assert_called_with() @@ -630,6 +635,7 @@ def test_all_args_guided_no_params_save_config( signing_profiles=self.signing_profiles, use_changeset=self.use_changeset, disable_rollback=True, + poll_delay=0.5, ) context_mock.run.assert_called_with() @@ -766,6 +772,7 @@ def test_all_args_guided_no_params_no_save_config( signing_profiles=self.signing_profiles, use_changeset=self.use_changeset, disable_rollback=self.disable_rollback, + poll_delay=0.5, ) context_mock.run.assert_called_with() @@ -839,6 +846,7 @@ def test_all_args_resolve_s3( signing_profiles=self.signing_profiles, use_changeset=self.use_changeset, disable_rollback=self.disable_rollback, + poll_delay=0.5, ) context_mock.run.assert_called_with() @@ -950,6 +958,7 @@ def test_all_args_resolve_image_repos( signing_profiles=self.signing_profiles, use_changeset=True, disable_rollback=self.disable_rollback, + poll_delay=0.5, ) context_mock.run.assert_called_with() diff --git a/tests/unit/commands/deploy/test_deploy_context.py b/tests/unit/commands/deploy/test_deploy_context.py index a4bb034b1d..fe01ff57e4 100644 --- a/tests/unit/commands/deploy/test_deploy_context.py +++ b/tests/unit/commands/deploy/test_deploy_context.py @@ -33,6 +33,7 @@ def setUp(self): signing_profiles=None, use_changeset=True, disable_rollback=False, + poll_delay=0.5, ) def test_template_improper(self): @@ -183,6 +184,7 @@ def test_sync(self, patched_get_buildable_stacks, patched_auth_required, patched signing_profiles=None, use_changeset=False, disable_rollback=False, + poll_delay=0.5, ) patched_get_buildable_stacks.return_value = (Mock(), []) patched_auth_required.return_value = [("HelloWorldFunction", False)] diff --git a/tests/unit/commands/sync/test_command.py b/tests/unit/commands/sync/test_command.py index ef59d39e98..2c041fd995 100644 --- a/tests/unit/commands/sync/test_command.py +++ b/tests/unit/commands/sync/test_command.py @@ -1,3 +1,4 @@ +import os from unittest import TestCase from unittest.mock import ANY, MagicMock, Mock, patch from parameterized import parameterized @@ -47,6 +48,7 @@ def setUp(self): MOCK_SAM_CONFIG.reset_mock() @parameterized.expand([(False, False, True), (False, False, False)]) + @patch("os.environ", {**os.environ, "SAM_CLI_POLL_DELAY": 10}) @patch("samcli.commands.sync.command.update_experimental_context") @patch("samcli.commands.sync.command.click") @patch("samcli.commands.sync.command.execute_code_sync") @@ -166,6 +168,7 @@ def test_infra_must_succeed_sync( force_upload=True, signing_profiles=None, disable_rollback=False, + poll_delay=10, ) build_context_mock.run.assert_called_once_with() package_context_mock.run.assert_called_once_with() @@ -291,6 +294,7 @@ def test_watch_must_succeed_sync( force_upload=True, signing_profiles=None, disable_rollback=False, + poll_delay=0.5, ) execute_watch_mock.assert_called_once_with( self.template_file, build_context_mock, package_context_mock, deploy_context_mock, auto_dependency_layer diff --git a/tests/unit/lib/deploy/test_deployer.py b/tests/unit/lib/deploy/test_deployer.py index 72d5da3b10..6f8895646a 100644 --- a/tests/unit/lib/deploy/test_deployer.py +++ b/tests/unit/lib/deploy/test_deployer.py @@ -1,6 +1,7 @@ from logging import captureWarnings import uuid import time +import math from datetime import datetime, timedelta from unittest import TestCase from unittest.mock import patch, MagicMock, ANY, call @@ -57,6 +58,26 @@ def test_deployer_init(self): self.assertEqual(self.deployer._client, self.cloudformation_client) self.assertEqual(self.deployer.changeset_prefix, "samcli-deploy") + def test_deployer_init_custom_sleep(self): + deployer = Deployer(MagicMock().client("cloudformation"), client_sleep=10) + self.assertEqual(deployer.client_sleep, 10) + + def test_deployer_init_custom_sleep_invalid(self): + deployer = Deployer(MagicMock().client("cloudformation"), client_sleep="INVALID") + self.assertEqual(deployer.client_sleep, 0.5) # 0.5 is the default value + + def test_deployer_init_custom_sleep_negative(self): + deployer = Deployer(MagicMock().client("cloudformation"), client_sleep=-5) + self.assertEqual(deployer.client_sleep, 0.5) # 0.5 is the default value + + def test_deployer_init_custom_sleep_zero(self): + deployer = Deployer(MagicMock().client("cloudformation"), client_sleep=0) + self.assertEqual(deployer.client_sleep, 0.5) # 0.5 is the default value + + def test_deployer_init_default_sleep(self): + deployer = Deployer(MagicMock().client("cloudformation")) + self.assertEqual(deployer.client_sleep, 0.5) + def test_deployer_has_no_stack(self): self.deployer._client.describe_stacks = MagicMock(return_value={"Stacks": []}) self.assertEqual(self.deployer.has_stack("test"), False) @@ -595,6 +616,79 @@ def test_describe_stack_events_resume_after_exceptions(self, patched_time, patch self.assertEqual(patched_math.pow.call_count, 3) self.assertEqual(patched_math.pow.call_args_list, [call(2, 1), call(2, 2), call(2, 3)]) + @patch("samcli.lib.deploy.deployer.math.pow", wraps=math.pow) + @patch("time.sleep") + def test_describe_stack_events_reset_retry_on_success_after_exceptions(self, patched_time, patched_pow): + current_timestamp = datetime.utcnow() + + self.deployer._client.describe_stacks = MagicMock( + side_effect=[ + {"Stacks": [{"StackStatus": "CREATE_IN_PROGRESS"}]}, + ClientError( + error_response={"Error": {"Message": "Rate Exceeded"}}, operation_name="describe_stack_events" + ), + ClientError( + error_response={"Error": {"Message": "Rate Exceeded"}}, operation_name="describe_stack_events" + ), + {"Stacks": [{"StackStatus": "CREATE_IN_PROGRESS"}]}, + ClientError( + error_response={"Error": {"Message": "Rate Exceeded"}}, operation_name="describe_stack_events" + ), + {"Stacks": [{"StackStatus": "CREATE_COMPLETE"}]}, + ] + ) + + self.deployer._client.get_paginator = MagicMock( + return_value=MockPaginator( + [ + { + "StackEvents": [ + { + "EventId": str(uuid.uuid4()), + "Timestamp": current_timestamp, + "ResourceStatus": "CREATE_IN_PROGRESS", + "ResourceType": "s3", + "LogicalResourceId": "mybucket", + } + ] + }, + { + "StackEvents": [ + { + "EventId": str(uuid.uuid4()), + "Timestamp": current_timestamp, + "ResourceStatus": "CREATE_IN_PROGRESS", + "ResourceType": "kms", + "LogicalResourceId": "mykms", + } + ] + }, + { + "StackEvents": [ + { + "EventId": str(uuid.uuid4()), + "Timestamp": current_timestamp, + "ResourceStatus": "CREATE_COMPLETE", + "ResourceType": "s3", + "LogicalResourceId": "mybucket", + } + ] + }, + ] + ) + ) + + self.deployer.describe_stack_events("test", time.time()) + + # There are 2 sleep call for exceptions (backoff + regular one at 0) + self.assertEqual(patched_time.call_count, 9) + self.assertEqual( + patched_time.call_args_list, + [call(0.5), call(0.5), call(2.0), call(0), call(4.0), call(0), call(0.5), call(2.0), call(0)], + ) + self.assertEqual(patched_pow.call_count, 3) + self.assertEqual(patched_pow.call_args_list, [call(2, 1), call(2, 2), call(2, 1)]) + def test_check_stack_status(self): self.assertEqual(self.deployer._check_stack_not_in_progress("CREATE_COMPLETE"), True) self.assertEqual(self.deployer._check_stack_not_in_progress("CREATE_FAILED"), True)