Created
October 22, 2024 21:40
-
-
Save bronius/5ade651801ca5ea6f6018602fb1548c3 to your computer and use it in GitHub Desktop.
terraform DEBUG log output exhibiting inexplicable 4 second delay between "waiting for RPC address" and "Starting .. provider"
This file contains hidden or bidirectional Unicode text that may be interpreted or compiled differently than what appears below. To review, open the file in an editor that reveals hidden Unicode characters.
Learn more about bidirectional Unicode characters
| 2024-10-22T16:35:32.546-0500 [INFO] Terraform version: 1.9.8 | |
| 2024-10-22T16:35:32.547-0500 [DEBUG] using github.com/hashicorp/go-tfe v1.58.0 | |
| 2024-10-22T16:35:32.547-0500 [DEBUG] using github.com/hashicorp/hcl/v2 v2.20.0 | |
| 2024-10-22T16:35:32.547-0500 [DEBUG] using github.com/hashicorp/terraform-svchost v0.1.1 | |
| 2024-10-22T16:35:32.547-0500 [DEBUG] using github.com/zclconf/go-cty v1.14.4 | |
| 2024-10-22T16:35:32.547-0500 [INFO] Go runtime version: go1.22.7 | |
| 2024-10-22T16:35:32.547-0500 [INFO] CLI args: []string{"/opt/homebrew/Cellar/tfenv/3.0.0/versions/1.9.8/terraform", "plan"} | |
| 2024-10-22T16:35:32.547-0500 [DEBUG] Attempting to open CLI config file: /Users/bronius/.terraformrc | |
| 2024-10-22T16:35:32.547-0500 [DEBUG] File doesn't exist, but doesn't need to. Ignoring. | |
| 2024-10-22T16:35:32.547-0500 [DEBUG] ignoring non-existing provider search directory terraform.d/plugins | |
| 2024-10-22T16:35:32.547-0500 [DEBUG] ignoring non-existing provider search directory /Users/bronius/.terraform.d/plugins | |
| 2024-10-22T16:35:32.547-0500 [DEBUG] ignoring non-existing provider search directory /Users/bronius/Library/Application Support/io.terraform/plugins | |
| 2024-10-22T16:35:32.547-0500 [DEBUG] ignoring non-existing provider search directory /Library/Application Support/io.terraform/plugins | |
| 2024-10-22T16:35:32.547-0500 [INFO] CLI command args: []string{"plan"} | |
| 2024-10-22T16:35:32.949-0500 [DEBUG] checking for provisioner in "." | |
| 2024-10-22T16:35:32.949-0500 [DEBUG] checking for provisioner in "/opt/homebrew/Cellar/tfenv/3.0.0/versions/1.9.8" | |
| 2024-10-22T16:35:32.950-0500 [INFO] backend/local: starting Plan operation | |
| 2024-10-22T16:35:32.953-0500 [DEBUG] created provider logger: level=debug | |
| 2024-10-22T16:35:32.953-0500 [INFO] provider: configuring client automatic mTLS | |
| 2024-10-22T16:35:32.960-0500 [DEBUG] provider: starting plugin: path=.terraform/providers/registry.terraform.io/hashicorp/aws/5.72.1/darwin_arm64/terraform-provider-aws_v5.72.1_x5 args=[".terraform/providers/registry.terraform.io/hashicorp/aws/5.72.1/darwin_arm64/terraform-provider-aws_v5.72.1_x5"] | |
| 2024-10-22T16:35:32.975-0500 [DEBUG] provider: plugin started: path=.terraform/providers/registry.terraform.io/hashicorp/aws/5.72.1/darwin_arm64/terraform-provider-aws_v5.72.1_x5 pid=94058 | |
| 2024-10-22T16:35:32.975-0500 [DEBUG] provider: waiting for RPC address: plugin=.terraform/providers/registry.terraform.io/hashicorp/aws/5.72.1/darwin_arm64/terraform-provider-aws_v5.72.1_x5 | |
| 2024-10-22T16:35:37.142-0500 [DEBUG] provider.terraform-provider-aws_v5.72.1_x5: Starting github.com/hashicorp/[email protected] (go1.23.2)... | |
| 2024-10-22T16:35:37.142-0500 [DEBUG] provider.terraform-provider-aws_v5.72.1_x5: Initializing Terraform AWS Provider... | |
| 2024-10-22T16:35:37.180-0500 [INFO] provider.terraform-provider-aws_v5.72.1_x5: configuring server automatic mTLS: timestamp=2024-10-22T16:35:37.180-0500 | |
| 2024-10-22T16:35:37.187-0500 [DEBUG] provider: using plugin: version=5 | |
| 2024-10-22T16:35:37.187-0500 [DEBUG] provider.terraform-provider-aws_v5.72.1_x5: plugin address: address=/var/folders/fx/9b4c3b5x0bq0lmwx94_259200000gq/T/plugin1633107598 network=unix timestamp=2024-10-22T16:35:37.187-0500 | |
| 2024-10-22T16:35:37.759-0500 [DEBUG] provider.stdio: received EOF, stopping recv loop: err="rpc error: code = Unavailable desc = error reading from server: EOF" | |
| 2024-10-22T16:35:37.764-0500 [INFO] provider: plugin process exited: plugin=.terraform/providers/registry.terraform.io/hashicorp/aws/5.72.1/darwin_arm64/terraform-provider-aws_v5.72.1_x5 id=94058 | |
| 2024-10-22T16:35:37.764-0500 [DEBUG] provider: plugin exited | |
| 2024-10-22T16:35:37.764-0500 [DEBUG] Building and walking validate graph | |
| 2024-10-22T16:35:37.765-0500 [DEBUG] ProviderTransformer: "aws_instance.app_server" (*terraform.NodeValidatableResource) needs provider["registry.terraform.io/hashicorp/aws"] | |
| 2024-10-22T16:35:37.765-0500 [DEBUG] ReferenceTransformer: "provider[\"registry.terraform.io/hashicorp/aws\"]" references: [] | |
| 2024-10-22T16:35:37.765-0500 [DEBUG] ReferenceTransformer: "aws_instance.app_server" references: [] | |
| 2024-10-22T16:35:37.765-0500 [DEBUG] Starting graph walk: walkValidate | |
| 2024-10-22T16:35:37.766-0500 [DEBUG] created provider logger: level=debug | |
| 2024-10-22T16:35:37.766-0500 [INFO] provider: configuring client automatic mTLS | |
| 2024-10-22T16:35:37.768-0500 [DEBUG] provider: starting plugin: path=.terraform/providers/registry.terraform.io/hashicorp/aws/5.72.1/darwin_arm64/terraform-provider-aws_v5.72.1_x5 args=[".terraform/providers/registry.terraform.io/hashicorp/aws/5.72.1/darwin_arm64/terraform-provider-aws_v5.72.1_x5"] | |
| 2024-10-22T16:35:37.787-0500 [DEBUG] provider: plugin started: path=.terraform/providers/registry.terraform.io/hashicorp/aws/5.72.1/darwin_arm64/terraform-provider-aws_v5.72.1_x5 pid=94092 | |
| 2024-10-22T16:35:37.788-0500 [DEBUG] provider: waiting for RPC address: plugin=.terraform/providers/registry.terraform.io/hashicorp/aws/5.72.1/darwin_arm64/terraform-provider-aws_v5.72.1_x5 | |
| 2024-10-22T16:35:41.842-0500 [DEBUG] provider.terraform-provider-aws_v5.72.1_x5: Starting github.com/hashicorp/[email protected] (go1.23.2)... | |
| 2024-10-22T16:35:41.842-0500 [DEBUG] provider.terraform-provider-aws_v5.72.1_x5: Initializing Terraform AWS Provider... | |
| 2024-10-22T16:35:41.863-0500 [INFO] provider.terraform-provider-aws_v5.72.1_x5: configuring server automatic mTLS: timestamp=2024-10-22T16:35:41.863-0500 | |
| 2024-10-22T16:35:41.869-0500 [DEBUG] provider: using plugin: version=5 | |
| 2024-10-22T16:35:41.870-0500 [DEBUG] provider.terraform-provider-aws_v5.72.1_x5: plugin address: address=/var/folders/fx/9b4c3b5x0bq0lmwx94_259200000gq/T/plugin4080399273 network=unix timestamp=2024-10-22T16:35:41.869-0500 | |
| 2024-10-22T16:35:41.930-0500 [DEBUG] provider.stdio: received EOF, stopping recv loop: err="rpc error: code = Unavailable desc = error reading from server: EOF" | |
| 2024-10-22T16:35:41.933-0500 [INFO] provider: plugin process exited: plugin=.terraform/providers/registry.terraform.io/hashicorp/aws/5.72.1/darwin_arm64/terraform-provider-aws_v5.72.1_x5 id=94092 | |
| 2024-10-22T16:35:41.933-0500 [DEBUG] provider: plugin exited | |
| 2024-10-22T16:35:41.933-0500 [INFO] backend/local: plan calling Plan | |
| 2024-10-22T16:35:41.933-0500 [DEBUG] Building and walking plan graph for NormalMode | |
| 2024-10-22T16:35:41.933-0500 [DEBUG] ProviderTransformer: "aws_instance.app_server (expand)" (*terraform.nodeExpandPlannableResource) needs provider["registry.terraform.io/hashicorp/aws"] | |
| 2024-10-22T16:35:41.933-0500 [DEBUG] ReferenceTransformer: "aws_instance.app_server (expand)" references: [] | |
| 2024-10-22T16:35:41.933-0500 [DEBUG] ReferenceTransformer: "provider[\"registry.terraform.io/hashicorp/aws\"]" references: [] | |
| 2024-10-22T16:35:41.933-0500 [DEBUG] Starting graph walk: walkPlan | |
| 2024-10-22T16:35:41.934-0500 [DEBUG] created provider logger: level=debug | |
| 2024-10-22T16:35:41.934-0500 [INFO] provider: configuring client automatic mTLS | |
| 2024-10-22T16:35:41.936-0500 [DEBUG] provider: starting plugin: path=.terraform/providers/registry.terraform.io/hashicorp/aws/5.72.1/darwin_arm64/terraform-provider-aws_v5.72.1_x5 args=[".terraform/providers/registry.terraform.io/hashicorp/aws/5.72.1/darwin_arm64/terraform-provider-aws_v5.72.1_x5"] | |
| 2024-10-22T16:35:41.955-0500 [DEBUG] provider: plugin started: path=.terraform/providers/registry.terraform.io/hashicorp/aws/5.72.1/darwin_arm64/terraform-provider-aws_v5.72.1_x5 pid=94110 | |
| 2024-10-22T16:35:41.956-0500 [DEBUG] provider: waiting for RPC address: plugin=.terraform/providers/registry.terraform.io/hashicorp/aws/5.72.1/darwin_arm64/terraform-provider-aws_v5.72.1_x5 | |
| 2024-10-22T16:35:46.018-0500 [DEBUG] provider.terraform-provider-aws_v5.72.1_x5: Starting github.com/hashicorp/[email protected] (go1.23.2)... | |
| 2024-10-22T16:35:46.018-0500 [DEBUG] provider.terraform-provider-aws_v5.72.1_x5: Initializing Terraform AWS Provider... | |
| 2024-10-22T16:35:46.038-0500 [INFO] provider.terraform-provider-aws_v5.72.1_x5: configuring server automatic mTLS: timestamp=2024-10-22T16:35:46.037-0500 | |
| 2024-10-22T16:35:46.044-0500 [DEBUG] provider: using plugin: version=5 | |
| 2024-10-22T16:35:46.044-0500 [DEBUG] provider.terraform-provider-aws_v5.72.1_x5: plugin address: network=unix address=/var/folders/fx/9b4c3b5x0bq0lmwx94_259200000gq/T/plugin4211643915 timestamp=2024-10-22T16:35:46.044-0500 | |
| 2024-10-22T16:35:46.097-0500 [DEBUG] provider.terraform-provider-aws_v5.72.1_x5: Configuring Terraform AWS Provider: tf_mux_provider="*schema.GRPCProviderServer" tf_req_id=e4435dd2-01bb-9719-cb88-7953a6935b0c @module=aws tf_provider_addr=registry.terraform.io/hashicorp/aws tf_rpc=ConfigureProvider @caller=github.com/hashicorp/terraform-provider-aws/internal/conns/config.go:144 timestamp=2024-10-22T16:35:46.096-0500 | |
| 2024-10-22T16:35:46.097-0500 [DEBUG] provider.terraform-provider-aws_v5.72.1_x5: Resolving credentials provider: @module=aws.aws-base tf_req_id=e4435dd2-01bb-9719-cb88-7953a6935b0c tf_rpc=ConfigureProvider @caller=github.com/hashicorp/aws-sdk-go-base/[email protected]/logging/tf_logger.go:47 tf_mux_provider="*schema.GRPCProviderServer" tf_provider_addr=registry.terraform.io/hashicorp/aws timestamp=2024-10-22T16:35:46.097-0500 | |
| 2024-10-22T16:35:46.097-0500 [DEBUG] provider.terraform-provider-aws_v5.72.1_x5: Loading configuration: @module=aws.aws-base tf_rpc=ConfigureProvider @caller=github.com/hashicorp/aws-sdk-go-base/[email protected]/logging/tf_logger.go:47 tf_mux_provider="*schema.GRPCProviderServer" tf_provider_addr=registry.terraform.io/hashicorp/aws tf_req_id=e4435dd2-01bb-9719-cb88-7953a6935b0c timestamp=2024-10-22T16:35:46.097-0500 | |
| 2024-10-22T16:35:46.098-0500 [DEBUG] provider.terraform-provider-aws_v5.72.1_x5: Retrieving credentials: tf_mux_provider="*schema.GRPCProviderServer" tf_req_id=e4435dd2-01bb-9719-cb88-7953a6935b0c tf_rpc=ConfigureProvider @caller=github.com/hashicorp/aws-sdk-go-base/[email protected]/logging/tf_logger.go:47 tf_provider_addr=registry.terraform.io/hashicorp/aws @module=aws.aws-base timestamp=2024-10-22T16:35:46.098-0500 | |
| 2024-10-22T16:35:46.098-0500 [INFO] provider.terraform-provider-aws_v5.72.1_x5: Retrieved credentials: @caller=github.com/hashicorp/aws-sdk-go-base/[email protected]/logging/tf_logger.go:39 tf_mux_provider="*schema.GRPCProviderServer" tf_rpc=ConfigureProvider @module=aws.aws-base tf_aws.credentials_source=EnvConfigCredentials tf_provider_addr=registry.terraform.io/hashicorp/aws tf_req_id=e4435dd2-01bb-9719-cb88-7953a6935b0c timestamp=2024-10-22T16:35:46.098-0500 | |
| 2024-10-22T16:35:46.098-0500 [DEBUG] provider.terraform-provider-aws_v5.72.1_x5: Loading configuration: tf_req_id=e4435dd2-01bb-9719-cb88-7953a6935b0c @caller=github.com/hashicorp/aws-sdk-go-base/[email protected]/logging/tf_logger.go:47 tf_provider_addr=registry.terraform.io/hashicorp/aws @module=aws.aws-base tf_mux_provider="*schema.GRPCProviderServer" tf_rpc=ConfigureProvider timestamp=2024-10-22T16:35:46.098-0500 | |
| 2024-10-22T16:35:46.098-0500 [DEBUG] provider.terraform-provider-aws_v5.72.1_x5: Creating AWS SDK v1 session: @module=aws tf_mux_provider="*schema.GRPCProviderServer" tf_provider_addr=registry.terraform.io/hashicorp/aws tf_req_id=e4435dd2-01bb-9719-cb88-7953a6935b0c tf_rpc=ConfigureProvider @caller=github.com/hashicorp/terraform-provider-aws/internal/conns/config.go:168 timestamp=2024-10-22T16:35:46.098-0500 | |
| 2024-10-22T16:35:46.098-0500 [DEBUG] provider.terraform-provider-aws_v5.72.1_x5: Retrieving AWS account details: @caller=github.com/hashicorp/terraform-provider-aws/internal/conns/config.go:183 @module=aws tf_mux_provider="*schema.GRPCProviderServer" tf_provider_addr=registry.terraform.io/hashicorp/aws tf_req_id=e4435dd2-01bb-9719-cb88-7953a6935b0c tf_rpc=ConfigureProvider timestamp=2024-10-22T16:35:46.098-0500 | |
| 2024-10-22T16:35:46.098-0500 [DEBUG] provider.terraform-provider-aws_v5.72.1_x5: Retrieving caller identity from STS: tf_mux_provider="*schema.GRPCProviderServer" tf_req_id=e4435dd2-01bb-9719-cb88-7953a6935b0c tf_provider_addr=registry.terraform.io/hashicorp/aws tf_rpc=ConfigureProvider @caller=github.com/hashicorp/aws-sdk-go-base/[email protected]/logging/tf_logger.go:47 @module=aws.aws-base timestamp=2024-10-22T16:35:46.098-0500 | |
| ... |
Sign up for free
to join this conversation on GitHub.
Already have an account?
Sign in to comment