Times out on successful command

[bryan-aguilar]

Describe the bug
We execute a multi line command whose final step is a terraform apply. We have seen behavior where the terraform apply will be successful but it will hang and then timeout. On the second retry no modifications need to be made by terraform and the terraform apply is instantly successful. We run a 1hr timeout. This leads to us seeing step times of approximately 1hr 5min. An example can be seen here.

Expected behavior
The first successful attempts actually exits and does not run a second time.

Screenshots

Logs
Relevant snippet I believe. End of first job where timeout happens

[0].subsegments[0].name=S3, [0].subsegments[0].id=26e9b8ff08beec05, [0].subsegments[0].start_time=1663030769.297894, [0].subsegments[0].end_time=1663030769.433909, [0].subsegments[0].namespace=aws, [0].subsegments[0].http.request.url=https://s3.us-west-2.amazonaws.com/, [0].subsegments[0].http.request.method=GET, [0].subsegments[0].http.request.user_agent=aws-sdk-java/2.14.26 Linux/5.10.130-118.517.amzn2.x86_64 OpenJDK_64-Bit_Server_VM/11.0.13+8-LTS Java/11.0.13 vendor/Amazon.com_Inc. io/sync http/Apache, [0].subsegments[0].http.response.status=200, [0].subsegments[0].http.response.content_length=0, [0].subsegments[0].aws.account_id=***, [0].subsegments[0].aws.ec2.availability_zone=us-west-2b, [0].subsegments[0].aws.ec2.instance_id=i-052772479814f11e3, [0].subsegments[0].aws.ec2.instance_size=t3.medium, [0].subsegments[0].aws.ec2.ami_id=ami-0c2ab3b8efb09f272, [0].subsegments[0].aws.xray.auto_instrumentation=true, [0].subsegments[0].aws.xray.sdk_version=1.4.1, [0].subsegments[0].aws.xray.sdk=opentelemetry for java, [0].subsegments[0].aws.operation=ListBuckets, [0].subsegments[0].aws.request_id=QGSXWT0YZR85BQD5, [0].subsegments[0].metadata.default[\"net.transport\"]=ip_tcp, [0].subsegments[0].metadata.default[\"http.flavor\"]=1.1, [0].subsegments[0].metadata.default[\"aws.service\"]=S3, [0].subsegments[0].metadata.default[\"aws.agent\"]=java-aws-sdk, [0].subsegments[0].metadata.default[\"thread.name\"]=qtp1768416789-30, [0].subsegments[0].metadata.default[\"thread.id\"]=30, [0].http.request.url=http://18.237.1.202:8080/aws-sdk-call, [0].http.request.method=GET, [0].http.request.user_agent=okhttp/4.9.3, [0].http.request.client_ip=20.124.198.204, [0].http.request.x_forwarded_for=true, [0].http.response.status=200, [0].http.response.content_length=0, [0].aws.account_id=***, [0].aws.ec2.availability_zone=us-west-2b, [0].aws.ec2.instance_id=i-052772479814f11e3, [0].aws.ec2.instance_size=t3.medium, [0].aws.ec2.ami_id=ami-0c2ab3b8efb09f272, [0].aws.xray.auto_instrumentation=true, [0].aws.xray.sdk_version=1.4.1, [0].aws.xray.sdk=opentelemetry for java, [0].metadata.default[\"http.flavor\"]=1.1, [0].metadata.default[\"otel.resource.host.arch\"]=amd64, [0].metadata.default[\"otel.resource.host.name\"]=99a5ab526dc5, [0].metadata.default[\"thread.name\"]=qtp1768416789-30, [0].metadata.default[\"otel.resource.service.name\"]=aws-otel-integ-test, [0].metadata.default[\"otel.resource.telemetry.auto.version\"]=1.4.1-aws, [0].metadata.default[\"otel.resource.process.pid\"]=1, [0].metadata.default[\"otel.resource.os.description\"]=Linux 5.10.130-118.517.amzn2.x86_64, [0].metadata.default[\"otel.resource.os.type\"]=linux, [0].metadata.default[\"otel.resource.cloud.region\"]=us-west-2, [0].metadata.default[\"otel.resource.host.type\"]=t3.medium, [0].metadata.default[\"thread.id\"]=30, [0].metadata.default[\"otel.resource.telemetry.sdk.name\"]=opentelemetry, [0].metadata.default[\"otel.resource.cloud.availability_zone\"]=us-west-2b, [0].metadata.default[\"otel.resource.host.image.id\"]=ami-0c2ab3b8efb09f272, [0].metadata.default[\"otel.resource.process.runtime.description\"]=Amazon.com Inc. OpenJDK 64-Bit Server VM 11.0.13+8-LTS, [0].metadata.default[\"otel.resource.process.runtime.version\"]=11.0.13+8-LTS, [0].metadata.default[\"otel.resource.host.id\"]=i-052772479814f11e3, [0].metadata.default[\"otel.resource.process.command_line\"]=/usr/lib/jvm/java-11-amazon-corretto:bin:java -javaagent:/app/aws-opentelemetry-agent.jar -Dotel.imr.export.interval=1000, [0].metadata.default[\"otel.resource.service.namespace\"]=aws-otel, [0].metadata.default[\"otel.resource.cloud.account.id\"]=***, [0].metadata.default[\"otel.resource.process.executable.path\"]=/usr/lib/jvm/java-11-amazon-corretto:bin:java, [0].metadata.default[\"otel.resource.telemetry.sdk.version\"]=1.4.1, [0].metadata.default[\"otel.resource.process.runtime.name\"]=OpenJDK Runtime Environment, [0].metadata.default[\"otel.resource.telemetry.sdk.language\"]=java, [0].metadata.default[\"otel.resource.cloud.provider\"]=aws, [1].name=S3, [1].id=145b65ee2d26ccb3, [1].parent_id=26e9b8ff08beec05, [1].start_time=1663030769.297894, [1].origin=AWS::S3, [1].trace_id=1-631fd5f1-f6e22f0b485b4b90971c0b96, [1].end_time=1663030769.433909, [1].inferred=true, [1].http.request.url=https://s3.us-west-2.amazonaws.com/, [1].http.request.method=GET, [1].http.request.user_agent=aws-sdk-java/2.14.26 Linux/5.10.130-118.517.amzn2.x86_64 OpenJDK_64-Bit_Server_VM/11.0.13+8-LTS Java/11.0.13 vendor/Amazon.com_Inc. io/sync http/Apache, [1].http.response.status=200, [1].http.response.content_length=0, [1].aws.account_id=***, [1].aws.ec2.availability_zone=us-west-2b, [1].aws.ec2.instance_id=i-052772479814f11e3, [1].aws.ec2.instance_size=t3.medium, [1].aws.ec2.ami_id=ami-0c2ab3b8efb09f272, [1].aws.xray.auto_instrumentation=true, [1].aws.xray.sdk_version=1.4.1, [1].aws.xray.sdk=opentelemetry for java, [1].aws.operation=ListBuckets, [1].aws.request_id=QGSXWT0YZR85BQD5}
2022-09-13T00:59:49.9429542Z �[0m�[0mmodule.ec2_setup.module.validator[0].null_resource.validator (local-exec): �[36mvalidator_1  |�[0m 00:59:49.928 [main] INFO  com.amazon.aoc.validators.TraceValidator - validation is passed for path /aws-sdk-call
2022-09-13T00:59:50.3206283Z �[0m�[0mmodule.ec2_setup.module.validator[0].null_resource.validator (local-exec): �[36mvalidator_1  |�[0m 00:59:50.318 [main] INFO  com.amazon.aoc.App - Validation has completed in 32 minutes.
2022-09-13T00:59:50.4545544Z �[0m�[0mmodule.ec2_setup.module.validator[0].null_resource.validator (local-exec): �[36mcanary_validator_1 exited with code 0
2022-09-13T00:59:50.4681435Z �[0m�[0mmodule.ec2_setup.module.validator[0].null_resource.validator (local-exec): �[0mAborting on container exit...
2022-09-13T00:59:50.5217974Z �[0m�[1mmodule.ec2_setup.module.validator[0].null_resource.validator: Creation complete after 34m8s [id=298226890415546555]�[0m�[0m
2022-09-13T00:59:50.6383254Z �[33m
2022-09-13T00:59:50.6395137Z �[1m�[33mWarning: �[0m�[0m�[1mDeprecated Resource�[0m
2022-09-13T00:59:50.6395371Z 
2022-09-13T00:59:50.6395798Z �[0m  on ../basic_components/main.tf line 39, in data "aws_subnet_ids" "aoc_private_subnet_ids":
2022-09-13T00:59:50.6396281Z   39: data "aws_subnet_ids" "aoc_private_subnet_ids" �[4m{�[0m
2022-09-13T00:59:50.6396583Z �[0m
2022-09-13T00:59:50.6396883Z The aws_subnet_ids data source has been deprecated and will be removed in a
2022-09-13T00:59:50.6397260Z future version. Use the aws_subnets data source instead.
2022-09-13T00:59:50.6397455Z 
2022-09-13T00:59:50.6397582Z (and 3 more similar warnings elsewhere)
2022-09-13T00:59:50.6397858Z �[0m�[0m
2022-09-13T00:59:50.6412468Z �[33m
2022-09-13T00:59:50.6412997Z �[1m�[33mWarning: �[0m�[0m�[1mArgument is deprecated�[0m
2022-09-13T00:59:50.6413199Z 
2022-09-13T00:59:50.6413488Z �[0m  on ../ec2/sshkey.tf line 34, in data "aws_s3_bucket_object" "ssh_private_key":
2022-09-13T00:59:50.6413895Z   34:   bucket = �[4mvar.sshkey_s3_bucket�[0m
2022-09-13T00:59:50.6414176Z �[0m
2022-09-13T00:59:50.6414416Z Use the aws_s3_object data source instead
2022-09-13T00:59:50.6414691Z �[0m�[0m
2022-09-13T00:59:50.6414926Z �[0m�[1m�[32m
2022-09-13T00:59:50.6415302Z Apply complete! Resources: 15 added, 0 changed, 0 destroyed.�[0m
2022-09-13T00:59:50.6415616Z �[0m�[1m�[32m
2022-09-13T00:59:50.6416013Z Outputs:
2022-09-13T00:59:50.6416147Z 
2022-09-13T00:59:50.6416332Z testing_id = "532c503bffd9ffd4"�[0m
2022-09-13T00:59:50.6927828Z 
2022-09-13T01:07:15.5801426Z ##[warning]Attempt 1 failed. Reason: Timeout of 3600000ms hit
2022-09-13T01:07:15.5809036Z 
2022-09-13T01:07:15.6374158Z [command]/home/runner/work/_temp/6abe0f53-d0d0-4ce6-9493-2706cb8f333e/terraform-bin init
2022-09-13T01:07:15.7110649Z �[0m�[1mInitializing modules...�[0m
2022-09-13T01:07:15.7477034Z 
2022-09-13T01:07:15.7488460Z �[0m�[1mInitializing the backend...�[0m
2022-09-13T01:07:16.8428328Z 
2022-09-13T01:07:16.8429254Z �[0m�[1mInitializing provider plugins...�[0m
2022-09-13T01:07:16.8430009Z - Reusing previous version of hashicorp/local from the dependency lock file
2022-09-13T01:07:16.8973205Z - Reusing previous version of hashicorp/aws from the dependency lock file
2022-09-13T01:07:16.9106414Z - Reusing previous version of hashicorp/template from the dependency lock file
2022-09-13T01:07:16.9207502Z - Reusing previous version of hashicorp/random from the dependency lock file
2022-09-13T01:07:16.9326543Z - Reusing previous version of hashicorp/null from the dependency lock file
2022-09-13T01:07:16.9528895Z - Reusing previous version of hashicorp/tls from the dependency lock file
2022-09-13T01:07:17.7957738Z - Using previously-installed hashicorp/aws v4.30.0
2022-09-13T01:07:17.8589242Z - Using previously-installed hashicorp/template v2.2.0
2022-09-13T01:07:17.8975221Z - Using previously-installed hashicorp/random v3.4.3
2022-09-13T01:07:17.9415466Z - Using previously-installed hashicorp/null v3.1.1
2022-09-13T01:07:17.9824733Z - Using previously-installed hashicorp/tls v4.0.2
2022-09-13T01:07:18.0272891Z - Using previously-installed hashicorp/local v2.2.3
2022-09-13T01:07:18.0273152Z 
2022-09-13T01:07:18.0273421Z �[0m�[1m�[32mTerraform has been successfully initialized!�[0m�[32m�[0m
2022-09-13T01:07:18.0273767Z �[0m�[32m
2022-09-13T01:07:18.0274079Z You may now begin working with Terraform. Try running "terraform plan" to see
2022-09-13T01:07:18.0274506Z any changes that are required for your infrastructure. All Terraform commands
2022-09-13T01:07:18.0274820Z should now work.
2022-09-13T01:07:18.0274963Z 
2022-09-13T01:07:18.0275147Z If you ever set or change modules or backend configuration for Terraform,
2022-09-13T01:07:18.0275550Z rerun this command to reinitialize your working directory. If you forget, other
2022-09-13T01:07:18.0276023Z commands will detect it and remind you to do so if necessary.�[0m
2022-09-13T01:07:18.0325874Z 
2022-09-13T01:07:18.0328890Z 
2022-09-13T01:07:18.0329672Z 
2022-09-13T01:07:18.0918281Z [command]/home/runner/work/_temp/6abe0f53-d0d0-4ce6-9493-2706cb8f333e/terraform-bin apply -auto-approve -lock=false -var-file=../testcases/otlp_trace/parameters.tfvars -var=aoc_version=latest -var=testcase=../testcases/otlp_trace -var=testing_ami=canary_windows
2022-09-13T01:07:23.6788843Z �[0m�[1mmodule.ec2_setup.module.common.random_id.testing_id: Refreshing state... [id=jNBPp7FhlMk]�[0m
2022-09-13T01:07:23.6850682Z �[0m�[1mmodule.basic_components.module.common.random_id.testing_id: Refreshing state... [id=Lsc_xoz1Ijg]�[0m
2022-09-13T01:07:23.7103657Z �[0m�[1mmodule.ec2_setup.module.basic_components.module.common.random_id.testing_id: Refreshing state... [id=LxHSiGmnPsY]�[0m
2022-09-13T01:07:23.7215937Z �[0m�[1mmodule.ec2_setup.tls_private_key.ssh_key[0]: Refreshing state... [id=e8b4a430a8704ceb4689ac11f2d91534444d430b]�[0m
2022-09-13T01:07:23.7376507Z �[0m�[1mmodule.common.random_id.testing_id: Refreshing state... [id=UyxQO__Z_9Q]�[0m
2022-09-13T01:07:24.8233634Z �[0m�[1mmodule.ec2_setup.aws_key_pair.aws_ssh_key[0]: Refreshing state... [id=testing-8cd04fa7b16194c9]�[0m
2022-09-13T01:07:25.7453492Z �[0m�[1mmodule.ec2_setup.aws_instance.sidecar: Refreshing state... [id=i-052772479814f11e3]�[0m
2022-09-13T01:07:25.7481191Z �[0m�[1mmodule.ec2_setup.aws_instance.aoc: Refreshing state... [id=i-012ce63c9a70b7f67]�[0m
2022-09-13T01:07:27.4677996Z �[0m�[1mmodule.ec2_setup.null_resource.check_patch[0]: Refreshing state... [id=7558068877623799063]�[0m
2022-09-13T01:07:27.4755791Z �[0m�[1mmodule.ec2_setup.null_resource.setup_mocked_server_cert_for_windows[0]: Refreshing state... [id=4777493023243761673]�[0m
2022-09-13T01:07:27.4756822Z �[0m�[1mmodule.ec2_setup.null_resource.setup_sample_app_and_mock_server[0]: Refreshing state... [id=5338849595985022880]�[0m
2022-09-13T01:07:27.4757834Z �[0m�[1mmodule.ec2_setup.null_resource.download_collector_from_s3[0]: Refreshing state... [id=2605438380643408551]�[0m
2022-09-13T01:07:27.4824823Z �[0m�[1mmodule.ec2_setup.null_resource.start_collector[0]: Refreshing state... [id=4748019381639749946]�[0m
2022-09-13T01:07:27.5077202Z �[0m�[1mmodule.ec2_setup.module.validator[0].local_file.docker_compose_file: Refreshing state... [id=5e05df56cc9659da81aabf931a6127aae650349e]�[0m
2022-09-13T01:07:27.5149902Z �[0m�[1mmodule.ec2_setup.module.validator[0].null_resource.validator: Refreshing state... [id=298226890415546555]�[0m
2022-09-13T01:07:29.9063603Z �[33m
2022-09-13T01:07:29.9064379Z �[1m�[33mWarning: �[0m�[0m�[1mDeprecated Resource�[0m
2022-09-13T01:07:29.9064878Z 
2022-09-13T01:07:29.9066245Z �[0m  on ../basic_components/main.tf line 39, in data "aws_subnet_ids" "aoc_private_subnet_ids":
2022-09-13T01:07:29.9066882Z   39: data "aws_subnet_ids" "aoc_private_subnet_ids" �[4m{�[0m
2022-09-13T01:07:29.9184579Z �[0m
2022-09-13T01:07:29.9184958Z The aws_subnet_ids data source has been deprecated and will be removed in a
2022-09-13T01:07:29.9185421Z future version. Use the aws_subnets data source instead.
2022-09-13T01:07:29.9185617Z 
2022-09-13T01:07:29.9185745Z (and 3 more similar warnings elsewhere)
2022-09-13T01:07:29.9186033Z �[0m�[0m
2022-09-13T01:07:29.9186473Z �[33m
2022-09-13T01:07:29.9186825Z �[1m�[33mWarning: �[0m�[0m�[1mArgument is deprecated�[0m
2022-09-13T01:07:29.9187012Z 
2022-09-13T01:07:29.9187290Z �[0m  on ../ec2/sshkey.tf line 34, in data "aws_s3_bucket_object" "ssh_private_key":
2022-09-13T01:07:29.9187728Z   34:   bucket = �[4mvar.sshkey_s3_bucket�[0m
2022-09-13T01:07:29.9188001Z �[0m
2022-09-13T01:07:29.9188251Z Use the aws_s3_object data source instead
2022-09-13T01:07:29.9188529Z �[0m�[0m
2022-09-13T01:07:29.9188768Z �[0m�[1m�[32m
2022-09-13T01:07:29.9189144Z Apply complete! Resources: 0 added, 0 changed, 0 destroyed.�[0m
2022-09-13T01:07:29.9189461Z �[0m�[1m�[32m
2022-09-13T01:07:29.9189674Z Outputs:
2022-09-13T01:07:29.9189801Z 
2022-09-13T01:07:29.9189980Z testing_id = "532c503bffd9ffd4"�[0m
2022-09-13T01:07:29.9339527Z 
2022-09-13T01:07:29.9341097Z 
2022-09-13T01:07:29.9342699Z 
2022-09-13T01:07:30.5933469Z Command completed after 2 attempt(s).
2022-09-13T01:07:30.5935501Z